Введение - кто мы, для кого будет полезна статья

Всем привет, меня зовут Полина, я техлид команды, занимающейся проектом электронного документооборота в среднего размера продуктовой компании. В этой статье я расскажу как мы обнаружили в привычном инструменте мониторинга ошибок - Sentry - распределенную трассировку и опробовали ее для своих задач. Примеры в статье приведены для конкретного стека, это python3 и FastAPI, храним мы данные в MongoDB, используем RabbitMQ.

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

Я не буду подробно углубляться в то, что такое распределенная трассировка, на Хабре уже было несколько статей на эту тему, например, эта. А можно залезть в прекрасную книгу Ричардсона про микросервисы в целом, например, в главу 11.3 “Проектирование наблюдаемых сервисов” и узнать о трассировке больше.

Ну что ж, намерения обозначили и погнали!

Какую проблему мы решали

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

Уже несколько месяцев к этому моменту мы разрабатывали и тестировали крупную фичу - интеграцию с потенциально любой сторонней системой документооборота (да-да, мы про “технологию роуминга” от ФНС, если вам это о чем-то говорит).

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

Что-то в этом процессе приема документа начало серьезно тормозить, а мы не могли точно узнать что и где. Как видно по картинке, в этой схеме много взаимодействия между компонентами и каждая связь потенциально могла быть корнем проблемы. Это задерживало тестирование со сторонней системой (где сидел человек и не всегда он был на связи), разработчики ходили грустные, а задачи закрывались медленнее. Боль из серии - пока не сталкиваешься - не замечаешь, но как доходит до тестирования твоей задачи, так нехило пригорает.

Мы выкроили где-то 3 рабочих человекодня на исследование. Гипотез об узком месте и причине было достаточно, вплоть до того, что просто python медленный, но нужны были точные данные. Таким образом боль стала отличным кандидатом для втаскивания распределенной трассировки (но только если быстро). Оставалось понять, какие именно инструменты будем использовать. Конечно, основными критериями выбора стали высокая скорость внедрения и малые трудозатраты команды на поддержку решения в дальнейшем, так как мы постоянно выкатываем новый функционал.

Обычно, когда речь заходит о распределенной трассировке, первыми в голову приходят Zipkin и Jaeger. Мы расспросили другие команды - кто-то пробовал для этой цели Zipkin, но инфраструктура была в ведении другой команды и работала не особо стабильно - его поддержка в работающем состоянии не была в приоритете, потому что ей мало пользовались (или все было наоборот, кто знает). К тому же клиентская библиотека Zipkin для python вгоняла в уныние необходимостью вручную обкладывать код инициализацией спанов, что предполагало кучу ручной работы и необходимость дополнительного тестирования всего этого богатства. А для Jaeger пришлось бы не только вручную определять границы спанов, но и поднимать (а потом, видимо, поддерживать) новую инфраструктуру. Все это нам не очень подходило.

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

Как выглядит трассировка в Sentry и коротко про сам Sentry

Изначально Sentry - система мониторинга ошибок и довольно популярная, судя по StackShare. Пишут, что ее используют Uber, Airbnb и Instagram. Забавно, что Sentry - еще и имя одного из самых сильных супергероев вселенной Marvel, хотя я это и узнала только при подготовке к этой статье.

Я часто встречала, что Sentry используют только как бездонный склад любых сообщений об ошибках, не особо вникая в ее организацию, основные абстракции и best practice, а для темы это важно, поэтому сейчас будет небольшая вводная.

Базовые абстракции Sentry - это event, issue и транзакция. Транзакция описывает некоторое действие, которое происходит в системе, более технически - это абстракция, описывающая стек вызов кода при некотором внешнем триггере в системе. Например, обработка HTTP запроса или, для фронта, действие загрузки или навигации по странице.

Собственно говоря, ошибка, произошедшая во время выполнения транзакции, отправляется в виде event на сервер Sentry, где группируется с такими же events в issue. По каждому такому event-у сохраняется метка времени и набор тегов, определяющих контекст конкретной ошибки, например, имя сервера, конкретный url, и все, что вы сами захотите в таком виде сохранять. В целом близко к структурированным логам на ELK стеке. В дальнейшем в UI можно посмотреть разбивку частоты ошибки в зависимости от значения каждого тега и найти корреляции или найти ошибку конкретного пользователя из обращения в тех. поддержку, настроить оповещения об ошибках в чат по частоте или по количеству задетых пользователей, отметить issue как решенную и увидеть метку о регрессе, если она появится снова и много других штук, чтобы не просто видеть ошибки, а удобно с ними что-то делать. Или замьютить и не делать. Все это настраивается для каждого проекта (сервиса, репозитория) отдельно и каждый проект имеет свое независимое “пространство имен”, так что если ошибка в одном сервисе привела к цепочке ошибок в других - вы просто так это не свяжете (без подключенной трассировки).

В контексте распределенной трассировки Sentry старается максимально близко придерживаться протокола Open Telemetry, который сейчас развивается вместо официально устаревшего Open Tracing, и не изобретает велосипед. То есть, в теории, можно выгрузить данные по трейсам (в интерфейсе для этого даже есть отдельная кнопка), и использовать их как источник данных в том же Zipkin. Единственное, что отличается, это название абстракции: вместо трейсов и спанов, которые могут быть вложенными друг в друга, у Sentry - трейсы, транзакции (как родительский спан) и просто спаны (см. картинку ниже из официальной документации). И в использовании уже существующей абстракции кроется важная часть фичи.

Те, кто пользуются Sentry, знают, что в большинстве случаев вам не нужно определять транзакции вручную, они генерируются автоматически с помощью готовых интеграций для каждого языка, веб-фреймворка, некоторых библиотек. Есть базовые интеграции, вроде LoggerIntegration (автоматически включенного) или ASGIIntegration/ WSGIIntegration, которые вам помогут, определят транзакцию, сгенерируют event с тегами и отправят на сервер Sentry. Есть интеграции для более детального сбора контекста для библиотек API запросов, ORM и т.п. И да, всегда можно законтрибьютить свои интеграцию или обложить что-то в коде детальнее, если очень надо. В общем, интеграции - это сила.

Таким образом, у нас уже есть родительские спаны - транзакции, да еще и со структурированным контекстом, что здорово. На самом деле, у нас уже есть и вся (структурированная) информация для просто спанов - запросов по API в другие сервисы, походы в базу данных и в кеш - она так же уже собиралась автоматически и раньше с помощью интеграций, но использовалась для детализации информации об ошибках. Немного магии разработчиков Sentry с одной стороны, обновление клиента Sentry в коде и/или определение количества трассируемых событий, с другой, и у нас в проекте есть распределенная трассировка, да еще и с историческими данными! Частичными, конечно, трейсы автоматически не проставятся, но все равно круто.

Базовая настройка - API, про дополнительные интеграции

Итак, добавить трассировку очень просто - прописываем в инициализацию клиента параметр traces_sample_rate=1.0 и готово. Число 1 отражает, какой процент транзакций по проекту попадет в Sentry, где 1 это 100%, но можно настроить и более точечно. Конечно, с 1 ехать на прод не рекомендуется, но для проверки подходит отлично. Так же в настройках можно выпилить часть транзакций из трассировки (например, healthheck запросы) и настроить ее динамически.

Обычно для связывания родительских спанов в разных микросервисах в единый трейс используют передачу информации о трейсе в заголовке HTTP запроса. Sentry делает то же самое, добавляя Header Sentry-Trace = traceid-spanid-sampled, sampled позволяет продолжать трейс в других сервисах (или не продолжать) консистентно, вне зависимости от индивидуальной настройки семплирования.

Python интеграция развивается как open-source проект. Если будете настраивать у себя имейте в виду, что не все интеграции с конкретными библиотеками перечислены в официальной документации, но их можно найти на GitHub. Например, для себя мы нашли полезными HttpxIntegration для спанов запросов к сторонним API и TreadingIntegration для блокирующего I/O кода, который запускается в отдельном треде, чтобы не блокировать I/O loop (не забудьте передать propagate_hub=True в инициализацию интеграции, чтобы новые спаны знали о родительской транзакции и трейсе).

Мы используем FastAPI (ASGIMiddleware) и httpx для API запросов (HttpxIntegration), спаны появились автоматически. К тому же подтянулись спаны Redis.

Что мы докручивали для себя

К сожалению, автоматическая инструментация была доступна только для SQL баз, а мы используем MongoDB. Заглянув в реализацию трассировки для SQL баз (основаны на сигналах), мы быстро соорудили что-то подобное для MongoDB.

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

class MongoDBCommandTracing(monitoring.CommandListener):
  """
  Трассирует команды MongoDB.
  Работает для асинхронных драйверов, основанных на pymongo, например, для motor.
  """
  request_to_span_mapper = {}
  
  def started(self, event):
      span = Hub.current.scope.span
      if span:
          new_span = span.start_child(
              op="db", description=str(event.command)
          )
          self.request_to_span_mapper[event.request_id] = new_span
  
  def succeeded(self, event):
      span = self.request_to_span_mapper.pop(event.request_id, None)
      if span:
          span.set_status("ok")
          span.finish()
  
  def failed(self, event):
      span = self.request_to_span_mapper.pop(event.request_id, None)
      if span:
          span.set_status("error")
          span.finish()

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

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

Мы написали еще одну небольшую обвязку для consumers с такой же логикой, как и в HTTP запросах: сложили в заголовки сообщения Sentry-Trace = traceid-spanid-sampled и написали декоратор для прокидывания трейса в обработчик сообщений из очереди.

from sentry_sdk import start_transaction, tracing, Hub


def sentry_trace_worker_async(func):
  """
  Включает трассировку функции-обработчика сообщения из очереди.
  Оборачиваемая функция должна получать объект message с атрибутом headers (словарь).
  Если в headers лежит заголовок для трассировки (по формату см. get_sentry_trace_header ниже),
  то трейс продолжится, если заголовка не будет - начнется новая транзакция и трейс.
  """
  @wraps(func)
  async def wrapper(message, *args, **kwargs):
    transaction = tracing.Transaction.continue_from_headers(
      headers=message.headers, name=func.name, op="queue"
    )
    with start_transaction(transaction=transaction):
      await func(message=message, *args, **kwargs)

  return wrapper

def get_sentry_trace_header() -> dict:
  """Формирует заголовок для продолжения трассировки в другом сервисе"""
  try:
    sampling_code = 1 if Hub.current.scope.transaction.sampled else 0
    return {
      "sentry-trace": f"{Hub.current.scope.transaction.trace_id}-{Hub.current.scope.span.span_id}-{sampling_code}"
    }
  except AttributeError as e:
    return {}

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

Итак, так выглядит обработка API запроса на отправку документа от нас в детализации на уровне одного сервиса:

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

А так - связи между сервисами:

Здесь видим, что трейс начался с API запроса, а потом продолжался через передачу сообщений в очередь.

К сожалению, для нашего кейса иллюстративных скринов не осталось, так что придется поверить мне на слово. Стало видно, в каком микросервисе и в каком спане внутри - узкое место. Это был запрос к базе данных, который длился 4 минуты, перебирая 3 миллиона записей без индекса.

Конечно, скажете вы, проблема в не оптимизированном запросе к базе данных была одним из самых вероятных вариантов, зачем еще было что-то прикручивать? Но ценность трассировки именно в том, что вместо набора гипотез мы получили конкретные данные - в каком микросервисе, какой именно запрос (с какими аргументами), сколько он выполняется, что-то одно тормозит или в нескольких местах, что сделало ясными необходимые правки. А после починки мы так же на данных увидели, как “усох” этот запрос и время выполнения вернулось в ожидаемые границы.

Что получили вместе с распределенной трассировкой

Что еще мы получили, настроив трассировку?

Во-первых, знание как на самом деле общаются микросервисы между собой и с хранилищами данных: когда происходит, сколько занимает времени для конкретных параметров запроса. Например, можно увидеть, что завершение транзакции в MongoDB занимает время и больше не спорить о том, насколько это влияет на производительность. Посмотреть, ответа какого API мы дольше всего ждем, сходить по трассировке в эту зависимость и посмотреть, что там больше всего влияет на производительность (конечно, если там тоже подключена трассировка). Мы еще прикрутили трассировку с фронта и знаем, какую скорость загрузки страниц видят пользователи, и какую роль в этом играет медленный интернет, а какую - формирование ответа на бэкенде. А информация о том, как именно фронт запрашивает данные - количество запросов, которые он делает для отрисовки страницы, их последовательность, мне, как backend-разработчику, было особенно интересно увидеть на живых примерах - это огромный простор данных для идей по оптимизации. Плюс, трейсы это, считай, живая самообновляющаяся документация по сложному функционалу без необходимости копать кодовую базу.

Во-вторых, ребята из Sentry не могли оставить эти данные просто так лежать и втащили сразу метрики, например, по распределению длительности обработки запроса еще и в нескольких форматах: и в процентилях, и в виде нормального распределения.

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

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

Более того, на основе этих данных считается метрика Failure Rate, на которую можно настроить алерты. Кстати, свои метрики на основе данных трассировки настроить можно через вкладку dashboards.

Что еще круче, Sentry знает о ваших тегах, автоматически присоединяет их к транзакции и использует в аналитике. Здесь все зависит от того, какие у нас настроены теги и какие вытаскивает ваша интеграция фреймворка и других библиотек.

Но даже дефолтная ASGIMiddleware собирает данные, например, об адресе машины и имени браузера. Sentry выдает вам блок Suspected Tags, подозрительные теги, которые, предположительно, влияют на производительность.

В общем, есть риск надолго залипнуть, изучая свою систему :-)

Заключение

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

Например, сейчас нет организации холодного хранения данных - то есть, даже старые данные хранятся в полном объеме. Можете себе представить скорость роста занимаемого места на диске. К тому же мы (точнее команда devops) пока не нашли способ аккуратно затирать только старые данные и/или только данные трассировки. Для нас это стало одной из причин поставить очень маленький процент отправки трейсов в Sentry. В такой ситуации все графики становятся не очень информативными - они показывают среднюю температуру по больнице. При необходимости исследовать что-то конкретное, можно снова увеличить количество трейсов, но ручное управление не радует, тем более, что исторические данные бывают очень полезны для дебага.

Также есть некоторые сложности с тем что это open source продукт. В каком-то новом функционале, который вы захотите у себя применить, могут быть ошибки и если вы не готовы это тестировать, то стоит выбирать изменения, только отлежавшиеся пару месяцев, и проверить наличие обращений по ним в GitHub. Мы столкнулись с такой ситуацией, например, при переходе на FastAPIIntegration с ASGIMiddleware.

В целом, я рекомендую вам попробовать трассировку через Sentry, если позволяет объем трафика, размер проекта и у вас еще нет трассировки. Очень интересная штука, особенно если вы хотите узнать больше о реальной архитектуре своего проекта, не сильно заморачиваясь.

Спасибо за внимание!

P.S. Если кто из прочитавших пользуется “взрослой” трассировкой, напишите, пожалуйста, в комментах, вы используете что-то самописное для автоматического перехвата вызовов базы данных, API запросов и прочих спанов или какую-то open source библиотеку?