Merge 6b0286df88 into 20cc983314

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 \

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 */

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)

src/prof_stack_range.c

@@ -13,6 +13,9 @@
 #include <string.h>
 #include <unistd.h>
 
+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/<pid>/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/<pid>/maps as [STACK:<tid>]. 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

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

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". */
 	}
 

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

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