Add unit tests for logging

This commit is contained in:
Tyler Etzel 2018-07-03 11:10:09 -07:00 committed by David Goldblatt
parent b664bd7935
commit 5e23f96dd4
5 changed files with 284 additions and 3 deletions

View File

@ -194,6 +194,7 @@ TESTS_UNIT := \
$(srcroot)test/unit/prof_active.c \ $(srcroot)test/unit/prof_active.c \
$(srcroot)test/unit/prof_gdump.c \ $(srcroot)test/unit/prof_gdump.c \
$(srcroot)test/unit/prof_idump.c \ $(srcroot)test/unit/prof_idump.c \
$(srcroot)test/unit/prof_log.c \
$(srcroot)test/unit/prof_reset.c \ $(srcroot)test/unit/prof_reset.c \
$(srcroot)test/unit/prof_tctx.c \ $(srcroot)test/unit/prof_tctx.c \
$(srcroot)test/unit/prof_thread_name.c \ $(srcroot)test/unit/prof_thread_name.c \

View File

@ -74,8 +74,6 @@ void prof_reset(tsd_t *tsd, size_t lg_sample);
void prof_tdata_cleanup(tsd_t *tsd); void prof_tdata_cleanup(tsd_t *tsd);
bool prof_active_get(tsdn_t *tsdn); bool prof_active_get(tsdn_t *tsdn);
bool prof_active_set(tsdn_t *tsdn, bool active); 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); const char *prof_thread_name_get(tsd_t *tsd);
int prof_thread_name_set(tsd_t *tsd, const char *thread_name); int prof_thread_name_set(tsd_t *tsd, const char *thread_name);
bool prof_thread_active_get(tsd_t *tsd); 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_postfork_child(tsdn_t *tsdn);
void prof_sample_threshold_update(prof_tdata_t *tdata); 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 */ #endif /* JEMALLOC_INTERNAL_PROF_EXTERNS_H */

View File

@ -86,6 +86,10 @@ enum prof_logging_state_e {
*/ */
prof_logging_state_t prof_logging_state = prof_logging_state_stopped; 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. */ /* Incremented for every log file that is output. */
static uint64_t log_seq = 0; static uint64_t log_seq = 0;
static char log_filename[ static char log_filename[
@ -2407,6 +2411,102 @@ prof_active_set(tsdn_t *tsdn, bool active) {
return prof_active_old; 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 bool
prof_log_start(tsdn_t *tsdn, const char *filename) { prof_log_start(tsdn_t *tsdn, const char *filename) {
if (!opt_prof || !prof_booted) { 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 *arg =
(struct prof_emitter_cb_arg_s *)opaque; (struct prof_emitter_cb_arg_s *)opaque;
size_t bytes = strlen(to_write); size_t bytes = strlen(to_write);
#ifdef JEMALLOC_JET
if (prof_log_dummy) {
return;
}
#endif
arg->ret = write(arg->fd, (void *)to_write, bytes); arg->ret = write(arg->fd, (void *)to_write, bytes);
} }
@ -2607,7 +2712,17 @@ prof_log_stop(tsdn_t *tsdn) {
emitter_t emitter; emitter_t emitter;
/* Create a file. */ /* 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) { if (fd == -1) {
malloc_printf("<jemalloc>: creat() for log file \"%s\" " 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; prof_logging_state = prof_logging_state_stopped;
malloc_mutex_unlock(tsdn, &log_mtx); malloc_mutex_unlock(tsdn, &log_mtx);
#ifdef JEMALLOC_JET
if (prof_log_dummy) {
return false;
}
#endif
return close(fd); return close(fd);
} }

146
test/unit/prof_log.c Normal file
View File

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

5
test/unit/prof_log.sh Normal file
View File

@ -0,0 +1,5 @@
#!/bin/sh
if [ "x${enable_prof}" = "x1" ] ; then
export MALLOC_CONF="prof:true,lg_prof_sample:0"
fi