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

Алгоритм расследования спорадических задержек

«Иногда медленно» — классический симптом нескольких проблем: N+1 запросы, lock contention, cold start connection pool, GC pause, внешний сервис с хвостовыми задержками. Подходим системно.

Шаг 1: Добавить трейсинг и отловить медленный запрос

import (
	"go.opentelemetry.io/contrib/instrumentation/github.com/labstack/echo/otelecho"
	"go.opentelemetry.io/otel"
	"go.opentelemetry.io/otel/attribute"
)

// Инициализация OTLP-экспортёра (Jaeger/Tempo)
func initTracer() func() {
	exporter, _ := otlptracehttp.New(context.Background(),
		otlptracehttp.WithEndpoint("localhost:4318"),
	)
	tp := trace.NewTracerProvider(
		trace.WithBatcher(exporter),
		trace.WithSampler(trace.AlwaysSample()),
	)
	otel.SetTracerProvider(tp)
	return func() { tp.Shutdown(context.Background()) }
}

// В main:
e.Use(otelecho.Middleware("orders-service"))

Теперь каждый запрос генерирует trace. Фильтруем в Jaeger по duration > 1s и смотрим waterfall-диаграмму — сразу видно, какой span занимает большую часть времени.

Шаг 2: Инструментировать хендлер

func getOrder(c echo.Context) error {
	ctx := c.Request().Context()
	tracer := otel.Tracer("orders")

	_, dbSpan := tracer.Start(ctx, "db.GetOrder")
	order, err := repo.GetOrder(ctx, c.Param("id"))
	dbSpan.End()
	if err != nil {
		return echo.NewHTTPError(404, err.Error())
	}

	_, extSpan := tracer.Start(ctx, "pricing-service.GetPrice")
	price, _ := pricingClient.Get(ctx, order.SKU)
	extSpan.End()

	return c.JSON(200, enrichOrder(order, price))
}

Шаг 3: Метрики latency-гистограмм

import "github.com/labstack/echo-contrib/echoprometheus"

e.Use(echoprometheus.NewMiddlewareWithConfig(echoprometheus.MiddlewareConfig{
	Subsystem: "http",
	HistogramOptsFunc: func(opts prometheus.HistogramOpts) prometheus.HistogramOpts {
		opts.Buckets = []float64{.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10}
		return opts
	},
}))

Запрос в Prometheus: histogram_quantile(0.99, rate(http_requests_duration_seconds_bucket[5m])) — p99 latency по эндпоинтам.

Шаг 4: Проверка connection pool

// pgx pool stats — логируем периодически
go func() {
	ticker := time.NewTicker(30 * time.Second)
	for range ticker.C {
		s := pool.Stat()
		log.Printf("db pool: acquired=%d idle=%d waitCount=%d waitDuration=%s",
			s.AcquiredConns(), s.IdleConns(),
			s.EmptyAcquireCount(), s.AcquireDuration())
	}
}()

Если AcquireDuration растёт в момент spike — проблема в исчерпании пула. Решение: увеличить MaxConns или оптимизировать время удержания соединения.

Шаг 5: Горутин-утечки и GC

# Снять stack всех горутин в момент проблемы
curl -s http://localhost:6060/debug/pprof/goroutine?debug=2 | head -100

# GC трейс
GODEBUG=gctrace=1 ./myapp 2>&1 | grep gc

Если количество горутин растёт линейно — ищите хендлеры, запускающие горутины без context.Done()-выхода.

Шаг 6: Логирование медленных запросов в Echo

e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
	LogLatency:   true,
	LogURI:       true,
	LogStatus:    true,
	LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error {
		if v.Latency > 500*time.Millisecond {
			log.Printf("SLOW REQUEST uri=%s latency=%s status=%d",
				v.URI, v.Latency, v.Status)
		}
		return nil
	},
}))

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

• Спорадические задержки часто связаны с DNS-резолвингом внешних сервисов — используйте httptrace.ClientTrace для измерения DNS+TLS времени отдельно.
• GC stop-the-world паузы в Go 1.21+ редки, но при heap > 2 ГБ могут достигать 10–50 мс — снизьте GOGC или используйте GOMEMLIMIT.
• Connection pool по умолчанию в database/sql имеет MaxOpenConns=0 (неограниченно) — под нагрузкой БД перегружается; всегда выставляйте явный лимит.
• Echo-middleware Logger использует fmt.Sprintf синхронно — под высокой нагрузкой это добавляет латентность; замените на zerolog/zap с async writer.
• Если трейсинг добавлен не на первое место в цепочке middleware, время аутентификации (часто обращается к Redis) не будет видно в трейсе.
• c.Request().Context() отменяется при завершении запроса — горутины, запущенные в хендлере без detached context, получат ошибку отмены при первом же медленном запросе клиента.
• Rate limiter или circuit breaker во внешнем клиенте может молча добавлять задержку через exponential backoff — логируйте retry-счётчики явно.
• Проблема может быть в одном конкретном экземпляре при горизонтальном масштабировании (hot pod, bad node) — добавляйте hostname в трейсы и метрики.

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

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