From a0ca1462f31747d028abe9106309f6c95c3daabf Mon Sep 17 00:00:00 2001 From: Rob Clark Date: Sat, 28 Mar 2020 09:57:35 -0700 Subject: [PATCH] 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 Part-of: --- .../drivers/freedreno/Makefile.sources | 2 + .../drivers/freedreno/freedreno_batch.c | 4 + .../drivers/freedreno/freedreno_batch.h | 2 + .../drivers/freedreno/freedreno_context.c | 14 ++ .../drivers/freedreno/freedreno_context.h | 7 + .../drivers/freedreno/freedreno_gmem.c | 2 + src/gallium/drivers/freedreno/freedreno_log.c | 205 ++++++++++++++++++ src/gallium/drivers/freedreno/freedreno_log.h | 65 ++++++ .../drivers/freedreno/freedreno_screen.c | 2 +- .../drivers/freedreno/freedreno_util.h | 2 +- src/gallium/drivers/freedreno/log-parser.py | 73 +++++++ src/gallium/drivers/freedreno/meson.build | 2 + 12 files changed, 378 insertions(+), 2 deletions(-) create mode 100644 src/gallium/drivers/freedreno/freedreno_log.c create mode 100644 src/gallium/drivers/freedreno/freedreno_log.h create mode 100755 src/gallium/drivers/freedreno/log-parser.py diff --git a/src/gallium/drivers/freedreno/Makefile.sources b/src/gallium/drivers/freedreno/Makefile.sources index 88e9e047c61..0fd7bcf5ddd 100644 --- a/src/gallium/drivers/freedreno/Makefile.sources +++ b/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 \ diff --git a/src/gallium/drivers/freedreno/freedreno_batch.c b/src/gallium/drivers/freedreno/freedreno_batch.c index 0dc27adb156..106959b4fed 100644 --- a/src/gallium/drivers/freedreno/freedreno_batch.c +++ b/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 diff --git a/src/gallium/drivers/freedreno/freedreno_batch.h b/src/gallium/drivers/freedreno/freedreno_batch.h index 477c3e49f6a..9266790bb80 100644 --- a/src/gallium/drivers/freedreno/freedreno_batch.h +++ b/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); diff --git a/src/gallium/drivers/freedreno/freedreno_context.c b/src/gallium/drivers/freedreno/freedreno_context.c index bc2b1455c61..5b52e1381f4 100644 --- a/src/gallium/drivers/freedreno/freedreno_context.c +++ b/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; diff --git a/src/gallium/drivers/freedreno/freedreno_context.h b/src/gallium/drivers/freedreno/freedreno_context.h index f724d7b6840..c07ef83e49d 100644 --- a/src/gallium/drivers/freedreno/freedreno_context.h +++ b/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): */ diff --git a/src/gallium/drivers/freedreno/freedreno_gmem.c b/src/gallium/drivers/freedreno/freedreno_gmem.c index 239f4f0e955..f2feada4561 100644 --- a/src/gallium/drivers/freedreno/freedreno_gmem.c +++ b/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) ×tamp); fd_fence_populate(batch->fence, timestamp, out_fence_fd); + fd_log_flush(batch); } void diff --git a/src/gallium/drivers/freedreno/freedreno_log.c b/src/gallium/drivers/freedreno/freedreno_log.c new file mode 100644 index 00000000000..3edbcdede74 --- /dev/null +++ b/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 +#include + +#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); +} diff --git a/src/gallium/drivers/freedreno/freedreno_log.h b/src/gallium/drivers/freedreno/freedreno_log.h new file mode 100644 index 00000000000..ea5e22eaaff --- /dev/null +++ b/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_ */ diff --git a/src/gallium/drivers/freedreno/freedreno_screen.c b/src/gallium/drivers/freedreno/freedreno_screen.c index f5ffe01a060..47222b258dc 100644 --- a/src/gallium/drivers/freedreno/freedreno_screen.c +++ b/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) */ diff --git a/src/gallium/drivers/freedreno/freedreno_util.h b/src/gallium/drivers/freedreno/freedreno_util.h index 4a5b0a13dd3..6bd900e93ad 100644 --- a/src/gallium/drivers/freedreno/freedreno_util.h +++ b/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) */ diff --git a/src/gallium/drivers/freedreno/log-parser.py b/src/gallium/drivers/freedreno/log-parser.py new file mode 100755 index 00000000000..87bcc439870 --- /dev/null +++ b/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() + diff --git a/src/gallium/drivers/freedreno/meson.build b/src/gallium/drivers/freedreno/meson.build index 7125ecd274f..a5c0935e07e 100644 --- a/src/gallium/drivers/freedreno/meson.build +++ b/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', -- 2.30.2