From 2441bd265da9e01eff1631a6fa99ddee5ccfd7a7 Mon Sep 17 00:00:00 2001 From: boykopovar Date: Wed, 7 Oct 2026 10:27:06 +0300 Subject: [PATCH] perf(log): write frame timings async to a buffered file --- CMakeLists.txt | 2 +- .../Execution/include/PerformanceTimer.hpp | 68 +++++++------- .../libSceVideoOut/include/FrameTimingLog.hpp | 94 +++++++++++++++++++ .../prx/libSceVideoOut/src/VideoOutDriver.cpp | 22 ++++- 4 files changed, 149 insertions(+), 37 deletions(-) create mode 100644 core/libs/prx/libSceVideoOut/include/FrameTimingLog.hpp diff --git a/CMakeLists.txt b/CMakeLists.txt index 5ef07bff0..dc964efd6 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -24,7 +24,7 @@ if(BUILD_TESTING) endif() option(ANYPS5_ENABLE_SPIRV_TOOLS "Enable SPIRV-Tools validation and optimization" OFF) -option(APS5_ENABLE_TIMING_LOG "Enable frame timing logging" OFF) +option(APS5_ENABLE_TIMING_LOG "Write frame timings asynchronously to frame-timing.log" OFF) add_compile_definitions(APS5_ENABLE_TIMING_LOG=$) set(CMAKE_CXX_STANDARD 20) diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp index 6ce0b2d54..a41e1a67e 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp +++ b/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp @@ -5,17 +5,15 @@ #include #include #include -#include +#include #include -#include #include #include #include -#include +#include #include #include #include -#include "prx/libc/include/general/LogMacros.hpp" namespace AgcDriver { @@ -107,39 +105,39 @@ public: gpuGapMs += gapMs; } - void Print(std::uint32_t outputHandle, std::int32_t buffer, std::int64_t argument, Clock::time_point finished, Clock::duration interval) { + std::function Capture(std::uint32_t outputHandle, std::int32_t buffer, std::int64_t argument, Clock::time_point finished, Clock::duration interval) { std::lock_guard lock(mutex); if (firstSerial == 0 || flipSerial == 0) throw std::runtime_error("Frame timing: incomplete submission lineage"); - std::ostringstream output; - output.imbue(std::locale::classic()); - output << std::fixed << std::setprecision(3); - output << "[FrameTiming] frame=" << id << " submissions=" << firstSerial << ':' << lastSerial; - output << " output=" << outputHandle; - output << " flip=" << flipSerial << ':' << flipOffset << " buffer=" << buffer << " argument=" << argument; - output << " endpoint=flip_complete display_confirmed=0"; - output << " first_submit_to_flip_ms=" << milliseconds(finished - start); - output << " flip_submit_to_complete_ms=" << milliseconds(finished - flipReceived); - output << " first_submit_to_execute_ms=" << milliseconds(executionStart - start); - output << " execute_to_flip_packet_ms=" << milliseconds(flipReached - executionStart); - output << " flip_packet_to_complete_ms=" << milliseconds(finished - flipReached); - auto accounted = Clock::duration::zero(); - for (const auto scope : {"Driver.Packet", "Driver.Suspend", "Driver.Worker", "Driver.Completion"}) { - const auto it = metrics.find({scope, "total"}); - if (it != metrics.end()) accounted += it->second.total; - } - output << " worker_unattributed_ms=" << milliseconds(flipReached - executionStart - accounted); - if (interval != Clock::duration::zero()) output << " flip_interval_ms=" << milliseconds(interval); - output << " batches_at_flip=" << batchesAtFlip << " unsignaled_at_flip=" << unsignaledAtFlip << " batches_at_blit=" << batchesAtBlit << " batches_after_flip=" << batchesAfterFlip; - output << " gpu_busy_ms=" << gpuBusyMs << " gpu_gap_ms=" << gpuGapMs; - output << " last_submit_after_flip_ms=" << milliseconds(lastSubmitAfterFlip) << " blit_submit_after_flip_ms=" << milliseconds(blitSubmitAfterFlip); - output << " metrics=inclusive(count,sum_ms,max_ms[,bytes])"; - for (const auto& [key, metric] : metrics) { - if (metric.count == 0) continue; - output << ' ' << key.first << '.' << key.second << "=(" << metric.count << ',' << milliseconds(metric.total) << ',' << milliseconds(metric.maximum); - if (metric.bytes != 0) output << ',' << metric.bytes; - output << ')'; - } - APS5_LOG_TIMING("%s", output.str().c_str()); + return [metrics = metrics, id = id, firstSerial = firstSerial, lastSerial = lastSerial, flipSerial = flipSerial, flipOffset = flipOffset, start = start, executionStart = executionStart, flipReceived = flipReceived, flipReached = flipReached, batchesAtFlip = batchesAtFlip, unsignaledAtFlip = unsignaledAtFlip, batchesAtBlit = batchesAtBlit, batchesAfterFlip = batchesAfterFlip, gpuBusyMs = gpuBusyMs, gpuGapMs = gpuGapMs, lastSubmitAfterFlip = lastSubmitAfterFlip, blitSubmitAfterFlip = blitSubmitAfterFlip, outputHandle, buffer, argument, finished, interval](std::ostream& output) { + output << std::fixed << std::setprecision(3); + output << "[FrameTiming] frame=" << id << " submissions=" << firstSerial << ':' << lastSerial; + output << " output=" << outputHandle; + output << " flip=" << flipSerial << ':' << flipOffset << " buffer=" << buffer << " argument=" << argument; + output << " endpoint=flip_complete display_confirmed=0"; + output << " first_submit_to_flip_ms=" << milliseconds(finished - start); + output << " flip_submit_to_complete_ms=" << milliseconds(finished - flipReceived); + output << " first_submit_to_execute_ms=" << milliseconds(executionStart - start); + output << " execute_to_flip_packet_ms=" << milliseconds(flipReached - executionStart); + output << " flip_packet_to_complete_ms=" << milliseconds(finished - flipReached); + auto accounted = Clock::duration::zero(); + for (const auto scope : {"Driver.Packet", "Driver.Suspend", "Driver.Worker", "Driver.Completion"}) { + const auto it = metrics.find({scope, "total"}); + if (it != metrics.end()) accounted += it->second.total; + } + output << " worker_unattributed_ms=" << milliseconds(flipReached - executionStart - accounted); + if (interval != Clock::duration::zero()) output << " flip_interval_ms=" << milliseconds(interval); + output << " batches_at_flip=" << batchesAtFlip << " unsignaled_at_flip=" << unsignaledAtFlip << " batches_at_blit=" << batchesAtBlit << " batches_after_flip=" << batchesAfterFlip; + output << " gpu_busy_ms=" << gpuBusyMs << " gpu_gap_ms=" << gpuGapMs; + output << " last_submit_after_flip_ms=" << milliseconds(lastSubmitAfterFlip) << " blit_submit_after_flip_ms=" << milliseconds(blitSubmitAfterFlip); + output << " metrics=inclusive(count,sum_ms,max_ms[,bytes])"; + for (const auto& [key, metric] : metrics) { + if (metric.count == 0) continue; + output << ' ' << key.first << '.' << key.second << "=(" << metric.count << ',' << milliseconds(metric.total) << ',' << milliseconds(metric.maximum); + if (metric.bytes != 0) output << ',' << metric.bytes; + output << ')'; + } + output << '\n'; + }; } private: diff --git a/core/libs/prx/libSceVideoOut/include/FrameTimingLog.hpp b/core/libs/prx/libSceVideoOut/include/FrameTimingLog.hpp new file mode 100644 index 000000000..56f96a6d4 --- /dev/null +++ b/core/libs/prx/libSceVideoOut/include/FrameTimingLog.hpp @@ -0,0 +1,94 @@ +#ifndef CORE_LIBS_PRX_LIBSCEVIDEOOUT_INCLUDE_FRAMETIMINGLOG_HPP +#define CORE_LIBS_PRX_LIBSCEVIDEOOUT_INCLUDE_FRAMETIMINGLOG_HPP + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +class FrameTimingLog { +public: + using Report = std::function; + + FrameTimingLog() { + pending.reserve(maxReports); + file.rdbuf()->pubsetbuf(buffer.data(), static_cast(buffer.size())); + file.exceptions(std::ios::badbit | std::ios::failbit); + file.imbue(std::locale::classic()); + file.open("frame-timing.log", std::ios::out | std::ios::binary | std::ios::trunc); + worker = std::jthread([this](std::stop_token token) { run(token); }); + } + + ~FrameTimingLog() { + worker.request_stop(); + changed.notify_one(); + } + + void Enqueue(Report report) { + { + std::lock_guard lock(mutex); + if (failure != nullptr) std::rethrow_exception(failure); + if (worker.get_stop_token().stop_requested()) throw std::runtime_error("frame timing log is closed"); + if (pending.size() == maxReports) throw std::runtime_error("frame timing log queue is full"); + pending.push_back(std::move(report)); + } + changed.notify_one(); + } + + void Finish() { + worker.request_stop(); + changed.notify_one(); + if (worker.joinable()) worker.join(); + if (failure != nullptr) std::rethrow_exception(failure); + } + +private: + void run(std::stop_token token) { + try { + std::vector reports; + reports.reserve(maxReports); + auto flushAt = std::chrono::steady_clock::now() + std::chrono::seconds(1); + for (;;) { + bool stopping = false; + { + std::unique_lock lock(mutex); + changed.wait_until(lock, flushAt, [&] { return token.stop_requested() || !pending.empty(); }); + reports.swap(pending); + stopping = token.stop_requested(); + } + for (const auto& report : reports) report(file); + reports.clear(); + if (stopping) break; + const auto now = std::chrono::steady_clock::now(); + if (now >= flushAt) { + file.flush(); + flushAt = now + std::chrono::seconds(1); + } + } + file.close(); + } catch (...) { + std::lock_guard lock(mutex); + failure = std::current_exception(); + } + } + + static constexpr std::size_t maxReports = 256; + std::array buffer{}; + std::ofstream file; + std::mutex mutex; + std::condition_variable changed; + std::vector pending; + std::exception_ptr failure; + std::jthread worker; +}; + +#endif diff --git a/core/libs/prx/libSceVideoOut/src/VideoOutDriver.cpp b/core/libs/prx/libSceVideoOut/src/VideoOutDriver.cpp index be2a9fa12..4c490cb77 100644 --- a/core/libs/prx/libSceVideoOut/src/VideoOutDriver.cpp +++ b/core/libs/prx/libSceVideoOut/src/VideoOutDriver.cpp @@ -16,6 +16,9 @@ #include "prx/libkernel/Equeue/Equeue.hpp" #include "prx/libkernel/Time/include/Time.hpp" #include "prx/libSceVideoOut/include/VideoOutDriver.hpp" +#if APS5_ENABLE_TIMING_LOG +#include "prx/libSceVideoOut/include/FrameTimingLog.hpp" +#endif #include "prx/libSceAgcDriver/Execution/include/Driver.hpp" #include "prx/libSceAgcDriver/Execution/include/Presentation.hpp" #include "prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp" @@ -465,7 +468,13 @@ void VideoOutDriver::processFlip(FlipRequest& req) { void VideoOutDriver::presentLoop(std::stop_token token) { std::shared_ptr current; +#if APS5_ENABLE_TIMING_LOG + std::unique_ptr timingLog; +#endif try { +#if APS5_ENABLE_TIMING_LOG + timingLog = std::make_unique(); +#endif PadInput padInput; MouseInput mouseInput; KeyboardInput keyboardInput; @@ -507,7 +516,9 @@ void VideoOutDriver::presentLoop(std::stop_token token) { if (previous != AgcDriver::FrameTiming::Clock::time_point{}) interval = finished - previous; current->cfg->lastTimingFlip = finished; } - current->timing->Print(current->outputHandle, current->index, current->flipArg, finished, interval); +#if APS5_ENABLE_TIMING_LOG + timingLog->Enqueue(current->timing->Capture(current->outputHandle, current->index, current->flipArg, finished, interval)); +#endif } if (current) { current.reset(); @@ -524,6 +535,15 @@ void VideoOutDriver::presentLoop(std::stop_token token) { std::fflush(stderr); std::terminate(); } +#if APS5_ENABLE_TIMING_LOG + try { + timingLog->Finish(); + } catch (const std::exception& error) { + std::fprintf(stderr, "[videoout] frame timing log failed: %s\n", error.what()); + std::fflush(stderr); + std::terminate(); + } +#endif current.reset(); { std::list> cancelled;