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 const unsigned bo_size = 0x1000;
  58 const unsigned msgs_per_chunk = bo_size / sizeof(uint64_t);
  59
  60 struct fd_log_chunk {
  61         struct list_head node;
  62
  63         unsigned num_msgs;
  64         struct util_fifo *msg_fifo;
  65
  66         /* list of recorded 64b timestamps */
  67         struct fd_bo *timestamps_bo;
  68
  69         bool eof;
  70         uint32_t *ring_cur;
  71 };
  72
  73 static struct fd_log_chunk *
  74 get_chunk(struct fd_batch *batch)
  75 {
  76         struct fd_log_chunk *chunk;
  77
  78         /* do we currently have a non-full chunk to append msgs to? */
  79         if (!list_is_empty(&batch->log_chunks)) {
  80                 chunk = list_last_entry(&batch->log_chunks,
  81                                 struct fd_log_chunk, node);
  82                 if (chunk->num_msgs < msgs_per_chunk)
  83                         return chunk;
  84         }
  85
  86         /* .. if not, then create a new one: */
  87         chunk = calloc(1, sizeof(*chunk));
  88         chunk->msg_fifo = u_fifo_create(msgs_per_chunk);
  89         chunk->timestamps_bo = fd_bo_new(batch->ctx->screen->dev, bo_size,
  90                         DRM_FREEDRENO_GEM_TYPE_KMEM, "timestamps");
  91
  92         list_addtail(&chunk->node, &batch->log_chunks);
  93
  94         return chunk;
  95 }
  96
  97 static void
  98 free_chunk(struct fd_log_chunk *chunk)
  99 {
 100         assert(chunk->msg_fifo->num == 0);
 101         u_fifo_destroy(chunk->msg_fifo);
 102         fd_bo_del(chunk->timestamps_bo);
 103         list_del(&chunk->node);
 104         free(chunk);
 105 }
 106
 107 static void
 108 process_chunk(struct fd_context *ctx, struct fd_log_chunk *chunk)
 109 {
 110         printf("+----- TS -----+ +----- NS -----+ +-- Δ --+  +----- MSG -----\n");
 111
 112         uint64_t *timestamps = fd_bo_map(chunk->timestamps_bo);
 113         uint64_t last_time_ns = 0;
 114         uint64_t first_time_ns = 0;
 115         unsigned n = 0;
 116         char *msg;
 117
 118         while (u_fifo_pop(chunk->msg_fifo, (void **)&msg)) {
 119                 uint64_t ts = timestamps[n++];
 120                 uint64_t ns = ctx->ts_to_ns(ts);
 121                 int32_t delta;
 122
 123                 if (!first_time_ns)
 124                         first_time_ns = ns;
 125
 126                 if (ns) {
 127                         delta = last_time_ns ? ns - last_time_ns : 0;
 128                         last_time_ns = ns;
 129                 } else {
 130                         /* we skipped recording the timestamp, so it should be
 131                          * the same as last msg:
 132                          */
 133                         ns = last_time_ns;
 134                         delta = 0;
 135                 }
 136
 137                 printf("%016"PRIu64" %016"PRIu64" %+9d: %s\n", ts, ns, delta, msg);
 138                 free(msg);
 139
 140         }
 141
 142         printf("ELAPSED: %"PRIu64" ns\n", last_time_ns - first_time_ns);
 143
 144         if (chunk->eof)
 145                 printf("END OF FRAME %u\n", ctx->frame_nr++);
 146 }
 147
 148 void
 149 fd_log_process(struct fd_context *ctx, bool wait)
 150 {
 151         while (!list_is_empty(&ctx->log_chunks)) {
 152                 struct fd_log_chunk *chunk = list_first_entry(&ctx->log_chunks,
 153                                 struct fd_log_chunk, node);
 154
 155                 unsigned flags = DRM_FREEDRENO_PREP_READ;
 156                 if (!wait)
 157                         flags |= DRM_FREEDRENO_PREP_NOSYNC;
 158
 159                 int ret = fd_bo_cpu_prep(chunk->timestamps_bo, ctx->pipe, flags);
 160                 if (ret)
 161                         break;
 162
 163                 process_chunk(ctx, chunk);
 164                 free_chunk(chunk);
 165         }
 166 }
 167
 168 void
 169 fd_log_flush(struct fd_batch *batch)
 170 {
 171         /* transfer batch's log chunks to context: */
 172         list_splicetail(&batch->log_chunks, &batch->ctx->log_chunks);
 173         list_inithead(&batch->log_chunks);
 174 }
 175
 176 void
 177 _fd_log(struct fd_batch *batch, const char *fmt, ...)
 178 {
 179         struct fd_context *ctx = batch->ctx;
 180         struct fd_ringbuffer *ring = batch->nondraw ? batch->draw : batch->gmem;
 181         struct fd_log_chunk *chunk = get_chunk(batch);
 182         char *msg;
 183
 184         va_list ap;
 185         va_start(ap, fmt);
 186         if (vasprintf(&msg, fmt, ap) < 0)
 187                 return;
 188         va_end(ap);
 189
 190         u_fifo_add(chunk->msg_fifo, msg);
 191
 192         assert(ctx->record_timestamp);
 193
 194         /* If nothing else has been emitted to the ring since the last log msg,
 195          * skip emitting another timestamp.
 196          */
 197         if (ring->cur == chunk->ring_cur) {
 198                 uint64_t *ts = fd_bo_map(chunk->timestamps_bo);
 199                 /* zero signifies an invalid timestamp to process_chunk(), so it
 200                  * will use the last valid timestamp for this msg instead.
 201                  */
 202                 ts[chunk->num_msgs] = 0;
 203         } else {
 204                 ctx->record_timestamp(ring, chunk->timestamps_bo,
 205                                 chunk->num_msgs * sizeof(uint64_t));
 206         }
 207
 208         chunk->num_msgs++;
 209         chunk->ring_cur = ring->cur;
 210 }
 211
 212 void fd_log_eof(struct fd_context *ctx)
 213 {
 214         if (!(fd_mesa_debug & FD_DBG_LOG))
 215                 return;
 216
 217         if (list_is_empty(&ctx->log_chunks)) {
 218                 printf("WARNING: no log chunks!\n");
 219                 return;
 220         }
 221
 222         struct fd_log_chunk *last_chunk = list_last_entry(&ctx->log_chunks,
 223                         struct fd_log_chunk, node);
 224         last_chunk->eof = true;
 225
 226         /* and process any chunks that are now idle/ready: */
 227         fd_log_process(ctx, false);
 228 }