add option to dump backtrace of stop-the-world straggler (JuliaLang#57045) (#208)

This is still a work in progress, but it should help determine what a
straggler thread was doing during the stop-the-world phase and why it
failed to reach a safepoint in a timely manner.

We've encountered long TTSP issues in production, and this tool should
provide a valuable means to accurately diagnose them.

Author: d-netto

base/options.jl

@@ -61,6 +61,7 @@ struct JLOptions
     trace_compile_timing::Int8
     safe_crash_log_file::Ptr{UInt8}
     task_metrics::Int8
+    timeout_for_safepoint_straggler_s::Int16
 end
 
 # This runs early in the sysimage != is not defined yet

src/gc.c

@@ -245,8 +245,22 @@ void jl_gc_wait_for_the_world(jl_ptls_t* gc_all_tls_states, int gc_n_threads)
             // We're currently also using atomic store release in mutator threads
             // (in jl_gc_state_set), but we may want to use signals to flush the
             // memory operations on those threads lazily instead.
-            while (!jl_atomic_load_relaxed(&ptls2->gc_state) || !jl_atomic_load_acquire(&ptls2->gc_state))
+            const int64_t timeout = jl_options.timeout_for_safepoint_straggler_s * 1000000000; // convert to nanoseconds
+            uint64_t t0 = jl_hrtime();
+            while (!jl_atomic_load_relaxed(&ptls2->gc_state) || !jl_atomic_load_acquire(&ptls2->gc_state)) {
                 jl_cpu_pause(); // yield?
+                if ((jl_hrtime() - t0) > timeout) {
+                    jl_safe_printf("===== Thread %d failed to reach safepoint after %d seconds, printing backtrace below =====\n", ptls2->tid + 1, jl_options.timeout_for_safepoint_straggler_s);
+                    // Try to record the backtrace of the straggler using `jl_try_record_thread_backtrace`
+                    jl_ptls_t ptls = jl_current_task->ptls;
+                    size_t bt_size = jl_try_record_thread_backtrace(ptls2, ptls->bt_data, JL_MAX_BT_SIZE);
+                    // Print the backtrace of the straggler
+                    for (size_t i = 0; i < bt_size; i += jl_bt_entry_size(ptls->bt_data + i)) {
+                        jl_print_bt_entry_codeloc(-1, ptls->bt_data + i);
+                    }
+                    t0 = jl_hrtime();
+                }
+            }
         }
     }
 }

src/jloptions.c

@@ -94,6 +94,7 @@ JL_DLLEXPORT void jl_init_options(void)
                         0, // trace_compile_timing
                         NULL, // safe_crash_log_file
                         0, // task_metrics
+                        -1, // timeout_for_safepoint_straggler_s
     };
     jl_options_initialized = 1;
 }
@@ -214,6 +215,8 @@ static const char opts_hidden[]  =
     " --output-asm <name>                           Generate an assembly file (.s)\n"
     " --output-incremental={yes|no*}                Generate an incremental output file (rather than\n"
     "                                               complete)\n"
+    " --timeout-for-safepoint-straggler <seconds>   If this value is set, then we will dump the backtrace for a thread\n"
+    "                                               that fails to reach a safepoint within the specified time\n"
     " --trace-compile={stderr|name}                 Print precompile statements for methods compiled\n"
     "                                               during execution or save to stderr or a path. Methods that\n"
     "                                               were recompiled are printed in yellow or with a trailing\n"
@@ -242,6 +245,7 @@ JL_DLLEXPORT void jl_parse_opts(int *argcp, char ***argvp)
            opt_warn_scope,
            opt_inline,
            opt_polly,
+           opt_timeout_for_safepoint_straggler,
            opt_trace_compile,
            opt_trace_compile_timing,
            opt_trace_dispatch,
@@ -321,6 +325,7 @@ JL_DLLEXPORT void jl_parse_opts(int *argcp, char ***argvp)
         { "warn-scope",      required_argument, 0, opt_warn_scope },
         { "inline",          required_argument, 0, opt_inline },
         { "polly",           required_argument, 0, opt_polly },
+        { "timeout-for-safepoint-straggler", required_argument, 0, opt_timeout_for_safepoint_straggler },
         { "trace-compile",   required_argument, 0, opt_trace_compile },
         { "trace-compile-timing",  no_argument, 0, opt_trace_compile_timing },
         { "trace-dispatch",  required_argument, 0, opt_trace_dispatch },
@@ -881,6 +886,13 @@ JL_DLLEXPORT void jl_parse_opts(int *argcp, char ***argvp)
             if (jl_options.safe_crash_log_file == NULL)
                 jl_error("julia: failed to allocate memory for --safe-crash-log-file");
             break;
+        case opt_timeout_for_safepoint_straggler:
+            errno = 0;
+            long timeout = strtol(optarg, &endptr, 10);
+            if (errno != 0 || optarg == endptr || timeout < 1 || timeout > INT16_MAX)
+                jl_errorf("julia: --timeout-for-safepoint-straggler=<seconds>; seconds must be an integer between 1 and %d", INT16_MAX);
+            jl_options.timeout_for_safepoint_straggler_s = (int16_t)timeout;
+            break;
         case opt_task_metrics:
             if (!strcmp(optarg, "no"))
                 jl_options.task_metrics = JL_OPTIONS_TASK_METRICS_OFF;

src/jloptions.h

@@ -65,6 +65,7 @@ typedef struct {
     int8_t trace_compile_timing;
     const char *safe_crash_log_file;
     int8_t task_metrics;
+    int16_t timeout_for_safepoint_straggler_s;
 } jl_options_t;
 
 #endif

src/julia_internal.h

@@ -213,6 +213,8 @@ typedef struct {
     size_t bt_size;
     int tid;
 } jl_record_backtrace_result_t;
+JL_DLLEXPORT JL_DLLEXPORT size_t jl_try_record_thread_backtrace(jl_ptls_t ptls2, struct _jl_bt_element_t *bt_data,
+                                                                size_t max_bt_size) JL_NOTSAFEPOINT;
 JL_DLLEXPORT jl_record_backtrace_result_t jl_record_backtrace(jl_task_t *t, struct _jl_bt_element_t *bt_data,
                                                               size_t max_bt_size, int all_tasks_profiler) JL_NOTSAFEPOINT;
 extern volatile struct _jl_bt_element_t *profile_bt_data_prof;

src/stackwalk.c

@@ -889,6 +889,26 @@ _os_ptr_munge(uintptr_t ptr)
 
 extern bt_context_t *jl_to_bt_context(void *sigctx);
 
+JL_DLLEXPORT size_t jl_try_record_thread_backtrace(jl_ptls_t ptls2, jl_bt_element_t *bt_data, size_t max_bt_size) JL_NOTSAFEPOINT
+{
+    int16_t tid = ptls2->tid;
+    jl_task_t *t = NULL;
+    bt_context_t *context = NULL;
+    bt_context_t c;
+    int lockret = jl_lock_stackwalk();
+    if (!jl_thread_suspend_and_get_state(tid, 0, &c)) {
+        jl_unlock_stackwalk(lockret);
+        return 0;
+    }
+    jl_unlock_stackwalk(lockret);
+    // thread is stopped, safe to read the task it was running before we stopped it
+    t = jl_atomic_load_relaxed(&ptls2->current_task);
+    context = &c;
+    size_t bt_size = rec_backtrace_ctx(bt_data, max_bt_size, context, ptls2->previous_task ? NULL : t->gcstack);
+    jl_thread_resume(tid);
+    return bt_size;
+}
+
 JL_DLLEXPORT jl_record_backtrace_result_t jl_record_backtrace(jl_task_t *t, jl_bt_element_t *bt_data, size_t max_bt_size, int all_tasks_profiler) JL_NOTSAFEPOINT
 {
     int16_t tid = INT16_MAX;

test/cmdlineargs.jl

@@ -1126,3 +1126,9 @@ end
 #heap-size-hint, we reserve 250 MB for non GC memory (llvm, etc.)
 @test readchomp(`$(Base.julia_cmd()) --startup-file=no --heap-size-hint=500M -e "println(@ccall jl_gc_get_max_memory()::UInt64)"`) == "$((500-250)*1024*1024)"
 end
+
+@testset "--timeout-for-safepoint-straggler" begin
+    exename = `$(Base.julia_cmd())`
+    timeout = 120
+    @test parse(Int,read(`$exename --timeout-for-safepoint-straggler=$timeout -E "Base.JLOptions().timeout_for_safepoint_straggler_s"`, String)) == timeout
+end

test/threads_exec.jl

@@ -1313,4 +1313,29 @@ end
     end
 end
 
+@testset "--timeout-for-safepoint-straggler command-line flag" begin
+    program = "
+        function main()
+            t = Threads.@spawn begin
+                ccall(:uv_sleep, Cvoid, (Cuint,), 5000)
+            end
+            # Force a GC
+            ccall(:uv_sleep, Cvoid, (Cuint,), 1000)
+            GC.gc()
+            wait(t)
+        end
+        main()
+    "
+    tmp_output_filename = tempname()
+    tmp_output_file = open(tmp_output_filename, "w")
+    if isnothing(tmp_output_file)
+        error("Failed to open file $tmp_output_filename")
+    end
+    run(pipeline(`$(Base.julia_cmd()) --threads=4 --timeout-for-safepoint-straggler=1 -e $program`, stderr=tmp_output_file))
+    # Check whether we printed the straggler's backtrace
+    @test !isempty(read(tmp_output_filename, String))
+    close(tmp_output_file)
+    rm(tmp_output_filename)
+end
+
 end # main testset