diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp index 0cefddf624..76e6bcbedc 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp +++ b/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(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() { diff --git a/core/libs/prx/libSceAgcDriver/Graphics/include/Recorder.hpp b/core/libs/prx/libSceAgcDriver/Graphics/include/Recorder.hpp index 1fda73efd9..134703542e 100644 --- a/core/libs/prx/libSceAgcDriver/Graphics/include/Recorder.hpp +++ b/core/libs/prx/libSceAgcDriver/Graphics/include/Recorder.hpp @@ -535,6 +535,7 @@ private: std::vector 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). diff --git a/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp b/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp index f3acc6488e..f4a993d8da 100644 --- a/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp +++ b/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 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(stamps[0]) * period; batch.gpuEndNs = static_cast(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(stamps[i * 2]) * period; batch.gpuEndNs = static_cast(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(stamps[i * 2]) * period, static_cast(stamps[i * 2 + 1]) * period); + if (key >= ClassKey(CommandClass::DispatchLeading) && key < ClassKey(CommandClass::Count)) PerformanceTrace::GpuRange(CommandClassNames[key - ClassKey(CommandClass::DispatchLeading)], static_cast(stamps[i * 2]) * period, static_cast(stamps[i * 2 + 1]) * period, batch.traceId); auto& totals = timingByKey[key]; ++totals.count; totals.ms += ns / 1e6; diff --git a/core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp b/core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp index 28c5136504..1fa281989f 100644 --- a/core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp +++ b/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 slices{{"Driver.Packet", "dispatch", origin + microseconds(10), microseconds(30), 42}}; + const std::vector threads{{"queue worker 0x0", slices, {}, false}}; + const std::vector 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 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 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();