use `RUBY_DEBUG_LOG` instead of `thread_debug`

`thread_debug()` was introduced to print debug messages
on `THREAD_DEBUG > 0` but `RUBY_DEBUG_LOG()` is more controllable.

3 files changed, 128 insertions, 192 deletions

diff --git a/thread.c b/thread.c
index cee0c6c8de..26c46ed9de 100644
--- a/thread.c
+++ b/thread.c
@@ -106,10 +106,6 @@
 #define RUBY_THREAD_PRIORITY_MIN -3
 #endif
 
-#ifndef THREAD_DEBUG
-#define THREAD_DEBUG 0
-#endif
-
 static VALUE rb_cThreadShield;
 
 static VALUE sym_immediate;
@@ -257,60 +253,6 @@ timeout_prepare(rb_hrtime_t **to, rb_hrtime_t *rel, rb_hrtime_t *end,
     }
 }
 
-#if THREAD_DEBUG
-#ifdef HAVE_VA_ARGS_MACRO
-void rb_thread_debug(const char *file, int line, const char *fmt, ...);
-#define thread_debug(...) rb_thread_debug(__FILE__, __LINE__, __VA_ARGS__)
-#define POSITION_FORMAT "%s:%d:"
-#define POSITION_ARGS ,file, line
-#else
-void rb_thread_debug(const char *fmt, ...);
-#define thread_debug rb_thread_debug
-#define POSITION_FORMAT
-#define POSITION_ARGS
-#endif
-
-# if THREAD_DEBUG < 0
-static int rb_thread_debug_enabled;
-
-/*
- *  call-seq:
- *     Thread.DEBUG     -> num
- *
- *  Returns the thread debug level.  Available only if compiled with
- *  THREAD_DEBUG=-1.
- */
-
-static VALUE
-rb_thread_s_debug(VALUE _)
-{
-    return INT2NUM(rb_thread_debug_enabled);
-}
-
-/*
- *  call-seq:
- *     Thread.DEBUG = num
- *
- *  Sets the thread debug level.  Available only if compiled with
- *  THREAD_DEBUG=-1.
- */
-
-static VALUE
-rb_thread_s_debug_set(VALUE self, VALUE val)
-{
-    rb_thread_debug_enabled = RTEST(val) ? NUM2INT(val) : 0;
-    return val;
-}
-# else
-# define rb_thread_debug_enabled THREAD_DEBUG
-# endif
-#else
-#define thread_debug if(0)printf
-#endif
-
-#define thread_id_str(th) ((void *)(uintptr_t)(th)->nt->thread_id)
-#define PRI_THREAD_ID "p"
-
 MAYBE_UNUSED(NOINLINE(static int thread_start_func_2(rb_thread_t *th, VALUE *stack_start)));
 void ruby_sigchld_handler(rb_vm_t *); /* signal.c */
 
@@ -335,35 +277,6 @@ ubf_sigwait(void *ignore)
 #  define USE_EVENTFD (0)
 #endif
 
-#if THREAD_DEBUG
-static int debug_mutex_initialized = 1;
-static rb_nativethread_lock_t debug_mutex;
-
-void
-rb_thread_debug(
-#ifdef HAVE_VA_ARGS_MACRO
-    const char *file, int line,
-#endif
-    const char *fmt, ...)
-{
-    va_list args;
-    char buf[BUFSIZ];
-
-    if (!rb_thread_debug_enabled) return;
-
-    if (debug_mutex_initialized == 1) {
-	debug_mutex_initialized = 0;
-        rb_native_mutex_initialize(&debug_mutex);
-    }
-
-    va_start(args, fmt);
-    vsnprintf(buf, BUFSIZ, fmt, args);
-    va_end(args);
-
-    DEBUG_OUT();
-}
-#endif
-
 #include "thread_sync.c"
 
 void
@@ -463,15 +376,15 @@ terminate_all(rb_ractor_t *r, const rb_thread_t *main_thread)
 
     ccan_list_for_each(&r->threads.set, th, lt_node) {
         if (th != main_thread) {
-	    thread_debug("terminate_all: begin (thid: %"PRI_THREAD_ID", status: %s)\n",
-			 thread_id_str(th), thread_status_name(th, TRUE));
-	    rb_threadptr_pending_interrupt_enque(th, eTerminateSignal);
+            RUBY_DEBUG_LOG("terminate start th:%u status:%s", rb_th_serial(th), thread_status_name(th, TRUE));
+
+            rb_threadptr_pending_interrupt_enque(th, eTerminateSignal);
 	    rb_threadptr_interrupt(th);
-	    thread_debug("terminate_all: end (thid: %"PRI_THREAD_ID", status: %s)\n",
-			 thread_id_str(th), thread_status_name(th, TRUE));
-	}
+
+            RUBY_DEBUG_LOG("terminate done th:%u status:%s", rb_th_serial(th), thread_status_name(th, TRUE));
+        }
 	else {
-	    thread_debug("terminate_all: main thread (%p)\n", (void *)th);
+            RUBY_DEBUG_LOG("main thread th:%u", rb_th_serial(th));
 	}
     }
 }
@@ -536,8 +449,9 @@ rb_thread_terminate_all(rb_thread_t *th)
     EC_PUSH_TAG(ec);
     if (EC_EXEC_TAG() == TAG_NONE) {
       retry:
-	thread_debug("rb_thread_terminate_all (main thread: %p)\n", (void *)th);
-	terminate_all(cr, th);
+        RUBY_DEBUG_LOG("th:%u", rb_th_serial(th));
+
+        terminate_all(cr, th);
 
 	while (rb_ractor_living_thread_num(cr) > 1) {
             rb_hrtime_t rel = RB_HRTIME_PER_SEC;
@@ -730,12 +644,14 @@ thread_start_func_2(rb_thread_t *th, VALUE *stack_start)
     VALUE * vm_stack = NULL;
 
     VM_ASSERT(th != th->vm->ractor.main_thread);
-    thread_debug("thread start: %p\n", (void *)th);
+    RUBY_DEBUG_LOG("th:%u", rb_th_serial(th));
 
     // setup native thread
     thread_sched_to_running(TH_SCHED(th), th);
     ruby_thread_set_native(th);
 
+    RUBY_DEBUG_LOG("got lock. th:%u", rb_th_serial(th));
+
     // setup ractor
     if (rb_ractor_status_p(th->ractor, ractor_blocking)) {
         RB_VM_LOCK();
@@ -760,8 +676,6 @@ thread_start_func_2(rb_thread_t *th, VALUE *stack_start)
     th->ec->machine.stack_start = STACK_DIR_UPPER(vm_stack + size, vm_stack);
     th->ec->machine.stack_maxsize -= size * sizeof(VALUE);
 
-    thread_debug("thread start (get lock): %p\n", (void *)th);
-
     // Ensure that we are not joinable.
     VM_ASSERT(th->value == Qundef);
 
@@ -820,7 +734,7 @@ thread_start_func_2(rb_thread_t *th, VALUE *stack_start)
     }
 
     th->status = THREAD_KILLED;
-    thread_debug("thread end: %p\n", (void *)th);
+    RUBY_DEBUG_LOG("killed th:%u", rb_th_serial(th));
 
     if (th->vm->ractor.main_thread == th) {
         ruby_stop(0);
@@ -936,7 +850,7 @@ thread_create_core(VALUE thval, struct thread_create_params *params)
 
     rb_native_mutex_initialize(&th->interrupt_lock);
 
-    RUBY_DEBUG_LOG("r:%u th:%p", rb_ractor_id(th->ractor), (void *)th);
+    RUBY_DEBUG_LOG("r:%u th:%u", rb_ractor_id(th->ractor), rb_th_serial(th));
 
     rb_ractor_living_threads_insert(th->ractor, th);
 
@@ -1138,8 +1052,7 @@ thread_join_sleep(VALUE arg)
         }
         else {
             if (hrtime_update_expire(limit, end)) {
-                thread_debug("thread_join: timeout (thid: %"PRI_THREAD_ID")\n",
-                             thread_id_str(target_th));
+                RUBY_DEBUG_LOG("timeout target_th:%u", rb_th_serial(target_th));
                 return Qfalse;
             }
             th->status = THREAD_STOPPED;
@@ -1147,8 +1060,8 @@ thread_join_sleep(VALUE arg)
         }
         RUBY_VM_CHECK_INTS_BLOCKING(th->ec);
         th->status = THREAD_RUNNABLE;
-        thread_debug("thread_join: interrupted (thid: %"PRI_THREAD_ID", status: %s)\n",
-                     thread_id_str(target_th), thread_status_name(target_th, TRUE));
+
+        RUBY_DEBUG_LOG("interrupted target_th:%u status:%s", rb_th_serial(target_th), thread_status_name(target_th, TRUE));
     }
     return Qtrue;
 }
@@ -1168,8 +1081,7 @@ thread_join(rb_thread_t *target_th, VALUE timeout, rb_hrtime_t *limit)
         rb_raise(rb_eThreadError, "Target thread must not be main thread");
     }
 
-    thread_debug("thread_join (thid: %"PRI_THREAD_ID", status: %s)\n",
-                 thread_id_str(target_th), thread_status_name(target_th, TRUE));
+    RUBY_DEBUG_LOG("target_th:%u status:%s", rb_th_serial(target_th), thread_status_name(target_th, TRUE));
 
     if (target_th->status != THREAD_KILLED) {
         struct rb_waiting_list waiter;
@@ -1189,8 +1101,7 @@ thread_join(rb_thread_t *target_th, VALUE timeout, rb_hrtime_t *limit)
         }
     }
 
-    thread_debug("thread_join: success (thid: %"PRI_THREAD_ID", status: %s)\n",
-                 thread_id_str(target_th), thread_status_name(target_th, TRUE));
+    RUBY_DEBUG_LOG("success target_th:%u status:%s", rb_th_serial(target_th), thread_status_name(target_th, TRUE));
 
     if (target_th->ec->errinfo != Qnil) {
         VALUE err = target_th->ec->errinfo;
@@ -1198,8 +1109,7 @@ thread_join(rb_thread_t *target_th, VALUE timeout, rb_hrtime_t *limit)
         if (FIXNUM_P(err)) {
             switch (err) {
               case INT2FIX(TAG_FATAL):
-                thread_debug("thread_join: terminated (thid: %"PRI_THREAD_ID", status: %s)\n",
-                             thread_id_str(target_th), thread_status_name(target_th, TRUE));
+                RUBY_DEBUG_LOG("terminated target_th:%u status:%s", rb_th_serial(target_th), thread_status_name(target_th, TRUE));
 
                 /* OK. killed. */
                 break;
@@ -1384,9 +1294,9 @@ hrtime_update_expire(rb_hrtime_t *timeout, const rb_hrtime_t end)
     rb_hrtime_t now = rb_hrtime_now();
 
     if (now > end) return 1;
-    thread_debug("hrtime_update_expire: "
-                 "%"PRIu64" > %"PRIu64"\n",
-                 (uint64_t)end, (uint64_t)now);
+
+    RUBY_DEBUG_LOG("%"PRIu64" > %"PRIu64"", (uint64_t)end, (uint64_t)now);
+
     *timeout = end - now;
     return 0;
 }
@@ -1417,14 +1327,14 @@ sleep_hrtime(rb_thread_t *th, rb_hrtime_t rel, unsigned int fl)
 void
 rb_thread_sleep_forever(void)
 {
-    thread_debug("rb_thread_sleep_forever\n");
+    RUBY_DEBUG_LOG("%s", "");
     sleep_forever(GET_THREAD(), SLEEP_SPURIOUS_CHECK);
 }
 
 void
 rb_thread_sleep_deadly(void)
 {
-    thread_debug("rb_thread_sleep_deadly\n");
+    RUBY_DEBUG_LOG("%s", "");
     sleep_forever(GET_THREAD(), SLEEP_DEADLOCKABLE|SLEEP_SPURIOUS_CHECK);
 }
 
@@ -1448,7 +1358,7 @@ rb_thread_sleep_deadly_allow_spurious_wakeup(VALUE blocker)
         rb_fiber_scheduler_block(scheduler, blocker, Qnil);
     }
     else {
-        thread_debug("rb_thread_sleep_deadly_allow_spurious_wakeup\n");
+        RUBY_DEBUG_LOG("%s", "");
         sleep_forever(GET_THREAD(), SLEEP_DEADLOCKABLE);
     }
 }
@@ -1500,16 +1410,18 @@ rb_thread_sleep(int sec)
 static void
 rb_thread_schedule_limits(uint32_t limits_us)
 {
-    thread_debug("rb_thread_schedule\n");
     if (!rb_thread_alone()) {
 	rb_thread_t *th = GET_THREAD();
+        RUBY_DEBUG_LOG("us:%u", (unsigned int)limits_us);
 
 	if (th->running_time_us >= limits_us) {
-	    thread_debug("rb_thread_schedule/switch start\n");
-	    RB_GC_SAVE_MACHINE_CONTEXT(th);
+	    RUBY_DEBUG_LOG("switch %s", "start");
+
+            RB_GC_SAVE_MACHINE_CONTEXT(th);
 	    thread_sched_yield(TH_SCHED(th), th);
             rb_ractor_thread_switch(th->ractor, th);
-	    thread_debug("rb_thread_schedule/switch done\n");
+
+            RUBY_DEBUG_LOG("switch %s", "done");
 	}
     }
 }
@@ -1530,14 +1442,17 @@ blocking_region_begin(rb_thread_t *th, struct rb_blocking_region_buffer *region,
 #ifdef RUBY_VM_CRITICAL_SECTION
     VM_ASSERT(ruby_assert_critical_section_entered == 0);
 #endif
+    VM_ASSERT(th == GET_THREAD());
 
     region->prev_status = th->status;
     if (unblock_function_set(th, ubf, arg, fail_if_interrupted)) {
 	th->blocking_region_buffer = region;
 	th->status = THREAD_STOPPED;
         rb_ractor_blocking_threads_inc(th->ractor, __FILE__, __LINE__);
-	thread_debug("enter blocking region (%p)\n", (void *)th);
-	RB_GC_SAVE_MACHINE_CONTEXT(th);
+
+        RUBY_DEBUG_LOG("%s", "");
+
+        RB_GC_SAVE_MACHINE_CONTEXT(th);
 	thread_sched_to_waiting(TH_SCHED(th));
 	return TRUE;
     }
@@ -1557,12 +1472,14 @@ blocking_region_end(rb_thread_t *th, struct rb_blocking_region_buffer *region)
     thread_sched_to_running(TH_SCHED(th), th);
     rb_ractor_thread_switch(th->ractor, th);
 
-    thread_debug("leave blocking region (%p)\n", (void *)th);
     th->blocking_region_buffer = 0;
     rb_ractor_blocking_threads_dec(th->ractor, __FILE__, __LINE__);
     if (th->status == THREAD_STOPPED) {
 	th->status = region->prev_status;
     }
+
+    RUBY_DEBUG_LOG("%s", "");
+    VM_ASSERT(th == GET_THREAD());
 }
 
 void *
@@ -2368,7 +2285,7 @@ rb_threadptr_execute_interrupts(rb_thread_t *th, int blocking_timing)
 	/* exception from another thread */
 	if (pending_interrupt && threadptr_pending_interrupt_active_p(th)) {
 	    VALUE err = rb_threadptr_pending_interrupt_deque(th, blocking_timing ? INTERRUPT_ON_BLOCKING : INTERRUPT_NONE);
-	    thread_debug("rb_thread_execute_interrupts: %"PRIdVALUE"\n", err);
+            RUBY_DEBUG_LOG("err:%"PRIdVALUE"\n", err);
             ret = TRUE;
 
 	    if (err == Qundef) {
@@ -2589,35 +2506,36 @@ thread_raise_m(int argc, VALUE *argv, VALUE self)
 VALUE
 rb_thread_kill(VALUE thread)
 {
-    rb_thread_t *th = rb_thread_ptr(thread);
+    rb_thread_t *target_th = rb_thread_ptr(thread);
 
-    if (th->to_kill || th->status == THREAD_KILLED) {
+    if (target_th->to_kill || target_th->status == THREAD_KILLED) {
 	return thread;
     }
-    if (th == th->vm->ractor.main_thread) {
+    if (target_th == target_th->vm->ractor.main_thread) {
 	rb_exit(EXIT_SUCCESS);
     }
 
-    thread_debug("rb_thread_kill: %p (%"PRI_THREAD_ID")\n", (void *)th, thread_id_str(th));
+    RUBY_DEBUG_LOG("target_th:%u", rb_th_serial(target_th));
 
-    if (th == GET_THREAD()) {
+    if (target_th == GET_THREAD()) {
 	/* kill myself immediately */
-	rb_threadptr_to_kill(th);
+	rb_threadptr_to_kill(target_th);
     }
     else {
-	threadptr_check_pending_interrupt_queue(th);
-	rb_threadptr_pending_interrupt_enque(th, eKillSignal);
-	rb_threadptr_interrupt(th);
+	threadptr_check_pending_interrupt_queue(target_th);
+	rb_threadptr_pending_interrupt_enque(target_th, eKillSignal);
+	rb_threadptr_interrupt(target_th);
     }
+
     return thread;
 }
 
 int
 rb_thread_to_be_killed(VALUE thread)
 {
-    rb_thread_t *th = rb_thread_ptr(thread);
+    rb_thread_t *target_th = rb_thread_ptr(thread);
 
-    if (th->to_kill || th->status == THREAD_KILLED) {
+    if (target_th->to_kill || target_th->status == THREAD_KILLED) {
 	return TRUE;
     }
     return FALSE;
@@ -5340,10 +5258,6 @@ Init_Thread(void)
     rb_define_singleton_method(rb_cThread, "report_on_exception=", rb_thread_s_report_exc_set, 1);
     rb_define_singleton_method(rb_cThread, "ignore_deadlock", rb_thread_s_ignore_deadlock, 0);
     rb_define_singleton_method(rb_cThread, "ignore_deadlock=", rb_thread_s_ignore_deadlock_set, 1);
-#if THREAD_DEBUG < 0
-    rb_define_singleton_method(rb_cThread, "DEBUG", rb_thread_s_debug, 0);
-    rb_define_singleton_method(rb_cThread, "DEBUG=", rb_thread_s_debug_set, 1);
-#endif
     rb_define_singleton_method(rb_cThread, "handle_interrupt", rb_thread_s_handle_interrupt, 1);
     rb_define_singleton_method(rb_cThread, "pending_interrupt?", rb_thread_s_pending_interrupt_p, -1);
     rb_define_method(rb_cThread, "pending_interrupt?", rb_thread_pending_interrupt_p, -1);
@@ -5429,6 +5343,12 @@ ruby_native_thread_p(void)
     return th != 0;
 }
 
+#ifdef NON_SCALAR_THREAD_ID
+  #define thread_id_str(th) (NULL)
+#else
+  #define thread_id_str(th) ((void *)(uintptr_t)(th)->nt->thread_id)
+#endif
+
 static void
 debug_deadlock_check(rb_ractor_t *r, VALUE msg)
 {
@@ -5441,7 +5361,7 @@ debug_deadlock_check(rb_ractor_t *r, VALUE msg)
 
     ccan_list_for_each(&r->threads.set, th, lt_node) {
         rb_str_catf(msg, "* %+"PRIsVALUE"\n   rb_thread_t:%p "
-                    "native:%"PRI_THREAD_ID" int:%u",
+                    "native:%p int:%u",
                     th->self, (void *)th, thread_id_str(th), th->ec->interrupt_flag);
 
         if (th->locking_mutex) {
diff --git a/thread_pthread.c b/thread_pthread.c
index c189a8130c..2108431456 100644
--- a/thread_pthread.c
+++ b/thread_pthread.c
@@ -1212,7 +1212,7 @@ native_thread_create(rb_thread_t *th)
     th->nt = ZALLOC(struct rb_native_thread);
 
     if (use_cached_thread(th)) {
-	thread_debug("create (use cached thread): %p\n", (void *)th);
+        RUBY_DEBUG_LOG("use cached nt. th:%u", rb_th_serial(th));
     }
     else {
 	pthread_attr_t attr;
@@ -1227,8 +1227,8 @@ native_thread_create(rb_thread_t *th)
 	CHECK_ERR(pthread_attr_init(&attr));
 
 # ifdef PTHREAD_STACK_MIN
-	thread_debug("create - stack size: %lu\n", (unsigned long)stack_size);
-	CHECK_ERR(pthread_attr_setstacksize(&attr, stack_size));
+        RUBY_DEBUG_LOG("stack size: %lu", (unsigned long)stack_size);
+        CHECK_ERR(pthread_attr_setstacksize(&attr, stack_size));
 # endif
 
 # ifdef HAVE_PTHREAD_ATTR_SETINHERITSCHED
@@ -1237,8 +1237,10 @@ native_thread_create(rb_thread_t *th)
 	CHECK_ERR(pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_DETACHED));
 
         err = pthread_create(&th->nt->thread_id, &attr, thread_start_func_1, th);
-	thread_debug("create: %p (%d)\n", (void *)th, err);
-	/* should be done in the created thread */
+
+        RUBY_DEBUG_LOG("th:%u err:%d", rb_th_serial(th), err);
+
+        /* should be done in the created thread */
 	CHECK_ERR(pthread_attr_destroy(&attr));
     }
     return err;
@@ -1284,7 +1286,7 @@ static void
 ubf_pthread_cond_signal(void *ptr)
 {
     rb_thread_t *th = (rb_thread_t *)ptr;
-    thread_debug("ubf_pthread_cond_signal (%p)\n", (void *)th);
+    RUBY_DEBUG_LOG("th:%u", rb_th_serial(th));
     rb_native_cond_signal(&th->nt->cond.intr);
 }
 
@@ -1312,7 +1314,7 @@ native_cond_sleep(rb_thread_t *th, rb_hrtime_t *rel)
 
 	if (RUBY_VM_INTERRUPTED(th->ec)) {
 	    /* interrupted.  return immediate */
-	    thread_debug("native_sleep: interrupted before sleep\n");
+            RUBY_DEBUG_LOG("interrupted before sleep th:%u", rb_th_serial(th));
 	}
 	else {
 	    if (!rel) {
@@ -1335,7 +1337,7 @@ native_cond_sleep(rb_thread_t *th, rb_hrtime_t *rel)
     }
     THREAD_BLOCKING_END(th);
 
-    thread_debug("native_sleep done\n");
+    RUBY_DEBUG_LOG("done th:%u", rb_th_serial(th));
 }
 
 #ifdef USE_UBF_LIST
@@ -1388,7 +1390,7 @@ unregister_ubf_list(rb_thread_t *th)
 static void
 ubf_wakeup_thread(rb_thread_t *th)
 {
-    thread_debug("thread_wait_queue_wakeup (%"PRI_THREAD_ID")\n", thread_id_str(th));
+    RUBY_DEBUG_LOG("th:%u", rb_th_serial(th));
     pthread_kill(th->nt->thread_id, SIGVTALRM);
 }
 
@@ -2152,7 +2154,7 @@ rb_sigwait_sleep(rb_thread_t *th, int sigwait_fd, const rb_hrtime_t *rel)
         check_signals_nogvl(th, sigwait_fd);
     }
     else {
-        rb_hrtime_t to = RB_HRTIME_MAX, end;
+        rb_hrtime_t to = RB_HRTIME_MAX, end = 0;
         int n = 0;
 
         if (rel) {
diff --git a/thread_win32.c b/thread_win32.c
index 966f0af5b6..ec5d336589 100644
--- a/thread_win32.c
+++ b/thread_win32.c
@@ -59,31 +59,45 @@ w32_error(const char *func)
     UNREACHABLE;
 }
 
+#define W32_EVENT_DEBUG 0
+
+#if W32_EVENT_DEBUG
+#define w32_event_debug printf
+#else
+#define w32_event_debug if (0) printf
+#endif
+
 static int
 w32_mutex_lock(HANDLE lock, bool try)
 {
     DWORD result;
     while (1) {
-        thread_debug("rb_native_mutex_lock: %p\n", lock);
+        // RUBY_DEBUG_LOG() is not available because RUBY_DEBUG_LOG() calls it.
+        w32_event_debug("lock:%p\n", lock);
+
         result = w32_wait_events(&lock, 1, try ? 0 : INFINITE, 0);
 	switch (result) {
 	  case WAIT_OBJECT_0:
 	    /* get mutex object */
-	    thread_debug("acquire mutex: %p\n", lock);
+            w32_event_debug("locked lock:%p\n", lock);
 	    return 0;
-	  case WAIT_OBJECT_0 + 1:
+
+          case WAIT_OBJECT_0 + 1:
 	    /* interrupt */
 	    errno = EINTR;
-	    thread_debug("acquire mutex interrupted: %p\n", lock);
+            w32_event_debug("interrupted lock:%p\n", lock);
 	    return 0;
-	  case WAIT_TIMEOUT:
-	    thread_debug("timeout mutex: %p\n", lock);
+
+          case WAIT_TIMEOUT:
+            w32_event_debug("timeout locK:%p\n", lock);
             return EBUSY;
-	  case WAIT_ABANDONED:
+
+          case WAIT_ABANDONED:
 	    rb_bug("win32_mutex_lock: WAIT_ABANDONED");
 	    break;
-	  default:
-	    rb_bug("win32_mutex_lock: unknown result (%ld)", result);
+
+          default:
+            rb_bug("win32_mutex_lock: unknown result (%ld)", result);
 	    break;
 	}
     }
@@ -174,10 +188,10 @@ Init_native_thread(rb_thread_t *main_th)
 		    GetCurrentProcess(),
 		    &main_th->nt->thread_id, 0, FALSE, DUPLICATE_SAME_ACCESS);
 
-    thread_debug("initial thread (th: %p, thid: %p, event: %p)\n",
-                 main_th,
-                 main_th->nt->thread_id,
-                 main_th->nt->interrupt_event);
+    RUBY_DEBUG_LOG("initial thread th:%u thid:%p, event: %p",
+                   rb_th_serial(main_th),
+                   main_th->nt->thread_id,
+                   main_th->nt->interrupt_event);
 }
 
 static int
@@ -188,34 +202,34 @@ w32_wait_events(HANDLE *events, int count, DWORD timeout, rb_thread_t *th)
     const int initcount = count;
     DWORD ret;
 
-    thread_debug("  w32_wait_events events:%p, count:%d, timeout:%ld, th:%p\n",
-		 events, count, timeout, th);
+    w32_event_debug("events:%p, count:%d, timeout:%ld, th:%u\n",
+                    events, count, timeout, th ? rb_th_serial(th) : -1);
+
     if (th && (intr = th->nt->interrupt_event)) {
 	if (ResetEvent(intr) && (!RUBY_VM_INTERRUPTED(th->ec) || SetEvent(intr))) {
 	    targets = ALLOCA_N(HANDLE, count + 1);
 	    memcpy(targets, events, sizeof(HANDLE) * count);
 
 	    targets[count++] = intr;
-	    thread_debug("  * handle: %p (count: %d, intr)\n", intr, count);
-	}
+            w32_event_debug("handle:%p (count:%d, intr)\n", intr, count);
+        }
 	else if (intr == th->nt->interrupt_event) {
 	    w32_error("w32_wait_events");
 	}
     }
 
-    thread_debug("  WaitForMultipleObjects start (count: %d)\n", count);
+    w32_event_debug("WaitForMultipleObjects start count:%d\n", count);
     ret = WaitForMultipleObjects(count, targets, FALSE, timeout);
-    thread_debug("  WaitForMultipleObjects end (ret: %lu)\n", ret);
+    w32_event_debug("WaitForMultipleObjects end ret:%lu\n", ret);
 
     if (ret == (DWORD)(WAIT_OBJECT_0 + initcount) && th) {
 	errno = EINTR;
     }
-    if (ret == WAIT_FAILED && THREAD_DEBUG) {
+    if (ret == WAIT_FAILED && W32_EVENT_DEBUG) {
 	int i;
-	DWORD dmy;
-	for (i = 0; i < count; i++) {
-	    thread_debug("  * error handle %d - %s\n", i,
-			 GetHandleInformation(targets[i], &dmy) ? "OK" : "NG");
+        DWORD dmy;
+        for (i = 0; i < count; i++) {
+            w32_event_debug("i:%d %s\n", i, GetHandleInformation(targets[i], &dmy) ? "OK" : "NG");
 	}
     }
     return ret;
@@ -320,9 +334,9 @@ native_sleep(rb_thread_t *th, rb_hrtime_t *rel)
 	    /* interrupted.  return immediate */
 	}
 	else {
-	    thread_debug("native_sleep start (%lu)\n", msec);
+	    RUBY_DEBUG_LOG("start msec:%lu", msec);
 	    ret = w32_wait_events(0, 0, msec, th);
-	    thread_debug("native_sleep done (%lu)\n", ret);
+	    RUBY_DEBUG_LOG("done ret:%lu", ret);
 	}
 
         rb_native_mutex_lock(&th->interrupt_lock);
@@ -357,7 +371,7 @@ void
 rb_native_mutex_unlock(rb_nativethread_lock_t *lock)
 {
 #ifdef USE_WIN32_MUTEX
-    thread_debug("release mutex: %p\n", lock->mutex);
+    RUBY_DEBUG_LOG("lock:%p", lock->mutex);
     ReleaseMutex(lock->mutex);
 #else
     LeaveCriticalSection(&lock->crit);
@@ -597,7 +611,7 @@ static void
 native_thread_destroy(rb_thread_t *th)
 {
     HANDLE intr = InterlockedExchangePointer(&th->nt->interrupt_event, 0);
-    thread_debug("close handle - intr: %p, thid: %p\n", intr, th->nt->thread_id);
+    RUBY_DEBUG_LOG("close handle intr:%p, thid:%p\n", intr, th->nt->thread_id);
     w32_close_handle(intr);
 }
 
@@ -611,13 +625,13 @@ thread_start_func_1(void *th_ptr)
     th->nt->interrupt_event = CreateEvent(0, TRUE, FALSE, 0);
 
     /* run */
-    thread_debug("thread created (th: %p, thid: %p, event: %p)\n", th,
-		 th->nt->thread_id, th->nt->interrupt_event);
+    RUBY_DEBUG_LOG("thread created th:%u, thid: %p, event: %p",
+                   rb_th_serial(th), th->nt->thread_id, th->nt->interrupt_event);
 
     thread_start_func_2(th, th->ec->machine.stack_start);
 
     w32_close_handle(thread_id);
-    thread_debug("thread deleted (th: %p)\n", th);
+    RUBY_DEBUG_LOG("thread deleted th:%u", rb_th_serial(th));
     return 0;
 }
 
@@ -634,11 +648,11 @@ native_thread_create(rb_thread_t *th)
 
     w32_resume_thread(th->nt->thread_id);
 
-    if (THREAD_DEBUG) {
-	Sleep(0);
-	thread_debug("create: (th: %p, thid: %p, intr: %p), stack size: %"PRIuSIZE"\n",
-		     th, th->nt->thread_id,
-		     th->nt->interrupt_event, stack_size);
+    if (USE_RUBY_DEBUG_LOG) {
+        Sleep(0);
+        RUBY_DEBUG_LOG("th:%u thid:%p intr:%p), stack size: %"PRIuSIZE"",
+                       rb_th_serial(th), th->nt->thread_id,
+                       th->nt->interrupt_event, stack_size);
     }
     return 0;
 }
@@ -702,7 +716,7 @@ static void
 ubf_handle(void *ptr)
 {
     rb_thread_t *th = (rb_thread_t *)ptr;
-    thread_debug("ubf_handle: %p\n", th);
+    RUBY_DEBUG_LOG("th:%u\n", rb_th_serial(th));
 
     if (!SetEvent(th->nt->interrupt_event)) {
 	w32_error("ubf_handle");
@@ -723,7 +737,7 @@ static unsigned long __stdcall
 timer_thread_func(void *dummy)
 {
     rb_vm_t *vm = GET_VM();
-    thread_debug("timer_thread\n");
+    RUBY_DEBUG_LOG("%s", "start");
     rb_w32_set_thread_description(GetCurrentThread(), L"ruby-timer-thread");
     while (WaitForSingleObject(timer_thread.lock,
                                TIME_QUANTUM_USEC/1000) == WAIT_TIMEOUT) {
@@ -731,7 +745,7 @@ timer_thread_func(void *dummy)
 	ruby_sigchld_handler(vm); /* probably no-op */
 	rb_threadptr_check_signal(vm->ractor.main_thread);
     }
-    thread_debug("timer killed\n");
+    RUBY_DEBUG_LOG("%s", "end");
     return 0;
 }
 
@@ -754,8 +768,8 @@ rb_thread_create_timer_thread(void)
 	if (!timer_thread.lock) {
 	    timer_thread.lock = CreateEvent(0, TRUE, FALSE, 0);
 	}
-	timer_thread.id = w32_create_thread(1024 + (THREAD_DEBUG ? BUFSIZ : 0),
-					    timer_thread_func, 0);
+        timer_thread.id = w32_create_thread(1024 + (USE_RUBY_DEBUG_LOG ? BUFSIZ : 0),
+                                            timer_thread_func, 0);
 	w32_resume_thread(timer_thread.id);
     }
 }