Thread State Analysis

Интро

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

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

Для этой цели разработали множество методологий под любой стек и задачу. Часть из них B. Gregg привел в своей книге Systems Performance: USE / RED / Tools / Science методы, Latency Analisys и др.

Методологии делятся на:

верхнеуровневые - фокус на симптомы, пытаются ответить на вопрос “что идет не так”;
низкоуровневые - фокус на анализ конкретных компонент, “почему сломалось”.

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

В этот раз обсудим верхнеуровневую методологию - Thread State Analisys (TSA):

The goal is to identify at a high level where application threads are spending their time, which solves some issues immediately, and directs the investigation of others.

Теория

Суть методологии сводится к отслеживанию сколько по времени и в каком состоянии (state) находятся треды приложения. Где под тредом подразумевается сущность, способная исполняться на процессоре. В linux kernel тред представлен структурой task_struct.

Состояние треда в linux можно упрощено представить диаграммой: Нас интересуют:

Runnable (R) - тред готов к исполнению и ожидает очереди в run queue процессора;
Running (R) - тред исполняется на процессоре в данный момент;
Uninterruptible Sleep (D) - тред заблокирован в ожидании завершения IO операции (сброс данных на диск, etc);
Interruptible Sleep (S) - тред заснул в ожидании какого-то события (между интервалами полинга TCP сокета например).

И чем дольше тред пребывает в определенном состоянии, тем бОльший интерес оно вызывает для исследований, среди таких может быть:

профилирование в on-cpu режиме (Running);
проверка длительности нахождения треда в run queue процессора, а так же длину самой очереди (Runnable);
профилирование в off-cpu режиме (D / S);
какие системные вызовы используются для обращений к IO (асинхронные / синхронные), их длительность (D);
etc

Подробнее о типах исследований, а так же в каком порядке их стоит использовать описано в статье The TSA Method.

Тулинг

Стандартные утилиты

Информация о состоянии тредов процесса доступна в /proc:

# ls /proc/589/task
589  646  648  650  652 # родительский и дочерние треды процесса

# cat /proc/589/task/*/status | grep -E 'State' # моментальный снимок состояния тредов
State:	S (sleeping)
State:	S (sleeping)
State:	S (sleeping)
State:	S (sleeping)
State:	S (sleeping)

#  tail /proc/589/task/*/wchan # на какой функции ядра тред "уснул"
==> /proc/589/task/589/wchan <==
futex_wait_queue
==> /proc/589/task/646/wchan <==
futex_wait_queue
==> /proc/589/task/648/wchan <==
do_epoll_wait
==> /proc/589/task/650/wchan <==
futex_wait_queue
==> /proc/589/task/652/wchan <==
futex_wait_queue

#  tail /proc/589/task/*/stack # и как тред до неё добрался
==> /proc/589/task/589/stack <==
[<0>] futex_wait_queue+0x60/0x90
[<0>] futex_wait+0x163/0x260
[<0>] do_futex+0x126/0x1c0
[<0>] __x64_sys_futex+0x81/0x1c0
[<0>] do_syscall_64+0x5c/0xc0
[<0>] entry_SYSCALL_64_after_hwframe+0x63/0xcd

==> /proc/589/task/652/stack <==
[<0>] do_epoll_wait+0x630/0x760
[<0>] do_compat_epoll_pwait.part.0+0xc/0x70
[<0>] __x64_sys_epoll_pwait+0x7f/0x130
[<0>] do_syscall_64+0x5c/0xc0
[<0>] entry_SYSCALL_64_after_hwframe+0x63/0xcd
...

Часть этой информации удобнее получить утилитой ps:

#  ps -eLo s,tid,comm,wchan | grep node_exporter
S     589 node_exporter   futex_wait_queue
S     646 node_exporter   futex_wait_queue
S     648 node_exporter   futex_wait_queue
S     650 node_exporter   futex_wait_queue
S     652 node_exporter   do_epoll_wait

Все это очень познавательно, но в сыром виде практическая польза от этой информации минимальна.

0x.tools

Это набор скриптов (на python, bash и C) призванный с минимальным оверхедом получать сведения о состоянии тредов из директории /proc, а значит для их работы не требуются (почти) внешние зависимости, что очень актуально в окружениях со старыми версиями ядер.

Утилита psn позволяет получать агрегированный результат по тредам во времени:

# psn -p 7121 -d 60 -G syscall,wchan,kstack  # для PID 7121, за 60 секунд отобрази только R и D, плюс доп. поля - syscall, wchan, kstask 
=== Active Threads ===========================================================================================================================================================================================================================================

 samples | avg_threads | comm              | state                  | syscall         | wchan | kstack
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    2158 |        2.52 | (opensearch[os-*) | Running (ON CPU)       | [running]       | 0     | -
     119 |        0.14 | (opensearch[os-*) | Disk (Uninterruptible) | fdatasync       | 0     | __x64_sys_fdatasync()->xfs_file_fsync()->xfs_log_force_seq()->xlog_force_lsn()
      60 |        0.07 | (opensearch[os-*) | Disk (Uninterruptible) | fdatasync       | 0     | __x64_sys_fdatasync()->xfs_file_fsync()->blkdev_issue_flush()->submit_bio_wait()
      50 |        0.06 | (opensearch[os-*) | Disk (Uninterruptible) | fdatasync       | 0     | __x64_sys_fdatasync()->xfs_file_fsync()->xfs_log_force_seq()->xlog_wait_on_iclog()
      48 |        0.06 | (GC Thread#*)     | Running (ON CPU)       | [running]       | 0     | -
      43 |        0.05 | (opensearch[os-*) | Running (ON CPU)       | [running]       | 0     | __x64_sys_epoll_wait()->do_epoll_wait()
      35 |        0.04 | (G* Conc#*)       | Running (ON CPU)       | [running]       | 0     | -
      35 |        0.04 | (opensearch[os-*) | Disk (Uninterruptible) | [kernel_thread] | 0     | exc_page_fault()->do_user_addr_fault()->handle_mm_fault()->__do_fault()->__xfs_filemap_fault()->filemap_fault()->wait_on_page_bit_common()
      30 |        0.04 | (opensearch[os-*) | Disk (Uninterruptible) | fdatasync       | 0     | -
      23 |        0.03 | (opensearch[os-*) | Disk (Uninterruptible) | fdatasync       | 0     | __x64_sys_fdatasync()->xfs_file_fsync()->xlog_wait_on_iclog()
...

В листинге выше подавляющее количество времени процесс исполнялся на CPU делая (возможно) что-то полезное, небольшие доли у GC и ожидания в D.

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

TSA, как и другие высокоуровневые методологии (USE, RED), может помочь сориентироваться и определить направления для дальнейшего анализа и сократить общее время устранения проблем.

Кстати автор 0xTools вовсю переписывает свои инструменты на bcc (epbf), будем смотреть.

Интро#

Теория#

Тулинг#

Стандартные утилиты#

0x.tools#

Интро

Теория

Тулинг

Стандартные утилиты

0x.tools