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

Алгоритм расследования медленного эндпоинта

Эндпоинт отвечает за секунды вместо миллисекунд — это значит, что где-то есть блокирующая операция или накопительный эффект. Задача — найти её за минимальное время.

Шаг 1. Воспроизвести и измерить

# Нагрузочный тест с измерением percentiles
ab -n 100 -c 10 https://myapp.com/api/slow-endpoint
# или через hey:
hey -n 200 -c 20 https://myapp.com/api/slow-endpoint

# Проверить curl с измерением времени
curl -w "\ntime_total: %{time_total}s\ntime_connect: %{time_connect}s\n" \
  -o /dev/null -s https://myapp.com/api/slow-endpoint

Важно понять: проблема воспроизводится всегда или только при параллельных запросах? Всегда — чистая медленная логика. Только под нагрузкой — конкуренция за ресурс (lock, connection pool).

Шаг 2. Прочитать Rails logs

# Найти медленные запросы в логах (>500ms)
grep 'Completed 200' production.log | awk '{print $NF}' | sort -t= -k2 -rn | head -20

# Или через grep + tail в реальном времени
tail -f production.log | grep -E 'Completed|ActiveRecord'

В Rails log каждый запрос содержит строку вида:

Completed 200 OK in 3421ms (Views: 12.3ms | ActiveRecord: 3390.1ms | Allocations: 48231)

Если ActiveRecord: 3390ms — проблема в базе. Если Views: 2800ms — в рендеринге. Если оба малы, а total большой — внешний HTTP или background computation.

Шаг 3. Анализ SQL-запросов

# Временно включить explain в development
ActiveRecord::Base.logger = Logger.new(STDOUT)

# Получить EXPLAIN ANALYZE конкретного запроса
result = User.joins(:orders).where(orders: { status: 'pending' }).explain
puts result
# Или через ActiveRecord
User.joins(:orders).where(orders: { status: 'pending' }).each_with_object([]) do |u, arr|
  arr << u
end
# В консоли:
ActiveRecord::Base.connection.execute(
  "EXPLAIN ANALYZE SELECT * FROM users JOIN orders ON ..."
).each { |row| puts row['QUERY PLAN'] }

-- Найти медленные запросы через pg_stat_statements
SELECT
  query,
  calls,
  round(mean_exec_time::numeric, 2) AS mean_ms,
  round(total_exec_time::numeric, 2) AS total_ms
FROM pg_stat_statements
WHERE mean_exec_time > 100
ORDER BY mean_exec_time DESC
LIMIT 20;

Шаг 4. Найти N+1 и неэффективные запросы

# Включить Bullet (gem 'bullet') в development
# config/environments/development.rb
Bullet.enable = true
Bullet.alert = true
Bullet.rails_logger = true

# Пример N+1 и его исправление
# ПЛОХО: N+1
posts = Post.all
posts.each { |p| puts p.author.name }  # SELECT * FROM users WHERE id=? x N

# ХОРОШО: eager load
posts = Post.includes(:author).all
posts.each { |p| puts p.author.name }  # 2 запроса суммарно

# Если нужен только один атрибут — pluck
Post.joins(:author).pluck('posts.id', 'users.name')

Шаг 5. Профилирование Ruby-кода

# gem 'stackprof'
result = StackProf.run(mode: :cpu, interval: 500, raw: true) do
  100.times { ArticlesController.new.index_action_simulation }
end

File.write('/tmp/stackprof.dump', Marshal.dump(result))
# Затем: stackprof /tmp/stackprof.dump --text --limit 20

stackprof /tmp/stackprof.dump --text --limit 20
# Показывает топ-20 методов по CPU-времени

# Flamegraph:
stackprof /tmp/stackprof.dump --flamegraph > /tmp/flamegraph.html

Шаг 6. Проверить внешние зависимости

# Найти внешние HTTP-вызовы без timeout
# Grep по коду:
# grep -rn 'HTTParty\|Faraday\|Net::HTTP\|RestClient' app/

# Убедиться что установлены timeouts
Faraday.new(url: 'https://api.example.com') do |conn|
  conn.options.timeout      = 5   # read timeout
  conn.options.open_timeout = 2   # connect timeout
  conn.adapter Faraday.default_adapter
end

Шаг 7. Проверить connection pool

# Текущее состояние пула соединений
ActiveRecord::Base.connection_pool.stat
# => {size: 5, connections: 5, busy: 5, dead: 0, idle: 0, waiting: 3, checkout_timeout: 5}
# waiting > 0 означает, что треды ждут соединения — нужно увеличить pool size

# config/database.yml
production:
  pool: <%= ENV.fetch("RAILS_MAX_THREADS") { 5 } %>
  checkout_timeout: 5

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

• Медленный запрос в development с маленьким датасетом может быть быстрым в production с другим планом запроса и наоборот — всегда анализировать EXPLAIN ANALYZE на production-данных (или репликации).
• Connection pool exhaustion выглядит как «случайные» зависания: запрос ждёт свободного соединения. Метрика waiting в connection_pool.stat должна быть 0.
• GC паузы Ruby могут быть причиной всплесков latency на P99. Проверить через GC::Profiler.enable; GC::Profiler.report.
• Rack Mini Profiler в production без ограничений доступа — серьёзная уязвимость: раскрывает SQL-запросы и внутреннюю структуру приложения.
• StackProf sampling с низким interval (100 мкс) сам создаёт накладные расходы — начинать с 1000–2000 мкс.
• Если проблема воспроизводится только под нагрузкой — смотреть на lock contention в PostgreSQL: SELECT * FROM pg_locks WHERE NOT granted;
• Кеширование (Rails.cache, fragment caching) может маскировать проблему: первый «холодный» запрос тормозит, последующие — нет. Проверять поведение при Rails.cache.clear.
• Внешние API-вызовы без circuit breaker превращают их деградацию в деградацию всего приложения — использовать гем stoplight или circuitbox.

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

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