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>
Josh Steadmon committed
Aug 22, 2024 at 14:57 UTC
cbe140754bc1eb4380ffe820de121e49357a9af8
2 files changed
+35
-4
Documentation/technical/api-trace2.txt
+15
-2
@@ -128,7 +128,7 @@ yields
128
129
------------
130
$ cat ~/log.event
131
-{"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"}
131
+{"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"}
132
{"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"]}
133
{"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"}
134
{"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.
344
{
345
"event":"version",
346
...
347
- "evt":"3", # EVENT format version
347
+ "evt":"4", # EVENT format version
348
"exe":"2.20.1.155.g426c96fcdb" # git version
349
}
350
------------
@@ -835,6 +835,19 @@ The "value" field may be an integer or a string.
835
}
836
------------
837
838
+`"printf"`::
839
+ This event logs a human-readable message with no particular formatting
840
+ guidelines.
841
++
842
+------------
843
+{
844
+ "event":"printf",
845
+ ...
846
+ "t_abs":0.015905, # elapsed time in seconds
847
+ "msg":"Hello world" # optional
848
+}
849
+------------
850
+
851
852
== Example Trace2 API Usage
853
trace2/tr2_tgt_event.c
+20
-2
@@ -24,7 +24,7 @@ static struct tr2_dst tr2dst_event = {
24
* a new field to an existing event, do not require an increment to the EVENT
25
* format version.
26
*/
27
-#define TR2_EVENT_VERSION "3"
27
+#define TR2_EVENT_VERSION "4"
28
29
/*
30
* 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,
622
}
623
}
624
625
+static void fn_printf_va_fl(const char *file, int line,
626
+ uint64_t us_elapsed_absolute,
627
+ const char *fmt, va_list ap)
628
+{
629
+ const char *event_name = "printf";
630
+ struct json_writer jw = JSON_WRITER_INIT;
631
+ double t_abs = (double)us_elapsed_absolute / 1000000.0;
632
+
633
+ jw_object_begin(&jw, 0);
634
+ event_fmt_prepare(event_name, file, line, NULL, &jw);
635
+ jw_object_double(&jw, "t_abs", 6, t_abs);
636
+ maybe_add_string_va(&jw, "msg", fmt, ap);
637
+ jw_end(&jw);
638
+
639
+ tr2_dst_write_line(&tr2dst_event, &jw.json);
640
+ jw_release(&jw);
641
+}
642
+
643
static void fn_timer(const struct tr2_timer_metadata *meta,
644
const struct tr2_timer *timer,
645
int is_final_data)
@@ -694,7 +712,7 @@ struct tr2_tgt tr2_tgt_event = {
712
.pfn_region_leave_printf_va_fl = fn_region_leave_printf_va_fl,
713
.pfn_data_fl = fn_data_fl,
714
.pfn_data_json_fl = fn_data_json_fl,
697
- .pfn_printf_va_fl = NULL,
715
+ .pfn_printf_va_fl = fn_printf_va_fl,
716
.pfn_timer = fn_timer,
717
.pfn_counter = fn_counter,
718
};