freedreno/log: avoid duplicate ts's

In cases where `fd_log()`/`fd_log_stream()` are called multiple times
back-to-back, just use the timestamp of the first trace.

This seems to avoid some occasional GPU hangs I was seeing with logging
enabled.  Although not exactly sure the reason for the hangs.  (Looks
like GPU hangs *after* all the cmdstream is processed, according to
crashdec.)

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

diff --git a/src/gallium/drivers/freedreno/freedreno_log.c b/src/gallium/drivers/freedreno/freedreno_log.c
index 3edbcdede74914f5e0accf111c8133ba95d412c8..c1fe4da814220511e46759f477112e8951b4e490 100644 (file)
--- a/src/gallium/drivers/freedreno/freedreno_log.c
+++ b/src/gallium/drivers/freedreno/freedreno_log.c
@@ -67,6 +67,7 @@ struct fd_log_chunk {
        struct fd_bo *timestamps_bo;
 
        bool eof;
+       uint32_t *ring_cur;
 };
 
 static struct fd_log_chunk *
@@ -117,12 +118,21 @@ process_chunk(struct fd_context *ctx, struct fd_log_chunk *chunk)
        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;
+               int32_t delta;
 
                if (!first_time_ns)
                        first_time_ns = ns;
 
-               last_time_ns = ns;
+               if (ns) {
+                       delta = last_time_ns ? ns - last_time_ns : 0;
+                       last_time_ns = ns;
+               } else {
+                       /* we skipped recording the timestamp, so it should be
+                        * the same as last msg:
+                        */
+                       ns = last_time_ns;
+                       delta = 0;
+               }
 
                printf("%016"PRIu64" %016"PRIu64" %+9d: %s\n", ts, ns, delta, msg);
                free(msg);
@@ -180,10 +190,23 @@ _fd_log(struct fd_batch *batch, const char *fmt, ...)
        u_fifo_add(chunk->msg_fifo, msg);
 
        assert(ctx->record_timestamp);
-       ctx->record_timestamp(ring, chunk->timestamps_bo,
-                       chunk->num_msgs * sizeof(uint64_t));
+
+       /* If nothing else has been emitted to the ring since the last log msg,
+        * skip emitting another timestamp.
+        */
+       if (ring->cur == chunk->ring_cur) {
+               uint64_t *ts = fd_bo_map(chunk->timestamps_bo);
+               /* zero signifies an invalid timestamp to process_chunk(), so it
+                * will use the last valid timestamp for this msg instead.
+                */
+               ts[chunk->num_msgs] = 0;
+       } else {
+               ctx->record_timestamp(ring, chunk->timestamps_bo,
+                               chunk->num_msgs * sizeof(uint64_t));
+       }
 
        chunk->num_msgs++;
+       chunk->ring_cur = ring->cur;
 }
 
 void fd_log_eof(struct fd_context *ctx)