Обнаружение N+1: query logs, APM traces и CI gates

Страница занимает 1.2 секунды. CPU flame graph — плоский. Коллега настаивает, что профилировщик, наверное, ошибается. Профилировщик не ошибается — вы смотрите не в тот инструмент. N+1 живёт в off-CPU wait time между запросами, а не в какой-то функции.

Почему CPU-профили пропускают N+1

CPU-профилировщик сэмплирует стек-трейсы работающих потоков. Проблема N+1 не нагружает CPU в каком-то одном месте. Каждый запрос отправляется за микросекунды; программа затем ждёт базу данных (off-CPU); ответ приходит быстро; отправляется следующий запрос. Ожидание — это узкое место, но оно происходит off-CPU.

Профилировщик видит быстрые всплески без ничего широкого. Совокупная стоимость распределена по многим быстрым точкам вызова — не сконцентрирована в одной медленной функции. CPU flame graph будет выглядеть здоровым, пока страница занимает 1.2 секунды.

Правильные инструменты

1. Database query log

Наиболее прямой инструмент. Каждая крупная СУБД может логировать каждый запрос с его длительностью и меткой времени.

# Postgres — логировать всё в разработке
log_min_duration_statement = 0

# MySQL slow query log
slow_query_log = 1
long_query_time = 0

# ORM-level logging
# Rails: config.log_level = :debug (ActiveRecord logger выводит каждый запрос)
# Django: LOGGING = { 'loggers': { 'django.db.backends': { 'level': 'DEBUG' } } }
# SQLAlchemy: echo=True

Сигнатура N+1 безошибочна: от десятков до сотен похожих запросов для одного запроса, часто один и тот же SELECT, отличающийся только параметром id = ? в WHERE.

2. APM tracing — waterfall view

Инструменты мониторинга производительности приложений (Datadog APM, Grafana Tempo, New Relic, Honeycomb с автоинструментированием) захватывают database span’ы в одном ряду с span’ами выполнения кода.

N+1 waterfall выглядит как высокая колонка коротких параллельных полосок — 50 или 100 коротких database span’ов в одном trace запроса. Один взгляд на trace view делает паттерн очевидным так, как логи сами по себе не делают.

Предупреждайте, когда количество span’ов p95 на endpoint растёт более чем на 30% за неделю.

3. Счётчик запросов на запрос

Пользовательский middleware, считающий запросы на request и логирующий или предупреждающий при превышении:

# Rails — middleware считает запросы на request
ActiveSupport::Notifications.subscribe('sql.active_record') do
  RequestStore[:query_count] ||= 0
  RequestStore[:query_count] += 1
end

after_action do
  if RequestStore[:query_count] > 20
    Rails.logger.warn "QUERY_COUNT #{params[:controller]}##{params[:action]}: #{RequestStore[:query_count]}"
  end
end

Публикуйте как Prometheus histogram по endpoint. Предупреждайте, когда p99 endpoint превышает 20 или растёт более чем на 50% за неделю.

CI gate — поймать на этапе PR

Наиболее эффективный механизм против N+1 — поймать регрессию на этапе PR, а не в продакшне. Команды, использующие этот gate, сообщают о снижении инцидентов N+1 в продакшне на 70–90%. Первоначальная настройка: 1–2 недели. Текущее обслуживание: минимальное — gate запускается в CI.

Rails: гем bullet вызывает исключение при любом lazy-loaded relation, обращение к которому происходит при рендеринге запроса. Тест контроллера, вызывающий N+1, не проходит.

# spec/spec_helper.rb
Bullet.enable = true
Bullet.raise = true  # превращает N+1 в провал теста

Django: assertNumQueries(N) в тестовом фреймворке считает точные запросы на view:

def test_orders_page(self):
    with self.assertNumQueries(2):  # проваливается если N+1 проскочил
        response = self.client.get('/orders/')

SQLAlchemy / Hibernate: включить статистику количества запросов и проверять на тест:

# SQLAlchemy — проверить количество запросов через events
# Hibernate — проверить через Statistics.getPrepareStatementCount()

Паттерн во всех них: PR запускает тесты, тесты выполняют запросы, счётчик запросов превышает порог по endpoint’у, тест проваливается, PR не может влиться.

Чтение реального query log

# tail -f log/development.log | grep -E "SELECT|Loading"

Started GET "/dashboard"
User Load (0.4ms)    SELECT "users".* FROM "users" WHERE "users"."id" = 42
Project Load (0.6ms) SELECT "projects".* FROM "projects" WHERE "projects"."user_id" = 42 LIMIT 50
Task Load (0.3ms)    SELECT "tasks".* FROM "tasks" WHERE "tasks"."project_id" = 1
Task Load (0.3ms)    SELECT "tasks".* FROM "tasks" WHERE "tasks"."project_id" = 2
Task Load (0.4ms)    SELECT "tasks".* FROM "tasks" WHERE "tasks"."project_id" = 3
... (ещё 47 строк Task Load)
Comment Load (0.2ms) SELECT "comments".* FROM "comments" WHERE "comments"."task_id" = 1
Comment Load (0.2ms) SELECT "comments".* FROM "comments" WHERE "comments"."task_id" = 2
... (ещё 243 строки Comment Load)

Completed 200 OK in 980ms (Views: 250.3ms | ActiveRecord: 689.4ms)

Читаем: 980 мс итого, 689 мс из которых — ActiveRecord на 300+ запросов. Два уровня N+1:

• Уровень 2 (projects → tasks): 50 отдельных Task Load запросов, по одному на project.
• Уровень 3 (tasks → comments): 200–300 отдельных Comment Load запросов, по одному на task.

Фикс: projects.includes(tasks: :comments).limit(50) в Rails (или эквивалент в вашем ORM). С 300 запросов до 4 — один для user, один для projects, один для tasks (IN), один для comments (IN). Время ActiveRecord: 689 мс → ~15 мс.