Merge pull request #5046 from parl0v/feat/trace-batch-ids

feat(agc): trace slices and GPU ranges carry the recorder batch they belong to

core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp

@@ -122,6 +122,8 @@ private:
     Clock::duration begun{};
 };
 
+inline thread_local std::uint64_t TraceBatchTag = 0;
+
 class TraceThread {
 public:
     using Clock = std::chrono::steady_clock;
@@ -133,6 +135,7 @@ public:
         const char* stage;
         Clock::time_point begin;
         Clock::duration length;
+        std::uint64_t batch = 0;
     };
 
     struct Total {
@@ -170,7 +173,7 @@ public:
             folded = {};
         }
         if (length < MinimumSlice) folded += length;
-        else append({scope, stage, begin, length});
+        else append({scope, stage, begin, length, TraceBatchTag});
     }
 
     Snapshot Collect() const {
@@ -255,6 +258,7 @@ struct TraceGpuRange {
     const char* name;
     double beginNs;
     double endNs;
+    std::uint64_t batch = 0;
 };
 
 struct TraceClockSample {
@@ -317,13 +321,14 @@ public:
             std::stable_sort(slices.begin(), slices.end(), [](const auto& a, const auto& b) { return a.begin != b.begin ? a.begin < b.begin : a.length > b.length; });
             const auto folded = thread.name + " folded";
             for (const auto& slice : slices) {
-                char text[64];
+                char text[112];
                 if (slice.scope == nullptr) {
                     event(folded, "C", slice.begin, tid);
                     std::snprintf(text, sizeof text, ",\"args\":{\"ms\":%.3f}}", milliseconds(slice.length));
                 } else {
                     event(Name(slice.scope, slice.stage), "X", slice.begin, tid);
-                    std::snprintf(text, sizeof text, ",\"dur\":%.3f}", microseconds(slice.length));
+                    if (slice.batch != 0) std::snprintf(text, sizeof text, ",\"dur\":%.3f,\"args\":{\"batch\":%llu}}", microseconds(slice.length), static_cast<unsigned long long>(slice.batch));
+                    else std::snprintf(text, sizeof text, ",\"dur\":%.3f}", microseconds(slice.length));
                 }
                 output += text;
             }
@@ -345,7 +350,7 @@ public:
             const auto begin = map(range.beginNs);
             const auto end = map(range.endNs);
             if (end <= begin || begin < origin) continue;
-            slices.push_back({range.name, nullptr, begin, end - begin});
+            slices.push_back({range.name, nullptr, begin, end - begin, range.batch});
         }
         return slices;
     }
@@ -462,14 +467,14 @@ public:
     static void BindThread(const char* name, std::size_t capacity = TraceThread::DefaultCapacity);
     static void Present(std::uint32_t width, std::uint32_t height, const VulkanDevice* device);
 
-    static void GpuRange(const char* name, double beginNs, double endNs) {
+    static void GpuRange(const char* name, double beginNs, double endNs, std::uint64_t batch = 0) {
         if (!buffering.load(std::memory_order_relaxed)) return;
         std::lock_guard lock(gpuMutex);
         if (gpuRanges.size() == gpuRanges.capacity()) {
             gpuDropped = true;
             return;
         }
-        gpuRanges.push_back({name, beginNs, endNs});
+        gpuRanges.push_back({name, beginNs, endNs, batch});
     }
 
     static bool Recording() {

core/libs/prx/libSceAgcDriver/Graphics/include/Recorder.hpp

@@ -535,6 +535,7 @@ private:
         std::vector<Read> reads;
         // Submission number (1-based): identifies a batch after its allocation may have been reused.
         std::uint64_t serial = 0;
+        std::uint64_t traceId = 0;
         bool submitted = false;
         // The GpuMutex queue tag of the thread that opened the batch, and when it was submitted
         // (the [syncwait] line reports what a wait's target and the batches ahead of it were).

core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp

@@ -1520,6 +1520,11 @@ void Recorder::ensureOpen() {
         dropStaleHoldKept();
         batch->kept.insert(batch->kept.end(), holdKept.begin(), holdKept.end());
         open = std::move(batch);
+        if (PerformanceTrace::Recording()) {
+            static std::atomic<std::uint64_t> traceIds{0};
+            open->traceId = traceIds.fetch_add(1, std::memory_order_relaxed) + 1;
+        }
+        TraceBatchTag = open->traceId;
         // The whole-batch range: its start stamp waits for the previous batches like any
         // bottom-of-pipe stamp, so it marks when this batch's execution began.
         if (BatchStampsEnabled()) open->batchTiming = beginTiming(BatchTimingKey);
@@ -2367,7 +2372,7 @@ void Recorder::readGpuTiming(Batch& batch) {
         if (batch.batchTiming == 0 && stamps[1] >= stamps[0]) {
             batch.gpuStartNs = static_cast<double>(stamps[0]) * period;
             batch.gpuEndNs = static_cast<double>(stamps[1]) * period;
-            PerformanceTrace::GpuRange("batch", batch.gpuStartNs, batch.gpuEndNs);
+            PerformanceTrace::GpuRange("batch", batch.gpuStartNs, batch.gpuEndNs, batch.traceId);
         }
         return;
     }
@@ -2383,12 +2388,12 @@ void Recorder::readGpuTiming(Batch& batch) {
             // The whole batch: apart from the per-program totals it contains.
             batch.gpuStartNs = static_cast<double>(stamps[i * 2]) * period;
             batch.gpuEndNs = static_cast<double>(stamps[i * 2 + 1]) * period;
-            PerformanceTrace::GpuRange("batch", batch.gpuStartNs, batch.gpuEndNs);
+            PerformanceTrace::GpuRange("batch", batch.gpuStartNs, batch.gpuEndNs, batch.traceId);
             timingBatchMs += ns / 1e6;
             continue;
         }
         const auto key = batch.timedKeys[i];
-        if (key >= ClassKey(CommandClass::DispatchLeading) && key < ClassKey(CommandClass::Count)) PerformanceTrace::GpuRange(CommandClassNames[key - ClassKey(CommandClass::DispatchLeading)], static_cast<double>(stamps[i * 2]) * period, static_cast<double>(stamps[i * 2 + 1]) * period);
+        if (key >= ClassKey(CommandClass::DispatchLeading) && key < ClassKey(CommandClass::Count)) PerformanceTrace::GpuRange(CommandClassNames[key - ClassKey(CommandClass::DispatchLeading)], static_cast<double>(stamps[i * 2]) * period, static_cast<double>(stamps[i * 2 + 1]) * period, batch.traceId);
         auto& totals = timingByKey[key];
         ++totals.count;
         totals.ms += ns / 1e6;

core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp

@@ -106,6 +106,27 @@ void EventsShape() {
     Check(json == expected, "trace events changed shape");
 }
 
+void BatchIds() {
+    const auto origin = Clock::now();
+    const std::vector<TraceThread::Slice> slices{{"Driver.Packet", "dispatch", origin + microseconds(10), microseconds(30), 42}};
+    const std::vector<TraceThread::Snapshot> threads{{"queue worker 0x0", slices, {}, false}};
+    const std::vector<Clock::time_point> presents{origin, origin + milliseconds(16)};
+    const auto json = TraceFormat::Events(7, origin, threads, 0, presents, 5);
+    Check(json.find("{\"name\":\"Driver.Packet.dispatch\",\"ph\":\"X\",\"ts\":10.000,\"pid\":7,\"tid\":1,\"dur\":30.000,\"args\":{\"batch\":42}}") != std::string::npos, "a slice's batch id was not written");
+    std::atomic<std::uint64_t> count{1};
+    TraceThread thread("queue worker 0x0", count, 4);
+    AgcDriver::TraceBatchTag = 9;
+    thread.Add("Driver.Packet", nullptr, origin, origin + microseconds(30));
+    AgcDriver::TraceBatchTag = 0;
+    thread.Add("Driver.Packet", nullptr, origin + milliseconds(1), origin + milliseconds(1) + microseconds(30));
+    const auto snapshot = thread.Collect();
+    Check(snapshot.slices.size() == 2 && snapshot.slices[0].batch == 9 && snapshot.slices[1].batch == 0, "a slice did not take its thread's batch id");
+    const AgcDriver::TraceClockSample first{1000.0, origin + microseconds(10)};
+    const AgcDriver::TraceClockSample last{41000.0, origin + microseconds(30)};
+    const std::vector<AgcDriver::TraceGpuRange> ranges{{"batch", 5000.0, 9000.0, 3}};
+    Check(TraceFormat::GpuSlices(ranges, first, last, origin)[0].batch == 3, "a GPU range lost its batch id");
+}
+
 void SummaryFields() {
     const auto origin = Clock::now();
     AgcDriver::TraceSummary summary;
@@ -280,6 +301,7 @@ int main() {
         FoldShortSlices();
         EscapeStrings();
         EventsShape();
+        BatchIds();
         SummaryFields();
         GpuClock();
         IntervalDue();