Как отследить и проанализировать медленные запросы в Go?

Ответ

Для отслеживания и анализа медленных запросов в Go-приложении используется комбинация нескольких подходов:

1. Простое измерение времени (Middleware)

Самый простой способ — измерить время выполнения запроса вручную. В веб-сервисах это удобно делать с помощью middleware-функции, которая оборачивает основной обработчик.

func LoggingMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()
        next.ServeHTTP(w, r)
        duration := time.Since(start)

        // Логируем, если запрос выполнялся дольше определенного порога
        if duration > 500*time.Millisecond {
            log.Printf("[%s] %s took %s (SLOW)", r.Method, r.RequestURI, duration)
        }
    })
}

// Использование:
// http.Handle("/", LoggingMiddleware(myHandler))

2. Профилирование с помощью pprof

pprof — это стандартный и мощный инструмент для профилирования Go-приложений. Он позволяет анализировать использование CPU, памяти, а также находить узкие места, вызывающие задержки.

Как использовать:

  1. Импортируйте пакет net/http/pprof.
  2. Запустите HTTP-сервер (часто на отдельном порту).
import (
    _ "net/http/pprof" // Анонимный импорт для регистрации обработчиков pprof
    "log"
    "net/http"
)

go func() {
    // Запускаем сервер pprof на порту 6060
    log.Println(http.ListenAndServe("localhost:6060", nil))
}()

После запуска вы можете использовать утилиту go tool pprof или веб-интерфейс (http://localhost:6060/debug/pprof/) для анализа:

  • CPU Profile: Показывает, какие функции потребляют больше всего процессорного времени.
  • Trace: go tool trace — особенно полезен для анализа задержек (latency). Он визуализирует выполнение горутин во времени и помогает найти, где программа "простаивала".

3. Распределенная трассировка (Distributed Tracing)

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

  • Стандарт: OpenTelemetry является индустриальным стандартом.
  • Инструменты: Jaeger, Zipkin, Datadog.

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

4. Контекст с таймаутом (для контроля, а не отслеживания)

context.WithTimeout или context.WithDeadline не отслеживают медленные запросы, а предотвращают их, прерывая операцию по истечении времени. Это важный механизм для обеспечения отказоустойчивости системы.

// Устанавливаем дедлайн в 2 секунды
ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second)
defer cancel()

// Передаем контекст в долгую операцию (например, запрос в БД или другой сервис)
err := longOperation(ctx)

if errors.Is(err, context.DeadlineExceeded) {
    // Операция была прервана по таймауту
    log.Println("Request failed due to timeout")
}

Ответ 18+ 🔞

А, ну это же классика, блядь! Ты сидишь, такой, смотришь на свой сервис, а он тормозит, как черепаха в патоках. И думаешь: "Ну что за пиздец, кто тут у меня самый медленный?" Давай разберем, как это выяснить, чтобы потом не орать "Муму!" на весь офис.

Первый способ — самый тупой, но рабочий, как лом. Просто засечь время.

Веб-сервисы — они же все через middleware проходят. Вот и вставь туда секундомер, блядь. Если запрос выполняется дольше, чем твоё терпение (скажем, полсекунды), пиши в лог, что тут у нас тормозит конь.

func LoggingMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()
        next.ServeHTTP(w, r)
        duration := time.Since(start)

        // Логируем, если запрос выполнялся дольше определенного порга
        if duration > 500*time.Millisecond {
            log.Printf("[%s] %s took %s (SLOW)", r.Method, r.RequestURI, duration)
        }
    })
}

Вот и всё, ёпта. Теперь в логах будут маячить эти тормознутые запросы, как гвозди в табуретке.

Второй способ — тяжёлая артиллерия, pprof. Это, блядь, как рентген для твоего кода. Показывает, какая функция жрёт процессор, как не в себя.

Подключаешь его одной строчкой, даже не надо думать:

import (
    _ "net/http/pprof" // Анонимный импорт для регистрации обработчиков pprof
    "log"
    "net/http"
)

go func() {
    // Запускаем сервер pprof на порту 6060
    log.Println(http.ListenAndServe("localhost:6060", nil))
}()

Запустил — и пошёл по адресу localhost:6060/debug/pprof/. Там тебе и CPU, и память, и, что самое главное — trace. А trace, сука, это вообще волшебная штука. Он показывает, как твои горутины бегают, где они спят, где ждут. Идеально, чтобы найти, где программа встала в позу "ждуна" и просто тупит.

Третий способ — для больших шишек, распределённая трассировка. Это когда у тебя не один сервис, а целая куча, и запрос прыгает из одного в другой, как блоха. И ты уже не поймёшь, в каком именно сервисе он застрял, как муха в паутине.

Тут уже нужны взрослые игрушки: OpenTelemetry, Jaeger, Zipkin. Они рисуют тебе красивую картинку всего пути запроса и показывают, в каком сервисе он провёл больше всего времени, просиживая штаны. Без этого в микросервисах — просто слепой котёнок.

Четвёртый пункт — это не про отслеживание, а про контроль, чтобы не дать запросу сойти с ума. Контекст с таймаутом.

// Устанавливаем дедлайн в 2 секунды
ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second)
defer cancel()

// Передаем контекст в долгую операцию (например, запрос в БД или другой сервис)
err := longOperation(ctx)

if errors.Is(err, context.DeadlineExceeded) {
    // Операция была прервана по таймауту
    log.Println("Request failed due to timeout")
}

Это чтобы твой запрос к базе данных, которая сегодня решила поспать, не висел до второго пришествия. Сказали "две секунды" — и всё, пип-пип, время вышло, пошёл нахуй. Система должна быть живучей, а не висеть в ожидании чуда.

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