Если у вас Django проект работает на синхронных воркерах и вы периодически их перезапускаете (например, в gunicorn это опция --max-requests), полезно было бы знать, что по-умолчанию после каждого перезапуска воркера, первый запрос к нему обрабатывается гораздо дольше, чем последующие.

В этой статье расскажу как я решил эту и другие проблемы, вызывающие аномальные задержки на случайных запросах.

В статье будут приведены примеры для gunicorn wsgi сервера. Но они актуальны при любых способах запуска проекта на синхронных воркерах. Тоже самое актуально и для uWSGI и mod_wsgi.

Недавно перенесли наш Django проект в Kubernetes кластер. Там есть readiness/liveness probes, которые могут дёргать каждый запущенный экземпляр wsgi сервера (в нашем случае это gunicorn) за указанную http ручку. У нас это /api/v1/status:

class StatusView(views.APIView):
    @staticmethod
    def get(request):
        overall_ok = True

        try:
            with django.db.connection.cursor() as cursor:
                cursor.execute('SELECT version()')
                cursor.fetchone()
        except Exception:
            log.exception('Database failure')
            db = 'fail'
            overall_ok = False
        else:
            db = 'ok'

        try:
            cache.set('status', 1)
        except Exception:
            log.exception('Redis failure')
            redis = 'fail'
            overall_ok = False
        else:
            redis = 'ok'

        if overall_ok:
            s = status.HTTP_200_OK
        else:
            s = status.HTTP_500_INTERNAL_SERVER_ERROR

        return Response({
            'web': 'ok',
            'db': db,
            'redis': redis,
        }, status=s)

Так вот, до переезда в Kubernetes у нас стоял Zabbix, который каждую минуту делал запрос на /api/v1/status через loadbalancer. И этот health check особо никогда не фэйлился. Но после переезда, когда проверки стали выполняться для каждого отдельного gunicorn инстанса и с большей частотой, вдруг оказалось, что иногда мы не укладываемся в таймаут 5 секунд.

Тем не менее все работало нормально, проблем у пользователей не было. Поэтому особо внимание этому не уделял, но поставил себе фоновую задачу все таки разобраться в чем же дело. И вот что удалось выяснить:

По-умолчанию gunicorn запускает master процесс, который форкает количество процессов указанное аргументом --workers. Причем модуль wsgi, переданный gunicorn в качестве основного аргумента, загружается каждым воркером уже после форка. Но есть опция --preload. Если её задать, модуль wsgi будет загружен ДО форка. Отсюда правило:

На проде всегда запускай gunicorn с опцией --preload, что позволит сократить время инициализации каждого воркера. В результате инициализация по большей части будет происходить только в мастер процессе, далее будут форкаться уже инициализированные worker процессы.

Повторюсь, что большая часть этих оптимизаций имеет смысл, если у вас Django проект работает на синхронных воркерах и вы периодически их перезапускаете (--max-requests).

Тем не менее, удалось выяснить, что использование --preload недостаточно, и первый запрос к свежезапущеному воркеру все равно занимает больше времени чем последующие. Трейс показал, что предзагрузка wsgi мало что даёт, и большая часть Django инициализируется лишь во время первого запроса. Поэтому родилось решение "в лоб":

В инициализацию wsgi довавьте фейковый запрос к health/status эндпоинту, чтобы сразу проинициализировать максимум подсистем.

Например, я добавил в wsgi.py следующее:

# make request to /api/v1/status to prepare everything for first user request
def make_init_request():
    from django.conf import settings
    from django.test import RequestFactory

    f = RequestFactory()
    request = f.request(**{
        'wsgi.url_scheme': 'http',
        'HTTP_HOST': settings.SITE_DOMAIN,
        'QUERY_STRING': '',
        'REQUEST_METHOD': 'GET',
        'PATH_INFO': '/api/v1/status',
        'SERVER_PORT': '80',
    })

    def start_response(*args):
        pass

    application(request.environ, start_response)

if os.environ.get('WSGI_FULL_INIT'):
    make_init_request()

В результате воркеры стали инициализироваться на порядок быстрее, т.к. уже форкались полностью готовыми к следующему запросу.

По трейсам проблемы с инициализацией прекратились… почти. К своему стыду я не знал об этой особенности. Оказывается, по-умолчанию, Django при каждом запросе переподключается к БД. За это отвечает настройка CONN_MAX_AGE, которая только лишь(?) по историческим причинам заставляет ваше Django приложение работать как php скрипт из нулевых. Так что правило:

В настройки Django БД адаптера добавить CONN_MAX_AGE=None, чтобы подключения были постоянными.

Я бы даже и не заметил этого. Но, по какой-то причине, вызов psycopg2.connect иногда подвисает ровно на 5 секунд. Вот в этом я до конца не разобрался. Параллельно запущенный скрипт, который вызывает эту функцию раз в 10 секунд работал стабильно и подключался к БД быстрее чем за секунду за все время пока был запущен (пару недель).

Но эти два правила конфиликтуют друг с другом, т.к. перед форком в основном процессе создаются подключения к БД и кешу. Дочерние процессы наследуют открытые сокеты основного процесса. В результате, это приводит к неопределённому поведению, когда несколько процессов будут одновременно работать с одним сокетом. Поэтому, перед форком, нужно закрыть все подключения:

# Close connections to database and cache before or after forking.
# Without this, child processes will share these connections and this is not supported.
def close_network_connections():
    from django import db
    from django.core import cache
    from django.conf import settings

    for conn in db.connections:
        db.connections[conn].close()

    django_redis_close_connection = getattr(settings, 'DJANGO_REDIS_CLOSE_CONNECTION', False)
    settings.DJANGO_REDIS_CLOSE_CONNECTION = True
    cache.close_caches()
    settings.DJANGO_REDIS_CLOSE_CONNECTION = django_redis_close_connection

if os.environ.get('WSGI_FULL_INIT'):
    make_init_request()
    # in case wsgi module preloaded in master process (i.e. `gunicorn --preload`)
    if os.environ.get('WSGI_FULL_INIT_CLOSE_CONNECTIONS'):
        close_network_connections()

Т.о. при использовании --preload и WSGI_FULL_INIT, нужно еще задать WSGI_FULL_INIT_CLOSE_CONNECTIONS.

В результате, аномальные задержки были полностью исключены. Но есть пара крайних случаев, когда они все же могут возникнуть:

Если все воркеры начнут перезапускаться одновременно. Это вполне вероятная ситуация, т.к. если запросы между воркерами распределяются приблизительно равномерно, то и max-requests наступит приблизительно в одно и то же время. Поэтому:

Запускай gunicorn c max-requests-jitter, чтобы воркеры не перезапускались одновременно, даже если они это делают достаточно быстро.

Также задержка может возникнуть во время первого запроса, когда создаются подключения к БД и другим внешним системам.

Это можно решить, но у меня нет идей как написать код независимый от используемого wsgi сервера. В gunicorn можно добавить обработчик для post_worker_init и там еще раз вызвать make_init_request(), тогда воркер перед получением первого запроса будет готов на 100%. Чтобы не усложнять, было решено пока что обойтись без этого, ведь мы и так добились того, что больше задержек на практике не наблюдается.