Instrumenting Julia with DTrace, and bpftrace

    Julia 1.8

    Support for probes was added in Julia 1.8

    Note

    This documentation has been written from a Linux perspective, most of this should hold on Mac OS/Darwin and FreeBSD.

    On Linux install the package that has a version of dtrace.

    1. > readelf -n usr/lib/libjulia-internal.so.1
    3. Displaying notes found in: .note.gnu.build-id
    4.   Owner                Data size     Description
    5.   GNU                  0x00000014    NT_GNU_BUILD_ID (unique build ID bitstring)
    6.     Build ID: 57161002f35548772a87418d2385c284ceb3ead8
    8. Displaying notes found in: .note.stapsdt
    9.   Owner                Data size     Description
    10.   stapsdt              0x00000029    NT_STAPSDT (SystemTap probe descriptors)
    11.     Provider: julia
    12.     Name: gc__begin
    13.     Location: 0x000000000013213e, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cac
    14.     Arguments:
    15.   stapsdt              0x00000032    NT_STAPSDT (SystemTap probe descriptors)
    16.     Provider: julia
    17.     Name: gc__stop_the_world
    18.     Location: 0x0000000000132144, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cae
    19.     Arguments:
    20.   stapsdt              0x00000027    NT_STAPSDT (SystemTap probe descriptors)
    21.     Provider: julia
    22.     Name: gc__end
    23.     Location: 0x000000000013214a, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cb0
    24.     Arguments:
    25.   stapsdt              0x0000002d    NT_STAPSDT (SystemTap probe descriptors)
    26.     Provider: julia
    27.     Location: 0x0000000000132150, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cb2
    28.     Arguments:

    Adding probes in libjulia

    Probes are declared in dtraces format in the file src/uprobes.d. The generated header file is included in src/julia_internal.h and if you add probes you should provide a noop implementation there.

    The header will contain a semaphore *_ENABLED and the actual call to the probe. If the probe arguments are expensive to compute you should first check if the probe is enabled and then compute the arguments and call the probe.

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

    If your probe has no arguments it is preferred to not include the semaphore check. With USDT probes enabled the cost of a semaphore is a memory load, irrespective of the fact that the probe is enabled or not.

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

    Whereas the probe itself is a noop sled that will be patched to a trampoline to the probe handler.

    1. julia:gc__begin: GC begins running on one thread and triggers stop-the-world.
    2. julia:gc__stop_the_world: All threads have reached a safepoint and GC runs.
    3. julia:gc__mark__begin: Beginning the mark phase
    4. julia:gc__mark_end(scanned_bytes, perm_scanned): Mark phase ended
    5. julia:gc__sweep_begin(full): Starting sweep
    6. julia:gc__sweep_end: Sweep phase finished
    7. julia:gc__end: GC is finished, other threads continue work
    8. julia:gc__finalizer: Initial GC thread has finished running finalizers

    1. julia:rt__run__task(task): Switching to task task on current thread.
    2. julia:rt__pause__task(task): Switching from task task on current thread.
    3. julia:rt__new__task(parent, child): Task created task child on current thread.
    4. julia:rt__start__task(task): Task task started for the first time with a new stack.
    5. julia:rt__finish__task(task): Task task finished and will no longer execute.
    6. julia:rt__start__process__events(task): Task task started processing libuv events.
    7. julia:rt__finish__process__events(task): Task task finished processing libuv events.
    1. julia:rt__taskq__insert(ptls, task): Thread ptls attempted to insert task into a PARTR multiq.
    2. julia:rt__taskq__get(ptls, task): Thread ptls popped task from a PARTR multiq.

    Thread sleep/wake probes

    1. julia:rt__sleep__check__wake(ptls, old_state): Thread (PTLS ptls) waking up, previously in state old_state.
    2. julia:rt__sleep__check__wakeup(ptls): Thread (PTLS ptls) woke itself up.
    3. julia:rt__sleep__check__sleep(ptls): Thread (PTLS ptls) is attempting to sleep.
    4. julia:rt__sleep__check__taskq__wake(ptls): Thread (PTLS ptls) fails to sleep due to tasks in PARTR multiq.
    5. julia:rt__sleep__check__task__wake(ptls): Thread (PTLS ptls) fails to sleep due to tasks in Base workqueue.
    6. julia:rt__sleep__check__uv__wake(ptls): Thread (PTLS ptls) fails to sleep due to libuv wakeup.

    Probe usage examples

    GC stop-the-world latency

    An example bpftrace script is given in contrib/gc_stop_the_world_latency.bt and it creates a histogram of the latency for all threads to reach a safepoint.

    Running this Julia code, with julia -t 2

    and in a second terminal

    1. > sudo contrib/bpftrace/gc_stop_the_world_latency.bt
    2. Attaching 4 probes...
    3. Tracing Julia GC Stop-The-World Latency... Hit Ctrl-C to end.
    4. ^C
    7. @usecs[1743412]:
    8. [4, 8)               971 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
    9. [8, 16)              837 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@        |
    10. [16, 32)             129 |@@@@@@                                              |
    11. [32, 64)              10 |                                                    |

    It’s sometimes useful to know when a task is spawning other tasks. This is very easy to see with rt__new__task. The first argument to the probe, parent, is the existing task which is creating a new task. This means that if you know the address of the task you want to monitor, you can easily just look at the tasks that that specific task spawned. Let’s see how to do this; first let’s start a Julia session and get the PID and REPL’s task address:

    1. > julia
    2.                _
    3.    _       _ _(_)_     |  Documentation: https://docs.julialang.org
    4.   (_)     | (_) (_)    |
    5.    _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
    6.   | | | | | | |/ _` |  |
    8.  _/ |\__'_|_|_|\__'_|  |  Official https://julialang.org/ release
    9. |__/                   |
    11. 1> getpid()
    12. 997825
    14. 2> current_task()
    15. Task (runnable) @0x00007f524d088010

    Now we can start bpftrace and have it monitor rt__new__task for only this parent:

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

    (Note that in the above, arg0 is the first argument, parent).

    And if we spawn a single task:

    @async 1+1

    we see this task being created:

    Task: 4d088010

    However, if we spawn a bunch of tasks from that newly-spawned task:

    1. @async for i in 1:10
    2.    @async 1+1
    3. end

    we still only see one task from bpftrace:

    Task: 4d088010

    and it’s still the same task we were monitoring! Of course, we can remove this filter to see all newly-created tasks just as easily:

    We can see our root task, and the newly-spawned task as the parent of the ten even newer tasks.

    Task runtimes can often suffer from the “thundering herd” problem: when some work is added to a quiet task runtime, all threads may be woken up from their slumber, even if there isn’t enough work for each thread to process. This can cause extra latency and CPU cycles while all threads awaken (and simultaneously go back to sleep, not finding any work to execute).

    We can see this problem illustrated with bpftrace quite easily. First, in one terminal we start Julia with multiple threads (6 in this example), and get the PID of that process:

    1. > julia -t 6
    2.                _
    3.    _       _ _(_)_     |  Documentation: https://docs.julialang.org
    4.   (_)     | (_) (_)    |
    5.    _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
    6.   | | | | | | |/ _` |  |
    7.   | | |_| | | | (_| |  |  Version 1.6.2 (2021-07-14)
    8.  _/ |\__'_|_|_|\__'_|  |  Official https://julialang.org/ release
    9. |__/                   |
    11. 1> getpid()
    12. 997825

    And in another terminal we start bpftrace monitoring our process, specifically probing the rt__sleep__check__wake hook:

    sudo bpftrace -p 997825 -e 'usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__wake { printf("Thread wake up! %x\n", arg0); }'

    Now, we create and execute a single task in Julia:

    Threads.@spawn 1+1

    And in bpftrace we see printed out something like:

    1. Thread wake up! 3f926100
    2. Thread wake up! 3ebd5140
    3. Thread wake up! 3f876130
    4. Thread wake up! 3e2711a0
    5. Thread wake up! 3e312190

    Even though we only spawned a single task (which only one thread could process at a time), we woke up all of our other threads! In the future, a smarter task runtime might only wake up a single thread (or none at all; the spawning thread could execute this task!), and we should see this behavior go away.

    BPFnative.jl is able to attach to USDT probe points just like bpftrace. There is a demo available for monitoring the task runtime, GC, and thread sleep/wake transitions here.

    An example probe in the bpftrace format looks like:

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

    The probe declaration takes the kind usdt, then either the path to the library or the PID, the provider name julia and the probe name . Note that I am using a relative path to the libjulia-internal.so, but this might need to be an absolute path on a production system.