Skip to content

Instantly share code, notes, and snippets.

@pioh

pioh/trace.md

Last active March 17, 2019 19:55
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save pioh/b106d58dbc1a9946e389df49eac5d638 to your computer and use it in GitHub Desktop.
Save pioh/b106d58dbc1a9946e389df49eac5d638 to your computer and use it in GitHub Desktop.
Download ZIP
trace.md
Raw
trace.md

Какие проблемы можно решить с помощью трассировки

  1. Найти узкие места в производительности как внутри одного сервиса, так и во всем дереве выполнения между всеми участвующими сервисами.
    К примеру:
  • Много коротких последовательных вызовов между сервисами, например, на геокодинг или к базе данных.
  • Долгие ожидания ввода вывода, например, передача данных по сети или чтение с диска.
  • Долгий парсинг данных.
  • Долгие операции, требующие cpu.
  • Участки кода, которые не нужны для получения конечного результата и могут быть удалены, либо запущены отложенно.

  1. Наглядно понять в какой последовательности что вызывается и что происходит когда выполняется операция. Видно что, например, Запрос пришел в сервис WS -> сервис WS дополнил данные через сервис R -> дальше отправил запрос в сервис V -> сервис V загрузил много данных из сервиса R -> сходил в сервис P -> сервис Р еще раз сходил в сервис R -> сервис V проигнорировал результат и пошел в сервис J -> и только потом вернул ответ в сервис WS, при этом продолжая в фоне вычислять что-то еще.
    Без такого трейса или подробной документации на весь процесс очень сложно понять что происходит, первый раз взглянув на код, да и код разбросан по разным сервисам и скрыт за кучей бинов и интерфейсов.

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

  3. Превращение трейсов в подмножество метрик и дальнейший анализ уже в виде метрик.

Что собирается трассировкой.

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

Span

В трассировке есть понятие спан, это аналог одного лога, в консоль. У спана есть:

  • название, обычно это название метода который выполнялся.
  • название сервиса, в котором был сгенеренн спан.
  • собственный уникальный id
  • какая-то мета информация в виде key/value, которую залогировали в него. Например, параметры метода или закончился метод ошибкой или нет.
  • время начала и конца выполнения этого спана.
  • id родительского спана

Каждый спан отправляется в collector спанов для сохранения в базу для последующего просмотра как только он завершил свое выполнение. В дальнейшем можно построить дерево всех спанов соединяя по id родителя. При анализе можно найти, например, все спаны в каком-то сервисе, которые заняли больше какого-то времени. Дальше, перейдя на конкретный спан, увидеть все дерево выше и ниже этого спана.

Opentrace

Есть общий стандарт opentrace, который описывает как и что должно собираться, не привязываясь трассировкой к конкретной реализации в каком-либо языке. https://opentracing.io/docs/overview/ Например, в java вся работа с трейсами ведется через общий api opentrace, а под ним может скрываться, например, jaeger или пустая дефолтная реализация которая ничего не делает.

Jaeger

У нас используется jaeger как имплиментация opentrace https://github.com/jaegertracing/jaeger https://www.jaegertracing.io/ Он состоит из нескольких компонент:

  • jaeger-agent - локальный агент, который обычно стоит на каждой машине и в него логируют сервисы на локальный дефолтный порт. Если агента нет, то трейсы всех сервисов на этой машине обычно выключены.
  • jaeger-collector - в него все агенты посылают собранные трейсы, а он кладет их в выбранную бд
  • база данных - предпочтительная у них cassandra, но у нас почему-то используется elasticsearch, есть реализации еще под пару других бд и in memory реализация, которая ничего не сохраняет на диск.
  • jaeger-query - это сервис который ходит в базу данных и отдает уже собранные трейсы для анализа.
  • jaeger-ui - это веб интерфейс для поиска и просмотров трейсов, он ходит в jaeger-query. Также все эти компоненты, кроме бд, могут быть собранны в один бинарник.

Отдельным компонентом можно назвать реализацию opentrace jaeger под конкретные языки. Через которую спаны отправляются в jaeger-agent.

Jaeger в SRG

У нас collector и ui запущен на trace.srg-it.ru, он же dwraf.srg-it.ru, там же запущен эластик в который сохраняются все спаны. Чтобы добавить в какой-то сервис трейсы достаточно поднять agent или проверить что он уже запущен на машине с сервисом и напривить его на trace.srg-it.ru на дефолтные порты. Есть деб пакет в 9r/jaeger который кладет бинарник и systemd конфиг на нужную машину. Либо можно просто запустить через docker. Конфиг docker-compose всех компонентов jaeger можно найти здесь https://github.com/jaegertracing/jaeger/blob/master/docker-compose/jaeger-docker-compose.yml Точно так же для тестов можно поднимать jaeger-agent локально. Но надо не забыть прописать локальное имя сервиса, чтобы не мешать локальные трейсы с продом.

Подключение jaeger в java

Все сводится к тому чтобы заимплиментить интерфейс io.opentracing.Tracer, после чего все трейсы через него будут улетать в реальный агент. https://github.com/jaegertracing/jaeger-client-java

Так же для компонент спринга можно подключить opentracing-spring-cloud-starter и имплементацию от jaeger opentracing-spring-jaeger-cloud-starter которая законфигурит автоматически трассировку на все что проходит через эти компоненты, например http запросы в контроллеры, запросы к бд через jdbc и т.д. https://github.com/opentracing-contrib/java-spring-cloud https://github.com/opentracing-contrib/java-spring-jaeger

Для старой версии спринга есть ветка io.opentracing.contrib:opentracing-spring-cloud-starter:0.1.17

Логирование трейсов в java

Где-то на самом верхнем уровне должен быть создан первый спан, это может быть сделанно автоматически например контроллером спринга при получении запроса, либо вручну если такого нет. Дальше он передается через scope ниже. Если какой-то метод ниже хочет добавить span, он берет из Scope текущий activeSpan, создает новый спан и говорит что его родительский полученный activeSpan, и делает новый span active. При вызове внешних сервисов им передается текущий активный спан, и те сервисы создают новые спаны с привязкой к этому спану.

Вся работа идет через инстанс Tracer, получить его можно через механизм DI, либо GlobalTracer.get() как глобальную переменную, если механизм DI не работает. По дефолту если tracer не был проинициализирован вернется NoopTracer который ничего не делает.

Дальше из tracer через ScopeManager достается текущий scope, создается новый scope от текущего с привязкой нового спана, а в дальнейшем закрывается созданный скоп, который закрывает созданный спан и возвращает в активное состояние прошлый scope. Scope привязан к потоку, поэтому при многопотоном программировании надо не забывать передавать активный спан в другой поток, для дальнейшей активации scope другого потока с привзякой к этому спану.

io.opentracing.Tracer tracer = ...; // GlobalTracer.get()

void DoSmth () {
   try (Scope scope = tracer.buildSpan("DoSmth").startActive(true)) {
      ...
   }
}
void DoOther () {
    Span span = tracer.buildSpan("someWork").start();
    try (Scope scope = tracer.scopeManager().activate(span, false)) {
        // Do things.
    } catch(Exception ex) {
        Tags.ERROR.set(span, true);
        span.log(Map.of(Fields.EVENT, "error", Fields.ERROR_OBJECT, ex, Fields.MESSAGE, ex.getMessage()));
    } finally {
        span.finish();
    }
}

void DoAsync () {
    try (Scope scope = tracer.buildSpan("ServiceHandlerSpan").startActive(false)) {
        ...
        final Span span = scope.span();
        doAsyncWork(() -> {
            // STEP 2 ABOVE: reactivate the Span in the callback, passing true to
            // startActive() if/when the Span must be finished.
            try (Scope scope = tracer.scopeManager().activate(span, false)) {
                ...
            }
        });
    }
}

Для упрощения работы есть хелперы, например com.srg.express.opentrace.Trace позволяет писать

void DoSmth() {
    try (Scope scope = Trace.scope()) { // создает новый спан с именем текущего метода и класса
    }
}

Или если работает механизм аннотаций то можно использовать com.srg.express.opentrace.TracedImpl

@Traced
void DoSmth () {

}

Для многопоточного программирования так же есть TracedExecutorService и аналогичные обертки, которые автоматически пробрасывают текущий спан в поток при запуски асинхронно таски.

private ExecutorService executor = new TracedExecutorService(
    Executors.newFixedThreadPool(10), GlobalTracer.get()
);

Для внешних http запросов есть TracingHttpClient https://github.com/opentracing-contrib/java-apache-httpclient

HttpClient httpClient = new TracingHttpClientBuilder().build();

Проблемы

  • Бины и DI не всегда работает если tracer используется не в сервисе или компоненте, тогда @Autowired Tracer может не работать и придется использовать GlobalTracer.get().
  • Не работают аннотации если это не компонент или сервис, или если вызов метода происходит из соседнего метода того же класса. Надо быть аккуратным, проверять что работает, и использовать ручное создание трейса если @Traced не работает. Так же можно прикрутить дополнительный компилер для java аннотаций, тогда должны работать везде.
  • В старых spring и spring boot не работает автоконфигурация opentraing spring cloud из-за багов в DI, тогда если хочется чтобы работали автоматически трейсы в компонентах спринга можно сделать по аналогии с comparablesrepository/express.valuator/src/main/java/com/srg/express/config/JaegerConfiguration.java, там конфигурация сделанная по аналогии с https://github.com/opentracing-contrib/java-spring-jaeger/blob/master/opentracing-spring-jaeger-starter/src/main/java/io/opentracing/contrib/java/spring/jaeger/starter/JaegerAutoConfiguration.java
  • В groovy не работает try with resources, надо обязательно использовать try finally.
  • У каждого сервиса надо прописывать свой spring.application.name под которым будут логироваться трейсы. При чем отдельный name для прода и теста, чтобы не мешать их вместе.
  • Если использовать GlobalTracer и tomcat то все сервисы запущенные в этом tomcat имеют один GlobalTracer, поэтому у них будет на всех одно имя сервиса.
  • При добавлении трейсов в метод, надо быть уверенным что он не вызывается в цикле много раз. Например в метод конвертации офферов не надо добавлять трейс на каждый вызов, так как этих офферов будет под 300тыс шт. Надо добавить один общий трейс на все вызовы, который залогирует суммарное время работы. Иначе будет создаваться избыточная нагрузка.
  • Один раз в jaeger-ui делали слишком большие запросы на большое количество трейсов и так как не дожидались ответа делали еще раз. В итоге jaeger-query стал есть много памяти и тормозить эластик. Помогло рестартом jaeger-query

Sampling

Есть три типа семплирования трейсов.

  • const который отправляет и сохраняет все трейсы
  • probabilistic который фильтрует трейсы с какой-то заданной вероятностью
  • ratelimiting который ограничивает число трейсов в секунду. Можно настроить эти параметры на клиенте, либо на jaeger-agent либо в коллекторе. Сейчас у нас в стеке валюаторов используется const 1 так как запросов не очень много но они занимают продолжительное время. В дальнейшем если это будет оказывать излишнюю нагрузку на систему можно ограничить.

https://www.jaegertracing.io/docs/1.9/sampling/

Хранение трейсов

Если использовать cassandra то по дефолту она хранит трейсы только за два дня. У нас используется эластик и трейсы хранятся за все время и не удаляются. На каждый день создается отдельный индекс, например jaeger-service-2019-03-04. В дальнейшем надо настроить автоматическую подчистку старых трейсов.
https://github.com/jaegertracing/jaeger/tree/master/plugin/storage/es

Просмотр трейсов

Смотреть трейсы можно по ссылке https://trace.srg-it.ru Для этого надо

  • Выбрать сервис по которому хочется пофильтровать трейсы, например для expres-ws это будет tomcat7-default так как он запущен в томкате и не может иметь совего имени.
  • Дальше лучше выбрать операцию, например ValuationRequestEndPoint::_onValuationRequest:247 запрос на оценку
  • Выбрать временной промежуток и минимальное время операции, например от 10 секунд, чтобы взять только долгие выполнения.
  • Перейти в один из трейсов и смотреть что там тормозило. например в верхнем трейсе было основное время заняло два последовательных походов в питон валюатор, затем был отдан ответ и еще раз в фоне схдоили в третий валюатор.

Так же если известен какой-то id запроса, то можно найти трейс по этому id через поиско по тегам, если этот id логируется в спан трейса.

В питон валюаторе не получилось настроить трассировку так как там для этого необходимо обновить часть библиотек. Поэтому не видно что делал внутри питон валюатор. Так же он мог сходить в это время в comparables-repository в котором есть трейсы, но их тоже здесь не видно, так как питон не передал id спана к которому привязывать спаны репозитория, поэтому они болтаются отдельно не привязанные к этому трейсу. Проверить тормозит ли питон валюатор из-за того что тормозит репозиторий можно проверив долгие трейсы репозитория за это время у которых нет сверху express-valuator

Документация

Статьи

Видео

Метрики

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment