Runtime event trace visualization

contrib/bpftrace/rt_perfetto.bt

@@ -0,0 +1,184 @@
+#!/usr/bin/env bpftrace
+
+BEGIN
+{
+    @gc_num = 1;
+    @ti_num = 1;
+    @cg_num = 1;
+    @co_num = 1;
+    @lo_num = 1;
+    printf("{\"traceEvents\":[\n");
+}
+
+END
+{
+    clear(@ti_num);
+    clear(@gc_num);
+    clear(@cg_num);
+    clear(@co_num);
+    clear(@lo_num);
+    printf("]}");
+}
+
+// GC events
+usdt:usr/lib/libjulia-internal.so:julia:gc__begin
+{
+    printf("{\"name\":\"GC\",\"cat\":\"gc\",\"id\":%-d,\"ph\":\"B\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @gc_num, pid, tid, elapsed/1000);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:gc__end
+{
+    printf("{\"name\":\"GC\",\"cat\":\"gc\",\"id\":%-d,\"ph\":\"E\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @gc_num, pid, tid, elapsed/1000);
+    @gc_num++;
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:gc__stop_the_world
+{
+    printf("{\"name\":\"StopTheWorld\",\"cat\":\"gc\",\"ph\":\"i\",\"s\":\"t\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", pid, tid, elapsed/1000);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:gc__mark__begin
+{
+    printf("{\"name\":\"Mark\",\"cat\":\"gc\",\"id\":%-d,\"ph\":\"B\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @gc_num, pid, tid, elapsed/1000);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:gc__mark__end
+{
+    //printf("{\"name\":\"Mark\",\"cat\":\"gc\",\"ph\":\"E\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu,\"args\":{\"scanned_bytes\":%ld,\"perm_scanned_bytes\":%ld}},\n", pid, tid, elapsed/1000, arg0, arg1);
+    printf("{\"name\":\"Mark\",\"cat\":\"gc\",\"id\":%-d,\"ph\":\"E\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @gc_num, pid, tid, elapsed/1000);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:gc__sweep__begin
+{
+    printf("{\"name\":\"Sweep\",\"cat\":\"gc\",\"id\":%-d,\"ph\":\"B\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu,\"args\":{\"full\":%d}},\n", @gc_num, pid, tid, elapsed/1000, arg0);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:gc__sweep__end
+{
+    printf("{\"name\":\"Sweep\",\"cat\":\"gc\",\"id\":%-d,\"ph\":\"E\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @gc_num, pid, tid, elapsed/1000);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:gc__finalizer
+{
+    printf("{\"name\":\"Finalizer\",\"cat\":\"gc\",\"ph\":\"i\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", pid, tid, elapsed/1000);
+}
+
+// Task events
+usdt:usr/lib/libjulia-internal.so:julia:rt__new__task
+{
+    printf("{\"name\":\"TaskNew\",\"cat\":\"task\",\"ph\":\"i\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu,\"args\":{\"task\":\"0x%x\",\"parent\":\"0x%x\"}},\n", pid, tid, elapsed/1000, arg1, arg0);
+    printf("{\"name\":\"TaskEnqueue\",\"cat\":\"task\",\"id\":\"0x%x\",\"ph\":\"s\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu,\"args\":{\"task\":\"0x%x\"}},\n", arg1, pid, tid, elapsed/1000, arg1);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:rt__start__task
+{
+    printf("{\"name\":\"TaskEnqueue\",\"cat\":\"task\",\"id\":\"0x%x\",\"ph\":\"f\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu,\"args\":{\"queue_duration\":2,\"task\":\"0x%x\"}},\n", arg0, pid, tid, elapsed/1000, arg0);
+    printf("{\"name\":\"TaskRun\",\"cat\":\"task\",\"id\":\"0x%x\",\"ph\":\"B\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu,\"args\":{\"task\":\"0x%x\"}},\n", arg0, pid, tid, elapsed/1000, arg0);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:rt__finish__task
+{
+    printf("{\"name\":\"TaskFinish\",\"cat\":\"task\",\"ph\":\"i\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu,\"args\":{\"task\":\"0x%x\"}},\n", pid, tid, elapsed/1000, arg0);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:rt__run__task
+{
+    printf("{\"name\":\"TaskRun\",\"cat\":\"task\",\"id\":\"0x%x\",\"ph\":\"B\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu,\"args\":{\"task\":\"0x%x\"}},\n", arg0, pid, tid, elapsed/1000, arg0);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:rt__pause__task
+{
+    printf("{\"name\":\"TaskRun\",\"cat\":\"task\",\"id\":\"0x%x\",\"ph\":\"E\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu,\"args\":{\"task\":\"0x%x\"}},\n", arg0, pid, tid, elapsed/1000, arg0);
+}
+
+// Type inference events
+usdt:usr/lib/libjulia-internal.so:julia:rt__start__typeinf
+{
+    printf("{\"name\":\"TypeInference\",\"cat\":\"compiler\",\"id\":%-d,\"ph\":\"B\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @ti_num, pid, tid, elapsed/1000);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:rt__finish__typeinf
+{
+    printf("{\"name\":\"TypeInference\",\"cat\":\"compiler\",\"id\":%-d,\"ph\":\"E\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @ti_num, pid, tid, elapsed/1000);
+    @ti_num++;
+}
+
+// Compilation events -- codegen, compile, optimize
+usdt:usr/lib/libjulia-codegen.so:julia:rt__start__codegen
+{
+    printf("{\"name\":\"CodeGen\",\"cat\":\"compiler\",\"id\":%-d,\"ph\":\"B\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @cg_num, pid, tid, elapsed/1000);
+}
+
+usdt:usr/lib/libjulia-codegen.so:julia:rt__finish__codegen
+{
+    printf("{\"name\":\"CodeGen\",\"cat\":\"compiler\",\"id\":%-d,\"ph\":\"E\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @cg_num, pid, tid, elapsed/1000);
+    @cg_num++;
+}
+
+usdt:usr/lib/libjulia-codegen.so:julia:rt__start__compile
+{
+    printf("{\"name\":\"Compile\",\"cat\":\"compiler\",\"id\":%-d,\"ph\":\"B\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @co_num, pid, tid, elapsed/1000);
+}
+
+usdt:usr/lib/libjulia-codegen.so:julia:rt__finish__compile
+{
+    printf("{\"name\":\"Compile\",\"cat\":\"compiler\",\"id\":%-d,\"ph\":\"E\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @co_num, pid, tid, elapsed/1000);
+    @cg_num++;
+}
+
+usdt:usr/lib/libjulia-codegen.so:julia:rt__start__llvmopt
+{
+    printf("{\"name\":\"LLVMOpt\",\"cat\":\"compiler\",\"id\":%-d,\"ph\":\"B\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @lo_num, pid, tid, elapsed/1000);
+}
+
+usdt:usr/lib/libjulia-codegen.so:julia:rt__finish__llvmopt
+{
+    printf("{\"name\":\"LLVMOpt\",\"cat\":\"compiler\",\"id\":%-d,\"ph\":\"E\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu},\n", @lo_num, pid, tid, elapsed/1000);
+    @lo_num++;
+}
+
+/*
+// IO loop events: MANY events
+usdt:usr/lib/libjulia-internal.so:julia:rt__start__process__events
+{
+    printf("{\"name\":\"ProcessEvents\",\"cat\":\"task\",\"ph\":\"B\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu,\"args\":{\"task\":\"0x%x\"}},\n", pid, tid, elapsed/1000, arg0);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:rt__finish__process__events
+{
+    printf("{\"name\":\"ProcessEvents\",\"cat\":\"task\",\"ph\":\"E\",\"pid\":%-d,\"tid\":%-d,\"ts\":%lu,\"args\":{\"task\":\"0x%x\"}},\n", pid, tid, elapsed/1000, arg0);
+}
+*/
+
+/*
+// Thread sleep logic: for debugging
+usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__wake
+{
+    printf("Thread waking: 0x%x (was sleeping?: %d)\n", arg0, arg1);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__wakeup
+{
+    printf("Thread wakeup: 0x%x\n", arg0);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__sleep
+{
+    printf("Thread trying to sleep: 0x%x\n", arg0);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__taskq__wake
+{
+    printf("Thread waking due to non-empty task queue: 0x%x\n", arg0);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__task__wake
+{
+    printf("Thread waking due to popped task: 0x%x\n", arg0);
+}
+
+usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__uv__wake
+{
+    printf("Thread waking due to libuv: 0x%x\n", arg0);
+}
+*/

src/Makefile

@@ -87,6 +87,7 @@ ifeq ($(WITH_DTRACE),1)
 DTRACE_HEADERS := uprobes.h.gen
 ifneq ($(OS),Darwin)
 SRCS += uprobes
+CODEGEN_SRCS += uprobes
 endif
 else
 DTRACE_HEADERS :=

src/codegen.cpp

@@ -8145,6 +8145,7 @@ jl_llvm_functions_t jl_emit_code(
         jl_codegen_params_t &params)
 {
     JL_TIMING(CODEGEN);
+    JL_PROBE_RT_START_CODEGEN();
     // caller must hold codegen_lock
     jl_llvm_functions_t decls = {};
     assert((params.params == &jl_default_cgparams /* fast path */ || !params.cache ||
@@ -8176,6 +8177,7 @@ jl_llvm_functions_t jl_emit_code(
         jl_printf((JL_STREAM*)STDERR_FILENO, "\n");
         jlbacktrace(); // written to STDERR_FILENO
     }
+    JL_PROBE_RT_FINISH_CODEGEN();
 
     return decls;
 }

src/gf.c

@@ -3384,6 +3384,7 @@ static uint8_t inference_is_measuring_compile_time = 0;
 
 JL_DLLEXPORT void jl_typeinf_timing_begin(void)
 {
+    JL_PROBE_RT_START_TYPEINF();
     if (jl_atomic_load_relaxed(&jl_measure_compile_time_enabled)) {
         JL_LOCK_NOGC(&inference_timing_mutex);
         if (inference_is_measuring_compile_time++ == 0) {
@@ -3410,6 +3411,7 @@ JL_DLLEXPORT void jl_typeinf_lock_begin(void)
 JL_DLLEXPORT void jl_typeinf_lock_end(void)
 {
     JL_UNLOCK(&typeinf_lock);
+    JL_PROBE_RT_FINISH_TYPEINF();
 }
 
 #ifdef __cplusplus

src/jitlayers.cpp

@@ -174,6 +174,7 @@ static jl_callptr_t _jl_compile_codeinst(
         size_t world,
         orc::ThreadSafeContext context)
 {
+    JL_PROBE_RT_START_COMPILE();
     // caller must hold codegen_lock
     // and have disabled finalizers
     uint64_t start_time = 0;
@@ -285,6 +286,7 @@ static jl_callptr_t _jl_compile_codeinst(
             jl_printf(stream, "\"\n");
         }
     }
+    JL_PROBE_RT_FINISH_COMPILE();
     return fptr;
 }
 
@@ -1079,6 +1081,7 @@ namespace {
 
         OptimizerResultT operator()(orc::ThreadSafeModule TSM, orc::MaterializationResponsibility &R) {
             TSM.withModuleDo([&](Module &M) {
+                JL_PROBE_RT_START_LLVMOPT();
                 uint64_t start_time = 0;
                 {
                     auto stream = *jl_ExecutionEngine->get_dump_llvm_opt_stream();
@@ -1128,6 +1131,7 @@ namespace {
                         }
                     }
                 }
+                JL_PROBE_RT_FINISH_LLVMOPT();
             });
             switch (optlevel) {
                 case 0:

src/jl_uv.c

@@ -211,10 +211,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);
+            JL_PROBE_RT_START_PROCESS_EVENTS(jl_object_id(ct));
             loop->stop_flag = 0;
             int r = uv_run(loop, UV_RUN_NOWAIT);
-            JL_PROBE_RT_FINISH_PROCESS_EVENTS(ct);
+            JL_PROBE_RT_FINISH_PROCESS_EVENTS(jl_object_id(ct));
             JL_UV_UNLOCK();
             return r;
         }

src/julia_internal.h

@@ -1656,14 +1656,20 @@ JL_DLLEXPORT uint16_t julia__truncdfhf2(double 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)
 #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_RT_START_TYPEINF() do ; while (0)
+#define JL_PROBE_RT_FINISH_TYPEINF() do ; while (0)
+#define JL_PROBE_RT_START_CODEGEN() do ; while (0)
+#define JL_PROBE_RT_FINISH_CODEGEN() do ; while (0)
+#define JL_PROBE_RT_START_COMPILE() do ; while (0)
+#define JL_PROBE_RT_FINISH_COMPILE() do ; while (0)
+#define JL_PROBE_RT_START_LLVMOPT() do ; while (0)
+#define JL_PROBE_RT_FINISH_LLVMOPT() do ; while (0)
 
 #define JL_PROBE_GC_BEGIN_ENABLED() (0)
 #define JL_PROBE_GC_STOP_THE_WORLD_ENABLED() (0)
@@ -1680,14 +1686,20 @@ JL_DLLEXPORT uint16_t julia__truncdfhf2(double 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)
 #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)
+#define JL_PROBE_RT_START_TYPEINF_ENABLED() (0)
+#define JL_PROBE_RT_FINISH_TYPEINF_ENABLED() (0)
+#define JL_PROBE_RT_START_CODEGEN_ENABLED() (0)
+#define JL_PROBE_RT_FINISH_CODEGEN_ENABLED() (0)
+#define JL_PROBE_RT_START_COMPILE_ENABLED() (0)
+#define JL_PROBE_RT_FINISH_COMPILE_ENABLED() (0)
+#define JL_PROBE_RT_START_LLVMOPT_ENABLED() (0)
+#define JL_PROBE_RT_FINISH_LLVMOPT_ENABLED() (0)
 #endif
 
 #endif

src/task.c

@@ -293,7 +293,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_PROBE_RT_FINISH_TASK(jl_object_id(t));
     JL_SIGATOMIC_BEGIN();
     if (jl_atomic_load_relaxed(&t->_isexception))
         jl_atomic_store_release(&t->_state, JL_TASK_STATE_FAILED);
@@ -635,7 +635,7 @@ 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);
+    JL_PROBE_RT_PAUSE_TASK(jl_object_id(ct));
 
     // Store old values on the stack and reset
     sig_atomic_t defer_signal = ptls->defer_signal;
@@ -685,7 +685,7 @@ JL_DLLEXPORT void jl_switch(void)
     if (other_defer_signal && !defer_signal)
         jl_sigint_safepoint(ptls);
 
-    JL_PROBE_RT_RUN_TASK(ct);
+    JL_PROBE_RT_RUN_TASK(jl_object_id(ct));
 }
 
 JL_DLLEXPORT void jl_switchto(jl_task_t **pt)
@@ -889,7 +889,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);
+    JL_PROBE_RT_NEW_TASK(jl_object_id(ct), jl_object_id(t));
     t->copy_stack = 0;
     if (ssize == 0) {
         // stack size unspecified; use default
@@ -1068,7 +1068,7 @@ CFI_NORETURN
 #endif
 
     ct->started = 1;
-    JL_PROBE_RT_START_TASK(ct);
+    JL_PROBE_RT_START_TASK(jl_object_id(ct));
     if (jl_atomic_load_relaxed(&ct->_isexception)) {
         record_backtrace(ptls, 0);
         jl_push_excstack(&ct->excstack, ct->result,

src/uprobes.d

@@ -10,21 +10,28 @@ provider julia {
     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);
-    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);
-    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__run__task(uint task);
+    probe rt__pause__task(uint task);
+    probe rt__new__task(uint parent, uint child);
+    probe rt__start__task(uint task);
+    probe rt__finish__task(uint task);
+    probe rt__start__process__events(uint task);
+    probe rt__finish__process__events(uint 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);
+
+    probe rt__start__typeinf();
+    probe rt__finish__typeinf();
+    probe rt__start__codegen();
+    probe rt__finish__codegen();
+    probe rt__start__compile();
+    probe rt__finish__compile();
+    probe rt__start__llvmopt();
+    probe rt__finish__llvmopt();
 };
 
 #pragma D attributes Evolving/Evolving/Common provider julia provider