OpenTelemetry на VPS: как связать медленный запрос API с SQL и внешним сервисом

Допустим, клиент жалуется: метод POST /orders/quote отвечает за две секунды, а раньше отвечал заметно быстрее. Вы открываете журнал медленных SQL-запросов и видите, что нужная команда выполнилась за сто с небольшим миллисекунд. Остальная секунда с лишним нигде не записана. Она не принадлежит ни базе, ни, на первый взгляд, коду. Она растворилась между сервисами, и именно такие потери трассировка помогает хотя бы найти на карте.

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

Начинаем с того, что видел клиент

Первая ошибка при разборе — сразу лезть в самый интересный компонент. Отправная точка должна быть там, где измерение ближе всего к человеку: время от входа запроса на границе (обратный прокси, балансировщик или сам HTTP-сервер приложения) до отправки ответа. Если на границе записано 2,0 секунды, это ваш бюджет. Всё, что вы найдёте ниже, должно объяснять именно эти две секунды, а не какие-то другие интервалы.

Чтобы найти нужный запрос в хранилище трасс, нужны опорные признаки: маршрут, примерное время, код ответа, длительность выше порога. Удобно, если идентификатор трассы попадает в заголовок ответа или в строку журнала доступа. Тогда путь «клиент пожаловался — вот его запрос — вот его trace» сокращается до одного копирования. Без этого вы будете искать по фильтру «маршрут и длительность больше секунды» и выбирать из десятка похожих кандидатов. Это тоже работает, но надо помнить, что вы смотрите пример медленного запроса, а не обязательно тот самый.

Если вы только знакомитесь с самой идеей и не уверены, зачем трассы на одном сервере, вводный материал есть в статье OpenTelemetry простыми словами: зачем это на одном сервере. Здесь мы считаем, что приложение уже экспортирует spans, и разбираем чтение.

Один trace — это набор связанных интервалов

Согласно документации OpenTelemetry о трассах, trace состоит из связанных spans, а client span может описывать как исходящий HTTP-запрос, так и обращение к базе данных. Для нашего случая это означает простую раскладку. Корневой span — входящий запрос к API. Внутри него — работа обработчика. Ещё глубже — клиентский span SQL и клиентский span вызова внешнего сервиса, например расчёта доставки или проверки платёжного статуса.

Представим такую картину, придуманную для примера:

Первое, что бросается в глаза: SQL занимает 120 мс, то есть шесть процентов от двух секунд. Вызов внешнего сервиса — 1400 мс. Но спешить с вердиктом «виноват сервис доставки» не стоит, и вот почему.

Что означает длинный client span

Длинный клиентский span говорит ровно одно: с точки зрения вашего приложения операция началась в одно время и завершилась в другое. Он не говорит, чем были заняты эти 1400 мс. Возможных ответов несколько, и они ведут к разным исправлениям:

• внешний сервис действительно медленно считал ответ;
• сетевой путь потерял пакеты или задержал установку соединения;
• ваше приложение ждало свободного соединения из пула, прежде чем реально отправить запрос;
• разрешение имени, TLS-рукопожатие или повторная попытка внутри HTTP-клиента добавили время до первого байта;
• процесс приложения был перегружен, и поток или цикл событий долго не доходил до чтения ответа.

Здесь полезно различать ожидание и активную работу. Span фиксирует интервал, а не загрузку процессора. Если процесс почти всё это время ничего не вычислял, а просто ждал сокета, то прибавка процессорных ядер ничего не изменит. Если же поток был занят чем-то тяжёлым и не успевал обработать готовый ответ, интервал тоже выглядит как «ожидание сервиса», хотя причина внутри вашего процесса. Трассировка даёт границы интервалов; чтобы понять характер времени, нужны дополнительные наблюдения: загрузка процессора и очередь выполнения на VPS, размер пула соединений, внутренние метки внутри span.

В документации описаны span events — отметки о событии внутри интервала. Это как раз инструмент для таких случаев: можно записать событие «соединение получено из пула» или «получен первый байт ответа». Тогда один длинный span разделяется смысловыми точками, и вы видите, что 1100 мс прошло до отправки запроса, а сам обмен занял 300. Какие именно события доступны, зависит от используемой инструментации и вашего кода; то, что их можно добавить вручную, — обычная практика, а не гарантия, что нужные отметки уже есть в вашей библиотеке.

Как контекст добирается до SQL и внешнего вызова

Дерево строится не само собой. Каждый span хранит ссылку на родителя, а между процессами эта ссылка путешествует в заголовках запроса. Внутри одного процесса контекст обычно живёт в текущем контексте выполнения: пока обработчик находится внутри корневого span, новые клиентские spans становятся его дочерними. Для SQL это происходит тогда, когда драйвер или слой доступа к данным инструментирован и вызывается в том же контексте. Для исходящего HTTP-вызова инструментированный клиент дополнительно добавляет заголовок с идентификаторами трассы и родителя, и принимающий сервис, если он поддерживает ту же схему, продолжит trace своим server span.

У этого механизма есть тихие места, где связность ломается без единой ошибки:

• работа переносится в фоновый поток, пул задач или горутину без явной передачи контекста;
• обращение к базе идёт через неинструментированную библиотеку или собственную обёртку;
• прокси или шлюз между сервисами отбрасывает незнакомые заголовки;
• внешний сервис принадлежит чужой организации и просто не участвует в вашей трассе.

Последний пункт важен. Если сервис доставки — сторонний API, продолжения trace на его стороне вы не увидите никогда. Ваш client span останется листом дерева. Это нормально: вы получаете верхнюю границу ожидания с вашей стороны, а не картину внутри чужой системы.

Когда складывать длительности нельзя

Вернёмся к таблице. Сумма дочерних spans: 15 + 120 + 1400 + 40 = 1575 мс. Корень — 2000 мс. Куда делись 425 мс? Тут и начинаются типичные арифметические ловушки.

Во-первых, между spans бывают промежутки, в которых нет ни одного измеренного интервала: код работал без отдельного span, ждал блокировки, сериализовал объект. Эти 425 мс могут быть не пустотой, а непокрытой инструментацией работой. Их стоит рассматривать как вопрос, а не как погрешность.

Во-вторых, spans могут перекрываться. Допустим, приложение вместо последовательных обращений запускает SQL и внешний вызов параллельно. Тогда SQL-интервал 30–150 мс целиком лежит внутри интервала вызова 160–1560 мс? Нет, в нашей таблице они идут друг за другом, но стоит изменить начало SQL на 170 мс — и два интервала частично накладываются. Сумма длительностей превысит реальное время, а вклад каждого в итоговую задержку окажется неочевидным. Правильный способ чтения — смотреть на критический путь: цепочку операций, определяющую момент завершения родителя. Если два вызова идут параллельно, ответ ждёт более медленный из них, а быстрый не добавляет ничего к общему времени.

В-третьих, при повторных попытках внутри клиента один логический вызов может породить несколько spans или один длинный span с несколькими обращениями по сети. Складывать их нужно осмысленно: две попытки по 700 мс — это 1400 мс для вашего запроса, независимо от того, что каждая попытка по отдельности выглядела «умеренной».

Практическое правило: прежде чем делать выводы, найдите на временной шкале ту цепочку, где конец одного span совпадает с началом следующего, и проверьте, покрывает ли она почти всё время корня. Если покрывает — вы нашли главный участок ожидания. Если нет — сначала ищите непокрытый зазор.

Разрыв: когда в дереве чего-то не хватает

Теперь представим вариант, который случается чаще идеального. Вы открываете trace и видите: корень на 2000 мс, внутри обработчик, SQL на 120 мс, а затем — пустота длиной больше секунды. Вызова внешнего сервиса в дереве нет вообще, хотя вы знаете, что код его делает. Либо рядом лежит отдельный trace с другим идентификатором, начинающийся примерно в тот же момент.

Это признак того, что контекст не дошёл до исходящего вызова. Причины обычно прозаичны: вызов выполняется в отдельной задаче без переданного контекста, используется HTTP-клиент без инструментации или его создали до подключения инструментации, и часть обращений идёт мимо неё. Важно не воспринимать такой разрыв как «ничего не было». Время ушло, просто осталось незамеченным.

Диагностика здесь честная и скромная. Сверьте время: нашёлся ли в хранилище trace с корнем на стороне другого сервиса, стартовавший сразу после SQL? Если да, значит, сам сервис трассируется, но заголовок с контекстом не был передан или был потерян по дороге. Если такого trace нет, возможно, вызов вообще не инструментирован. В первом случае чините передачу контекста, во втором — добавляете ручной client span вокруг вызова, чтобы хотя бы увидеть границы интервала.

Для асинхронных случаев в документации описаны span links — связи между причинно связанными операциями, в том числе когда одна не является прямым потомком другой. Если запрос на расчёт кладётся в очередь, а обработка идёт отдельным worker-ом позже, ссылка между spans сохраняет причинную связь, не притворяясь, что это один синхронный вызов. Для нашего двухсекундного ответа это важно тогда, когда часть работы действительно вынесена в очередь, а в ответе клиент ждёт результат: тогда нужно решить, измеряем ли мы время до постановки в очередь или до появления результата.

Сколько трасс хранить и что убрать из каждой

Хорошо, у вас теперь есть способ разобрать один запрос. Но трассы существуют не для одного случая. Если сохранять все spans всех запросов, хранилище на небольшом VPS превратится в соревнование за диск и процессор с самим приложением. Если сохранять слишком мало, именно тот медленный запрос окажется в числе выброшенных.

Тут нужна политика выборки, и она зависит от задачи. Универсальной доли нет, и числа вроде «один процент» стоит выбирать исходя из объёма трафика и размера spans, проверяя нагрузку на своём сервере. Логика же такая. Случайная доля даёт общую картину, но может пропустить редкие медленные запросы. Решение, принимаемое уже после завершения trace — по длительности или коду ошибки, — оставляет именно аномалии, но требует, чтобы весь trace временно удерживался в памяти компонента, который принимает решение. Это стоимость в оперативной памяти, и на небольшой машине её надо учитывать при выборе ресурсов. Для сравнения: у тарифов VPS MAATRIX объём памяти варьируется от 2 ГБ у Ba до 32 ГБ у Djed, но эти цифры описывают ресурсы, а не ёмкость под конкретную нагрузку трасс; её можно определить только замером.

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

Секреты в атрибутах

Теперь о том, что лежит внутри spans. Инструментация SQL часто записывает текст запроса, HTTP — полный URL, а разработчики добавляют атрибуты вручную: идентификатор пользователя, почту, номер заказа. Всё это попадёт в хранилище, и доступ к нему получат люди, которым не нужны чужие данные. В нашем примере SELECT цен может содержать значения параметров, а URL к сервису доставки — адрес клиента в строке запроса.

В документации по работе с чувствительными данными рассматривается их удаление и преобразование в Collector: redaction processor умеет удалять атрибуты, а transform processor изменяет значения по заданным правилам. Для нашего случая это даёт две разумные меры. Атрибуты, которые не нужны для диагностики ожидания (адрес, почта, токены в параметрах), удаляются целиком. Атрибуты, нужные в урезанном виде, преобразуются: например, текст SQL остаётся с плейсхолдерами вместо значений, а URL обрезается до пути без строки запроса.

Практическая последовательность такая: сначала перечислите, какие атрибуты реально появились в spans этого маршрута, — просто откройте несколько трасс и прочитайте. Затем решите по каждому, нужен ли он для вопроса «где запрос ждал». Всё остальное удаляйте до записи в хранилище, а не после. Удаление в Collector, стоящем рядом с приложением, означает, что чувствительное значение не уходит по сети дальше и не оседает на диске. Это решение удобно размещать на том же VPS, что и приложение, но выбор места зависит от вашей архитектуры.

Одно предупреждение: правила удаления нужно проверять на реальных трассах после включения. Опечатка в имени атрибута молча оставит значение на месте, и вы не узнаете об этом, пока не откроете trace.

От найденного ожидания к исправлению

Вернёмся к нашим двум секундам. Предположим, вы добавили события внутри client span вызова сервиса доставки и увидели: 1100 мс прошло до отправки запроса, и лишь потом пошёл обмен. Значит, приложение ждало свободного соединения в пуле, а не отвечал медленно сервис. Это гипотеза, а не вердикт, и её надо проверить: сравните размер пула с числом одновременных запросов в пиковый момент, посмотрите, не удерживаются ли соединения дольше нужного.

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

Поэтому после правки нужно повторное наблюдение. Сравните не среднюю длительность по всем запросам, а структуру того же маршрута: сократился ли интервал до отправки, не вырос ли SQL, не появились ли новые зазоры. Хороший признак — изменилась форма trace: исчез длинный участок ожидания, критический путь стал короче и понятнее. Плохой — общее время упало, но только потому, что стало меньше нагрузки в этот час. Чтобы отличить одно от другого, сравнивайте периоды с похожим трафиком и смотрите на те же признаки, по которым вы нашли проблему: долю трасс выше порога, длительность конкретного span, число попыток.

Если трассы, Collector и приложение живут на одном VPS, помните, что они делят процессор и память. Тяжёлая обработка трасс в момент пика может сама добавить задержку к тем запросам, которые вы измеряете. Поэтому проверяйте нагрузку от самого сбора: потребление памяти Collector при выбранной политике выборки и задержку экспорта. Root-доступ на VPS позволяет посмотреть это стандартными средствами системы, а при росте объёма телеметрии Collector и хранилище можно вынести на отдельный сервер, если выбранный тариф перестал подходить. Какой размер нужен, покажут ваши замеры, а не название тарифа.

Что на самом деле вернулось клиенту

Вернёмся к тому запросу, с которого мы начали: две секунды у клиента и сто двадцать миллисекунд в SQL. Красивое дерево spans само по себе ничего не починило бы — его можно распечатать и повесить на стену, а клиент будет ждать те же две секунды. Ценность в другом: вместо расплывчатого «где-то между сервисами» появился конкретный интервал с известными границами, гипотеза о том, чем он занят, и способ её проверить.

Если после исправления тот же запрос проходит путь иначе — ожидание соединения исчезло, зазоры объяснены, критический путь укоротился, — значит, трассировка сделала свою работу. А если дерево стало красивее, а клиент по-прежнему ждёт, значит, вы наблюдали не то. Для клиента важна не картинка, а то, что его запрос теперь идёт другим путём и приходит быстрее.