Трассировка стека / анализ дампа потоков

За свою карьеру в качестве инженера по производительности я имел удовольствие работать с рядом ИТ-специалистов среднего звена (включая разработчиков). Во многих случаях мне приходилось объяснять, почему я вижу проблему во время выполнения приложения, а они нет — чтобы не быть отброшенным как человек, который воображает вещи и тратит их драгоценное время. И довольно часто мои выводы основаны на StackTraces. К сожалению, многие разработчики программного обеспечения, получив StackTrace, даже не знают, с чего начать, чтобы посмотреть на него. И тут меня осенило: StackTraces — это такая информативная структура данных и ее так легко получить — жаль, что многие специалисты не знают, как с ней работать.

Этот пост предназначен для вас, коллеги-разработчики и специалисты по производительности, которые хотят ознакомиться с анализом StackTrace или просто освежить в памяти, как работать со стеками.

Что есть что

Трассировка стека (ST, STrace)

Трассировка стека (ST) — это моментальный снимок того, что делает процесс в данный момент. ST не раскрывает никаких данных, секретов или переменных. Однако ST показывает классы (в некоторых случаях) и вызываемые методы/функции.

Чтобы лучше понять ST, рассмотрим простое приложение:

function assertAuthorized() {
    user = db.findUser(request.getUsername(), hash(request.getPassword()));
    assert user != null;
}

function prepare() {
    assertVariables();
    assertAuhorized();
}

function doJob() {
    prepare();
    task1();
}

Если мы выполним doJob() и зафиксируем ST в момент вызова prepare() → request.getUserName(), мы получим ST, который выглядит примерно так:

Thread main
  at HttpRequest.getUserName
  at prepare
  at doJob

В самом верху ST находится заголовок, который в данном случае сообщает нам имя потока (main). Под заголовком находится фактическая трассировка вызовов, начиная с самого последнего вызова, сделанного этим процессом: getUsername. Функция getusername была вызвана prepare(), поэтому это следующая строка в трассировке. А prepare() была вызвана doJob(), так что это то, что мы находим непосредственно под prepare.

Читая ST снизу вверх, мы можем увидеть, насколько «глубоко» находится процесс в данный момент. В этом конкретном примере процесс вызвал doJob() (в doJob), внутри doJob он вызвал prepare() (в prepare), а внутри prepare он вызвал getUsername() класса HttpRequest. Мы не видим вызов db.findUser() в трассировке, потому что он еще не был сделан. Чтобы выполнить этот вызов, процесс должен сначала получить имя пользователя и хэш пароля и поместить их в стек.

Другой способ визуализации ST был бы горизонтальным, а не вертикальным. Что в данный момент делает поток?

doJob() → prepare() → HttpRequest.getUsername().

Это точно то же самое, что и раньше, просто изложено по-другому.

N.B. переменные стека процесса/потока НЕ фиксируются в трассировке стека.

Некоторые среды выполнения могут вставлять в трассировку стека больше информации, например, номер строки исходного файла, в котором находится каждая функция, библиотеку с версией или без, в которую входит функция, PID/TID/NTID (ProcessID/ThreadID/NativeThreadID), использование ресурсов (время выполнения потока, количество CPU%, потребляемых этим потоком), задействованные примитивы синхронизации (мониторы) и т.д. Все эти дополнения меняются от времени выполнения к времени выполнения, от версии к версии, и не следует полагать, что они всегда будут доступны.

Дамп потоков (TD, TDump)

Часто Stack Trace и Thread Dump используются как взаимозаменяемые понятия. Хотя есть небольшое различие, ST и TD очень похожи — почти одно и то же.

Трассировка стека отражает последовательность вызовов одного процесса или потока, которые он выполняет в данный момент — это и есть трассировка. Эти вызовы, называемые в языках низкого уровня указателями инструкций, хранятся в структуре памяти процесса, называемой стеком — это и есть часть стека. Иногда StackTraces также называют CallTraces, хотя CallTrace является более общим термином и не фокусируется на потоках/процессах/стеках в явном виде.

ThreadDump — это пакет ST для каждого потока, выполняемого приложением. Возможно, с некоторой дополнительной информацией, такой как временная метка захвата, возможно, некоторые статистические данные и другая соответствующая диагностическая информация. И в этом практически вся разница. Захватите кучу ST — по одному на каждый поток запущенного приложения — и засуньте их все в один файл. Вот, у вас есть ThreadDump!

Уровни трассировки стека

Все процессы имеют трассировку стека. Возможно, за единственным исключением процессов в состоянии Z (т.е. процессов-зомби), все процессы выполняют какую-либо функцию в любой момент времени. Как только последняя оставшаяся (или первая, которую процесс выполнил при запуске) функция возвращается, процесс завершается. Однако в некоторых средах выполнения ST процесса может не быть трассировкой вызовов, которая нам действительно нужна. Рассмотрим приложения Java. Все они выполняются на JVM — своеобразной виртуальной машине, которая анализирует и переводит код в родные двоичные инструкции, которые способен понять процессор. Если мы найдем PID процесса JVM и посмотрим на трассировку его вызовов, мы увидим какую-то тарабарщину, и ни одна строчка не будет похожа на java. Это потому, что процессы JVM являются бинарными — они НЕ являются Java. Эти процессы — настоящие процессы JVM — те, которые запускают JVM на своих плечах. И наше приложение выполняется внутри них. Поэтому, чтобы увидеть трассировку вызовов наших Java-потоков, мы не захватываем StackTraces процессов. Вместо этого мы используем инструменты JRE, такие как jstack, которые подключаются к JVM и захватывают трассы вызовов потоков вашего приложения изнутри этих родных процессов — изнутри виртуальной машины Java.

Практически то же самое относится к любому интерпретируемому или псевдоинтерпретируемому языку. Родные процессы запускают механизм, который выполняет ваше приложение, поэтому если вы захватите их ST, вы не увидите, что делает ваше приложение; вместо этого вы увидите, что делает ваш механизм выполнения. Чтобы увидеть, что происходит внутри него и каковы трассировки вызовов потоков вашего приложения, используйте инструменты, предоставляемые движком среды выполнения вашего языка. Вы можете получить трассировку стека даже для bash (см.: bthrow)!

Что находится внутри ST/TD

• строгая последовательность вызовов методов/функций, выполненных процессом/потоком.
• самый старый вызов находится внизу
• самый новый (последний) вызов — вверху.

Что НЕ находится внутри ST/TD

• операции
  • while, for, switch, if, другие встроенные в синтаксис операции
  • арифметические операции (+ — * / ^ и т.д.)
  • операции присваивания (=)
  • операции сравнения (== > < >= <= !=)
• данные
  • переменные
  • константы
  • объекты/существа
  • значения параметров функций/методов

Когда

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

• существительные — это данные приложения: переменные, буферы, строки, байты, массивы, объекты, куча, память, утечки памяти, оперативная память — все эти ключевые слова относятся к ДАННЫМ. Вы заботитесь о данных, когда знаете, что с ними что-то не так: либо их слишком много (например, утечки памяти), либо данные неверны (ошибки целостности). Для этих случаев вам нужен либо coredump (для родных процессов), либо heapdump (например, для JVM). Данные не имеют ничего общего с потоками или трассировкой вызовов/стека.
• Глаголы — это действия приложения: функции, методы, процедуры, рутины, лямбды. Они загружаются в стеки процессов/потоков в очень строгой последовательности, что позволяет нам проследить поток выполнения.

Когда речь заходит о производительности, мы часто видим, что приложение ведет себя неправильно:

• зависание функций
• потоки не отвечают
• процессы/потоки сжигают процессор на 100%
• потоки блокируют друг друга
• медленные ответы
• огромное количество открытых файлов/сокетов
• огромное количество операций ввода-вывода файлов/сокетов
• …

Во всех этих случаях нам нужен либо ST, либо TD. Только когда у нас есть снимок всех потоков/процессов действий (существительных) приложения, мы можем сказать, что происходит внутри него и что делает приложение. В верхней части трассировки вызовов каждого из процессов/потоков приложения мы увидим, какой последний вызов функции/метода сделал каждый метод/fn (или делает, как это было бы более технически правильно). Пройдя вниз по стеку, мы увидим, откуда исходит этот вызов. Таким образом, мы можем отследить, КАКИЕ и ПОЧЕМУ процессы/потоки нашего драгоценного приложения выполняют все эти действия.

Как перехватить

Трассировка стека / дамп потоков — это моментальный снимок активности приложения. Обычно нам не нужно следить за ST. Только когда приложение ведет себя неправильно, нам важно проверить его выполнение. Учитывая это, перехват STs полезен только в момент неправильного поведения. Мало того, чтобы получить полезный StackTrace, мы должны захватить его в тот самый момент, когда приложение испытывает проблемы. Не раньше и уж точно не после того, как проблема исчезнет. Это как рентгеновский снимок: его нужно сделать, пока мы больны, а не до и не после болезни. Иногда очень трудно захватить ST в нужный момент, потому что некоторые проблемы длятся всего секунду или даже меньше. Захват ST может быть автоматизирован и интегрирован в системы мониторинга/оповещения как реактивно-диагностическая мера, чтобы увеличить шансы на захват правильных данных, или мы можем захватывать серию ST каждую секунду (или меньше; или больше — в зависимости от проблемы), надеясь получить хотя бы один ST, который отражает проблему.

Захват серии ST имеет еще одно преимущество. Если эти ST сняты достаточно близко друг к другу (с интервалом в секунды/миллисекунды), мы можем рассматривать эту связку как профиль. Подобно тому, как для проецирования на экран требуется 25 кадров в секунду, чтобы обмануть наши глаза (разум) и заставить их думать, что это живое движение, мы можем снимать несколько ST в секунду и считать, что это «живое движение приложения», т.е. таким образом мы можем отслеживать действия приложения во времени. Точность такого отслеживания становится тем хуже, чем дальше друг от друга находятся эти снимки. Подробнее об этом позже.

Нативный (процесс)

Linux

Получить StackTrace процесса в Linux довольно просто. Однако стоит заметить, что для любого процесса в Linux можно получить доступ к двум трассам стека (хотя в некоторых дистрибутивах это невозможно): одна в пространстве ядра, другая в пространстве пользователя. Это потому, что каждый процесс работает в обоих регионах: он выполняет все вычисления и принимает решения в пространстве пользователя, но когда дело доходит до аппаратных вещей (ввод-вывод, сон, память и т.д.), процесс должен попросить операционную систему сделать эту работу за него. А ОС выполняет свою часть работы в пространстве ядра. Чтобы упростить ситуацию, каждый процесс получает долю памяти, выделенную для стека в обеих областях, поэтому он может свободно выполнять пользовательский код и код ядра.

Обычно, когда процесс просит ядро сделать что-то, он становится невосприимчивым к пространству пользователя (как бы застывает). Поэтому, если ваш процесс не отвечает — посмотрите на его стек в ядре. В противном случае — посмотрите его стек в пространстве пользователя.

Чтобы увидеть стек процесса, вам понадобится PID этого процесса.

1. найдите PID интересующего вас процесса.

Теперь процедура доступа к стеку ядра и стеку пользователя немного отличается.

1. Для получения стека пространства ядра выполните команду sudo cat /proc/${PID}/stack и вы получите хороший стек-трассировку. Стек sleep 9999 выглядит следующим образом:

[<0>] hrtimer_nanosleep+0x99/0x120
[<0>] common_nsleep+0x44/0x50
[<0>] __x64_sys_clock_nanosleep+0xc6/0x130
[<0>] do_syscall_64+0x59/0xc0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xae

(обратите внимание на вызовы nsleep и nanosleep — это ОС делает фактический вызов сна)

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

[<0>] ep_poll+0x2aa/0x370
[<0>] do_epoll_wait+0xb2/0xd0
[<0>] __x64_sys_epoll_wait+0x60/0x100
[<0>] do_syscall_64+0x59/0xc0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xae

(обратите внимание на вызовы wait и poll — ОС ожидает выполнения задач в пространстве ядра).

1. Для стека пользовательского пространства у вас есть 2 основных варианта:
   • использовать отладчик gdb для подключения к запущенному процессу (gdb -p ${pid} и запустить bt внутри)
   • установите инструменты, которые могут автоматизировать это для вас, например pstack или eu-stack (поставляется с пакетом elfutils)

pstack обычно предустановлен, и использовать его очень просто — просто укажите ему PID и увидите, как стек появится в вашей консоли. Однако я предпочитаю eu-stack, потому что у него больше возможностей, например, печать потоков, многословность и другие приятные функции (см. eu-stack --help).

~ $ eu-stack -p 715821
PID 715821 - process
TID 715821:
#0  0x00007f75b5c991b4 clock_nanosleep@@GLIBC_2.17
#1  0x00007f75b5c9eec7 __nanosleep
#2  0x0000555a72b09827
#3  0x0000555a72b09600
#4  0x0000555a72b067b0
#5  0x00007f75b5be0083 __libc_start_main
#6  0x0000555a72b0687e

или с включением всех причудливых опций:

~ $ eu-stack -aismdvp 715821
PID 715821 - process
TID 715821:
#0  0x00007f75b5c991b4     __GI___clock_nanosleep - /usr/lib/x86_64-linux-gnu/libc-2.31.so
    ../sysdeps/unix/sysv/linux/clock_nanosleep.c:78:5
#1  0x00007f75b5c9eec7 - 1 __GI___nanosleep - /usr/lib/x86_64-linux-gnu/libc-2.31.so
    /build/glibc-SzIz7B/glibc-2.31/posix/nanosleep.c:27:13
#2  0x0000555a72b09827 - 1 - /usr/bin/sleep
#3  0x0000555a72b09600 - 1 - /usr/bin/sleep
#4  0x0000555a72b067b0 - 1 - /usr/bin/sleep
#5  0x00007f75b5be0083 - 1 __libc_start_main - /usr/lib/x86_64-linux-gnu/libc-2.31.so
    ../csu/libc-start.c:308:16
#6  0x0000555a72b0687e - 1 - /usr/bin/sleep

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

Windows

вздохните…
…

Вероятно, самый простой подход — это великолепный ProcessExplorer, описанный здесь и во многих других местах в интернете.

• скачать и установить ProcessExplorer
• запустите ProcessExplorer
• найдите PID, для которого вам нужен ST
• щелкните правой кнопкой мыши → свойства
• выберите вкладку Threads
• выберите поток, который вы хотите проинспектировать
• нажмите на кнопку Stack.

Кадры стека будут выглядеть загадочно, но если вам этого достаточно — вот так! Если вы хотите получить более четкий ST, вам придется скачать и установить Debug Tools и загрузить Debug Symbols в ProcessExplorer, как показано в руководствах:

• Options → Configure Symbols

JVM

И снова, в случае JVM, есть как минимум 2 уровня трассировки вызовов:

• родной
• приложение

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

Чтобы получить StackTrace приложения, JVM предоставляет возможность захвата ThreadDump (TD). Существует несколько способов захвата TD работающего приложения:

Захват TD в JVM останавливает JVM на долю секунды и возобновляет ее сразу после этого. В некоторых случаях JVM может показаться застрявшей, и jstack может порекомендовать использовать опцию -F. Как всегда, обращайтесь с опцией force очень осторожно, поскольку она может навсегда заблокировать все потоки вашего приложения (спросите меня, откуда я это знаю).

Другие режимы выполнения

Некоторые среды выполнения имеют свои собственные альтернативы JVM jstack, другие — либо не имеют, либо поддерживают плагины для GNU gdb для получения TD через отладчик. Обратитесь к документации вашей среды выполнения, чтобы узнать, есть ли в ней средства для захвата трассировки вызова. Не помешает также спросить мнение Google.

Анализ

Анализ трассировки вызовов может дать нам много информации о том, что происходит с приложением:

• сколько потоков выполняют X в данный момент
• сколько всего потоков
• какие действия «зависают» и на каких вызовах функций
• какие потоки «провисают
• какие потоки застряли в бесконечных циклах и какие функции их вызвали
• какие потоки могут быть причиной высокой загрузки процессора; что они делают для этого
• какие потоки делают исходящие длительные вызовы ввода-вывода; откуда эти вызовы исходят в коде
• какие потоки блокируют другие потоки (используя примитивы синхронизации) и при каких вызовах функций (как блокированных, так и блокирующих)
• сколько потоков запущено в X части вашего кода (например, PaymentService2.transfer()), если вам интересно узнать, вызывается ли определенный метод/функция
• какие потоки могут привести к взрывам стека (переполнениям стека); и через какие вызовы функций
• насколько велики ваши пулы потоков и являются ли они избыточными/недостаточными
• другая полезная информация, в зависимости от того, в чем проблема.

Отдельные ST

Анализ отдельных текстовых StackTraces поначалу может показаться сложной задачей, но через несколько стеков картина становится более понятной. Однако в случае с ThreadDumps, особенно с большим количеством запущенных потоков (сотни-тысячи), ручной анализ все еще остается сложной задачей.

Найти нужные потоки

Подход к ручному анализу ST зависит от того, какую проблему мы пытаемся решить. Обычно мы фокусируемся на загруженных потоках — тех, у которых длинные трассы вызовов. Однако «длинный» — понятие относительное. В некоторых приложениях «длинный» — это 200 стековых кадров, в то время как в других он может составлять всего 30. Позвольте мне перефразировать это:

• Холостые потоки [короткие следы вызовов] — потоки запустились, инициализировались и теперь ждут задач для работы; в стандартных веб-приложениях Java мне нравится брать 30 кадров за точку отсчета и искать потоки со следами вызовов длиной ~30 кадров; может быть меньше, может быть больше. Эти потоки простаивают, независимо от их состояния Thread.
• Занятые потоки [длинные трассы вызовов] — потоки получили задание для работы и в данный момент обрабатывают его. Во время обработки задачи их трассировка вызовов обычно значительно больше, чем в режиме ожидания — она может составлять сотни кадров. Эти потоки заняты, независимо от их состояния Thread.

Обычно нам нужно сначала найти эти занятые потоки.

Нет занятых потоков

Может случиться так, что приложение работает медленно или «зависает», а занятых потоков нет. Наиболее вероятная причина — узкое место где-то вне процесса приложения. То есть, если приложение ничего не делает (простаивает), то оно не медленное — никто не дает ему никакой работы. Был ли запрос потерян или отброшен в пути, даже не дойдя до вашего процесса приложения? Он застрял в пути?

Вторая наиболее вероятная причина заключается в том, что TD был получен в неправильное время: либо до, либо после того, как возникла медлительность. Это случается чаще, чем хотелось бы признать. Это почти всегда происходит, если трассировку захватываете не вы, а кто-то другой («Оперативная группа, пожалуйста, захватите TD»; 5 минут спустя: «вот она»; проблема ушла 4 минуты назад), особенно если этот кто-то не знает, как/когда ее захватывать, чтобы получить полезную диагностическую информацию.

Третья причина может заключаться в том, что ST был получен не из того процесса. Это особенно часто случается, когда запросы попадают на какой-либо LoadBalancer (DNS-сервер также является примитивным LB) и нет возможности определить, на какой сервер попадет запрос. Часто операторы берут ST/TD с любого случайного сервера/инстанса в пуле, который принадлежит пулу приложений, и считают, что это то, что вы просили.

И четвертая причина, с которой я столкнулся, заключается в том, что вы неправильно установили порог холостого хода/занятости. В некоторых приложениях обработка задачи может добавить очень мало стековых кадров, от 1 до 5. Посмотрите на имеющиеся у вас трассы, сравните их и посмотрите, что находится на самом верху. Возможно, вы неправильно рассчитали, что такое «длинная» трассировка стека в вашем конкретном случае.

Есть несколько занятых потоков

Отлично, теперь, когда вам удалось найти занятые потоки, пришло время посмотреть, что в них находится. Возможно, самый быстрый способ увидеть, что происходит в потоке, — это прочитать его сверху вниз, а еще лучше — просто взглянуть на 5 или около того верхних кадров в трассировке вызовов. Начните с самого верха. Посмотрите, какой был последний вызов функции — как она называется? Это может подсказать вам, что делал поток в тот самый момент, когда был захвачен этот ST. Если вызов функции не имеет особого смысла — посмотрите на кадр ниже. Если все еще ничего — посмотрите ниже. Продолжайте двигаться вниз, пока не достигнете кадра, который можно объяснить. Если этот кадр достаточно хорошо объясняет вам, что делает поток — ура! Если нет — попробуйте вернуться вверх, пытаясь понять, что делает внутри метод, кадр которого вы узнали, или вниз, пытаясь найти, какая другая функция его вызвала.

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

Посмотрите, сколько потоков заняты более или менее одним и тем же делом. Если есть несколько потоков с очень похожими трассировками стека — вы, вероятно, нашли узкое место. Чем выше в стеке вы находитесь — тем точнее вы можете определить природу узкого места. Лучше всего уметь понимать 5 верхних кадров в стеке.

Примеры

"Camel (camel-8) thread #140 - aws-sqs://prod-q" #235 daemon prio=5 os_prio=0 tid=0x00007f5e40f26000 nid=0x113 runnable [0x00007f5c00dcb000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:464)
        at sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:68)
        at sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1346)
        at sun.security.ssl.SSLSocketImpl.access$300(SSLSocketImpl.java:73)
        at sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:962)
...

java.net.SocketInputStream.socketRead0() — означает, что само приложение ожидает ответа по сети от удаленного сервиса, от которого оно зависит. Вероятно, нижележащий сервис отстает.

"threadPoolTaskExecutor-1" #114 prio=5 os_prio=0 cpu=4226.74ms elapsed=356.38s tid=0x00007f1b5df8cee0 nid=0xd3 waiting on condition  [0x00007f1b568a9000]
   java.lang.Thread.State: WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@11.0.16/Native Method)
        - parking to wait for  <0x00001000dbd3afd0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(java.base@11.0.16/LockSupport.java:194)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.16/AbstractQueuedSynchronizer.java:2081)
        at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:393)
        at org.apache.http.pool.AbstractConnPool.access$300(AbstractConnPool.java:70)
        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:253)
        - locked <0x00001000db478530> (a org.apache.http.pool.AbstractConnPool$2)
        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:198)
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:306)
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:282)
        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:190)
        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
        at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)

...

org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(), что вскоре приводит к вызову org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking() и парковке потока — означает, что у вас слишком маленький пул соединений HttpClient для эффективной обработки нагрузки. Возможно, вам нужно увеличить этот пул и провести повторное тестирование.

"threadPoolTaskExecutor-5" #73 prio=5 os_prio=0 cpu=1190.99ms elapsed=5982.61s tid=0x00007f103db6e940 nid=0xb3 waiting on condition  [0x00007f103ac64000]
   java.lang.Thread.State: WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@11.0.16/Native Method)
        - parking to wait for  <0x0000100073c178f0> (a java.util.concurrent.CompletableFuture$Signaller)
        at java.util.concurrent.locks.LockSupport.park(java.base@11.0.16/LockSupport.java:194)
        at java.util.concurrent.CompletableFuture$Signaller.block(java.base@11.0.16/CompletableFuture.java:1796)
        at java.util.concurrent.ForkJoinPool.managedBlock(java.base@11.0.16/ForkJoinPool.java:3128)
        at java.util.concurrent.CompletableFuture.waitingGet(java.base@11.0.16/CompletableFuture.java:1823)
        at java.util.concurrent.CompletableFuture.join(java.base@11.0.16/CompletableFuture.java:2043)
...

java.util.concurrent.locks.LockSupport.park(), когда вы видите некоторые вызовы CompletableFuture.get() — вероятно, вы используете общий пул потоков ForkJoin для ваших CompletableFutures, который по умолчанию ограничен очень малым количеством потоков (count(CPU)-1). Либо перепишите код для использования вашего пользовательского исполнителя, либо увеличьте размер общего пула.

Графы пламени

Что это такое

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

Я согласен, пламеграфы — это не красивые картинки. Потому что это не то, чем они являются. Вместо этого они представляют собой очень мощное, интерактивное, многомерное графическое представление данных связанных деревьев, таких как CallTraces. Чтобы понять их, не обязательно любить их. Мне нравится называть их «несколькими следами вызовов, наложенными друг на друга». Как если бы это были прозрачные листы пластика с похожими кривыми и формами, которые можно сложить в кучу и посмотреть сквозь кучу, насколько эти кривые и формы отличаются или похожи.

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

Если у нас все трассы начинаются с одних и тех же 5 вызовов, а последующие вызовы разделены на 2 разных набора последовательностей вызовов функций на всех ST — на FlameGraph у нас будет один столбец высотой в 5 кадров, поверх которого расположены 2 более узких столбца, представляющих 2 разные последовательности вызовов функций, как было сказано ранее.

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

Размеры

Каждый FlameGraph имеет как минимум 3 измерения:

• высота — это то, насколько глубоко в стеке находится фрейм. Чем выше фрейм — тем глубже (чем более поздний) вызов. Точно так же, как в необработанных StackTraces.
• ширина — сколько таких одинаковых последовательностей кадров стека по сравнению с другими кадрами стека
  • если ширина полосы такая же, как ширина картинки — все эти вызовы встречались во всех потоках
  • если полоса составляет 50% от ширины картинки — 50% потоков имели этот вызов в своих ST на этой же позиции (с той же последовательностью предшествующих вызовов); остальные 50% имели разные вызовы на этой глубине стека
• цвета — это необязательное, но удобное измерение: оно выделяет вызовы, сделанные функциями, написанными нами, и приглушает вызовы функций внутри библиотек. Так проще отфильтровать вызовы, которые нас интересуют в первую очередь, от тех, которые выполняются внутри библиотек.
• text — описывает, что представлял собой вызов функции (по сути, выдержка из CallTrace).
• other — опционально, могут быть всплывающие окна при наведении мыши, предоставляющие дополнительную информацию о каждом кадре.

Каждый кадр в пламеграфе является кликабельным. Щелкнув на фрейме, вы можете расширить/масштабировать дерево его подвызовов (т.е. сделать ширину щелкнутого фрейма 100% и расширить все верхние фреймы соответственно). Щелкая на фреймах ниже расширенного, можно уменьшить масштаб.

Я знаю, это много для восприятия. Разработчики, которым я пытался показать пламеграфы, были озадачены и не хотели учиться их использовать, считая, что это слишком сложный инструмент, требующий много знаний/умений/времени, чтобы получить хоть какую-то пользу. НА САМОМ ДЕЛЕ ЭТО НЕ ТАК!!! Если вы можете читать CallTraces — читать FlameGraphs будет так же легко, если вы потрудитесь поиграть с ними в течение 10 минут в первый раз. Вам не должно понадобиться больше 10 минут, чтобы понять концепцию.

Зачем напрягаться?

Прекрасный вопрос. И это стоит того, чтобы потрудиться, потому что это уменьшает количество данных, которые вам нужно анализировать, с 70 МБ обычного текста TD до одного изображения, которое поместится на вашем экране. Более того, на FlameGraph большая часть анализа уже сделана за вас, и она визуализирована!

В общем, когда я анализирую FlameGraphs, я ищу самые большие кластеры одинаковых CallTraces. Они будут изображены в виде небоскребов с самыми плоскими крышами. Чем выше небоскреб и чем площе крыша — тем больше вероятность того, что это узкое место. Но как связаны здания и CallTraces?

• Чем выше столбец — тем глубже поток находится в процессе выполнения своей задачи. Помните, что при анализе необработанных ST мы фокусируемся на загруженных потоках — тех, которые имеют большие трассы вызовов.
• Чем больше потоков имеют одинаковый след вызова (до какого-то конкретного кадра), тем шире будет выглядеть башня/столбец.

Пример

Рассмотрим этот пример на языке Clojure:

Позвольте мне разложить его для вас. Мы смотрим на отдельные «башни». Здесь мы видим 4 значительно отличающиеся друг от друга «башни»

1. На этой много острых пиков, что означает, что несколько потоков работают над такой задачей (основание башни несколько широкое), но в процессе обработки этих задач потоки занимаются самыми разными вещами (разные пики). Нет ни одной вещи, на которой несколько потоков могли бы застрять (один и тот же кадр в нескольких потоках будет представлен в виде широкой ячейки: чем больше потоков — тем шире ячейка). Я не вижу здесь никаких проблем.
2. Крыша этой башни настолько широкая, что ее даже трудно назвать башней. Больше похоже на плоскость (геологическую)… Глубина стека определенно больше 30 кадров. Это занятые или неработающие потоки? Если холостые — они нас не особо волнуют, но если занятые — … Это стоит выяснить. Трудно представить себе неработающий поток, который бы ожидал новых задач во время вызова Object.hashCode(), так что это должны быть занятые потоки. Почему так много потоков (потому что столбец очень широкий) застряли на вызове Object.hashCode()? Это определенно похоже на серьезную проблему производительности, поскольку обычно вычисление хэша происходит слишком быстро, чтобы даже появиться в StackTraces. А теперь у нас не один, не два, а более 50% всех потоков застряли там! Имеет ли эта функция хэш-кода какую-то собственную реализацию? Нужно посмотреть.
3. Эта башня — самая узкая из четырех, а на крыше много антенн и нет плоских плоскостей, на которые мог бы приземлиться вертолет. Это выглядит как здоровое исполнение — не вижу здесь никаких проблем!
4. Это относительно широкая башня, с широким основанием. Но посмотрите на вершину — у нее есть несколько шипов и большая плоская поверхность на самом верху! Эта плоская крыша говорит о том, что несколько потоков застряли на одинаковом вызове функции и не могут двигаться дальше. Что написано на этой крыше…? Я плохо вижу. Увеличьте масштаб этой башни, щелкнув по одной из самых широких рамок на ней. Вот, теперь все лучше. Похоже, что несколько потоков застряли на вызове Object.clone(). Это может быть нормально в некоторых случаях, потому что clone() может потребоваться обход большого графа объектов (если это глубокий клон), или это может быть другая проблема производительности. Возможно, стоит обратить на это внимание сразу после того, как слон по имени Object.hashCode() покинет комнату.

Граф пламени с обратными корнями

После того как вы хорошо освоите FlameGraphs, я хотел бы представить вам Reverse-roots Flamegraph (RrFG). Позвольте мне сделать это на примере.

Рассмотрим приведенный ниже FlameGraph. Приложение работает вяло и не спешит отвечать на некоторые запросы, в то время как другие запросы оно выполняет очень быстро. Общим знаменателем между медленными запросами является то, что приложение выполняет последующие сетевые вызовы для обработки этих запросов. Поэтому мы подозреваем проблемы, связанные с сетью. Теперь на этом FlameGraph мы видим несколько высоких колонн, некоторые с плоскими крышами, другие — с зубчатыми. Как узнать, какие из них выполняют сетевые вызовы? Ну, мы наводим курсор мыши на каждую крышу и смотрим, что говорит всплывающее окно — является ли это socketRead0() или нет. А это утомительная и чреватая ошибками работа. Посмотрите на FlameGraph ниже — обведенные крыши это вызовы socketRead0(). Можете ли вы определить, сколько потоков выполняют этот вызов? Я точно не могу, без блокнота, карандаша, калькулятора и получаса свободного времени. Разве не было бы здорово собрать все похожие «крыши» в одном месте?

Вот тут-то и приходит на помощь RrFG. И он делает именно это. Он переворачивает все StackTraces и рисует FlameGraph как раньше. Однако до реверсирования большинство ST начинались (внизу) с Thread.run() и заканчивались Object.wait(). После реверсирования эти ST теперь начинаются с Object.wait() и заканчиваются Thread.run(). Этот маневр не только меняет порядок чтения стека, но и суммирует все вызовы Object.wait() в одну ячейку в самом низу. Аналогично, он также суммирует все вызовы socketRead0(). Теперь мы видим общее количество вызовов socketRead0(), как они соотносятся с другими вызовами в потоках, и знаем, откуда эти вызовы исходили (читая вверх по столбцу).

Серия ST. Профилирование

Анализ StackTrace дает много полезной информации для работы, но все это при условии, что у вас есть правильный ST. В некоторых случаях может быть трудно получить ST, отражающий рассматриваемую проблему, особенно если она длится до секунды, и еще больше — если ее нелегко воспроизвести или ее возникновение непредсказуемо. Поэтому вместо того, чтобы ловить шпроты гарпуном, мы можем закинуть сеть и надеяться, что поймаем хотя бы одну из них. Мы можем сделать это, захватывая StackTraces одного и того же процесса каждые 500 мс или даже чаще и складывая их в файл. Это повышает вероятность того, что мы поймаем приложение в тот момент, когда оно испытывает трудности, и захватим информативный ST, необходимый нам для анализа.

Предположим, вы микроменеджер. У вас в подчинении разработчик, и вы хотите знать, что он делает. Самый простой подход — подходить к его столу каждые 2 минуты и смотреть самому.

• 09:00-09:28 он отсутствует
• 09:30-12:44 он за своим столом
• 12:46-13:18 он снова отсутствует
• 13:20-14:52 он за своим столом
• 15:54-15:58 он отсутствует
• 16:00-18:00 он за своим столом

Видя результаты, мы можем предположить, что разработчик опоздал утром на 28 минут. Затем он работал без перерыва до 12:46, когда, вероятно, сделал перерыв на обед. В 13:20 он вернулся и работал непрерывно до конца рабочего дня с единственным коротким перерывом в 15:54 — вероятно, в туалет. Что происходило между каждым 2-минутным опросом — мы не знаем, может быть, он работал, может быть, бегал голым — узнать невозможно. Но из той последовательности данных, которая у нас есть, кажется, что он довольно хороший и трудолюбивый работник.

То же самое мы можем сделать с последовательностью StackTraces. Если мы будем опрашивать стек приложения достаточно часто, мы сможем получить достаточно хорошее представление о том, что оно делает с течением времени: где быстро, где медленно, а где простаивает. Чем ближе опросы, тем лучше детализация работы приложения, и тем более точный профиль приложения мы можем создать. Конечно, опрос в течение 8 часов каждые 500 мс или менее может быть чрезмерным, не говоря уже о количестве создаваемых данных. Хорошая идея — составлять профиль приложения только в период, когда у него есть проблемы. Что касается количества ST для анализа — либо соберите все эти ST в один FlameGraph и посмотрите, на какие функции приложение тратило больше всего времени, либо создайте FlameGraph для каждого захвата ST и сравните их друг с другом. Или, например, сгруппировать ST по секундам (или по 5 секунд, или так далее) и создать FlameGraphs для каждой из групп и визуально сравнить их друг с другом. Или сделать все вышеперечисленное.

Подводные камни

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

Захват

Очень важно, КОГДА захватывается StackTrace. Чтобы быть полезной диагностической информацией, она должна быть захвачена в нужное время — именно тогда, когда приложение испытывает проблемы. Даже 1 секунда слишком поздно или слишком рано означает целый мир и делает ST непригодным для анализа.

Анализ

Имея такой мощный инструмент, как FlameGraph, вы можете поддаться искушению и начать использовать фразы типа «этот метод выполнялся дольше, чем <…>». В StackTraces нет понятия «дольше», так же как нет понятия «быстрее». В StackTraces нет временной продолжительности, так же как нет временного промежутка на 20-летней фотографии, где вы изображены ребенком. Просто взглянув на фотографию, я не смогу сказать, как долго вы стояли в этой позе. И это особенно актуально при сминании ThreadDump с большим количеством потоков, запущенных во FlameGraph. Выполнение Object.hashCode() не заняло на 50% больше времени, чем выполнение любого другого метода в приложении. Правильнее было бы сказать: «50% занятых потоков вызывали Object.hashCode()«. И зная быструю природу hachCode(), мы можем предположить, что появление этого метода в ST не является нормальным, если только его выполнение не занимает больше времени, чем ожидалось.

У нас может возникнуть ощущение времени, если мы захватим серию ST и скомпонуем их в FlameGraph, потому что у нас нет временного интервала — эти ST были захвачены в течение времени. Но будьте осторожны, поскольку измерение времени смешивается с измерением потоков на ТД. Каждый снимок, который вы делаете, может иметь ряд потоков, выполняющих некоторые вызовы функций. И по мере выполнения задач они, как правило, попадают в разные потоки для выполнения. И никто не говорит, что выполнение не может длиться ровно 500 мс — достаточно долго, чтобы вы не заметили никакой разницы между опросами ST. И если вы не заметите ни смены потоков, ни длительности выполнения (а вы, вероятно, не заметите, поскольку не знаете, что происходит между опросами ST), у вас возникнет соблазн предположить, что выполнение продолжается в течение некоторого времени.

Будьте осторожны. StackTraces не имеет никакого отношения к продолжительности выполнения. Они могут предполагать это, если вы фиксируете последовательность ST с достаточно высокой детализацией, но всегда есть шанс, что вы пропустили прерывание/изменение выполнения между опросами.

Ссылки

• https://www.ibm.com/docs/en/sdk-java-technology/7.1?topic=ij-threads-stack-trace-threads-1
• https://unix.stackexchange.com/questions/166541/how-to-know-where-a-program-is-stuck-in-linux

Написано с помощью StackEdit.