Mesa (main): util/u_trace: Add json output
GitLab Mirror
gitlab-mirror at kemper.freedesktop.org
Thu May 19 08:16:10 UTC 2022
Module: Mesa
Branch: main
Commit: 850ae76970dabec1fe9c53674e515f496914915d
URL: http://cgit.freedesktop.org/mesa/mesa/commit/?id=850ae76970dabec1fe9c53674e515f496914915d
Author: Danylo Piliaiev <dpiliaiev at igalia.com>
Date: Wed May 11 12:29:52 2022 +0300
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 <dpiliaiev at igalia.com>
Reviewed-by: Lionel Landwerlin <lionel.g.landwerlin at intel.com>
Part-of: <https://gitlab.freedesktop.org/mesa/mesa/-/merge_requests/16475>
---
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 29c9c8c5652..ce2b3d411e6 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 2e38f068d40..53f805e4007 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 c0ef3db9d86..fd02c401b3f 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 87337155a23..d925b06526b 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
More information about the mesa-commit
mailing list