diff --git a/contrib/bpftrace/rt_perfetto.bt b/contrib/bpftrace/rt_perfetto.bt new file mode 100755 index 0000000000000..037111c12e226 --- /dev/null +++ b/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); +} +*/ diff --git a/src/Makefile b/src/Makefile index 8b996f28aeee0..8a835a13e17c4 100644 --- a/src/Makefile +++ b/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 := diff --git a/src/codegen.cpp b/src/codegen.cpp index 9c09314c9aee1..e11d74e0e5118 100644 --- a/src/codegen.cpp +++ b/src/codegen.cpp @@ -8145,6 +8145,7 @@ jl_llvm_functions_t jl_emit_code( jl_codegen_params_t ¶ms) { 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; } diff --git a/src/gf.c b/src/gf.c index abfa0713b9508..6804b97e1d0e0 100644 --- a/src/gf.c +++ b/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 diff --git a/src/jitlayers.cpp b/src/jitlayers.cpp index a0dd11e7f009e..f703b477a0304 100644 --- a/src/jitlayers.cpp +++ b/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: diff --git a/src/jl_uv.c b/src/jl_uv.c index a2f7fc43a5fca..a0538f7cfac05 100644 --- a/src/jl_uv.c +++ b/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; } diff --git a/src/julia_internal.h b/src/julia_internal.h index 5423f07846456..089396037b0e5 100644 --- a/src/julia_internal.h +++ b/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 diff --git a/src/task.c b/src/task.c index a1adb704695a7..57ad0dc8a53bc 100644 --- a/src/task.c +++ b/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, diff --git a/src/uprobes.d b/src/uprobes.d index 29dc39598c1da..31b4f2fef6181 100644 --- a/src/uprobes.d +++ b/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