freedreno: add logging infrastructure

Provides a way to log msgs timestamped at the corresponding position in
the GPU cmdstream, mostly for the purposes of profiling.

Signed-off-by: Rob Clark <robdclark@chromium.org>
Part-of: <https://gitlab.freedesktop.org/mesa/mesa/-/merge_requests/4366>

src/gallium/drivers/freedreno/Makefile.sources

@@ -14,6 +14,8 @@ C_SOURCES := \
 	freedreno_fence.h \
 	freedreno_gmem.c \
 	freedreno_gmem.h \
+	freedreno_log.c \
+	freedreno_log.h \
 	freedreno_program.c \
 	freedreno_program.h \
 	freedreno_query.c \

src/gallium/drivers/freedreno/freedreno_batch.c

@@ -102,6 +102,8 @@ batch_init(struct fd_batch *batch)
 	assert(batch->resources->entries == 0);
 
 	util_dynarray_init(&batch->samples, NULL);
+
+	list_inithead(&batch->log_chunks);
 }
 
 struct fd_batch *
@@ -191,6 +193,8 @@ batch_fini(struct fd_batch *batch)
 		fd_hw_sample_reference(batch->ctx, &samp, NULL);
 	}
 	util_dynarray_fini(&batch->samples);
+
+	assert(list_is_empty(&batch->log_chunks));
 }
 
 static void

src/gallium/drivers/freedreno/freedreno_batch.h

@@ -240,6 +240,8 @@ struct fd_batch {
 	uint32_t tessparam_size;
 
 	struct fd_ringbuffer *tess_addrs_constobj;
+
+	struct list_head log_chunks;  /* list of unflushed log chunks in fifo order */
 };
 
 struct fd_batch * fd_batch_create(struct fd_context *ctx, bool nondraw);

src/gallium/drivers/freedreno/freedreno_context.c

@@ -28,6 +28,7 @@
 #include "freedreno_blitter.h"
 #include "freedreno_draw.h"
 #include "freedreno_fence.h"
+#include "freedreno_log.h"
 #include "freedreno_program.h"
 #include "freedreno_resource.h"
 #include "freedreno_texture.h"
@@ -89,6 +90,9 @@ out:
 	fd_fence_ref(&ctx->last_fence, fence);
 
 	fd_fence_ref(&fence, NULL);
+
+	if (flags & PIPE_FLUSH_END_OF_FRAME)
+		fd_log_eof(ctx);
 }
 
 static void
@@ -168,6 +172,9 @@ fd_context_destroy(struct pipe_context *pctx)
 
 	DBG("");
 
+	fd_log_process(ctx, true);
+	assert(list_is_empty(&ctx->log_chunks));
+
 	fd_fence_ref(&ctx->last_fence, NULL);
 
 	util_copy_framebuffer_state(&ctx->framebuffer, NULL);
@@ -404,6 +411,13 @@ fd_context_init(struct fd_context *ctx, struct pipe_screen *pscreen,
 
 	list_inithead(&ctx->hw_active_queries);
 	list_inithead(&ctx->acc_active_queries);
+	list_inithead(&ctx->log_chunks);
+
+	if ((fd_mesa_debug & FD_DBG_LOG) &&
+			!(ctx->record_timestamp && ctx->ts_to_ns)) {
+		printf("logging not supported!\n");
+		fd_mesa_debug &= ~FD_DBG_LOG;
+	}
 
 	return pctx;
 

src/gallium/drivers/freedreno/freedreno_context.h

@@ -355,6 +355,13 @@ struct fd_context {
 	/* handling for barriers: */
 	void (*framebuffer_barrier)(struct fd_context *ctx);
 
+	/* logger: */
+	void (*record_timestamp)(struct fd_ringbuffer *ring, struct fd_bo *bo, unsigned offset);
+	uint64_t (*ts_to_ns)(uint64_t ts);
+
+	struct list_head log_chunks;  /* list of flushed log chunks in fifo order */
+	unsigned frame_nr;            /* frame counter (for fd_log) */
+
 	/*
 	 * Common pre-cooked VBO state (used for a3xx and later):
 	 */

src/gallium/drivers/freedreno/freedreno_gmem.c

@@ -34,6 +34,7 @@
 #include "freedreno_gmem.h"
 #include "freedreno_context.h"
 #include "freedreno_fence.h"
+#include "freedreno_log.h"
 #include "freedreno_resource.h"
 #include "freedreno_query_hw.h"
 #include "freedreno_util.h"
@@ -531,6 +532,7 @@ flush_ring(struct fd_batch *batch)
 			&timestamp);
 
 	fd_fence_populate(batch->fence, timestamp, out_fence_fd);
+	fd_log_flush(batch);
 }
 
 void

src/gallium/drivers/freedreno/freedreno_log.c

@@ -0,0 +1,205 @@
+/*
+ * Copyright © 2020 Google, Inc.
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a
+ * copy of this software and associated documentation files (the "Software"),
+ * to deal in the Software without restriction, including without limitation
+ * the rights to use, copy, modify, merge, publish, distribute, sublicense,
+ * and/or sell copies of the Software, and to permit persons to whom the
+ * Software is furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice (including the next
+ * paragraph) shall be included in all copies or substantial portions of the
+ * Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
+ * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+ * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+ * SOFTWARE.
+ */
+
+#include <inttypes.h>
+#include <stdarg.h>
+
+#include "freedreno_log.h"
+#include "freedreno_batch.h"
+#include "freedreno_context.h"
+
+#include "util/u_fifo.h"
+
+/* A simple(ish) logging mechanism with timestamps recorded at the
+ * corresponding point in the cmdstream.  The overall design is based
+ * on fd_log_chunk's, which buffer up up to 'msgs_per_chunk' log msgs
+ * and track an associated bo containing timestamps written from the
+ * GPU.
+ *
+ * The fd_batch tracks a list of fd_log_chunk's.  When fd_log() is
+ * called, msgs are pushed into the last (most recent) chunk until
+ * it is full, at which point a new chunk is created.  And cmds are
+ * inserted into the cmdstream to record the GPU timestamp that
+ * corresponds with the log msg.
+ *
+ * When the batch is flushed, the list of log chunks is transferred
+ * to the end of fd_context's list of chunks, and we attempt to pop
+ * chunks from the from of the list if their timestamp bo is idle (ie.
+ * the GPU has finished the batch that was writing the timestamps).
+ *
+ * NOTE: this is only appropriate for IB1 (ie. "gmem" level) cmdstream,
+ * the IB2 (draw/binning) cmdstream can be executed multiple times,
+ * which this mechanism is not designed to support.  Other existing
+ * GL level queries (time-elapsed, amd-perfcntrs) are more appropriate
+ * for profiling at that level.
+ */
+
+const unsigned bo_size = 0x1000;
+const unsigned msgs_per_chunk = bo_size / sizeof(uint64_t);
+
+struct fd_log_chunk {
+	struct list_head node;
+
+	unsigned num_msgs;
+	struct util_fifo *msg_fifo;
+
+	/* list of recorded 64b timestamps */
+	struct fd_bo *timestamps_bo;
+
+	bool eof;
+};
+
+static struct fd_log_chunk *
+get_chunk(struct fd_batch *batch)
+{
+	struct fd_log_chunk *chunk;
+
+	/* do we currently have a non-full chunk to append msgs to? */
+	if (!list_is_empty(&batch->log_chunks)) {
+		chunk = list_last_entry(&batch->log_chunks,
+				struct fd_log_chunk, node);
+		if (chunk->num_msgs < msgs_per_chunk)
+			return chunk;
+	}
+
+	/* .. if not, then create a new one: */
+	chunk = calloc(1, sizeof(*chunk));
+	chunk->msg_fifo = u_fifo_create(msgs_per_chunk);
+	chunk->timestamps_bo = fd_bo_new(batch->ctx->screen->dev, bo_size,
+			DRM_FREEDRENO_GEM_TYPE_KMEM, "timestamps");
+
+	list_addtail(&chunk->node, &batch->log_chunks);
+
+	return chunk;
+}
+
+static void
+free_chunk(struct fd_log_chunk *chunk)
+{
+	assert(chunk->msg_fifo->num == 0);
+	u_fifo_destroy(chunk->msg_fifo);
+	fd_bo_del(chunk->timestamps_bo);
+	list_del(&chunk->node);
+	free(chunk);
+}
+
+static void
+process_chunk(struct fd_context *ctx, struct fd_log_chunk *chunk)
+{
+	printf("+----- TS -----+ +----- NS -----+ +-- Δ --+  +----- MSG -----\n");
+
+	uint64_t *timestamps = fd_bo_map(chunk->timestamps_bo);
+	uint64_t last_time_ns = 0;
+	uint64_t first_time_ns = 0;
+	unsigned n = 0;
+	char *msg;
+
+	while (u_fifo_pop(chunk->msg_fifo, (void **)&msg)) {
+		uint64_t ts = timestamps[n++];
+		uint64_t ns = ctx->ts_to_ns(ts);
+		int32_t delta = last_time_ns ? ns - last_time_ns : 0;
+
+		if (!first_time_ns)
+			first_time_ns = ns;
+
+		last_time_ns = ns;
+
+		printf("%016"PRIu64" %016"PRIu64" %+9d: %s\n", ts, ns, delta, msg);
+		free(msg);
+
+	}
+
+	printf("ELAPSED: %"PRIu64" ns\n", last_time_ns - first_time_ns);
+
+	if (chunk->eof)
+		printf("END OF FRAME %u\n", ctx->frame_nr++);
+}
+
+void
+fd_log_process(struct fd_context *ctx, bool wait)
+{
+	while (!list_is_empty(&ctx->log_chunks)) {
+		struct fd_log_chunk *chunk = list_first_entry(&ctx->log_chunks,
+				struct fd_log_chunk, node);
+
+		unsigned flags = DRM_FREEDRENO_PREP_READ;
+		if (!wait)
+			flags |= DRM_FREEDRENO_PREP_NOSYNC;
+
+		int ret = fd_bo_cpu_prep(chunk->timestamps_bo, ctx->pipe, flags);
+		if (ret)
+			break;
+
+		process_chunk(ctx, chunk);
+		free_chunk(chunk);
+	}
+}
+
+void
+fd_log_flush(struct fd_batch *batch)
+{
+	/* transfer batch's log chunks to context: */
+	list_splicetail(&batch->log_chunks, &batch->ctx->log_chunks);
+	list_inithead(&batch->log_chunks);
+}
+
+void
+_fd_log(struct fd_batch *batch, const char *fmt, ...)
+{
+	struct fd_context *ctx = batch->ctx;
+	struct fd_ringbuffer *ring = batch->nondraw ? batch->draw : batch->gmem;
+	struct fd_log_chunk *chunk = get_chunk(batch);
+	char *msg;
+
+	va_list ap;
+	va_start(ap, fmt);
+	if (vasprintf(&msg, fmt, ap) < 0)
+		return;
+	va_end(ap);
+
+	u_fifo_add(chunk->msg_fifo, msg);
+
+	assert(ctx->record_timestamp);
+	ctx->record_timestamp(ring, chunk->timestamps_bo,
+			chunk->num_msgs * sizeof(uint64_t));
+
+	chunk->num_msgs++;
+}
+
+void fd_log_eof(struct fd_context *ctx)
+{
+	if (!(fd_mesa_debug & FD_DBG_LOG))
+		return;
+
+	if (list_is_empty(&ctx->log_chunks)) {
+		printf("WARNING: no log chunks!\n");
+		return;
+	}
+
+	struct fd_log_chunk *last_chunk = list_last_entry(&ctx->log_chunks,
+			struct fd_log_chunk, node);
+	last_chunk->eof = true;
+
+	/* and process any chunks that are now idle/ready: */
+	fd_log_process(ctx, false);
+}

src/gallium/drivers/freedreno/freedreno_log.h

@@ -0,0 +1,65 @@
+/*
+ * Copyright © 2020 Google, Inc.
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a
+ * copy of this software and associated documentation files (the "Software"),
+ * to deal in the Software without restriction, including without limitation
+ * the rights to use, copy, modify, merge, publish, distribute, sublicense,
+ * and/or sell copies of the Software, and to permit persons to whom the
+ * Software is furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice (including the next
+ * paragraph) shall be included in all copies or substantial portions of the
+ * Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
+ * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+ * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+ * SOFTWARE.
+ */
+
+#ifndef FREEDRENO_LOG_H_
+#define FREEDRENO_LOG_H_
+
+#include "freedreno_util.h"
+
+struct fd_batch;
+struct fd_context;
+
+void fd_log_process(struct fd_context *ctx, bool wait);
+void fd_log_flush(struct fd_batch *batch);
+void _fd_log(struct fd_batch *batch, const char *fmt, ...)
+	_util_printf_format(2, 3);
+
+/* macro wrapper so that arguments are not evaluated when logging is not
+ * enabled:
+ */
+#define fd_log(__batch, __fmt, ...) 							\
+	do { 														\
+		if (unlikely(fd_mesa_debug & FD_DBG_LOG)) { 			\
+			_fd_log(__batch, __fmt, ##__VA_ARGS__); 			\
+		} else { 												\
+			DBG(__fmt, ##__VA_ARGS__); 							\
+		} 														\
+	} while (0)
+
+/* A variant of fd_log() which provides a FILE* stream to write the
+ * log msg into, mostly to make u_dump_state stuff useful
+ */
+#define fd_log_stream(__batch, __stream, __exp)					\
+	do {														\
+		if (unlikely(fd_mesa_debug & FD_DBG_LOG)) { 			\
+			char buf[1024];										\
+			FILE *__stream = fmemopen(buf, sizeof(buf), "w");	\
+			__exp;												\
+			fclose(__stream);									\
+			_fd_log(__batch, "%s", buf);						\
+		} 														\
+	} while (0)
+
+void fd_log_eof(struct fd_context *ctx);
+
+#endif /* FREEDRENO_LOG_H_ */

src/gallium/drivers/freedreno/freedreno_screen.c

@@ -72,7 +72,7 @@ static const struct debug_named_value debug_options[] = {
 		{"noscis",    FD_DBG_NOSCIS, "Disable scissor optimization"},
 		{"direct",    FD_DBG_DIRECT, "Force inline (SS_DIRECT) state loads"},
 		{"nobypass",  FD_DBG_NOBYPASS, "Disable GMEM bypass"},
-		/* BIT(7) */
+		{"log",       FD_DBG_LOG,    "Enable GPU timestamp based logging (a6xx+)"},
 		{"nobin",     FD_DBG_NOBIN,  "Disable hw binning"},
 		{"nogmem",    FD_DBG_NOGMEM,  "Disable GMEM rendering (bypass only)"},
 		/* BIT(10) */

src/gallium/drivers/freedreno/freedreno_util.h

@@ -69,7 +69,7 @@ enum fd_debug_flag {
 	FD_DBG_NOSCIS       = BITFIELD_BIT(4),
 	FD_DBG_DIRECT       = BITFIELD_BIT(5),
 	FD_DBG_NOBYPASS     = BITFIELD_BIT(6),
-	/* BIT(7) */
+	FD_DBG_LOG          = BITFIELD_BIT(7),
 	FD_DBG_NOBIN        = BITFIELD_BIT(8),
 	FD_DBG_NOGMEM       = BITFIELD_BIT(9),
 	/* BIT(10) */

src/gallium/drivers/freedreno/log-parser.py

@@ -0,0 +1,73 @@
+#!/usr/bin/env python3
+
+import re
+import sys
+
+def main():
+    file = open(sys.argv[1], "r")
+    lines = file.read().split('\n')
+
+    gmem_match = re.compile(r": rendering (\S+)x(\S+) tiles")
+    sysmem_match = re.compile(r": rendering sysmem (\S+)x(\S+)")
+    blit_match = re.compile(r": END BLIT")
+    elapsed_match = re.compile(r"ELAPSED: (\S+) ns")
+    eof_match = re.compile(r"END OF FRAME (\S+)")
+
+    # Times in ns:
+    times_blit = []
+    times_sysmem = []
+    times_gmem = []
+    times = None
+
+    for line in lines:
+        match = re.search(gmem_match, line)
+        if match is not None:
+            #print("GMEM")
+            if times is not None:
+                print("expected times to not be set yet")
+            times = times_gmem
+            continue
+
+        match = re.search(sysmem_match, line)
+        if match is not None:
+            #print("SYSMEM")
+            if times is not None:
+                print("expected times to not be set yet")
+            times = times_sysmem
+            continue
+
+        match = re.search(blit_match, line)
+        if match is not None:
+            #print("BLIT")
+            if times is not None:
+                print("expected times to not be set yet")
+            times = times_blit
+            continue
+
+        match = re.search(eof_match, line)
+        if match is not None:
+            frame_nr = int(match.group(1))
+            print("FRAME[{}]: {} blits ({:,} ns), {} SYSMEM ({:,} ns), {} GMEM ({:,} ns)".format(
+                    frame_nr,
+                    len(times_blit), sum(times_blit),
+                    len(times_sysmem), sum(times_sysmem),
+                    len(times_gmem), sum(times_gmem)
+                ))
+            times_blit = []
+            times_sysmem = []
+            times_gmem = []
+            times = None
+            continue
+
+        match = re.search(elapsed_match, line)
+        if match is not None:
+            time = int(match.group(1))
+            #print("ELAPSED: " + str(time) + " ns")
+            times.append(time)
+            times = None
+            continue
+
+
+if __name__ == "__main__":
+    main()
+

src/gallium/drivers/freedreno/meson.build

@@ -34,6 +34,8 @@ files_libfreedreno = files(
   'freedreno_fence.h',
   'freedreno_gmem.c',
   'freedreno_gmem.h',
+  'freedreno_log.c',
+  'freedreno_log.h',
   'freedreno_program.c',
   'freedreno_program.h',
   'freedreno_query.c',