diff options
Diffstat (limited to 'trace2')
-rw-r--r-- | trace2/tr2_cfg.c | 4 | ||||
-rw-r--r-- | trace2/tr2_cmd_name.c | 3 | ||||
-rw-r--r-- | trace2/tr2_ctr.c | 101 | ||||
-rw-r--r-- | trace2/tr2_ctr.h | 104 | ||||
-rw-r--r-- | trace2/tr2_dst.c | 4 | ||||
-rw-r--r-- | trace2/tr2_sid.c | 4 | ||||
-rw-r--r-- | trace2/tr2_sysenv.c | 2 | ||||
-rw-r--r-- | trace2/tr2_tbuf.c | 2 | ||||
-rw-r--r-- | trace2/tr2_tgt.h | 16 | ||||
-rw-r--r-- | trace2/tr2_tgt_event.c | 50 | ||||
-rw-r--r-- | trace2/tr2_tgt_normal.c | 42 | ||||
-rw-r--r-- | trace2/tr2_tgt_perf.c | 46 | ||||
-rw-r--r-- | trace2/tr2_tls.c | 38 | ||||
-rw-r--r-- | trace2/tr2_tls.h | 55 | ||||
-rw-r--r-- | trace2/tr2_tmr.c | 183 | ||||
-rw-r--r-- | trace2/tr2_tmr.h | 140 |
16 files changed, 754 insertions, 40 deletions
diff --git a/trace2/tr2_cfg.c b/trace2/tr2_cfg.c index ec9ac1a6ef..78cfc15d52 100644 --- a/trace2/tr2_cfg.c +++ b/trace2/tr2_cfg.c @@ -1,5 +1,7 @@ -#include "cache.h" +#include "git-compat-util.h" #include "config.h" +#include "strbuf.h" +#include "trace2.h" #include "trace2/tr2_cfg.h" #include "trace2/tr2_sysenv.h" diff --git a/trace2/tr2_cmd_name.c b/trace2/tr2_cmd_name.c index dd313204f5..b7b5a869b7 100644 --- a/trace2/tr2_cmd_name.c +++ b/trace2/tr2_cmd_name.c @@ -1,4 +1,5 @@ -#include "cache.h" +#include "git-compat-util.h" +#include "strbuf.h" #include "trace2/tr2_cmd_name.h" #define TR2_ENVVAR_PARENT_NAME "GIT_TRACE2_PARENT_NAME" diff --git a/trace2/tr2_ctr.c b/trace2/tr2_ctr.c new file mode 100644 index 0000000000..b342d3b1a3 --- /dev/null +++ b/trace2/tr2_ctr.c @@ -0,0 +1,101 @@ +#include "git-compat-util.h" +#include "thread-utils.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" +#include "trace2/tr2_ctr.h" + +/* + * A global counter block to aggregrate values from the partial sums + * from each thread. + */ +static struct tr2_counter_block final_counter_block; /* access under tr2tls_mutex */ + +/* + * Define metadata for each global counter. + * + * This array must match the "enum trace2_counter_id" and the values + * in "struct tr2_counter_block.counter[*]". + */ +static struct tr2_counter_metadata tr2_counter_metadata[TRACE2_NUMBER_OF_COUNTERS] = { + [TRACE2_COUNTER_ID_TEST1] = { + .category = "test", + .name = "test1", + .want_per_thread_events = 0, + }, + [TRACE2_COUNTER_ID_TEST2] = { + .category = "test", + .name = "test2", + .want_per_thread_events = 1, + }, + + /* Add additional metadata before here. */ +}; + +void tr2_counter_increment(enum trace2_counter_id cid, uint64_t value) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + struct tr2_counter *c = &ctx->counter_block.counter[cid]; + + c->value += value; + + ctx->used_any_counter = 1; + if (tr2_counter_metadata[cid].want_per_thread_events) + ctx->used_any_per_thread_counter = 1; +} + +void tr2_update_final_counters(void) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + enum trace2_counter_id cid; + + if (!ctx->used_any_counter) + return; + + /* + * Access `final_counter_block` requires holding `tr2tls_mutex`. + * We assume that our caller is holding the lock. + */ + + for (cid = 0; cid < TRACE2_NUMBER_OF_COUNTERS; cid++) { + struct tr2_counter *c_final = &final_counter_block.counter[cid]; + const struct tr2_counter *c = &ctx->counter_block.counter[cid]; + + c_final->value += c->value; + } +} + +void tr2_emit_per_thread_counters(tr2_tgt_evt_counter_t *fn_apply) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + enum trace2_counter_id cid; + + if (!ctx->used_any_per_thread_counter) + return; + + /* + * For each counter, if the counter wants per-thread events + * and this thread used it (the value is non-zero), emit it. + */ + for (cid = 0; cid < TRACE2_NUMBER_OF_COUNTERS; cid++) + if (tr2_counter_metadata[cid].want_per_thread_events && + ctx->counter_block.counter[cid].value) + fn_apply(&tr2_counter_metadata[cid], + &ctx->counter_block.counter[cid], + 0); +} + +void tr2_emit_final_counters(tr2_tgt_evt_counter_t *fn_apply) +{ + enum trace2_counter_id cid; + + /* + * Access `final_counter_block` requires holding `tr2tls_mutex`. + * We assume that our caller is holding the lock. + */ + + for (cid = 0; cid < TRACE2_NUMBER_OF_COUNTERS; cid++) + if (final_counter_block.counter[cid].value) + fn_apply(&tr2_counter_metadata[cid], + &final_counter_block.counter[cid], + 1); +} diff --git a/trace2/tr2_ctr.h b/trace2/tr2_ctr.h new file mode 100644 index 0000000000..a2267ee990 --- /dev/null +++ b/trace2/tr2_ctr.h @@ -0,0 +1,104 @@ +#ifndef TR2_CTR_H +#define TR2_CTR_H + +#include "trace2.h" +#include "trace2/tr2_tgt.h" + +/* + * Define a mechanism to allow global "counters". + * + * Counters can be used count interesting activity that does not fit + * the "region and data" model, such as code called from many + * different regions and/or where you want to count a number of items, + * but don't have control of when the last item will be processed, + * such as counter the number of calls to `lstat()`. + * + * Counters differ from Trace2 "data" events. Data events are emitted + * immediately and are appropriate for documenting loop counters at + * the end of a region, for example. Counter values are accumulated + * during the program and final counter values are emitted at program + * exit. + * + * To make this model efficient, we define a compile-time fixed set of + * counters and counter ids using a fixed size "counter block" array + * in thread-local storage. This gives us constant time, lock-free + * access to each counter within each thread. This lets us avoid the + * complexities of dynamically allocating a counter and sharing that + * definition with other threads. + * + * Each thread uses the counter block in its thread-local storage to + * increment partial sums for each counter (without locking). When a + * thread exits, those partial sums are (under lock) added to the + * global final sum. + * + * Partial sums for each counter are optionally emitted when a thread + * exits. + * + * Final sums for each counter are emitted between the "exit" and + * "atexit" events. + * + * A parallel "counter metadata" table contains the "category" and + * "name" fields for each counter. This eliminates the need to + * include those args in the various counter APIs. + */ + +/* + * The definition of an individual counter as used by an individual + * thread (and later in aggregation). + */ +struct tr2_counter { + uint64_t value; +}; + +/* + * Metadata for a counter. + */ +struct tr2_counter_metadata { + const char *category; + const char *name; + + /* + * True if we should emit per-thread events for this counter + * when individual threads exit. + */ + unsigned int want_per_thread_events:1; +}; + +/* + * A compile-time fixed block of counters 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_counter_block { + struct tr2_counter counter[TRACE2_NUMBER_OF_COUNTERS]; +}; + +/* + * Private routines used by trace2.c to increment a counter for the + * current thread. + */ +void tr2_counter_increment(enum trace2_counter_id cid, uint64_t value); + +/* + * Add the current thread's counter data to the global totals. + * This is called during thread-exit. + * + * Caller must be holding the tr2tls_mutex. + */ +void tr2_update_final_counters(void); + +/* + * Emit per-thread counter data for the current thread. + * This is called during thread-exit. + */ +void tr2_emit_per_thread_counters(tr2_tgt_evt_counter_t *fn_apply); + +/* + * Emit global counter values. + * This is called during atexit handling. + * + * Caller must be holding the tr2tls_mutex. + */ +void tr2_emit_final_counters(tr2_tgt_evt_counter_t *fn_apply); + +#endif /* TR2_CTR_H */ diff --git a/trace2/tr2_dst.c b/trace2/tr2_dst.c index 8a21dd2972..5be892cd5c 100644 --- a/trace2/tr2_dst.c +++ b/trace2/tr2_dst.c @@ -1,5 +1,7 @@ -#include "cache.h" +#include "git-compat-util.h" +#include "abspath.h" #include "sigchain.h" +#include "strbuf.h" #include "trace2/tr2_dst.h" #include "trace2/tr2_sid.h" #include "trace2/tr2_sysenv.h" diff --git a/trace2/tr2_sid.c b/trace2/tr2_sid.c index dc6e75ef13..09c4ef0d17 100644 --- a/trace2/tr2_sid.c +++ b/trace2/tr2_sid.c @@ -1,4 +1,6 @@ -#include "cache.h" +#include "git-compat-util.h" +#include "hex.h" +#include "strbuf.h" #include "trace2/tr2_tbuf.h" #include "trace2/tr2_sid.h" diff --git a/trace2/tr2_sysenv.c b/trace2/tr2_sysenv.c index a380dcf910..069786cb92 100644 --- a/trace2/tr2_sysenv.c +++ b/trace2/tr2_sysenv.c @@ -1,4 +1,4 @@ -#include "cache.h" +#include "git-compat-util.h" #include "config.h" #include "dir.h" #include "tr2_sysenv.h" diff --git a/trace2/tr2_tbuf.c b/trace2/tr2_tbuf.c index 2498482d9a..c3b3822ed7 100644 --- a/trace2/tr2_tbuf.c +++ b/trace2/tr2_tbuf.c @@ -1,4 +1,4 @@ -#include "cache.h" +#include "git-compat-util.h" #include "tr2_tbuf.h" void tr2_tbuf_local_time(struct tr2_tbuf *tb) diff --git a/trace2/tr2_tgt.h b/trace2/tr2_tgt.h index 65f94e1574..bf8745c4f0 100644 --- a/trace2/tr2_tgt.h +++ b/trace2/tr2_tgt.h @@ -4,6 +4,12 @@ struct child_process; struct repository; struct json_writer; +struct tr2_timer_metadata; +struct tr2_timer; +struct tr2_counter_metadata; +struct tr2_counter; + +#define NS_TO_SEC(ns) ((double)(ns) / 1.0e9) /* * Function prototypes for a TRACE2 "target" vtable. @@ -96,6 +102,14 @@ 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); + +typedef void(tr2_tgt_evt_counter_t)(const struct tr2_counter_metadata *meta, + const struct tr2_counter *counter, + int is_final_data); + /* * "vtable" for a TRACE2 target. Use NULL if a target does not want * to emit that message. @@ -132,6 +146,8 @@ 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; + tr2_tgt_evt_counter_t *pfn_counter; }; /* clang-format on */ diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c index 37a3163be1..2af53e5d4d 100644 --- a/trace2/tr2_tgt_event.c +++ b/trace2/tr2_tgt_event.c @@ -1,6 +1,7 @@ -#include "cache.h" +#include "git-compat-util.h" #include "config.h" #include "json-writer.h" +#include "repository.h" #include "run-command.h" #include "version.h" #include "trace2/tr2_dst.h" @@ -9,6 +10,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, @@ -90,7 +92,7 @@ static void event_fmt_prepare(const char *event_name, const char *file, jw_object_string(jw, "event", event_name); jw_object_string(jw, "sid", tr2_sid_get()); - jw_object_string(jw, "thread", ctx->thread_name.buf); + jw_object_string(jw, "thread", ctx->thread_name); /* * In brief mode, only emit <time> on these 2 event types. @@ -617,6 +619,48 @@ 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); +} + +static void fn_counter(const struct tr2_counter_metadata *meta, + const struct tr2_counter *counter, + int is_final_data) +{ + const char *event_name = is_final_data ? "counter" : "th_counter"; + struct json_writer jw = JSON_WRITER_INIT; + + 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, "count", counter->value); + 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 +692,6 @@ 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, + .pfn_counter = fn_counter, }; diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c index 69f8033077..1ebfb464d5 100644 --- a/trace2/tr2_tgt_normal.c +++ b/trace2/tr2_tgt_normal.c @@ -1,5 +1,6 @@ -#include "cache.h" +#include "git-compat-util.h" #include "config.h" +#include "repository.h" #include "run-command.h" #include "quote.h" #include "version.h" @@ -8,6 +9,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 +331,42 @@ 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); +} + +static void fn_counter(const struct tr2_counter_metadata *meta, + const struct tr2_counter *counter, + int is_final_data) +{ + const char *event_name = is_final_data ? "counter" : "th_counter"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "%s %s/%s value:%"PRIu64, + event_name, meta->category, meta->name, + counter->value); + + normal_io_write_fl(__FILE__, __LINE__, &buf_payload); + strbuf_release(&buf_payload); +} + struct tr2_tgt tr2_tgt_normal = { .pdst = &tr2dst_normal, @@ -360,4 +398,6 @@ 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, + .pfn_counter = fn_counter, }; diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c index 8cb792488c..328e483a05 100644 --- a/trace2/tr2_tgt_perf.c +++ b/trace2/tr2_tgt_perf.c @@ -1,5 +1,6 @@ -#include "cache.h" +#include "git-compat-util.h" #include "config.h" +#include "repository.h" #include "run-command.h" #include "quote.h" #include "version.h" @@ -10,6 +11,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, @@ -108,7 +110,7 @@ static void perf_fmt_prepare(const char *event_name, strbuf_addf(buf, "d%d | ", tr2_sid_depth()); strbuf_addf(buf, "%-*s | %-*s | ", TR2_MAX_THREAD_NAME, - ctx->thread_name.buf, TR2FMT_PERF_MAX_EVENT_NAME, + ctx->thread_name, TR2FMT_PERF_MAX_EVENT_NAME, event_name); len = buf->len + TR2FMT_PERF_REPO_WIDTH; @@ -555,6 +557,44 @@ 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); +} + +static void fn_counter(const struct tr2_counter_metadata *meta, + const struct tr2_counter *counter, + int is_final_data) +{ + const char *event_name = is_final_data ? "counter" : "th_counter"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "name:%s value:%"PRIu64, + meta->name, + counter->value); + + 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 +626,6 @@ 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, + .pfn_counter = fn_counter, }; diff --git a/trace2/tr2_tls.c b/trace2/tr2_tls.c index 7da94aba52..9f46ae12f5 100644 --- a/trace2/tr2_tls.c +++ b/trace2/tr2_tls.c @@ -1,5 +1,7 @@ -#include "cache.h" +#include "git-compat-util.h" +#include "alloc.h" #include "thread-utils.h" +#include "trace.h" #include "trace2/tr2_tls.h" /* @@ -31,10 +33,11 @@ void tr2tls_start_process_clock(void) tr2tls_us_start_process = getnanotime() / 1000; } -struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name, +struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_base_name, uint64_t us_thread_start) { struct tr2tls_thread_ctx *ctx = xcalloc(1, sizeof(*ctx)); + struct strbuf buf = STRBUF_INIT; /* * Implicitly "tr2tls_push_self()" to capture the thread's start @@ -47,12 +50,13 @@ struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name, ctx->thread_id = tr2tls_locked_increment(&tr2_next_thread_id); - strbuf_init(&ctx->thread_name, 0); + strbuf_init(&buf, 0); if (ctx->thread_id) - strbuf_addf(&ctx->thread_name, "th%02d:", ctx->thread_id); - strbuf_addstr(&ctx->thread_name, thread_name); - if (ctx->thread_name.len > TR2_MAX_THREAD_NAME) - strbuf_setlen(&ctx->thread_name, TR2_MAX_THREAD_NAME); + strbuf_addf(&buf, "th%02d:", ctx->thread_id); + strbuf_addstr(&buf, thread_base_name); + if (buf.len > TR2_MAX_THREAD_NAME) + strbuf_setlen(&buf, TR2_MAX_THREAD_NAME); + ctx->thread_name = strbuf_detach(&buf, NULL); pthread_setspecific(tr2tls_key, ctx); @@ -69,9 +73,9 @@ struct tr2tls_thread_ctx *tr2tls_get_self(void) ctx = pthread_getspecific(tr2tls_key); /* - * If the thread-proc did not call trace2_thread_start(), we won't - * have any TLS data associated with the current thread. Fix it - * here and silently continue. + * If the current thread's thread-proc did not call + * trace2_thread_start(), then the thread will not have any + * thread-local storage. Create it now and silently continue. */ if (!ctx) ctx = tr2tls_create_self("unknown", getnanotime() / 1000); @@ -95,7 +99,7 @@ void tr2tls_unset_self(void) pthread_setspecific(tr2tls_key, NULL); - strbuf_release(&ctx->thread_name); + free((char *)ctx->thread_name); free(ctx->array_us_start); free(ctx); } @@ -113,7 +117,7 @@ void tr2tls_pop_self(void) struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); if (!ctx->nr_open_regions) - BUG("no open regions in thread '%s'", ctx->thread_name.buf); + BUG("no open regions in thread '%s'", ctx->thread_name); ctx->nr_open_regions--; } @@ -179,3 +183,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 b1e327a928..f9049805d4 100644 --- a/trace2/tr2_tls.h +++ b/trace2/tr2_tls.h @@ -2,6 +2,14 @@ #define TR2_TLS_H #include "strbuf.h" +#include "trace2/tr2_ctr.h" +#include "trace2/tr2_tmr.h" + +/* + * Notice: the term "TLS" refers to "thread-local storage" in the + * Trace2 source files. This usage is borrowed from GCC and Windows. + * There is NO relation to "transport layer security". + */ /* * Arbitry limit for thread names for column alignment. @@ -9,33 +17,40 @@ #define TR2_MAX_THREAD_NAME (24) struct tr2tls_thread_ctx { - struct strbuf thread_name; + const char *thread_name; uint64_t *array_us_start; - int alloc; - int nr_open_regions; /* plays role of "nr" in ALLOC_GROW */ + size_t alloc; + size_t nr_open_regions; /* plays role of "nr" in ALLOC_GROW */ int thread_id; + struct tr2_timer_block timer_block; + struct tr2_counter_block counter_block; + unsigned int used_any_timer:1; + unsigned int used_any_per_thread_timer:1; + unsigned int used_any_counter:1; + unsigned int used_any_per_thread_counter:1; }; /* - * Create TLS data for the current thread. This gives us a place to - * put per-thread data, such as thread start time, function nesting - * and a per-thread label for our messages. - * - * We assume the first thread is "main". Other threads are given - * non-zero thread-ids to help distinguish messages from concurrent - * threads. + * Create thread-local storage for the current thread. * - * Truncate the thread name if necessary to help with column alignment - * in printf-style messages. + * The first thread in the process will have: + * { .thread_id=0, .thread_name="main" } + * Subsequent threads are given a non-zero thread_id and a thread_name + * constructed from the id and a thread base name (which is usually just + * the name of the thread-proc function). For example: + * { .thread_id=10, .thread_name="th10:fsm-listen" } + * This helps to identify and distinguish messages from concurrent threads. + * The ctx.thread_name field is truncated if necessary to help with column + * alignment in printf-style messages. * * In this and all following functions the term "self" refers to the * current thread. */ -struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name, +struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_base_name, uint64_t us_thread_start); /* - * Get our TLS data. + * Get the thread-local storage pointer of the current thread. */ struct tr2tls_thread_ctx *tr2tls_get_self(void); @@ -45,7 +60,7 @@ struct tr2tls_thread_ctx *tr2tls_get_self(void); int tr2tls_is_main_thread(void); /* - * Free our TLS data. + * Free the current thread's thread-local storage. */ void tr2tls_unset_self(void); @@ -81,12 +96,12 @@ uint64_t tr2tls_region_elasped_self(uint64_t us); uint64_t tr2tls_absolute_elapsed(uint64_t us); /* - * Initialize the tr2 TLS system. + * Initialize thread-local storage for Trace2. */ void tr2tls_init(void); /* - * Free all tr2 TLS resources. + * Free all Trace2 thread-local storage resources. */ void tr2tls_release(void); @@ -100,4 +115,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..31d0e4d1bd --- /dev/null +++ b/trace2/tr2_tmr.c @@ -0,0 +1,183 @@ +#include "git-compat-util.h" +#include "thread-utils.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" +#include "trace2/tr2_tmr.h" +#include "trace.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 */ |