Skip to content

Commit

Permalink
RUBY_DEBUG_LOG_TIME to print times
Browse files Browse the repository at this point in the history
`RUBY_DEBUG_LOG=1 RUBY_DEBUG_LOG_TIME=1 ruby ...` will prints
debug logs with current time.
  • Loading branch information
ko1 committed Aug 3, 2023
1 parent 4b6c584 commit 33ac16d
Show file tree
Hide file tree
Showing 2 changed files with 20 additions and 0 deletions.
3 changes: 3 additions & 0 deletions common.mk
Original file line number Diff line number Diff line change
Expand Up @@ -3781,13 +3781,15 @@ 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
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
Expand All @@ -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
Expand Down
17 changes: 17 additions & 0 deletions debug.c
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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;

Expand Down Expand Up @@ -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();
}
}
}

Expand Down Expand Up @@ -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);
Expand Down

0 comments on commit 33ac16d

Please sign in to comment.