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

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

Проблема «иногда секунды» — классический признак intermittent issue: lock contention, connection pool exhaustion, GC pause или внешний сервис с высоким p99. Следуем структурированному процессу.

Шаг 1: Воспроизведение и фиксация данных

Сначала убеждаемся, что видим проблему в метриках, а не только в жалобах:

# Нагрузочный тест с wrk для воспроизведения
wrk -t4 -c100 -d30s http://localhost:8080/api/orders

# Или hey
hey -n 10000 -c 50 http://localhost:8080/api/orders

Смотрим p99 и max latency. Если max >> p99 — outlier-проблема (lock, GC, cold path).

Шаг 2: Трейсинг для локализации слоя

import (
	"go.opentelemetry.io/contrib/instrumentation/github.com/gin-gonic/gin/otelgin"
	"go.opentelemetry.io/otel"
	"go.opentelemetry.io/otel/exporters/jaeger"
)

// В main.go: инициализация Jaeger exporter
exporter, _ := jaeger.New(jaeger.WithCollectorEndpoint(
	jaeger.WithEndpoint("http://jaeger:14268/api/traces"),
))

// Middleware
r.Use(otelgin.Middleware("orders-service"))

// В handler — span на каждый I/O
func getOrder(c *gin.Context) {
	ctx := c.Request.Context()

	ctx, dbSpan := otel.Tracer("").Start(ctx, "db.getOrder")
	order, err := repo.Get(ctx, c.Param("id"))
	dbSpan.End()

	if err != nil {
		c.JSON(500, gin.H{"error": err.Error()})
		return
	}

	ctx, cacheSpan := otel.Tracer("").Start(ctx, "cache.getOrderMeta")
	meta := cache.Get(ctx, order.ID)
	cacheSpan.End()

	c.JSON(200, gin.H{"order": order, "meta": meta})
}

В Jaeger фильтруем трейсы по duration > 500ms. Это мгновенно покажет, какой span «проваливается» в секунды.

Шаг 3: pprof под нагрузкой

# Включить pprof (только внутренний network)
git grep -r "pprof.Register"

# CPU профиль во время нагрузки
go tool pprof -http :9090 http://localhost:8080/debug/pprof/profile?seconds=30

# Заблокированные горутины (mutex contention)
go tool pprof http://localhost:8080/debug/pprof/mutex

# Горутины в ожидании (I/O, channels)
curl http://localhost:8080/debug/pprof/goroutine?debug=2 | grep -A5 "waiting"

Шаг 4: Connection Pool и БД

// Логирование stats пула каждые 10 секунд
go func() {
	ticker := time.NewTicker(10 * time.Second)
	for range ticker.C {
		stats := db.Stats()
		log.Printf("db pool: open=%d inuse=%d idle=%d waitCount=%d waitDuration=%s",
			stats.OpenConnections, stats.InUse, stats.Idle,
			stats.WaitCount, stats.WaitDuration)
	}
}()

Если WaitCount растёт — пул исчерпан. Решение: увеличить db.SetMaxOpenConns() или найти запросы, не возвращающие соединение (забытый rows.Close()).

Шаг 5: GC Pause

# Включить GC trace
GODEBUG=gctrace=1 ./myservice 2>&1 | grep "^gc"

# Или через runtime metrics в Prometheus
# go_gc_duration_seconds{quantile="0.99"}

GC pause >100ms при большом heap — признак memory pressure. Решение: уменьшить аллокации в hot path, настроить GOGC или GOMEMLIMIT.

Шаг 6: Внешние HTTP-вызовы

// Всегда используйте таймауты и контекст запроса
client := &http.Client{
	Timeout: 2 * time.Second,
	Transport: otelhttp.NewTransport(http.DefaultTransport),
}

req, _ := http.NewRequestWithContext(c.Request.Context(), "GET", url, nil)
resp, err := client.Do(req)

Типичные причины «иногда секунды»

• N+1 query: в цикле по 100 элементам — 100 запросов в БД.
• Cold connection в пуле при первом запросе после долгого простоя.
• Lock на таблице PostgreSQL от параллельного UPDATE/migration.
• DNS lookup при каждом HTTP-вызове без keep-alive.
• Redis с KEYS * в production блокирует сервер на секунды.

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

• Без c.Request.Context() в DB-вызовах — запрос продолжает работать после отмены клиентом, потребляя ресурсы без результата.
• Таймаут на уровне Gin (http.Server{ReadTimeout}) и таймаут БД — разные вещи; нужны оба.
• Трейсинг без sampling настроен на 100% — под нагрузкой exporter становится bottleneck; используйте ratio-based sampling.
• pprof mutex profiling выключен по умолчанию — нужно runtime.SetMutexProfileFraction(1) для активации.
• GC pause в Go 1.21+ значительно меньше 1 мс для большинства heap — если видите секунды, ищите I/O, не GC.
• Логи Gin по умолчанию пишутся синхронно в stdout — под нагрузкой это serialization point; используйте асинхронный Zap writer.
• rows.Close() и resp.Body.Close() без defer вызывают утечку соединений — pool исчерпывается постепенно, симптомы нарастают со временем.
• Метрика http_request_duration_seconds без разбивки по FullPath скрывает медленный endpoint за средними значениями быстрых.

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

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