perf(log): write frame timings async to a buffered file
This commit is contained in:
boykopovar
parent
2ec144d4d3
commit
2441bd265d
|
|
@ -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=$<BOOL:${APS5_ENABLE_TIMING_LOG}>)
|
||||
|
||||
set(CMAKE_CXX_STANDARD 20)
|
||||
|
|
|
|||
|
|
@ -5,17 +5,15 @@
|
|||
#include <chrono>
|
||||
#include <cstddef>
|
||||
#include <cstdint>
|
||||
#include <cstdio>
|
||||
#include <functional>
|
||||
#include <iomanip>
|
||||
#include <locale>
|
||||
#include <map>
|
||||
#include <memory>
|
||||
#include <mutex>
|
||||
#include <sstream>
|
||||
#include <ostream>
|
||||
#include <stdexcept>
|
||||
#include <string_view>
|
||||
#include <utility>
|
||||
#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<void(std::ostream&)> 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:
|
||||
|
|
|
|||
|
|
@ -0,0 +1,94 @@
|
|||
#ifndef CORE_LIBS_PRX_LIBSCEVIDEOOUT_INCLUDE_FRAMETIMINGLOG_HPP
|
||||
#define CORE_LIBS_PRX_LIBSCEVIDEOOUT_INCLUDE_FRAMETIMINGLOG_HPP
|
||||
|
||||
#include <array>
|
||||
#include <chrono>
|
||||
#include <condition_variable>
|
||||
#include <exception>
|
||||
#include <fstream>
|
||||
#include <functional>
|
||||
#include <locale>
|
||||
#include <mutex>
|
||||
#include <ostream>
|
||||
#include <stdexcept>
|
||||
#include <thread>
|
||||
#include <utility>
|
||||
#include <vector>
|
||||
|
||||
class FrameTimingLog {
|
||||
public:
|
||||
using Report = std::function<void(std::ostream&)>;
|
||||
|
||||
FrameTimingLog() {
|
||||
pending.reserve(maxReports);
|
||||
file.rdbuf()->pubsetbuf(buffer.data(), static_cast<std::streamsize>(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<Report> 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<char, 65536> buffer{};
|
||||
std::ofstream file;
|
||||
std::mutex mutex;
|
||||
std::condition_variable changed;
|
||||
std::vector<Report> pending;
|
||||
std::exception_ptr failure;
|
||||
std::jthread worker;
|
||||
};
|
||||
|
||||
#endif
|
||||
|
|
@ -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<FlipRequest> current;
|
||||
#if APS5_ENABLE_TIMING_LOG
|
||||
std::unique_ptr<FrameTimingLog> timingLog;
|
||||
#endif
|
||||
try {
|
||||
#if APS5_ENABLE_TIMING_LOG
|
||||
timingLog = std::make_unique<FrameTimingLog>();
|
||||
#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<std::shared_ptr<FlipRequest>> cancelled;
|
||||
|
|
|
|||
Loading…
Reference in New Issue