src/gallium/drivers/freedreno/freedreno_log.c

   1 /*
   2  * Copyright © 2020 Google, Inc.
   3  *
   4  * Permission is hereby granted, free of charge, to any person obtaining a
   5  * copy of this software and associated documentation files (the "Software"),
   6  * to deal in the Software without restriction, including without limitation
   7  * the rights to use, copy, modify, merge, publish, distribute, sublicense,
   8  * and/or sell copies of the Software, and to permit persons to whom the
   9  * Software is furnished to do so, subject to the following conditions:
  10  *
  11  * The above copyright notice and this permission notice (including the next
  12  * paragraph) shall be included in all copies or substantial portions of the
  13  * Software.
  14  *
  15  * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
  16  * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
  17  * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
  18  * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
  19  * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
  20  * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
  21  * SOFTWARE.
  22  */
  23
  24 #include <inttypes.h>
  25 #include <stdarg.h>
  26
  27 #include "freedreno_log.h"
  28 #include "freedreno_batch.h"
  29 #include "freedreno_context.h"
  30
  31 #include "util/u_fifo.h"
  32
  33 /* A simple(ish) logging mechanism with timestamps recorded at the
  34  * corresponding point in the cmdstream.  The overall design is based
  35  * on fd_log_chunk's, which buffer up up to 'msgs_per_chunk' log msgs
  36  * and track an associated bo containing timestamps written from the
  37  * GPU.
  38  *
  39  * The fd_batch tracks a list of fd_log_chunk's.  When fd_log() is
  40  * called, msgs are pushed into the last (most recent) chunk until
  41  * it is full, at which point a new chunk is created.  And cmds are
  42  * inserted into the cmdstream to record the GPU timestamp that
  43  * corresponds with the log msg.
  44  *
  45  * When the batch is flushed, the list of log chunks is transferred
  46  * to the end of fd_context's list of chunks, and we attempt to pop
  47  * chunks from the from of the list if their timestamp bo is idle (ie.
  48  * the GPU has finished the batch that was writing the timestamps).
  49  *
  50  * NOTE: this is only appropriate for IB1 (ie. "gmem" level) cmdstream,
  51  * the IB2 (draw/binning) cmdstream can be executed multiple times,
  52  * which this mechanism is not designed to support.  Other existing
  53  * GL level queries (time-elapsed, amd-perfcntrs) are more appropriate
  54  * for profiling at that level.
  55  */
  56
  57 enum {
  58         bo_size = 0x1000,
  59         msgs_per_chunk = bo_size / sizeof(uint64_t),
  60 };
  61
  62 struct fd_log_chunk {
  63         struct list_head node;
  64
  65         unsigned num_msgs;
  66         struct util_fifo *msg_fifo;
  67
  68         /* list of recorded 64b timestamps */
  69         struct fd_bo *timestamps_bo;
  70
  71         bool eof;
  72         uint32_t *ring_cur;
  73 };
  74
  75 static struct fd_log_chunk *
  76 get_chunk(struct fd_batch *batch)
  77 {
  78         struct fd_log_chunk *chunk;
  79
  80         /* do we currently have a non-full chunk to append msgs to? */
  81         if (!list_is_empty(&batch->log_chunks)) {
  82                 chunk = list_last_entry(&batch->log_chunks,
  83                                 struct fd_log_chunk, node);
  84                 if (chunk->num_msgs < msgs_per_chunk)
  85                         return chunk;
  86         }
  87
  88         /* .. if not, then create a new one: */
  89         chunk = calloc(1, sizeof(*chunk));
  90         chunk->msg_fifo = u_fifo_create(msgs_per_chunk);
  91         chunk->timestamps_bo = fd_bo_new(batch->ctx->screen->dev, bo_size,
  92                         DRM_FREEDRENO_GEM_TYPE_KMEM, "timestamps");
  93
  94         list_addtail(&chunk->node, &batch->log_chunks);
  95
  96         return chunk;
  97 }
  98
  99 static void
 100 free_chunk(struct fd_log_chunk *chunk)
 101 {
 102         assert(chunk->msg_fifo->num == 0);
 103         u_fifo_destroy(chunk->msg_fifo);
 104         fd_bo_del(chunk->timestamps_bo);
 105         list_del(&chunk->node);
 106         free(chunk);
 107 }
 108
 109 static void
 110 process_chunk(struct fd_context *ctx, struct fd_log_chunk *chunk)
 111 {
 112         fprintf(ctx->log_out, "+----- TS -----+ +----- NS -----+ +-- Δ --+  +----- MSG -----\n");
 113
 114         uint64_t *timestamps = fd_bo_map(chunk->timestamps_bo);
 115         uint64_t last_time_ns = 0;
 116         uint64_t first_time_ns = 0;
 117         unsigned n = 0;
 118         char *msg;
 119
 120         while (u_fifo_pop(chunk->msg_fifo, (void **)&msg)) {
 121                 uint64_t ts = timestamps[n++];
 122                 uint64_t ns = ctx->ts_to_ns(ts);
 123                 int32_t delta;
 124
 125                 if (!first_time_ns)
 126                         first_time_ns = ns;
 127
 128                 if (ns) {
 129                         delta = last_time_ns ? ns - last_time_ns : 0;
 130                         last_time_ns = ns;
 131                 } else {
 132                         /* we skipped recording the timestamp, so it should be
 133                          * the same as last msg:
 134                          */
 135                         ns = last_time_ns;
 136                         delta = 0;
 137                 }
 138
 139                 fprintf(ctx->log_out, "%016"PRIu64" %016"PRIu64" %+9d: %s\n", ts, ns, delta, msg);
 140                 free(msg);
 141
 142         }
 143
 144         fprintf(ctx->log_out, "ELAPSED: %"PRIu64" ns\n", last_time_ns - first_time_ns);
 145
 146         if (chunk->eof)
 147                 fprintf(ctx->log_out, "END OF FRAME %u\n", ctx->frame_nr++);
 148 }
 149
 150 void
 151 fd_log_process(struct fd_context *ctx, bool wait)
 152 {
 153         while (!list_is_empty(&ctx->log_chunks)) {
 154                 struct fd_log_chunk *chunk = list_first_entry(&ctx->log_chunks,
 155                                 struct fd_log_chunk, node);
 156
 157                 unsigned flags = DRM_FREEDRENO_PREP_READ;
 158                 if (!wait)
 159                         flags |= DRM_FREEDRENO_PREP_NOSYNC;
 160
 161                 int ret = fd_bo_cpu_prep(chunk->timestamps_bo, ctx->pipe, flags);
 162                 if (ret)
 163                         break;
 164
 165                 process_chunk(ctx, chunk);
 166                 free_chunk(chunk);
 167         }
 168
 169         fflush(ctx->log_out);
 170 }
 171
 172 void
 173 fd_log_flush(struct fd_batch *batch)
 174 {
 175         /* transfer batch's log chunks to context: */
 176         list_splicetail(&batch->log_chunks, &batch->ctx->log_chunks);
 177         list_inithead(&batch->log_chunks);
 178 }
 179
 180 void
 181 _fd_log(struct fd_batch *batch, const char *fmt, ...)
 182 {
 183         struct fd_context *ctx = batch->ctx;
 184         struct fd_ringbuffer *ring = batch->nondraw ? batch->draw : batch->gmem;
 185         struct fd_log_chunk *chunk = get_chunk(batch);
 186         char *msg;
 187
 188         va_list ap;
 189         va_start(ap, fmt);
 190         if (vasprintf(&msg, fmt, ap) < 0)
 191                 return;
 192         va_end(ap);
 193
 194         u_fifo_add(chunk->msg_fifo, msg);
 195
 196         assert(ctx->record_timestamp);
 197
 198         /* If nothing else has been emitted to the ring since the last log msg,
 199          * skip emitting another timestamp.
 200          */
 201         if (ring->cur == chunk->ring_cur) {
 202                 uint64_t *ts = fd_bo_map(chunk->timestamps_bo);
 203                 /* zero signifies an invalid timestamp to process_chunk(), so it
 204                  * will use the last valid timestamp for this msg instead.
 205                  */
 206                 ts[chunk->num_msgs] = 0;
 207         } else {
 208                 ctx->record_timestamp(ring, chunk->timestamps_bo,
 209                                 chunk->num_msgs * sizeof(uint64_t));
 210         }
 211
 212         chunk->num_msgs++;
 213         chunk->ring_cur = ring->cur;
 214 }
 215
 216 void fd_log_eof(struct fd_context *ctx)
 217 {
 218         if (!(fd_mesa_debug & FD_DBG_LOG))
 219                 return;
 220
 221         if (list_is_empty(&ctx->log_chunks)) {
 222                 fprintf(ctx->log_out, "WARNING: no log chunks!\n");
 223                 return;
 224         }
 225
 226         struct fd_log_chunk *last_chunk = list_last_entry(&ctx->log_chunks,
 227                         struct fd_log_chunk, node);
 228         last_chunk->eof = true;
 229
 230         /* and process any chunks that are now idle/ready: */
 231         fd_log_process(ctx, false);
 232 }