GPU Metal: optional command-buffer timeline

With GPUCA_METAL_TIMELINE=<file>, write one line per command buffer once it
completes: stream, status, CPU commit time, GPUStartTime and GPUEndTime, the
kernels (with their threadgroup counts), blits, and the events it waits for
and signals; and one line per host drain that had to wait. Off by default,
the only cost then is a pointer test per encoded command.

This is what is needed to see how the streams overlap on the GPU and where
they wait for each other, without a profiler attached.

Author: ktf

GPU/GPUTracking/Base/metal/GPUReconstructionMetal.mm

@@ -167,6 +167,10 @@ uint32_t metalGPUCoreCount()
       mInternals->streamOrderValue[i] = 0;
       mInternals->streamFence[i] = [mInternals->device newFence];
       mInternals->streamHasWork[i] = false;
+      mInternals->timelineKernels[i] = 0;
+    }
+    if (const char* timeline = getenv("GPUCA_METAL_TIMELINE")) {
+      mInternals->timeline = fopen(timeline, "w");
     }
 
     mInternals->mem_host = metalNewSharedBuffer(mInternals->device, mHostMemorySize);
@@ -247,6 +251,9 @@ uint32_t metalGPUCoreCount()
       }
       [mInternals->mem_host release];
     }
+    if (mInternals->timeline) {
+      fflush(mInternals->timeline);  // not closed: a completion handler may still write to it
+    }
 
     [mInternals->library release];
     [mInternals->device release];
@@ -313,6 +320,7 @@ MetalMemRef metalResolve(const GPUReconstructionMetalInternals* internals, const
     id<MTLCommandBuffer> cb = mInternals->commandBuffers[realStream];
     id<MTLBlitCommandEncoder> blit = [cb blitCommandEncoder];
     metalBeginEncoder(mInternals, blit, realStream);
+    metalTimelineAdd(mInternals, realStream, "b", nullptr, sizeBytes);
     [blit copyFromBuffer:s.buffer
             sourceOffset:s.offset
                 toBuffer:d.buffer
@@ -346,6 +354,7 @@ MetalMemRef metalResolve(const GPUReconstructionMetalInternals* internals, const
     id<MTLCommandBuffer> cb = mInternals->commandBuffers[realStream];
     id<MTLBlitCommandEncoder> blit = [cb blitCommandEncoder];
     metalBeginEncoder(mInternals, blit, realStream);
+    metalTimelineAdd(mInternals, realStream, "b", nullptr, size);
     [blit copyFromBuffer:s.buffer
             sourceOffset:s.offset
                 toBuffer:mInternals->mem_constant
@@ -384,6 +393,7 @@ MetalMemRef metalResolve(const GPUReconstructionMetalInternals* internals, const
   const uint64_t value = EventValue(*ev, true);
   [cb encodeSignalEvent:mtlEvent value:value];
   metalSignalOnError(cb, mtlEvent, value);
+  metalTimelineAdd(mInternals, stream, "s", mtlEvent, value);
   CommitStream(stream);
 }
 
@@ -396,13 +406,27 @@ MetalMemRef metalResolve(const GPUReconstructionMetalInternals* internals, const
   const uint64_t value = ++mInternals->streamOrderValue[stream];
   [cb encodeSignalEvent:mInternals->streamOrder[stream] value:value];
   metalSignalOnError(cb, mInternals->streamOrder[stream], value);
+  if (mInternals->timeline) {
+    metalTimelineAdd(mInternals, stream, "s", mInternals->streamOrder[stream], value);
+    FILE* f = mInternals->timeline;
+    const std::string ops = std::move(mInternals->timelineOps[stream]);
+    const uint32_t nKernels = mInternals->timelineKernels[stream];
+    const uint64_t seq = mInternals->timelineBuffers++;
+    const double commitTime = metalHostTime();
+    [cb addCompletedHandler:^(id<MTLCommandBuffer> c) {
+      fprintf(f, "CB %llu s%d st%d commit %.6f gpu %.6f %.6f nk %u:%s\n", (unsigned long long)seq, stream, (int)c.status, commitTime, c.GPUStartTime, c.GPUEndTime, nKernels, ops.c_str());
+    }];
+    mInternals->timelineOps[stream].clear();
+    mInternals->timelineKernels[stream] = 0;
+  }
   [cb commit];
   // Hand the committed buffer over to the stream's submission list, which owns
   // it until it is waited for, and open a fresh one to encode the next work in.
   mInternals->submittedBuffers[stream].emplace_back(cb);
   mInternals->streamHasWork[stream] = false;
   mInternals->commandBuffers[stream] = [[mInternals->commandQueues[stream] commandBuffer] retain];
   [mInternals->commandBuffers[stream] encodeWaitForEvent:mInternals->streamOrder[stream] value:value];
+  metalTimelineAdd(mInternals, stream, "w", mInternals->streamOrder[stream], value);
 }
 
 void GPUReconstructionMetal::DrainStream(int32_t stream)
@@ -421,6 +445,7 @@ MetalMemRef metalResolve(const GPUReconstructionMetalInternals* internals, const
   // waitUntilCompleted, which sleeps until the completion has been processed.
   // Only short waits are worth a busy core, so give up after a while.
   bool done = false;
+  const double drainStart = mInternals->timeline && !mInternals->submittedBuffers[stream].empty() ? metalHostTime() : 0.;
   const auto t0 = std::chrono::steady_clock::now();
   while (!mInternals->submittedBuffers[stream].empty() && !(done = mInternals->streamOrder[stream].signaledValue >= mInternals->streamOrderValue[stream]) && std::chrono::steady_clock::now() - t0 < std::chrono::milliseconds(20)) {
   }
@@ -436,6 +461,9 @@ MetalMemRef metalResolve(const GPUReconstructionMetalInternals* internals, const
     [cb release];
   }
   mInternals->submittedBuffers[stream].clear();
+  if (drainStart) {
+    fprintf(mInternals->timeline, "DR s%d %.6f %.6f\n", stream, drainStart, metalHostTime());
+  }
   // The work of a failed buffer is lost, so the results are wrong: fail like the other backends.
   if (error && !mInternals->exiting) {
     GPUChkErr(error);
@@ -469,6 +497,7 @@ MetalMemRef metalResolve(const GPUReconstructionMetalInternals* internals, const
     auto mtlEvent = (__bridge id<MTLSharedEvent>)(evList[ei].get<void*>());
     if (const uint64_t value = EventValue(evList[ei], false)) {
       [cb encodeWaitForEvent:mtlEvent value:value];
+      metalTimelineAdd(mInternals, stream, "w", mtlEvent, value);
     }
   }
   CommitStream(stream);

GPU/GPUTracking/Base/metal/GPUReconstructionMetalIncludesHost.h

@@ -34,6 +34,8 @@ using half = _Float16;
 #include <memory>
 #include <mutex>
 #include <unordered_map>
+#include <cstdio>
+#include <mach/mach_time.h>
 #include "GPULogging.h"
 
 #include "GPUReconstructionMetal.h"
@@ -68,6 +70,12 @@ struct GPUReconstructionMetalInternals {
   std::array<bool, constants::GPU_MAX_STREAMS> streamHasWork;
   // Set while the device is torn down, when a failed command buffer is no longer fatal
   bool exiting = false;
+  // Opt-in command-buffer timeline, GPUCA_METAL_TIMELINE=<file>: what each open
+  // buffer contains (kernels, blits, waits, signals), written out once it completes
+  FILE* timeline = nullptr;
+  std::array<std::string, constants::GPU_MAX_STREAMS> timelineOps;
+  std::array<uint32_t, constants::GPU_MAX_STREAMS> timelineKernels;
+  uint64_t timelineBuffers = 0;
 
   std::vector<id<MTLFunction>> functions;
   std::vector<id<MTLComputePipelineState>> pipelines;
@@ -103,6 +111,20 @@ inline void metalSignalOnError(id<MTLCommandBuffer> cb, id<MTLSharedEvent> event
     }
   }];
 }
+// In the time base of the command buffers' GPUStartTime and GPUEndTime
+inline double metalHostTime()
+{
+  static const double scale = [] { mach_timebase_info_data_t tb; mach_timebase_info(&tb); return 1e-9 * tb.numer / tb.denom; }();
+  return mach_absolute_time() * scale;
+}
+inline void metalTimelineAdd(GPUReconstructionMetalInternals* internals, int32_t stream, const char* op, const void* id, uint64_t value)
+{
+  if (internals->timeline) {
+    char buf[96];
+    snprintf(buf, sizeof(buf), " %s:%p=%llu", op, id, (unsigned long long)value);
+    internals->timelineOps[stream] += buf;
+  }
+}
 template <class E>
 inline void metalEndEncoder(GPUReconstructionMetalInternals* internals, E encoder, int32_t stream)
 {

GPU/GPUTracking/Base/metal/GPUReconstructionMetalKernels.mm

@@ -50,6 +50,10 @@
   if (threadGroupSize > mInternals->maxThreadsPerGroup[num]) {
     threadGroupSize = mInternals->maxThreadsPerGroup[num];
   }
+  if (mInternals->timeline) {
+    mInternals->timelineOps[kExec.stream] += std::string(" k:") + GetKernelName<T, I>() + "/" + std::to_string(kExec.nBlocks);
+    mInternals->timelineKernels[kExec.stream]++;
+  }
   [computeEncoder dispatchThreadgroups:MTLSizeMake(kExec.nBlocks, 1, 1)
                  threadsPerThreadgroup:MTLSizeMake(threadGroupSize, 1, 1)];
   metalEndEncoder(mInternals, computeEncoder, kExec.stream);