diff --git a/Makefile.in b/Makefile.in index fec1397a..6e3424fe 100644 --- a/Makefile.in +++ b/Makefile.in @@ -102,6 +102,7 @@ C_SRCS := $(srcroot)src/jemalloc.c \ $(srcroot)src/hash.c \ $(srcroot)src/hooks.c \ $(srcroot)src/large.c \ + $(srcroot)src/log.c \ $(srcroot)src/malloc_io.c \ $(srcroot)src/mutex.c \ $(srcroot)src/mutex_pool.c \ @@ -171,6 +172,7 @@ TESTS_UNIT := \ $(srcroot)test/unit/junk.c \ $(srcroot)test/unit/junk_alloc.c \ $(srcroot)test/unit/junk_free.c \ + $(srcroot)test/unit/log.c \ $(srcroot)test/unit/mallctl.c \ $(srcroot)test/unit/malloc_io.c \ $(srcroot)test/unit/math.c \ diff --git a/configure.ac b/configure.ac index 1551ded8..02151543 100644 --- a/configure.ac +++ b/configure.ac @@ -1226,6 +1226,21 @@ if test "x$enable_cache_oblivious" = "x1" ; then fi AC_SUBST([enable_cache_oblivious]) +dnl Do not log by default. +AC_ARG_ENABLE([log], + [AS_HELP_STRING([--enable-log], [Support debug logging])], +[if test "x$enable_log" = "xno" ; then + enable_log="0" +else + enable_log="1" +fi +], +[enable_log="0"] +) +if test "x$enable_log" = "x1" ; then + AC_DEFINE([JEMALLOC_LOG], [ ]) +fi +AC_SUBST([enable_log]) JE_COMPILABLE([a program using __builtin_unreachable], [ @@ -2188,6 +2203,7 @@ AC_MSG_RESULT([thp : ${enable_thp}]) AC_MSG_RESULT([fill : ${enable_fill}]) AC_MSG_RESULT([utrace : ${enable_utrace}]) AC_MSG_RESULT([xmalloc : ${enable_xmalloc}]) +AC_MSG_RESULT([log : ${enable_log}]) AC_MSG_RESULT([lazy_lock : ${enable_lazy_lock}]) AC_MSG_RESULT([cache-oblivious : ${enable_cache_oblivious}]) AC_MSG_RESULT([cxx : ${enable_cxx}]) diff --git a/include/jemalloc/internal/jemalloc_internal_defs.h.in b/include/jemalloc/internal/jemalloc_internal_defs.h.in index c0f834f2..b73daf04 100644 --- a/include/jemalloc/internal/jemalloc_internal_defs.h.in +++ b/include/jemalloc/internal/jemalloc_internal_defs.h.in @@ -237,6 +237,12 @@ */ #undef JEMALLOC_CACHE_OBLIVIOUS +/* + * If defined, enable logging facilities. We make this a configure option to + * avoid taking extra branches everywhere. + */ +#undef JEMALLOC_LOG + /* * Darwin (OS X) uses zones to work around Mach-O symbol override shortcomings. */ diff --git a/include/jemalloc/internal/jemalloc_preamble.h.in b/include/jemalloc/internal/jemalloc_preamble.h.in index 18539a09..099f98d8 100644 --- a/include/jemalloc/internal/jemalloc_preamble.h.in +++ b/include/jemalloc/internal/jemalloc_preamble.h.in @@ -146,6 +146,17 @@ static const bool config_cache_oblivious = false #endif ; +/* + * Undocumented, for jemalloc development use only at the moment. See the note + * in jemalloc/internal/log.h. + */ +static const bool config_log = +#ifdef JEMALLOC_LOG + true +#else + false +#endif + ; #ifdef JEMALLOC_HAVE_SCHED_GETCPU /* Currently percpu_arena depends on sched_getcpu. */ #define JEMALLOC_PERCPU_ARENA diff --git a/include/jemalloc/internal/log.h b/include/jemalloc/internal/log.h new file mode 100644 index 00000000..8413a4d6 --- /dev/null +++ b/include/jemalloc/internal/log.h @@ -0,0 +1,89 @@ +#ifndef JEMALLOC_INTERNAL_LOG_H +#define JEMALLOC_INTERNAL_LOG_H + +#include "jemalloc/internal/atomic.h" +#include "jemalloc/internal/mutex.h" + +#ifdef JEMALLOC_LOG +# define JEMALLOC_LOG_BUFSIZE 1000 +#else +# define JEMALLOC_LOG_BUFSIZE 1 +#endif + +/* + * The log_vars malloc_conf option is a '|'-delimited list of log_var name + * segments to log. The log_var names are themselves hierarchical, with '.' as + * the delimiter (a "segment" is just a prefix in the log namespace). So, if + * you have: + * + * static log_var_t log_arena = LOG_VAR_INIT("arena"); // 1 + * static log_var_t log_arena_a = LOG_VAR_INIT("arena.a"); // 2 + * static log_var_t log_arena_b = LOG_VAR_INIT("arena.b"); // 3 + * static log_var_t log_arena_a_a = LOG_VAR_INIT("arena.a.a"); // 4 + * static_log_var_t log_extent_a = LOG_VAR_INIT("extent.a"); // 5 + * static_log_var_t log_extent_b = LOG_VAR_INIT("extent.b"); // 6 + * + * And your malloc_conf option is "log_vars=arena.a|extent", then log_vars 2, 4, + * 5, and 6 will be enabled. You can enable logging from all log vars by + * writing "log_vars=.". + * + * You can then log by writing: + * log(log_var, "format string -- my int is %d", my_int); + * + * None of this should be regarded as a stable API for right now. It's intended + * as a debugging interface, to let us keep around some of our printf-debugging + * statements. + */ + +extern char log_var_names[JEMALLOC_LOG_BUFSIZE]; +extern atomic_b_t log_init_done; + +typedef struct log_var_s log_var_t; +struct log_var_s { + /* + * Lowest bit is "inited", second lowest is "enabled". Putting them in + * a single word lets us avoid any fences on weak architectures. + */ + atomic_u_t state; + const char *name; +}; + +#define LOG_NOT_INITIALIZED 0U +#define LOG_INITIALIZED_NOT_ENABLED 1U +#define LOG_ENABLED 2U + +#define LOG_VAR_INIT(name_str) {ATOMIC_INIT(LOG_NOT_INITIALIZED), name_str} + +/* + * Returns the value we should assume for state (which is not necessarily + * accurate; if logging is done before logging has finished initializing, then + * we default to doing the safe thing by logging everything). + */ +unsigned log_var_update_state(log_var_t *log_var); + +/* We factor out the metadata management to allow us to test more easily. */ +#define log_do_begin(log_var) \ +if (config_log) { \ + unsigned log_state = atomic_load_u(&(log_var).state, \ + ATOMIC_RELAXED); \ + if (unlikely(log_state == LOG_NOT_INITIALIZED)) { \ + log_state = log_var_update_state(&(log_var)); \ + assert(log_state != LOG_NOT_INITIALIZED); \ + } \ + if (log_state == LOG_ENABLED) { \ + { + /* User code executes here. */ +#define log_do_end(log_var) \ + } \ + } \ +} + +#define log(log_var, format, ...) \ +do { \ + log_do_begin(log_var) \ + malloc_printf("%s: " format "\n", \ + (log_var).name, __VA_ARGS__); \ + log_do_end(log_var) \ +} while (0) + +#endif /* JEMALLOC_INTERNAL_LOG_H */ diff --git a/src/jemalloc.c b/src/jemalloc.c index 0ee8ad48..09bac9eb 100644 --- a/src/jemalloc.c +++ b/src/jemalloc.c @@ -8,6 +8,7 @@ #include "jemalloc/internal/extent_dss.h" #include "jemalloc/internal/extent_mmap.h" #include "jemalloc/internal/jemalloc_internal_types.h" +#include "jemalloc/internal/log.h" #include "jemalloc/internal/malloc_io.h" #include "jemalloc/internal/mutex.h" #include "jemalloc/internal/rtree.h" @@ -1173,6 +1174,16 @@ malloc_conf_init(void) { CONF_HANDLE_BOOL(opt_prof_final, "prof_final") CONF_HANDLE_BOOL(opt_prof_leak, "prof_leak") } + if (config_log) { + if (CONF_MATCH("log_vars")) { + size_t cpylen = ( + vlen <= sizeof(log_var_names) ? + vlen : sizeof(log_var_names) - 1); + strncpy(log_var_names, v, cpylen); + log_var_names[cpylen] = '\0'; + continue; + } + } malloc_conf_error("Invalid conf pair", k, klen, v, vlen); #undef CONF_MATCH @@ -1189,6 +1200,7 @@ malloc_conf_init(void) { #undef CONF_HANDLE_CHAR_P } } + atomic_store_b(&log_init_done, true, ATOMIC_RELEASE); } static bool diff --git a/src/log.c b/src/log.c new file mode 100644 index 00000000..022dc584 --- /dev/null +++ b/src/log.c @@ -0,0 +1,78 @@ +#include "jemalloc/internal/jemalloc_preamble.h" +#include "jemalloc/internal/jemalloc_internal_includes.h" + +#include "jemalloc/internal/log.h" + +char log_var_names[JEMALLOC_LOG_BUFSIZE]; +atomic_b_t log_init_done = ATOMIC_INIT(false); + +/* + * Returns true if we were able to pick out a segment. Fills in r_segment_end + * with a pointer to the first character after the end of the string. + */ +static const char * +log_var_extract_segment(const char* segment_begin) { + const char *end; + for (end = segment_begin; *end != '\0' && *end != '|'; end++) { + } + return end; +} + +static bool +log_var_matches_segment(const char *segment_begin, const char *segment_end, + const char *log_var_begin, const char *log_var_end) { + assert(segment_begin <= segment_end); + assert(log_var_begin < log_var_end); + + ptrdiff_t segment_len = segment_end - segment_begin; + ptrdiff_t log_var_len = log_var_end - log_var_begin; + /* The special '.' segment matches everything. */ + if (segment_len == 1 && *segment_begin == '.') { + return true; + } + if (segment_len == log_var_len) { + return strncmp(segment_begin, log_var_begin, segment_len) == 0; + } else if (segment_len < log_var_len) { + return strncmp(segment_begin, log_var_begin, segment_len) == 0 + && log_var_begin[segment_len] == '.'; + } else { + return false; + } +} + +unsigned +log_var_update_state(log_var_t *log_var) { + const char *log_var_begin = log_var->name; + const char *log_var_end = log_var->name + strlen(log_var->name); + + /* Pointer to one before the beginning of the current segment. */ + const char *segment_begin = log_var_names; + + /* + * If log_init done is false, we haven't parsed the malloc conf yet. To + * avoid log-spew, we default to not displaying anything. + */ + if (!atomic_load_b(&log_init_done, ATOMIC_ACQUIRE)) { + return LOG_INITIALIZED_NOT_ENABLED; + } + + while (true) { + const char *segment_end = log_var_extract_segment( + segment_begin); + assert(segment_end < log_var_names + JEMALLOC_LOG_BUFSIZE); + if (log_var_matches_segment(segment_begin, segment_end, + log_var_begin, log_var_end)) { + atomic_store_u(&log_var->state, LOG_ENABLED, + ATOMIC_RELAXED); + return LOG_ENABLED; + } + if (*segment_end == '\0') { + /* Hit the end of the segment string with no match. */ + atomic_store_u(&log_var->state, + LOG_INITIALIZED_NOT_ENABLED, ATOMIC_RELAXED); + return LOG_INITIALIZED_NOT_ENABLED; + } + /* Otherwise, skip the delimiter and continue. */ + segment_begin = segment_end + 1; + } +} diff --git a/test/unit/log.c b/test/unit/log.c new file mode 100644 index 00000000..6db256f1 --- /dev/null +++ b/test/unit/log.c @@ -0,0 +1,182 @@ +#include "test/jemalloc_test.h" + +#include "jemalloc/internal/log.h" + +static void +expect_no_logging(const char *names) { + log_var_t log_l1 = LOG_VAR_INIT("l1"); + log_var_t log_l2 = LOG_VAR_INIT("l2"); + log_var_t log_l2_a = LOG_VAR_INIT("l2.a"); + + strcpy(log_var_names, names); + + int count = 0; + + for (int i = 0; i < 10; i++) { + log_do_begin(log_l1) + count++; + log_do_end(log_l1) + + log_do_begin(log_l2) + count++; + log_do_end(log_l2) + + log_do_begin(log_l2_a) + count++; + log_do_end(log_l2_a) + } + assert_d_eq(count, 0, "Disabled logging not ignored!"); +} + +TEST_BEGIN(test_log_disabled) { + test_skip_if(!config_log); + atomic_store_b(&log_init_done, true, ATOMIC_RELAXED); + expect_no_logging(""); + expect_no_logging("abc"); + expect_no_logging("a.b.c"); + expect_no_logging("l12"); + expect_no_logging("l123|a456|b789"); + expect_no_logging("|||"); +} +TEST_END + +TEST_BEGIN(test_log_enabled_direct) { + test_skip_if(!config_log); + atomic_store_b(&log_init_done, true, ATOMIC_RELAXED); + log_var_t log_l1 = LOG_VAR_INIT("l1"); + log_var_t log_l1_a = LOG_VAR_INIT("l1.a"); + log_var_t log_l2 = LOG_VAR_INIT("l2"); + + int count; + + count = 0; + strcpy(log_var_names, "l1"); + for (int i = 0; i < 10; i++) { + log_do_begin(log_l1) + count++; + log_do_end(log_l1) + } + assert_d_eq(count, 10, "Mis-logged!"); + + count = 0; + strcpy(log_var_names, "l1.a"); + for (int i = 0; i < 10; i++) { + log_do_begin(log_l1_a) + count++; + log_do_end(log_l1_a) + } + assert_d_eq(count, 10, "Mis-logged!"); + + count = 0; + strcpy(log_var_names, "l1.a|abc|l2|def"); + for (int i = 0; i < 10; i++) { + log_do_begin(log_l1_a) + count++; + log_do_end(log_l1_a) + + log_do_begin(log_l2) + count++; + log_do_end(log_l2) + } + assert_d_eq(count, 20, "Mis-logged!"); +} +TEST_END + +TEST_BEGIN(test_log_enabled_indirect) { + test_skip_if(!config_log); + atomic_store_b(&log_init_done, true, ATOMIC_RELAXED); + strcpy(log_var_names, "l0|l1|abc|l2.b|def"); + + /* On. */ + log_var_t log_l1 = LOG_VAR_INIT("l1"); + /* Off. */ + log_var_t log_l1a = LOG_VAR_INIT("l1a"); + /* On. */ + log_var_t log_l1_a = LOG_VAR_INIT("l1.a"); + /* Off. */ + log_var_t log_l2_a = LOG_VAR_INIT("l2.a"); + /* On. */ + log_var_t log_l2_b_a = LOG_VAR_INIT("l2.b.a"); + /* On. */ + log_var_t log_l2_b_b = LOG_VAR_INIT("l2.b.b"); + + /* 4 are on total, so should sum to 40. */ + int count = 0; + for (int i = 0; i < 10; i++) { + log_do_begin(log_l1) + count++; + log_do_end(log_l1) + + log_do_begin(log_l1a) + count++; + log_do_end(log_l1a) + + log_do_begin(log_l1_a) + count++; + log_do_end(log_l1_a) + + log_do_begin(log_l2_a) + count++; + log_do_end(log_l2_a) + + log_do_begin(log_l2_b_a) + count++; + log_do_end(log_l2_b_a) + + log_do_begin(log_l2_b_b) + count++; + log_do_end(log_l2_b_b) + } + + assert_d_eq(count, 40, "Mis-logged!"); +} +TEST_END + +TEST_BEGIN(test_log_enabled_global) { + test_skip_if(!config_log); + atomic_store_b(&log_init_done, true, ATOMIC_RELAXED); + strcpy(log_var_names, "abc|.|def"); + + log_var_t log_l1 = LOG_VAR_INIT("l1"); + log_var_t log_l2_a_a = LOG_VAR_INIT("l2.a.a"); + + int count = 0; + for (int i = 0; i < 10; i++) { + log_do_begin(log_l1) + count++; + log_do_end(log_l1) + + log_do_begin(log_l2_a_a) + count++; + log_do_end(log_l2_a_a) + } + assert_d_eq(count, 20, "Mis-logged!"); +} +TEST_END + +TEST_BEGIN(test_logs_if_no_init) { + test_skip_if(!config_log); + atomic_store_b(&log_init_done, false, ATOMIC_RELAXED); + + log_var_t l = LOG_VAR_INIT("definitely.not.enabled"); + + int count = 0; + for (int i = 0; i < 10; i++) { + log_do_begin(l) + count++; + log_do_end(l) + } + assert_d_eq(count, 0, "Logging shouldn't happen if not initialized."); +} +TEST_END + +int +main(void) { + + return test( + test_log_disabled, + test_log_enabled_direct, + test_log_enabled_indirect, + test_log_enabled_global, + test_logs_if_no_init); +}