Add a logging facility.

This sets up a hierarchical logging facility, so that we can add logging
statements liberally, and turn them on in a fine-grained manner.

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 \

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}])

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.
  */

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

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 */

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

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;
+	}
+}

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