trace2: implement trace2_printf() for event target

The trace2 event target does not have an implementation for
trace2_printf(). While the event target is for structured events, and
trace2_printf() is for unstructured, human-readable messages, it may
still be useful to wrap these unstructured messages in a structured JSON
object. Among other things, it may reduce confusion when manually
debugging using event trace data.

Add a simple implementation for the event target that wraps
trace2_printf() messages in a minimal JSON object. Document this in
Documentation/technical/api-trace2.txt, and bump the event format
version since we're adding a new event type.

Signed-off-by: Josh Steadmon <steadmon@google.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>

diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt
index de5fc250595b7a216e32623e6959b29673c2d192..5817b18310c0f9a344cb7df0cf0fd5b1f2427280 100644 (file)
--- a/Documentation/technical/api-trace2.txt
+++ b/Documentation/technical/api-trace2.txt
@@ -128,7 +128,7 @@ yields
 
 ------------
 $ cat ~/log.event
-{"event":"version","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.620713Z","file":"common-main.c","line":38,"evt":"3","exe":"2.20.1.155.g426c96fcdb"}
+{"event":"version","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.620713Z","file":"common-main.c","line":38,"evt":"4","exe":"2.20.1.155.g426c96fcdb"}
 {"event":"start","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621027Z","file":"common-main.c","line":39,"t_abs":0.001173,"argv":["git","version"]}
 {"event":"cmd_name","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621122Z","file":"git.c","line":432,"name":"version","hierarchy":"version"}
 {"event":"exit","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621236Z","file":"git.c","line":662,"t_abs":0.001227,"code":0}
@@ -344,7 +344,7 @@ only present on the "start" and "atexit" events.
 {
        "event":"version",
        ...
-       "evt":"3",                     # EVENT format version
+       "evt":"4",                     # EVENT format version
        "exe":"2.20.1.155.g426c96fcdb" # git version
 }
 ------------
@@ -835,6 +835,19 @@ The "value" field may be an integer or a string.
 }
 ------------
 
+`"printf"`::
+       This event logs a human-readable message with no particular formatting
+       guidelines.
++
+------------
+{
+       "event":"printf",
+       ...
+       "t_abs":0.015905,      # elapsed time in seconds
+       "msg":"Hello world"    # optional
+}
+------------
+
 
 == Example Trace2 API Usage
 

diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c
index 59910a1a4f7c0f280fb6839873429d9cc877d3cf..45b0850a5ec5c8d1e35df940da003fa9bbddd2ba 100644 (file)
--- a/trace2/tr2_tgt_event.c
+++ b/trace2/tr2_tgt_event.c
@@ -24,7 +24,7 @@ static struct tr2_dst tr2dst_event = {
  * a new field to an existing event, do not require an increment to the EVENT
  * format version.
  */
-#define TR2_EVENT_VERSION "3"
+#define TR2_EVENT_VERSION "4"
 
 /*
  * Region nesting limit for messages written to the event target.
@@ -622,6 +622,24 @@ static void fn_data_json_fl(const char *file, int line,
        }
 }
 
+static void fn_printf_va_fl(const char *file, int line,
+                           uint64_t us_elapsed_absolute,
+                           const char *fmt, va_list ap)
+{
+       const char *event_name = "printf";
+       struct json_writer jw = JSON_WRITER_INIT;
+       double t_abs = (double)us_elapsed_absolute / 1000000.0;
+
+       jw_object_begin(&jw, 0);
+       event_fmt_prepare(event_name, file, line, NULL, &jw);
+       jw_object_double(&jw, "t_abs", 6, t_abs);
+       maybe_add_string_va(&jw, "msg", fmt, ap);
+       jw_end(&jw);
+
+       tr2_dst_write_line(&tr2dst_event, &jw.json);
+       jw_release(&jw);
+}
+
 static void fn_timer(const struct tr2_timer_metadata *meta,
                     const struct tr2_timer *timer,
                     int is_final_data)
@@ -694,7 +712,7 @@ struct tr2_tgt tr2_tgt_event = {
        .pfn_region_leave_printf_va_fl = fn_region_leave_printf_va_fl,
        .pfn_data_fl = fn_data_fl,
        .pfn_data_json_fl = fn_data_json_fl,
-       .pfn_printf_va_fl = NULL,
+       .pfn_printf_va_fl = fn_printf_va_fl,
        .pfn_timer = fn_timer,
        .pfn_counter = fn_counter,
 };