From 5e23f96dd4e4ff2847a85d44a01b66e4ed2da21f Mon Sep 17 00:00:00 2001 From: Tyler Etzel Date: Tue, 3 Jul 2018 11:10:09 -0700 Subject: [PATCH] Add unit tests for logging --- Makefile.in | 1 + include/jemalloc/internal/prof_externs.h | 13 +- src/prof.c | 122 ++++++++++++++++++- test/unit/prof_log.c | 146 +++++++++++++++++++++++ test/unit/prof_log.sh | 5 + 5 files changed, 284 insertions(+), 3 deletions(-) create mode 100644 test/unit/prof_log.c create mode 100644 test/unit/prof_log.sh 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(": 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