From 5668e0d0e776143fe9e77eab528332ba903465d4 Mon Sep 17 00:00:00 2001 From: AlxcBTW <187763517+AlxcBTW@users.noreply.github.com> Date: Mon, 12 Oct 2026 15:44:43 +0200 Subject: [PATCH 1/4] feat(agc): record a present window as a Chrome trace and a summary line APS5_TRACE_FRAMES=: (or APS5_TRACE_SECONDS=:) records every PerformanceTimer scope and stage of the queue workers and the presenter inside the window as complete events, named after their frame timing keys, into a preallocated buffer per thread. Slices under 20 us are counted per thread instead of written; a full buffer stops that thread and sets trace_dropped. When the window closes, a ProfileOutput writer thread writes aps5-trace--.json.gz and appends one line to aps5-summary.jsonl. Without either switch a PerformanceTimer costs one more predictable branch. Co-Authored-By: Claude Opus 5.5 --- core/libs/prx/libSceAgcDriver/CMakeLists.txt | 30 +- .../Execution/include/PerformanceTimer.hpp | 20 +- .../Execution/include/PerformanceTrace.hpp | 396 ++++++++++++++++++ .../Execution/include/VulkanDevice.hpp | 1 + .../Execution/src/Driver/Presentation.cpp | 2 +- .../src/Driver/Queues/QueueWorker.cpp | 9 +- .../Execution/src/PerformanceTrace.cpp | 205 +++++++++ .../Execution/src/VulkanDevice.cpp | 13 +- .../libSceAgcDriver/Graphics/src/Recorder.cpp | 4 +- .../tests/PerformanceTrace.cpp | 157 +++++++ .../prx/libSceAgcDriver/trace_revision.cmake | 19 + docs/dev/BUILD.md | 10 + 12 files changed, 850 insertions(+), 16 deletions(-) create mode 100644 core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp create mode 100644 core/libs/prx/libSceAgcDriver/Execution/src/PerformanceTrace.cpp create mode 100644 core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp create mode 100644 core/libs/prx/libSceAgcDriver/trace_revision.cmake diff --git a/core/libs/prx/libSceAgcDriver/CMakeLists.txt b/core/libs/prx/libSceAgcDriver/CMakeLists.txt index 5177c7d3c..d45eb56d5 100644 --- a/core/libs/prx/libSceAgcDriver/CMakeLists.txt +++ b/core/libs/prx/libSceAgcDriver/CMakeLists.txt @@ -162,6 +162,7 @@ set(agcDriverSources ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/Driver/Synchronization/WaitMemory.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/Driver/Synchronization/WaitStatistics.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/WorkerSampler.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/PerformanceTrace.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/ThreadPriority.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/GuestMemory.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/ShaderMemory.cpp @@ -219,9 +220,21 @@ set(agcDriverSources ${CMAKE_CURRENT_SOURCE_DIR}/Submit/src/Dcb.cpp ) +find_package(Git QUIET) +set(agcTraceRevisionHeader ${agcTextureDetileGeneratedRoot}/prx/libSceAgcDriver/TraceRevision.hpp) +add_custom_target(agc_trace_revision + COMMAND ${CMAKE_COMMAND} -DGIT=${GIT_EXECUTABLE} -DSOURCE=${CMAKE_SOURCE_DIR} -DOUTPUT=${agcTraceRevisionHeader} -P ${CMAKE_CURRENT_SOURCE_DIR}/trace_revision.cmake + BYPRODUCTS ${agcTraceRevisionHeader} + VERBATIM +) +set_source_files_properties(${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/PerformanceTrace.cpp PROPERTIES + INCLUDE_DIRECTORIES ${CMAKE_SOURCE_DIR}/3rdparty/libjpeg-turbo/src/spng/zlib +) + add_library(libSceAgcDriver SHARED EXCLUDE_FROM_ALL ${agcDriverSources} ) +add_dependencies(libSceAgcDriver agc_trace_revision) target_include_directories(libSceAgcDriver PRIVATE ${LIBS_INCLUDE_DIR} @@ -247,6 +260,7 @@ target_link_libraries(libSceAgcDriver PRIVATE SDL2-static libc libkernel + jpeg_turbo ${CMAKE_DL_LIBS} ) @@ -285,6 +299,17 @@ if(BUILD_TESTING) set_tests_properties(agc_stack_walk PROPERTIES ENVIRONMENT_MODIFICATION "PATH=path_list_prepend:$") endif() + + add_test_executable(agc_performance_trace_tests tests/PerformanceTrace.cpp) + target_include_directories(agc_performance_trace_tests PRIVATE ${LIBS_INCLUDE_DIR}) + target_link_libraries(agc_performance_trace_tests PRIVATE libc) + configure_windows_unwind(agc_performance_trace_tests) + add_test(NAME agc_performance_trace COMMAND agc_performance_trace_tests) + set_tests_properties(agc_performance_trace PROPERTIES TIMEOUT 20) + if(WIN32) + set_tests_properties(agc_performance_trace PROPERTIES ENVIRONMENT_MODIFICATION + "PATH=path_list_prepend:$") + endif() endif() if(WIN32) @@ -1014,7 +1039,8 @@ target_include_directories(agc_driver_mesh_tests PRIVATE ${ANYPS5_VULKAN_HEADERS_INCLUDE_DIR} ${ANYPS5_SPIRV_HEADERS_INCLUDE_DIR} ) -target_link_libraries(agc_driver_mesh_tests PRIVATE shader_recompiler_agc_driver SDL2-static libc libkernel ${CMAKE_DL_LIBS}) +target_link_libraries(agc_driver_mesh_tests PRIVATE shader_recompiler_agc_driver SDL2-static libc libkernel jpeg_turbo ${CMAKE_DL_LIBS}) +add_dependencies(agc_driver_mesh_tests agc_trace_revision) set_target_properties(agc_driver_mesh_tests PROPERTIES CXX_EXTENSIONS OFF) configure_windows_unwind(agc_driver_mesh_tests) @@ -1345,7 +1371,9 @@ if(AGC_BUILD_VISUAL_TEST) SDL2-static libc libkernel + jpeg_turbo ) + add_dependencies(agc_driver_visual_test agc_trace_revision) set_target_properties(agc_driver_visual_test PROPERTIES CXX_EXTENSIONS OFF) configure_windows_unwind(agc_driver_visual_test) diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp index 1f6bb75a0..c2cf77331 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp +++ b/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp @@ -1,6 +1,7 @@ #ifndef CORE_LIBS_PRX_LIBSCEAGCDRIVER_EXECUTION_INCLUDE_PERFORMANCETIMER_HPP #define CORE_LIBS_PRX_LIBSCEAGCDRIVER_EXECUTION_INCLUDE_PERFORMANCETIMER_HPP +#include "prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp" #include #include #include @@ -258,11 +259,11 @@ private: class PerformanceTimer { public: - explicit PerformanceTimer(const char* scope) : frame(PerformanceContext::Current()), scope(scope) { + explicit PerformanceTimer(const char* scope) : frame(PerformanceContext::Current()), trace(PerformanceTrace::Recording() ? PerformanceTrace::Thread() : nullptr), scope(scope) { if (frame != nullptr) { total = frame->Get(scope, "total"); } - if (frame != nullptr) start = Clock::now(); + if (frame != nullptr || trace != nullptr) start = Clock::now(); previous = start; } @@ -274,8 +275,11 @@ public: } void Finish() { - if (frame == nullptr) return; + if (frame == nullptr && trace == nullptr) return; const auto end = Clock::now(); + if (trace != nullptr) trace->Add(scope, nullptr, start, end); + trace = nullptr; + if (frame == nullptr) return; if (tail != nullptr) frame->Add(tail, end - previous); frame->Add(total, end - start); frame = nullptr; @@ -287,10 +291,13 @@ public: } void Mark(const char* stage, std::uint64_t bytes = 0) { - if (frame == nullptr) return; + if (frame == nullptr && trace == nullptr) return; const auto now = Clock::now(); - if (tail == nullptr) tail = frame->Get(scope, "tail"); - frame->Add(frame->Get(scope, stage), now - previous, bytes); + if (trace != nullptr) trace->Add(scope, stage, previous, now); + if (frame != nullptr) { + if (tail == nullptr) tail = frame->Get(scope, "tail"); + frame->Add(frame->Get(scope, stage), now - previous, bytes); + } previous = now; } @@ -298,6 +305,7 @@ private: using Clock = FrameTiming::Clock; FrameTiming* frame; + TraceThread* trace; const char* scope; FrameTiming::Metric* total = nullptr; FrameTiming::Metric* tail = nullptr; diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp new file mode 100644 index 000000000..d08dcc14a --- /dev/null +++ b/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp @@ -0,0 +1,396 @@ +#ifndef CORE_LIBS_PRX_LIBSCEAGCDRIVER_EXECUTION_INCLUDE_PERFORMANCETRACE_HPP +#define CORE_LIBS_PRX_LIBSCEAGCDRIVER_EXECUTION_INCLUDE_PERFORMANCETRACE_HPP + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +namespace AgcDriver { + +class VulkanDevice; + +class TraceWindow { +public: + using Clock = std::chrono::steady_clock; + enum class Edge { None, Open, Close }; + + static std::optional Parse(const char* frames, const char* seconds) { + if (frames == nullptr && seconds == nullptr) return std::nullopt; + if (frames != nullptr && seconds != nullptr) throw std::invalid_argument("APS5_TRACE_FRAMES and APS5_TRACE_SECONDS cannot be set together"); + const std::string_view name = frames != nullptr ? "APS5_TRACE_FRAMES" : "APS5_TRACE_SECONDS"; + const std::string_view text = frames != nullptr ? frames : seconds; + const auto colon = text.find(':'); + std::uint64_t start = 0; + std::uint64_t length = 0; + if (colon == std::string_view::npos || !number(text.substr(0, colon), start) || !number(text.substr(colon + 1), length) || length == 0) + throw std::invalid_argument(std::string(name) + "=" + std::string(text) + " is not : with a length above 0"); + return TraceWindow(frames != nullptr, start, length); + } + + Edge Present(std::uint64_t present, Clock::duration elapsed) { + if (state == State::Closed) return Edge::None; + if (state == State::Waiting) { + if (frames ? present < start : wholeSeconds(elapsed) < start) return Edge::None; + state = State::Open; + openedPresent = present; + openedAt = elapsed; + return Edge::Open; + } + if (frames ? present - openedPresent < length : wholeSeconds(elapsed - openedAt) < length) return Edge::None; + state = State::Closed; + return Edge::Close; + } + + std::string Describe() const { + return std::string(frames ? "frames " : "seconds ") + std::to_string(start) + ":" + std::to_string(length); + } + +private: + enum class State { Waiting, Open, Closed }; + + TraceWindow(bool frames, std::uint64_t start, std::uint64_t length) : frames(frames), start(start), length(length) {} + + static bool number(std::string_view text, std::uint64_t& value) { + const auto end = text.data() + text.size(); + const auto [last, error] = std::from_chars(text.data(), end, value); + return !text.empty() && error == std::errc{} && last == end; + } + + static std::uint64_t wholeSeconds(Clock::duration elapsed) { + return static_cast(std::chrono::duration_cast(elapsed).count()); + } + + bool frames; + std::uint64_t start; + std::uint64_t length; + State state = State::Waiting; + std::uint64_t openedPresent = 0; + Clock::duration openedAt{}; +}; + +class TraceThread { +public: + using Clock = std::chrono::steady_clock; + static constexpr std::size_t DefaultCapacity = 262144; + static constexpr Clock::duration MinimumSlice = std::chrono::microseconds(20); + + struct Slice { + const char* scope; + const char* stage; + Clock::time_point begin; + Clock::duration length; + }; + + struct Total { + const char* scope; + const char* stage; + Clock::duration length; + std::uint64_t count; + }; + + struct Snapshot { + std::string name; + std::span slices; + std::vector totals; + bool dropped = false; + }; + + TraceThread(std::string name, const std::atomic& presents, std::size_t capacity = DefaultCapacity) + : name(std::move(name)), presents(presents), slices(std::make_unique(capacity)), capacity(capacity) {} + + TraceThread(const TraceThread&) = delete; + TraceThread& operator=(const TraceThread&) = delete; + + void Add(const char* scope, const char* stage, Clock::time_point begin, Clock::time_point end) { + const auto length = end - begin; + account(scope, stage, length); + const auto present = presents.load(std::memory_order_relaxed); + if (!sampled || present != sampledPresent) { + if (sampled) append({nullptr, nullptr, sampleBegin, folded}); + sampled = true; + sampledPresent = present; + sampleBegin = begin; + folded = {}; + } + if (length < MinimumSlice) folded += length; + else append({scope, stage, begin, length}); + } + + Snapshot Collect() const { + Snapshot snapshot{name, {slices.get(), used.load(std::memory_order_acquire)}, {}, false}; + for (const auto& entry : entries) { + const auto* scope = entry.scope.load(std::memory_order_acquire); + if (scope == nullptr) continue; + snapshot.totals.push_back({scope, entry.stage.load(std::memory_order_relaxed), Clock::duration(entry.length.load(std::memory_order_relaxed)), entry.count.load(std::memory_order_relaxed)}); + } + snapshot.dropped = dropped.load(std::memory_order_relaxed); + return snapshot; + } + +private: + struct Entry { + std::atomic scope{nullptr}; + std::atomic stage{nullptr}; + std::atomic length{0}; + std::atomic count{0}; + }; + + void append(const Slice& slice) { + const auto index = used.load(std::memory_order_relaxed); + if (index == capacity) { + dropped.store(true, std::memory_order_relaxed); + return; + } + slices[index] = slice; + used.store(index + 1, std::memory_order_release); + } + + void account(const char* scope, const char* stage, Clock::duration length) { + const auto key = reinterpret_cast(scope) ^ (reinterpret_cast(stage) >> 3); + const auto hash = static_cast((static_cast(key) * 0x9e3779b97f4a7c15ull) >> 55); + for (std::size_t probe = 0; probe < entries.size(); ++probe) { + auto& entry = entries[(hash + probe) % entries.size()]; + const auto* current = entry.scope.load(std::memory_order_relaxed); + if (current == nullptr) { + entry.stage.store(stage, std::memory_order_relaxed); + entry.scope.store(scope, std::memory_order_release); + } else if (current != scope || entry.stage.load(std::memory_order_relaxed) != stage) { + continue; + } + entry.length.store(entry.length.load(std::memory_order_relaxed) + length.count(), std::memory_order_relaxed); + entry.count.store(entry.count.load(std::memory_order_relaxed) + 1, std::memory_order_relaxed); + return; + } + dropped.store(true, std::memory_order_relaxed); + } + + const std::string name; + const std::atomic& presents; + const std::unique_ptr slices; + const std::size_t capacity; + std::atomic used{0}; + std::atomic dropped{false}; + std::array entries; + bool sampled = false; + std::uint64_t sampledPresent = 0; + Clock::time_point sampleBegin{}; + Clock::duration folded{}; +}; + +struct TraceSummary { + std::string commit; + std::optional dirty; + std::vector> environment; + std::string gpu; + std::string driver; + std::string os; + std::uint32_t width = 0; + std::uint32_t height = 0; + std::string window; + std::uint64_t firstPresent = 0; + double gpuBusyMs = 0; + std::string trace; +}; + +class TraceFormat { +public: + using Clock = std::chrono::steady_clock; + static constexpr std::array WorkerBusyScopes{"Driver.Packet", "Driver.Suspend", "Driver.EndSubmission", "Driver.Rewind", "Driver.Completion"}; + static constexpr std::string_view WorkerWaitScope = "Driver.WorkerWait"; + static constexpr std::string_view WorkerPrefix = "queue worker "; + static constexpr std::size_t TopPhases = 8; + + static void AppendString(std::string& output, std::string_view text) { + output += '"'; + for (const char character : text) { + const auto byte = static_cast(character); + if (character == '"' || character == '\\') { + output += '\\'; + output += character; + } else if (byte < 0x20 || byte >= 0x7f) { + char escaped[8]; + std::snprintf(escaped, sizeof escaped, "\\u%04x", static_cast(byte)); + output += escaped; + } else { + output += character; + } + } + output += '"'; + } + + static std::string Name(const char* scope, const char* stage) { + return stage == nullptr ? std::string(scope) : std::string(scope) + "." + stage; + } + + static std::string Events(std::uint64_t process, Clock::time_point origin, std::span threads, std::size_t presenter, std::span presents, std::uint64_t firstPresent) { + std::string output = "{\"traceEvents\":[\n"; + bool first = true; + const auto event = [&](std::string_view name, const char* phase, Clock::time_point at, std::size_t tid) { + if (!first) output += ",\n"; + first = false; + output += "{\"name\":"; + AppendString(output, name); + char text[96]; + std::snprintf(text, sizeof text, ",\"ph\":\"%s\",\"ts\":%.3f,\"pid\":%llu,\"tid\":%llu", phase, microseconds(at - origin), static_cast(process), static_cast(tid)); + output += text; + }; + event("process_name", "M", origin, 0); + output += ",\"args\":{\"name\":\"AnyPS5\"}}"; + for (std::size_t index = 0; index < threads.size(); ++index) { + const auto& thread = threads[index]; + const auto tid = index + 1; + event("thread_name", "M", origin, tid); + output += ",\"args\":{\"name\":"; + AppendString(output, thread.name); + output += "}}"; + std::vector slices(thread.slices.begin(), thread.slices.end()); + 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]; + 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)); + } + output += text; + } + } + for (std::size_t index = 0; index + 1 < presents.size(); ++index) { + event("present", "i", presents[index], presenter + 1); + output += ",\"s\":\"g\",\"args\":{\"present\":" + std::to_string(firstPresent + index) + "}}"; + } + output += "\n]}\n"; + return output; + } + + 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(); + std::vector frames; + for (std::size_t index = 1; index < presents.size(); ++index) frames.push_back(milliseconds(presents[index] - presents[index - 1])); + std::sort(frames.begin(), frames.end()); + const auto percentile = [&](double fraction) { return frames.empty() ? 0.0 : frames[std::min(frames.size() - 1, static_cast(fraction * static_cast(frames.size())))]; }; + const double perPresent = count != 0 ? 1.0 / static_cast(count) : 0.0; + + std::string output = "{\"commit\":"; + AppendString(output, summary.commit); + output += ",\"dirty\":"; + output += summary.dirty.has_value() ? (*summary.dirty ? "true" : "false") : "null"; + output += ",\"env\":{"; + for (std::size_t index = 0; index < summary.environment.size(); ++index) { + if (index != 0) output += ','; + AppendString(output, summary.environment[index].first); + output += ':'; + AppendString(output, summary.environment[index].second); + } + output += "},\"gpu\":"; + AppendString(output, summary.gpu); + output += ",\"driver\":"; + AppendString(output, summary.driver); + output += ",\"os\":"; + AppendString(output, summary.os); + output += ",\"resolution\":"; + AppendString(output, std::to_string(summary.width) + "x" + std::to_string(summary.height)); + output += ",\"window\":{\"spec\":"; + AppendString(output, summary.window); + output += ",\"first_present\":" + std::to_string(summary.firstPresent); + output += ",\"ms\":" + number(milliseconds(span)) + "}"; + output += ",\"presents\":" + std::to_string(count); + output += ",\"frame_ms\":{\"p50\":" + number(percentile(0.5)) + ",\"p90\":" + number(percentile(0.9)) + ",\"p99\":" + number(percentile(0.99)) + ",\"max\":" + number(frames.empty() ? 0.0 : frames.back()) + "}"; + output += ",\"gpu_busy_ms_per_present\":" + number(summary.gpuBusyMs * perPresent); + + output += ",\"worker_busy_pct\":{"; + bool firstWorker = true; + std::map phases; + bool dropped = false; + for (const auto& thread : threads) { + dropped = dropped || thread.dropped; + Clock::duration busy{}; + for (const auto& total : thread.totals) { + const std::string_view scope = total.scope; + if (total.stage == nullptr && std::find(WorkerBusyScopes.begin(), WorkerBusyScopes.end(), scope) != WorkerBusyScopes.end()) busy += total.length; + if (scope != WorkerWaitScope) phases[Name(total.scope, total.stage)] += total.length; + } + if (!thread.name.starts_with(WorkerPrefix)) continue; + if (!firstWorker) output += ','; + firstWorker = false; + AppendString(output, thread.name); + output += ':' + number(span != Clock::duration{} ? 100.0 * static_cast(busy.count()) / static_cast(span.count()) : 0.0); + } + output += "},\"top_phases_ms_per_frame\":{"; + std::vector> top(phases.begin(), phases.end()); + std::stable_sort(top.begin(), top.end(), [](const auto& a, const auto& b) { return a.second > b.second; }); + for (std::size_t index = 0; index < top.size() && index < TopPhases; ++index) { + if (index != 0) output += ','; + AppendString(output, top[index].first); + output += ':' + number(milliseconds(top[index].second) * perPresent); + } + output += "},\"trace_dropped\":"; + output += dropped ? "true" : "false"; + output += ",\"trace\":"; + AppendString(output, summary.trace); + output += "}\n"; + return output; + } + +private: + static double microseconds(Clock::duration elapsed) { + return std::chrono::duration(elapsed).count(); + } + + static double milliseconds(Clock::duration elapsed) { + return std::chrono::duration(elapsed).count(); + } + + static std::string number(double value) { + char text[32]; + std::snprintf(text, sizeof text, "%.3f", value); + return text; + } +}; + +class PerformanceTrace { +public: + static bool Configured() { + static const bool configured = std::getenv("APS5_TRACE_FRAMES") != nullptr || std::getenv("APS5_TRACE_SECONDS") != nullptr; + return configured; + } + + static void BindThread(const char* name); + static void Present(std::uint32_t width, std::uint32_t height, const VulkanDevice* device); + + static bool Recording() { + return recording.load(std::memory_order_relaxed); + } + + static TraceThread* Thread() { + return local; + } + +private: + inline static std::atomic recording{false}; + inline static std::atomic presentCount{0}; + inline static thread_local TraceThread* local = nullptr; +}; + +} + +#endif diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/VulkanDevice.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/VulkanDevice.hpp index 2027874af..0b1c4c94d 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/include/VulkanDevice.hpp +++ b/core/libs/prx/libSceAgcDriver/Execution/include/VulkanDevice.hpp @@ -39,6 +39,7 @@ public: VulkanDevice(const VulkanDevice&) = delete; VulkanDevice& operator=(const VulkanDevice&) = delete; std::string DeviceName() const; + std::string DriverInfo() 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/Presentation.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Presentation.cpp index e1c00238f..8ea2d6e87 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Presentation.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Presentation.cpp @@ -37,7 +37,7 @@ void Driver::AttachWindow(const PresentationWindow& window) { } void Driver::Present(const PresentationWindow& window, const DisplayBuffer* buffer, bool opaque, void (*gpuReady)(void*), void* context) { - + if (PerformanceTrace::Configured()) PerformanceTrace::Present(window.width, window.height, device.Load().get()); PerformanceContext timingContext(window.timing.get()); PerformanceTimer timing("Driver.Present"); static thread_local bool pinned = false; diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Queues/QueueWorker.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Queues/QueueWorker.cpp index d568f7b81..3705fa7ec 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Queues/QueueWorker.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Queues/QueueWorker.cpp @@ -67,11 +67,9 @@ void Driver::reapCompletionLabels() { void Driver::run(std::uint32_t id) noexcept { onWorkerThread() = true; - { - char role[32]; - std::snprintf(role, sizeof role, "queue worker 0x%x", id); - PinWorkerThread(role); - } + char role[32]; + std::snprintf(role, sizeof role, "queue worker 0x%x", id); + PinWorkerThread(role); GuestMemory::TagGpuLockThread(id); if (id == 0) StartWorkerSampler(); @@ -79,6 +77,7 @@ void Driver::run(std::uint32_t id) noexcept { static const bool profile = std::getenv("APS5_PROFILE_DRAW") != nullptr; auto& costs = submissionCosts(id); try { + if (PerformanceTrace::Configured()) PerformanceTrace::BindThread(role); for (;;) { submission = Submission{}; struct Running { diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/PerformanceTrace.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/PerformanceTrace.cpp new file mode 100644 index 000000000..4fecef3d1 --- /dev/null +++ b/core/libs/prx/libSceAgcDriver/Execution/src/PerformanceTrace.cpp @@ -0,0 +1,205 @@ +#include "prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp" +#include "prx/libSceAgcDriver/Execution/include/ProfileOutput.hpp" +#include "prx/libSceAgcDriver/Execution/include/VulkanDevice.hpp" +#include "prx/libSceAgcDriver/TraceRevision.hpp" +#include "zlib.h" +#include +#include +#include +#include +#include +#include +#ifdef _WIN32 +#include +#else +#include +#include +#include +#endif + +#ifndef _WIN32 +extern char** environ; +#endif + +namespace AgcDriver { + +namespace { + +using Clock = std::chrono::steady_clock; + +struct Session { + std::mutex mutex; + std::vector> threads; + std::optional window; + Clock::time_point first{}; + std::uint64_t present = 0; + std::uint64_t firstPresent = 0; + double gpuBusyAtOpen = 0; + std::vector presents; +}; + +Session& session() { + static auto& state = *new Session(); + return state; +} + +std::unique_ptr& writer() { + static std::unique_ptr output; + return output; +} + +std::uint64_t processId() { +#ifdef _WIN32 + return GetCurrentProcessId(); +#else + return static_cast(::getpid()); +#endif +} + +std::string operatingSystem() { +#ifdef _WIN32 + using QueryVersion = LONG(WINAPI*)(PRTL_OSVERSIONINFOW); + static const auto query = reinterpret_cast(reinterpret_cast(::GetProcAddress(::GetModuleHandleW(L"ntdll.dll"), "RtlGetVersion"))); + RTL_OSVERSIONINFOW version{}; + version.dwOSVersionInfoSize = sizeof(version); + if (query == nullptr || query(&version) != 0) throw std::runtime_error("RtlGetVersion failed"); + return "Windows " + std::to_string(version.dwMajorVersion) + "." + std::to_string(version.dwMinorVersion) + "." + std::to_string(version.dwBuildNumber); +#else + utsname name{}; + if (::uname(&name) != 0) throw std::system_error(errno, std::generic_category(), "uname"); + return std::string(name.sysname) + " " + name.release; +#endif +} + +std::vector> environment() { +#ifdef _WIN32 + char** entries = _environ; +#else + char** entries = environ; +#endif + std::vector> result; + for (; entries != nullptr && *entries != nullptr; ++entries) { + const std::string_view entry = *entries; + const auto equals = entry.find('='); + if (!entry.starts_with("APS5_") || equals == std::string_view::npos) continue; + std::string value(entry.substr(equals + 1)); + if (value.find_first_of("/\\") != std::string::npos) value = ""; + result.emplace_back(std::string(entry.substr(0, equals)), std::move(value)); + } + std::sort(result.begin(), result.end()); + return result; +} + +void writeGzip(const std::filesystem::path& path, std::string_view text) { + z_stream stream{}; + if (deflateInit2(&stream, Z_DEFAULT_COMPRESSION, Z_DEFLATED, 15 + 16, 8, Z_DEFAULT_STRATEGY) != Z_OK) throw std::runtime_error("deflateInit2 failed"); + struct End { + z_stream& stream; + ~End() { deflateEnd(&stream); } + } end{stream}; + std::ofstream output; + output.exceptions(std::ios::badbit | std::ios::failbit); + output.open(path, std::ios::binary | std::ios::trunc); + std::vector chunk(1 << 16); + std::size_t offset = 0; + int status = Z_OK; + while (status != Z_STREAM_END) { + if (stream.avail_in == 0 && offset < text.size()) { + const auto piece = std::min(text.size() - offset, std::numeric_limits::max()); + stream.next_in = reinterpret_cast(const_cast(text.data() + offset)); + stream.avail_in = static_cast(piece); + offset += piece; + } + stream.next_out = chunk.data(); + stream.avail_out = static_cast(chunk.size()); + status = deflate(&stream, offset == text.size() ? Z_FINISH : Z_NO_FLUSH); + if (status != Z_OK && status != Z_STREAM_END) throw std::runtime_error("deflate failed with " + std::to_string(status)); + output.write(reinterpret_cast(chunk.data()), static_cast(chunk.size() - stream.avail_out)); + } + output.close(); +} + +void appendLine(const std::filesystem::path& path, std::string_view line) { + std::ofstream output; + output.exceptions(std::ios::badbit | std::ios::failbit); + output.open(path, std::ios::binary | std::ios::app); + output.write(line.data(), static_cast(line.size())); + output.close(); +} + +} + +void PerformanceTrace::BindThread(const char* name) { + if (!Configured() || local != nullptr) return; + auto bound = std::make_unique(name, presentCount); + auto& state = session(); + std::lock_guard lock(state.mutex); + local = bound.get(); + state.threads.push_back(std::move(bound)); +} + +void PerformanceTrace::Present(std::uint32_t width, std::uint32_t height, const VulkanDevice* device) { + const auto now = Clock::now(); + BindThread("presenter"); + auto& state = session(); + std::lock_guard lock(state.mutex); + if (!state.window) { + state.window.emplace(TraceWindow::Parse(std::getenv("APS5_TRACE_FRAMES"), std::getenv("APS5_TRACE_SECONDS")).value()); + state.first = now; + } + const auto present = state.present++; + const auto edge = state.window->Present(present, now - state.first); + if (edge == TraceWindow::Edge::Open) { + state.firstPresent = present; + state.gpuBusyAtOpen = VulkanDevice::PresentCounts().gpuBusyMs; + 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)); + return; + } + if (!recording.load(std::memory_order_relaxed)) return; + state.presents.push_back(now); + presentCount.fetch_add(1, std::memory_order_relaxed); + if (edge != TraceWindow::Edge::Close) return; + recording.store(false, std::memory_order_relaxed); + + std::vector snapshots; + std::size_t presenter = 0; + for (std::size_t index = 0; index < state.threads.size(); ++index) { + if (state.threads[index].get() == local) presenter = index; + snapshots.push_back(state.threads[index]->Collect()); + } + const auto process = processId(); + TraceSummary summary; + summary.commit = APS5_TRACE_COMMIT; + if (APS5_TRACE_DIRTY >= 0) summary.dirty = APS5_TRACE_DIRTY != 0; + summary.environment = environment(); + summary.gpu = device != nullptr ? device->DeviceName() : std::string(); + summary.driver = device != nullptr ? device->DriverInfo() : std::string(); + summary.os = operatingSystem(); + summary.width = width; + summary.height = height; + summary.window = state.window->Describe(); + summary.firstPresent = state.firstPresent; + summary.gpuBusyMs = VulkanDevice::PresentCounts().gpuBusyMs - state.gpuBusyAtOpen; + summary.trace = "aps5-trace-" + summary.commit + "-" + std::to_string(process) + ".json.gz"; + auto events = TraceFormat::Events(process, state.presents.front(), snapshots, presenter, state.presents, state.firstPresent); + const char* traceDirectory = std::getenv("APS5_TRACE_DIR"); + auto& output = writer(); + output = std::make_unique([directory = std::filesystem::path(traceDirectory != nullptr ? traceDirectory : "."), name = summary.trace, line = TraceFormat::Summary(summary, snapshots, state.presents)](std::string_view text) { + try { + std::filesystem::create_directories(directory); + writeGzip(directory / name, text); + appendLine(directory / "aps5-summary.jsonl", line); + std::fprintf(stderr, "[trace] wrote %s and its line in aps5-summary.jsonl\n", name.c_str()); + } catch (const std::exception& error) { + std::fprintf(stderr, "[trace] writing %s failed: %s\n", name.c_str(), error.what()); + throw; + } + }, std::numeric_limits::max()); + ProfilePrint_nid_no_patch("[trace] closed at present %llu, writing %s (%zu bytes of JSON)\n", static_cast(present), summary.trace.c_str(), events.size()); + output->Write(std::move(events)); +} + +} diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp index 8da0d00f9..7de696407 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp @@ -255,6 +255,7 @@ struct VulkanDevice::State { void* uploadMapping = nullptr; VkDeviceSize uploadSize = 0; VkPhysicalDeviceProperties properties{}; + std::string driverInfo; VkPhysicalDeviceSubgroupProperties subgroup{VK_STRUCTURE_TYPE_PHYSICAL_DEVICE_SUBGROUP_PROPERTIES}; std::vector capabilities{1}; std::vector spirvExtensions; @@ -1039,7 +1040,13 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window, bool compileOnly) : std::vector availableExtensions(extensionCount); check(enumerateDeviceExtensions(selected, nullptr, &extensionCount, availableExtensions.data()), "vkEnumerateDeviceExtensionProperties"); const auto hasExtension = [&](const char* name) { return std::any_of(availableExtensions.begin(), availableExtensions.end(), [&](const auto& item) { return std::strcmp(item.extensionName, name) == 0; }); }; - auto byteFeatures = QueryBdaByteFeatures(selected, state->InstanceFunction("vkGetPhysicalDeviceFeatures2"), availableExtensions); + if (hasExtension(VK_KHR_DRIVER_PROPERTIES_EXTENSION_NAME)) { + VkPhysicalDeviceDriverProperties driver{VK_STRUCTURE_TYPE_PHYSICAL_DEVICE_DRIVER_PROPERTIES}; + VkPhysicalDeviceProperties2 driverProperties{VK_STRUCTURE_TYPE_PHYSICAL_DEVICE_PROPERTIES_2, &driver}; + state->InstanceFunction("vkGetPhysicalDeviceProperties2")(selected, &driverProperties); + state->driverInfo = std::string(driver.driverName) + " " + driver.driverInfo; + } + auto byteFeatures =QueryBdaByteFeatures(selected, state->InstanceFunction("vkGetPhysicalDeviceFeatures2"), availableExtensions); auto bdaFeatures = QueryBdaFeatures(selected, state->InstanceFunction("vkGetPhysicalDeviceFeatures2"), availableExtensions); require(hasExtension(VK_KHR_SHADER_FLOAT_CONTROLS_EXTENSION_NAME), "VK_KHR_shader_float_controls is unavailable"); VkPhysicalDeviceFloatControlsProperties floatControls{VK_STRUCTURE_TYPE_PHYSICAL_DEVICE_FLOAT_CONTROLS_PROPERTIES}; @@ -2942,6 +2949,10 @@ std::string VulkanDevice::DeviceName() const { return state->properties.deviceName; } +std::string VulkanDevice::DriverInfo() const { + return state->driverInfo.empty() ? std::to_string(state->properties.driverVersion) : state->driverInfo; +} + 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 ea8d595f5..c9d389575 100644 --- a/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp +++ b/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp @@ -1811,7 +1811,7 @@ bool Recorder::GpuTimingEnabled() { } bool Recorder::BatchStampsEnabled() { - return GpuTimingEnabled() || DrawProfiled(); + return GpuTimingEnabled() || DrawProfiled() || PerformanceTrace::Configured(); } void Recorder::CountBarriers(CommandClass which, std::uint32_t count) { @@ -1903,7 +1903,7 @@ std::uint32_t Recorder::BeginGpuTiming(std::uint64_t key) { std::uint32_t Recorder::beginTiming(std::uint64_t key) { const bool full = GpuTimingEnabled(); - if (!full && !(key == BatchTimingKey && DrawProfiled())) return NoTiming; + if (!full && !(key == BatchTimingKey && BatchStampsEnabled())) return NoTiming; const auto commands = open->commands; const std::uint32_t queryCount = full ? MaxTimedRanges * 2 : 2; if (open->queries == VK_NULL_HANDLE) { diff --git a/core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp b/core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp new file mode 100644 index 000000000..51e487265 --- /dev/null +++ b/core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp @@ -0,0 +1,157 @@ +#include "prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp" +#include + +namespace { + +using AgcDriver::TraceFormat; +using AgcDriver::TraceThread; +using AgcDriver::TraceWindow; +using Clock = std::chrono::steady_clock; +using Edge = TraceWindow::Edge; +using std::chrono::microseconds; +using std::chrono::milliseconds; + +void Check(bool condition, const char* message) { + if (!condition) throw std::runtime_error(message); +} + +void WindowByFrames() { + auto window = TraceWindow::Parse("3:2", nullptr).value(); + std::vector edges; + for (std::uint64_t present = 0; present < 8; ++present) edges.push_back(window.Present(present, std::chrono::seconds(present))); + Check(edges == std::vector{Edge::None, Edge::None, Edge::None, Edge::Open, Edge::None, Edge::Close, Edge::None, Edge::None}, "frame window opened or closed at the wrong present"); + Check(window.Describe() == "frames 3:2", "frame window description changed"); +} + +void WindowBySeconds() { + auto window = TraceWindow::Parse(nullptr, "2:1").value(); + std::vector edges; + for (const auto elapsed : {milliseconds(0), milliseconds(1999), milliseconds(2000), milliseconds(2999), milliseconds(3000), milliseconds(5000)}) + edges.push_back(window.Present(0, elapsed)); + Check(edges == std::vector{Edge::None, Edge::None, Edge::Open, Edge::None, Edge::Close, Edge::None}, "seconds window opened or closed at the wrong present"); + Check(window.Describe() == "seconds 2:1", "seconds window description changed"); +} + +void WindowRejects() { + Check(!TraceWindow::Parse(nullptr, nullptr).has_value(), "a window was made without a switch"); + for (const auto* text : {"5", "a:1", "1:0", "1:", ":1", "1:2:3", "-1:2"}) { + bool rejected = false; + try { TraceWindow::Parse(text, nullptr); } + catch (const std::invalid_argument&) { rejected = true; } + Check(rejected, "a malformed window was accepted"); + } + bool rejected = false; + try { TraceWindow::Parse("1:1", "1:1"); } + catch (const std::invalid_argument&) { rejected = true; } + Check(rejected, "frames and seconds were accepted together"); +} + +void BufferCap() { + std::atomic presents{1}; + TraceThread thread("queue worker 0x0", presents, 2); + const auto origin = Clock::now(); + for (int index = 0; index < 3; ++index) thread.Add("Driver.Packet", nullptr, origin + milliseconds(index), origin + milliseconds(index) + microseconds(30)); + const auto snapshot = thread.Collect(); + Check(snapshot.slices.size() == 2 && snapshot.dropped, "a full buffer did not stop and set the dropped flag"); + Check(snapshot.totals.size() == 1 && snapshot.totals[0].count == 3 && snapshot.totals[0].length == microseconds(90), "totals missed a slice past the cap"); +} + +void FoldShortSlices() { + std::atomic presents{1}; + TraceThread thread("queue worker 0x0", presents, 16); + const auto origin = Clock::now(); + thread.Add("Driver.Packet", nullptr, origin, origin + microseconds(5)); + thread.Add("Driver.Packet", "draw", origin + microseconds(5), origin + microseconds(10)); + thread.Add("Driver.Draw", nullptr, origin + microseconds(10), origin + microseconds(40)); + presents.store(2); + thread.Add("Driver.Completion", nullptr, origin + microseconds(50), origin + microseconds(90)); + const auto snapshot = thread.Collect(); + Check(snapshot.slices.size() == 3 && !snapshot.dropped, "short slices were written or long ones lost"); + Check(std::string_view(snapshot.slices[0].scope) == "Driver.Draw", "the first long slice is missing"); + Check(snapshot.slices[1].scope == nullptr && snapshot.slices[1].begin == origin && snapshot.slices[1].length == microseconds(10), "the folded sample of the previous present is wrong"); + Check(std::string_view(snapshot.slices[2].scope) == "Driver.Completion", "the slice after the present is missing"); + Check(snapshot.totals.size() == 4, "totals did not keep scope and stage apart"); + for (const auto& total : snapshot.totals) Check(total.count == 1, "a total counted a slice twice"); +} + +void EscapeStrings() { + std::string output; + TraceFormat::AppendString(output, "a\"b\\c\n\xe9"); + Check(output == "\"a\\\"b\\\\c\\u000a\\u00e9\"", "string escaping is not valid JSON"); +} + +void EventsShape() { + const auto origin = Clock::now(); + const std::vector slices{ + {"Driver.Packet", nullptr, origin + microseconds(10), microseconds(30)}, + {"Driver.Packet", "draw", origin + microseconds(12), microseconds(25)}, + {nullptr, nullptr, origin, milliseconds(2)}, + }; + 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); + const std::string expected = + "{\"traceEvents\":[\n" + "{\"name\":\"process_name\",\"ph\":\"M\",\"ts\":0.000,\"pid\":7,\"tid\":0,\"args\":{\"name\":\"AnyPS5\"}},\n" + "{\"name\":\"thread_name\",\"ph\":\"M\",\"ts\":0.000,\"pid\":7,\"tid\":1,\"args\":{\"name\":\"queue worker 0x0\"}},\n" + "{\"name\":\"queue worker 0x0 folded\",\"ph\":\"C\",\"ts\":0.000,\"pid\":7,\"tid\":1,\"args\":{\"ms\":2.000}},\n" + "{\"name\":\"Driver.Packet\",\"ph\":\"X\",\"ts\":10.000,\"pid\":7,\"tid\":1,\"dur\":30.000},\n" + "{\"name\":\"Driver.Packet.draw\",\"ph\":\"X\",\"ts\":12.000,\"pid\":7,\"tid\":1,\"dur\":25.000},\n" + "{\"name\":\"present\",\"ph\":\"i\",\"ts\":0.000,\"pid\":7,\"tid\":1,\"s\":\"g\",\"args\":{\"present\":5}}\n" + "]}\n"; + Check(json == expected, "trace events changed shape"); +} + +void SummaryFields() { + const auto origin = Clock::now(); + AgcDriver::TraceSummary summary; + summary.commit = "abc"; + summary.dirty = false; + summary.environment = {{"APS5_TRACE_FRAMES", "3:2"}}; + summary.gpu = "GPU"; + summary.driver = "Driver 1"; + summary.os = "OS 1"; + summary.width = 1920; + summary.height = 1080; + summary.window = "frames 3:2"; + summary.firstPresent = 3; + summary.gpuBusyMs = 20; + summary.trace = "aps5-trace-abc-7.json.gz"; + const std::vector threads{ + {"queue worker 0x0", {}, {{"Driver.Packet", nullptr, milliseconds(12), 4}, {"Driver.WorkerWait", nullptr, milliseconds(8), 4}, {"Driver.Completion", nullptr, milliseconds(2), 4}, {"Driver.Packet", "draw", milliseconds(10), 2}}, false}, + {"presenter", {}, {{"Driver.Present", nullptr, milliseconds(6), 2}, {"Driver.Present", "inflight_wait", milliseconds(4), 2}}, false}, + }; + const std::vector presents{origin, origin + milliseconds(16), origin + milliseconds(40)}; + const auto line = TraceFormat::Summary(summary, threads, presents); + const std::string expected = + "{\"commit\":\"abc\",\"dirty\":false,\"env\":{\"APS5_TRACE_FRAMES\":\"3:2\"},\"gpu\":\"GPU\",\"driver\":\"Driver 1\",\"os\":\"OS 1\"," + "\"resolution\":\"1920x1080\",\"window\":{\"spec\":\"frames 3:2\",\"first_present\":3,\"ms\":40.000},\"presents\":2," + "\"frame_ms\":{\"p50\":24.000,\"p90\":24.000,\"p99\":24.000,\"max\":24.000},\"gpu_busy_ms_per_present\":10.000," + "\"worker_busy_pct\":{\"queue worker 0x0\":35.000}," + "\"top_phases_ms_per_frame\":{\"Driver.Packet\":6.000,\"Driver.Packet.draw\":5.000,\"Driver.Present\":3.000,\"Driver.Present.inflight_wait\":2.000,\"Driver.Completion\":1.000}," + "\"trace_dropped\":false,\"trace\":\"aps5-trace-abc-7.json.gz\"}\n"; + Check(line == expected, "summary line changed"); + auto dropped = threads; + dropped[1].dropped = true; + Check(TraceFormat::Summary(summary, dropped, presents).find("\"trace_dropped\":true") != std::string::npos, "a dropped thread did not mark the summary"); +} + +} + +int main() { + try { + WindowByFrames(); + WindowBySeconds(); + WindowRejects(); + BufferCap(); + FoldShortSlices(); + EscapeStrings(); + EventsShape(); + SummaryFields(); + std::cout << "performance trace tests passed\n"; + return 0; + } catch (const std::exception& error) { + std::cerr << error.what() << '\n'; + return 1; + } +} diff --git a/core/libs/prx/libSceAgcDriver/trace_revision.cmake b/core/libs/prx/libSceAgcDriver/trace_revision.cmake new file mode 100644 index 000000000..a63974e68 --- /dev/null +++ b/core/libs/prx/libSceAgcDriver/trace_revision.cmake @@ -0,0 +1,19 @@ +set(commit unknown) +set(dirty -1) +if(GIT) + execute_process(COMMAND "${GIT}" -C "${SOURCE}" rev-parse --short=12 HEAD + OUTPUT_VARIABLE head RESULT_VARIABLE failed OUTPUT_STRIP_TRAILING_WHITESPACE ERROR_QUIET) + if(failed EQUAL 0 AND NOT head STREQUAL "") + set(commit ${head}) + execute_process(COMMAND "${GIT}" -C "${SOURCE}" status --porcelain --untracked-files=no + OUTPUT_VARIABLE changes RESULT_VARIABLE failed ERROR_QUIET) + if(failed EQUAL 0 AND changes STREQUAL "") + set(dirty 0) + elseif(failed EQUAL 0) + set(dirty 1) + endif() + endif() +endif() +file(WRITE "${OUTPUT}.new" "#pragma once\n#define APS5_TRACE_COMMIT \"${commit}\"\n#define APS5_TRACE_DIRTY ${dirty}\n") +execute_process(COMMAND ${CMAKE_COMMAND} -E copy_if_different "${OUTPUT}.new" "${OUTPUT}") +file(REMOVE "${OUTPUT}.new") diff --git a/docs/dev/BUILD.md b/docs/dev/BUILD.md index 95afced99..3bd170987 100644 --- a/docs/dev/BUILD.md +++ b/docs/dev/BUILD.md @@ -120,6 +120,16 @@ Set `APS5_SAMPLE_WORKER=` to sample queue worker 0 every millisecond (in p `APS5_SAMPLE_THREADS=` samples every thread of the process every 2 ms and writes the 40 hottest addresses of each busy thread to ``, 12 frames deep and through `.pdata` only. Both samplers exist only on Windows; the addresses are symbolized offline, for example with `nm` on the `.prx`. +## Performance trace + +Set `APS5_TRACE_FRAMES=:` to record `` presents from present `` (counted from 0), or `APS5_TRACE_SECONDS=:` to record from the first present at least `` seconds after the first present until the first present `` seconds later. Both values are whole numbers and the length is above 0; a malformed value, or both switches together, fails the first present. The window opens and closes at presents. + +Inside the window the queue workers and the presenter record every `PerformanceTimer` scope and stage as a complete event named after its frame timing key: `Driver.WorkerWait`, `Driver.Packet`, `Driver.Packet.draw`, `Graphics.Draw`, `Driver.Present`, `Driver.Present.inflight_wait`, `Vulkan.Retire` and so on. A slice shorter than 20 us is only counted: its time is in the thread's counter ` folded` (milliseconds per present) and in the summary. Each thread allocates a buffer for 262,144 events when it starts; a full buffer stops that thread's recording and sets `trace_dropped`. When the window closes, the presenter formats the trace once and a `ProfileOutput` writer thread writes `aps5-trace--.json.gz` (Chrome trace-event JSON, opened by ui.perfetto.dev or chrome://tracing) and appends one line to `aps5-summary.jsonl`, both in `APS5_TRACE_DIR` or the working directory. A window that is still open when the title exits writes nothing. + +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. + ## Driver thread priority Set `APS5_THREAD_PRIORITY=high` to raise the AGC driver's queue workers and the video output presenter above the title's threads. On Linux the threads get nice `APS5_THREAD_NICE` (default -10) through rtkit; on Windows they get `THREAD_PRIORITY_HIGHEST`. `APS5_THREAD_PRIORITY=rt` asks rtkit for real-time priority `APS5_THREAD_RT` (default 10, at most rtkit's `MaxRealtimePriority`) under rtkit's policy, `SCHED_RR` by default; on Windows it sets `THREAD_PRIORITY_TIME_CRITICAL`. rtkit only grants it when the process's hard `RLIMIT_RTTIME` is at most its `RTTimeUSecMax` (200000 us by default), so a hard limit above `APS5_THREAD_RTTIME_US` (default 200000, capped at `RTTimeUSecMax`) is lowered to it and the soft limit to at most half of it. The hard limit cannot be raised again and stays lowered for the whole process even if rtkit then refuses; see [technical debt](TechnicalDebt.md#functional). There is no fallback between the modes: when rtkit or `SetThreadPriority` refuses, a queue worker reports the refusal as a driver failure, which the next submission, wait or shutdown rethrows, and the presenter's start throws it. Each raised thread logs its priority once as `[thread-priority]`. The setting is `off` by default; a value other than `off`, `high` or `rt` is reported the same way as a refusal. From 5c7da226df9f73db9376156e90ef25a23710ee19 Mon Sep 17 00:00:00 2001 From: AlxcBTW <187763517+AlxcBTW@users.noreply.github.com> Date: Mon, 12 Oct 2026 16:52:58 +0200 Subject: [PATCH 2/4] fix(agc): write the trace's gzip framing around a raw deflate stream The zlib in the tree (libjpeg-turbo's) is built with NO_GZIP, so deflateInit2 refuses the gzip wrapper (windowBits 31) and no trace was written. The trace file now writes the gzip header, a raw deflate stream, and the CRC-32 and size trailer itself. The writer's result line is flushed, since stderr is buffered in a title process. The file writing moves to TraceFile, and a test inflates a written file and checks its CRC-32 and size. Co-Authored-By: Claude Opus 5.5 --- core/libs/prx/libSceAgcDriver/CMakeLists.txt | 12 ++-- .../Execution/include/TraceFile.hpp | 17 ++++++ .../Execution/src/PerformanceTrace.cpp | 46 ++------------ .../Execution/src/TraceFile.cpp | 61 +++++++++++++++++++ .../tests/PerformanceTrace.cpp | 50 +++++++++++++++ 5 files changed, 140 insertions(+), 46 deletions(-) create mode 100644 core/libs/prx/libSceAgcDriver/Execution/include/TraceFile.hpp create mode 100644 core/libs/prx/libSceAgcDriver/Execution/src/TraceFile.cpp diff --git a/core/libs/prx/libSceAgcDriver/CMakeLists.txt b/core/libs/prx/libSceAgcDriver/CMakeLists.txt index d45eb56d5..e7428c6d5 100644 --- a/core/libs/prx/libSceAgcDriver/CMakeLists.txt +++ b/core/libs/prx/libSceAgcDriver/CMakeLists.txt @@ -163,6 +163,7 @@ set(agcDriverSources ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/Driver/Synchronization/WaitStatistics.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/WorkerSampler.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/PerformanceTrace.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/TraceFile.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/ThreadPriority.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/GuestMemory.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/ShaderMemory.cpp @@ -227,8 +228,9 @@ add_custom_target(agc_trace_revision BYPRODUCTS ${agcTraceRevisionHeader} VERBATIM ) -set_source_files_properties(${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/PerformanceTrace.cpp PROPERTIES - INCLUDE_DIRECTORIES ${CMAKE_SOURCE_DIR}/3rdparty/libjpeg-turbo/src/spng/zlib +set(agcZlibIncludeDir ${CMAKE_SOURCE_DIR}/3rdparty/libjpeg-turbo/src/spng/zlib) +set_source_files_properties(${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/TraceFile.cpp PROPERTIES + INCLUDE_DIRECTORIES ${agcZlibIncludeDir} ) add_library(libSceAgcDriver SHARED EXCLUDE_FROM_ALL @@ -300,9 +302,9 @@ if(BUILD_TESTING) "PATH=path_list_prepend:$") endif() - add_test_executable(agc_performance_trace_tests tests/PerformanceTrace.cpp) - target_include_directories(agc_performance_trace_tests PRIVATE ${LIBS_INCLUDE_DIR}) - target_link_libraries(agc_performance_trace_tests PRIVATE libc) + add_test_executable(agc_performance_trace_tests tests/PerformanceTrace.cpp Execution/src/TraceFile.cpp) + target_include_directories(agc_performance_trace_tests PRIVATE ${LIBS_INCLUDE_DIR} ${agcZlibIncludeDir}) + target_link_libraries(agc_performance_trace_tests PRIVATE libc jpeg_turbo) configure_windows_unwind(agc_performance_trace_tests) add_test(NAME agc_performance_trace COMMAND agc_performance_trace_tests) set_tests_properties(agc_performance_trace PROPERTIES TIMEOUT 20) diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/TraceFile.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/TraceFile.hpp new file mode 100644 index 000000000..9174bfbc0 --- /dev/null +++ b/core/libs/prx/libSceAgcDriver/Execution/include/TraceFile.hpp @@ -0,0 +1,17 @@ +#ifndef CORE_LIBS_PRX_LIBSCEAGCDRIVER_EXECUTION_INCLUDE_TRACEFILE_HPP +#define CORE_LIBS_PRX_LIBSCEAGCDRIVER_EXECUTION_INCLUDE_TRACEFILE_HPP + +#include +#include + +namespace AgcDriver { + +class TraceFile { +public: + static void WriteGzip(const std::filesystem::path& path, std::string_view text); + static void AppendLine(const std::filesystem::path& path, std::string_view line); +}; + +} + +#endif diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/PerformanceTrace.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/PerformanceTrace.cpp index 4fecef3d1..f435f16ac 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/PerformanceTrace.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/PerformanceTrace.cpp @@ -1,11 +1,10 @@ #include "prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp" #include "prx/libSceAgcDriver/Execution/include/ProfileOutput.hpp" +#include "prx/libSceAgcDriver/Execution/include/TraceFile.hpp" #include "prx/libSceAgcDriver/Execution/include/VulkanDevice.hpp" #include "prx/libSceAgcDriver/TraceRevision.hpp" -#include "zlib.h" #include #include -#include #include #include #include @@ -90,43 +89,6 @@ std::vector> environment() { return result; } -void writeGzip(const std::filesystem::path& path, std::string_view text) { - z_stream stream{}; - if (deflateInit2(&stream, Z_DEFAULT_COMPRESSION, Z_DEFLATED, 15 + 16, 8, Z_DEFAULT_STRATEGY) != Z_OK) throw std::runtime_error("deflateInit2 failed"); - struct End { - z_stream& stream; - ~End() { deflateEnd(&stream); } - } end{stream}; - std::ofstream output; - output.exceptions(std::ios::badbit | std::ios::failbit); - output.open(path, std::ios::binary | std::ios::trunc); - std::vector chunk(1 << 16); - std::size_t offset = 0; - int status = Z_OK; - while (status != Z_STREAM_END) { - if (stream.avail_in == 0 && offset < text.size()) { - const auto piece = std::min(text.size() - offset, std::numeric_limits::max()); - stream.next_in = reinterpret_cast(const_cast(text.data() + offset)); - stream.avail_in = static_cast(piece); - offset += piece; - } - stream.next_out = chunk.data(); - stream.avail_out = static_cast(chunk.size()); - status = deflate(&stream, offset == text.size() ? Z_FINISH : Z_NO_FLUSH); - if (status != Z_OK && status != Z_STREAM_END) throw std::runtime_error("deflate failed with " + std::to_string(status)); - output.write(reinterpret_cast(chunk.data()), static_cast(chunk.size() - stream.avail_out)); - } - output.close(); -} - -void appendLine(const std::filesystem::path& path, std::string_view line) { - std::ofstream output; - output.exceptions(std::ios::badbit | std::ios::failbit); - output.open(path, std::ios::binary | std::ios::app); - output.write(line.data(), static_cast(line.size())); - output.close(); -} - } void PerformanceTrace::BindThread(const char* name) { @@ -190,11 +152,13 @@ void PerformanceTrace::Present(std::uint32_t width, std::uint32_t height, const output = std::make_unique([directory = std::filesystem::path(traceDirectory != nullptr ? traceDirectory : "."), name = summary.trace, line = TraceFormat::Summary(summary, snapshots, state.presents)](std::string_view text) { try { std::filesystem::create_directories(directory); - writeGzip(directory / name, text); - appendLine(directory / "aps5-summary.jsonl", line); + TraceFile::WriteGzip(directory / name, text); + TraceFile::AppendLine(directory / "aps5-summary.jsonl", line); std::fprintf(stderr, "[trace] wrote %s and its line in aps5-summary.jsonl\n", name.c_str()); + std::fflush(stderr); } catch (const std::exception& error) { std::fprintf(stderr, "[trace] writing %s failed: %s\n", name.c_str(), error.what()); + std::fflush(stderr); throw; } }, std::numeric_limits::max()); diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/TraceFile.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/TraceFile.cpp new file mode 100644 index 000000000..40d0a7e08 --- /dev/null +++ b/core/libs/prx/libSceAgcDriver/Execution/src/TraceFile.cpp @@ -0,0 +1,61 @@ +#include "prx/libSceAgcDriver/Execution/include/TraceFile.hpp" +#include "zlib.h" +#include +#include +#include +#include +#include +#include +#include + +namespace AgcDriver { + +void TraceFile::WriteGzip(const std::filesystem::path& path, std::string_view text) { + z_stream stream{}; + if (deflateInit2(&stream, Z_DEFAULT_COMPRESSION, Z_DEFLATED, -MAX_WBITS, 8, Z_DEFAULT_STRATEGY) != Z_OK) throw std::runtime_error("deflateInit2 failed"); + struct End { + z_stream& stream; + ~End() { deflateEnd(&stream); } + } end{stream}; + std::ofstream output; + output.exceptions(std::ios::badbit | std::ios::failbit); + output.open(path, std::ios::binary | std::ios::trunc); + const std::array header{0x1f, 0x8b, 8, 0, 0, 0, 0, 0, 0, 0xff}; + output.write(reinterpret_cast(header.data()), header.size()); + uLong crc = crc32(0, Z_NULL, 0); + std::vector chunk(1 << 16); + std::size_t offset = 0; + int status = Z_OK; + while (status != Z_STREAM_END) { + if (stream.avail_in == 0 && offset < text.size()) { + const auto piece = static_cast(std::min(text.size() - offset, std::size_t{1} << 30)); + stream.next_in = reinterpret_cast(const_cast(text.data() + offset)); + stream.avail_in = piece; + crc = crc32(crc, stream.next_in, piece); + offset += piece; + } + stream.next_out = chunk.data(); + stream.avail_out = static_cast(chunk.size()); + status = deflate(&stream, offset == text.size() ? Z_FINISH : Z_NO_FLUSH); + if (status != Z_OK && status != Z_STREAM_END) throw std::runtime_error("deflate failed with " + std::to_string(status)); + output.write(reinterpret_cast(chunk.data()), static_cast(chunk.size() - stream.avail_out)); + } + std::array trailer{}; + const auto size = static_cast(text.size()); + for (unsigned index = 0; index < 4; ++index) { + trailer[index] = static_cast((crc >> (8 * index)) & 0xff); + trailer[4 + index] = static_cast((size >> (8 * index)) & 0xff); + } + output.write(reinterpret_cast(trailer.data()), trailer.size()); + output.close(); +} + +void TraceFile::AppendLine(const std::filesystem::path& path, std::string_view line) { + std::ofstream output; + output.exceptions(std::ios::badbit | std::ios::failbit); + output.open(path, std::ios::binary | std::ios::app); + output.write(line.data(), static_cast(line.size())); + output.close(); +} + +} diff --git a/core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp b/core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp index 51e487265..00e28defc 100644 --- a/core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp +++ b/core/libs/prx/libSceAgcDriver/tests/PerformanceTrace.cpp @@ -1,5 +1,9 @@ #include "prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp" +#include "prx/libSceAgcDriver/Execution/include/TraceFile.hpp" +#include "zlib.h" +#include #include +#include namespace { @@ -136,6 +140,50 @@ void SummaryFields() { Check(TraceFormat::Summary(summary, dropped, presents).find("\"trace_dropped\":true") != std::string::npos, "a dropped thread did not mark the summary"); } +void GzipFile() { + std::string text; + for (int index = 0; index < 20000; ++index) text += "{\"name\":\"Driver.Packet\",\"ph\":\"X\",\"ts\":" + std::to_string(index) + "}\n"; + const auto stem = "aps5-trace-test-" + std::to_string(Clock::now().time_since_epoch().count()); + const auto path = std::filesystem::temp_directory_path() / (stem + ".json.gz"); + AgcDriver::TraceFile::WriteGzip(path, text); + std::ifstream input(path, std::ios::binary); + const std::vector bytes((std::istreambuf_iterator(input)), std::istreambuf_iterator()); + input.close(); + std::filesystem::remove(path); + Check(bytes.size() > 18 && bytes[0] == 0x1f && bytes[1] == 0x8b && bytes[2] == 8 && bytes[3] == 0, "the gzip header is wrong"); + z_stream stream{}; + Check(inflateInit2(&stream, -MAX_WBITS) == Z_OK, "inflateInit2 failed"); + std::string inflated(text.size() + 1, 0); + stream.next_in = const_cast(bytes.data() + 10); + stream.avail_in = static_cast(bytes.size() - 18); + stream.next_out = reinterpret_cast(inflated.data()); + stream.avail_out = static_cast(inflated.size()); + const int status = inflate(&stream, Z_FINISH); + inflated.resize(inflated.size() - stream.avail_out); + const bool consumed = stream.avail_in == 0; + inflateEnd(&stream); + Check(status == Z_STREAM_END && consumed, "the deflate stream does not end at the trailer"); + Check(inflated == text, "the gzip file does not hold the text"); + const auto word = [&](std::size_t at) { + std::uint32_t value = 0; + for (unsigned index = 0; index < 4; ++index) value |= static_cast(bytes[at + index]) << (8 * index); + return value; + }; + Check(word(bytes.size() - 8) == crc32(0, reinterpret_cast(text.data()), static_cast(text.size())), "the CRC-32 is wrong"); + Check(word(bytes.size() - 4) == text.size(), "the size is wrong"); +} + +void AppendLines() { + const auto path = std::filesystem::temp_directory_path() / ("aps5-summary-test-" + std::to_string(Clock::now().time_since_epoch().count()) + ".jsonl"); + AgcDriver::TraceFile::AppendLine(path, "{\"presents\":1}\n"); + AgcDriver::TraceFile::AppendLine(path, "{\"presents\":2}\n"); + std::ifstream input(path, std::ios::binary); + const std::string written((std::istreambuf_iterator(input)), std::istreambuf_iterator()); + input.close(); + std::filesystem::remove(path); + Check(written == "{\"presents\":1}\n{\"presents\":2}\n", "summary lines were not appended"); +} + } int main() { @@ -148,6 +196,8 @@ int main() { EscapeStrings(); EventsShape(); SummaryFields(); + GzipFile(); + AppendLines(); std::cout << "performance trace tests passed\n"; return 0; } catch (const std::exception& error) { From af52bc430f13657bf9033b0f0a80e0795453022e Mon Sep 17 00:00:00 2001 From: AlxcBTW <187763517+AlxcBTW@users.noreply.github.com> Date: Mon, 12 Oct 2026 20:19:13 +0200 Subject: [PATCH 3/4] style(agc): restore the space before QueryBdaByteFeatures Co-Authored-By: Claude Opus 5.5 --- core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp index 7de696407..3bff0dfa4 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp @@ -1046,7 +1046,7 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window, bool compileOnly) : state->InstanceFunction("vkGetPhysicalDeviceProperties2")(selected, &driverProperties); state->driverInfo = std::string(driver.driverName) + " " + driver.driverInfo; } - auto byteFeatures =QueryBdaByteFeatures(selected, state->InstanceFunction("vkGetPhysicalDeviceFeatures2"), availableExtensions); + auto byteFeatures = QueryBdaByteFeatures(selected, state->InstanceFunction("vkGetPhysicalDeviceFeatures2"), availableExtensions); auto bdaFeatures = QueryBdaFeatures(selected, state->InstanceFunction("vkGetPhysicalDeviceFeatures2"), availableExtensions); require(hasExtension(VK_KHR_SHADER_FLOAT_CONTROLS_EXTENSION_NAME), "VK_KHR_shader_float_controls is unavailable"); VkPhysicalDeviceFloatControlsProperties floatControls{VK_STRUCTURE_TYPE_PHYSICAL_DEVICE_FLOAT_CONTROLS_PROPERTIES}; From 6116fc75e1ff43ed053265681450980abe4084cf Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Adri=C3=A0=20Franch?= Date: Mon, 12 Oct 2026 21:31:49 +0200 Subject: [PATCH 4/4] docs(agc): say the last present of a trace window has no folded sample Co-Authored-By: Claude --- docs/dev/BUILD.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/dev/BUILD.md b/docs/dev/BUILD.md index 3bd170987..8825151d9 100644 --- a/docs/dev/BUILD.md +++ b/docs/dev/BUILD.md @@ -124,7 +124,7 @@ Set `APS5_SAMPLE_WORKER=` to sample queue worker 0 every millisecond (in p Set `APS5_TRACE_FRAMES=:` to record `` presents from present `` (counted from 0), or `APS5_TRACE_SECONDS=:` to record from the first present at least `` seconds after the first present until the first present `` seconds later. Both values are whole numbers and the length is above 0; a malformed value, or both switches together, fails the first present. The window opens and closes at presents. -Inside the window the queue workers and the presenter record every `PerformanceTimer` scope and stage as a complete event named after its frame timing key: `Driver.WorkerWait`, `Driver.Packet`, `Driver.Packet.draw`, `Graphics.Draw`, `Driver.Present`, `Driver.Present.inflight_wait`, `Vulkan.Retire` and so on. A slice shorter than 20 us is only counted: its time is in the thread's counter ` folded` (milliseconds per present) and in the summary. Each thread allocates a buffer for 262,144 events when it starts; a full buffer stops that thread's recording and sets `trace_dropped`. When the window closes, the presenter formats the trace once and a `ProfileOutput` writer thread writes `aps5-trace--.json.gz` (Chrome trace-event JSON, opened by ui.perfetto.dev or chrome://tracing) and appends one line to `aps5-summary.jsonl`, both in `APS5_TRACE_DIR` or the working directory. A window that is still open when the title exits writes nothing. +Inside the window the queue workers and the presenter record every `PerformanceTimer` scope and stage as a complete event named after its frame timing key: `Driver.WorkerWait`, `Driver.Packet`, `Driver.Packet.draw`, `Graphics.Draw`, `Driver.Present`, `Driver.Present.inflight_wait`, `Vulkan.Retire` and so on. A slice shorter than 20 us is only counted: its time is in the thread's counter ` folded` (milliseconds per present) and in the summary. A thread writes a present's counter sample at its first slice after the next present, so the last present of the window has no sample; its time is still in the summary. Each thread allocates a buffer for 262,144 events when it starts; a full buffer stops that thread's recording and sets `trace_dropped`. When the window closes, the presenter formats the trace once and a `ProfileOutput` writer thread writes `aps5-trace--.json.gz` (Chrome trace-event JSON, opened by ui.perfetto.dev or chrome://tracing) and appends one line to `aps5-summary.jsonl`, both in `APS5_TRACE_DIR` or the working directory. A window that is still open when the title exits writes nothing. 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.