diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp index d08dcc14a..af289475d 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp +++ b/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp @@ -12,6 +12,7 @@ #include #include #include +#include #include #include #include @@ -207,6 +208,17 @@ struct TraceSummary { std::string trace; }; +struct TraceGpuRange { + const char* name; + double beginNs; + double endNs; +}; + +struct TraceClockSample { + double gpuNs = 0; + std::chrono::steady_clock::time_point cpu{}; +}; + class TraceFormat { public: using Clock = std::chrono::steady_clock; @@ -281,6 +293,20 @@ public: return output; } + static std::vector GpuSlices(std::span ranges, const TraceClockSample& first, const TraceClockSample& last, Clock::time_point origin) { + const double gpuSpan = last.gpuNs - first.gpuNs; + const double scale = gpuSpan > 0 ? std::chrono::duration(last.cpu - first.cpu).count() / gpuSpan : 1.0; + const auto map = [&](double gpuNs) { return first.cpu + std::chrono::duration_cast(std::chrono::duration((gpuNs - first.gpuNs) * scale)); }; + std::vector slices; + for (const auto& range : ranges) { + 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}); + } + return slices; + } + static std::string Summary(const TraceSummary& summary, std::span threads, std::span presents) { const auto count = presents.empty() ? std::size_t{0} : presents.size() - 1; const auto span = presents.empty() ? Clock::duration{} : presents.back() - presents.front(); @@ -374,9 +400,19 @@ public: return configured; } - static void BindThread(const char* name); + 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) { + if (!Recording()) return; + std::lock_guard lock(gpuMutex); + if (gpuRanges.size() == gpuRanges.capacity()) { + gpuDropped = true; + return; + } + gpuRanges.push_back({name, beginNs, endNs}); + } + static bool Recording() { return recording.load(std::memory_order_relaxed); } @@ -389,6 +425,9 @@ private: inline static std::atomic recording{false}; inline static std::atomic presentCount{0}; inline static thread_local TraceThread* local = nullptr; + inline static std::mutex gpuMutex; + inline static std::vector gpuRanges; + inline static bool gpuDropped = false; }; } diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/VulkanDevice.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/VulkanDevice.hpp index 0b1c4c94d..916de6b35 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/include/VulkanDevice.hpp +++ b/core/libs/prx/libSceAgcDriver/Execution/include/VulkanDevice.hpp @@ -11,6 +11,7 @@ #include "prx/libSceAgcDriver/Graphics/include/Draw.hpp" #include "prx/libSceAgcDriver/Graphics/include/Recorder.hpp" #include "prx/libc/include/GuestAllocations.hpp" +#include #include #include #include @@ -40,6 +41,7 @@ public: VulkanDevice& operator=(const VulkanDevice&) = delete; std::string DeviceName() const; std::string DriverInfo() const; + bool CalibrateClock(double& gpuNs, std::chrono::steady_clock::time_point& cpu) const; ShaderRecompiler::SpirvTarget Target() const; std::optional GeometryLimits() const; const std::uint32_t* WorkGroupCountLimit() const; diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Shaders/ShaderRegistry.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Shaders/ShaderRegistry.cpp index 55c09e78c..eaaf07633 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Shaders/ShaderRegistry.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Shaders/ShaderRegistry.cpp @@ -793,6 +793,7 @@ private: static void* Main(void* argument) { auto& pool = *static_cast(argument); + if (PerformanceTrace::Configured()) PerformanceTrace::BindThread("shader prepare", TraceThread::DefaultCapacity / 8); for (;;) { std::function task; { diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/GuestMemory.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/GuestMemory.cpp index 20ac655e1..9c8838dab 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/GuestMemory.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/GuestMemory.cpp @@ -1,5 +1,6 @@ #include "prx/libSceAgcDriver/Execution/include/ProfileOutput.hpp" #include "prx/libSceAgcDriver/Execution/include/GuestMemory.hpp" +#include "prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp" #include "prx/libSceAgcDriver/Execution/include/WriteWatchCoverage.hpp" #include "ThreadOwned.hpp" #include "prx/libc/include/GuestAllocations.hpp" @@ -1671,7 +1672,17 @@ void AssertGpuLockHeld(const char* where) { void GpuMutexType::lock() { if (!GpuLockProfiled()) { - mutex.lock(); + auto* trace = PerformanceTrace::Recording() ? PerformanceTrace::Thread() : nullptr; + if (trace == nullptr) { + mutex.lock(); + } else { + const auto site = static_cast(std::exchange(LockStats().nextSite, GpuLockSite::Other)); + if (!mutex.try_lock()) { + const auto start = std::chrono::steady_clock::now(); + mutex.lock(); + trace->Add("GpuMutex.wait", GpuLockSiteNames[site], start, std::chrono::steady_clock::now()); + } + } acquired(); return; } @@ -1689,6 +1700,7 @@ void GpuMutexType::lock() { mutex.lock(); acquired(); const auto now = std::chrono::steady_clock::now(); + if (auto* trace = PerformanceTrace::Recording() ? PerformanceTrace::Thread() : nullptr) trace->Add("GpuMutex.wait", GpuLockSiteNames[site], start, now); if (holders) { HolderMatrixValues after{}; Holders().Snapshot(after); @@ -1762,7 +1774,7 @@ void GpuMutexType::lock() { void TagGpuLockSite(GpuLockSite site) { // Off the profiled path the tag is never read, so the thread-local is not touched either. - if (!GpuLockProfiled()) return; + if (!GpuLockProfiled() && !PerformanceTrace::Recording()) return; LockStats().nextSite = site; } diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/PerformanceTrace.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/PerformanceTrace.cpp index f435f16ac..96a32723a 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/PerformanceTrace.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/PerformanceTrace.cpp @@ -25,6 +25,7 @@ namespace AgcDriver { namespace { using Clock = std::chrono::steady_clock; +constexpr std::size_t GpuRangeCapacity = TraceThread::DefaultCapacity; struct Session { std::mutex mutex; @@ -34,6 +35,7 @@ struct Session { std::uint64_t present = 0; std::uint64_t firstPresent = 0; double gpuBusyAtOpen = 0; + std::optional gpuClock; std::vector presents; }; @@ -91,9 +93,9 @@ std::vector> environment() { } -void PerformanceTrace::BindThread(const char* name) { +void PerformanceTrace::BindThread(const char* name, std::size_t capacity) { if (!Configured() || local != nullptr) return; - auto bound = std::make_unique(name, presentCount); + auto bound = std::make_unique(name, presentCount, capacity); auto& state = session(); std::lock_guard lock(state.mutex); local = bound.get(); @@ -114,10 +116,17 @@ void PerformanceTrace::Present(std::uint32_t width, std::uint32_t height, const if (edge == TraceWindow::Edge::Open) { state.firstPresent = present; state.gpuBusyAtOpen = VulkanDevice::PresentCounts().gpuBusyMs; + TraceClockSample clock; + if (device != nullptr && device->CalibrateClock(clock.gpuNs, clock.cpu)) state.gpuClock = clock; + { + std::lock_guard gpu(gpuMutex); + gpuRanges.clear(); + gpuRanges.reserve(GpuRangeCapacity); + } state.presents.push_back(now); presentCount.fetch_add(1, std::memory_order_relaxed); recording.store(true, std::memory_order_relaxed); - ProfilePrint_nid_no_patch("[trace] recording %s from present %llu\n", state.window->Describe().c_str(), static_cast(present)); + ProfilePrint_nid_no_patch("[trace] recording %s from present %llu%s\n", state.window->Describe().c_str(), static_cast(present), state.gpuClock ? "" : "; no GPU track: the device has no calibrated timestamps"); return; } if (!recording.load(std::memory_order_relaxed)) return; @@ -132,6 +141,13 @@ void PerformanceTrace::Present(std::uint32_t width, std::uint32_t height, const if (state.threads[index].get() == local) presenter = index; snapshots.push_back(state.threads[index]->Collect()); } + std::vector gpuSlices; + TraceClockSample clock; + if (state.gpuClock && device != nullptr && device->CalibrateClock(clock.gpuNs, clock.cpu)) { + std::lock_guard gpu(gpuMutex); + gpuSlices = TraceFormat::GpuSlices(gpuRanges, *state.gpuClock, clock, state.presents.front()); + snapshots.push_back({"gpu", gpuSlices, {}, gpuDropped}); + } const auto process = processId(); TraceSummary summary; summary.commit = APS5_TRACE_COMMIT; diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp index 3bff0dfa4..4153efa14 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp @@ -43,6 +43,7 @@ #include #include #include +#include #include #include #include @@ -256,6 +257,8 @@ struct VulkanDevice::State { VkDeviceSize uploadSize = 0; VkPhysicalDeviceProperties properties{}; std::string driverInfo; + PFN_vkGetCalibratedTimestampsKHR calibratedTimestamps = nullptr; + VkTimeDomainKHR hostTimeDomain = VK_TIME_DOMAIN_DEVICE_KHR; VkPhysicalDeviceSubgroupProperties subgroup{VK_STRUCTURE_TYPE_PHYSICAL_DEVICE_SUBGROUP_PROPERTIES}; std::vector capabilities{1}; std::vector spirvExtensions; @@ -1440,6 +1443,8 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window, bool compileOnly) : state->samplerAnisotropy = true; state->textureCompressionBC = true; deviceInfo.pEnabledFeatures = &enabled; + const char* calibratedTimestamps = !PerformanceTrace::Configured() ? nullptr : hasExtension(VK_KHR_CALIBRATED_TIMESTAMPS_EXTENSION_NAME) ? VK_KHR_CALIBRATED_TIMESTAMPS_EXTENSION_NAME : hasExtension(VK_EXT_CALIBRATED_TIMESTAMPS_EXTENSION_NAME) ? VK_EXT_CALIBRATED_TIMESTAMPS_EXTENSION_NAME : nullptr; + if (calibratedTimestamps != nullptr) deviceExtensions.push_back(calibratedTimestamps); deviceInfo.enabledExtensionCount = static_cast(deviceExtensions.size()); deviceInfo.ppEnabledExtensionNames = deviceExtensions.data(); if (state->meshShader) { @@ -1591,6 +1596,25 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window, bool compileOnly) : check(state->InstanceFunction("vkCreateDevice")(selected, &deviceInfo, nullptr, &state->device), "vkCreateDevice"); state->shaderProfile = std::move(shaderProfile); if (compileOnly) return; + if (calibratedTimestamps != nullptr) { + const bool khr = std::strcmp(calibratedTimestamps, VK_KHR_CALIBRATED_TIMESTAMPS_EXTENSION_NAME) == 0; + const auto domains = reinterpret_cast(state->instanceProc(state->instance, khr ? "vkGetPhysicalDeviceCalibrateableTimeDomainsKHR" : "vkGetPhysicalDeviceCalibrateableTimeDomainsEXT")); + std::uint32_t domainCount = 0; + std::vector available; + if (domains != nullptr && domains(selected, &domainCount, nullptr) == VK_SUCCESS) { + available.resize(domainCount); + if (domains(selected, &domainCount, available.data()) != VK_SUCCESS) available.clear(); + } +#ifdef _WIN32 + const auto host = VK_TIME_DOMAIN_QUERY_PERFORMANCE_COUNTER_KHR; +#else + const auto host = VK_TIME_DOMAIN_CLOCK_MONOTONIC_KHR; +#endif + if (std::ranges::find(available, VK_TIME_DOMAIN_DEVICE_KHR) != available.end() && std::ranges::find(available, host) != available.end()) { + state->hostTimeDomain = host; + state->calibratedTimestamps = state->DeviceFunction(khr ? "vkGetCalibratedTimestampsKHR" : "vkGetCalibratedTimestampsEXT"); + } + } state->DeviceFunction("vkGetDeviceQueue")(state->device, family, 0, &state->queue); APS5_LOG_OUT("Vulkan device ready device=%p queue=%p family=%u", reinterpret_cast(state->device), reinterpret_cast(state->queue), family); VkCommandPoolCreateInfo poolInfo{VK_STRUCTURE_TYPE_COMMAND_POOL_CREATE_INFO}; @@ -2953,6 +2977,30 @@ std::string VulkanDevice::DriverInfo() const { return state->driverInfo.empty() ? std::to_string(state->properties.driverVersion) : state->driverInfo; } +bool VulkanDevice::CalibrateClock(double& gpuNs, std::chrono::steady_clock::time_point& cpu) const { + if (state->calibratedTimestamps == nullptr) return false; + const std::array domains{VkCalibratedTimestampInfoKHR{VK_STRUCTURE_TYPE_CALIBRATED_TIMESTAMP_INFO_KHR, nullptr, VK_TIME_DOMAIN_DEVICE_KHR}, VkCalibratedTimestampInfoKHR{VK_STRUCTURE_TYPE_CALIBRATED_TIMESTAMP_INFO_KHR, nullptr, state->hostTimeDomain}}; + std::array stamps{}; + std::uint64_t deviation = 0; + if (state->calibratedTimestamps(state->device, static_cast(domains.size()), domains.data(), stamps.data(), &deviation) != VK_SUCCESS) return false; +#ifdef _WIN32 + LARGE_INTEGER counter{}; + LARGE_INTEGER frequency{}; + QueryPerformanceCounter(&counter); + const auto now = std::chrono::steady_clock::now(); + QueryPerformanceFrequency(&frequency); + const double sinceNs = static_cast(static_cast(counter.QuadPart) - stamps[1]) * 1e9 / static_cast(frequency.QuadPart); +#else + timespec monotonic{}; + clock_gettime(CLOCK_MONOTONIC, &monotonic); + const auto now = std::chrono::steady_clock::now(); + const double sinceNs = static_cast(static_cast(monotonic.tv_sec) * 1000000000ull + static_cast(monotonic.tv_nsec) - stamps[1]); +#endif + gpuNs = static_cast(stamps[0]) * state->properties.limits.timestampPeriod; + cpu = now - std::chrono::duration_cast(std::chrono::duration(sinceNs)); + return true; +} + const std::uint32_t* VulkanDevice::WorkGroupCountLimit() const { return state->properties.limits.maxComputeWorkGroupCount; } diff --git a/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp b/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp index c9d389575..a03be59e1 100644 --- a/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp +++ b/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp @@ -2358,6 +2358,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); } return; } @@ -2373,10 +2374,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); 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); 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 00e28defc..25c9a62be 100644 --- a/core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp +++ b/core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp @@ -140,6 +140,19 @@ void SummaryFields() { Check(TraceFormat::Summary(summary, dropped, presents).find("\"trace_dropped\":true") != std::string::npos, "a dropped thread did not mark the summary"); } +void GpuClock() { + const auto origin = Clock::now(); + 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}, {"draw", 6000.0, 7000.0}, {"batch", -39000.0, -30000.0}, {"copy", 8000.0, 8000.0}}; + const auto slices = TraceFormat::GpuSlices(ranges, first, last, origin); + Check(slices.size() == 2, "a GPU range before the window or without length was kept"); + Check(std::string_view(slices[0].scope) == "batch" && slices[0].stage == nullptr && slices[0].begin == origin + microseconds(12) && slices[0].length == microseconds(2), "a GPU range was not mapped between the two calibrations"); + Check(std::string_view(slices[1].scope) == "draw" && slices[1].begin == origin + std::chrono::nanoseconds(12500) && slices[1].length == std::chrono::nanoseconds(500), "a nested GPU range was not mapped"); + const AgcDriver::TraceClockSample same{1000.0, origin + microseconds(10)}; + Check(TraceFormat::GpuSlices(ranges, same, same, origin)[0].begin == origin + microseconds(14), "one calibration does not map at the CPU rate"); +} + void GzipFile() { std::string text; for (int index = 0; index < 20000; ++index) text += "{\"name\":\"Driver.Packet\",\"ph\":\"X\",\"ts\":" + std::to_string(index) + "}\n"; @@ -196,6 +209,7 @@ int main() { EscapeStrings(); EventsShape(); SummaryFields(); + GpuClock(); GzipFile(); AppendLines(); std::cout << "performance trace tests passed\n"; diff --git a/docs/dev/BUILD.md b/docs/dev/BUILD.md index 8825151d9..ecda8e546 100644 --- a/docs/dev/BUILD.md +++ b/docs/dev/BUILD.md @@ -128,7 +128,11 @@ Inside the window the queue workers and the presenter record every `PerformanceT The summary line has `commit` and `dirty` of the build, `env` (every `APS5_*` variable; a value containing `/` or `\` is written as ``), `gpu`, `driver`, `os`, `resolution` (the video output's), `window`, `presents`, `frame_ms` (p50, p90, p99 and max of the intervals between presents), `gpu_busy_ms_per_present` (the batch timestamps behind `[present]`), `worker_busy_pct` (share of the window each queue worker spends in `Driver.Packet`, `Driver.Suspend`, `Driver.EndSubmission`, `Driver.Rewind` and `Driver.Completion`), `top_phases_ms_per_frame` (the eight largest scopes and stages, without `Driver.WorkerWait`), `trace_dropped` and `trace`. A trace holds timings, scope names, counts and thread names; no guest memory, paths or strings of the title. -With either switch set, the recorder writes a timestamp pair per batch for the whole run, as with `APS5_PROFILE_DRAW`. Without them, a `PerformanceTimer` costs one more predictable branch. +The shader preparation threads are traced as well, `shader prepare`, with a buffer for 32,768 events each. A wait for the GPU mutex on a traced thread is a `GpuMutex.wait.` slice (`dispatch`, `draw`, `present`, `flush` and so on, as on the `[lock]` line). + +The `gpu` track holds one `batch` slice per recorder batch, from the batch's timestamp pair. With `APS5_PROFILE_GPU=1` it also holds a slice per command class range, under the class names of the `[gputime]` line (`draw`, `copy`, `fill`, `present-blit`, ...); program ranges are left out. The track keeps up to 262,144 ranges; more set `trace_dropped`. The GPU clock is mapped onto the CPU clock with calibrated timestamps (`VK_KHR_calibrated_timestamps` or the EXT version, enabled only when a trace switch is set) taken when the window opens and when it closes, so the two clocks are matched at both ends of the window. A batch is added when the driver reads its timestamps, after its fence signals, so the batches of the last frames of the window, which complete after it closes, are missing. Without calibrated timestamps the trace has no `gpu` track, and the `[trace]` line says so. + +With either switch set, the recorder writes a timestamp pair per batch for the whole run, as with `APS5_PROFILE_DRAW`. Without them, a `PerformanceTimer`, a GPU mutex acquisition and a read of batch timestamps each cost one more predictable branch. ## Driver thread priority