GitHub

Instrumenting Julia with DTrace, and bpftrace

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

Julia 1.8

Поддержка проб была добавлена в Julia 1.8

Note

Эта документация написана с точки зрения Linux, большинство из этого должно быть актуально для Mac OS/Darwin и FreeBSD.

Enabling support

На Linux установите пакет systemtap, который содержит версию dtrace, и создайте файл Make.user, содержащий

WITH_DTRACE=1

включить зондирование USDT.

Verifying

> readelf -n usr/lib/libjulia-internal.so.1

Displaying notes found in: .note.gnu.build-id
  Owner                Data size  Description
  GNU                  0x00000014 NT_GNU_BUILD_ID (unique build ID bitstring)
    Build ID: 57161002f35548772a87418d2385c284ceb3ead8

Displaying notes found in: .note.stapsdt
  Owner                Data size  Description
  stapsdt              0x00000029 NT_STAPSDT (SystemTap probe descriptors)
    Provider: julia
    Name: gc__begin
    Location: 0x000000000013213e, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cac
    Arguments:
  stapsdt              0x00000032 NT_STAPSDT (SystemTap probe descriptors)
    Provider: julia
    Name: gc__stop_the_world
    Location: 0x0000000000132144, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cae
    Arguments:
  stapsdt              0x00000027 NT_STAPSDT (SystemTap probe descriptors)
    Provider: julia
    Name: gc__end
    Location: 0x000000000013214a, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cb0
    Arguments:
  stapsdt              0x0000002d NT_STAPSDT (SystemTap probe descriptors)
    Provider: julia
    Name: gc__finalizer
    Location: 0x0000000000132150, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cb2
    Arguments:

Adding probes in libjulia

Пробы объявляются в формате dtraces в файле src/uprobes.d. Сгенерированный заголовочный файл включается в src/julia_internal.h, и если вы добавляете пробы, вы должны предоставить реализацию noop там.

Заголовок будет содержать семафор *_ENABLED и фактический вызов зонда. Если аргументы зонда дорогостоящие для вычисления, сначала следует проверить, включен ли зонд, а затем вычислить аргументы и вызвать зонд.

  if (JL_PROBE_{PROBE}_ENABLED())
    auto expensive_arg = ...;
    JL_PROBE_{PROBE}(expensive_arg);

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

#define JL_PROBE_GC_BEGIN_ENABLED() __builtin_expect (julia_gc__begin_semaphore, 0)
__extension__ extern unsigned short julia_gc__begin_semaphore __attribute__ ((unused)) __attribute__ ((section (".probes")));

В то время как сам зонд является noop-санкой, которая будет подключена к батуту для обработчика зонда.

Available probes

GC probes

  1. julia:gc__begin: GC начинает работу на одном потоке и вызывает остановку всего мира.
  2. julia:gc__stop_the_world: Все потоки достигли безопасной точки, и сборщик мусора работает.
  3. julia:gc__mark__begin: Начало фазы маркировки
  4. julia:gc__mark_end(scanned_bytes, perm_scanned): Фаза маркировки завершена
  5. julia:gc__sweep_begin(full): Начало очистки
  6. julia:gc__sweep_end: Фаза очистки завершена
  7. julia:gc__end: Сборка мусора завершена, другие потоки продолжают работу
  8. julia:gc__finalizer: Начальный поток сборщика мусора завершил выполнение финализаторов

Task runtime probes

  1. julia:rt__run__task(task): Переключение на задачу task в текущем потоке.
  2. julia:rt__pause__task(task): Переключение с задачи task на текущем потоке.
  3. julia:rt__new__task(parent, child): Задача parent создала задачу child в текущем потоке.
  4. julia:rt__start__task(task): Задача task запущена в первый раз с новым стеком.
  5. julia:rt__finish__task(task): Задача task завершена и больше не будет выполняться.
  6. julia:rt__start__process__events(task): Задача task начала обработку событий libuv.
  7. julia:rt__finish__process__events(task): Задача task завершила обработку событий libuv.

Task queue probes

  1. julia:rt__taskq__insert(ptls, task): Поток ptls попытался вставить task в многопоточную очередь PARTR.
  2. julia:rt__taskq__get(ptls, task): Поток ptls извлек task из многопоточной очереди PARTR.

Thread sleep/wake probes

  1. julia:rt__sleep__check__wake(ptls, old_state): Поток (PTLS ptls) просыпается, ранее находясь в состоянии old_state.
  2. julia:rt__sleep__check__wakeup(ptls): Поток (PTLS ptls) сам себя разбудил.
  3. julia:rt__sleep__check__sleep(ptls): Поток (PTLS ptls) пытается уснуть.
  4. julia:rt__sleep__check__taskq__wake(ptls): Поток (PTLS ptls) не может уснуть из-за задач в PARTR multiq.
  5. julia:rt__sleep__check__task__wake(ptls): Поток (PTLS ptls) не может уснуть из-за задач в рабочей очереди Base.
  6. julia:rt__sleep__check__uv__wake(ptls): Поток (PTLS ptls) не может уснуть из-за пробуждения libuv.

Probe usage examples

GC stop-the-world latency

Пример скрипта bpftrace приведен в contrib/gc_stop_the_world_latency.bt, и он создает гистограмму задержки для всех потоков, чтобы достичь безопасной точки.

Запустив этот код на Julia с julia -t 2

using Base.Threads

fib(x) = x <= 1 ? 1 : fib(x-1) + fib(x-2)

beaver = @spawn begin
    while true
        fib(30)
        # A manual safepoint is necessary since otherwise this loop
        # may never yield to GC.
        GC.safepoint()
    end
end

allocator = @spawn begin
    while true
        zeros(1024)
    end
end

wait(allocator)

и во втором терминале

> sudo contrib/bpftrace/gc_stop_the_world_latency.bt
Attaching 4 probes...
Tracing Julia GC Stop-The-World Latency... Hit Ctrl-C to end.
^C


@usecs[1743412]:
[4, 8)               971 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[8, 16)              837 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@        |
[16, 32)             129 |@@@@@@                                              |
[32, 64)              10 |                                                    |
[64, 128)              1 |                                                    |

Мы можем увидеть распределение задержки фазы остановки мира в выполненном процессе Julia.

Task spawn monitor

Иногда полезно знать, когда задача порождает другие задачи. Это очень легко увидеть с помощью rt__new__task. Первый аргумент к пробе, parent, — это существующая задача, которая создает новую задачу. Это означает, что если вы знаете адрес задачи, которую хотите отслеживать, вы можете легко посмотреть на задачи, которые порождает эта конкретная задача. Давайте посмотрим, как это сделать; сначала начнем сессии Julia и получим PID и адрес задачи REPL:

> julia
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.6.2 (2021-07-14)
 _/ |\__'_|_|_|\__'_|  |  Official https://julialang.org/ release
|__/                   |

1> getpid()
997825

2> current_task()
Task (runnable) @0x00007f524d088010

Теперь мы можем запустить bpftrace и заставить его отслеживать rt__new__task только для этого родителя:

sudo bpftrace -p 997825 -e 'usdt:usr/lib/libjulia-internal.so:julia:rt__new__task /arg0==0x00007f524d088010/{ printf("Задача: %x\n", arg0); }'

(Обратите внимание, что в приведенном выше примере arg0 является первым аргументом, parent.)

И если мы создадим одну задачу:

@async 1+1

мы видим, что эта задача создается:

Задача: 4d088010

Однако, если мы создадим множество задач из этой только что созданной задачи:

@async for i in 1:10
   @async 1+1
end

мы все еще видим только одну задачу от bpftrace:

Задача: 4d088010

и это все та же задача, которую мы отслеживали! Конечно, мы можем убрать этот фильтр, чтобы увидеть все вновь созданные задачи так же легко:

sudo bpftrace -p 997825 -e 'usdt:usr/lib/libjulia-internal.so:julia:rt__new__task { printf("Задача: %x\n", arg0); }'

Task: 4d088010
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290

Мы можем видеть нашу корневую задачу и вновь созданную задачу как родительскую для десяти еще более новых задач.

Thundering herd detection

Время выполнения задач может часто страдать от проблемы "громадного стада": когда в тихий поток задач добавляется работа, все потоки могут быть разбудены от своего сна, даже если для каждого потока недостаточно работы для обработки. Это может вызвать дополнительную задержку и циклы ЦП, пока все потоки пробуждаются (и одновременно снова засыпают, не находя работы для выполнения).

Мы можем легко увидеть эту проблему, проиллюстрировав её с помощью bpftrace. Сначала в одном терминале мы запускаем Julia с несколькими потоками (6 в этом примере) и получаем PID этого процесса:

> julia -t 6
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.6.2 (2021-07-14)
 _/ |\__'_|_|_|\__'_|  |  Official https://julialang.org/ release
|__/                   |

1> getpid()
997825

И в другом терминале мы запускаем bpftrace, чтобы мониторить наш процесс, в частности, проверяя хук rt__sleep__check__wake:

sudo bpftrace -p 997825 -e 'usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__wake { printf("Пробуждение потока! %x\n", arg0); }'

Теперь мы создадим и выполним одну задачу в Julia:

Threads.@spawn 1+1

И в bpftrace мы видим напечатанное что-то вроде:

Thread wake up! 3f926100
Thread wake up! 3ebd5140
Thread wake up! 3f876130
Thread wake up! 3e2711a0
Thread wake up! 3e312190

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

Task Monitor with BPFnative.jl

BPFnative.jl может подключаться к точкам проб USDT так же, как и bpftrace. Доступна демонстрация для мониторинга времени выполнения задач, сборки мусора и переходов потоков в сон/пробуждение here.

Notes on using bpftrace

Пример зонда в формате bpftrace выглядит следующим образом:

usdt:usr/lib/libjulia-internal.so:julia:gc__begin
{
  @start[pid] = nsecs;
}

Объявление зонда принимает вид usdt, затем либо путь к библиотеке, либо PID, имя провайдера julia и имя зонда gc__begin. Обратите внимание, что я использую относительный путь к libjulia-internal.so, но на производственной системе это может потребовать абсолютного пути.

Useful references: