[PATCH v1 10/25] structured-logging: add timer facility

[git@jeffhostetler.com]

From: Jeff Hostetler <jeffhost@microsoft.com>

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@microsoft.com>
---
 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