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);