«Кажется, тупит сеть. Посмотрите?» — как мы мониторим летенси в Ingress / Хабр

Привет, на связи Денис Крашенинников, SRE Lead Mindbox. В этой статье я расскажу, как мы мониторим летенси в Ingress.

В 2023 году к нам регулярно приходили разработчики с вопросом: «Кажется, тупит сеть. Посмотрите?» Вопросы были по делу, но каждый раз отвечать было сложно. Лучшее, что мы могли посмотреть, выстраивая графики по логам, — это тайминги HAProxy. Но, если под HAProxy лежит не само приложение, а кубовый Ingress, API-gate и еще несколько компонентов, эти тайминги едва ли помогают с диагностикой.

Когда тойл от подобных вопросов превысил разумные пределы, мы решили разработать SLO на летенси в Ingress. Но оказалось, что это не так уж просто:

Часть нашей Ingress-инфраструктуры не поддерживает трейсинг из коробки.
Сам по себе трейсинг не решил бы проблему: нам нужно не просто искать самые длинные трейсы, а находить среди них именно те, где подвел Ingress. Причем так, чтобы дебажить было удобно.

От облака до ЦОДа: выделяем участки для покрытия SLO

Сначала расскажу, как устроена наша инфраструктура в части некоторых синхронных запросов и что конкретно мы хотели покрыть SLO.

Как видно на схеме, у нас не нативный Kubernetes Ingress стэк. Кроме того, он разделен на Ingress до Kubernetes и Ingress в Kubernetes. А это дополнительные узлы, где что-то может пойти не так. Еще есть интерконнект от облака до ЦОДа — самый неконтролируемый участок сети на тот момент. Надежных метрик качества сигнала на этих линках не было, а про рефлектограмму провайдер и вовсе слышать не хотел. Даже наш самописный API-gate, как оказалось, не так-то просто покрыть полезными спанами. .NET до 9 версии не имел инструментов детализации спанов HTTP-клиента, рисовал просто POST-запрос, внутри которого скрывалось всякое страшное.

В итоге надо было покрыть трейсингом следующий стек:

HAProxy,
Traefik,
.NET-приложения.

«Нам нужно больше спанов!» — что и как измеряем

Сам по себе трейсинг проблему измерения летенси Ingress не решал. Нужно было определиться с метриками, кот��рые будут отражать эти задержки.

Какое коробочное open source решение для генерации метрик из трейсов ни выбери, набор этих метрик будет примерно одинаковый:

длительность трейса целиком;
длительность отдельных cпанов в тех срезах, которые можно прокинуть в атрибуты спанов/трейсов.

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

От рутового спана на HAProxy API до входящего спана нашего API-gate.
От исходящего спана на API-gate до входящего спана в CDP.

В таком случае для рассчета SLO можно было использовать формулу: $(p99RootSpan - p99ApiGateServerSpan) + (p99ApiGateClientSpan - p99CdpServerSpan) \\= p99TotalIngressLatency$

То есть все время, что трейс проводит не в приложении с бизнес-логикой, — это затраты на инфраструктуру Ingress. Время в API-gate тоже относим к полезной бизнесовой нагрузке. Вроде бы выглядит валидно, но мы не учли буферизацию запросов до полной загрузки пэйлоада от клиентов. Это тоже своего рода полезная нагрузка, и ее тоже нужно исключать из p99TotalIngressLatency.

В тот момент буферизация была организована не на HAProxy API, а глубже — в Traefik API, но тогда мы решили не двигать ее ближе к клиенту, а просто исключили этот спан из рассчета летенси Ingress. И получили такую формулу: $(p99RootSpan - p99BufferingSpan - p99ApiGateServerSpan) + (p99ApiGateClientSpan \\- p99CdpServerSpan) = p99TotalIngressLatency$

Кто-то может сказать, что формула математически неверная, и будет абсолютно прав! Но к этому вопросу мы вернемся в блоке «Считаем SLO: меняем формулу и добавляем ClickHouse».

Добавляем трейсинг: HAProxy, Traefik и .NET-приложения

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

HAProxy

HAProxy — первый управляемый узел, через который клиент подключается к нашему приложению. Сейчас про трейсинг на HAProxy можно нагуглить много разных решений: от lua-скриптов до плагинов, хотя полноценной поддержки так и не появилось. В 2023 году на эту тему в гугле был только OpenTracing filter аддон. Но стоило лишь взглянуть на результаты тестов HAProxy с ним, пользоваться им сразу расхотелось: перформанс резко падал. Все, что я смог тогда найти полезного, — вот этот GithubGist: Creating opentelemetry tracing data from an haproxy access log. Как видим из названия, в нем описывается создание трейсов из логов HAProxy. Подход показался нам интересным, и мы решили попробовать, переделав на свой лад. В итоге пришли к такому конфигу на стороне HAProxy:

### Tracing beg

acl trace_sampled_earlier req.hdr(uber-trace-id) -m found
http-request set-var(txn.uber) req.hdr(uber-trace-id)

# trace_sampled_earlier true
http-request set-var(txn.server_parentspanid) req.hdr(uber-trace-id),'regsub("^([^:]+):([^:]+):([^:]+):([^:]+)$","\2",)' if trace_sampled_earlier
http-request set-var(txn.trace_id) req.hdr(uber-trace-id),'regsub("^([^:]+):([^:]+):([^:]+):([^:]+)$","\1",)' if trace_sampled_earlier
http-request set-var(txn.trace_sampled) req.hdr(uber-trace-id),'regsub("^([^:]+):([^:]+):([^:]+):([^:]+)$","\4",)' if trace_sampled_earlier

# trace_sampled_earlier false
http-request set-var(txn.trace_id) uuid(),lower,'regsub("^([^-]+)-([^-]+)-([^-]+)-([^-]+)-([^-]+)$","\1\2\3\4\5",)' unless trace_sampled_earlier
http-request set-var(txn.server_parentspanid) str("0") unless trace_sampled_earlier
http-request set-var(txn.trace_sampled) str("1") unless trace_sampled_earlier

# common
http-request set-var(txn.server_span_id) uuid(),lower,'regsub("^([^-]+)-([^-]+)-([^-]+)-([^-]+)-([^-]+)$","\1\2\3",)'
http-request set-var(txn.client_span_id) uuid(),lower,'regsub("^([^-]+)-([^-]+)-([^-]+)-([^-]+)-([^-]+)$","\1\2\3",)'
http-request set-header uber-trace-id  %[var(txn.trace_id)]:%[var(txn.client_span_id)]:%[var(txn.server_span_id)]:%[var(txn.trace_sampled)]

### Tracing fin

В данном случае мы пришли к uber-trace-id, потому что остальную инфраструктуру подружить легче всего оказалось именно с ним. По сути нам надо было перехватить, а затем собрать себе хедер uber-trace-id с таким содержанием $\{trace-id\}:\{span-id\}:\{parent-span-id\}:\{sampledbool\}$ , где:

trace-id — уникальный ID для всего трейса. В первую очередь по нему определяется принадлежность спанов к той или иной цепочке. Его нужно брать из хедера, с которым пришел запрос. Если в запросе пусто, то это рутовый спан, и нужно создать новый Trace ID.
span-id — уникальный ID для конкретного спана. Помимо просто уникального trace-id, span-id нужен для определения взаимосвязей между трейсами. Тут нам всегда нужно генерить уникальный.
parent-span-id — ID спана, предшествующего текущему. Необходим, чтобы определять взаимосвязи между трейсами. Если это рутовый спан, то пишем 0. В противном случае берем из перехваченного хедера. Важно вспомнить, что в трейсинге спаны делятс�� на Server и Client. Так что если это не последний спан в трейсе, что на прокси едва ли возможно, то попадает сюда span-id из Server спана этой же HAProxy. Само собой, в зависимости от стандарта, есть еще Internal спаны, но они нам тут не интересны.
sampledbool — сюда ставим 1 или 0. Это зависит от того, хотим ли, чтобы этот трейс собирался и трекался дальше. В примере он всегда равен единице. За исключением тех случаев, когда наша гейтовая HAProxy каким-то образом оказалась не рутовым спаном. В этом случае там уже проставлен 0. Тут же можно реализовать и сабсемплинг. Примеры ниже.

Для сабсемплинга 1% запросов конфиг выглядел бы вот так

### Tracing beg

http-request set-var(txn.randomint) rand(100)
acl subsampling var(txn.randomint) -m int 0
acl trace_sampled_earlier req.hdr(uber-trace-id) -m found
http-request set-var(txn.uber) req.hdr(uber-trace-id)

# trace_sampled_earlier true
http-request set-var(txn.server_parentspanid) req.hdr(uber-trace-id),'regsub("^([^:]+):([^:]+):([^:]+):([^:]+)$","\2",)' if trace_sampled_earlier
http-request set-var(txn.trace_id) req.hdr(uber-trace-id),'regsub("^([^:]+):([^:]+):([^:]+):([^:]+)$","\1",)' if trace_sampled_earlier
http-request set-var(txn.trace_sampled) req.hdr(uber-trace-id),'regsub("^([^:]+):([^:]+):([^:]+):([^:]+)$","\4",)' if trace_sampled_earlier

# trace_sampled_earlier false
http-request set-var(txn.trace_id) uuid(),lower,'regsub("^([^-]+)-([^-]+)-([^-]+)-([^-]+)-([^-]+)$","\1\2\3\4\5",)' unless trace_sampled_earlier
http-request set-var(txn.server_parentspanid) str("0") unless trace_sampled_earlier
http-request set-var(txn.trace_sampled) str("0") if !trace_sampled_earlier !subsampling
http-request set-var(txn.trace_sampled) str("1") if !trace_sampled_earlier subsampling

# common
http-request set-var(txn.server_span_id) uuid(),lower,'regsub("^([^-]+)-([^-]+)-([^-]+)-([^-]+)-([^-]+)$","\1\2\3",)'
http-request set-var(txn.client_span_id) uuid(),lower,'regsub("^([^-]+)-([^-]+)-([^-]+)-([^-]+)-([^-]+)$","\1\2\3",)'
http-request set-header uber-trace-id  %[var(txn.trace_id)]:%[var(txn.client_span_id)]:%[var(txn.server_span_id)]:%[var(txn.trace_sampled)]

### Tracing fin

Для сабсемплинга по роутам это выглядело бы вот так

### Tracing beg

acl trace_sampled_earlier req.hdr(uber-trace-id) -m found
acl tracing_path path -m beg /abc /bca /cba
http-request set-var(txn.uber) req.hdr(uber-trace-id)

# trace_sampled_earlier true
http-request set-var(txn.server_parentspanid) req.hdr(uber-trace-id),'regsub("^([^:]+):([^:]+):([^:]+):([^:]+)$","\2",)' if trace_sampled_earlier
http-request set-var(txn.trace_id) req.hdr(uber-trace-id),'regsub("^([^:]+):([^:]+):([^:]+):([^:]+)$","\1",)' if trace_sampled_earlier
http-request set-var(txn.trace_sampled) req.hdr(uber-trace-id),'regsub("^([^:]+):([^:]+):([^:]+):([^:]+)$","\4",)' if trace_sampled_earlier

# trace_sampled_earlier false
http-request set-var(txn.trace_id) uuid(),lower,'regsub("^([^-]+)-([^-]+)-([^-]+)-([^-]+)-([^-]+)$","\1\2\3\4\5",)' unless trace_sampled_earlier
http-request set-var(txn.server_parentspanid) str("0") unless trace_sampled_earlier
http-request set-var(txn.trace_sampled) str("0") if !trace_sampled_earlier !tracing_path
http-request set-var(txn.trace_sampled) str("1") if !trace_sampled_earlier tracing_path

# common
http-request set-var(txn.server_span_id) uuid(),lower,'regsub("^([^-]+)-([^-]+)-([^-]+)-([^-]+)-([^-]+)$","\1\2\3",)'
http-request set-var(txn.client_span_id) uuid(),lower,'regsub("^([^-]+)-([^-]+)-([^-]+)-([^-]+)-([^-]+)$","\1\2\3",)'
http-request set-header uber-trace-id  %[var(txn.trace_id)]:%[var(txn.client_span_id)]:%[var(txn.server_span_id)]:%[var(txn.trace_sampled)]

### Tracing fin

У нас классическая инфраструктура сбора логов: на HAProxy поднят Vector, который читает лог и пишет его в Kafka. Затем этот лог из Kafka забирает хранилка логов. Очевидно, что самый простой способ трансформировать лог в спан и отправлять в сборщик трейсов — это подписаться на ту же Kafka. Так как Vector в схеме уже есть, его и выбрали в роли перекладывателя и трансформатора. В схеме без Kafka можно было бы прямо в одном месте сделать пуш лога в хранилище логов и трейса в хранилище трейсов.

Интересная часть конфига выглядит так

customConfig:
  data_dir: /vector-data-dir
  sinks:
    sending_traces_client:
      encoding:
        codec: json
      inputs:
      - edit_fields_client
      method: post
      type: http
      uri: http://opentelemetry-collector.ingress-slo.svc.cluster.local:9411/
    sending_traces_server:
      encoding:
        codec: json
      inputs:
      - edit_fields_server
      method: post
      type: http
      uri: http://opentelemetry-collector.ingress-slo.svc.cluster.local:9411/
    vector_exporter:
      address: 0.0.0.0:9090
      inputs:
      - vector_metrics
      type: prometheus_exporter
  sources:
    kafka_source:
      bootstrap_servers: "{{ $.Values.brokers }}"
      group_id: vector-{{ $.Values.instanceName }}
      topics:
        - "{{ $.Values.topic }}"
      type: kafka
      auto_offset_reset: largest
      fetch_wait_max_ms: 1000
      commit_interval_ms: 1000
      socket_timeout_ms: 100000
      librdkafka_options:
        fetch.min.bytes: "1000"
        fetch.message.max.bytes: "30048576"
        fetch.max.bytes: "502428800"
        reconnect.backoff.ms: "5000"
        enable.auto.offset.store: "false"
        max.poll.interval.ms: "600000"
        session.timeout.ms: "90000"
      decoding:
        codec: json
    vector_metrics:
      type: internal_metrics
  transforms:
    edit_fields_base:
      inputs:
      - filter_logs
      source: |
        .localEndpoint = { "serviceName": "{{ .Values.instanceName }}" }
        for_each(.)->|key,value|{
          if starts_with(key, "haproxy") {
            .tags = set!(.tags, [key], to_string!(value))
            . = remove!(., [key])
          }
          if match(key, r'haproxy_FrontendCurrentConn|haproxy_Timestamp|haproxy_actconn|haproxy_backendCurrentConn|haproxy_backendQueue|haproxy_backendSourcePort|haproxy_bytes|haproxy_capturedHttpRequestReferer|haproxy_capturedHttpRequestUserAgent|haproxy_capturedRequestHeaders|haproxy_clientPort|haproxy_dateTime|haproxy_frontendNameTransport|haproxy_frontendPort|haproxy_httpRequestMethod|haproxy_httpRequestURI|haproxy_serverPort|haproxy_ssl') {
            .tags = remove!(.tags, [key])
            . = remove!(., [key])
          }
          if match(key, r'traceSampled|operation|endpointId|fluentbit|@timestamp|^time$|date|Content-Length|partition|offset|pri|topic|ident|pid|Content-Type|Accept|host|message|headers|source_type|uber-trace-id|endpointExternalId') {
            . = remove!(., [key])
          }
        }
      type: remap
    edit_fields_client:
      type: remap
      inputs:
      - edit_fields_base
      source: |
        .kind = "CLIENT"
        .id = .client_id
        .parentId = .server_id
        .timestamp = (to_int!(.timestamp_epoch)+ to_int!(.tags.haproxy_Tq) + to_int!(.tags.haproxy_TR)) * 1000
        if .server_parentId == "0" {
            .duration = (to_int!(.tags.haproxy_Tt) - to_int!(.tags.haproxy_Tq) - to_int!(.tags.haproxy_Td)) * 1000
          } else {
            .duration = (to_int!(.tags.haproxy_Tt) - to_int!(.tags.haproxy_Tq)) * 1000
          }
        del(.client_id)
        del(.server_id)
        del(.server_parentId)
        del(.timestamp_epoch)
    edit_fields_server:
      type: remap
      inputs:
      - edit_fields_base
      source: |
        .kind = "SERVER"
        .id = .server_id
        if (exists(.server_parentId) && .server_parentId != "0") {
          .parentId = .server_parentId
        }
        .timestamp = (to_int!(.timestamp_epoch) + to_int!(.tags.haproxy_Tq)) * 1000
        if .server_parentId == "0" {
            .duration = (to_int!(.tags.haproxy_Tt) - to_int!(.tags.haproxy_Tq) - to_int!(.tags.haproxy_Td) + to_int!(.tags.haproxy_TR)) * 1000
          } else {
            .duration = (to_int!(.tags.haproxy_Tt) - to_int!(.tags.haproxy_Tq)) * 1000
          }
        del(.client_id)
        del(.server_id)
        del(.server_parentId)
        del(.timestamp_epoch)
    filter_logs:
      condition: .traceSampled == "1"
      inputs:
      - kafka_source
      type: filter

Самое интересное кроется в подсчете duration для спана, его мы считаем по-разному для клиентского и серверного спанов HAProxy. Сейчас в эту разницу попадает буферизация, которую мы наконец вынесли на HAProxy, а раньше серверный и клиентский спаны были практически идентичны.

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

Traefik

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

tracing:
  jaeger:
    propagation: jaeger
    collector:
      endpoint: http://opentelemetry-collector.ingress-slo.svc.cluster.local:14268/api/traces?format=jaeger.thrift
    samplingParam: 0
    samplingType: const

Начиная с версии 3.0, Traefik отказался от поддержки всех стандартов трейсинга, кроме OpenTelemetry, так что скоро нам предстоит чуть переработать весь пропагейтинг в нашем трейсинге.

.NET

Здесь ничего особо не расскажу, ведь статья для SRE, которые вряд ли захотят читать C#-код. Важно, что мы вытащили интересующий нас минимум: спаны на входящий и исходящий HTTP-запрос.

Увидев, что исходящие спаны в 99-м перцентиле получаются очень длинными, мы захотели сделать их подробнее, но не вышло. Седьмая версия .NET не поддерживала детализацию спанов HTTP-клиента. Но по коду библиотеки мы и так понимали, на что уходит время. В основном, на ожидание слота в connection pool и DNS резолв хоста, к которому идет обращение.

Кстати, девятая версия .NET уже поддерживает спаны, по которым спустя пару лет мы и подтвердили свои догадки.

Финалим инфру: где хранятся трейсы

Теперь все эти трейсы нужно было куда-то сгрузить. Учитывая, что в первую очередь нас интересуют метрики по множеству трейсов, а не какие-то конкретные, требований к хранилищу было не так много, поэтому мы выбрали Grafana Tempo просто за приятный интерфейс и удобную интеграцию с Grafana. И наконец мы можем посмотреть, что же за трейс у нас собрался:

Периодически дочерняя операция чуть съезжает по временной оси, но это не страшно: у нас не высокочастотный трейдинг, так что в атомные часы и PTP мы не инвестируем

А вот чтобы пощупать генераторы метрик, мы пробовали тонну разных инструментов. Но на тот момент у них всех был примерно одинаковый функционал. В итоге генерить метрики оказалось удобней не из хранилища трейсов, а прямо на агрегаторе, а именно на OpenTelemetry Collector.

Так мы теперь генерируем и храним трейсы и метрики

Считаем SLO: меняем формулу и добавляем ClickHouse

Когда у нас появились все нужные спаны, пора было загнать их в формулу и посмотреть, что получится. Напомню, формула выглядела так: $(p99RootSpan - p99BufferingSpan - p99ApiGateServerSpan) + (p99ApiGateClientSpan \\- p99CdpServerSpan) = p99TotalIngressLatency$

Получилась полнейшая ерунда! Мало того, что Prometheus не справлялся с таким объемом гистограмм, так и p99TotalIngressLatency получился таким, что к нему не было никакого доверия: его значения скакали от −200 до 500 мс.

Именно минус 200. Выходило, что мы получили метрику, которая периодически возвещает, что наша сеть превосходит принципы пространственно-временного континуума и ускоряет обработку запроса на 200 мс.

Еще до получения этой метрики мы понимали, что от складывания или вычитания перцентилей не получится честный перцентиль на выходе. Но видеть отрицательные значения было неприятно. Мы планировали доверять этой метрике и строить на ней SLO, даже зная, что она математически неправильная, так как альтернатив тогда еще не придумали.

Стало понятно, что нам нужно считать задержку на каждый отдельный трейс, и из получившихся значений уже сможем взять перцентиль. И наша формула должна выглядеть так: $p99((RootSpan - BufferingSpan - ApiGateServerSpan) + (pApiGateClientSpan \\- CdpServerSpan)) = p99TotalIngressLatency$

Оставалось понять, как это сделать, ведь все доступные инструменты для генерации метрик из трейсов оперируют на уровне спанов. А те метрики, которые можно получить на уровне трейсов из хранилок вроде Grafana Tempo, едва ли были полезны.

Собрав на брейншторм лучшие умы команды, мы придумали сгружать все эти метрики в Clickhouse, прикрутить к нему prometheus-sql-exporter и получать нужные метрики, делая запросы в базу.

Запрос, считающий p99TotalIngressLatency, получился такой

WITH
  NetworkLatencies AS
  (
    SELECT
        TraceId,
        max(Timestamp) AS EndTimestamp,
        maxIf(
          Duration,
          ParentSpanId = ''
          AND NOT match(SpanAttributes['haproxy_terminationState'], '^[Cc]')
        ) AS TotalDuration,
        maxIf(
          Duration,
          ServiceName LIKE 'traefik-api%' 
          AND SpanName = 'traefik-api-operations-api-buffering@kubernetescrd'
        ) AS TraefikBufferingMiddlewareDuration,
        maxIf(
          Duration,
          ServiceName LIKE 'traefik-api%'
          AND SpanKind = 'SPAN_KIND_CLIENT'
        ) AS OperationsApiClientDuration,
        maxIf(
          Duration,
          ServiceName = 'operations-api-sync'
          AND ScopeName = 'Microsoft.AspNetCore'
        ) AS OperationsApiDuration,
        maxIf(
          Duration,
          ServiceName = 'operations-api-sync'
          AND ScopeName = 'System.Net.Http'
          AND SpanAttributes['url.full'] LIKE '%/actions'
        ) AS CdpClientDuration,
        maxIf(
          Duration,
          ServiceName = 'cdp-services'
          AND ScopeName = 'Microsoft.AspNetCore'
        ) AS CdpDuration,
        TraefikBufferingMiddlewareDuration - OperationsApiClientDuration AS RequestBodyBufferingLatency,
        (TotalDuration - RequestBodyBufferingLatency - OperationsApiDuration) + (CdpClientDuration - CdpDuration) AS NetworkOverhead
    FROM otel.otel_traces
    WHERE Timestamp BETWEEN (now() - INTERVAL 180 SECOND) AND (now() - INTERVAL 60 SECOND)
      AND TraceId IN (
          SELECT TraceId
          FROM otel.otel_traces
          WHERE ServiceName = 'operations-api-sync' 
            AND SpanKind = 'SPAN_KIND_CLIENT'
            AND Timestamp BETWEEN (now() - INTERVAL 180 SECOND) AND (now() - INTERVAL 60 SECOND)
          GROUP BY TraceId
          HAVING COUNT(*) = 1
      )
    GROUP BY TraceId
    HAVING 
      TotalDuration > OperationsApiDuration
      AND OperationsApiDuration > 0
      AND CdpClientDuration > CdpDuration
      AND CdpDuration > 0
      AND TraefikBufferingMiddlewareDuration > OperationsApiClientDuration
      AND OperationsApiClientDuration > 0
  )
SELECT
    toInt32(quantile(0.99)(NetworkOverhead) / 1000000) AS p99,
    toInt32(quantile(0.95)(NetworkOverhead) / 1000000) AS p95,
    toInt32(quantile(0.9)(NetworkOverhead) / 1000000) AS p90,
    toInt32(quantile(0.5)(NetworkOverhead) / 1000000) AS p50,
    toInt32(quantile(0.99)(RequestBodyBufferingLatency) / 1000000) AS request_body_buffering_latency_p99,
    count() AS sample_count
FROM NetworkLatencies
WHERE EndTimestamp BETWEEN (now() - INTERVAL 120 SECOND) AND (now() - INTERVAL 60 SECOND);

Этот запрос предполагает, что буферизация запросов организована на стороне Traefik, как это было у нас раньше.

Теперь буферизация переехала на HAProxy, и актуальный запрос выглядит так

WITH
  TraceRoots AS (
    SELECT
        TraceId,
        anyIf(SpanId, ParentSpanId = '') AS RootSpanId
    FROM otel.otel_traces
    WHERE Timestamp BETWEEN (now() - INTERVAL 180 SECOND) AND (now() - INTERVAL 60 SECOND)
    GROUP BY TraceId
  ),
  NetworkLatencies AS
  (
    SELECT
        t.TraceId,
        t.RootSpanId,
        max(ot.Timestamp) AS EndTimestamp,
        maxIf(
          ot.Duration,
          ot.ParentSpanId = ''
          AND NOT match(ot.SpanAttributes['haproxy_terminationState'], '^[Cc]')
        ) AS TotalDurationWithBuffer,
        maxIf(
          ot.Duration,
          ot.ParentSpanId = t.RootSpanId
          AND NOT match(ot.SpanAttributes['haproxy_terminationState'], '^[Cc]')
        ) AS TotalDuration,

        maxIf(
          ot.Duration,
          ot.ServiceName LIKE 'traefik-api%'
          AND ot.SpanKind = 'SPAN_KIND_CLIENT'
        ) AS OperationsApiClientDuration,
        maxIf(
          ot.Duration,
          ot.ServiceName = 'operations-api-sync'
          AND ot.ScopeName = 'Microsoft.AspNetCore'
        ) AS OperationsApiDuration,
        maxIf(
          ot.Duration,
          ot.ServiceName = 'operations-api-sync'
          AND ot.ScopeName = 'System.Net.Http'
          AND ot.SpanAttributes['url.full'] LIKE '%/actions'
        ) AS CdpClientDuration,
        maxIf(
          ot.Duration,
          ot.ServiceName = 'cdp-services'
          AND ot.ScopeName = 'Microsoft.AspNetCore'
        ) AS CdpDuration,
        TotalDurationWithBuffer - TotalDuration AS RequestBodyBufferingLatency,
        (TotalDuration - RequestBodyBufferingLatency - OperationsApiDuration) + (CdpClientDuration - CdpDuration) AS NetworkOverhead
    FROM otel.otel_traces ot
    JOIN TraceRoots t ON ot.TraceId = t.TraceId
    WHERE ot.Timestamp BETWEEN (now() - INTERVAL 180 SECOND) AND (now() - INTERVAL 60 SECOND)
      AND ot.TraceId IN (
          SELECT TraceId
          FROM otel.otel_traces
          WHERE ServiceName = 'operations-api-sync' 
            AND SpanKind = 'SPAN_KIND_CLIENT'
            AND Timestamp BETWEEN (now() - INTERVAL 180 SECOND) AND (now() - INTERVAL 60 SECOND)
          GROUP BY TraceId
          HAVING COUNT(*) = 1
      )
      AND ot.TraceId NOT IN (
          SELECT DISTINCT TraceId
          FROM otel.otel_traces
          WHERE SpanAttributes['haproxy_statusCode'] = '503'
            AND Timestamp BETWEEN (now() - INTERVAL 180 SECOND) AND (now() - INTERVAL 60 SECOND)
      )
    GROUP BY t.TraceId, t.RootSpanId
    HAVING 
      TotalDuration > OperationsApiDuration
      AND OperationsApiDuration > 0
      AND CdpClientDuration > CdpDuration
      AND CdpDuration > 0
      AND OperationsApiClientDuration > 0
  )
SELECT
    toInt32(quantile(0.995)(NetworkOverhead) / 1000000) AS p995,
    toInt32(quantile(0.99)(NetworkOverhead) / 1000000) AS p99,
    toInt32(quantile(0.95)(NetworkOverhead) / 1000000) AS p95,
    toInt32(quantile(0.9)(NetworkOverhead) / 1000000) AS p90,
    toInt32(quantile(0.5)(NetworkOverhead) / 1000000) AS p50,
    toInt32(quantile(0.99)(RequestBodyBufferingLatency) / 1000000) AS request_body_buffering_latency_p99,
    count() AS sample_count
FROM NetworkLatencies
WHERE EndTimestamp BETWEEN (now() - INTERVAL 120 SECOND) AND (now() - INTERVAL 60 SECOND);

Не утверждаю, что эти запросы написаны эффективно и академически правильно. Когда-то их первую версию написал специалист, хорошо разбирающийся в этих вопросах, но спустя пару лет к ним приложил руку не один ИИ-агент.

Общая задержка Ingress в разных перцентилях: p99 не превышает SLO

Когда мы еще только получили эти метрики, пиковые значения были выше, и мы задались вопросом: как улучшить?

Сначала стоило разобраться, где мы вообще теряем драгоценные миллисекунды. Значит, нужно получить метрики по ключевым отрезкам маршрута, который мы собрались покрывать SLO. Теперь, когда наши трейсы собраны в Clickhouse, от желанной метрики нас отделяет лишь один запрос.

Собственно вот он

WITH
    SpanDurations AS
    (
      SELECT
        Timestamp,
        SpanKind,
        ServiceName,
        SpanKind == 'SPAN_KIND_CLIENT' ? SpanId : ParentSpanId AS ClientSpanId,
        Duration
      FROM otel.otel_traces
      WHERE (Timestamp BETWEEN (now() - INTERVAL 180 SECOND) AND (now() - INTERVAL 60 SECOND))
      HAVING ClientSpanId != ''
    ),
    ClientServerNetworkOverheads AS
    (
      SELECT
        max(Timestamp) AS EndTimestamp,
        ClientSpanId,
        anyIf(ServiceName, SpanKind == 'SPAN_KIND_CLIENT') AS Client,
        anyIf(ServiceName, SpanKind == 'SPAN_KIND_SERVER') AS Server,
        anyIf(Duration, SpanKind == 'SPAN_KIND_CLIENT') - anyIf(Duration, SpanKind == 'SPAN_KIND_SERVER') AS NetworkOverhead
      FROM SpanDurations
      GROUP BY ClientSpanId
      HAVING Client != '' AND Server != '' AND Client != Server
    )
SELECT
  Client AS client,
  Server AS server,
  toInt32(quantile(0.995)(NetworkOverhead) / 1000000) AS p995,
  toInt32(quantile(0.99)(NetworkOverhead) / 1000000) AS p99,
  toInt32(quantile(0.95)(NetworkOverhead) / 1000000) AS p95,
  toInt32(quantile(0.9)(NetworkOverhead) / 1000000) AS p90,
  toInt32(quantile(0.5)(NetworkOverhead) / 1000000) AS p50,
  count() AS sample_count
FROM ClientServerNetworkOverheads
WHERE EndTimestamp BETWEEN (now() - INTERVAL 120 SECOND) AND (now() - INTERVAL 60 SECOND)
GROUP BY Client, Server

Получили время выполнения запросов на ключевых участках Ingress

Теперь мы понимаем, из чего складываются общие миллисекунды, и где нам в первую очередь стоит искать возможности для ускорения Ingress. Но для дебага скоуп все еще широковат. Можно придумать много гипотез, почему мы видим на графике резкий всплеск в том или ином отрезке. Но зачем что-то придумывать, когда мы можем написать очередной запрос в ClickHouse и получить еще более детальные метрики.

Ок, пишем очередной запрос

WITH
    SpanDurations AS
    (
      SELECT
        Timestamp,
        SpanKind,
        ServiceName,
        ResourceAttributes AS ResourceAttributes,
        SpanKind == 'SPAN_KIND_CLIENT' ? SpanId : ParentSpanId AS ClientSpanId,
        Duration
      FROM otel.otel_traces
      WHERE (Timestamp BETWEEN (now() - INTERVAL 180 SECOND) AND (now() - INTERVAL 60 SECOND))
      HAVING ClientSpanId != ''
    ),
    ClientServerNetworkOverheads AS
    (
      SELECT
        max(Timestamp) AS EndTimestamp,
        ClientSpanId,
        anyIf(ServiceName, SpanKind == 'SPAN_KIND_CLIENT') AS Client,
        anyIf(ServiceName, SpanKind == 'SPAN_KIND_SERVER') AS Server,
        anyIf(ResourceAttributes, SpanKind == 'SPAN_KIND_CLIENT') AS ClientAttributes,
        anyIf(Duration, SpanKind == 'SPAN_KIND_CLIENT') - anyIf(Duration, SpanKind == 'SPAN_KIND_SERVER') AS NetworkOverhead
      FROM SpanDurations
      GROUP BY ClientSpanId
      HAVING Client != '' AND Server != '' AND Client != Server
    )
SELECT
  Client AS client,
  Server AS server,
  'node' AS client_attribute_key,
  ClientAttributes[client_attribute_key] AS client_attribute_value,
  toInt32(quantile(0.995)(NetworkOverhead) / 1000000) AS p995,
  toInt32(quantile(0.99)(NetworkOverhead) / 1000000) AS p99,
  toInt32(quantile(0.95)(NetworkOverhead) / 1000000) AS p95,
  toInt32(quantile(0.9)(NetworkOverhead) / 1000000) AS p90,
  toInt32(quantile(0.5)(NetworkOverhead) / 1000000) AS p50
FROM ClientServerNetworkOverheads
WHERE EndTimestamp BETWEEN (now() - INTERVAL 120 SECOND) AND (now() - INTERVAL 60 SECOND) AND client_attribute_value != ''
GROUP BY client, server, client_attribute_value
UNION ALL
SELECT
  Client AS client,
  Server AS server,
  'zone' AS client_attribute_key,
  ClientAttributes[client_attribute_key] AS client_attribute_value,
  toInt32(quantile(0.995)(NetworkOverhead) / 1000000) AS p995,
  toInt32(quantile(0.99)(NetworkOverhead) / 1000000) AS p99,
  toInt32(quantile(0.95)(NetworkOverhead) / 1000000) AS p95,
  toInt32(quantile(0.9)(NetworkOverhead) / 1000000) AS p90,
  toInt32(quantile(0.5)(NetworkOverhead) / 1000000) AS p50
FROM ClientServerNetworkOverheads
WHERE EndTimestamp BETWEEN (now() - INTERVAL 120 SECOND) AND (now() - INTERVAL 60 SECOND) AND client_attribute_value != ''
GROUP BY client, server, client_attribute_value

А чтобы увидеть проблемы не только в срезе атрибутов клиентского спана, но и в срезе атрибутов серверного спана, можно выполнить вот такой запрос

WITH
    SpanDurations AS
    (
      SELECT
        Timestamp,
        SpanKind,
        ServiceName,
        ResourceAttributes AS ResourceAttributes,
        SpanKind == 'SPAN_KIND_CLIENT' ? SpanId : ParentSpanId AS ClientSpanId,
        Duration
      FROM otel.otel_traces
      WHERE (Timestamp BETWEEN (now() - INTERVAL 180 SECOND) AND (now() - INTERVAL 60 SECOND))
      HAVING ClientSpanId != ''
    ),
    ClientServerNetworkOverheads AS
    (
      SELECT
        max(Timestamp) AS EndTimestamp,
        ClientSpanId,
        anyIf(ServiceName, SpanKind == 'SPAN_KIND_CLIENT') AS Client,
        anyIf(ServiceName, SpanKind == 'SPAN_KIND_SERVER') AS Server,
        anyIf(ResourceAttributes, SpanKind == 'SPAN_KIND_SERVER') AS ServerAttributes,
        anyIf(Duration, SpanKind == 'SPAN_KIND_CLIENT') - anyIf(Duration, SpanKind == 'SPAN_KIND_SERVER') AS NetworkOverhead
      FROM SpanDurations
      GROUP BY ClientSpanId
      HAVING Client != '' AND Server != '' AND Client != Server
    )
SELECT
  Client AS client,
  Server AS server,
  'node' AS server_attribute_key,
  ServerAttributes[server_attribute_key] AS server_attribute_value,
  toInt32(quantile(0.995)(NetworkOverhead) / 1000000) AS p995,
  toInt32(quantile(0.99)(NetworkOverhead) / 1000000) AS p99,
  toInt32(quantile(0.95)(NetworkOverhead) / 1000000) AS p95,
  toInt32(quantile(0.9)(NetworkOverhead) / 1000000) AS p90,
  toInt32(quantile(0.5)(NetworkOverhead) / 1000000) AS p50
FROM ClientServerNetworkOverheads
WHERE EndTimestamp BETWEEN (now() - INTERVAL 120 SECOND) AND (now() - INTERVAL 60 SECOND) AND server_attribute_value != ''
GROUP BY client, server, server_attribute_value
UNION ALL
SELECT
  Client AS client,
  Server AS server,
  'zone' AS server_attribute_key,
  ServerAttributes[server_attribute_key] AS server_attribute_value,
  toInt32(quantile(0.995)(NetworkOverhead) / 1000000) AS p995,
  toInt32(quantile(0.99)(NetworkOverhead) / 1000000) AS p99,
  toInt32(quantile(0.95)(NetworkOverhead) / 1000000) AS p95,
  toInt32(quantile(0.9)(NetworkOverhead) / 1000000) AS p90,
  toInt32(quantile(0.5)(NetworkOverhead) / 1000000) AS p50
FROM ClientServerNetworkOverheads
WHERE EndTimestamp BETWEEN (now() - INTERVAL 120 SECOND) AND (now() - INTERVAL 60 SECOND) AND server_attribute_value != ''
GROUP BY client, server, server_attribute_value

Можем визуализировать метрики вплоть до среза по конкретным нодам или зонам доступности облака

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

Применяем визуализацию SLO и ускоряем сеть

Инфраструктура у всех разная, поэтому погружаться в конкретные кейсы не буду. Постараюсь выделить применимые для всех сценарии.

Ручное масштабирование. Спайки и значимый рост летенси случаются днем, а ночью стабилизируются. С большой вероятностью, мы упираемся здесь в производительность. Даже в 2025 году автомасштабирование применимо не везде. Поэтому возможны такие ситуации: мы мигрировали нагрузку между кластерами и забыли предварительно масштабировать Ingress нового кластера. Стоило лишь поскейлить, и спайки на графиках растворились.

Задержка между компонентами ingress до и после скейла

Зональность трафика. Реализация зависит от архитектуры и применяемых технологий. Тем не менее не стоит гонять впустую трафик по зонам доступности облака или ЦОДам геораспределенного кластера. Если трафик пришел в Ingress в зоне А, то всю цепочку до приложения он должен пройти по этой зоне.

Как видно по скриншоту ниже, TAR (Tolopogy Aware Routing) позволяет добиться 0 мс задержки в 50-м перцентиле, а в некоторых случаях и сэкономить на чеке за межзональный трафик в облаке. Поэтому не пользоваться им просто преступление, по крайней мере в Kubernetes, где его настройка максимально проста.

Использование TAR позволяет добиться 0 мс задержки в 50-м перцентиле

DNS. Любой слой, в котором выполняется разрешение DNS-записей, будет существенно зависеть от DNS на уровне 99-го перцентиля.

Для наглядности приведу абсурдный кейс, где малейшее изменение дает значимый результат. У «Яндекс Облака» есть CoreDNS, который поставляется из коробки в менеджед кластерах Kubernetes. Он сделан деплойментом, а не daemonset-ом. При этом скейлится от ЦПУ/НОД в кластере, но не имеет ни одного toleration, что вынуждает поды селиться только на ноды без taint. Подробнее можно почитать в их документации.

В итоге мы получили ситуацию, когда на 30 нодах сидит 100+ реплик CoreDNS, которые регулярно скейлятся вниз/вверх, кеш DNS размазан даже в рамках одной ноды и периодически обнуляется из-за скейла. Простое закрепление реплик в 30 шт. дало нам ~5 мс или 8% от всего слоя в 99-м перцентиле.

Зафиксировали 30 реплик CoreDNS и снизили задержку с ~66 до ~60 мс

Мониторим летенси и реагируем на нарушения SLO

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

Тупящая нода. Классический кейс, когда нода начинает хуже работать. Например, это могут быть шумный сосед или паразитирующая нагрузка. На наших графиках теперь это отлично видно. Чаще всего дежурный просто выводит такую ноду.

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

Деградация зоны. Легко и непринужденно узнаем о неполадках на трассах между зонами «Яндекс Облака». Тут можно только писать в поддержку. К счастью, такие переключения не сильно портят летенси.

Поддержка подтвердила, что проблемы на стороне «Яндекса»

Деградация одной из трасс интерконнекта: самый яркий кейс. Скрин начала деградации приложить не могу, но на картинке ниже видны перцентили задержки при запланированном нашим подрядчиком отключении линка.

После работ подрядчика все стало еще хуже

Самое неприятное здесь, что даже по низким перцентилям (p90/p95) видно, что во время отключения одной из сетевых трасс задержки заметно уменьшились. А задержки в таких перцентилях уже означают не редкие зависания конкретных запросов, а глобальное ухудшение производительности системы.

Такое ровное, небольшое замедление всей системы обычно трудно поймать: ошибок почти нет, всё просто работает чуть медленнее. В этой ситуации помогли графики Ingress SLO: на них проблема была видна лучше всего. Единственная метрика, показавшая наличие проблемы, — метрика времени жизни BGP-сессии интерконнекта, которая с началом деградации начала рваться примерно раз в день по BFD. Но по одному факту разрывов BGP-сессии сложно догадаться о масштабах проблемы.

Как мы позже узнали, это был скол на оптике трассы интерконнекта, и даже провайдер трассы не видел его на своих метриках.

Бонус: как победили плохо работающие сервера за счет метрик Ingress

Монолит — до боли знакомое всем SRE слово. В том или ином виде такое архитектурное решение есть во всех продуктах, но боль оно приносит всем по-разному. В нашем случае — это крайне волатильное потребление CPU, а если еще точнее — кратный бёрст нагрузки на старте.

Наш монолит живет в Kubernetes. И хотя для каждого клиента деплоится отдельный инстанс, живет все это на общих нодах. Так что важно поддерживать актуальные реквесты всех подов. Сделать это сложно, когда на старте под потребляет 2+ CPU, а в остальное время — 0,1–0,3. VPA (Vertical Pod Autoscaler) тут едва ли поможет, так как изменение реквестов повлечет очередной ролаут с бёрстом нагрузки. А почему не стоит использовать лимиты в Kubernetes, наверное, все и так уже знают.

За многие годы жизни нашего монолита мы обложились тонной механизмов по хотя бы частичному решению этой проблемы. Даже приходилось использовать кастомные шедулеры, учитывающие эти бёрсты нагрузки. Но до конца победить так и не смогли, так что подобные статуспейджи продолжали появляться. Поэтому, когда очередной превентивный механизм не спас, решили, что пора улучшить хотя бы реакцию на эти ситуации.

Какая нода «плохая», понять весьма сложно. CPU usage, Load average и прочие — всё это полезные метрики, но в реальности они не отражают, насколько хорошо работается приложению на конкретной ноде. Когда в очередной раз мы попытались придумать новую метрику, которая хорошо коррелирует с производительностью приложения, мы вспомнили, что и так уже собираем максимально бизнесовую метрику. Её ни само приложение, ни нода по отдельности показать не могут. Это и есть тот самый Ingress SLO. В итоге очередным запросом в ClickHouse с трейсами получили нужную метрику.

Нотификация не относится к графику выше. Свежих кейсов с метриками без даунсемплинга не нашлось

Дальше дело уже за малым. Пишем простенький сервис. Он смотрит на эту метрику и при аномалиях выводит ноду, где приложение работает сильно хуже других. Добавляем нотификацию с алертом на это дело, и готово. Теперь «плохая» нода выводится автоматически за пару минут, вне зависимости от скорости реакции дежурного на алерт. А посмотреть, что же там случилось, можно и после.

«Кажется, тупит сеть. Посмотрите?» — как мы мониторим летенси в Ingress