Irbisa · Шпаргалка

Observability и эксплуатация

slog, Prometheus, OpenTelemetry, пробы, SLO, разбор всплеска p99

Senior-разработчик · 24 вопроса

  1. 01

    Логи, метрики и трейсы: на какой вопрос отвечает только каждый из них?

    Метрики говорят, что что-то не так и насколько, трейсы показывают, где в запросе ушло время или возникла ошибка, а логи объясняют, что именно произошло в одном событии.

  2. 02

    Что такое структурированное логирование, как его делает log/slog и какой уровень лога для чего использовать?

    Структурированное логирование пишет каждое событие как постоянное сообщение плюс типизированные пары ключ/значение, поэтому хранилище логов умеет фильтровать и считать по полям, а не грепать текст; log/slog (Go 1.21+) делает это в стандартной библиотеке.

    // wrong: the fields are baked into the sentence, so every question is a grepfunc placeOld(id, tenant string, err error) {	log.Printf("order %s failed for tenant %s: %v", id, tenant, err)} var level = new(slog.LevelVar) // Leveler: flip at runtime, no redeploy…
  3. 03

    Найдите баг: неудачные списания попадают в лог строками ERROR, но поиск по полю err их не находит.

    func (s *Server) handleCharge(w http.ResponseWriter, r *http.Request) {	orderID := r.PathValue("id")	log := s.log.With("request_id", requestID(r)) 	if err := s.payments.Charge(r.Context(), orderID); err != nil {		log.ErrorContext(r.Context(), "charge failed", "order_id", orderID, err)		http.Error(w, "payment failed", http.StatusBadGateway)		return	}	log.InfoContext(r.Context(), "charge ok", "order_id", orderID)	w.WriteHeader(http.StatusNoContent)}

    ErrorContext получает err без ключа, поэтому slog пишет его под ключом-заглушкой !BADKEY: строка в логе есть, но поля err, по которому можно искать, фильтровать и алертить, в ней нет.

  4. 04

    Как Prometheus забирает метрики из Go-сервиса и какие метрики рантайма client_golang отдаёт без единой строки вашего кода?

    Prometheus тянет (pull): раз в интервал скрейпа (обычно 15–30 с) он шлёт GET /metrics каждой цели, а promhttp отвечает текущими значениями всех метрик в текстовом виде.

    func newMetrics() (*prometheus.Registry, *prometheus.CounterVec) {	reg := prometheus.NewRegistry() // empty: nothing is implicit here 	reg.MustRegister(		collectors.NewGoCollector(			collectors.WithGoCollectorRuntimeMetrics(collectors.MetricsScheduler),…
  5. 05

    Чем отличаются counter, gauge, histogram и summary и какой тип брать для задержки запросов?

    Counter только растёт и читается через rate(); gauge ходит вверх и вниз и читается как есть; histogram раскладывает наблюдения по бакетам, чтобы перцентили можно было посчитать по всем подам; summary считает перцентили внутри одного процесса.

    var (	requests = promauto.NewCounterVec(prometheus.CounterOpts{		Name: "http_requests_total",		Help: "Requests by route and status class.",	}, []string{"route", "status"})…
  6. 06

    Что такое трейс, спан и trace id и как trace id переходит из одного сервиса в другой?

    Трейс описывает весь путь одного запроса: дерево спанов, где каждый спан соответствует одной замеренной операции (хендлер, запрос в базу, исходящий вызов) с атрибутами и статусом.

    func initTracing(ctx context.Context) (func(context.Context) error, error) {	exp, err := otlptracegrpc.New(ctx) // endpoint from OTEL_EXPORTER_OTLP_ENDPOINT	if err != nil {		return nil, err	}	tp := sdktrace.NewTracerProvider(…
  7. 07

    Что такое SLI, SLO и SLA и что такое бюджет ошибок?

    SLI измеряет долю хороших событий, например запросов, отвеченных без 5xx быстрее 300 мс.

  8. 08

    Как расшифровываются RED и USE и какой из двух наборов инструментировать первым на HTTP-сервисе, а какой на воркере очереди?

    На HTTP-сервисе начинают с RED (Rate, Errors, Duration) по каждому роуту; на воркере очереди начинают с saturation в духе USE (глубина очереди и возраст самого старого сообщения) и добавляют RED для обрабатываемых задач.

  9. 09

    Хендлеры повторяют "request_id", rid в каждом вызове slog, а в строках из пакетов поглубже его нет. Как это исправить и в чём ловушка с логгером в Context?

    Привяжите атрибуты запроса один раз через logger.With(...) и передавайте этот дочерний логгер вниз.

    type ctxKey struct{} func withLogger(ctx context.Context, l *slog.Logger) context.Context {	return context.WithValue(ctx, ctxKey{}, l)}…
  10. 10

    slog.Info("auth ok", "user", u) положил живой bearer-токен в хранилище логов, а эта структура логируется из десятка мест. Где это чинится один раз?

    Дайте типу метод LogValue() slog.Value: slog.LogValuer разрешается хендлером в момент вывода, поэтому вычищенный вид выдаёт любое место, где это значение логируют.

    type Token string // Resolved by the handler at output time, everywhere this value is logged.func (Token) LogValue() slog.Value { return slog.StringValue("REDACTED") } type User struct {…
  11. 11

    Один неудачный поход в базу даёт пять строк ERROR и пять инкрементов счётчика ошибок, по одному на слой. Какое здесь правило и где место единственной строке лога?

    Обработайте ошибку один раз: либо залогируйте, либо верните, но не то и другое. Каждый слой добавляет контекст обёрткой fmt.Errorf("load order %s: %w", id, err), а единственную запись пишет самая внешняя граница.

    // wrong: logged here, and again by every caller abovefunc (r *Repo) load(ctx context.Context, id string) (Order, error) {	var o Order	if err := r.db.QueryRowContext(ctx, q, id).Scan(&o.ID); err != nil {		slog.ErrorContext(ctx, "query failed", "err", err)		return Order{}, err…
  12. 12

    Этот хендлер обслуживает первый запрос и падает на каждом следующем. Что происходит и где нужно создавать счётчик?

    func (s *Server) handleOrder(w http.ResponseWriter, r *http.Request) {	orders := prometheus.NewCounter(prometheus.CounterOpts{		Name: "orders_created_total",		Help: "Orders created.",	})	prometheus.MustRegister(orders) 	if err := s.create(r.Context(), r); err != nil {		http.Error(w, "create failed", http.StatusInternalServerError)		return	}	orders.Inc()	w.WriteHeader(http.StatusCreated)}

    Второй вызов prometheus.MustRegister паникует с duplicate metrics collector registration attempted, потому что счётчик с таким именем уже есть в дефолтном реестре.

  13. 13

    Как выбрать бакеты гистограммы для задержки запросов и почему верхний бакет по умолчанию искажает p99?

    Ставьте границы бакетов вокруг SLO и за таймаут: квантиль интерполируется внутри бакета, поэтому с верхней границей по умолчанию в 10 с плохой p99 выглядит как «около десяти секунд».

    var latency = prometheus.NewHistogramVec(prometheus.HistogramOpts{	Name: "http_request_duration_seconds",	// Boundaries around the SLO (300ms) and out past the timeout (10s),	// so the p99 does not saturate at the last bucket.	Buckets: []float64{.005, .01, .025, .05, .1, .2, .3, .5, 1, 2.5, 5, 10, 30},…
  14. 14

    Найдите баг: гистограмма задержек checkout кладёт каждый запрос в самый нижний бакет, включая те, на которых клиенты отваливаются по таймауту.

    var checkoutDuration = promauto.NewHistogram(prometheus.HistogramOpts{	Name:    "checkout_duration_seconds",	Help:    "Checkout handler latency.",	Buckets: []float64{.05, .1, .3, .5, 1, 2.5, 5, 10},}) func (s *Server) handleCheckout(w http.ResponseWriter, r *http.Request) {	start := time.Now()	defer checkoutDuration.Observe(time.Since(start).Seconds()) 	if err := s.checkout(r.Context(), r); err != nil {		http.Error(w, "checkout failed", http.StatusInternalServerError)		return	}	w.WriteHeader(http.StatusCreated)}

    Аргументы отложенного вызова вычисляются в момент defer, поэтому time.Since(start) берётся сразу после установки start: каждый запрос записывается как примерно ноль секунд, p99 выглядит идеально, а алерт по задержке не сработает никогда.

  15. 15

    Запрос вернул 500, а его спан в трейсе зелёный. Что код не сделал и чем span.RecordError отличается от span.SetStatus?

    span.RecordError(err) добавляет только событие-исключение; статус спана остаётся Unset, пока вы не вызовете span.SetStatus(codes.Error, err.Error()), а красит, фильтрует и алертит бэкенд именно по статусу.

    var tracer = otel.Tracer("github.com/acme/orders") func (s *Service) Load(ctx context.Context, id string) (Order, error) {	// Attributes at Start are visible to the sampler; later ones are not.	ctx, span := tracer.Start(ctx, "OrderService.Load",		trace.WithAttributes(attribute.String("order.id", id)))…
  16. 16

    В трейсе спан запроса из репозитория висит соседом GetOrder, а не его ребёнком, а неудачные поиски не появляются вовсе. Почему?

    func (s *Service) GetOrder(ctx context.Context, id string) (Order, error) {	_, span := tracer.Start(ctx, "GetOrder") 	o, err := s.repo.Find(ctx, id) // repo starts its own "db.query" span from ctx	if err != nil {		return Order{}, fmt.Errorf("get order %s: %w", id, err)	} 	span.End()	return o, nil}

    Два бага: ctx, который вернул tracer.Start, выброшен, поэтому спан репозитория цепляется к родителю GetOrder; а span.End() вызывается только при успехе, так что каждый неудачный поиск оставляет спан, который никогда не закрывается и не экспортируется.

  17. 17

    Оба сервиса работают с SDK OpenTelemetry, но нижний заводит совершенно новый трейс на каждый запрос, который присылает гейтвей. Чего не хватает?

    Пропагатор в Go SDK по умолчанию пустой: пока вы не вызовете otel.SetTextMapPropagator(...) (причём в обоих процессах), заголовок W3C traceparent никто не пишет и не читает.

    func initPropagation() {	// Without this the SDK propagates nothing at all.	otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator(		propagation.TraceContext{}, // W3C traceparent / tracestate		propagation.Baggage{},	))…
  18. 18

    Что решает каждая из проб (liveness, readiness и startup) и что каждая из них должна проверять в Go-сервисе?

    Liveness решает, перезапустить ли контейнер, readiness определяет, пускать ли на под трафик, а startup-проба придерживает обе, пока не закончится медленная инициализация.

    type Probes struct {	started  atomic.Bool  // set once config, caches and pools are ready	draining atomic.Bool  // set on SIGTERM	lastTick atomic.Int64 // unix nanos, set at start and bumped by the worker loop}…
  19. 19

    Каждый роллинг-деплой теряет несколько запросов, хотя сервис вызывает srv.Shutdown по SIGTERM. Что в этот момент делает Kubernetes и как это переждать?

    SIGTERM и удаление пода из эндпоинтов Service происходят одновременно, а не по очереди, и удаление за секунды доходит до kube-proxy и балансировщиков, а они всё это время шлют трафик в сервер, который Shutdown уже закрыл.

  20. 20

    Лейбл user_id на http_requests_total оставил Prometheus с четырьмя миллионами рядов и запросами, падающими по таймауту. Почему один лейбл так дорог и как его ограничить?

    Каждая уникальная комбинация значений лейблов образует отдельный временной ряд: свои записи в индексе, свои чанки на диске.

    func metrics(next http.Handler) http.Handler {	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {		rec := &statusRecorder{ResponseWriter: w, status: http.StatusOK}		next.ServeHTTP(rec, r) 		route := r.Pattern // set by the mux while routing: read it after next…
  21. 21

    Двадцатисекундное моргание базы превратилось в четырёхминутный простой сервиса, чья readiness-проба пингует эту базу. Откуда взялись остальные три с половиной минуты?

    Все реплики разом завалили пробу, и у Service не осталось эндпоинтов: они вернулись только после успешных проб, когда поды переподключили пулы и прогрелись, а шквал переподключений замедлил только что поднявшуюся базу.

  22. 22

    Вы сэмплируете 1% трейсов на входе (head-based), и девятисекундного оформления заказа клиента в бэкенде нет. На что отвечает 1% и что изменил бы tail-сэмплинг?

    Head-сэмплер решает на корневом спане, до того как случилось что-то интересное, поэтому редкий медленный запрос выживает только по удаче: 1% отвечает про форму трафика, но никогда не скажет про «вот этот запрос».

    func provider(exp sdktrace.SpanExporter) *sdktrace.TracerProvider {	return sdktrace.NewTracerProvider(		sdktrace.WithBatcher(exp),		// ParentBased: only a root flips the coin; downstream follows traceparent.		sdktrace.WithSampler(sdktrace.ParentBased(sdktrace.TraceIDRatioBased(0.01))),	)…
  23. 23

    В 14:05 p99 вырос втрое при ровном CPU и без деплоев. Как в проде дойти от дашборда до медленного места в коде и что должно быть готово заранее для pprof?

    Утроившийся p99 при ровном CPU означает ожидание, а не вычисления: сужайте по уже готовым лейблам, откройте один трейс из медленного бакета и берите профиль block, mutex или goroutine, а не CPU.

    // Importing this package registers its handlers on http.DefaultServeMux from// its init(), which is exactly why the public server must never use that mux.import "net/http/pprof" func startDebug() *http.Server {	mux := http.NewServeMux() // our own mux, registered explicitly…
  24. 24

    Вас будят в три ночи алерты CPU > 80% и p99 > 500ms, которые гаснут раньше, чем кто-то посмотрит, а настоящая двухчасовая деградация не разбудила никого. Как переделать алертинг?

    Будят по симптому, который чувствует пользователь, измеренному как скорость сжигания бюджета ошибок относительно SLO, и никогда по причине. Алерт обязан отвечать, не тратится ли бюджет быстрее допустимого: это скорость за окно, а не значение в моменте.

    groups:  - name: orders-slo    rules:      - record: orders:error_ratio:rate5m        expr: |          sum(rate(http_requests_total{job="orders",status="5xx"}[5m]))…