From 33ac16d70e28f89c8352d46340b1e65a10eaebed Mon Sep 17 00:00:00 2001
From: Koichi Sasada <ko1@atdot.net>
Date: Thu, 3 Aug 2023 15:32:24 +0900
Subject: [PATCH] `RUBY_DEBUG_LOG_TIME` to print times

`RUBY_DEBUG_LOG=1 RUBY_DEBUG_LOG_TIME=1 ruby ...` will prints
debug logs with current time.
---
 common.mk |  3 +++
 debug.c   | 17 +++++++++++++++++
 2 files changed, 20 insertions(+)

diff --git a/common.mk b/common.mk
index 0b348bf52d2bbd..ae9c822c63ef92 100644
--- a/common.mk
+++ b/common.mk
@@ -3781,6 +3781,7 @@ debug.$(OBJEXT): $(CCAN_DIR)/str/str.h
 debug.$(OBJEXT): $(hdrdir)/ruby/ruby.h
 debug.$(OBJEXT): $(top_srcdir)/internal/array.h
 debug.$(OBJEXT): $(top_srcdir)/internal/basic_operators.h
+debug.$(OBJEXT): $(top_srcdir)/internal/bits.h
 debug.$(OBJEXT): $(top_srcdir)/internal/class.h
 debug.$(OBJEXT): $(top_srcdir)/internal/compilers.h
 debug.$(OBJEXT): $(top_srcdir)/internal/gc.h
@@ -3788,6 +3789,7 @@ debug.$(OBJEXT): $(top_srcdir)/internal/imemo.h
 debug.$(OBJEXT): $(top_srcdir)/internal/serial.h
 debug.$(OBJEXT): $(top_srcdir)/internal/signal.h
 debug.$(OBJEXT): $(top_srcdir)/internal/static_assert.h
+debug.$(OBJEXT): $(top_srcdir)/internal/time.h
 debug.$(OBJEXT): $(top_srcdir)/internal/variable.h
 debug.$(OBJEXT): $(top_srcdir)/internal/vm.h
 debug.$(OBJEXT): $(top_srcdir)/internal/warnings.h
@@ -3810,6 +3812,7 @@ debug.$(OBJEXT): {$(VPATH)}defines.h
 debug.$(OBJEXT): {$(VPATH)}encindex.h
 debug.$(OBJEXT): {$(VPATH)}encoding.h
 debug.$(OBJEXT): {$(VPATH)}eval_intern.h
+debug.$(OBJEXT): {$(VPATH)}hrtime.h
 debug.$(OBJEXT): {$(VPATH)}id.h
 debug.$(OBJEXT): {$(VPATH)}id_table.h
 debug.$(OBJEXT): {$(VPATH)}intern.h
diff --git a/debug.c b/debug.c
index b5cba590bab5d3..1997993e5f2a23 100644
--- a/debug.c
+++ b/debug.c
@@ -27,6 +27,7 @@
 #include "vm_callinfo.h"
 #include "ruby/thread_native.h"
 #include "ractor_core.h"
+#include "hrtime.h"
 
 /* This is the only place struct RIMemo is actually used */
 struct RIMemo {
@@ -291,7 +292,9 @@ static struct {
     struct debug_log_filter filters[MAX_DEBUG_LOG_FILTER_NUM];
     unsigned int filters_num;
     bool show_pid;
+    bool show_time;
     rb_nativethread_lock_t lock;
+    rb_hrtime_t prev_time;
     FILE *output;
 } debug_log;
 
@@ -411,6 +414,10 @@ setup_debug_log(void)
         if (getenv("RUBY_DEBUG_LOG_PID")) {
             debug_log.show_pid = true;
         }
+        if (getenv("RUBY_DEBUG_LOG_TIME")) {
+            debug_log.show_time = true;
+            debug_log.prev_time = rb_hrtime_now();
+        }
     }
 }
 
@@ -512,6 +519,16 @@ ruby_debug_log(const char *file, int line, const char *func_name, const char *fm
         len += r;
     }
 
+    if (debug_log.show_time) {
+        rb_hrtime_t now = rb_hrtime_now();
+        rb_hrtime_t diff = now > debug_log.prev_time ? now - debug_log.prev_time : 0;
+        debug_log.prev_time = now;
+
+        r = snprintf(buff + len, MAX_DEBUG_LOG_MESSAGE_LEN, "%lu\t", (unsigned long)(diff / 1000L));
+        if (r < 0) rb_bug("ruby_debug_log returns %d\n", r);
+        len += r;
+    }
+
     // message title
     if (func_name && len < MAX_DEBUG_LOG_MESSAGE_LEN) {
         r = snprintf(buff + len, MAX_DEBUG_LOG_MESSAGE_LEN, "%s\t", func_name);