From: Jeff Hostetler <[email protected]> Add timer facility to structured logging. This allows stopwatch-like operations over the life of the git process. Timer data is summarized in the "cmd_exit" event.
Signed-off-by: Jeff Hostetler <[email protected]> --- Documentation/config.txt | 6 ++ structured-logging.c | 180 +++++++++++++++++++++++++++++++++++++++++++++++ structured-logging.h | 19 +++++ 3 files changed, 205 insertions(+) diff --git a/Documentation/config.txt b/Documentation/config.txt index 88f93fe..7817966 100644 --- a/Documentation/config.txt +++ b/Documentation/config.txt @@ -3189,6 +3189,12 @@ code. This is intended to be an extendable facility where new events can easily be added (possibly only for debugging or performance testing purposes). +slog.timers:: + (EXPERIMENTAL) May be set to a boolean value or a list of comma + separated tokens. Controls which categories of SLOG timers are + enabled. Defaults to off. Data for enabled timers is added to + the `cmd_exit` event. + splitIndex.maxPercentChange:: When the split index feature is used, this specifies the percent of entries the split index can contain compared to the diff --git a/structured-logging.c b/structured-logging.c index 9cbf3bd..215138c 100644 --- a/structured-logging.c +++ b/structured-logging.c @@ -15,6 +15,26 @@ #define SLOG_VERSION 0 +struct timer_data { + char *category; + char *name; + uint64_t total_ns; + uint64_t min_ns; + uint64_t max_ns; + uint64_t start_ns; + int count; + int started; +}; + +struct timer_data_array { + struct timer_data **array; + size_t nr, alloc; +}; + +static struct timer_data_array my__timers; +static void format_timers(struct json_writer *jw); +static void free_timers(void); + static uint64_t my__start_time; static uint64_t my__exit_time; static int my__is_config_loaded; @@ -41,6 +61,7 @@ struct category_filter }; static struct category_filter my__detail_categories; +static struct category_filter my__timer_categories; static void set_want_categories(struct category_filter *cf, const char *value) { @@ -228,6 +249,12 @@ static void emit_exit_event(void) jw_object_intmax(&jw, "slog", SLOG_VERSION); } jw_end(&jw); + + if (my__timers.nr) { + jw_object_inline_begin_object(&jw, "timers"); + format_timers(&jw); + jw_end(&jw); + } } jw_end(&jw); @@ -294,6 +321,12 @@ static int cfg_detail(const char *key, const char *value) return 0; } +static int cfg_timers(const char *key, const char *value) +{ + set_want_categories(&my__timer_categories, value); + return 0; +} + int slog_default_config(const char *key, const char *value) { const char *sub; @@ -314,6 +347,8 @@ int slog_default_config(const char *key, const char *value) return cfg_pretty(key, value); if (!strcmp(sub, "detail")) return cfg_detail(key, value); + if (!strcmp(sub, "timers")) + return cfg_timers(key, value); } return 0; @@ -371,6 +406,7 @@ static void do_final_steps(int in_signal) argv_array_clear(&my__argv); jw_release(&my__errors); strbuf_release(&my__session_id); + free_timers(); } static void slog_atexit(void) @@ -519,4 +555,148 @@ void slog_emit_detail_event(const char *category, const char *label, emit_detail_event(category, label, data); } +int slog_start_timer(const char *category, const char *name) +{ + int k; + struct timer_data *td; + + if (!want_category(&my__timer_categories, category)) + return SLOG_UNDEFINED_TIMER_ID; + if (!name || !*name) + return SLOG_UNDEFINED_TIMER_ID; + + for (k = 0; k < my__timers.nr; k++) { + td = my__timers.array[k]; + if (!strcmp(category, td->category) && !strcmp(name, td->name)) + goto start_timer; + } + + td = xcalloc(1, sizeof(struct timer_data)); + td->category = xstrdup(category); + td->name = xstrdup(name); + td->min_ns = UINT64_MAX; + + ALLOC_GROW(my__timers.array, my__timers.nr + 1, my__timers.alloc); + my__timers.array[my__timers.nr++] = td; + +start_timer: + if (td->started) + BUG("slog.timer '%s:%s' already started", + td->category, td->name); + + td->start_ns = getnanotime(); + td->started = 1; + + return k; +} + +static void stop_timer(struct timer_data *td) +{ + uint64_t delta_ns = getnanotime() - td->start_ns; + + td->count++; + td->total_ns += delta_ns; + if (delta_ns < td->min_ns) + td->min_ns = delta_ns; + if (delta_ns > td->max_ns) + td->max_ns = delta_ns; + td->started = 0; +} + +void slog_stop_timer(int tid) +{ + struct timer_data *td; + + if (tid == SLOG_UNDEFINED_TIMER_ID) + return; + if (tid >= my__timers.nr || tid < 0) + BUG("Invalid slog.timer id '%d'", tid); + + td = my__timers.array[tid]; + if (!td->started) + BUG("slog.timer '%s:%s' not started", td->category, td->name); + + stop_timer(td); +} + +static int sort_timers_cb(const void *a, const void *b) +{ + struct timer_data *td_a = *(struct timer_data **)a; + struct timer_data *td_b = *(struct timer_data **)b; + int r; + + r = strcmp(td_a->category, td_b->category); + if (r) + return r; + return strcmp(td_a->name, td_b->name); +} + +static void format_a_timer(struct json_writer *jw, struct timer_data *td, + int force_stop) +{ + jw_object_inline_begin_object(jw, td->name); + { + jw_object_intmax(jw, "count", td->count); + jw_object_intmax(jw, "total_us", td->total_ns / 1000); + if (td->count > 1) { + uint64_t avg_ns = td->total_ns / td->count; + + jw_object_intmax(jw, "min_us", td->min_ns / 1000); + jw_object_intmax(jw, "max_us", td->max_ns / 1000); + jw_object_intmax(jw, "avg_us", avg_ns / 1000); + } + if (force_stop) + jw_object_true(jw, "force_stop"); + } + jw_end(jw); +} + +static void format_timers(struct json_writer *jw) +{ + const char *open_category = NULL; + int k; + + QSORT(my__timers.array, my__timers.nr, sort_timers_cb); + + for (k = 0; k < my__timers.nr; k++) { + struct timer_data *td = my__timers.array[k]; + int force_stop = td->started; + + if (force_stop) + stop_timer(td); + + if (!open_category) { + jw_object_inline_begin_object(jw, td->category); + open_category = td->category; + } + else if (strcmp(open_category, td->category)) { + jw_end(jw); + jw_object_inline_begin_object(jw, td->category); + open_category = td->category; + } + + format_a_timer(jw, td, force_stop); + } + + if (open_category) + jw_end(jw); +} + +static void free_timers(void) +{ + int k; + + for (k = 0; k < my__timers.nr; k++) { + struct timer_data *td = my__timers.array[k]; + + free(td->category); + free(td->name); + free(td); + } + + FREE_AND_NULL(my__timers.array); + my__timers.nr = 0; + my__timers.alloc = 0; +} + #endif diff --git a/structured-logging.h b/structured-logging.h index 01ae55d..a29aa6e 100644 --- a/structured-logging.h +++ b/structured-logging.h @@ -5,6 +5,8 @@ struct json_writer; typedef int (*slog_fn_main_t)(int, const char **); +#define SLOG_UNDEFINED_TIMER_ID (-1) + #if !defined(STRUCTURED_LOGGING) /* * Structured logging is not available. @@ -21,6 +23,8 @@ typedef int (*slog_fn_main_t)(int, const char **); #define slog_error_message(prefix, fmt, params) do { } while (0) #define slog_want_detail_event(category) (0) #define slog_emit_detail_event(category, label, data) do { } while (0) +#define slog_start_timer(category, name) (SLOG_UNDEFINED_TIMER_ID) +static inline void slog_stop_timer(int tid) { }; #else @@ -107,5 +111,20 @@ int slog_want_detail_event(const char *category); void slog_emit_detail_event(const char *category, const char *label, const struct json_writer *data); +/* + * Define and start or restart a structured logging timer. Stats for the + * timer will be added to the "cmd_exit" event. Use a timer when you are + * interested in the net time of an operation (such as part of a computation + * in a loop) but don't want a detail event for each iteration. + * + * Returns a timer id. + */ +int slog_start_timer(const char *category, const char *name); + +/* + * Stop the timer. + */ +void slog_stop_timer(int tid); + #endif /* STRUCTURED_LOGGING */ #endif /* STRUCTURED_LOGGING_H */ -- 2.9.3
