From c5833bf5c65bcd3e629c331300ddba1b69d03322 Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Fri, 17 Dec 2021 14:10:04 -0600 Subject: [PATCH 01/11] Add USDTs for task switch and allocation --- contrib/bpftrace/rt_all.bt | 21 +++++++++++++++++++++ doc/src/devdocs/probes.md | 7 ++++++- src/julia_internal.h | 6 ++++++ src/task.c | 6 ++++++ src/uprobes.d | 4 ++++ 5 files changed, 43 insertions(+), 1 deletion(-) create mode 100755 contrib/bpftrace/rt_all.bt diff --git a/contrib/bpftrace/rt_all.bt b/contrib/bpftrace/rt_all.bt new file mode 100755 index 0000000000000..60fe28a4906fd --- /dev/null +++ b/contrib/bpftrace/rt_all.bt @@ -0,0 +1,21 @@ +#!/usr/bin/env bpftrace + +BEGIN +{ + printf("Tracing Julia Task events... Hit Ctrl-C to end.\n"); +} + +usdt:usr/lib/libjulia-internal.so:julia:rt__run__task +{ + printf("Task running: %x\n", arg0); +} + +usdt:usr/lib/libjulia-internal.so:julia:rt__pause__task +{ + printf("Task pausing: %x\n", arg0); +} + +usdt:usr/lib/libjulia-internal.so:julia:rt__new__task +{ + printf("Task created: %x (Parent %x)\n", arg1, arg0); +} diff --git a/doc/src/devdocs/probes.md b/doc/src/devdocs/probes.md index 7e2fb96df5ac8..83e63bdb621ce 100644 --- a/doc/src/devdocs/probes.md +++ b/doc/src/devdocs/probes.md @@ -90,10 +90,15 @@ the probe handler. 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 +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 +### Task runtime probes + +1. `julia:rt__ctx__switch(last, next, ptls)`: Switching from task `last` to task `next` on thread associated with PTLS `ptls`. +2. `julia:rt__new__task(parent, child, ptls)`: Task `parent` created task `child` on thread associated with PTLS `ptls`. + #### GC stop-the-world latency An example `bpftrace` script is given in `contrib/gc_stop_the_world_latency.bt` diff --git a/src/julia_internal.h b/src/julia_internal.h index 4990268e5f417..7c426d8e57f22 100644 --- a/src/julia_internal.h +++ b/src/julia_internal.h @@ -1540,6 +1540,9 @@ uint16_t __gnu_f2h_ieee(float param) JL_NOTSAFEPOINT; #define JL_PROBE_GC_SWEEP_END() do ; while (0) #define JL_PROBE_GC_END() do ; while (0) #define JL_PROBE_GC_FINALIZER() do ; while (0) +#define JL_PROBE_RT_RUN_TASK(task) do ; while (0) +#define JL_PROBE_RT_PAUSE_TASK(task) do ; while (0) +#define JL_PROBE_RT_NEW_TASK(parent, child) do ; while (0) #define JL_PROBE_GC_BEGIN_ENABLED() (0) #define JL_PROBE_GC_STOP_THE_WORLD_ENABLED() (0) @@ -1549,6 +1552,9 @@ uint16_t __gnu_f2h_ieee(float param) JL_NOTSAFEPOINT; #define JL_PROBE_GC_SWEEP_END_ENABLED() (0) #define JL_PROBE_GC_END_ENABLED() (0) #define JL_PROBE_GC_FINALIZER_ENABLED() (0) +#define JL_PROBE_RT_RUN_TASK_ENABLED() (0) +#define JL_PROBE_RT_PAUSE_TASK_ENABLED() (0) +#define JL_PROBE_RT_NEW_TASK_ENABLED() (0) #endif #endif diff --git a/src/task.c b/src/task.c index 9f55b9b64a833..ff6c484dedb60 100644 --- a/src/task.c +++ b/src/task.c @@ -532,6 +532,8 @@ JL_DLLEXPORT void jl_switch(void) if (!jl_set_task_tid(t, jl_atomic_load_relaxed(&ct->tid))) // manually yielding to a task jl_error("cannot switch to task running on another thread"); + JL_PROBE_RT_PAUSE_TASK(ct); + // Store old values on the stack and reset sig_atomic_t defer_signal = ptls->defer_signal; int8_t gc_state = jl_gc_unsafe_enter(ptls); @@ -579,6 +581,8 @@ JL_DLLEXPORT void jl_switch(void) ptls->defer_signal = defer_signal; if (other_defer_signal && !defer_signal) jl_sigint_safepoint(ptls); + + JL_PROBE_RT_RUN_TASK(ct); } JL_DLLEXPORT void jl_switchto(jl_task_t **pt) @@ -813,6 +817,7 @@ JL_DLLEXPORT jl_task_t *jl_new_task(jl_function_t *start, jl_value_t *completion #ifdef _COMPILER_TSAN_ENABLED_ t->ctx.tsan_state = __tsan_create_fiber(0); #endif + JL_PROBE_RT_NEW_TASK(ct, t); return t; } @@ -908,6 +913,7 @@ CFI_NORETURN #endif ct->started = 1; + JL_PROBE_RT_RUN_TASK(ct); if (jl_atomic_load_relaxed(&ct->_isexception)) { record_backtrace(ptls, 0); jl_push_excstack(&ct->excstack, ct->result, diff --git a/src/uprobes.d b/src/uprobes.d index a583daf8c58f4..8cb0329e74a4b 100644 --- a/src/uprobes.d +++ b/src/uprobes.d @@ -9,6 +9,10 @@ provider julia { probe gc__sweep__end(); probe gc__end(); probe gc__finalizer(); + + probe rt__run__task(jl_task_t *task); + probe rt__pause__task(jl_task_t *task); + probe rt__new__task(jl_task_t *parent, jl_task_t *child); }; #pragma D attributes Evolving/Evolving/Common provider julia provider From 1e0ad56eb09482be4ac15556ef99622e37f3f5c0 Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Sat, 18 Dec 2021 14:32:17 -0600 Subject: [PATCH 02/11] Add USDTs for process_events start/finish Co-authored-by: Takafumi Arakaki --- contrib/bpftrace/rt_all.bt | 10 ++++++++++ src/jl_uv.c | 2 ++ src/julia_internal.h | 4 ++++ src/uprobes.d | 2 ++ 4 files changed, 18 insertions(+) diff --git a/contrib/bpftrace/rt_all.bt b/contrib/bpftrace/rt_all.bt index 60fe28a4906fd..d986d5f28edd3 100755 --- a/contrib/bpftrace/rt_all.bt +++ b/contrib/bpftrace/rt_all.bt @@ -19,3 +19,13 @@ usdt:usr/lib/libjulia-internal.so:julia:rt__new__task { printf("Task created: %x (Parent %x)\n", arg1, arg0); } + +usdt:usr/lib/libjulia-internal.so:julia:rt__start__process__events +{ + printf("Task processing libuv events: %x\n", arg0); +} + +usdt:usr/lib/libjulia-internal.so:julia:rt__finish__process__events +{ + printf("Task processed libuv events: %x\n", arg0); +} diff --git a/src/jl_uv.c b/src/jl_uv.c index e803e6263142d..d2372b59c4670 100644 --- a/src/jl_uv.c +++ b/src/jl_uv.c @@ -205,8 +205,10 @@ JL_DLLEXPORT int jl_process_events(void) jl_gc_safepoint_(ct->ptls); if (loop && (jl_atomic_load_relaxed(&_threadedregion) || jl_atomic_load_relaxed(&ct->tid) == 0)) { if (jl_atomic_load_relaxed(&jl_uv_n_waiters) == 0 && jl_mutex_trylock(&jl_uv_mutex)) { + JL_PROBE_RT_START_PROCESS_EVENTS(ct); loop->stop_flag = 0; int r = uv_run(loop, UV_RUN_NOWAIT); + JL_PROBE_RT_FINISH_PROCESS_EVENTS(ct); JL_UV_UNLOCK(); return r; } diff --git a/src/julia_internal.h b/src/julia_internal.h index 7c426d8e57f22..b4f2e38a76a13 100644 --- a/src/julia_internal.h +++ b/src/julia_internal.h @@ -1543,6 +1543,8 @@ uint16_t __gnu_f2h_ieee(float param) JL_NOTSAFEPOINT; #define JL_PROBE_RT_RUN_TASK(task) do ; while (0) #define JL_PROBE_RT_PAUSE_TASK(task) do ; while (0) #define JL_PROBE_RT_NEW_TASK(parent, child) do ; while (0) +#define JL_PROBE_RT_START_PROCESS_EVENTS(task) do ; while (0) +#define JL_PROBE_RT_FINISH_PROCESS_EVENTS(task) do ; while (0) #define JL_PROBE_GC_BEGIN_ENABLED() (0) #define JL_PROBE_GC_STOP_THE_WORLD_ENABLED() (0) @@ -1555,6 +1557,8 @@ uint16_t __gnu_f2h_ieee(float param) JL_NOTSAFEPOINT; #define JL_PROBE_RT_RUN_TASK_ENABLED() (0) #define JL_PROBE_RT_PAUSE_TASK_ENABLED() (0) #define JL_PROBE_RT_NEW_TASK_ENABLED() (0) +#define JL_PROBE_RT_START_PROCESS_EVENTS_ENABLED() (0) +#define JL_PROBE_RT_FINISH_PROCESS_EVENTS_ENABLED() (0) #endif #endif diff --git a/src/uprobes.d b/src/uprobes.d index 8cb0329e74a4b..4cb5e73655c48 100644 --- a/src/uprobes.d +++ b/src/uprobes.d @@ -13,6 +13,8 @@ provider julia { probe rt__run__task(jl_task_t *task); probe rt__pause__task(jl_task_t *task); probe rt__new__task(jl_task_t *parent, jl_task_t *child); + probe rt__start__process__events(jl_task_t *task); + probe rt__finish__process__events(jl_task_t *task); }; #pragma D attributes Evolving/Evolving/Common provider julia provider From 7047c66df90be7714c12da3a8c22d17db1ecf20a Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Tue, 4 Jan 2022 14:08:11 -0600 Subject: [PATCH 03/11] devdocs: Add some task runtime probe docs --- doc/src/devdocs/probes.md | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/doc/src/devdocs/probes.md b/doc/src/devdocs/probes.md index 83e63bdb621ce..b00d5693875fe 100644 --- a/doc/src/devdocs/probes.md +++ b/doc/src/devdocs/probes.md @@ -96,8 +96,11 @@ the probe handler. ### Task runtime probes -1. `julia:rt__ctx__switch(last, next, ptls)`: Switching from task `last` to task `next` on thread associated with PTLS `ptls`. -2. `julia:rt__new__task(parent, child, ptls)`: Task `parent` created task `child` on thread associated with PTLS `ptls`. +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 `parent` created task `child` on current thread. +4. `julia:rt__start__process__events(task)`: Task `task` started processing libuv events. +5. `julia:rt__finish__process__events(task)`: Task `task` finished processing libuv events. #### GC stop-the-world latency From 5eb9bac0d85046010b10ddae7ffdc282b30fb7dc Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Wed, 5 Jan 2022 10:38:17 -0600 Subject: [PATCH 04/11] Add USDTs for thread sleep/wakeup --- contrib/bpftrace/rt_all.bt | 30 ++++++++++++++++++++++++++++++ doc/src/devdocs/probes.md | 6 ++++++ src/julia_internal.h | 12 ++++++++++++ src/partr.c | 22 +++++++++++++++++----- src/uprobes.d | 6 ++++++ 5 files changed, 71 insertions(+), 5 deletions(-) diff --git a/contrib/bpftrace/rt_all.bt b/contrib/bpftrace/rt_all.bt index d986d5f28edd3..bc362010a0a2f 100755 --- a/contrib/bpftrace/rt_all.bt +++ b/contrib/bpftrace/rt_all.bt @@ -29,3 +29,33 @@ usdt:usr/lib/libjulia-internal.so:julia:rt__finish__process__events { printf("Task processed libuv events: %x\n", arg0); } + +usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__wake +{ + printf("Thread waking: %x (was sleeping?: %d)\n", arg0, arg1); +} + +usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__wakeup +{ + printf("Thread wakeup: %x\n", arg0); +} + +usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__sleep +{ + printf("Thread trying to sleep: %x\n", arg0); +} + +usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__taskq__wake +{ + printf("Thread waking due to non-empty task queue: %x\n", arg0); +} + +usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__task__wake +{ + printf("Thread waking due to popped task: %x\n", arg0); +} + +usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__uv__wake +{ + printf("Thread waking due to libuv: %x\n", arg0); +} diff --git a/doc/src/devdocs/probes.md b/doc/src/devdocs/probes.md index b00d5693875fe..c89832a76b63e 100644 --- a/doc/src/devdocs/probes.md +++ b/doc/src/devdocs/probes.md @@ -101,6 +101,12 @@ the probe handler. 3. `julia:rt__new__task(parent, child)`: Task `parent` created task `child` on current thread. 4. `julia:rt__start__process__events(task)`: Task `task` started processing libuv events. 5. `julia:rt__finish__process__events(task)`: Task `task` finished processing libuv events. +6. `julia:rt__sleep__check__wake(ptls, old_state)`: Thread (PTLS `ptls`) waking up, previously in state `old_state`. +7. `julia:rt__sleep__check__wakeup(ptls)`: Thread (PTLS `ptls`) woke itself up. +8. `julia:rt__sleep__check__sleep(ptls)`: Thread (PTLS `ptls`) is attempting to sleep. +9. `julia:rt__sleep__check__taskq__wake(ptls)`: Thread (PTLS `ptls`) fails to sleep due to tasks in PARTR multiq. +10. `julia:rt__sleep__check__task__wake(ptls)`: Thread (PTLS `ptls`) fails to sleep due to tasks in Base workqueue. +11. `julia:rt__sleep__check__uv__wake(ptls)`: Thread (PTLS `ptls`) fails to sleep due to libuv wakeup. #### GC stop-the-world latency diff --git a/src/julia_internal.h b/src/julia_internal.h index b4f2e38a76a13..d0d47c17eae30 100644 --- a/src/julia_internal.h +++ b/src/julia_internal.h @@ -1545,6 +1545,12 @@ uint16_t __gnu_f2h_ieee(float param) JL_NOTSAFEPOINT; #define JL_PROBE_RT_NEW_TASK(parent, child) do ; while (0) #define JL_PROBE_RT_START_PROCESS_EVENTS(task) do ; while (0) #define JL_PROBE_RT_FINISH_PROCESS_EVENTS(task) do ; while (0) +#define JL_PROBE_RT_SLEEP_CHECK_WAKE(other, old_state) do ; while (0) +#define JL_PROBE_RT_SLEEP_CHECK_WAKEUP(ptls) do ; while (0) +#define JL_PROBE_RT_SLEEP_CHECK_SLEEP(ptls) do ; while (0) +#define JL_PROBE_RT_SLEEP_CHECK_TASKQ_WAKE(ptls) do ; while (0) +#define JL_PROBE_RT_SLEEP_CHECK_TASK_WAKE(ptls) do ; while (0) +#define JL_PROBE_RT_SLEEP_CHECK_UV_WAKE(ptls) do ; while (0) #define JL_PROBE_GC_BEGIN_ENABLED() (0) #define JL_PROBE_GC_STOP_THE_WORLD_ENABLED() (0) @@ -1559,6 +1565,12 @@ uint16_t __gnu_f2h_ieee(float param) JL_NOTSAFEPOINT; #define JL_PROBE_RT_NEW_TASK_ENABLED() (0) #define JL_PROBE_RT_START_PROCESS_EVENTS_ENABLED() (0) #define JL_PROBE_RT_FINISH_PROCESS_EVENTS_ENABLED() (0) +#define JL_PROBE_RT_SLEEP_CHECK_WAKE_ENABLED() (0) +#define JL_PROBE_RT_SLEEP_CHECK_WAKEUP_ENABLED() (0) +#define JL_PROBE_RT_SLEEP_CHECK_SLEEP_ENABLED() (0) +#define JL_PROBE_RT_SLEEP_CHECK_TASKQ_WAKE_ENABLED() (0) +#define JL_PROBE_RT_SLEEP_CHECK_TASK_WAKE_ENABLED() (0) +#define JL_PROBE_RT_SLEEP_CHECK_UV_WAKE_ENABLED() (0) #endif #endif diff --git a/src/partr.c b/src/partr.c index 22c9c15605f21..49ce36d28c37a 100644 --- a/src/partr.c +++ b/src/partr.c @@ -365,6 +365,7 @@ static int wake_thread(int16_t tid) if (jl_atomic_load_relaxed(&other->sleep_check_state) == sleeping) { if (jl_atomic_cmpswap_relaxed(&other->sleep_check_state, &state, not_sleeping)) { + JL_PROBE_RT_SLEEP_CHECK_WAKE(other, state); uv_mutex_lock(&sleep_locks[tid]); uv_cond_signal(&wake_signals[tid]); uv_mutex_unlock(&sleep_locks[tid]); @@ -394,8 +395,10 @@ JL_DLLEXPORT void jl_wakeup_thread(int16_t tid) if (tid == self || tid == -1) { // we're already awake, but make sure we'll exit uv_run jl_ptls_t ptls = ct->ptls; - if (jl_atomic_load_relaxed(&ptls->sleep_check_state) == sleeping) + if (jl_atomic_load_relaxed(&ptls->sleep_check_state) == sleeping) { jl_atomic_store_relaxed(&ptls->sleep_check_state, not_sleeping); + JL_PROBE_RT_SLEEP_CHECK_WAKEUP(ptls); + } if (uvlock == ct) uv_stop(jl_global_event_loop()); } @@ -482,24 +485,31 @@ JL_DLLEXPORT jl_task_t *jl_task_get_next(jl_value_t *trypoptask, jl_value_t *q) // acquire sleep-check lock jl_atomic_store_relaxed(&ptls->sleep_check_state, sleeping); jl_fence(); // [^store_buffering_1] + JL_PROBE_RT_SLEEP_CHECK_SLEEP(ptls); if (!multiq_check_empty()) { // uses relaxed loads - if (jl_atomic_load_relaxed(&ptls->sleep_check_state) != not_sleeping) + if (jl_atomic_load_relaxed(&ptls->sleep_check_state) != not_sleeping) { jl_atomic_store_relaxed(&ptls->sleep_check_state, not_sleeping); // let other threads know they don't need to wake us + JL_PROBE_RT_SLEEP_CHECK_TASKQ_WAKE(ptls); + } continue; } task = get_next_task(trypoptask, q); // note: this should not yield if (ptls != ct->ptls) { // sigh, a yield was detected, so let's go ahead and handle it anyway by starting over ptls = ct->ptls; - if (jl_atomic_load_relaxed(&ptls->sleep_check_state) != not_sleeping) + if (jl_atomic_load_relaxed(&ptls->sleep_check_state) != not_sleeping) { jl_atomic_store_relaxed(&ptls->sleep_check_state, not_sleeping); // let other threads know they don't need to wake us + JL_PROBE_RT_SLEEP_CHECK_TASK_WAKE(ptls); + } if (task) return task; continue; } if (task) { - if (jl_atomic_load_relaxed(&ptls->sleep_check_state) != not_sleeping) + if (jl_atomic_load_relaxed(&ptls->sleep_check_state) != not_sleeping) { jl_atomic_store_relaxed(&ptls->sleep_check_state, not_sleeping); // let other threads know they don't need to wake us + JL_PROBE_RT_SLEEP_CHECK_TASK_WAKE(ptls); + } return task; } @@ -554,8 +564,10 @@ JL_DLLEXPORT jl_task_t *jl_task_get_next(jl_value_t *trypoptask, jl_value_t *q) if (!jl_atomic_load_relaxed(&_threadedregion) && active && ptls->tid == 0) { // thread 0 is the only thread permitted to run the event loop // so it needs to stay alive, just spin-looping if necessary - if (jl_atomic_load_relaxed(&ptls->sleep_check_state) != not_sleeping) + if (jl_atomic_load_relaxed(&ptls->sleep_check_state) != not_sleeping) { jl_atomic_store_relaxed(&ptls->sleep_check_state, not_sleeping); // let other threads know they don't need to wake us + JL_PROBE_RT_SLEEP_CHECK_UV_WAKE(ptls); + } start_cycles = 0; continue; } diff --git a/src/uprobes.d b/src/uprobes.d index 4cb5e73655c48..07f98d74025c9 100644 --- a/src/uprobes.d +++ b/src/uprobes.d @@ -15,6 +15,12 @@ provider julia { probe rt__new__task(jl_task_t *parent, jl_task_t *child); probe rt__start__process__events(jl_task_t *task); probe rt__finish__process__events(jl_task_t *task); + probe rt__sleep__check__wake(jl_ptls_t other, int8_t old_state); + probe rt__sleep__check__wakeup(jl_ptls_t ptls); + probe rt__sleep__check__sleep(jl_ptls_t ptls); + probe rt__sleep__check__taskq__wake(jl_ptls_t ptls); + probe rt__sleep__check__task__wake(jl_ptls_t ptls); + probe rt__sleep__check__uv__wake(jl_ptls_t ptls); }; #pragma D attributes Evolving/Evolving/Common provider julia provider From 3414f1c21ef665b5b5435e0be2fe0abf724d0f96 Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Sat, 22 Jan 2022 16:47:40 -0600 Subject: [PATCH 05/11] devdocs/probes: Split out Thread sleep/wake --- doc/src/devdocs/probes.md | 15 +++++++++------ 1 file changed, 9 insertions(+), 6 deletions(-) diff --git a/doc/src/devdocs/probes.md b/doc/src/devdocs/probes.md index c89832a76b63e..ffc3b273cd815 100644 --- a/doc/src/devdocs/probes.md +++ b/doc/src/devdocs/probes.md @@ -101,12 +101,15 @@ the probe handler. 3. `julia:rt__new__task(parent, child)`: Task `parent` created task `child` on current thread. 4. `julia:rt__start__process__events(task)`: Task `task` started processing libuv events. 5. `julia:rt__finish__process__events(task)`: Task `task` finished processing libuv events. -6. `julia:rt__sleep__check__wake(ptls, old_state)`: Thread (PTLS `ptls`) waking up, previously in state `old_state`. -7. `julia:rt__sleep__check__wakeup(ptls)`: Thread (PTLS `ptls`) woke itself up. -8. `julia:rt__sleep__check__sleep(ptls)`: Thread (PTLS `ptls`) is attempting to sleep. -9. `julia:rt__sleep__check__taskq__wake(ptls)`: Thread (PTLS `ptls`) fails to sleep due to tasks in PARTR multiq. -10. `julia:rt__sleep__check__task__wake(ptls)`: Thread (PTLS `ptls`) fails to sleep due to tasks in Base workqueue. -11. `julia:rt__sleep__check__uv__wake(ptls)`: Thread (PTLS `ptls`) fails to sleep due to libuv wakeup. + +### 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. #### GC stop-the-world latency From 27b9160d9c513f22aa5271f4079bde23da79b0e7 Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Sat, 22 Jan 2022 17:43:51 -0600 Subject: [PATCH 06/11] devdocs/probes: Add usage examples for task RT/thread sleep --- doc/src/devdocs/probes.md | 128 +++++++++++++++++++++++++++++++++++++- 1 file changed, 127 insertions(+), 1 deletion(-) diff --git a/doc/src/devdocs/probes.md b/doc/src/devdocs/probes.md index ffc3b273cd815..02ae320a38145 100644 --- a/doc/src/devdocs/probes.md +++ b/doc/src/devdocs/probes.md @@ -111,7 +111,9 @@ the probe handler. 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. -#### GC stop-the-world latency +## 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. @@ -160,6 +162,130 @@ Tracing Julia GC Stop-The-World Latency... Hit Ctrl-C to end. We can see the latency distribution of the stop-the-world phase in the executed Julia process. +### Task spawn monitor + +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: + +``` +> 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 +``` + +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: + +```julia +@async for i in 1:10 + @async 1+1 +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: + +`sudo bpftrace -p 997825 -e 'usdt:usr/lib/libjulia-internal.so:julia:rt__new__task { printf("Task: %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 +``` + +We can see our root task, and the newly-spawned task as the parent of the ten +even newer tasks. + +### Thundering herd detection + +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: + +``` +> 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 +``` + +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: + +``` +Thread wake up! 3f926100 +Thread wake up! 3ebd5140 +Thread wake up! 3f876130 +Thread wake up! 3e2711a0 +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. + ## Notes on using `bpftrace` An example probe in the bpftrace format looks like: From 5b9974f265640265ae4f61fbafdcb0314c068ca8 Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Sun, 23 Jan 2022 08:27:47 -0600 Subject: [PATCH 07/11] devdocs/probes: Add link to BPFnative task RT demo --- doc/src/devdocs/probes.md | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/doc/src/devdocs/probes.md b/doc/src/devdocs/probes.md index 02ae320a38145..6f51ddfa27112 100644 --- a/doc/src/devdocs/probes.md +++ b/doc/src/devdocs/probes.md @@ -286,6 +286,12 @@ 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. +### Task Monitor with BPFnative.jl + +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](https://github.com/jpsamaroo/BPFnative.jl/blob/master/examples/task-runtime.jl). + ## Notes on using `bpftrace` An example probe in the bpftrace format looks like: From 3ca21abfd745e993804347df86109f8a60a6d196 Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Tue, 25 Jan 2022 09:37:24 -0600 Subject: [PATCH 08/11] Add USDT for task finish --- contrib/bpftrace/rt_all.bt | 5 +++++ doc/src/devdocs/probes.md | 5 +++-- src/julia_internal.h | 2 ++ src/task.c | 1 + src/uprobes.d | 1 + 5 files changed, 12 insertions(+), 2 deletions(-) diff --git a/contrib/bpftrace/rt_all.bt b/contrib/bpftrace/rt_all.bt index bc362010a0a2f..ca32999c28280 100755 --- a/contrib/bpftrace/rt_all.bt +++ b/contrib/bpftrace/rt_all.bt @@ -20,6 +20,11 @@ usdt:usr/lib/libjulia-internal.so:julia:rt__new__task printf("Task created: %x (Parent %x)\n", arg1, arg0); } +usdt:usr/lib/libjulia-internal.so:julia:rt__finish__task +{ + printf("Task finished: %x\n", arg0); +} + usdt:usr/lib/libjulia-internal.so:julia:rt__start__process__events { printf("Task processing libuv events: %x\n", arg0); diff --git a/doc/src/devdocs/probes.md b/doc/src/devdocs/probes.md index 6f51ddfa27112..8452773db0286 100644 --- a/doc/src/devdocs/probes.md +++ b/doc/src/devdocs/probes.md @@ -99,8 +99,9 @@ the probe handler. 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 `parent` created task `child` on current thread. -4. `julia:rt__start__process__events(task)`: Task `task` started processing libuv events. -5. `julia:rt__finish__process__events(task)`: Task `task` finished processing libuv events. +4. `julia:rt__finish__task(task)`: Task `task` finished and will no longer execute. +5. `julia:rt__start__process__events(task)`: Task `task` started processing libuv events. +6. `julia:rt__finish__process__events(task)`: Task `task` finished processing libuv events. ### Thread sleep/wake probes diff --git a/src/julia_internal.h b/src/julia_internal.h index d0d47c17eae30..0b479b7303fd1 100644 --- a/src/julia_internal.h +++ b/src/julia_internal.h @@ -1543,6 +1543,7 @@ uint16_t __gnu_f2h_ieee(float param) JL_NOTSAFEPOINT; #define JL_PROBE_RT_RUN_TASK(task) do ; while (0) #define JL_PROBE_RT_PAUSE_TASK(task) do ; while (0) #define JL_PROBE_RT_NEW_TASK(parent, child) do ; while (0) +#define JL_PROBE_RT_FINISH_TASK(task) do ; while (0) #define JL_PROBE_RT_START_PROCESS_EVENTS(task) do ; while (0) #define JL_PROBE_RT_FINISH_PROCESS_EVENTS(task) do ; while (0) #define JL_PROBE_RT_SLEEP_CHECK_WAKE(other, old_state) do ; while (0) @@ -1561,6 +1562,7 @@ uint16_t __gnu_f2h_ieee(float param) JL_NOTSAFEPOINT; #define JL_PROBE_GC_END_ENABLED() (0) #define JL_PROBE_GC_FINALIZER_ENABLED() (0) #define JL_PROBE_RT_RUN_TASK_ENABLED() (0) +#define JL_PROBE_RT_FINISH_TASK_ENABLED() (0) #define JL_PROBE_RT_PAUSE_TASK_ENABLED() (0) #define JL_PROBE_RT_NEW_TASK_ENABLED() (0) #define JL_PROBE_RT_START_PROCESS_EVENTS_ENABLED() (0) diff --git a/src/task.c b/src/task.c index ff6c484dedb60..0900f6b10a680 100644 --- a/src/task.c +++ b/src/task.c @@ -229,6 +229,7 @@ static _Atomic(jl_function_t*) task_done_hook_func JL_GLOBALLY_ROOTED = NULL; void JL_NORETURN jl_finish_task(jl_task_t *t) { jl_task_t *ct = jl_current_task; + JL_PROBE_RT_FINISH_TASK(ct); JL_SIGATOMIC_BEGIN(); if (jl_atomic_load_relaxed(&t->_isexception)) jl_atomic_store_release(&t->_state, JL_TASK_STATE_FAILED); diff --git a/src/uprobes.d b/src/uprobes.d index 07f98d74025c9..ab698da04cee7 100644 --- a/src/uprobes.d +++ b/src/uprobes.d @@ -13,6 +13,7 @@ provider julia { probe rt__run__task(jl_task_t *task); probe rt__pause__task(jl_task_t *task); probe rt__new__task(jl_task_t *parent, jl_task_t *child); + probe rt__finish__task(jl_task_t *task); probe rt__start__process__events(jl_task_t *task); probe rt__finish__process__events(jl_task_t *task); probe rt__sleep__check__wake(jl_ptls_t other, int8_t old_state); From 1818cdc96e0bb159d673573c866a8634fd2e93af Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Wed, 2 Feb 2022 15:00:00 -0600 Subject: [PATCH 09/11] Add separate USDT for task start --- contrib/bpftrace/rt_all.bt | 5 +++++ doc/src/devdocs/probes.md | 7 ++++--- src/julia_internal.h | 4 +++- src/task.c | 2 +- src/uprobes.d | 1 + 5 files changed, 14 insertions(+), 5 deletions(-) diff --git a/contrib/bpftrace/rt_all.bt b/contrib/bpftrace/rt_all.bt index ca32999c28280..5fb6a297799c0 100755 --- a/contrib/bpftrace/rt_all.bt +++ b/contrib/bpftrace/rt_all.bt @@ -20,6 +20,11 @@ usdt:usr/lib/libjulia-internal.so:julia:rt__new__task printf("Task created: %x (Parent %x)\n", arg1, arg0); } +usdt:usr/lib/libjulia-internal.so:julia:rt__start__task +{ + printf("Task started: %x\n", arg0); +} + usdt:usr/lib/libjulia-internal.so:julia:rt__finish__task { printf("Task finished: %x\n", arg0); diff --git a/doc/src/devdocs/probes.md b/doc/src/devdocs/probes.md index 8452773db0286..fd75ed75d2782 100644 --- a/doc/src/devdocs/probes.md +++ b/doc/src/devdocs/probes.md @@ -99,9 +99,10 @@ the probe handler. 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 `parent` created task `child` on current thread. -4. `julia:rt__finish__task(task)`: Task `task` finished and will no longer execute. -5. `julia:rt__start__process__events(task)`: Task `task` started processing libuv events. -6. `julia:rt__finish__process__events(task)`: Task `task` finished processing libuv events. +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. ### Thread sleep/wake probes diff --git a/src/julia_internal.h b/src/julia_internal.h index 0b479b7303fd1..dc3ef3ea66bed 100644 --- a/src/julia_internal.h +++ b/src/julia_internal.h @@ -1543,6 +1543,7 @@ uint16_t __gnu_f2h_ieee(float param) JL_NOTSAFEPOINT; #define JL_PROBE_RT_RUN_TASK(task) do ; while (0) #define JL_PROBE_RT_PAUSE_TASK(task) do ; while (0) #define JL_PROBE_RT_NEW_TASK(parent, child) do ; while (0) +#define JL_PROBE_RT_START_TASK(task) do ; while (0) #define JL_PROBE_RT_FINISH_TASK(task) do ; while (0) #define JL_PROBE_RT_START_PROCESS_EVENTS(task) do ; while (0) #define JL_PROBE_RT_FINISH_PROCESS_EVENTS(task) do ; while (0) @@ -1562,9 +1563,10 @@ uint16_t __gnu_f2h_ieee(float param) JL_NOTSAFEPOINT; #define JL_PROBE_GC_END_ENABLED() (0) #define JL_PROBE_GC_FINALIZER_ENABLED() (0) #define JL_PROBE_RT_RUN_TASK_ENABLED() (0) -#define JL_PROBE_RT_FINISH_TASK_ENABLED() (0) #define JL_PROBE_RT_PAUSE_TASK_ENABLED() (0) #define JL_PROBE_RT_NEW_TASK_ENABLED() (0) +#define JL_PROBE_RT_START_TASK_ENABLED() (0) +#define JL_PROBE_RT_FINISH_TASK_ENABLED() (0) #define JL_PROBE_RT_START_PROCESS_EVENTS_ENABLED() (0) #define JL_PROBE_RT_FINISH_PROCESS_EVENTS_ENABLED() (0) #define JL_PROBE_RT_SLEEP_CHECK_WAKE_ENABLED() (0) diff --git a/src/task.c b/src/task.c index 0900f6b10a680..a79b463847d7e 100644 --- a/src/task.c +++ b/src/task.c @@ -914,7 +914,7 @@ CFI_NORETURN #endif ct->started = 1; - JL_PROBE_RT_RUN_TASK(ct); + JL_PROBE_RT_START_TASK(ct); if (jl_atomic_load_relaxed(&ct->_isexception)) { record_backtrace(ptls, 0); jl_push_excstack(&ct->excstack, ct->result, diff --git a/src/uprobes.d b/src/uprobes.d index ab698da04cee7..dd9bdf524f2d7 100644 --- a/src/uprobes.d +++ b/src/uprobes.d @@ -13,6 +13,7 @@ provider julia { probe rt__run__task(jl_task_t *task); probe rt__pause__task(jl_task_t *task); probe rt__new__task(jl_task_t *parent, jl_task_t *child); + probe rt__start__task(jl_task_t *task); probe rt__finish__task(jl_task_t *task); probe rt__start__process__events(jl_task_t *task); probe rt__finish__process__events(jl_task_t *task); From ff2f91319b1d4d4454f1e0a4bddf2a5bd92d96d2 Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Mon, 7 Feb 2022 17:50:35 -0600 Subject: [PATCH 10/11] Execute RT_NEW_TASK early --- src/task.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/task.c b/src/task.c index a79b463847d7e..1dd4e76b8ba1c 100644 --- a/src/task.c +++ b/src/task.c @@ -758,6 +758,7 @@ JL_DLLEXPORT jl_task_t *jl_new_task(jl_function_t *start, jl_value_t *completion { jl_task_t *ct = jl_current_task; jl_task_t *t = (jl_task_t*)jl_gc_alloc(ct->ptls, sizeof(jl_task_t), jl_task_type); + JL_PROBE_RT_NEW_TASK(ct, t); t->copy_stack = 0; if (ssize == 0) { // stack size unspecified; use default @@ -818,7 +819,6 @@ JL_DLLEXPORT jl_task_t *jl_new_task(jl_function_t *start, jl_value_t *completion #ifdef _COMPILER_TSAN_ENABLED_ t->ctx.tsan_state = __tsan_create_fiber(0); #endif - JL_PROBE_RT_NEW_TASK(ct, t); return t; } From 77d54ae2a8ff15cc43366dc26542d3d5ff612936 Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Tue, 8 Feb 2022 15:13:40 -0600 Subject: [PATCH 11/11] Add USDTs for multiq insert/deletemin --- contrib/bpftrace/rt_all.bt | 10 ++++++++++ doc/src/devdocs/probes.md | 5 +++++ src/julia_internal.h | 4 ++++ src/partr.c | 12 +++++++++--- src/uprobes.d | 2 ++ 5 files changed, 30 insertions(+), 3 deletions(-) diff --git a/contrib/bpftrace/rt_all.bt b/contrib/bpftrace/rt_all.bt index 5fb6a297799c0..d4de28e354a50 100755 --- a/contrib/bpftrace/rt_all.bt +++ b/contrib/bpftrace/rt_all.bt @@ -40,6 +40,16 @@ usdt:usr/lib/libjulia-internal.so:julia:rt__finish__process__events printf("Task processed libuv events: %x\n", arg0); } +usdt:usr/lib/libjulia-internal.so:julia:rt__taskq__insert +{ + printf("Thread %x inserting task to multiq: %x\n", arg0, arg1); +} + +usdt:usr/lib/libjulia-internal.so:julia:rt__taskq__get +{ + printf("Thread %x popped task from multiq: %x\n", arg0, arg1); +} + usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__wake { printf("Thread waking: %x (was sleeping?: %d)\n", arg0, arg1); diff --git a/doc/src/devdocs/probes.md b/doc/src/devdocs/probes.md index fd75ed75d2782..c5cd21b7c91db 100644 --- a/doc/src/devdocs/probes.md +++ b/doc/src/devdocs/probes.md @@ -104,6 +104,11 @@ the probe handler. 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. +### Task queue probes + +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`. diff --git a/src/julia_internal.h b/src/julia_internal.h index dc3ef3ea66bed..8c66bf54fb674 100644 --- a/src/julia_internal.h +++ b/src/julia_internal.h @@ -1547,6 +1547,8 @@ uint16_t __gnu_f2h_ieee(float param) JL_NOTSAFEPOINT; #define JL_PROBE_RT_FINISH_TASK(task) do ; while (0) #define JL_PROBE_RT_START_PROCESS_EVENTS(task) do ; while (0) #define JL_PROBE_RT_FINISH_PROCESS_EVENTS(task) do ; while (0) +#define JL_PROBE_RT_TASKQ_INSERT(ptls, task) do ; while (0) +#define JL_PROBE_RT_TASKQ_GET(ptls, task) do ; while (0) #define JL_PROBE_RT_SLEEP_CHECK_WAKE(other, old_state) do ; while (0) #define JL_PROBE_RT_SLEEP_CHECK_WAKEUP(ptls) do ; while (0) #define JL_PROBE_RT_SLEEP_CHECK_SLEEP(ptls) do ; while (0) @@ -1569,6 +1571,8 @@ uint16_t __gnu_f2h_ieee(float param) JL_NOTSAFEPOINT; #define JL_PROBE_RT_FINISH_TASK_ENABLED() (0) #define JL_PROBE_RT_START_PROCESS_EVENTS_ENABLED() (0) #define JL_PROBE_RT_FINISH_PROCESS_EVENTS_ENABLED() (0) +#define JL_PROBE_RT_TASKQ_INSERT_ENABLED() (0) +#define JL_PROBE_RT_TASKQ_GET_ENABLED() (0) #define JL_PROBE_RT_SLEEP_CHECK_WAKE_ENABLED() (0) #define JL_PROBE_RT_SLEEP_CHECK_WAKEUP_ENABLED() (0) #define JL_PROBE_RT_SLEEP_CHECK_SLEEP_ENABLED() (0) diff --git a/src/partr.c b/src/partr.c index 49ce36d28c37a..c8cc3245ebb4c 100644 --- a/src/partr.c +++ b/src/partr.c @@ -302,9 +302,12 @@ void jl_threadfun(void *arg) // enqueue the specified task for execution JL_DLLEXPORT int jl_enqueue_task(jl_task_t *task) { + char failed; if (multiq_insert(task, task->prio) == -1) - return 1; - return 0; + failed = 1; + failed = 0; + JL_PROBE_RT_TASKQ_INSERT(jl_current_task->ptls, task); + return failed; } @@ -447,7 +450,10 @@ static jl_task_t *get_next_task(jl_value_t *trypoptask, jl_value_t *q) jl_set_task_tid(task, self); return task; } - return multiq_deletemin(); + task = multiq_deletemin(); + if (task) + JL_PROBE_RT_TASKQ_GET(jl_current_task->ptls, task); + return task; } static int may_sleep(jl_ptls_t ptls) JL_NOTSAFEPOINT diff --git a/src/uprobes.d b/src/uprobes.d index dd9bdf524f2d7..29dc39598c1da 100644 --- a/src/uprobes.d +++ b/src/uprobes.d @@ -17,6 +17,8 @@ provider julia { probe rt__finish__task(jl_task_t *task); probe rt__start__process__events(jl_task_t *task); probe rt__finish__process__events(jl_task_t *task); + probe rt__taskq__insert(jl_ptls_t ptls, jl_task_t *task); + probe rt__taskq__get(jl_ptls_t ptls, jl_task_t *task); probe rt__sleep__check__wake(jl_ptls_t other, int8_t old_state); probe rt__sleep__check__wakeup(jl_ptls_t ptls); probe rt__sleep__check__sleep(jl_ptls_t ptls);