diff options
Diffstat (limited to 'trace2')
| -rw-r--r-- | trace2/tr2_tgt.h | 9 | ||||
| -rw-r--r-- | trace2/tr2_tgt_event.c | 26 | ||||
| -rw-r--r-- | trace2/tr2_tgt_normal.c | 23 | ||||
| -rw-r--r-- | trace2/tr2_tgt_perf.c | 24 | ||||
| -rw-r--r-- | trace2/tr2_tls.c | 10 | ||||
| -rw-r--r-- | trace2/tr2_tls.h | 10 | ||||
| -rw-r--r-- | trace2/tr2_tmr.c | 182 | ||||
| -rw-r--r-- | trace2/tr2_tmr.h | 140 |
8 files changed, 424 insertions, 0 deletions
diff --git a/trace2/tr2_tgt.h b/trace2/tr2_tgt.h index 65f94e1574..85c8d2d7f5 100644 --- a/trace2/tr2_tgt.h +++ b/trace2/tr2_tgt.h @@ -4,6 +4,10 @@ struct child_process; struct repository; struct json_writer; +struct tr2_timer_metadata; +struct tr2_timer; + +#define NS_TO_SEC(ns) ((double)(ns) / 1.0e9) /* * Function prototypes for a TRACE2 "target" vtable. @@ -96,6 +100,10 @@ typedef void(tr2_tgt_evt_printf_va_fl_t)(const char *file, int line, uint64_t us_elapsed_absolute, const char *fmt, va_list ap); +typedef void(tr2_tgt_evt_timer_t)(const struct tr2_timer_metadata *meta, + const struct tr2_timer *timer, + int is_final_data); + /* * "vtable" for a TRACE2 target. Use NULL if a target does not want * to emit that message. @@ -132,6 +140,7 @@ struct tr2_tgt { tr2_tgt_evt_data_fl_t *pfn_data_fl; tr2_tgt_evt_data_json_fl_t *pfn_data_json_fl; tr2_tgt_evt_printf_va_fl_t *pfn_printf_va_fl; + tr2_tgt_evt_timer_t *pfn_timer; }; /* clang-format on */ diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c index 52f9356c69..af5a8edb47 100644 --- a/trace2/tr2_tgt_event.c +++ b/trace2/tr2_tgt_event.c @@ -9,6 +9,7 @@ #include "trace2/tr2_sysenv.h" #include "trace2/tr2_tgt.h" #include "trace2/tr2_tls.h" +#include "trace2/tr2_tmr.h" static struct tr2_dst tr2dst_event = { .sysenv_var = TR2_SYSENV_EVENT, @@ -617,6 +618,30 @@ static void fn_data_json_fl(const char *file, int line, } } +static void fn_timer(const struct tr2_timer_metadata *meta, + const struct tr2_timer *timer, + int is_final_data) +{ + const char *event_name = is_final_data ? "timer" : "th_timer"; + struct json_writer jw = JSON_WRITER_INIT; + double t_total = NS_TO_SEC(timer->total_ns); + double t_min = NS_TO_SEC(timer->min_ns); + double t_max = NS_TO_SEC(timer->max_ns); + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw); + jw_object_string(&jw, "category", meta->category); + jw_object_string(&jw, "name", meta->name); + jw_object_intmax(&jw, "intervals", timer->interval_count); + jw_object_double(&jw, "t_total", 6, t_total); + jw_object_double(&jw, "t_min", 6, t_min); + jw_object_double(&jw, "t_max", 6, t_max); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + struct tr2_tgt tr2_tgt_event = { .pdst = &tr2dst_event, @@ -648,4 +673,5 @@ struct tr2_tgt tr2_tgt_event = { .pfn_data_fl = fn_data_fl, .pfn_data_json_fl = fn_data_json_fl, .pfn_printf_va_fl = NULL, + .pfn_timer = fn_timer, }; diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c index 69f8033077..b079baf100 100644 --- a/trace2/tr2_tgt_normal.c +++ b/trace2/tr2_tgt_normal.c @@ -8,6 +8,7 @@ #include "trace2/tr2_tbuf.h" #include "trace2/tr2_tgt.h" #include "trace2/tr2_tls.h" +#include "trace2/tr2_tmr.h" static struct tr2_dst tr2dst_normal = { .sysenv_var = TR2_SYSENV_NORMAL, @@ -329,6 +330,27 @@ static void fn_printf_va_fl(const char *file, int line, strbuf_release(&buf_payload); } +static void fn_timer(const struct tr2_timer_metadata *meta, + const struct tr2_timer *timer, + int is_final_data) +{ + const char *event_name = is_final_data ? "timer" : "th_timer"; + struct strbuf buf_payload = STRBUF_INIT; + double t_total = NS_TO_SEC(timer->total_ns); + double t_min = NS_TO_SEC(timer->min_ns); + double t_max = NS_TO_SEC(timer->max_ns); + + strbuf_addf(&buf_payload, ("%s %s/%s" + " intervals:%"PRIu64 + " total:%8.6f min:%8.6f max:%8.6f"), + event_name, meta->category, meta->name, + timer->interval_count, + t_total, t_min, t_max); + + normal_io_write_fl(__FILE__, __LINE__, &buf_payload); + strbuf_release(&buf_payload); +} + struct tr2_tgt tr2_tgt_normal = { .pdst = &tr2dst_normal, @@ -360,4 +382,5 @@ struct tr2_tgt tr2_tgt_normal = { .pfn_data_fl = NULL, .pfn_data_json_fl = NULL, .pfn_printf_va_fl = fn_printf_va_fl, + .pfn_timer = fn_timer, }; diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c index 59ca58f862..e69375e979 100644 --- a/trace2/tr2_tgt_perf.c +++ b/trace2/tr2_tgt_perf.c @@ -10,6 +10,7 @@ #include "trace2/tr2_tbuf.h" #include "trace2/tr2_tgt.h" #include "trace2/tr2_tls.h" +#include "trace2/tr2_tmr.h" static struct tr2_dst tr2dst_perf = { .sysenv_var = TR2_SYSENV_PERF, @@ -555,6 +556,28 @@ static void fn_printf_va_fl(const char *file, int line, strbuf_release(&buf_payload); } +static void fn_timer(const struct tr2_timer_metadata *meta, + const struct tr2_timer *timer, + int is_final_data) +{ + const char *event_name = is_final_data ? "timer" : "th_timer"; + struct strbuf buf_payload = STRBUF_INIT; + double t_total = NS_TO_SEC(timer->total_ns); + double t_min = NS_TO_SEC(timer->min_ns); + double t_max = NS_TO_SEC(timer->max_ns); + + strbuf_addf(&buf_payload, ("name:%s" + " intervals:%"PRIu64 + " total:%8.6f min:%8.6f max:%8.6f"), + meta->name, + timer->interval_count, + t_total, t_min, t_max); + + perf_io_write_fl(__FILE__, __LINE__, event_name, NULL, NULL, NULL, + meta->category, &buf_payload); + strbuf_release(&buf_payload); +} + struct tr2_tgt tr2_tgt_perf = { .pdst = &tr2dst_perf, @@ -586,4 +609,5 @@ struct tr2_tgt tr2_tgt_perf = { .pfn_data_fl = fn_data_fl, .pfn_data_json_fl = fn_data_json_fl, .pfn_printf_va_fl = fn_printf_va_fl, + .pfn_timer = fn_timer, }; diff --git a/trace2/tr2_tls.c b/trace2/tr2_tls.c index 3a67532aae..04900bb4c3 100644 --- a/trace2/tr2_tls.c +++ b/trace2/tr2_tls.c @@ -181,3 +181,13 @@ int tr2tls_locked_increment(int *p) return current_value; } + +void tr2tls_lock(void) +{ + pthread_mutex_lock(&tr2tls_mutex); +} + +void tr2tls_unlock(void) +{ + pthread_mutex_unlock(&tr2tls_mutex); +} diff --git a/trace2/tr2_tls.h b/trace2/tr2_tls.h index 65836b1399..a064b66e4c 100644 --- a/trace2/tr2_tls.h +++ b/trace2/tr2_tls.h @@ -2,6 +2,7 @@ #define TR2_TLS_H #include "strbuf.h" +#include "trace2/tr2_tmr.h" /* * Notice: the term "TLS" refers to "thread-local storage" in the @@ -20,6 +21,9 @@ struct tr2tls_thread_ctx { size_t alloc; size_t nr_open_regions; /* plays role of "nr" in ALLOC_GROW */ int thread_id; + struct tr2_timer_block timer_block; + unsigned int used_any_timer:1; + unsigned int used_any_per_thread_timer:1; }; /* @@ -107,4 +111,10 @@ int tr2tls_locked_increment(int *p); */ void tr2tls_start_process_clock(void); +/* + * Explicitly lock/unlock our mutex. + */ +void tr2tls_lock(void); +void tr2tls_unlock(void); + #endif /* TR2_TLS_H */ diff --git a/trace2/tr2_tmr.c b/trace2/tr2_tmr.c new file mode 100644 index 0000000000..786762dfd2 --- /dev/null +++ b/trace2/tr2_tmr.c @@ -0,0 +1,182 @@ +#include "cache.h" +#include "thread-utils.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" +#include "trace2/tr2_tmr.h" + +#define MY_MAX(a, b) ((a) > (b) ? (a) : (b)) +#define MY_MIN(a, b) ((a) < (b) ? (a) : (b)) + +/* + * A global timer block to aggregate values from the partial sums from + * each thread. + */ +static struct tr2_timer_block final_timer_block; /* access under tr2tls_mutex */ + +/* + * Define metadata for each stopwatch timer. + * + * This array must match "enum trace2_timer_id" and the values + * in "struct tr2_timer_block.timer[*]". + */ +static struct tr2_timer_metadata tr2_timer_metadata[TRACE2_NUMBER_OF_TIMERS] = { + [TRACE2_TIMER_ID_TEST1] = { + .category = "test", + .name = "test1", + .want_per_thread_events = 0, + }, + [TRACE2_TIMER_ID_TEST2] = { + .category = "test", + .name = "test2", + .want_per_thread_events = 1, + }, + + /* Add additional metadata before here. */ +}; + +void tr2_start_timer(enum trace2_timer_id tid) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + struct tr2_timer *t = &ctx->timer_block.timer[tid]; + + t->recursion_count++; + if (t->recursion_count > 1) + return; /* ignore recursive starts */ + + t->start_ns = getnanotime(); +} + +void tr2_stop_timer(enum trace2_timer_id tid) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + struct tr2_timer *t = &ctx->timer_block.timer[tid]; + uint64_t ns_now; + uint64_t ns_interval; + + assert(t->recursion_count > 0); + + t->recursion_count--; + if (t->recursion_count) + return; /* still in recursive call(s) */ + + ns_now = getnanotime(); + ns_interval = ns_now - t->start_ns; + + t->total_ns += ns_interval; + + /* + * min_ns was initialized to zero (in the xcalloc()) rather + * than UINT_MAX when the block of timers was allocated, + * so we should always set both the min_ns and max_ns values + * the first time that the timer is used. + */ + if (!t->interval_count) { + t->min_ns = ns_interval; + t->max_ns = ns_interval; + } else { + t->min_ns = MY_MIN(ns_interval, t->min_ns); + t->max_ns = MY_MAX(ns_interval, t->max_ns); + } + + t->interval_count++; + + ctx->used_any_timer = 1; + if (tr2_timer_metadata[tid].want_per_thread_events) + ctx->used_any_per_thread_timer = 1; +} + +void tr2_update_final_timers(void) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + enum trace2_timer_id tid; + + if (!ctx->used_any_timer) + return; + + /* + * Accessing `final_timer_block` requires holding `tr2tls_mutex`. + * We assume that our caller is holding the lock. + */ + + for (tid = 0; tid < TRACE2_NUMBER_OF_TIMERS; tid++) { + struct tr2_timer *t_final = &final_timer_block.timer[tid]; + struct tr2_timer *t = &ctx->timer_block.timer[tid]; + + if (t->recursion_count) { + /* + * The current thread is exiting with + * timer[tid] still running. + * + * Technically, this is a bug, but I'm going + * to ignore it. + * + * I don't think it is worth calling die() + * for. I don't think it is worth killing the + * process for this bookkeeping error. We + * might want to call warning(), but I'm going + * to wait on that. + * + * The downside here is that total_ns won't + * include the current open interval (now - + * start_ns). I can live with that. + */ + } + + if (!t->interval_count) + continue; /* this timer was not used by this thread */ + + t_final->total_ns += t->total_ns; + + /* + * final_timer_block.timer[tid].min_ns was initialized to + * was initialized to zero rather than UINT_MAX, so we should + * always set both the min_ns and max_ns values the first time + * that we add a partial sum into it. + */ + if (!t_final->interval_count) { + t_final->min_ns = t->min_ns; + t_final->max_ns = t->max_ns; + } else { + t_final->min_ns = MY_MIN(t_final->min_ns, t->min_ns); + t_final->max_ns = MY_MAX(t_final->max_ns, t->max_ns); + } + + t_final->interval_count += t->interval_count; + } +} + +void tr2_emit_per_thread_timers(tr2_tgt_evt_timer_t *fn_apply) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + enum trace2_timer_id tid; + + if (!ctx->used_any_per_thread_timer) + return; + + /* + * For each timer, if the timer wants per-thread events and + * this thread used it, emit it. + */ + for (tid = 0; tid < TRACE2_NUMBER_OF_TIMERS; tid++) + if (tr2_timer_metadata[tid].want_per_thread_events && + ctx->timer_block.timer[tid].interval_count) + fn_apply(&tr2_timer_metadata[tid], + &ctx->timer_block.timer[tid], + 0); +} + +void tr2_emit_final_timers(tr2_tgt_evt_timer_t *fn_apply) +{ + enum trace2_timer_id tid; + + /* + * Accessing `final_timer_block` requires holding `tr2tls_mutex`. + * We assume that our caller is holding the lock. + */ + + for (tid = 0; tid < TRACE2_NUMBER_OF_TIMERS; tid++) + if (final_timer_block.timer[tid].interval_count) + fn_apply(&tr2_timer_metadata[tid], + &final_timer_block.timer[tid], + 1); +} diff --git a/trace2/tr2_tmr.h b/trace2/tr2_tmr.h new file mode 100644 index 0000000000..d575357613 --- /dev/null +++ b/trace2/tr2_tmr.h @@ -0,0 +1,140 @@ +#ifndef TR2_TMR_H +#define TR2_TMR_H + +#include "trace2.h" +#include "trace2/tr2_tgt.h" + +/* + * Define a mechanism to allow "stopwatch" timers. + * + * Timers can be used to measure "interesting" activity that does not + * fit the "region" model, such as code called from many different + * regions (like zlib) and/or where data for individual calls are not + * interesting or are too numerous to be efficiently logged. + * + * Timer values are accumulated during program execution and emitted + * to the Trace2 logs at program exit. + * + * To make this model efficient, we define a compile-time fixed set of + * timers and timer ids using a "timer block" array in thread-local + * storage. This gives us constant time access to each timer within + * each thread, since we want start/stop operations to be as fast as + * possible. This lets us avoid the complexities of dynamically + * allocating a timer on the first use by a thread and/or possibly + * sharing that timer definition with other concurrent threads. + * However, this does require that we define time the set of timers at + * compile time. + * + * Each thread uses the timer block in its thread-local storage to + * compute partial sums for each timer (without locking). When a + * thread exits, those partial sums are (under lock) added to the + * global final sum. + * + * Using this "timer block" model costs ~48 bytes per timer per thread + * (we have about six uint64 fields per timer). This does increase + * the size of the thread-local storage block, but it is allocated (at + * thread create time) and not on the thread stack, so I'm not worried + * about the size. + * + * Partial sums for each timer are optionally emitted when a thread + * exits. + * + * Final sums for each timer are emitted between the "exit" and + * "atexit" events. + * + * A parallel "timer metadata" table contains the "category" and "name" + * fields for each timer. This eliminates the need to include those + * args in the various timer APIs. + */ + +/* + * The definition of an individual timer and used by an individual + * thread. + */ +struct tr2_timer { + /* + * Total elapsed time for this timer in this thread in nanoseconds. + */ + uint64_t total_ns; + + /* + * The maximum and minimum interval values observed for this + * timer in this thread. + */ + uint64_t min_ns; + uint64_t max_ns; + + /* + * The value of the clock when this timer was started in this + * thread. (Undefined when the timer is not active in this + * thread.) + */ + uint64_t start_ns; + + /* + * Number of times that this timer has been started and stopped + * in this thread. (Recursive starts are ignored.) + */ + uint64_t interval_count; + + /* + * Number of nested starts on the stack in this thread. (We + * ignore recursive starts and use this to track the recursive + * calls.) + */ + unsigned int recursion_count; +}; + +/* + * Metadata for a timer. + */ +struct tr2_timer_metadata { + const char *category; + const char *name; + + /* + * True if we should emit per-thread events for this timer + * when individual threads exit. + */ + unsigned int want_per_thread_events:1; +}; + +/* + * A compile-time fixed-size block of timers to insert into + * thread-local storage. This wrapper is used to avoid quirks + * of C and the usual need to pass an array size argument. + */ +struct tr2_timer_block { + struct tr2_timer timer[TRACE2_NUMBER_OF_TIMERS]; +}; + +/* + * Private routines used by trace2.c to actually start/stop an + * individual timer in the current thread. + */ +void tr2_start_timer(enum trace2_timer_id tid); +void tr2_stop_timer(enum trace2_timer_id tid); + +/* + * Add the current thread's timer data to the global totals. + * This is called during thread-exit. + * + * Caller must be holding the tr2tls_mutex. + */ +void tr2_update_final_timers(void); + +/* + * Emit per-thread timer data for the current thread. + * This is called during thread-exit. + */ +void tr2_emit_per_thread_timers(tr2_tgt_evt_timer_t *fn_apply); + +/* + * Emit global total timer values. + * This is called during atexit handling. + * + * Caller must be holding the tr2tls_mutex. + */ +void tr2_emit_final_timers(tr2_tgt_evt_timer_t *fn_apply); + +#endif /* TR2_TMR_H */ |