diff --git a/Makefile.in b/Makefile.in index 27eb90d3..ff410544 100644 --- a/Makefile.in +++ b/Makefile.in @@ -266,6 +266,7 @@ TESTS_UNIT := \ $(srcroot)test/unit/prof_stats.c \ $(srcroot)test/unit/prof_tctx.c \ $(srcroot)test/unit/prof_thread_name.c \ + $(srcroot)test/unit/prof_sys_backtrace.c \ $(srcroot)test/unit/prof_sys_thread_name.c \ $(srcroot)test/unit/psset.c \ $(srcroot)test/unit/ql.c \ diff --git a/include/jemalloc/internal/prof_stats.h b/include/jemalloc/internal/prof_stats.h index c4d269e5..97e6be85 100644 --- a/include/jemalloc/internal/prof_stats.h +++ b/include/jemalloc/internal/prof_stats.h @@ -17,4 +17,11 @@ void prof_stats_dec(tsd_t *tsd, szind_t ind, size_t size); void prof_stats_get_live(tsd_t *tsd, szind_t ind, prof_stats_t *stats); void prof_stats_get_accum(tsd_t *tsd, szind_t ind, prof_stats_t *stats); +extern atomic_u64_t prof_backtrace_count; +extern atomic_u64_t prof_backtrace_time_ns; +#ifdef JEMALLOC_PROF_FRAME_POINTER +extern atomic_u64_t prof_stack_range_count; +extern atomic_u64_t prof_stack_range_time_ns; +#endif + #endif /* JEMALLOC_INTERNAL_PROF_STATS_H */ diff --git a/src/ctl.c b/src/ctl.c index 66844105..b053f439 100644 --- a/src/ctl.c +++ b/src/ctl.c @@ -351,6 +351,12 @@ CTL_PROTO(stats_resident) CTL_PROTO(stats_mapped) CTL_PROTO(stats_retained) CTL_PROTO(stats_zero_reallocs) +CTL_PROTO(stats_prof_backtrace_count) +CTL_PROTO(stats_prof_backtrace_time_ns) +#ifdef JEMALLOC_PROF_FRAME_POINTER +CTL_PROTO(stats_prof_stack_range_count) +CTL_PROTO(stats_prof_stack_range_time_ns) +#endif CTL_PROTO(experimental_hooks_install) CTL_PROTO(experimental_hooks_remove) CTL_PROTO(experimental_hooks_prof_backtrace) @@ -956,6 +962,12 @@ static const ctl_named_node_t stats_node[] = { {NAME("mutexes"), CHILD(named, stats_mutexes)}, {NAME("arenas"), CHILD(indexed, stats_arenas)}, {NAME("zero_reallocs"), CTL(stats_zero_reallocs)}, + {NAME("prof_backtrace_count"), CTL(stats_prof_backtrace_count)}, + {NAME("prof_backtrace_time_ns"), CTL(stats_prof_backtrace_time_ns)}, +#ifdef JEMALLOC_PROF_FRAME_POINTER + {NAME("prof_stack_range_count"), CTL(stats_prof_stack_range_count)}, + {NAME("prof_stack_range_time_ns"), CTL(stats_prof_stack_range_time_ns)}, +#endif }; static const ctl_named_node_t experimental_hooks_node[] = { @@ -3822,6 +3834,20 @@ CTL_RO_CGEN(config_stats, stats_background_thread_run_interval, CTL_RO_CGEN(config_stats, stats_zero_reallocs, atomic_load_zu(&zero_realloc_count, ATOMIC_RELAXED), size_t) +CTL_RO_CGEN(config_stats, stats_prof_backtrace_count, + atomic_load_u64(&prof_backtrace_count, ATOMIC_RELAXED), uint64_t) + +CTL_RO_CGEN(config_stats, stats_prof_backtrace_time_ns, + atomic_load_u64(&prof_backtrace_time_ns, ATOMIC_RELAXED), uint64_t) + +#ifdef JEMALLOC_PROF_FRAME_POINTER +CTL_RO_CGEN(config_stats, stats_prof_stack_range_count, + atomic_load_u64(&prof_stack_range_count, ATOMIC_RELAXED), uint64_t) + +CTL_RO_CGEN(config_stats, stats_prof_stack_range_time_ns, + atomic_load_u64(&prof_stack_range_time_ns, ATOMIC_RELAXED), uint64_t) +#endif + CTL_RO_GEN(stats_arenas_i_dss, arenas_i(mib[2])->dss, const char *) CTL_RO_GEN(stats_arenas_i_dirty_decay_ms, arenas_i(mib[2])->dirty_decay_ms, ssize_t) diff --git a/src/prof_stack_range.c b/src/prof_stack_range.c index 6a99b56f..d2a8aa41 100644 --- a/src/prof_stack_range.c +++ b/src/prof_stack_range.c @@ -13,6 +13,9 @@ #include #include +atomic_u64_t prof_stack_range_count = ATOMIC_INIT(0); +atomic_u64_t prof_stack_range_time_ns = ATOMIC_INIT(0); + static int prof_mapping_containing_addr( uintptr_t addr, const char* maps_path, @@ -129,10 +132,17 @@ static uintptr_t prof_main_thread_stack_start(const char* stat_path) { uintptr_t prof_thread_stack_start(uintptr_t stack_end) { pid_t pid = getpid(); pid_t tid = gettid(); + + nstime_t ts_begin; + if (config_stats) { + nstime_init_update(&ts_begin); + } + + uintptr_t stack_start = 0; if (pid == tid) { char stat_path[32]; // "/proc//stat" malloc_snprintf(stat_path, sizeof(stat_path), "/proc/%d/stat", pid); - return prof_main_thread_stack_start(stat_path); + stack_start = prof_main_thread_stack_start(stat_path); } else { // NOTE: Prior to kernel 4.5 an entry for every thread stack was included in // /proc//maps as [STACK:]. Starting with kernel 4.5 only the main @@ -145,11 +155,19 @@ uintptr_t prof_thread_stack_start(uintptr_t stack_end) { uintptr_t mm_start, mm_end; if (prof_mapping_containing_addr( - stack_end, maps_path, &mm_start, &mm_end) != 0) { - return 0; + stack_end, maps_path, &mm_start, &mm_end) == 0) { + stack_start = mm_end; } - return mm_end; } + + if (config_stats) { + nstime_t ts_end; + nstime_init_update(&ts_end); + atomic_fetch_add_u64(&prof_stack_range_time_ns, + nstime_ns(&ts_end) - nstime_ns(&ts_begin), ATOMIC_RELAXED); + atomic_fetch_add_u64(&prof_stack_range_count, 1, ATOMIC_RELAXED); + } + return stack_start; } #else diff --git a/src/prof_sys.c b/src/prof_sys.c index f0bc8b4b..773255a5 100644 --- a/src/prof_sys.c +++ b/src/prof_sys.c @@ -23,6 +23,9 @@ #define _Unwind_Backtrace JEMALLOC_TEST_HOOK(_Unwind_Backtrace, test_hooks_libc_hook) #endif +atomic_u64_t prof_backtrace_count = ATOMIC_INIT(0); +atomic_u64_t prof_backtrace_time_ns = ATOMIC_INIT(0); + /******************************************************************************/ malloc_mutex_t prof_dump_filename_mtx; @@ -458,6 +461,11 @@ prof_backtrace_impl(void **vec, unsigned *len, unsigned max_len) { void prof_backtrace(tsd_t *tsd, prof_bt_t *bt) { + nstime_t ts_begin; + if (config_stats) { + nstime_init_update(&ts_begin); + } + cassert(config_prof); prof_backtrace_hook_t prof_backtrace_hook = prof_backtrace_hook_get(); assert(prof_backtrace_hook != NULL); @@ -465,6 +473,14 @@ prof_backtrace(tsd_t *tsd, prof_bt_t *bt) { pre_reentrancy(tsd, NULL); prof_backtrace_hook(bt->vec, &bt->len, opt_prof_bt_max); post_reentrancy(tsd); + + if (config_stats) { + nstime_t ts_end; + nstime_init_update(&ts_end); + atomic_fetch_add_u64(&prof_backtrace_time_ns, + nstime_ns(&ts_end) - nstime_ns(&ts_begin), ATOMIC_RELAXED); + atomic_fetch_add_u64(&prof_backtrace_count, 1, ATOMIC_RELAXED); + } } void diff --git a/src/stats.c b/src/stats.c index b28b9942..89d3fca1 100644 --- a/src/stats.c +++ b/src/stats.c @@ -1763,6 +1763,58 @@ stats_general_print(emitter_t *emitter) { emitter_kv(emitter, "lg_sample", "prof.lg_sample", emitter_type_ssize, &ssv); + uint64_t backtrace_count, backtrace_time_ns; + CTL_GET("stats.prof_backtrace_count", &backtrace_count, uint64_t); + CTL_GET("stats.prof_backtrace_time_ns", &backtrace_time_ns, uint64_t); + uint64_t backtrace_avg_time_ns = backtrace_count > 0 + ? backtrace_time_ns / backtrace_count + : 0; +#ifdef JEMALLOC_PROF_FRAME_POINTER + uint64_t fp_stack_range_count, fp_stack_range_time_ns; + CTL_GET("stats.prof_stack_range_count", &fp_stack_range_count, uint64_t); + CTL_GET("stats.prof_stack_range_time_ns", &fp_stack_range_time_ns, uint64_t); + uint64_t fp_avg_stack_range_time_ns = fp_stack_range_count > 0 + ? fp_stack_range_time_ns / fp_stack_range_count + : 0; +#endif + uint64_t uptime; + CTL_M2_GET("stats.arenas.0.uptime", 0, &uptime, uint64_t); + + emitter_table_printf(emitter, + "Profiling stats:\n" + " Backtrace Count: %" FMTu64 " (%" FMTu64 " / sec)\n" + " Backtrace Time (ns): %" FMTu64 " total (%" FMTu64 " avg)\n", + backtrace_count, rate_per_second(backtrace_count, uptime), + backtrace_time_ns, backtrace_avg_time_ns); +#ifdef JEMALLOC_PROF_FRAME_POINTER + emitter_table_printf(emitter, + " FP Stack Range Count: %" FMTu64 " (%" FMTu64 " / sec)\n" + " FP Stack Range Time (ns): %" FMTu64 " total (%" FMTu64 " avg)\n", + fp_stack_range_count, rate_per_second(fp_stack_range_count, uptime), + fp_stack_range_time_ns, fp_avg_stack_range_time_ns); +#endif + emitter_table_printf(emitter, "\n"); + + emitter_json_object_kv_begin(emitter, "backtrace"); + emitter_json_kv(emitter, "backtrace_count", emitter_type_uint64, + &backtrace_count); + emitter_json_kv(emitter, "backtrace_total_time_ns", + emitter_type_uint64, &backtrace_time_ns); + emitter_json_kv(emitter, "backtrace_avg_time_ns", + emitter_type_uint64, &backtrace_avg_time_ns); + emitter_json_object_end(emitter); /* Close "backtrace". */ + +#ifdef JEMALLOC_PROF_FRAME_POINTER + emitter_json_object_kv_begin(emitter, "backtrace_fp"); + emitter_json_kv(emitter, "stack_range_count", emitter_type_uint64, + &fp_stack_range_count); + emitter_json_kv(emitter, "stack_range_total_time_ns", emitter_type_uint64, + &fp_stack_range_time_ns); + emitter_json_kv(emitter, "stack_range_avg_time_ns", emitter_type_uint64, + &fp_avg_stack_range_time_ns); + emitter_json_object_end(emitter); /* Close "backtrace_fp". */ +#endif + emitter_dict_end(emitter); /* Close "prof". */ } diff --git a/test/unit/prof_sys_backtrace.c b/test/unit/prof_sys_backtrace.c new file mode 100644 index 00000000..3c383094 --- /dev/null +++ b/test/unit/prof_sys_backtrace.c @@ -0,0 +1,53 @@ +#include "test/jemalloc_test.h" + +#include "jemalloc/internal/prof_sys.h" + +TEST_BEGIN(test_prof_backtrace_stats) { + test_skip_if(!config_prof); + test_skip_if(!config_stats); + + uint64_t oldval; + size_t sz = sizeof(oldval); + assert_d_eq(mallctl("stats.prof_backtrace_count", &oldval, &sz, NULL, 0), + 0, "mallctl failed"); + + void *p = malloc(1); + free(p); + + uint64_t newval; + assert_d_eq(mallctl("stats.prof_backtrace_count", &newval, &sz, NULL, 0), + 0, "mallctl failed"); + + assert_u64_eq(newval, oldval + 1, "prof_backtrace_count not incremented"); +} +TEST_END + +TEST_BEGIN(test_prof_stack_range_stats) { +#ifdef __linux__ + test_skip_if(!config_prof); + test_skip_if(!config_prof_frameptr); + test_skip_if(!config_stats); + + uint64_t oldval; + size_t sz = sizeof(oldval); + assert_d_eq(mallctl("stats.prof_stack_range_count", &oldval, &sz, NULL, 0), + 0, "mallctl failed"); + + uintptr_t stack_end = (uintptr_t)__builtin_frame_address(0); + prof_thread_stack_start(stack_end); + + uint64_t newval; + assert_d_eq(mallctl("stats.prof_stack_range_count", &newval, &sz, NULL, 0), + 0, "mallctl failed"); + + assert_u64_eq(newval, oldval + 1, "prof_stack_range_count not incremented"); +#else + test_skip_if(true); +#endif // __linux__ +} +TEST_END + +int +main(void) { + return test(test_prof_backtrace_stats, test_prof_stack_range_stats); +} diff --git a/test/unit/prof_sys_backtrace.sh b/test/unit/prof_sys_backtrace.sh new file mode 100644 index 00000000..1f02a8a8 --- /dev/null +++ b/test/unit/prof_sys_backtrace.sh @@ -0,0 +1,5 @@ +#!/bin/sh + +if [ "x${enable_prof}" = "x1" ] ; then + export MALLOC_CONF="prof:true,prof_active:true,lg_prof_sample:0,prof_sys_thread_name:true" +fi