From 850ae76970dabec1fe9c53674e515f496914915d Mon Sep 17 00:00:00 2001 From: Danylo Piliaiev Date: Wed, 11 May 2022 12:29:52 +0300 Subject: [PATCH] util/u_trace: Add json output If we want to load the u_trace output somewhere for analysis it's much easier to deal with json than to parse strings. Signed-off-by: Danylo Piliaiev Reviewed-by: Lionel Landwerlin Part-of: --- src/util/perf/u_trace.c | 195 +++++++++++++++++++++++++++++++++++++++---- src/util/perf/u_trace.h | 5 ++ src/util/perf/u_trace.py | 30 +++++++ src/util/perf/u_trace_priv.h | 1 + 4 files changed, 216 insertions(+), 15 deletions(-) diff --git a/src/util/perf/u_trace.c b/src/util/perf/u_trace.c index 29c9c8c..ce2b3d4 100644 --- a/src/util/perf/u_trace.c +++ b/src/util/perf/u_trace.c @@ -108,6 +108,139 @@ struct u_trace_chunk { bool free_flush_data; }; +struct u_trace_printer { + void (*start)(struct u_trace_context *utctx); + void (*end)(struct u_trace_context *utctx); + void (*start_of_frame)(struct u_trace_context *utctx); + void (*end_of_frame)(struct u_trace_context *utctx); + void (*start_of_batch)(struct u_trace_context *utctx); + void (*end_of_batch)(struct u_trace_context *utctx); + void (*event)(struct u_trace_context *utctx, + struct u_trace_chunk *chunk, + const struct u_trace_event *evt, + uint64_t ns, int32_t delta); +}; + +static void +print_txt_start(struct u_trace_context *utctx) +{ + +} + +static void +print_txt_end_of_frame(struct u_trace_context *utctx) +{ + fprintf(utctx->out, "END OF FRAME %u\n", utctx->frame_nr); +} + +static void +print_txt_start_of_batch(struct u_trace_context *utctx) +{ + fprintf(utctx->out, "+----- NS -----+ +-- Δ --+ +----- MSG -----\n"); +} + +static void +print_txt_end_of_batch(struct u_trace_context *utctx) +{ + uint64_t elapsed = utctx->last_time_ns - utctx->first_time_ns; + fprintf(utctx->out, "ELAPSED: %"PRIu64" ns\n", elapsed); +} + +static void +print_txt_event(struct u_trace_context *utctx, + struct u_trace_chunk *chunk, + const struct u_trace_event *evt, + uint64_t ns, int32_t delta) +{ + if (evt->tp->print) { + fprintf(utctx->out, "%016"PRIu64" %+9d: %s: ", ns, delta, evt->tp->name); + evt->tp->print(utctx->out, evt->payload); + } else { + fprintf(utctx->out, "%016"PRIu64" %+9d: %s\n", ns, delta, evt->tp->name); + } +} + +static struct u_trace_printer txt_printer = { + .start = &print_txt_start, + .end = &print_txt_start, + .start_of_frame = &print_txt_start, + .end_of_frame = &print_txt_end_of_frame, + .start_of_batch = &print_txt_start_of_batch, + .end_of_batch = &print_txt_end_of_batch, + .event = &print_txt_event, +}; + +static void +print_json_start(struct u_trace_context *utctx) +{ + fprintf(utctx->out, "[\n"); +} + +static void +print_json_end(struct u_trace_context *utctx) +{ + fprintf(utctx->out, "\n]"); +} + +static void +print_json_start_of_frame(struct u_trace_context *utctx) +{ + if (utctx->frame_nr != 0) + fprintf(utctx->out, ",\n"); + fprintf(utctx->out, "{\n\"frame\": %u,\n", utctx->frame_nr); + fprintf(utctx->out, "\"batches\": [\n"); +} + +static void +print_json_end_of_frame(struct u_trace_context *utctx) +{ + fprintf(utctx->out, "]\n}\n"); + fflush(utctx->out); +} + +static void +print_json_start_of_batch(struct u_trace_context *utctx) +{ + if (utctx->batch_nr != 0) + fprintf(utctx->out, ",\n"); + fprintf(utctx->out, "{\n\"events\": [\n"); +} + +static void +print_json_end_of_batch(struct u_trace_context *utctx) +{ + uint64_t elapsed = utctx->last_time_ns - utctx->first_time_ns; + fprintf(utctx->out, "],\n"); + fprintf(utctx->out, "\"duration_ns\": %"PRIu64"\n", elapsed); + fprintf(utctx->out, "}\n"); +} + +static void +print_json_event(struct u_trace_context *utctx, + struct u_trace_chunk *chunk, + const struct u_trace_event *evt, + uint64_t ns, int32_t delta) +{ + if (utctx->event_nr != 0) + fprintf(utctx->out, ",\n"); + fprintf(utctx->out, "{\n\"event\": \"%s\",\n", evt->tp->name); + fprintf(utctx->out, "\"time_ns\": \"%016"PRIu64"\",\n", ns); + fprintf(utctx->out, "\"params\": {"); + if (evt->tp->print) + evt->tp->print_json(utctx->out, evt->payload); + fprintf(utctx->out, "}\n}\n"); +} + +static struct u_trace_printer json_printer = { + .start = print_json_start, + .end = print_json_end, + .start_of_frame = &print_json_start_of_frame, + .end_of_frame = &print_json_end_of_frame, + .start_of_batch = &print_json_start_of_batch, + .end_of_batch = &print_json_end_of_batch, + .event = &print_json_event, +}; + static struct u_trace_payload_buf * u_trace_payload_buf_create(void) { @@ -222,6 +355,7 @@ get_chunk(struct u_trace *ut, size_t payload_size) DEBUG_GET_ONCE_BOOL_OPTION(trace_instrument, "GPU_TRACE_INSTRUMENT", false) DEBUG_GET_ONCE_BOOL_OPTION(trace, "GPU_TRACE", false) DEBUG_GET_ONCE_FILE_OPTION(trace_file, "GPU_TRACEFILE", NULL, "w") +DEBUG_GET_ONCE_OPTION(trace_format, "GPU_TRACE_FORMAT", "txt") static FILE * get_tracefile(void) @@ -277,11 +411,21 @@ u_trace_context_init(struct u_trace_context *utctx, utctx->last_time_ns = 0; utctx->first_time_ns = 0; utctx->frame_nr = 0; + utctx->batch_nr = 0; + utctx->event_nr = 0; + utctx->start_of_frame = true; list_inithead(&utctx->flushed_trace_chunks); utctx->out = get_tracefile(); + const char *trace_format = debug_get_option_trace_format(); + if (strcmp(trace_format, "json") == 0) { + utctx->out_printer = &json_printer; + } else { + utctx->out_printer = &txt_printer; + } + #ifdef HAVE_PERFETTO list_add(&utctx->node, &ctx_list); #endif @@ -290,6 +434,10 @@ u_trace_context_init(struct u_trace_context *utctx, return; queue_init(utctx); + + if (utctx->out) { + utctx->out_printer->start(utctx); + } } void @@ -298,11 +446,16 @@ u_trace_context_fini(struct u_trace_context *utctx) #ifdef HAVE_PERFETTO list_del(&utctx->node); #endif + + if (utctx->out) { + utctx->out_printer->end(utctx); + fflush(utctx->out); + } + if (!utctx->queue.jobs) return; util_queue_finish(&utctx->queue); util_queue_destroy(&utctx->queue); - fflush(utctx->out); free_chunks(&utctx->flushed_trace_chunks); } @@ -329,9 +482,20 @@ process_chunk(void *job, void *gdata, int thread_index) struct u_trace_chunk *chunk = job; struct u_trace_context *utctx = chunk->utctx; + if (utctx->start_of_frame) { + utctx->start_of_frame = false; + utctx->batch_nr = 0; + if (utctx->out) { + utctx->out_printer->start_of_frame(utctx); + } + } + /* For first chunk of batch, accumulated times will be zerod: */ - if (utctx->out && !utctx->last_time_ns) { - fprintf(utctx->out, "+----- NS -----+ +-- Δ --+ +----- MSG -----\n"); + if (!utctx->last_time_ns) { + utctx->event_nr = 0; + if (utctx->out) { + utctx->out_printer->start_of_batch(utctx); + } } for (unsigned idx = 0; idx < chunk->num_traces; idx++) { @@ -358,36 +522,37 @@ process_chunk(void *job, void *gdata, int thread_index) } if (utctx->out) { - if (evt->tp->print) { - fprintf(utctx->out, "%016"PRIu64" %+9d: %s: ", ns, delta, evt->tp->name); - evt->tp->print(utctx->out, evt->payload); - } else { - fprintf(utctx->out, "%016"PRIu64" %+9d: %s\n", ns, delta, evt->tp->name); - } + utctx->out_printer->event(utctx, chunk, evt, ns, delta); } #ifdef HAVE_PERFETTO if (evt->tp->perfetto) { evt->tp->perfetto(utctx->pctx, ns, chunk->flush_data, evt->payload); } #endif + + utctx->event_nr++; } if (chunk->last) { if (utctx->out) { - uint64_t elapsed = utctx->last_time_ns - utctx->first_time_ns; - fprintf(utctx->out, "ELAPSED: %"PRIu64" ns\n", elapsed); + utctx->out_printer->end_of_batch(utctx); } + utctx->batch_nr++; utctx->last_time_ns = 0; utctx->first_time_ns = 0; } - if (chunk->free_flush_data && utctx->delete_flush_data) { - utctx->delete_flush_data(utctx, chunk->flush_data); + if (chunk->eof) { + if (utctx->out) { + utctx->out_printer->end_of_frame(utctx); + } + utctx->frame_nr++; + utctx->start_of_frame = true; } - if (utctx->out && chunk->eof) { - fprintf(utctx->out, "END OF FRAME %u\n", utctx->frame_nr++); + if (chunk->free_flush_data && utctx->delete_flush_data) { + utctx->delete_flush_data(utctx, chunk->flush_data); } } diff --git a/src/util/perf/u_trace.h b/src/util/perf/u_trace.h index 2e38f06..53f805e 100644 --- a/src/util/perf/u_trace.h +++ b/src/util/perf/u_trace.h @@ -69,6 +69,7 @@ extern "C" { struct u_trace_context; struct u_trace; struct u_trace_chunk; +struct u_trace_printer; /** * Special reserved value to indicate that no timestamp was captured, @@ -143,6 +144,7 @@ struct u_trace_context { u_trace_delete_flush_data delete_flush_data; FILE *out; + struct u_trace_printer *out_printer; /* Once u_trace_flush() is called u_trace_chunk's are queued up to * render tracepoints on a queue. The per-chunk queue jobs block until @@ -162,6 +164,9 @@ struct u_trace_context { uint64_t first_time_ns; uint32_t frame_nr; + uint32_t batch_nr; + uint32_t event_nr; + bool start_of_frame; /* list of unprocessed trace chunks in fifo order: */ struct list_head flushed_trace_chunks; diff --git a/src/util/perf/u_trace.py b/src/util/perf/u_trace.py index c0ef3db..fd02c40 100644 --- a/src/util/perf/u_trace.py +++ b/src/util/perf/u_trace.py @@ -304,14 +304,44 @@ static void __print_${trace_name}(FILE *out, const void *arg) { % endif ); } + +static void __print_json_${trace_name}(FILE *out, const void *arg) { + const struct trace_${trace_name} *__entry = + (const struct trace_${trace_name} *)arg; + % if trace.tp_print is not None: + fprintf(out, "\\"unstructured\\": \\"${trace.tp_print[0]}\\"" + % for arg in trace.tp_print[1:]: + , ${arg} + % endfor + % else: + fprintf(out, "" + % for arg in trace.tp_struct: + "\\"${arg.name}\\": \\"${arg.c_format}\\"" + % if arg != trace.tp_struct[-1]: + ", " + % endif + % endfor + % for arg in trace.tp_struct: + % if arg.to_prim_type: + ,${arg.to_prim_type.format('__entry->' + arg.name)} + % else: + ,__entry->${arg.name} + % endif + % endfor + % endif + ); +} + % else: #define __print_${trace_name} NULL +#define __print_json_${trace_name} NULL % endif static const struct u_tracepoint __tp_${trace_name} = { ALIGN_POT(sizeof(struct trace_${trace_name}), 8), /* keep size 64b aligned */ "${trace_name}", ${"true" if trace.end_of_pipe else "false"}, __print_${trace_name}, + __print_json_${trace_name}, % if trace.tp_perfetto is not None: #ifdef HAVE_PERFETTO (void (*)(void *pctx, uint64_t, const void *, const void *))${trace.tp_perfetto}, diff --git a/src/util/perf/u_trace_priv.h b/src/util/perf/u_trace_priv.h index 8733715..d925b06 100644 --- a/src/util/perf/u_trace_priv.h +++ b/src/util/perf/u_trace_priv.h @@ -44,6 +44,7 @@ struct u_tracepoint { const char *name; bool end_of_pipe; void (*print)(FILE *out, const void *payload); + void (*print_json)(FILE *out, const void *payload); #ifdef HAVE_PERFETTO /** * Callback to emit a perfetto event, such as render-stage trace -- 2.7.4