From: Jeff Hostetler <jeffhost@xxxxxxxxxxxxx>
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 <jeffhost@xxxxxxxxxxxxx>
---
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
