[Profile] further improvements for Windows-only (#59877)

- Instead of preventing profiling entirely (which might deadlock if
DllInit accesses Julia in any way), use a suggestion by @gbaraldi to
abort the profile if it takes too long (100ms), allowing the stopped
thread to release any locks and free up both threads to continue all.
Many, many other projects have encountered this same bug, including
dotNet (closed as won't fix) and Firefox (uses a single stepping
debugger to find the memory address of the offending locks), but those
seem difficult responses for us.
- Define correct ordering for taking profile-related locks
- Profile all threads instead of just main thread
- Refactor needsSymRefreshModuleList to use a modern API for doing so
reliably. The API does not appear to implement the documented behaviors,
but it seems to do what we need.
- Make stack unwinding on Windows thread-safe so that using multiple
threads that throw exceptions won't cause memory corruption anymore
- Use condition variables for correctly controlling profiler start/stop,
instead of volatile

Author: vtjnash

doc/src/devdocs/locks.md

@@ -51,12 +51,11 @@ exception frames, and taking/releasing locks.
       `jl_ast_context_list_t` pool.  Likewise, the `ResourcePool<?>::mutexes`
       just protect the associated resource pool.
 
-* `jl_in_stackwalk` (`uv_mutex_t`, Win32 only)
 * `ResourcePool<?>.mutex` (`std::mutex`)
 * `RLST_mutex` (`std::mutex`)
 * `llvm_printing_mutex` (`std::mutex`)
 * `jl_locked_stream.mutex` (`std::mutex`)
-* `debuginfo_asyncsafe` (`uv_rwlock_t`)
+* `debuginfo_asyncsafe` (`uv_rwlock_t`) (can still acquire `jl_in_stackwalk` (`uv_mutex_t`, Win32 only))
 * `profile_show_peek_cond_lock` (`jl_mutex_t`)
 * `trampoline_lock` (`uv_mutex_t`)
 * `bt_data_prof_lock` (`uv_mutex_t`)

src/debuginfo.cpp

@@ -1076,7 +1076,6 @@ bool jl_dylib_DI_for_fptr(size_t pointer, object::SectionRef *Section, int64_t *
     IMAGEHLP_MODULE64 ModuleInfo;
     ModuleInfo.SizeOfStruct = sizeof(IMAGEHLP_MODULE64);
     uv_mutex_lock(&jl_in_stackwalk);
-    jl_refresh_dbg_module_list();
     bool isvalid = SymGetModuleInfo64(GetCurrentProcess(), (DWORD64)pointer, &ModuleInfo);
     uv_mutex_unlock(&jl_in_stackwalk);
     if (!isvalid)
@@ -1178,7 +1177,6 @@ static int jl_getDylibFunctionInfo(jl_frame_t **frames, size_t pointer, int skip
     static IMAGEHLP_LINE64 frame_info_line;
     DWORD dwDisplacement = 0;
     uv_mutex_lock(&jl_in_stackwalk);
-    jl_refresh_dbg_module_list();
     DWORD64 dwAddress = pointer;
     frame_info_line.SizeOfStruct = sizeof(IMAGEHLP_LINE64);
     if (SymGetLineFromAddr64(GetCurrentProcess(), dwAddress, &dwDisplacement, &frame_info_line)) {

src/dlload.c

@@ -162,8 +162,6 @@ JL_DLLEXPORT void *jl_dlopen(const char *filename, unsigned flags) JL_NOTSAFEPOI
     }
     else {
         lib = LoadLibraryExW(wfilename, NULL, LOAD_WITH_ALTERED_SEARCH_PATH);
-        if (lib)
-            needsSymRefreshModuleList = 1;
     }
     return lib;
 }

src/init.c

@@ -37,8 +37,8 @@ extern "C" {
 #endif
 
 #ifdef _OS_WINDOWS_
-extern int needsSymRefreshModuleList;
-extern BOOL (WINAPI *hSymRefreshModuleList)(HANDLE);
+extern void jl_init_stackwalk(void);
+extern void jl_fin_stackwalk(void);
 #else
 #include <sys/resource.h>
 #include <unistd.h>
@@ -349,6 +349,9 @@ JL_DLLEXPORT void jl_atexit_hook(int exitcode) JL_NOTSAFEPOINT_ENTER
     jl_print_timings();
 #endif
     jl_teardown_codegen(); // prints stats
+#ifdef _OS_WINDOWS_
+    jl_fin_stackwalk();
+#endif
 }
 
 JL_DLLEXPORT void jl_postoutput_hook(void)
@@ -685,12 +688,7 @@ JL_DLLEXPORT void jl_init_(jl_image_buf_t sysimage)
     // initialize backtraces
     jl_init_profile_lock();
 #ifdef _OS_WINDOWS_
-    uv_mutex_init(&jl_in_stackwalk);
-    SymSetOptions(SYMOPT_UNDNAME | SYMOPT_DEFERRED_LOADS | SYMOPT_LOAD_LINES | SYMOPT_IGNORE_CVREC);
-    if (!SymInitialize(GetCurrentProcess(), "", 1)) {
-        jl_safe_printf("WARNING: failed to initialize stack walk info\n");
-    }
-    needsSymRefreshModuleList = 0;
+    jl_init_stackwalk();
 #else
     // nongnu libunwind initialization is only threadsafe on architecture where the
     // author could access TSAN, per https://github.com/libunwind/libunwind/pull/109
@@ -736,10 +734,6 @@ JL_DLLEXPORT void jl_init_(jl_image_buf_t sysimage)
     jl_kernel32_handle = jl_dlopen("kernel32.dll", JL_RTLD_NOLOAD);
     jl_crtdll_handle = jl_dlopen(jl_crtdll_name, JL_RTLD_NOLOAD);
     jl_winsock_handle = jl_dlopen("ws2_32.dll", JL_RTLD_NOLOAD);
-    HMODULE jl_dbghelp = (HMODULE) jl_dlopen("dbghelp.dll", JL_RTLD_NOLOAD);
-    needsSymRefreshModuleList = 0;
-    if (jl_dbghelp)
-        jl_dlsym(jl_dbghelp, "SymRefreshModuleList", (void **)&hSymRefreshModuleList, 1, 0);
 #else
     /* macOS dlopen(3): If path is NULL and the option RTLD_FIRST is used, the
        handle returned will only search the main executable. */

src/julia_internal.h

@@ -271,6 +271,9 @@ extern uv_mutex_t bt_data_prof_lock;
 #define PROFILE_STATE_THREAD_SLEEPING (2)
 #define PROFILE_STATE_WALL_TIME_PROFILING (3)
 void jl_profile_task(void);
+#if defined(_OS_WINDOWS_) && defined(_CPU_X86_64_)
+JL_DLLEXPORT void jl_set_profile_abort_ptr(_Atomic(int) *abort_ptr) JL_NOTSAFEPOINT;
+#endif
 
 // number of cycles since power-on
 static inline uint64_t cycleclock(void) JL_NOTSAFEPOINT
@@ -1529,9 +1532,6 @@ JL_DLLEXPORT void jl_gdblookup(void* ip) JL_NOTSAFEPOINT;
 JL_DLLEXPORT void jl_print_task_backtraces(int show_done) JL_NOTSAFEPOINT;
 void jl_fprint_native_codeloc(ios_t *s, uintptr_t ip) JL_NOTSAFEPOINT;
 void jl_fprint_bt_entry_codeloc(ios_t *s, jl_bt_element_t *bt_data) JL_NOTSAFEPOINT;
-#ifdef _OS_WINDOWS_
-JL_DLLEXPORT void jl_refresh_dbg_module_list(void);
-#endif
 void jl_thread_resume(int tid) JL_NOTSAFEPOINT;
 int jl_thread_suspend(int16_t tid, bt_context_t *ctx) JL_NOTSAFEPOINT;
 

src/signal-handling.c

@@ -178,7 +178,6 @@ void jl_unlock_profile_wr(void)
 }
 
 
-#ifndef _OS_WINDOWS_
 static uint64_t profile_cong_rng_seed = 0;
 static int *profile_round_robin_thread_order = NULL;
 static int profile_round_robin_thread_order_size = 0;
@@ -209,7 +208,6 @@ static int *profile_get_randperm(int size)
     jl_shuffle_int_array_inplace(profile_round_robin_thread_order, size, &profile_cong_rng_seed);
     return profile_round_robin_thread_order;
 }
-#endif
 
 
 JL_DLLEXPORT int jl_profile_is_buffer_full(void)

src/signals-win.c

@@ -409,9 +409,33 @@ JL_DLLEXPORT void jl_install_sigint_handler(void)
     SetConsoleCtrlHandler((PHANDLER_ROUTINE)sigint_handler,1);
 }
 
-static volatile HANDLE hBtThread = 0;
+static TIMECAPS timecaps;
+static HANDLE hBtThread = 0;
+static uv_cond_t bt_data_prof_cond = CONDITION_VARIABLE_INIT;
+
+#ifdef _CPU_X86_64_
+// Callback data structure for profile timeout
+typedef struct {
+    _Atomic(int) *abort_ptr;
+    int tid;
+} profile_timeout_data_t;
+
+static void CALLBACK profile_timeout_cb(PVOID lpParam, BOOLEAN TimerOrWaitFired)
+{
+    profile_timeout_data_t *data = (profile_timeout_data_t*)lpParam;
+    if (TimerOrWaitFired && data != NULL && data->abort_ptr != NULL) {
+        // Timeout reached, signal an abort should occur
+        // jl_safe_fprintf(ios_safe_stderr, "profile_timeout_cb called.\n");
+        if (jl_atomic_exchange(data->abort_ptr, 2) == 1) {
+            // jl_safe_fprintf(ios_safe_stderr, "profile_timeout_cb jl_thread_resume.\n");
+            jl_thread_resume(data->tid);
+            data->tid = -1;
+        }
+    }
+}
+#endif
 
-int jl_thread_suspend_and_get_state(int tid, int timeout, bt_context_t *ctx)
+static int jl_thread_suspend_and_get_state(int tid, int timeout, bt_context_t *ctx)
 {
     (void)timeout;
     jl_ptls_t ptls2 = jl_atomic_load_relaxed(&jl_all_tls_states)[tid];
@@ -421,8 +445,10 @@ int jl_thread_suspend_and_get_state(int tid, int timeout, bt_context_t *ctx)
     if (ct2 == NULL) // this thread is already dead
         return 0;
     HANDLE hThread = ptls2->system_id;
-    if ((DWORD)-1 == SuspendThread(hThread))
+    if ((DWORD)-1 == SuspendThread(hThread)) {
+        // jl_safe_fprintf(ios_safe_stderr, "failed to suspend thread %d: %lu\n", tid, GetLastError());
         return 0;
+    }
     assert(sizeof(*ctx) == sizeof(CONTEXT));
     memset(ctx, 0, sizeof(CONTEXT));
     ctx->ContextFlags = CONTEXT_CONTROL | CONTEXT_INTEGER;
@@ -439,90 +465,127 @@ void jl_thread_resume(int tid)
     jl_ptls_t ptls2 = jl_atomic_load_relaxed(&jl_all_tls_states)[tid];
     HANDLE hThread = ptls2->system_id;
     if ((DWORD)-1 == ResumeThread(hThread)) {
-        fputs("failed to resume main thread! aborting.", stderr);
+        jl_safe_fprintf(ios_safe_stderr, "failed to resume main thread! aborting.\n");
         abort();
     }
 }
 
 int jl_thread_suspend(int16_t tid, bt_context_t *ctx)
 {
-    uv_mutex_lock(&jl_in_stackwalk);
-    jl_lock_profile();
-    ULONG_PTR lock_cookie = 0;
-    LdrLockLoaderLock(0x1, NULL, &lock_cookie);
+    jl_lock_profile(); // prevent concurrent mutation
+    uv_mutex_lock(&jl_in_stackwalk); // prevent multi-threaded dbghelp calls
     int success = jl_thread_suspend_and_get_state(tid, 0, ctx);
-    LdrUnlockLoaderLock(0x1, lock_cookie);
-    jl_unlock_profile();
     uv_mutex_unlock(&jl_in_stackwalk);
+    jl_unlock_profile();
     return success;
 }
 
 static DWORD WINAPI profile_bt( LPVOID lparam )
 {
     // Note: illegal to use jl_* functions from this thread except for profiling-specific functions
+    // Dummy event for RegisterWaitForSingleObject (to use timeout callback)
+    HANDLE hProfileEvent = CreateEvent(NULL, TRUE, FALSE, NULL);
+    if (hProfileEvent == NULL) {
+        jl_safe_fprintf(ios_safe_stderr, "failed to create profile event.\n");
+        abort();
+    }
     while (1) {
         DWORD timeout_ms = nsecprof / (GIGA / 1000);
         Sleep(timeout_ms > 0 ? timeout_ms : 1);
-        if (profile_running) {
-            if (jl_profile_is_buffer_full()) {
-                jl_profile_stop_timer(); // does not change the thread state
-                SuspendThread(GetCurrentThread());
-                continue;
-            }
-            else if (profile_all_tasks) {
-                // Don't take the stackwalk lock here since it's already taken in `jl_rec_backtrace`
-                jl_profile_task();
-            }
-            else {
-                // TODO: bring this up to parity with other OS by adding loop over tid here
-                bt_context_t c;
-                if (!jl_thread_suspend(0, &c)) {
-                    fputs("failed to suspend main thread. aborting profiling.", stderr);
+        if (jl_profile_is_buffer_full())
+            jl_profile_stop_timer(); // does not change the thread state
+        if (!profile_running) {
+            uv_mutex_lock(&bt_data_prof_lock);
+            while (!profile_running)
+                uv_cond_wait(&bt_data_prof_cond, &bt_data_prof_lock);
+            uv_mutex_unlock(&bt_data_prof_lock);
+        }
+        else if (profile_all_tasks) {
+            // Don't take the stackwalk lock here since it's already taken in `jl_rec_backtrace`
+            jl_profile_task();
+        }
+        else {
+            // Profile all threads, similar to Unix implementation
+            bt_context_t c;
+            int nthreads = jl_atomic_load_acquire(&jl_n_threads);
+            int *randperm = profile_get_randperm(nthreads);
+            for (int idx = nthreads; idx-- > 0; ) {
+                int tid = randperm[idx];
+                if (!profile_running)
+                    break;
+                if (jl_profile_is_buffer_full()) {
                     jl_profile_stop_timer();
                     break;
                 }
+                if (!jl_thread_suspend(tid, &c))
+                    continue;
+                jl_ptls_t ptls = jl_atomic_load_relaxed(&jl_all_tls_states)[tid];
+                jl_task_t *t2 = jl_atomic_load_relaxed(&ptls->current_task);
+                int state = jl_atomic_load_relaxed(&ptls->sleep_check_state) == 0 ? PROFILE_STATE_THREAD_NOT_SLEEPING : PROFILE_STATE_THREAD_SLEEPING;
+
+                // Set up timeout handler for stackwalk
+#ifdef _CPU_X86_64_
+                _Atomic(int) abort_profiling = 0;
+                profile_timeout_data_t timeout_data;
+                timeout_data.abort_ptr = &abort_profiling;
+                timeout_data.tid = tid;
+                jl_set_profile_abort_ptr(&abort_profiling);
+                HANDLE hWaitHandle = NULL;
+                if (!RegisterWaitForSingleObject(&hWaitHandle, hProfileEvent, profile_timeout_cb,
+                                                 &timeout_data, 100, WT_EXECUTEONLYONCE | WT_EXECUTEINWAITTHREAD)) {
+                    // Failed to register wait, proceed without timeout protection
+                    hWaitHandle = NULL;
+                }
+#endif
                 // Get backtrace data
                 profile_bt_size_cur += rec_backtrace_ctx((jl_bt_element_t*)profile_bt_data_prof + profile_bt_size_cur,
                         profile_bt_size_max - profile_bt_size_cur - 1, &c, NULL);
-
-                jl_ptls_t ptls = jl_atomic_load_relaxed(&jl_all_tls_states)[0]; // given only profiling hMainThread
+#ifdef _CPU_X86_64_
+                // Clear abort pointer from TLS
+                jl_set_profile_abort_ptr(NULL);
+                // Wait for callback to complete or cancel before continuing
+                if (hWaitHandle != NULL)
+                    UnregisterWaitEx(hWaitHandle, INVALID_HANDLE_VALUE);
+                if (timeout_data.tid != -1)
+#endif
+                    jl_thread_resume(tid);
 
                 // META_OFFSET_THREADID store threadid but add 1 as 0 is preserved to indicate end of block
-                profile_bt_data_prof[profile_bt_size_cur++].uintptr = ptls->tid + 1;
+                profile_bt_data_prof[profile_bt_size_cur++].uintptr = tid + 1;
 
                 // META_OFFSET_TASKID store task id (never null)
-                profile_bt_data_prof[profile_bt_size_cur++].jlvalue = (jl_value_t*)jl_atomic_load_relaxed(&ptls->current_task);
+                profile_bt_data_prof[profile_bt_size_cur++].jlvalue = (jl_value_t*)t2;
 
                 // META_OFFSET_CPUCYCLECLOCK store cpu cycle clock
                 profile_bt_data_prof[profile_bt_size_cur++].uintptr = cycleclock();
 
                 // store whether thread is sleeping (don't ever encode a state as `0` since is preserved to indicate end of block)
-                int state = jl_atomic_load_relaxed(&ptls->sleep_check_state) == 0 ? PROFILE_STATE_THREAD_NOT_SLEEPING : PROFILE_STATE_THREAD_SLEEPING;
                 profile_bt_data_prof[profile_bt_size_cur++].uintptr = state;
 
                 // Mark the end of this block with two 0's
                 profile_bt_data_prof[profile_bt_size_cur++].uintptr = 0;
                 profile_bt_data_prof[profile_bt_size_cur++].uintptr = 0;
-                jl_thread_resume(0);
-                jl_check_profile_autostop();
             }
+            jl_check_profile_autostop();
         }
     }
-    uv_mutex_unlock(&jl_in_stackwalk);
-    jl_profile_stop_timer();
+    // this is unreachable, but would be the relevant cleanup
+    uv_mutex_lock(&bt_data_prof_lock);
     hBtThread = NULL;
+    uv_mutex_unlock(&bt_data_prof_lock);
+    jl_profile_stop_timer();
+    CloseHandle(hProfileEvent);
     return 0;
 }
 
-static volatile TIMECAPS timecaps;
-
 JL_DLLEXPORT int jl_profile_start_timer(uint8_t all_tasks)
 {
+    uv_mutex_lock(&bt_data_prof_lock);
     if (hBtThread == NULL) {
-
         TIMECAPS _timecaps;
         if (MMSYSERR_NOERROR != timeGetDevCaps(&_timecaps, sizeof(_timecaps))) {
-            fputs("failed to get timer resolution", stderr);
+            uv_mutex_unlock(&bt_data_prof_lock);
+            jl_safe_fprintf(ios_safe_stderr, "failed to get timer resolution.\n");
             return -2;
         }
         timecaps = _timecaps;
@@ -534,15 +597,12 @@ JL_DLLEXPORT int jl_profile_start_timer(uint8_t all_tasks)
             0,                      // argument to thread function
             0,                      // use default creation flags
             0);                     // returns the thread identifier
-        if (hBtThread == NULL)
+        if (hBtThread == NULL) {
+            uv_mutex_unlock(&bt_data_prof_lock);
+            jl_safe_fprintf(ios_safe_stderr, "failed to allocate profile thread.\n");
             return -1;
-        (void)SetThreadPriority(hBtThread, THREAD_PRIORITY_ABOVE_NORMAL);
-    }
-    else {
-        if ((DWORD)-1 == ResumeThread(hBtThread)) {
-            fputs("failed to resume profiling thread.", stderr);
-            return -2;
         }
+        (void)SetThreadPriority(hBtThread, THREAD_PRIORITY_ABOVE_NORMAL);
     }
     if (profile_running == 0) {
         // Failure to change the timer resolution is not fatal. However, it is important to
@@ -552,6 +612,8 @@ JL_DLLEXPORT int jl_profile_start_timer(uint8_t all_tasks)
     }
     profile_all_tasks = all_tasks;
     profile_running = 1; // set `profile_running` finally
+    uv_cond_broadcast(&bt_data_prof_cond);
+    uv_mutex_unlock(&bt_data_prof_lock);
     return 0;
 }
 JL_DLLEXPORT void jl_profile_stop_timer(void)