diff --git a/core/libs/prx/libSceAgcDriver/CMakeLists.txt b/core/libs/prx/libSceAgcDriver/CMakeLists.txt index 641225581a..0e534cec35 100644 --- a/core/libs/prx/libSceAgcDriver/CMakeLists.txt +++ b/core/libs/prx/libSceAgcDriver/CMakeLists.txt @@ -1560,12 +1560,13 @@ configure_windows_unwind(agc_driver_recorder_tests) if(BUILD_TESTING) set_target_properties(agc_driver_recorder_tests PROPERTIES EXCLUDE_FROM_ALL OFF) add_test(NAME agc_recorder_device_selection COMMAND agc_driver_recorder_tests --device-selection-only) + add_test(NAME agc_gpu_timing_key COMMAND agc_driver_recorder_tests --gpu-timing-key-only) add_test(NAME agc_gpu_timing_complete COMMAND agc_driver_recorder_tests --gpu-timing-complete-only) add_test(NAME agc_gpu_timing_incomplete COMMAND agc_driver_recorder_tests --gpu-timing-incomplete-only) set_tests_properties(agc_gpu_timing_complete agc_gpu_timing_incomplete PROPERTIES ENVIRONMENT "APS5_PROFILE_GPU=1" TIMEOUT 15 SKIP_RETURN_CODE 77) if(WIN32) - set_tests_properties(agc_recorder_device_selection agc_gpu_timing_complete agc_gpu_timing_incomplete PROPERTIES ENVIRONMENT_MODIFICATION + set_tests_properties(agc_recorder_device_selection agc_gpu_timing_key agc_gpu_timing_complete agc_gpu_timing_incomplete PROPERTIES ENVIRONMENT_MODIFICATION "PATH=path_list_prepend:$") endif() add_test(NAME agc_command_memory_reuse COMMAND agc_driver_recorder_tests --command-reuse-only) diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Draw/Draw.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Draw/Draw.cpp index 4d85df3c00..f1e01ef9ec 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Draw/Draw.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Draw/Draw.cpp @@ -1210,6 +1210,15 @@ DrawVerdict Driver::finishDraw(DrawTail& tail, PerformanceTimer& timing) { return DrawVerdict::Rejected; } } + if (static const bool nameVariants = std::getenv("APS5_PROFILE_GPU_DRAWS") != nullptr; nameVariants && stages.size() == programs.size()) { + static std::mutex namedMutex; + static std::set named; + std::lock_guard namedLock(namedMutex); + for (std::size_t i = 0; i < stages.size(); ++i) { + if (stages[i].program == nullptr || !named.insert(stages[i].program->variantId).second) continue; + std::fprintf(stderr, "[drawvariant] 0x%llx stage %d code 0x%llx\n", static_cast(stages[i].program->variantId), static_cast(stages[i].stage), static_cast(programs[i].binary.codeAddress)); + } + } if (pipelined && !drawParameters.indirect && (tail.queue == nullptr || deferredLabels().labels.empty())) { phaseTiming.Phase(DrawRowVectors); auto writes = drawWriteRanges(graphics, stages); diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Draw/DrawCapture.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Draw/DrawCapture.cpp index a6f6b5ebd9..443174fec5 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Draw/DrawCapture.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Draw/DrawCapture.cpp @@ -133,7 +133,7 @@ std::shared_ptr Driver::materializeDraw if (dumpTarget != 0) { const auto slot0 = (static_cast(readRegister(queue.context, 0x390)) << 40u) | (static_cast(readRegister(queue.context, 0x318)) << 8u); - if ((graphics.hasColorTarget && graphics.color.address == dumpTarget) || slot0 == dumpTarget) static_cast(dumpRequest(program.binary.codeAddress, request)); + if ((graphics.hasColorTarget && graphics.color.address == dumpTarget) || slot0 == dumpTarget || program.binary.codeAddress == dumpTarget) static_cast(dumpRequest(program.binary.codeAddress, request)); } if (dumpSlot1 != 0) { const auto value = [&](std::uint32_t offset) -> std::uint64_t { const auto it = queue.context.find(offset); return it == queue.context.end() ? 0u : it->second; }; diff --git a/core/libs/prx/libSceAgcDriver/Graphics/include/Recorder.hpp b/core/libs/prx/libSceAgcDriver/Graphics/include/Recorder.hpp index f76e061983..826dc8cb7d 100644 --- a/core/libs/prx/libSceAgcDriver/Graphics/include/Recorder.hpp +++ b/core/libs/prx/libSceAgcDriver/Graphics/include/Recorder.hpp @@ -22,6 +22,7 @@ #include #include #include +#include #include namespace AgcDriver::Graphics { @@ -472,9 +473,13 @@ public: // queries around each timed range; the totals per key are reported every 10 s. Begin returns the // range index to pass to End, or NoTiming when timing is off or the batch's queries are used up. static constexpr std::uint32_t NoTiming = 0xffffffffu; + static constexpr std::uint64_t DrawTimingFlag = std::uint64_t{1} << 63u; + static constexpr std::uint64_t DrawTimingKey(std::uint64_t variantId) { return variantId | DrawTimingFlag; } + static std::string TimingKeyLabel(std::uint64_t key); static bool GpuTimingEnabled(); static bool BatchStampsEnabled(); std::uint32_t BeginGpuTiming(std::uint64_t key); + std::uint32_t BeginInPassGpuTiming(std::uint64_t key); // `bytes`: what the range moved (a fill's, a copy's), summed per key on the [gputime] line. void EndGpuTiming(std::uint32_t index, std::uint64_t bytes = 0); // The key of the whole-batch range (first to last command; reported as "batch" on the [gputime] diff --git a/core/libs/prx/libSceAgcDriver/Graphics/src/Draw.cpp b/core/libs/prx/libSceAgcDriver/Graphics/src/Draw.cpp index 967d113df9..88104b74b4 100644 --- a/core/libs/prx/libSceAgcDriver/Graphics/src/Draw.cpp +++ b/core/libs/prx/libSceAgcDriver/Graphics/src/Draw.cpp @@ -2328,6 +2328,15 @@ void recordDraw(const Context& context, const State& state, const Pm4::DrawParam APS5_LOG_CHARS_OUT_DEBUG("Resources bound"); pushDrawConstants(*record.pipeline, commands, state, draw, shaders, resources, record.pushBytes, record.pushStages, meshArguments != nullptr ? meshArguments->DeviceAddress() : 0, !inputs.restartTable.empty()); APS5_LOG_CHARS_OUT_DEBUG("Push constants recorded"); + static const bool timeEachDraw = std::getenv("APS5_PROFILE_GPU_DRAWS") != nullptr; + auto eachDrawTiming = Recorder::NoTiming; + if (timeEachDraw) { + std::uint64_t key = 0; + for (const auto& shader : shaders) { + if (shader.program != nullptr && (key == 0 || shader.stage == ShaderRecompiler::ShaderStage::Fragment)) key = shader.program->variantId; + } + eachDrawTiming = recorder->BeginInPassGpuTiming(Recorder::DrawTimingKey(key)); + } if (record.stencilReplay.empty()) recordDrawCommands(context, commands, state, draw, inputs, record.indirect, argumentBuffer, argumentOffset, trace, subdraw); else { recordStencilReplay(context, commands, state, draw, inputs, record.stencilReplay, shaders, resources, record.pushBytes, record.pushStages); @@ -2341,6 +2350,7 @@ void recordDraw(const Context& context, const State& state, const Pm4::DrawParam record.pipeline->ContinueSecondChannel(commands); recordDrawCommands(context, commands, state, draw, inputs, record.indirect, argumentBuffer, argumentOffset, trace, subdraw); } + recorder->EndGpuTiming(eachDrawTiming); if (meshArguments != nullptr) recorder->Keep(meshArguments); if (args != nullptr) CountIndirectDraw(record.indirect->path, record.indirect->readMs, rewritten); auto checkRecords = indirectRecordCheck(record.indirect); diff --git a/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp b/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp index 3abc0aec26..c657013f21 100644 --- a/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp +++ b/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp @@ -2017,6 +2017,17 @@ std::uint32_t Recorder::BeginGpuTiming(std::uint64_t key) { return beginTiming(key); } +std::string Recorder::TimingKeyLabel(std::uint64_t key) { + char text[32]; + std::snprintf(text, sizeof(text), (key & DrawTimingFlag) != 0 ? "draw 0x%llx" : "0x%llx", static_cast(key & ~DrawTimingFlag)); + return text; +} + +std::uint32_t Recorder::BeginInPassGpuTiming(std::uint64_t key) { + if (!GpuTimingEnabled() || open == nullptr || open->queries == VK_NULL_HANDLE) return NoTiming; + return beginTiming(key); +} + std::uint32_t Recorder::beginTiming(std::uint64_t key) { const bool full = GpuTimingEnabled(); if (!full && !(key == BatchTimingKey && BatchStampsEnabled())) return NoTiming; @@ -2688,7 +2699,7 @@ void Recorder::readGpuTiming(Batch& batch) { std::sort(hot.begin(), hot.end(), [](const auto& a, const auto& b) { return a.second.ms > b.second.ms; }); // The first field stays the program sum: the measure scripts match on it. AgcDriver::ProfilePrint_nid_no_patch("[gputime] %.0f ms of GPU time in %llu batches over 10 s (batch %.0f ms first to last command; classes %.0f ms, all ranges %.0f ms, untimed %.0f ms outside every range; %llu presents; %llu ranges dropped at the %u cap); by program:", timingProgramMs, static_cast(timingBatches), timingBatchMs, timingClassMs, timingUnionMs, timingBatchMs - timingUnionMs, static_cast(presents), static_cast(timingDropped.exchange(0, std::memory_order_relaxed)), MaxTimedRanges); - for (std::size_t i = 0; i < hot.size() && i < 12; ++i) AgcDriver::ProfilePrint_nid_no_patch(" 0x%llx x%llu %.0fms", static_cast(hot[i].first), static_cast(hot[i].second.count), hot[i].second.ms); + for (std::size_t i = 0; i < hot.size() && i < 12; ++i) AgcDriver::ProfilePrint_nid_no_patch(" %s x%llu %.0fms", Recorder::TimingKeyLabel(hot[i].first).c_str(), static_cast(hot[i].second.count), hot[i].second.ms); AgcDriver::ProfilePrint_nid_no_patch("; by class:%s\n", classes.c_str()); timingByKey.clear(); timingProgramMs = timingClassMs = timingUnionMs = timingBatchMs = 0; diff --git a/core/libs/prx/libSceAgcDriver/tests/Recorder.cpp b/core/libs/prx/libSceAgcDriver/tests/Recorder.cpp index 4a400c6f7d..37951e9e15 100644 --- a/core/libs/prx/libSceAgcDriver/tests/Recorder.cpp +++ b/core/libs/prx/libSceAgcDriver/tests/Recorder.cpp @@ -252,6 +252,18 @@ bool hintMappingHistoryTests() { #endif } +void gpuTimingKeyTests() { + constexpr std::uint64_t variant = 0x2; + const auto key = Recorder::DrawTimingKey(variant); + Require(key != variant && (key & Recorder::DrawTimingFlag) != 0, "a draw's timing key is not flagged apart from the other keys"); + char named[64]; + std::snprintf(named, sizeof(named), "0x%llx", static_cast(variant)); + Require(Recorder::TimingKeyLabel(key) == std::string("draw ") + named, "a draw's timing label is not 'draw ' plus the id [drawvariant] prints"); + Require(Recorder::TimingKeyLabel(variant) == named, "a key that is not a draw's is labelled with the draw prefix"); + Require(Recorder::TimingKeyLabel(Recorder::DrawTimingKey(0)) == "draw 0x0", "a draw with no program is not labelled as a draw"); + Require(Recorder::TimingKeyLabel(Recorder::DrawTimingKey(0x123456789abcdefull)) == "draw 0x123456789abcdef", "a wide variant id was cut in the label"); +} + void deviceSelectionTests() { const auto properties = [](const char* name, VkPhysicalDeviceType type) { VkPhysicalDeviceProperties result{}; @@ -11492,6 +11504,11 @@ int main(int argc, char** argv) { std::cout << "partial private write-watch restoration tests passed\n"; return 0; } + if (argc == 2 && std::string_view(argv[1]) == "--gpu-timing-key-only") { + gpuTimingKeyTests(); + std::cout << "gpu timing key tests passed\n"; + return 0; + } if (argc == 2 && std::string_view(argv[1]) == "--device-selection-only") { deviceSelectionTests(); std::cout << "recorder device selection tests passed\n"; diff --git a/docs/dev/ENVIRONMENT.md b/docs/dev/ENVIRONMENT.md index 19cc8dcfb4..ade54bbf7c 100644 --- a/docs/dev/ENVIRONMENT.md +++ b/docs/dev/ENVIRONMENT.md @@ -136,7 +136,7 @@ The code reads environment names through `getenv`, `IsEnvironmentSet`, `kibSetti | `APS5_DRAW_UPLOAD_MAX` | integer | `core/libs/prx/libSceAgcDriver/Graphics/src/ShaderResources.cpp` | 4096 | largest draw snapshot in bytes copied into the per-recorder upload chunk; 0 turns the chunk off | | `APS5_DUMP_COMPUTE_MIN_WORDS` | integer | `core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp` | | only captures compute pipelines whose SPIR-V has at least this many words | | `APS5_DUMP_COMPUTE_PIPELINES` | string | `core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp` | | directory in which captured compute pipelines are written | -| `APS5_DUMP_DRAW_SHADERS` | integer | `core/libs/prx/libSceAgcDriver/Execution/src/Driver/Draw/Draw.cpp` | 0 | hex color-target or slot-0 address whose draw's shaders are dumped | +| `APS5_DUMP_DRAW_SHADERS` | integer | `core/libs/prx/libSceAgcDriver/Execution/src/Driver/Draw/Draw.cpp` | 0 | hex color-target or slot-0 address, or a program's code address, whose draw's shaders are dumped | | `APS5_DUMP_DRAW_SLOT1` | integer | `core/libs/prx/libSceAgcDriver/Execution/src/Driver/Draw/Draw.cpp` | 0 | hex slot-1 address whose draw's shaders and register state are dumped | | `APS5_DUMP_FRAMES` | integer | `core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp` | 0 | saves the first n presented frames as frame_.bmp | | `APS5_DUMP_FRAMES_EVERY` | integer | `core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp` | 1 | dumps every n-th presented frame | @@ -370,6 +370,7 @@ The code reads environment names through `getenv`, `IsEnvironmentSet`, `kibSetti | `APS5_PROBE_DISPATCH` | string | `core/libs/prx/libSceAgcDriver/Execution/src/Driver/Dispatch/Dispatch.cpp` | | probes one dispatch at a hex program address (optionally `:index`) with debug output | | `APS5_PROFILE_DRAW` | presence | `core/libs/prx/libSceAgcDriver/Execution/src/Driver/Dispatch/Dispatch.cpp` | | prints the per-phase driver and draw timing totals | | `APS5_PROFILE_GPU` | presence | `core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp` | | records the GPU time of recorded work by key from batch timestamps | +| `APS5_PROFILE_GPU_DRAWS` | presence | `core/libs/prx/libSceAgcDriver/Execution/src/Driver/Draw/Draw.cpp`, `core/libs/prx/libSceAgcDriver/Graphics/src/Draw.cpp` | | with APS5_PROFILE_GPU, records the GPU time of each recorded draw by its fragment program's variant id and prints a [drawvariant] line with the code address behind each variant id once (draws that do not use a recipe only; the [gputime] line labels each `draw 0x`, the id [drawvariant] prints, and the ranges share the batch's query cap) | | `APS5_REAP_EACH_PACKET` | presence | `core/libs/prx/libSceAgcDriver/Execution/src/Driver/Synchronization/DeferredLabels.cpp` | | reaps deferred labels after every packet | | `APS5_RELEASE_ON_UNLOCK` | presence | `core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp` | | destroys deferred batches on the unlocking thread instead of a release thread | | `APS5_RELEASE_QUEUE_MAX` | integer | `core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp` | 256 | maximum deferred batches handed to the release thread before a thread destroys its own |