High Resolution Timestamps for Profiling

This commit is contained in:
Jon Haslam 2020-06-02 06:42:44 -07:00 committed by David Goldblatt
parent d82a164d0d
commit 4aea743279
13 changed files with 123 additions and 39 deletions

View File

@ -1776,6 +1776,18 @@ if test "x${je_cv_mach_absolute_time}" = "xyes" ; then
AC_DEFINE([JEMALLOC_HAVE_MACH_ABSOLUTE_TIME]) AC_DEFINE([JEMALLOC_HAVE_MACH_ABSOLUTE_TIME])
fi fi
dnl check for CLOCK_REALTIME (always should be available on Linux)
JE_COMPILABLE([clock_gettime(CLOCK_REALTIME, ...)], [
#include <time.h>
], [
struct timespec ts;
clock_gettime(CLOCK_REALTIME, &ts);
], [je_cv_clock_realtime])
if test "x${je_cv_clock_realtime}" = "xyes" ; then
AC_DEFINE([JEMALLOC_HAVE_CLOCK_REALTIME])
fi
dnl Use syscall(2) (if available) by default. dnl Use syscall(2) (if available) by default.
AC_ARG_ENABLE([syscall], AC_ARG_ENABLE([syscall],
[AS_HELP_STRING([--disable-syscall], [Disable use of syscall(2)])], [AS_HELP_STRING([--disable-syscall], [Disable use of syscall(2)])],

View File

@ -100,6 +100,11 @@
*/ */
#undef JEMALLOC_HAVE_MACH_ABSOLUTE_TIME #undef JEMALLOC_HAVE_MACH_ABSOLUTE_TIME
/*
* Defined if clock_gettime(CLOCK_REALTIME, ...) is available.
*/
#undef JEMALLOC_HAVE_CLOCK_REALTIME
/* /*
* Defined if _malloc_thread_cleanup() exists. At least in the case of * Defined if _malloc_thread_cleanup() exists. At least in the case of
* FreeBSD, pthread_key_create() allocates, which if used during malloc * FreeBSD, pthread_key_create() allocates, which if used during malloc

View File

@ -3,6 +3,7 @@
#include "jemalloc/internal/atomic.h" #include "jemalloc/internal/atomic.h"
#include "jemalloc/internal/tsd_types.h" #include "jemalloc/internal/tsd_types.h"
#include "jemalloc/internal/nstime.h"
/* TSD checks this to set thread local slow state accordingly. */ /* TSD checks this to set thread local slow state accordingly. */
extern bool malloc_slow; extern bool malloc_slow;

View File

@ -209,5 +209,12 @@ static const bool have_background_thread =
false false
#endif #endif
; ;
static const bool config_high_res_timer =
#ifdef JEMALLOC_HAVE_CLOCK_REALTIME
true
#else
false
#endif
;
#endif /* JEMALLOC_PREAMBLE_H */ #endif /* JEMALLOC_PREAMBLE_H */

View File

@ -30,10 +30,23 @@ uint64_t nstime_divide(const nstime_t *time, const nstime_t *divisor);
typedef bool (nstime_monotonic_t)(void); typedef bool (nstime_monotonic_t)(void);
extern nstime_monotonic_t *JET_MUTABLE nstime_monotonic; extern nstime_monotonic_t *JET_MUTABLE nstime_monotonic;
typedef bool (nstime_update_t)(nstime_t *); typedef void (nstime_update_t)(nstime_t *);
extern nstime_update_t *JET_MUTABLE nstime_update; extern nstime_update_t *JET_MUTABLE nstime_update;
bool nstime_init_update(nstime_t *time); typedef void (nstime_prof_update_t)(nstime_t *);
extern nstime_prof_update_t *JET_MUTABLE nstime_prof_update;
void nstime_init_update(nstime_t *time);
void nstime_prof_init_update(nstime_t *time);
enum prof_time_res_e {
prof_time_res_default = 0,
prof_time_res_high = 1
};
typedef enum prof_time_res_e prof_time_res_t;
extern prof_time_res_t opt_prof_time_res;
extern const char *prof_time_res_mode_names[];
JEMALLOC_ALWAYS_INLINE void JEMALLOC_ALWAYS_INLINE void
nstime_init_zero(nstime_t *time) { nstime_init_zero(nstime_t *time) {

View File

@ -129,6 +129,7 @@ CTL_PROTO(opt_prof_leak)
CTL_PROTO(opt_prof_accum) CTL_PROTO(opt_prof_accum)
CTL_PROTO(opt_prof_recent_alloc_max) CTL_PROTO(opt_prof_recent_alloc_max)
CTL_PROTO(opt_prof_experimental_use_sys_thread_name) CTL_PROTO(opt_prof_experimental_use_sys_thread_name)
CTL_PROTO(opt_prof_time_res)
CTL_PROTO(opt_zero_realloc) CTL_PROTO(opt_zero_realloc)
CTL_PROTO(tcache_create) CTL_PROTO(tcache_create)
CTL_PROTO(tcache_flush) CTL_PROTO(tcache_flush)
@ -385,7 +386,8 @@ static const ctl_named_node_t opt_node[] = {
{NAME("prof_recent_alloc_max"), CTL(opt_prof_recent_alloc_max)}, {NAME("prof_recent_alloc_max"), CTL(opt_prof_recent_alloc_max)},
{NAME("prof_experimental_use_sys_thread_name"), {NAME("prof_experimental_use_sys_thread_name"),
CTL(opt_prof_experimental_use_sys_thread_name)}, CTL(opt_prof_experimental_use_sys_thread_name)},
{NAME("zero_realloc"), CTL(opt_zero_realloc)} {NAME("zero_realloc"), CTL(opt_zero_realloc)},
{NAME("prof_time_resolution"), CTL(opt_prof_time_res)}
}; };
static const ctl_named_node_t tcache_node[] = { static const ctl_named_node_t tcache_node[] = {
@ -1853,6 +1855,8 @@ CTL_RO_NL_CGEN(config_prof, opt_prof_recent_alloc_max,
opt_prof_recent_alloc_max, ssize_t) opt_prof_recent_alloc_max, ssize_t)
CTL_RO_NL_CGEN(config_prof, opt_prof_experimental_use_sys_thread_name, CTL_RO_NL_CGEN(config_prof, opt_prof_experimental_use_sys_thread_name,
opt_prof_experimental_use_sys_thread_name, bool) opt_prof_experimental_use_sys_thread_name, bool)
CTL_RO_NL_CGEN(config_prof, opt_prof_time_res,
prof_time_res_mode_names[opt_prof_time_res], const char *)
CTL_RO_NL_GEN(opt_zero_realloc, CTL_RO_NL_GEN(opt_zero_realloc,
zero_realloc_mode_names[opt_zero_realloc_action], const char *) zero_realloc_mode_names[opt_zero_realloc_action], const char *)

View File

@ -14,6 +14,7 @@
#include "jemalloc/internal/log.h" #include "jemalloc/internal/log.h"
#include "jemalloc/internal/malloc_io.h" #include "jemalloc/internal/malloc_io.h"
#include "jemalloc/internal/mutex.h" #include "jemalloc/internal/mutex.h"
#include "jemalloc/internal/nstime.h"
#include "jemalloc/internal/rtree.h" #include "jemalloc/internal/rtree.h"
#include "jemalloc/internal/safety_check.h" #include "jemalloc/internal/safety_check.h"
#include "jemalloc/internal/sc.h" #include "jemalloc/internal/sc.h"
@ -1497,6 +1498,26 @@ malloc_conf_init_helper(sc_data_t *sc_data, unsigned bin_shard_sizes[SC_NBINS],
CONF_HANDLE_BOOL( CONF_HANDLE_BOOL(
opt_prof_experimental_use_sys_thread_name, opt_prof_experimental_use_sys_thread_name,
"prof_experimental_use_sys_thread_name") "prof_experimental_use_sys_thread_name")
if (CONF_MATCH("prof_time_resolution")) {
if (CONF_MATCH_VALUE("default")) {
opt_prof_time_res =
prof_time_res_default;
} else if (CONF_MATCH_VALUE("high")) {
if (!config_high_res_timer) {
CONF_ERROR(
"No high resolution"
" timer support",
k, klen, v, vlen);
} else {
opt_prof_time_res =
prof_time_res_high;
}
} else {
CONF_ERROR("Invalid conf value",
k, klen, v, vlen);
}
}
CONF_CONTINUE;
} }
if (config_log) { if (config_log) {
if (CONF_MATCH("log")) { if (CONF_MATCH("log")) {

View File

@ -305,7 +305,7 @@ large_prof_tctx_reset(edata_t *edata) {
void void
large_prof_info_set(edata_t *edata, prof_tctx_t *tctx) { large_prof_info_set(edata_t *edata, prof_tctx_t *tctx) {
nstime_t t; nstime_t t;
nstime_init_update(&t); nstime_prof_init_update(&t);
edata_prof_alloc_time_set(edata, &t); edata_prof_alloc_time_set(edata, &t);
edata_prof_recent_alloc_init(edata); edata_prof_recent_alloc_init(edata);
large_prof_tctx_set(edata, tctx); large_prof_tctx_set(edata, tctx);

View File

@ -152,7 +152,42 @@ nstime_monotonic_impl(void) {
} }
nstime_monotonic_t *JET_MUTABLE nstime_monotonic = nstime_monotonic_impl; nstime_monotonic_t *JET_MUTABLE nstime_monotonic = nstime_monotonic_impl;
static bool prof_time_res_t opt_prof_time_res =
prof_time_res_default;
const char *prof_time_res_mode_names[] = {
"default",
"high",
};
static void
nstime_get_realtime(nstime_t *time) {
#if defined(JEMALLOC_HAVE_CLOCK_REALTIME) && !defined(_WIN32)
struct timespec ts;
clock_gettime(CLOCK_REALTIME, &ts);
nstime_init2(time, ts.tv_sec, ts.tv_nsec);
#else
unreachable();
#endif
}
static void
nstime_prof_update_impl(nstime_t *time) {
nstime_t old_time;
nstime_copy(&old_time, time);
if (opt_prof_time_res == prof_time_res_high) {
nstime_get_realtime(time);
} else {
nstime_get(time);
}
}
nstime_prof_update_t *JET_MUTABLE nstime_prof_update = nstime_prof_update_impl;
static void
nstime_update_impl(nstime_t *time) { nstime_update_impl(nstime_t *time) {
nstime_t old_time; nstime_t old_time;
@ -162,15 +197,20 @@ nstime_update_impl(nstime_t *time) {
/* Handle non-monotonic clocks. */ /* Handle non-monotonic clocks. */
if (unlikely(nstime_compare(&old_time, time) > 0)) { if (unlikely(nstime_compare(&old_time, time) > 0)) {
nstime_copy(time, &old_time); nstime_copy(time, &old_time);
return true;
} }
return false;
} }
nstime_update_t *JET_MUTABLE nstime_update = nstime_update_impl; nstime_update_t *JET_MUTABLE nstime_update = nstime_update_impl;
bool void
nstime_init_update(nstime_t *time) { nstime_init_update(nstime_t *time) {
nstime_init_zero(time); nstime_init_zero(time);
return nstime_update(time); nstime_update(time);
} }
void
nstime_prof_init_update(nstime_t *time) {
nstime_init_zero(time);
nstime_prof_update(time);
}

View File

@ -235,7 +235,7 @@ prof_try_log(tsd_t *tsd, size_t usize, prof_info_t *prof_info) {
nstime_t alloc_time = prof_info->alloc_time; nstime_t alloc_time = prof_info->alloc_time;
nstime_t free_time; nstime_t free_time;
nstime_init_update(&free_time); nstime_prof_init_update(&free_time);
size_t sz = sizeof(prof_alloc_node_t); size_t sz = sizeof(prof_alloc_node_t);
prof_alloc_node_t *new_node = (prof_alloc_node_t *) prof_alloc_node_t *new_node = (prof_alloc_node_t *)
@ -572,6 +572,11 @@ prof_log_emit_metadata(emitter_t *emitter) {
emitter_json_kv(emitter, "lg_sample_rate", emitter_json_kv(emitter, "lg_sample_rate",
emitter_type_int, &lg_prof_sample); emitter_type_int, &lg_prof_sample);
const char *res_type =
prof_time_res_mode_names[opt_prof_time_res];
emitter_json_kv(emitter, "prof_time_resolution",
emitter_type_string, &res_type);
int pid = prof_getpid(); int pid = prof_getpid();
emitter_json_kv(emitter, "pid", emitter_type_int, &pid); emitter_json_kv(emitter, "pid", emitter_type_int, &pid);

View File

@ -219,7 +219,7 @@ prof_recent_alloc_reset(tsd_t *tsd, edata_t *edata) {
assert(nstime_equals_zero(&recent->dalloc_time)); assert(nstime_equals_zero(&recent->dalloc_time));
assert(recent->dalloc_tctx == NULL); assert(recent->dalloc_tctx == NULL);
if (dalloc_tctx != NULL) { if (dalloc_tctx != NULL) {
nstime_update(&recent->dalloc_time); nstime_prof_update(&recent->dalloc_time);
recent->dalloc_tctx = dalloc_tctx; recent->dalloc_tctx = dalloc_tctx;
dalloc_tctx = NULL; dalloc_tctx = NULL;
} }

View File

@ -26,13 +26,12 @@ nstime_monotonic_mock(void) {
return monotonic_mock; return monotonic_mock;
} }
static bool static void
nstime_update_mock(nstime_t *time) { nstime_update_mock(nstime_t *time) {
nupdates_mock++; nupdates_mock++;
if (monotonic_mock) { if (monotonic_mock) {
nstime_copy(time, &time_mock); nstime_copy(time, &time_mock);
} }
return !monotonic_mock;
} }
static unsigned static unsigned

View File

@ -206,28 +206,6 @@ TEST_BEGIN(test_nstime_monotonic) {
} }
TEST_END TEST_END
TEST_BEGIN(test_nstime_update) {
nstime_t nst;
expect_false(nstime_init_update(&nst), "Basic time update failed.");
/* Only Rip Van Winkle sleeps this long. */
{
nstime_t addend;
nstime_init2(&addend, 631152000, 0);
nstime_add(&nst, &addend);
}
{
nstime_t nst0;
nstime_copy(&nst0, &nst);
expect_true(nstime_update(&nst),
"Update should detect time roll-back.");
expect_d_eq(nstime_compare(&nst, &nst0), 0,
"Time should not have been modified");
}
}
TEST_END
int int
main(void) { main(void) {
return test( return test(
@ -242,6 +220,5 @@ main(void) {
test_nstime_imultiply, test_nstime_imultiply,
test_nstime_idivide, test_nstime_idivide,
test_nstime_divide, test_nstime_divide,
test_nstime_monotonic, test_nstime_monotonic);
test_nstime_update);
} }