Представьте, endpoint на Django иногда отвечает за секунды вместо миллисекунд. Как вы будете искать причину?

Расследование нестабильной медленной работы эндпоинта

Нестабильность («иногда медленно») — самый сложный класс проблем. Детерминированные баги воспроизводятся; флаппинг требует наблюдения в реальном времени и сбора статистики.

Шаг 1: Собрать данные о задержках

Первый приоритет — зафиксировать паттерн. Когда именно медленно? Только в пиковые часы? Каждый N-й запрос? После нескольких часов аптайма?

# Простой мониторинг из shell: запрос каждые 5 секунд с временем ответа
while true; do
  curl -o /dev/null -s -w "%{time_total}\n" https://api.example.com/endpoint
  sleep 5
done

• Настроить Gunicorn access log с временем: access_log_format = '%(h)s %(r)s %(s)s %(b)s %(D)s' (D — microseconds).
• В Nginx: $upstream_response_time vs $request_time — разница укажет на сетевой overhead между nginx и gunicorn.
• Собирать перцентили (p50, p95, p99) через Prometheus + histogram_quantile или Datadog APM.

Шаг 2: Проверить ресурсы в момент тормозов

# Активные запросы к Postgres во время медленного ответа
psql -U postgres -c "
  SELECT pid, now() - query_start AS dur, state, wait_event_type, wait_event, left(query, 100)
  FROM pg_stat_activity
  WHERE state != 'idle'
  ORDER BY dur DESC;
"

# Блокировки
psql -U postgres -c "
  SELECT blocked.pid, blocking.pid AS blocking_pid, blocked.query
  FROM pg_locks blocked_locks
  JOIN pg_stat_activity blocked ON blocked.pid = blocked_locks.pid
  JOIN pg_locks blocking_locks ON blocking_locks.locktype = blocked_locks.locktype
    AND blocking_locks.relation IS NOT DISTINCT FROM blocked_locks.relation
    AND blocking_locks.granted AND NOT blocked_locks.granted
  JOIN pg_stat_activity blocking ON blocking.pid = blocking_locks.pid;
"

Шаг 3: Подозреваемые — connection pool и N+1

• Connection pool exhaustion: Django открывает соединение на запрос. Если все CONN_MAX_AGE соединения заняты, новый запрос ждёт. Проверить: SELECT count(*) FROM pg_stat_activity WHERE datname='mydb'. Использовать pgBouncer в transaction mode.
• N+1 запросы: один запрос делает 1+N SQL — нагрузка растёт линейно с данными. django-debug-toolbar в dev покажет дубли. В production — django-silk или EXPLAIN ANALYZE.

# Выявить N+1: поставить middleware для логирования числа запросов
import logging
from django.db import connection

class QueryCountMiddleware:
    def __init__(self, get_response):
        self.get_response = get_response

    def __call__(self, request):
        start = len(connection.queries)
        response = self.get_response(request)
        end = len(connection.queries)
        if end - start > 20:  # порог
            logging.warning(
                "High query count: %d for %s",
                end - start,
                request.path,
            )
        return response

Шаг 4: Исключить внешние вызовы без timeout

import httpx

# Плохо: нет timeout — воркер может висеть 30+ секунд
response = httpx.get("https://external-api.com/data")

# Хорошо: явный timeout
response = httpx.get(
    "https://external-api.com/data",
    timeout=httpx.Timeout(connect=2.0, read=5.0, write=2.0, pool=1.0),
)

Шаг 5: Профилировать в production без перезапуска

# py-spy: attach к воркеру без downtime
pip install py-spy
py-spy top --pid $(pgrep -f 'gunicorn: worker')

# Запись flame graph
py-spy record -o flame.svg --pid 12345 --duration 30

Шаг 6: Кэш и race condition

• Cache stampede: несколько запросов одновременно получают cache miss и бегут в БД. Решение — django-cache-lock или cache-aside с jitter на TTL.
• Проверить Redis: redis-cli --latency-history -i 1 — всплески латентности.
• Eviction policy: если Redis заполнен и maxmemory-policy = allkeys-lru, кэш постоянно инвалидируется.

Подводные камни

• Нестабильность часто связана с VACUUM в PostgreSQL: autovacuum захватывает ресурсы ночью или после массовых UPDATE — смотреть pg_stat_user_tables.last_autovacuum.
• Gunicorn worker recycling (--max-requests) вызывает кратковременные пики при перезапуске воркера под нагрузкой.
• GC-паузы в Python при большом heap — включить gc.set_debug(gc.DEBUG_STATS) для проверки.
• DNS-кэш в контейнере: если эндпоинт ходит во внешний сервис, TTL 0 у DNS-провайдера вызывает повторную резолюцию на каждый запрос.
• CONN_MAX_AGE=0 (дефолт) создаёт новое TCP-соединение на каждый запрос — накладные расходы на handshake заметны при высоком RPS.
• django-silk в production хранит все запросы в БД — само по себе замедляет сервис; использовать только точечно с фильтром по path.
• Таймаут Gunicorn (--timeout 30) убивает воркер без логирования traceback — ищите «WORKER TIMEOUT» в supervisor/systemd журнале.
• ORM lazy loading в async view: await sync_to_async(lambda: list(qs))() запускается в отдельном потоке — при высоком параллелизме создаёт очередь из-за ограниченного thread pool.

• Сразу обвинять Django, не проверив соседние слои системы
• Чинить симптом без минимального воспроизведения и evidence
• Не учитывать версии, конфигурацию, окружение и recent changes

• Умеет локализовать проблему вокруг Django
• Двигается от симптома к гипотезам и проверкам
• Отличает баг инструмента от ошибки использования или окружения