From 8655c2e69041cc812d30c2e951a8ac9ea7a60c47 Mon Sep 17 00:00:00 2001 From: Koichi Sasada Date: Fri, 3 Jul 2020 16:55:54 +0900 Subject: RUBY_DEBUG_LOG: Logging debug information mechanism (#3279) * RUBY_DEBUG_LOG: Logging debug information mechanism This feature provides a mechanism to store logging information to a file, stderr or memory space with simple macros. The following information will be stored. * (1) __FILE__, __LINE__ in C * (2) __FILE__, __LINE__ in Ruby * (3) __func__ in C (message title) * (4) given string with sprintf format * (5) Thread number (if multiple threads are running) This feature is enabled only USE_RUBY_DEBUG_LOG is enabled. Release version should not enable it. Running with the `RUBY_DEBUG_LOG` environment variable enables this feature. # logging into a file RUBY_DEBUG_LOG=/path/to/file STDERR # logging into STDERR RUBY_DEBUG_LOG=stderr # logging into memory space (check with a debugger) # It will help if the timing is important. RUBY_DEBUG_LOG=mem RUBY_DEBUG_LOG_FILTER environment variable can specify the fileter string. If "(3) __func__ in C (message title)" contains the specified string, the infomation will be stored (example: RUBY_DEBUG_LOG_FILTER=str will enable only on str related information). In a MRI source code, you can use the following macros: * RUBY_DEBUG_LOG(fmt, ...): Above (1) to (4) will be logged. * RUBY_DEBUG_LOG2(file, line, fmt, ...): Same as RUBY_DEBUG_LOG(), but (1) will be replaced with given file, line. --- .github/workflows/compilers.yml | 1 + debug.c | 231 ++++++++++++++++++++++++++++++++++++++++ vm_debug.h | 73 +++++++++++++ 3 files changed, 305 insertions(+) diff --git a/.github/workflows/compilers.yml b/.github/workflows/compilers.yml index 6925477aaf..5e58de225f 100644 --- a/.github/workflows/compilers.yml +++ b/.github/workflows/compilers.yml @@ -116,6 +116,7 @@ jobs: - { key: cppflags, name: USE_SYMBOL_GC=0, value: '-DUSE_SYMBOL_GC=0' } - { key: cppflags, name: USE_THREAD_CACHE=0, value: '-DUSE_THREAD_CACHE=0' } - { key: cppflags, name: USE_TRANSIENT_HEAP=0, value: '-DUSE_TRANSIENT_HEAP=0' } + - { key: cppflags, name: USE_RUBY_DEBUG_LOG=1, value: '-DUSE_RUBY_DEBUG_LOG=1' } - { key: cppflags, name: DEBUG_FIND_TIME_NUMGESS, value: '-DDEBUG_FIND_TIME_NUMGESS' } - { key: cppflags, name: DEBUG_INTEGER_PACK, value: '-DDEBUG_INTEGER_PACK' } diff --git a/debug.c b/debug.c index 88b5805ee2..7241d37b4d 100644 --- a/debug.c +++ b/debug.c @@ -25,6 +25,7 @@ #include "vm_core.h" #include "vm_debug.h" #include "vm_callinfo.h" +#include "ruby/thread_native.h" /* This is the only place struct RIMemo is actually used */ struct RIMemo { @@ -243,8 +244,238 @@ set_debug_option(const char *str, int len, void *arg) } } +STATIC_ASSERT(USE_RUBY_DEBUG_LOG, USE_RUBY_DEBUG_LOG ? RUBY_DEVEL : 1); + +#if RUBY_DEVEL +static void setup_debug_log(void); +#else +#define setup_debug_log() +#endif + void ruby_set_debug_option(const char *str) { ruby_each_words(str, set_debug_option, 0); + setup_debug_log(); +} + +#if RUBY_DEVEL + +// RUBY_DEBUG_LOG features +// See vm_debug.h comments for details. + +#define MAX_DEBUG_LOG 0x1000 +#define MAX_DEBUG_LOG_MESSAGE_LEN 0x0200 +#define MAX_DEBUG_LOG_FILTER 0x0001 + +enum ruby_debug_log_mode ruby_debug_log_mode; + +static struct { + char *mem; + unsigned int cnt; + const char *filters[MAX_DEBUG_LOG_FILTER]; + unsigned int filters_num; + rb_nativethread_lock_t lock; + FILE *output; +} debug_log; + +static char * +RUBY_DEBUG_LOG_MEM_ENTRY(unsigned int index) +{ + return &debug_log.mem[MAX_DEBUG_LOG_MESSAGE_LEN * index]; +} + +static void +setup_debug_log(void) +{ + // check RUBY_DEBUG_LOG + const char *log_config = getenv("RUBY_DEBUG_LOG"); + if (log_config) { + fprintf(stderr, "RUBY_DEBUG_LOG=%s\n", log_config); + if (strcmp(log_config, "mem") == 0) { + debug_log.mem = (char *)malloc(MAX_DEBUG_LOG * MAX_DEBUG_LOG_MESSAGE_LEN); + if (debug_log.mem == NULL) { + fprintf(stderr, "setup_debug_log failed (can't allocate memory)\n"); + exit(1); + } + ruby_debug_log_mode |= ruby_debug_log_memory; + } + else if (strcmp(log_config, "stderr") == 0) { + ruby_debug_log_mode |= ruby_debug_log_stderr; + } + else { + ruby_debug_log_mode |= ruby_debug_log_file; + if ((debug_log.output = fopen(log_config, "w")) == NULL) { + fprintf(stderr, "can not open %s for RUBY_DEBUG_LOG\n", log_config); + exit(1); + } + setvbuf(debug_log.output, NULL, _IONBF, 0); + } + + rb_nativethread_lock_initialize(&debug_log.lock); + } + + // check RUBY_DEBUG_LOG_FILTER + const char *filter_config = getenv("RUBY_DEBUG_LOG_FILTER"); + if (filter_config) { + fprintf(stderr, "RUBY_DEBUG_LOG_FILTER=%s\n", filter_config); + + // TODO: multiple filters + debug_log.filters[0] = filter_config; + debug_log.filters_num = 1; + } +} + +static const char * +pretty_filename(const char *path) +{ + // basename is one idea. + const char *s; + while ((s = strchr(path, '/')) != NULL) { + path = s+1; + } + return path; +} + +void +ruby_debug_log(const char *file, int line, const char *func_name, const char *fmt, ...) +{ + char buff[MAX_DEBUG_LOG_MESSAGE_LEN] = {0}; + int len = 0; + int r; + + // message title + if (func_name && len < MAX_DEBUG_LOG_MESSAGE_LEN) { + // filter on func_name + if (debug_log.filters_num > 0) { + int hit = 0; + for (unsigned int i = 0; iractor.cnt > 1) { + rb_ractor_t *cr = GET_RACTOR(); + if (r && len < MAX_DEBUG_LOG_MESSAGE_LEN) { + r = snprintf(buff + len, MAX_DEBUG_LOG_MESSAGE_LEN - len, "\tr:#%u/%u", + (unsigned int)rb_ractor_id(cr), GET_VM()->ractor.cnt); + if (r < 0) rb_bug("ruby_debug_log returns %d\n", r); + len += r; + } + } +#endif + + // thread information + if (!rb_thread_alone()) { + const rb_thread_t *th = GET_THREAD(); + if (r && len < MAX_DEBUG_LOG_MESSAGE_LEN) { + r = snprintf(buff + len, MAX_DEBUG_LOG_MESSAGE_LEN - len, "\tth:%p", (void *)th); + if (r < 0) rb_bug("ruby_debug_log returns %d\n", r); + len += r; + } + } + + rb_nativethread_lock_lock(&debug_log.lock); + { + unsigned int cnt = debug_log.cnt++; + + if (ruby_debug_log_mode & ruby_debug_log_memory) { + unsigned int index = cnt % MAX_DEBUG_LOG; + char *dst = RUBY_DEBUG_LOG_MEM_ENTRY(index); + strncpy(dst, buff, MAX_DEBUG_LOG_MESSAGE_LEN); + } + if (ruby_debug_log_mode & ruby_debug_log_stderr) { + fprintf(stderr, "%4u: %s\n", cnt, buff); + } + if (ruby_debug_log_mode & ruby_debug_log_file) { + fprintf(debug_log.output, "%u\t%s\n", cnt, buff); + } + } + rb_nativethread_lock_unlock(&debug_log.lock); +} + +// for debugger +static void +debug_log_dump(FILE *out, unsigned int n) +{ + if (ruby_debug_log_mode & ruby_debug_log_memory) { + unsigned int size = debug_log.cnt > MAX_DEBUG_LOG ? MAX_DEBUG_LOG : debug_log.cnt; + unsigned int current_index = debug_log.cnt % MAX_DEBUG_LOG; + if (n == 0) n = size; + if (n > size) n = size; + + for (unsigned int i=0; i