Add unit tests for logging

5 files changed, 284 insertions, 3 deletions

diff --git a/Makefile.in b/Makefile.in
index 8b2f5ca6..49585ed9 100644
--- a/Makefile.in
+++ b/Makefile.in
@@ -194,6 +194,7 @@ TESTS_UNIT := \
 	$(srcroot)test/unit/prof_active.c \
 	$(srcroot)test/unit/prof_gdump.c \
 	$(srcroot)test/unit/prof_idump.c \
+	$(srcroot)test/unit/prof_log.c \
 	$(srcroot)test/unit/prof_reset.c \
 	$(srcroot)test/unit/prof_tctx.c \
 	$(srcroot)test/unit/prof_thread_name.c \
diff --git a/include/jemalloc/internal/prof_externs.h b/include/jemalloc/internal/prof_externs.h
index 74315ce5..094f3e17 100644
--- a/include/jemalloc/internal/prof_externs.h
+++ b/include/jemalloc/internal/prof_externs.h
@@ -74,8 +74,6 @@ void prof_reset(tsd_t *tsd, size_t lg_sample);
 void prof_tdata_cleanup(tsd_t *tsd);
 bool prof_active_get(tsdn_t *tsdn);
 bool prof_active_set(tsdn_t *tsdn, bool active);
-bool prof_log_start(tsdn_t *tsdn, const char *filename);
-bool prof_log_stop(tsdn_t *tsdn);
 const char *prof_thread_name_get(tsd_t *tsd);
 int prof_thread_name_set(tsd_t *tsd, const char *thread_name);
 bool prof_thread_active_get(tsd_t *tsd);
@@ -93,4 +91,15 @@ void prof_postfork_parent(tsdn_t *tsdn);
 void prof_postfork_child(tsdn_t *tsdn);
 void prof_sample_threshold_update(prof_tdata_t *tdata);
 
+bool prof_log_start(tsdn_t *tsdn, const char *filename);
+bool prof_log_stop(tsdn_t *tsdn);
+#ifdef JEMALLOC_JET
+size_t prof_log_bt_count(void);
+size_t prof_log_alloc_count(void);
+size_t prof_log_thr_count(void);
+bool prof_log_is_logging(void);
+bool prof_log_rep_check(void);
+void prof_log_dummy_set(bool new_value);
+#endif
+
 #endif /* JEMALLOC_INTERNAL_PROF_EXTERNS_H */
diff --git a/src/prof.c b/src/prof.c
index 21421c04..458c6cd0 100644
--- a/src/prof.c
+++ b/src/prof.c
@@ -86,6 +86,10 @@ enum prof_logging_state_e {
  */
 prof_logging_state_t prof_logging_state = prof_logging_state_stopped;
 
+#ifdef JEMALLOC_JET
+static bool prof_log_dummy = false;
+#endif
+
 /* Incremented for every log file that is output. */
 static uint64_t log_seq = 0;
 static char log_filename[
@@ -2407,6 +2411,102 @@ prof_active_set(tsdn_t *tsdn, bool active) {
 	return prof_active_old;
 }
 
+#ifdef JEMALLOC_JET
+size_t
+prof_log_bt_count(void) {
+	size_t cnt = 0;
+	prof_bt_node_t *node = log_bt_first;
+	while (node != NULL) {
+		cnt++;
+		node = node->next;
+	}
+	return cnt;
+}
+
+size_t
+prof_log_alloc_count(void) {
+	size_t cnt = 0;
+	prof_alloc_node_t *node = log_alloc_first;
+	while (node != NULL) {
+		cnt++;
+		node = node->next;
+	}
+	return cnt;
+}
+
+size_t
+prof_log_thr_count(void) {
+	size_t cnt = 0;
+	prof_thr_node_t *node = log_thr_first;
+	while (node != NULL) {
+		cnt++;
+		node = node->next;
+	}
+	return cnt;
+}
+
+bool
+prof_log_is_logging(void) {
+	return prof_logging_state == prof_logging_state_started;
+}
+
+bool
+prof_log_rep_check(void) {
+	if (prof_logging_state == prof_logging_state_stopped
+	    && log_tables_initialized) {
+		return true;
+	}
+
+	if (log_bt_last != NULL && log_bt_last->next != NULL) {
+		return true;
+	}
+	if (log_thr_last != NULL && log_thr_last->next != NULL) {
+		return true;
+	}
+	if (log_alloc_last != NULL && log_alloc_last->next != NULL) {
+		return true;
+	}
+
+	size_t bt_count = prof_log_bt_count();
+	size_t thr_count = prof_log_thr_count();
+	size_t alloc_count = prof_log_alloc_count();
+
+
+	if (prof_logging_state == prof_logging_state_stopped) {
+		if (bt_count != 0 || thr_count != 0 || alloc_count || 0) {
+			return true;
+		}
+	}
+
+	prof_alloc_node_t *node = log_alloc_first;
+	while (node != NULL) {
+		if (node->alloc_bt_ind >= bt_count) {
+			return true;
+		}
+		if (node->free_bt_ind >= bt_count) {
+			return true;
+		}
+		if (node->alloc_thr_ind >= thr_count) {
+			return true;
+		}
+		if (node->free_thr_ind >= thr_count) {
+			return true;
+		}
+		if (node->alloc_time_ns > node->free_time_ns) {
+			return true;
+		}
+		node = node->next;
+	}
+
+	return false;
+}
+
+void
+prof_log_dummy_set(bool new_value) {
+	prof_log_dummy = new_value;
+}
+#endif
+
 bool
 prof_log_start(tsdn_t *tsdn, const char *filename) {
 	if (!opt_prof || !prof_booted) {
@@ -2459,6 +2559,11 @@ prof_emitter_write_cb(void *opaque, const char *to_write) {
 	struct prof_emitter_cb_arg_s *arg =
 	    (struct prof_emitter_cb_arg_s *)opaque;
 	size_t bytes = strlen(to_write);
+#ifdef JEMALLOC_JET
+	if (prof_log_dummy) {
+		return;
+	}
+#endif
 	arg->ret = write(arg->fd, (void *)to_write, bytes);
 }
 
@@ -2607,7 +2712,17 @@ prof_log_stop(tsdn_t *tsdn) {
 	emitter_t emitter;
 
 	/* Create a file. */
-	int fd = creat(log_filename, 0644);
+
+	int fd;
+#ifdef JEMALLOC_JET
+	if (prof_log_dummy) {
+		fd = 0;
+	} else {
+		fd = creat(log_filename, 0644);
+	}
+#else
+	fd = creat(log_filename, 0644);
+#endif
 
 	if (fd == -1) {
 		malloc_printf("<jemalloc>: creat() for log file \"%s\" "
@@ -2650,6 +2765,11 @@ prof_log_stop(tsdn_t *tsdn) {
 	prof_logging_state = prof_logging_state_stopped;
 	malloc_mutex_unlock(tsdn, &log_mtx);
 
+#ifdef JEMALLOC_JET
+	if (prof_log_dummy) {
+		return false;
+	}
+#endif
 	return close(fd);
 }
 
diff --git a/test/unit/prof_log.c b/test/unit/prof_log.c
new file mode 100644
index 00000000..6a3464b4
--- /dev/null
+++ b/test/unit/prof_log.c
@@ -0,0 +1,146 @@
+#include "test/jemalloc_test.h"
+
+#define N_PARAM 100
+#define N_THREADS 10
+
+static void assert_rep() {
+	assert_b_eq(prof_log_rep_check(), false, "Rep check failed");
+}
+
+static void assert_log_empty() {
+	assert_zu_eq(prof_log_bt_count(), 0,
+	    "The log has backtraces; it isn't empty");
+	assert_zu_eq(prof_log_thr_count(), 0,
+	    "The log has threads; it isn't empty");
+	assert_zu_eq(prof_log_alloc_count(), 0,
+	    "The log has allocations; it isn't empty");
+}
+
+void *buf[N_PARAM];
+
+static void f() {
+	int i;
+	for (i = 0; i < N_PARAM; i++) {
+		buf[i] = malloc(100);
+	}
+	for (i = 0; i < N_PARAM; i++) {
+		free(buf[i]);
+	}
+}
+
+TEST_BEGIN(test_prof_log_many_logs) {
+	int i;
+
+	test_skip_if(!config_prof);
+
+	for (i = 0; i < N_PARAM; i++) {
+		assert_b_eq(prof_log_is_logging(), false,
+		    "Logging shouldn't have started yet");
+		assert_d_eq(mallctl("prof.log_start", NULL, NULL, NULL, 0), 0,
+		    "Unexpected mallctl failure when starting logging");
+		assert_b_eq(prof_log_is_logging(), true,
+		    "Logging should be started by now");
+		assert_log_empty();
+		assert_rep();
+		f();
+		assert_zu_eq(prof_log_thr_count(), 1, "Wrong thread count");
+		assert_rep();
+		assert_b_eq(prof_log_is_logging(), true,
+		    "Logging should still be on");
+		assert_d_eq(mallctl("prof.log_stop", NULL, NULL, NULL, 0), 0,
+		    "Unexpected mallctl failure when stopping logging");
+		assert_b_eq(prof_log_is_logging(), false,
+		    "Logging should have turned off");
+	}
+}
+TEST_END
+
+thd_t thr_buf[N_THREADS];
+
+static void *f_thread(void *unused) {
+	int i;
+	for (i = 0; i < N_PARAM; i++) {
+		void *p = malloc(100);
+		memset(p, 100, sizeof(char));
+		free(p);
+	}
+
+	return NULL;
+}
+
+TEST_BEGIN(test_prof_log_many_threads) {
+
+	test_skip_if(!config_prof);
+
+	int i;
+	assert_d_eq(mallctl("prof.log_start", NULL, NULL, NULL, 0), 0,
+	    "Unexpected mallctl failure when starting logging");
+	for (i = 0; i < N_THREADS; i++) {
+		thd_create(&thr_buf[i], &f_thread, NULL);
+	}
+
+	for (i = 0; i < N_THREADS; i++) {
+		thd_join(thr_buf[i], NULL);
+	}
+	assert_zu_eq(prof_log_thr_count(), N_THREADS,
+	    "Wrong number of thread entries");
+	assert_rep();
+	assert_d_eq(mallctl("prof.log_stop", NULL, NULL, NULL, 0), 0,
+	    "Unexpected mallctl failure when stopping logging");
+}
+TEST_END
+
+static void f3() {
+	void *p = malloc(100);
+	free(p);
+}
+
+static void f1() {
+	void *p = malloc(100);
+	f3();
+	free(p);
+}
+
+static void f2() {
+	void *p = malloc(100);
+	free(p);
+}
+
+TEST_BEGIN(test_prof_log_many_traces) {
+
+	test_skip_if(!config_prof);
+
+	assert_d_eq(mallctl("prof.log_start", NULL, NULL, NULL, 0), 0,
+	    "Unexpected mallctl failure when starting logging");
+	int i;
+	assert_rep();
+	assert_log_empty();
+	for (i = 0; i < N_PARAM; i++) {
+		assert_rep();
+		f1();
+		assert_rep();
+		f2();
+		assert_rep();
+		f3();
+		assert_rep();
+	}
+	/*
+	 * There should be 8 total backtraces: two for malloc/free in f1(),
+	 * two for malloc/free in f2(), two for malloc/free in f3(), and then
+	 * two for malloc/free in f1()'s call to f3().
+	 */
+	assert_zu_eq(prof_log_bt_count(), 8,
+	    "Wrong number of backtraces given sample workload");
+	assert_d_eq(mallctl("prof.log_stop", NULL, NULL, NULL, 0), 0,
+	    "Unexpected mallctl failure when stopping logging");
+}
+TEST_END
+
+int
+main(void) {
+	prof_log_dummy_set(true);
+	return test_no_reentrancy(
+	    test_prof_log_many_logs,
+	    test_prof_log_many_traces,
+	    test_prof_log_many_threads);
+}
diff --git a/test/unit/prof_log.sh b/test/unit/prof_log.sh
new file mode 100644
index 00000000..8fcc7d8a
--- /dev/null
+++ b/test/unit/prof_log.sh
@@ -0,0 +1,5 @@
+#!/bin/sh
+
+if [ "x${enable_prof}" = "x1" ] ; then
+  export MALLOC_CONF="prof:true,lg_prof_sample:0"
+fi