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@igalia.com>
Reviewed-by: Lionel Landwerlin <lionel.g.landwerlin@intel.com>
Part-of: <https://gitlab.freedesktop.org/mesa/mesa/-/merge_requests/16475>

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);
    }
 }
 

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;

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},

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