From b664bd79356d7f6da6f413023f9aef014b85c145 Mon Sep 17 00:00:00 2001 From: Tyler Etzel Date: Thu, 5 Jul 2018 10:56:33 -0700 Subject: [PATCH] Add logging for sampled allocations - prof_opt_log flag starts logging automatically at runtime - prof_log_{start,stop} mallctl for manual control --- include/jemalloc/internal/arena_inlines_b.h | 26 + include/jemalloc/internal/extent_inlines.h | 10 + include/jemalloc/internal/extent_structs.h | 12 +- include/jemalloc/internal/large_externs.h | 3 + include/jemalloc/internal/prof_externs.h | 6 +- include/jemalloc/internal/prof_inlines_b.h | 21 +- include/jemalloc/internal/witness.h | 28 +- src/ctl.c | 44 +- src/jemalloc.c | 1 + src/large.c | 10 + src/prof.c | 565 +++++++++++++++++++- 11 files changed, 702 insertions(+), 24 deletions(-) diff --git a/include/jemalloc/internal/arena_inlines_b.h b/include/jemalloc/internal/arena_inlines_b.h index 2b3915ae..8bf0a817 100644 --- a/include/jemalloc/internal/arena_inlines_b.h +++ b/include/jemalloc/internal/arena_inlines_b.h @@ -78,6 +78,32 @@ arena_prof_tctx_reset(tsdn_t *tsdn, const void *ptr, prof_tctx_t *tctx) { large_prof_tctx_reset(tsdn, extent); } +JEMALLOC_ALWAYS_INLINE nstime_t +arena_prof_alloc_time_get(tsdn_t *tsdn, const void *ptr, + alloc_ctx_t *alloc_ctx) { + cassert(config_prof); + assert(ptr != NULL); + + extent_t *extent = iealloc(tsdn, ptr); + /* + * Unlike arena_prof_prof_tctx_{get, set}, we only call this once we're + * sure we have a sampled allocation. + */ + assert(!extent_slab_get(extent)); + return large_prof_alloc_time_get(extent); +} + +JEMALLOC_ALWAYS_INLINE void +arena_prof_alloc_time_set(tsdn_t *tsdn, const void *ptr, alloc_ctx_t *alloc_ctx, + nstime_t t) { + cassert(config_prof); + assert(ptr != NULL); + + extent_t *extent = iealloc(tsdn, ptr); + assert(!extent_slab_get(extent)); + large_prof_alloc_time_set(extent, t); +} + JEMALLOC_ALWAYS_INLINE void arena_decay_ticks(tsdn_t *tsdn, arena_t *arena, unsigned nticks) { tsd_t *tsd; diff --git a/include/jemalloc/internal/extent_inlines.h b/include/jemalloc/internal/extent_inlines.h index a43d00db..145fa2d6 100644 --- a/include/jemalloc/internal/extent_inlines.h +++ b/include/jemalloc/internal/extent_inlines.h @@ -177,6 +177,11 @@ extent_prof_tctx_get(const extent_t *extent) { ATOMIC_ACQUIRE); } +static inline nstime_t +extent_prof_alloc_time_get(const extent_t *extent) { + return extent->e_alloc_time; +} + static inline void extent_arena_set(extent_t *extent, arena_t *arena) { unsigned arena_ind = (arena != NULL) ? arena_ind_get(arena) : ((1U << @@ -300,6 +305,11 @@ extent_prof_tctx_set(extent_t *extent, prof_tctx_t *tctx) { atomic_store_p(&extent->e_prof_tctx, tctx, ATOMIC_RELEASE); } +static inline void +extent_prof_alloc_time_set(extent_t *extent, nstime_t t) { + nstime_copy(&extent->e_alloc_time, &t); +} + static inline void extent_init(extent_t *extent, arena_t *arena, void *addr, size_t size, bool slab, szind_t szind, size_t sn, extent_state_t state, bool zeroed, diff --git a/include/jemalloc/internal/extent_structs.h b/include/jemalloc/internal/extent_structs.h index 1983097e..d709577e 100644 --- a/include/jemalloc/internal/extent_structs.h +++ b/include/jemalloc/internal/extent_structs.h @@ -161,11 +161,13 @@ struct extent_s { /* Small region slab metadata. */ arena_slab_data_t e_slab_data; - /* - * Profile counters, used for large objects. Points to a - * prof_tctx_t. - */ - atomic_p_t e_prof_tctx; + /* Profiling data, used for large objects. */ + struct { + /* Time when this was allocated. */ + nstime_t e_alloc_time; + /* Points to a prof_tctx_t. */ + atomic_p_t e_prof_tctx; + }; }; }; typedef ql_head(extent_t) extent_list_t; diff --git a/include/jemalloc/internal/large_externs.h b/include/jemalloc/internal/large_externs.h index 88682eac..a05019e8 100644 --- a/include/jemalloc/internal/large_externs.h +++ b/include/jemalloc/internal/large_externs.h @@ -26,4 +26,7 @@ prof_tctx_t *large_prof_tctx_get(tsdn_t *tsdn, const extent_t *extent); void large_prof_tctx_set(tsdn_t *tsdn, extent_t *extent, prof_tctx_t *tctx); void large_prof_tctx_reset(tsdn_t *tsdn, extent_t *extent); +nstime_t large_prof_alloc_time_get(const extent_t *extent); +void large_prof_alloc_time_set(extent_t *extent, nstime_t time); + #endif /* JEMALLOC_INTERNAL_LARGE_EXTERNS_H */ diff --git a/include/jemalloc/internal/prof_externs.h b/include/jemalloc/internal/prof_externs.h index 04348696..74315ce5 100644 --- a/include/jemalloc/internal/prof_externs.h +++ b/include/jemalloc/internal/prof_externs.h @@ -14,6 +14,7 @@ extern bool opt_prof_gdump; /* High-water memory dumping. */ extern bool opt_prof_final; /* Final profile dumping. */ extern bool opt_prof_leak; /* Dump leak summary at exit. */ extern bool opt_prof_accum; /* Report cumulative bytes. */ +extern bool opt_prof_log; /* Turn logging on at boot. */ extern char opt_prof_prefix[ /* Minimize memory bloat for non-prof builds. */ #ifdef JEMALLOC_PROF @@ -45,7 +46,8 @@ extern size_t lg_prof_sample; void prof_alloc_rollback(tsd_t *tsd, prof_tctx_t *tctx, bool updated); void prof_malloc_sample_object(tsdn_t *tsdn, const void *ptr, size_t usize, prof_tctx_t *tctx); -void prof_free_sampled_object(tsd_t *tsd, size_t usize, prof_tctx_t *tctx); +void prof_free_sampled_object(tsd_t *tsd, const void *ptr, size_t usize, + prof_tctx_t *tctx); void bt_init(prof_bt_t *bt, void **vec); void prof_backtrace(prof_bt_t *bt); prof_tctx_t *prof_lookup(tsd_t *tsd, prof_bt_t *bt); @@ -72,6 +74,8 @@ 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); diff --git a/include/jemalloc/internal/prof_inlines_b.h b/include/jemalloc/internal/prof_inlines_b.h index 6ff465ad..5e0b0642 100644 --- a/include/jemalloc/internal/prof_inlines_b.h +++ b/include/jemalloc/internal/prof_inlines_b.h @@ -61,6 +61,23 @@ prof_tctx_reset(tsdn_t *tsdn, const void *ptr, prof_tctx_t *tctx) { arena_prof_tctx_reset(tsdn, ptr, tctx); } +JEMALLOC_ALWAYS_INLINE nstime_t +prof_alloc_time_get(tsdn_t *tsdn, const void *ptr, alloc_ctx_t *alloc_ctx) { + cassert(config_prof); + assert(ptr != NULL); + + return arena_prof_alloc_time_get(tsdn, ptr, alloc_ctx); +} + +JEMALLOC_ALWAYS_INLINE void +prof_alloc_time_set(tsdn_t *tsdn, const void *ptr, alloc_ctx_t *alloc_ctx, + nstime_t t) { + cassert(config_prof); + assert(ptr != NULL); + + arena_prof_alloc_time_set(tsdn, ptr, alloc_ctx, t); +} + JEMALLOC_ALWAYS_INLINE bool prof_sample_accum_update(tsd_t *tsd, size_t usize, bool update, prof_tdata_t **tdata_out) { @@ -187,7 +204,7 @@ prof_realloc(tsd_t *tsd, const void *ptr, size_t usize, prof_tctx_t *tctx, * counters. */ if (unlikely(old_sampled)) { - prof_free_sampled_object(tsd, old_usize, old_tctx); + prof_free_sampled_object(tsd, ptr, old_usize, old_tctx); } } @@ -199,7 +216,7 @@ prof_free(tsd_t *tsd, const void *ptr, size_t usize, alloc_ctx_t *alloc_ctx) { assert(usize == isalloc(tsd_tsdn(tsd), ptr)); if (unlikely((uintptr_t)tctx > (uintptr_t)1U)) { - prof_free_sampled_object(tsd, usize, tctx); + prof_free_sampled_object(tsd, ptr, usize, tctx); } } diff --git a/include/jemalloc/internal/witness.h b/include/jemalloc/internal/witness.h index 80ea70c2..fff9e98c 100644 --- a/include/jemalloc/internal/witness.h +++ b/include/jemalloc/internal/witness.h @@ -27,9 +27,9 @@ #define WITNESS_RANK_PROF_BT2GCTX 6U #define WITNESS_RANK_PROF_TDATAS 7U #define WITNESS_RANK_PROF_TDATA 8U -#define WITNESS_RANK_PROF_GCTX 9U - -#define WITNESS_RANK_BACKGROUND_THREAD 10U +#define WITNESS_RANK_PROF_LOG 9U +#define WITNESS_RANK_PROF_GCTX 10U +#define WITNESS_RANK_BACKGROUND_THREAD 11U /* * Used as an argument to witness_assert_depth_to_rank() in order to validate @@ -37,19 +37,19 @@ * witness_assert_depth_to_rank() is inclusive rather than exclusive, this * definition can have the same value as the minimally ranked core lock. */ -#define WITNESS_RANK_CORE 11U +#define WITNESS_RANK_CORE 12U -#define WITNESS_RANK_DECAY 11U -#define WITNESS_RANK_TCACHE_QL 12U -#define WITNESS_RANK_EXTENT_GROW 13U -#define WITNESS_RANK_EXTENTS 14U -#define WITNESS_RANK_EXTENT_AVAIL 15U +#define WITNESS_RANK_DECAY 12U +#define WITNESS_RANK_TCACHE_QL 13U +#define WITNESS_RANK_EXTENT_GROW 14U +#define WITNESS_RANK_EXTENTS 15U +#define WITNESS_RANK_EXTENT_AVAIL 16U -#define WITNESS_RANK_EXTENT_POOL 16U -#define WITNESS_RANK_RTREE 17U -#define WITNESS_RANK_BASE 18U -#define WITNESS_RANK_ARENA_LARGE 19U -#define WITNESS_RANK_HOOK 20U +#define WITNESS_RANK_EXTENT_POOL 17U +#define WITNESS_RANK_RTREE 18U +#define WITNESS_RANK_BASE 19U +#define WITNESS_RANK_ARENA_LARGE 20U +#define WITNESS_RANK_HOOK 21U #define WITNESS_RANK_LEAF 0xffffffffU #define WITNESS_RANK_BIN WITNESS_RANK_LEAF diff --git a/src/ctl.c b/src/ctl.c index 38529d08..448ec7bf 100644 --- a/src/ctl.c +++ b/src/ctl.c @@ -148,6 +148,8 @@ CTL_PROTO(prof_gdump) CTL_PROTO(prof_reset) CTL_PROTO(prof_interval) CTL_PROTO(lg_prof_sample) +CTL_PROTO(prof_log_start) +CTL_PROTO(prof_log_stop) CTL_PROTO(stats_arenas_i_small_allocated) CTL_PROTO(stats_arenas_i_small_nmalloc) CTL_PROTO(stats_arenas_i_small_ndalloc) @@ -389,7 +391,9 @@ static const ctl_named_node_t prof_node[] = { {NAME("gdump"), CTL(prof_gdump)}, {NAME("reset"), CTL(prof_reset)}, {NAME("interval"), CTL(prof_interval)}, - {NAME("lg_sample"), CTL(lg_prof_sample)} + {NAME("lg_sample"), CTL(lg_prof_sample)}, + {NAME("log_start"), CTL(prof_log_start)}, + {NAME("log_stop"), CTL(prof_log_stop)} }; static const ctl_named_node_t stats_arenas_i_small_node[] = { @@ -2644,6 +2648,44 @@ label_return: CTL_RO_NL_CGEN(config_prof, prof_interval, prof_interval, uint64_t) CTL_RO_NL_CGEN(config_prof, lg_prof_sample, lg_prof_sample, size_t) +static int +prof_log_start_ctl(tsd_t *tsd, const size_t *mib, size_t miblen, void *oldp, + size_t *oldlenp, void *newp, size_t newlen) { + int ret; + + const char *filename = NULL; + + if (!config_prof) { + return ENOENT; + } + + WRITEONLY(); + WRITE(filename, const char *); + + if (prof_log_start(tsd_tsdn(tsd), filename)) { + ret = EFAULT; + goto label_return; + } + + ret = 0; +label_return: + return ret; +} + +static int +prof_log_stop_ctl(tsd_t *tsd, const size_t *mib, size_t miblen, void *oldp, + size_t *oldlenp, void *newp, size_t newlen) { + if (!config_prof) { + return ENOENT; + } + + if (prof_log_stop(tsd_tsdn(tsd))) { + return EFAULT; + } + + return 0; +} + /******************************************************************************/ CTL_RO_CGEN(config_stats, stats_allocated, ctl_stats->allocated, size_t) diff --git a/src/jemalloc.c b/src/jemalloc.c index 85ec9e0b..e8f110f7 100644 --- a/src/jemalloc.c +++ b/src/jemalloc.c @@ -1282,6 +1282,7 @@ malloc_conf_init(sc_data_t *sc_data) { CONF_HANDLE_BOOL(opt_prof_gdump, "prof_gdump") CONF_HANDLE_BOOL(opt_prof_final, "prof_final") CONF_HANDLE_BOOL(opt_prof_leak, "prof_leak") + CONF_HANDLE_BOOL(opt_prof_log, "prof_log") } if (config_log) { if (CONF_MATCH("log")) { diff --git a/src/large.c b/src/large.c index 84073618..8e7a781d 100644 --- a/src/large.c +++ b/src/large.c @@ -383,3 +383,13 @@ void large_prof_tctx_reset(tsdn_t *tsdn, extent_t *extent) { large_prof_tctx_set(tsdn, extent, (prof_tctx_t *)(uintptr_t)1U); } + +nstime_t +large_prof_alloc_time_get(const extent_t *extent) { + return extent_prof_alloc_time_get(extent); +} + +void +large_prof_alloc_time_set(extent_t *extent, nstime_t t) { + extent_prof_alloc_time_set(extent, t); +} diff --git a/src/prof.c b/src/prof.c index 405de4b3..21421c04 100644 --- a/src/prof.c +++ b/src/prof.c @@ -7,6 +7,7 @@ #include "jemalloc/internal/hash.h" #include "jemalloc/internal/malloc_io.h" #include "jemalloc/internal/mutex.h" +#include "jemalloc/internal/emitter.h" /******************************************************************************/ @@ -38,6 +39,7 @@ bool opt_prof_gdump = false; bool opt_prof_final = false; bool opt_prof_leak = false; bool opt_prof_accum = false; +bool opt_prof_log = false; char opt_prof_prefix[ /* Minimize memory bloat for non-prof builds. */ #ifdef JEMALLOC_PROF @@ -70,6 +72,96 @@ uint64_t prof_interval = 0; size_t lg_prof_sample; +typedef enum prof_logging_state_e prof_logging_state_t; +enum prof_logging_state_e { + prof_logging_state_stopped, + prof_logging_state_started, + prof_logging_state_dumping +}; + +/* + * - stopped: log_start never called, or previous log_stop has completed. + * - started: log_start called, log_stop not called yet. Allocations are logged. + * - dumping: log_stop called but not finished; samples are not logged anymore. + */ +prof_logging_state_t prof_logging_state = prof_logging_state_stopped; + +/* Incremented for every log file that is output. */ +static uint64_t log_seq = 0; +static char log_filename[ + /* Minimize memory bloat for non-prof builds. */ +#ifdef JEMALLOC_PROF + PATH_MAX + +#endif + 1]; + +/* Timestamp for most recent call to log_start(). */ +static nstime_t log_start_timestamp = NSTIME_ZERO_INITIALIZER; + +/* Increment these when adding to the log_bt and log_thr linked lists. */ +static size_t log_bt_index = 0; +static size_t log_thr_index = 0; + +/* Linked list node definitions. These are only used in prof.c. */ +typedef struct prof_bt_node_s prof_bt_node_t; + +struct prof_bt_node_s { + prof_bt_node_t *next; + size_t index; + prof_bt_t bt; + /* Variable size backtrace vector pointed to by bt. */ + void *vec[1]; +}; + +typedef struct prof_thr_node_s prof_thr_node_t; + +struct prof_thr_node_s { + prof_thr_node_t *next; + size_t index; + uint64_t thr_uid; + /* Variable size based on thr_name_sz. */ + char name[1]; +}; + +typedef struct prof_alloc_node_s prof_alloc_node_t; + +/* This is output when logging sampled allocations. */ +struct prof_alloc_node_s { + prof_alloc_node_t *next; + /* Indices into an array of thread data. */ + size_t alloc_thr_ind; + size_t free_thr_ind; + + /* Indices into an array of backtraces. */ + size_t alloc_bt_ind; + size_t free_bt_ind; + + uint64_t alloc_time_ns; + uint64_t free_time_ns; + + size_t usize; +}; + +/* + * Created on the first call to prof_log_start and deleted on prof_log_stop. + * These are the backtraces and threads that have already been logged by an + * allocation. + */ +static bool log_tables_initialized = false; +static ckh_t log_bt_node_set; +static ckh_t log_thr_node_set; + +/* Store linked lists for logged data. */ +static prof_bt_node_t *log_bt_first = NULL; +static prof_bt_node_t *log_bt_last = NULL; +static prof_thr_node_t *log_thr_first = NULL; +static prof_thr_node_t *log_thr_last = NULL; +static prof_alloc_node_t *log_alloc_first = NULL; +static prof_alloc_node_t *log_alloc_last = NULL; + +/* Protects the prof_logging_state and any log_{...} variable. */ +static malloc_mutex_t log_mtx; + /* * Table of mutexes that are shared among gctx's. These are leaf locks, so * there is no problem with using them for more than one gctx at the same time. @@ -145,6 +237,12 @@ static void prof_tdata_destroy(tsd_t *tsd, prof_tdata_t *tdata, bool even_if_attached); static char *prof_thread_name_alloc(tsdn_t *tsdn, const char *thread_name); +/* Hashtable functions for log_bt_node_set and log_thr_node_set. */ +static void prof_thr_node_hash(const void *key, size_t r_hash[2]); +static bool prof_thr_node_keycomp(const void *k1, const void *k2); +static void prof_bt_node_hash(const void *key, size_t r_hash[2]); +static bool prof_bt_node_keycomp(const void *k1, const void *k2); + /******************************************************************************/ /* Red-black trees. */ @@ -242,6 +340,12 @@ prof_malloc_sample_object(tsdn_t *tsdn, const void *ptr, size_t usize, prof_tctx_t *tctx) { prof_tctx_set(tsdn, ptr, usize, NULL, tctx); + /* Get the current time and set this in the extent_t. We'll read this + * when free() is called. */ + nstime_t t = NSTIME_ZERO_INITIALIZER; + nstime_update(&t); + prof_alloc_time_set(tsdn, ptr, NULL, t); + malloc_mutex_lock(tsdn, tctx->tdata->lock); tctx->cnts.curobjs++; tctx->cnts.curbytes += usize; @@ -253,14 +357,171 @@ prof_malloc_sample_object(tsdn_t *tsdn, const void *ptr, size_t usize, malloc_mutex_unlock(tsdn, tctx->tdata->lock); } +static size_t +prof_log_bt_index(tsd_t *tsd, prof_bt_t *bt) { + assert(prof_logging_state == prof_logging_state_started); + malloc_mutex_assert_owner(tsd_tsdn(tsd), &log_mtx); + + prof_bt_node_t dummy_node; + dummy_node.bt = *bt; + prof_bt_node_t *node; + + /* See if this backtrace is already cached in the table. */ + if (ckh_search(&log_bt_node_set, (void *)(&dummy_node), + (void **)(&node), NULL)) { + size_t sz = offsetof(prof_bt_node_t, vec) + + (bt->len * sizeof(void *)); + prof_bt_node_t *new_node = (prof_bt_node_t *) + ialloc(tsd, sz, sz_size2index(sz), false, true); + if (log_bt_first == NULL) { + log_bt_first = new_node; + log_bt_last = new_node; + } else { + log_bt_last->next = new_node; + log_bt_last = new_node; + } + + new_node->next = NULL; + new_node->index = log_bt_index; + /* + * Copy the backtrace: bt is inside a tdata or gctx, which + * might die before prof_log_stop is called. + */ + new_node->bt.len = bt->len; + memcpy(new_node->vec, bt->vec, bt->len * sizeof(void *)); + new_node->bt.vec = new_node->vec; + + log_bt_index++; + ckh_insert(tsd, &log_bt_node_set, (void *)new_node, NULL); + return new_node->index; + } else { + return node->index; + } +} +static size_t +prof_log_thr_index(tsd_t *tsd, uint64_t thr_uid, const char *name) { + assert(prof_logging_state == prof_logging_state_started); + malloc_mutex_assert_owner(tsd_tsdn(tsd), &log_mtx); + + prof_thr_node_t dummy_node; + dummy_node.thr_uid = thr_uid; + prof_thr_node_t *node; + + /* See if this thread is already cached in the table. */ + if (ckh_search(&log_thr_node_set, (void *)(&dummy_node), + (void **)(&node), NULL)) { + size_t sz = offsetof(prof_thr_node_t, name) + strlen(name) + 1; + prof_thr_node_t *new_node = (prof_thr_node_t *) + ialloc(tsd, sz, sz_size2index(sz), false, true); + if (log_thr_first == NULL) { + log_thr_first = new_node; + log_thr_last = new_node; + } else { + log_thr_last->next = new_node; + log_thr_last = new_node; + } + + new_node->next = NULL; + new_node->index = log_thr_index; + new_node->thr_uid = thr_uid; + strcpy(new_node->name, name); + + log_thr_index++; + ckh_insert(tsd, &log_thr_node_set, (void *)new_node, NULL); + return new_node->index; + } else { + return node->index; + } +} + +static void +prof_try_log(tsd_t *tsd, const void *ptr, size_t usize, prof_tctx_t *tctx) { + malloc_mutex_assert_owner(tsd_tsdn(tsd), tctx->tdata->lock); + + prof_tdata_t *cons_tdata = prof_tdata_get(tsd, false); + if (cons_tdata == NULL) { + /* + * We decide not to log these allocations. cons_tdata will be + * NULL only when the current thread is in a weird state (e.g. + * it's being destroyed). + */ + return; + } + + malloc_mutex_lock(tsd_tsdn(tsd), &log_mtx); + + if (prof_logging_state != prof_logging_state_started) { + goto label_done; + } + + if (!log_tables_initialized) { + bool err1 = ckh_new(tsd, &log_bt_node_set, PROF_CKH_MINITEMS, + prof_bt_node_hash, prof_bt_node_keycomp); + bool err2 = ckh_new(tsd, &log_thr_node_set, PROF_CKH_MINITEMS, + prof_thr_node_hash, prof_thr_node_keycomp); + if (err1 || err2) { + goto label_done; + } + log_tables_initialized = true; + } + + nstime_t alloc_time = prof_alloc_time_get(tsd_tsdn(tsd), ptr, + (alloc_ctx_t *)NULL); + nstime_t free_time = NSTIME_ZERO_INITIALIZER; + nstime_update(&free_time); + + prof_alloc_node_t *new_node = (prof_alloc_node_t *) + ialloc(tsd, sizeof(prof_alloc_node_t), + sz_size2index(sizeof(prof_alloc_node_t)), false, true); + + const char *prod_thr_name = (tctx->tdata->thread_name == NULL)? + "" : tctx->tdata->thread_name; + const char *cons_thr_name = prof_thread_name_get(tsd); + + prof_bt_t bt; + /* Initialize the backtrace, using the buffer in tdata to store it. */ + bt_init(&bt, cons_tdata->vec); + prof_backtrace(&bt); + prof_bt_t *cons_bt = &bt; + + /* We haven't destroyed tctx yet, so gctx should be good to read. */ + prof_bt_t *prod_bt = &tctx->gctx->bt; + + new_node->next = NULL; + new_node->alloc_thr_ind = prof_log_thr_index(tsd, tctx->tdata->thr_uid, + prod_thr_name); + new_node->free_thr_ind = prof_log_thr_index(tsd, cons_tdata->thr_uid, + cons_thr_name); + new_node->alloc_bt_ind = prof_log_bt_index(tsd, prod_bt); + new_node->free_bt_ind = prof_log_bt_index(tsd, cons_bt); + new_node->alloc_time_ns = nstime_ns(&alloc_time); + new_node->free_time_ns = nstime_ns(&free_time); + new_node->usize = usize; + + if (log_alloc_first == NULL) { + log_alloc_first = new_node; + log_alloc_last = new_node; + } else { + log_alloc_last->next = new_node; + log_alloc_last = new_node; + } + +label_done: + malloc_mutex_unlock(tsd_tsdn(tsd), &log_mtx); +} + void -prof_free_sampled_object(tsd_t *tsd, size_t usize, prof_tctx_t *tctx) { +prof_free_sampled_object(tsd_t *tsd, const void *ptr, size_t usize, + prof_tctx_t *tctx) { malloc_mutex_lock(tsd_tsdn(tsd), tctx->tdata->lock); + assert(tctx->cnts.curobjs > 0); assert(tctx->cnts.curbytes >= usize); tctx->cnts.curobjs--; tctx->cnts.curbytes -= usize; + prof_try_log(tsd, ptr, usize, tctx); + if (prof_tctx_should_destroy(tsd_tsdn(tsd), tctx)) { prof_tctx_destroy(tsd, tctx); } else { @@ -1887,6 +2148,33 @@ prof_bt_keycomp(const void *k1, const void *k2) { return (memcmp(bt1->vec, bt2->vec, bt1->len * sizeof(void *)) == 0); } +static void +prof_bt_node_hash(const void *key, size_t r_hash[2]) { + const prof_bt_node_t *bt_node = (prof_bt_node_t *)key; + prof_bt_hash((void *)(&bt_node->bt), r_hash); +} + +static bool +prof_bt_node_keycomp(const void *k1, const void *k2) { + const prof_bt_node_t *bt_node1 = (prof_bt_node_t *)k1; + const prof_bt_node_t *bt_node2 = (prof_bt_node_t *)k2; + return prof_bt_keycomp((void *)(&bt_node1->bt), + (void *)(&bt_node2->bt)); +} + +static void +prof_thr_node_hash(const void *key, size_t r_hash[2]) { + const prof_thr_node_t *thr_node = (prof_thr_node_t *)key; + hash(&thr_node->thr_uid, sizeof(uint64_t), 0x94122f35U, r_hash); +} + +static bool +prof_thr_node_keycomp(const void *k1, const void *k2) { + const prof_thr_node_t *thr_node1 = (prof_thr_node_t *)k1; + const prof_thr_node_t *thr_node2 = (prof_thr_node_t *)k2; + return thr_node1->thr_uid == thr_node2->thr_uid; +} + static uint64_t prof_thr_uid_alloc(tsdn_t *tsdn) { uint64_t thr_uid; @@ -2119,6 +2407,252 @@ prof_active_set(tsdn_t *tsdn, bool active) { return prof_active_old; } +bool +prof_log_start(tsdn_t *tsdn, const char *filename) { + if (!opt_prof || !prof_booted) { + return true; + } + + bool ret = false; + size_t buf_size = PATH_MAX + 1; + + malloc_mutex_lock(tsdn, &log_mtx); + + if (prof_logging_state != prof_logging_state_stopped) { + ret = true; + } else if (filename == NULL) { + /* Make default name. */ + malloc_snprintf(log_filename, buf_size, "%s.%d.%"FMTu64".json", + opt_prof_prefix, prof_getpid(), log_seq); + log_seq++; + prof_logging_state = prof_logging_state_started; + } else if (strlen(filename) >= buf_size) { + ret = true; + } else { + strcpy(log_filename, filename); + prof_logging_state = prof_logging_state_started; + } + + if (!ret) { + nstime_update(&log_start_timestamp); + } + + malloc_mutex_unlock(tsdn, &log_mtx); + + return ret; +} + +/* Used as an atexit function to stop logging on exit. */ +static void +prof_log_stop_final(void) { + tsd_t *tsd = tsd_fetch(); + prof_log_stop(tsd_tsdn(tsd)); +} + +struct prof_emitter_cb_arg_s { + int fd; + ssize_t ret; +}; + +static void +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); + arg->ret = write(arg->fd, (void *)to_write, bytes); +} + +/* + * prof_log_emit_{...} goes through the appropriate linked list, emitting each + * node to the json and deallocating it. + */ +static void +prof_log_emit_threads(tsd_t *tsd, emitter_t *emitter) { + emitter_json_array_kv_begin(emitter, "threads"); + prof_thr_node_t *thr_node = log_thr_first; + prof_thr_node_t *thr_old_node; + while (thr_node != NULL) { + emitter_json_object_begin(emitter); + + emitter_json_kv(emitter, "thr_uid", emitter_type_uint64, + &thr_node->thr_uid); + + char *thr_name = thr_node->name; + + emitter_json_kv(emitter, "thr_name", emitter_type_string, + &thr_name); + + emitter_json_object_end(emitter); + thr_old_node = thr_node; + thr_node = thr_node->next; + idalloc(tsd, thr_old_node); + } + emitter_json_array_end(emitter); +} + +static void +prof_log_emit_traces(tsd_t *tsd, emitter_t *emitter) { + emitter_json_array_kv_begin(emitter, "stack_traces"); + prof_bt_node_t *bt_node = log_bt_first; + prof_bt_node_t *bt_old_node; + /* + * Calculate how many hex digits we need: twice number of bytes, two for + * "0x", and then one more for terminating '\0'. + */ + char buf[2 * sizeof(intptr_t) + 3]; + size_t buf_sz = sizeof(buf); + while (bt_node != NULL) { + emitter_json_array_begin(emitter); + size_t i; + for (i = 0; i < bt_node->bt.len; i++) { + malloc_snprintf(buf, buf_sz, "%p", bt_node->bt.vec[i]); + char *trace_str = buf; + emitter_json_value(emitter, emitter_type_string, + &trace_str); + } + emitter_json_array_end(emitter); + + bt_old_node = bt_node; + bt_node = bt_node->next; + idalloc(tsd, bt_old_node); + } + emitter_json_array_end(emitter); +} + +static void +prof_log_emit_allocs(tsd_t *tsd, emitter_t *emitter) { + emitter_json_array_kv_begin(emitter, "allocations"); + prof_alloc_node_t *alloc_node = log_alloc_first; + prof_alloc_node_t *alloc_old_node; + while (alloc_node != NULL) { + emitter_json_object_begin(emitter); + + emitter_json_kv(emitter, "alloc_thread", emitter_type_size, + &alloc_node->alloc_thr_ind); + + emitter_json_kv(emitter, "free_thread", emitter_type_size, + &alloc_node->free_thr_ind); + + emitter_json_kv(emitter, "alloc_trace", emitter_type_size, + &alloc_node->alloc_bt_ind); + + emitter_json_kv(emitter, "free_trace", emitter_type_size, + &alloc_node->free_bt_ind); + + emitter_json_kv(emitter, "alloc_timestamp", + emitter_type_uint64, &alloc_node->alloc_time_ns); + + emitter_json_kv(emitter, "free_timestamp", emitter_type_uint64, + &alloc_node->free_time_ns); + + emitter_json_kv(emitter, "usize", emitter_type_uint64, + &alloc_node->usize); + + emitter_json_object_end(emitter); + + alloc_old_node = alloc_node; + alloc_node = alloc_node->next; + idalloc(tsd, alloc_old_node); + } + emitter_json_array_end(emitter); +} + +static void +prof_log_emit_metadata(emitter_t *emitter) { + emitter_json_object_kv_begin(emitter, "info"); + + nstime_t now = NSTIME_ZERO_INITIALIZER; + + nstime_update(&now); + uint64_t ns = nstime_ns(&now) - nstime_ns(&log_start_timestamp); + emitter_json_kv(emitter, "duration", emitter_type_uint64, &ns); + + char *vers = JEMALLOC_VERSION; + emitter_json_kv(emitter, "version", + emitter_type_string, &vers); + + emitter_json_kv(emitter, "lg_sample_rate", + emitter_type_int, &lg_prof_sample); + + int pid = prof_getpid(); + emitter_json_kv(emitter, "pid", emitter_type_int, &pid); + + emitter_json_object_end(emitter); +} + + +bool +prof_log_stop(tsdn_t *tsdn) { + if (!opt_prof || !prof_booted) { + return true; + } + + tsd_t *tsd = tsdn_tsd(tsdn); + malloc_mutex_lock(tsdn, &log_mtx); + + if (prof_logging_state != prof_logging_state_started) { + malloc_mutex_unlock(tsdn, &log_mtx); + return true; + } + + /* + * Set the state to dumping. We'll set it to stopped when we're done. + * Since other threads won't be able to start/stop/log when the state is + * dumping, we don't have to hold the lock during the whole method. + */ + prof_logging_state = prof_logging_state_dumping; + malloc_mutex_unlock(tsdn, &log_mtx); + + + emitter_t emitter; + + /* Create a file. */ + int fd = creat(log_filename, 0644); + + if (fd == -1) { + malloc_printf(": creat() for log file \"%s\" " + " failed with %d\n", log_filename, errno); + if (opt_abort) { + abort(); + } + return true; + } + + /* Emit to json. */ + struct prof_emitter_cb_arg_s arg; + arg.fd = fd; + emitter_init(&emitter, emitter_output_json, &prof_emitter_write_cb, + (void *)(&arg)); + + emitter_json_object_begin(&emitter); + prof_log_emit_metadata(&emitter); + prof_log_emit_threads(tsd, &emitter); + prof_log_emit_traces(tsd, &emitter); + prof_log_emit_allocs(tsd, &emitter); + emitter_json_object_end(&emitter); + + /* Reset global state. */ + if (log_tables_initialized) { + ckh_delete(tsd, &log_bt_node_set); + ckh_delete(tsd, &log_thr_node_set); + } + log_tables_initialized = false; + log_bt_index = 0; + log_thr_index = 0; + log_bt_first = NULL; + log_bt_last = NULL; + log_thr_first = NULL; + log_thr_last = NULL; + log_alloc_first = NULL; + log_alloc_last = NULL; + + malloc_mutex_lock(tsdn, &log_mtx); + prof_logging_state = prof_logging_state_stopped; + malloc_mutex_unlock(tsdn, &log_mtx); + + return close(fd); +} + const char * prof_thread_name_get(tsd_t *tsd) { prof_tdata_t *tdata; @@ -2355,6 +2889,35 @@ prof_boot2(tsd_t *tsd) { } } + if (opt_prof_log) { + prof_log_start(tsd_tsdn(tsd), NULL); + } + + if (atexit(prof_log_stop_final) != 0) { + malloc_write(": Error in atexit() " + "for logging\n"); + if (opt_abort) { + abort(); + } + } + + if (malloc_mutex_init(&log_mtx, "prof_log", + WITNESS_RANK_PROF_LOG, malloc_mutex_rank_exclusive)) { + return true; + } + + if (ckh_new(tsd, &log_bt_node_set, PROF_CKH_MINITEMS, + prof_bt_node_hash, prof_bt_node_keycomp)) { + return true; + } + + if (ckh_new(tsd, &log_thr_node_set, PROF_CKH_MINITEMS, + prof_thr_node_hash, prof_thr_node_keycomp)) { + return true; + } + + log_tables_initialized = true; + gctx_locks = (malloc_mutex_t *)base_alloc(tsd_tsdn(tsd), b0get(), PROF_NCTX_LOCKS * sizeof(malloc_mutex_t), CACHELINE);