From e98d2163f459ff8bd682f3a36ff267bd76366d24 Mon Sep 17 00:00:00 2001 From: boykopovar Date: Thu, 24 Sep 2026 20:35:59 +0300 Subject: [PATCH] refactor(log): remove extra logs + refactor timing logging --- .../Shader/src/InterpolantMapping.cpp | 2 - .../prx/libSceAgc/Shader/src/PrimState.cpp | 2 - .../Execution/include/PerformanceTimer.hpp | 177 +++++++++++++++--- .../Execution/include/Presentation.hpp | 4 + .../Execution/include/VideoOutput.hpp | 4 +- .../libSceAgcDriver/Execution/src/Driver.cpp | 106 +++++++++-- .../Execution/src/GuestMemory.cpp | 7 + .../prx/libSceAgcDriver/Execution/src/Pm4.cpp | 6 - .../Execution/src/VulkanDevice.cpp | 42 +---- .../prx/libSceAgcDriver/Graphics/src/Draw.cpp | 42 ----- .../Graphics/src/GpuColorTransfer.cpp | 7 + .../libSceAgcDriver/Graphics/src/State.cpp | 22 --- core/libs/prx/libSceAgcDriver/tests/Flip.cpp | 2 +- core/libs/prx/libSceAgcDriver/tests/Pm4.cpp | 4 + .../libSceVideoOut/include/VideoOutDriver.hpp | 8 +- .../prx/libSceVideoOut/src/VideoOutDriver.cpp | 38 +++- core/libs/prx/libSceVideoOut/tests/Flip.cpp | 2 +- core/shader/recompiler/Recompiler.cpp | 14 -- 18 files changed, 313 insertions(+), 176 deletions(-) diff --git a/core/libs/prx/libSceAgc/Shader/src/InterpolantMapping.cpp b/core/libs/prx/libSceAgc/Shader/src/InterpolantMapping.cpp index 6dee8d72b..515458391 100644 --- a/core/libs/prx/libSceAgc/Shader/src/InterpolantMapping.cpp +++ b/core/libs/prx/libSceAgc/Shader/src/InterpolantMapping.cpp @@ -19,7 +19,6 @@ int APS5_VABI sceAgcCreateInterpolantMapping(ShaderRegister* regs, const Shader* if (ps == nullptr || ps->num_input_semantics == 0) { FillIdentityInterpolants(regs, 0); - APS5_LOG_CHARS_OUT("OK identity ps_inputs=0"); return 0; } @@ -52,7 +51,6 @@ int APS5_VABI sceAgcCreateInterpolantMapping(ShaderRegister* regs, const Shader* } FillIdentityInterpolants(regs, ps->num_input_semantics); - APS5_LOG_OUT("OK ps_inputs=%u gs_outputs=%u", ps->num_input_semantics, gs->num_output_semantics); return 0; } diff --git a/core/libs/prx/libSceAgc/Shader/src/PrimState.cpp b/core/libs/prx/libSceAgc/Shader/src/PrimState.cpp index ace10ea99..365a70a3d 100644 --- a/core/libs/prx/libSceAgc/Shader/src/PrimState.cpp +++ b/core/libs/prx/libSceAgc/Shader/src/PrimState.cpp @@ -60,7 +60,6 @@ int APS5_VABI sceAgcCreatePrimState(ShaderRegister* cx_regs, ShaderRegister* uc_ } } - APS5_LOG_OUT("OK prim_type=%u", prim_type); return 0; } @@ -75,7 +74,6 @@ int APS5_VABI sceAgcUpdatePrimState(ShaderRegister* cx_regs, ShaderRegister* uc_ uc_regs[2].value |= prim_type; } - APS5_LOG_OUT("OK prim_type=%u", prim_type); return 0; } diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp index 443e18e13..1f0b1a685 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp +++ b/core/libs/prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp @@ -1,52 +1,183 @@ #ifndef CORE_LIBS_PRX_LIBSCEAGCDRIVER_EXECUTION_INCLUDE_PERFORMANCETIMER_HPP #define CORE_LIBS_PRX_LIBSCEAGCDRIVER_EXECUTION_INCLUDE_PERFORMANCETIMER_HPP -#include "prx/libc/include/general/LogMacros.hpp" -#include +#include #include #include +#include #include -#include +#include +#include +#include +#include +#include +#include #include +#include +#include namespace AgcDriver { +class FrameTiming { +public: + using Clock = std::chrono::steady_clock; + + struct Metric { + Clock::duration total{}; + Clock::duration maximum{}; + std::uint64_t count = 0; + std::uint64_t bytes = 0; + }; + + explicit FrameTiming(std::uint64_t id) : id(id) {} + + Metric* Get(const char* scope, const char* stage) { + std::lock_guard lock(mutex); + return &metrics[{scope, stage}]; + } + + void Add(Metric* metric, Clock::duration elapsed, std::uint64_t bytes = 0) { + std::lock_guard lock(mutex); + metric->total += elapsed; + metric->maximum = std::max(metric->maximum, elapsed); + ++metric->count; + metric->bytes += bytes; + } + + void IncludeSubmission(std::uint64_t serial, Clock::time_point received, Clock::time_point enqueued, Clock::time_point dequeued, bool firstSegment) { + if (serial == 0 || received > enqueued || enqueued > dequeued) throw std::runtime_error("Frame timing: invalid submission timestamps"); + if (firstSerial == 0) { + firstSerial = serial; + start = received; + executionStart = dequeued; + } + start = std::min(start, received); + lastSerial = serial; + if (firstSegment) { + Add(Get("Submission", "accept"), enqueued - received); + Add(Get("Submission", "queue"), dequeued - enqueued); + } + } + + void SetFlip(std::uint64_t serial, std::size_t offset, Clock::time_point received, Clock::time_point reached) { + if (serial != lastSerial || received > reached || executionStart > reached) throw std::runtime_error("Frame timing: invalid flip lineage"); + flipSerial = serial; + flipOffset = offset; + flipReceived = received; + flipReached = reached; + } + + void Print(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 << " 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'; + const auto text = output.str(); + if (std::fwrite(text.data(), 1, text.size(), stdout) != text.size() || std::fflush(stdout) != 0) throw std::runtime_error("Frame timing: report write failed"); + } + +private: + static double milliseconds(Clock::duration elapsed) { + return std::chrono::duration(elapsed).count(); + } + + std::mutex mutex; + std::map, Metric> metrics; + std::uint64_t id; + std::uint64_t firstSerial = 0; + std::uint64_t lastSerial = 0; + std::uint64_t flipSerial = 0; + std::size_t flipOffset = 0; + Clock::time_point start{}; + Clock::time_point executionStart{}; + Clock::time_point flipReceived{}; + Clock::time_point flipReached{}; +}; + +class PerformanceContext { +public: + explicit PerformanceContext(FrameTiming* frame) : previous(current) { + current = frame; + } + + PerformanceContext(const PerformanceContext&) = delete; + PerformanceContext& operator=(const PerformanceContext&) = delete; + + ~PerformanceContext() { + current = previous; + } + + static FrameTiming* Current() { + return current; + } + +private: + inline static thread_local FrameTiming* current = nullptr; + FrameTiming* previous; +}; + class PerformanceTimer { public: - explicit PerformanceTimer(const char* scope) : scope(scope) {} + explicit PerformanceTimer(const char* scope) : frame(PerformanceContext::Current()), scope(scope) { + if (frame != nullptr) { + total = frame->Get(scope, "total"); + } + start = Clock::now(); + previous = start; + } + PerformanceTimer(const PerformanceTimer&) = delete; PerformanceTimer& operator=(const PerformanceTimer&) = delete; ~PerformanceTimer() { + if (frame == nullptr) return; const auto end = Clock::now(); - APS5_LOG_OUT("[Timing] id=%llu scope=%s total_ms=%.3f tail_ms=%.3f unwinding=%u%s", id, scope, milliseconds(end - start), milliseconds(end - previous), std::uncaught_exceptions() > exceptions ? 1u : 0u, stages); + if (tail != nullptr) frame->Add(tail, end - previous); + frame->Add(total, end - start); } - void Mark(const char* stage) { + void Mark(const char* stage, std::uint64_t bytes = 0) { + if (frame == nullptr) return; const auto now = Clock::now(); - const auto count = std::snprintf(stages + used, sizeof(stages) - used, " %s_ms=%.3f", stage, milliseconds(now - previous)); - if (count < 0 || static_cast(count) >= sizeof(stages) - used) { - throw std::runtime_error("PerformanceTimer: timing log capacity exceeded"); - } - used += static_cast(count); + if (tail == nullptr) tail = frame->Get(scope, "tail"); + frame->Add(frame->Get(scope, stage), now - previous, bytes); previous = now; } private: - using Clock = std::chrono::steady_clock; + using Clock = FrameTiming::Clock; - static double milliseconds(Clock::duration duration) { - return std::chrono::duration(duration).count(); - } - - inline static std::atomic nextId{0}; + FrameTiming* frame; const char* scope; - unsigned long long id = nextId.fetch_add(1, std::memory_order_relaxed); - Clock::time_point start = Clock::now(); - Clock::time_point previous = start; - int exceptions = std::uncaught_exceptions(); - char stages[2048]{}; - std::size_t used = 0; + FrameTiming::Metric* total = nullptr; + FrameTiming::Metric* tail = nullptr; + Clock::time_point start; + Clock::time_point previous; }; } diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/Presentation.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/Presentation.hpp index c51d31eab..88dd83ead 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/include/Presentation.hpp +++ b/core/libs/prx/libSceAgcDriver/Execution/include/Presentation.hpp @@ -6,10 +6,13 @@ #include #include #include +#include #include "prx/libSceAgcDriver/Execution/include/DisplayBuffer.hpp" namespace AgcDriver { +class FrameTiming; + struct PresentationWindow { void* context; std::span extensions; @@ -17,6 +20,7 @@ struct PresentationWindow { void (*getDrawableSize)(void* context, std::uint32_t* width, std::uint32_t* height); std::uint32_t width; std::uint32_t height; + std::shared_ptr timing; }; } diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/VideoOutput.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/VideoOutput.hpp index dfa9796d8..f5b6ab74a 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/include/VideoOutput.hpp +++ b/core/libs/prx/libSceAgcDriver/Execution/include/VideoOutput.hpp @@ -7,6 +7,8 @@ namespace AgcDriver { +class FrameTiming; + inline constexpr std::uint32_t FlipPacketHeader = 0xc004105cu; inline constexpr std::uint32_t FlipPacketWords = 6; @@ -20,7 +22,7 @@ struct FlipInfo { class IFlipRequest { public: virtual ~IFlipRequest() = default; - virtual void GpuReady() = 0; + virtual void GpuReady(const std::shared_ptr& timing) = 0; virtual void Fail(std::exception_ptr error) noexcept = 0; }; diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/Driver.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/Driver.cpp index 9664d0cd5..28af0a23e 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/Driver.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/Driver.cpp @@ -49,6 +49,11 @@ struct Submission { std::map> shaders; std::map> flips; bool suspend = false; + FrameTiming::Clock::time_point received; + FrameTiming::Clock::time_point copied; + FrameTiming::Clock::time_point validated; + FrameTiming::Clock::time_point enqueued; + FrameTiming::Clock::time_point dequeued; }; std::uint32_t readRegister(const Registers& registers, std::uint32_t offset) { @@ -88,6 +93,7 @@ private: public: void Submit(const Packet* packet, std::uint32_t queue) { + const auto received = FrameTiming::Clock::now(); CheckFailure(); require(queue == 0 || (queue >= 0x20 && queue < 0x58), "unsupported compute queue"); GuestMemory::CheckRange(packet, sizeof(Packet), alignof(Packet)); @@ -95,12 +101,15 @@ public: require(descriptor.flags == 0, "nonzero submission flags are not implemented"); Submission submission{}; submission.queue = queue; + submission.received = received; if (descriptor.dw_num != 0) { require(descriptor.dw_num <= std::numeric_limits::max() / sizeof(std::uint32_t), "command size overflow"); GuestMemory::CheckRange(descriptor.addr, static_cast(descriptor.dw_num) * sizeof(std::uint32_t), alignof(std::uint32_t)); submission.commands.assign(descriptor.addr, descriptor.addr + descriptor.dw_num); } + submission.copied = FrameTiming::Clock::now(); validate(submission.commands, queue); + submission.validated = FrameTiming::Clock::now(); { std::lock_guard lock(mutex); rethrowFailure(); @@ -120,6 +129,7 @@ public: } submission.shaders = shaders; submission.serial = accepted + 1; + submission.enqueued = FrameTiming::Clock::now(); pending.push_back(std::move(submission)); ++accepted; } @@ -135,6 +145,7 @@ public: } void SuspendPoint() { + const auto received = FrameTiming::Clock::now(); require(std::this_thread::get_id() != worker.get_id(), "worker cannot suspend itself"); std::unique_lock lock(mutex); rethrowFailure(); @@ -143,6 +154,10 @@ public: Submission boundary{}; boundary.serial = accepted + 1; boundary.suspend = true; + boundary.received = received; + boundary.copied = received; + boundary.validated = received; + boundary.enqueued = FrameTiming::Clock::now(); pending.push_back(std::move(boundary)); const auto target = ++accepted; changed.notify_all(); @@ -185,6 +200,7 @@ public: } void Present(const PresentationWindow& window, const DisplayBuffer* buffer, bool opaque, void (*gpuReady)(void*), void* context) { + PerformanceContext timingContext(window.timing.get()); PerformanceTimer timing("Driver.Present"); CheckFailure(); require(gpuReady != nullptr && context != nullptr, "missing GPU completion callback"); @@ -269,6 +285,8 @@ private: std::exception_ptr failure; bool stopping = false; bool resetGraphics = false; + std::shared_ptr frameTiming; + std::uint64_t frameSerial = 0; std::thread worker; Driver() : worker([this] { run(); }) { @@ -302,7 +320,9 @@ private: } void dispatch(QueueState& queue, std::span packet, const Submission& submission) { + PerformanceTimer timing("Driver.Dispatch"); std::lock_guard gpuLock(gpuMutex); + timing.Mark("gpu_mutex_wait"); const auto address = (static_cast(readRegister(queue.shader, 0x20c)) << 8u) | (static_cast(readRegister(queue.shader, 0x20d) & 0xffu) << 40u); auto it = submission.shaders.upper_bound(address); require(it != submission.shaders.begin(), "compute program does not belong to a registered shader"); @@ -328,13 +348,19 @@ private: {0, 0, 0, 128} }; ShaderMemory shaderMemory(memory); + timing.Mark("prepare"); shaderMemory.Capture(request); + timing.Mark("shader_memory_capture"); const auto captured = shaderMemory.Regions(); request.context.memory = captured; + timing.Mark("request_memory"); const auto compiled = ShaderRecompiler::Recompile(request); + timing.Mark("shader_compile"); std::vector snapshots; for (const auto& region : captured) snapshots.push_back({region.guestAddress, region.bytes}); + timing.Mark("snapshots"); device->Dispatch(compiled, packet[1], packet[2], packet[3], snapshots); + timing.Mark("dispatch_and_resource_release"); } void draw(QueueState& queue, std::span packet, const Submission& submission) { @@ -448,10 +474,14 @@ private: {0, 0, pushCursorBytes, Graphics::PipelinePushConstantBytes - pushCursorBytes}, ShaderRecompiler::GraphicsCompileContext{program.firstUserSgpr, linked, graphics.stages.mesh, graphics.stages.tessellation, {drawParameters.indexAddress, drawParameters.indexCount, drawParameters.indexSize, drawParameters.instanceCount}} }; + PerformanceTimer shaderTiming("Driver.GraphicsShader"); shaderMemory.Capture(request); + shaderTiming.Mark("memory_capture"); memory = shaderMemory.Regions(); request.context.memory = memory; + shaderTiming.Mark("request_memory"); results.push_back(ShaderRecompiler::Recompile(request)); + shaderTiming.Mark("compile"); const auto& result = results.back(); if (!drawParameters.indexed && i == 0) { const auto offsetValue = [&](std::int32_t sgpr) { @@ -467,7 +497,7 @@ private: stages.push_back({program.binary.stage, &result, result.pushConstants.empty() ? 0u : pushCursorBytes}); pushCursorBytes += static_cast(result.pushConstants.size()); } - timing.Mark("shader_compile_and_link"); + timing.Mark("shaders"); if (graphics.rectList) { require(stages.size() == 2, "rect-list requires vertex and fragment programs"); auto rectangle = ShaderRecompiler::BuildRectListShaders(results[0], results[1], device->Target()); @@ -482,10 +512,29 @@ private: timing.Mark("draw_and_resource_release"); } + void includeSubmission(const Submission& submission, bool firstSegment) { + if (frameTiming == nullptr) { + require(frameSerial != std::numeric_limits::max(), "frame serial overflow"); + frameTiming = std::make_shared(++frameSerial); + } + const auto dequeued = firstSegment ? submission.dequeued : FrameTiming::Clock::now(); + frameTiming->IncludeSubmission(submission.serial, submission.received, submission.enqueued, dequeued, firstSegment); + if (firstSegment) { + frameTiming->Add(frameTiming->Get("Submission", "copy"), submission.copied - submission.received, submission.commands.size() * sizeof(std::uint32_t)); + frameTiming->Add(frameTiming->Get("Submission", "validate"), submission.validated - submission.copied); + frameTiming->Add(frameTiming->Get("Submission", "reserve_enqueue"), submission.enqueued - submission.validated); + } + } + void execute(const Submission& submission) { + includeSubmission(submission, true); if (submission.suspend) { + PerformanceContext timingContext(frameTiming.get()); + PerformanceTimer timing("Driver.Suspend"); std::lock_guard gpuLock(gpuMutex); + timing.Mark("gpu_mutex_wait"); if (device != nullptr) device->WaitIdle(); + timing.Mark("device_idle_wait"); resetGraphics = true; return; } @@ -495,27 +544,41 @@ private: } auto& queue = queues[submission.queue]; for (std::size_t cursor = 0; cursor < submission.commands.size();) { - CheckFailure(); + if (frameTiming == nullptr) includeSubmission(submission, false); const auto header = submission.commands[cursor]; const auto count = static_cast((header >> 16u) & 0x3fffu) + 2; const auto packet = std::span(submission.commands).subspan(cursor, count); const auto opcode = (header >> 8u) & 0xffu; - if (Pm4::AccessesMemory(header) || opcode == 0x42 || opcode == 0x46 || opcode == 0x58 || header == FlipPacketHeader) { - std::lock_guard gpuLock(gpuMutex); - if (device != nullptr) device->WaitIdle(); + { + PerformanceContext timingContext(frameTiming.get()); + PerformanceTimer timing("Driver.Packet"); + CheckFailure(); + timing.Mark("failure_check"); + if (Pm4::AccessesMemory(header) || opcode == 0x42 || opcode == 0x46 || opcode == 0x58 || header == FlipPacketHeader) { + std::lock_guard gpuLock(gpuMutex); + timing.Mark("gpu_mutex_wait"); + if (device != nullptr) device->WaitIdle(); + timing.Mark("device_idle_wait"); + } + if (header == FlipPacketHeader) { + CheckFailure(); + timing.Mark("flip_prepare"); + } else if (opcode == 0x15) { + dispatch(queue, packet, submission); + } else if (opcode == 0x16) { + const auto direct = Pm4::ResolveDispatch(packet, queue); + dispatch(queue, direct, submission); + } else if (opcode == 0x35 || opcode == 0x2d) { + draw(queue, packet, submission); + } else if (opcode != 0x42 && opcode != 0x46 && opcode != 0x58) { + Pm4::Execute(packet, queue); + timing.Mark("pm4_execute"); + } } if (header == FlipPacketHeader) { - CheckFailure(); - submission.flips.at(cursor)->GpuReady(); - } else if (opcode == 0x15) { - dispatch(queue, packet, submission); - } else if (opcode == 0x16) { - const auto direct = Pm4::ResolveDispatch(packet, queue); - dispatch(queue, direct, submission); - } else if (opcode == 0x35 || opcode == 0x2d) { - draw(queue, packet, submission); - } else if (opcode != 0x42 && opcode != 0x46 && opcode != 0x58) { - Pm4::Execute(packet, queue); + frameTiming->SetFlip(submission.serial, cursor, submission.received, FrameTiming::Clock::now()); + const auto completedFrame = std::exchange(frameTiming, nullptr); + submission.flips.at(cursor)->GpuReady(completedFrame); } cursor += count; } @@ -525,20 +588,29 @@ private: Submission submission; try { for (;;) { - submission = Submission{}; { + PerformanceContext timingContext(frameTiming.get()); + PerformanceTimer timing("Driver.Worker"); + submission = Submission{}; + timing.Mark("submission_release"); std::unique_lock lock(mutex); + timing.Mark("queue_mutex_wait"); changed.wait(lock, [&] { return failure || stopping || !pending.empty(); }); + timing.Mark("wait_for_submission"); rethrowFailure(); if (pending.empty()) { break; } submission = std::move(pending.front()); pending.pop_front(); + submission.dequeued = FrameTiming::Clock::now(); } execute(submission); { + PerformanceContext timingContext(frameTiming.get()); + PerformanceTimer timing("Driver.Completion"); std::lock_guard lock(mutex); + timing.Mark("mutex_wait"); rethrowFailure(); completed = submission.serial; } diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/GuestMemory.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/GuestMemory.cpp index e2b83b033..8965d2de1 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/GuestMemory.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/GuestMemory.cpp @@ -1,4 +1,5 @@ #include "prx/libSceAgcDriver/Execution/include/GuestMemory.hpp" +#include "prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp" #include #include #include @@ -61,17 +62,23 @@ void CheckRange(const void* pointer, std::size_t bytes, std::size_t alignment, b } void Read(std::uint64_t address, std::span destination, std::size_t alignment) { + PerformanceTimer timing("GuestMemory.Read"); if (destination.empty()) return; const auto* source = reinterpret_cast(address); CheckRange(source, destination.size(), alignment); + timing.Mark("range_check"); std::memcpy(destination.data(), source, destination.size()); + timing.Mark("copy", destination.size()); } void Write(std::uint64_t address, std::span source, std::size_t alignment) { + PerformanceTimer timing("GuestMemory.Write"); if (source.empty()) return; auto* destination = reinterpret_cast(address); CheckRange(destination, source.size(), alignment, true); + timing.Mark("range_check"); std::memcpy(destination, source.data(), source.size()); + timing.Mark("copy", source.size()); } } diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/Pm4.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/Pm4.cpp index 4bc554be0..c22d4a440 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/Pm4.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/Pm4.cpp @@ -32,8 +32,6 @@ Registers& registersFor(QueueState& queue, std::uint32_t opcode) { } void writeRegister(QueueState& queue, std::uint32_t opcode, std::uint32_t offset, std::uint32_t value) { - if ((opcode == 0x69 || opcode == 0x9f) && (offset == 0x8e || offset == 0x8f || offset == 0x318 || offset == 0x31b || offset == 0x31c || offset == 0x31d || offset == 0x390 || offset == 0x3b0 || offset == 0x3b8)) - APS5_LOG_OUT_DEBUG("CONTEXT WRITE opcode=0x%x offset=0x%x value=0x%x", opcode, offset, value); registersFor(queue, opcode).insert_or_assign(offset, value); if ((opcode == 0x64 || opcode == 0x79 || opcode == 0x7a) && offset == 0x243) queue.indexType = value & 3u; } @@ -307,7 +305,6 @@ DrawParameters ResolveDraw(std::span packet, const QueueSta const auto bytes = static_cast(packet[3]) * indexSize; require(bytes <= std::numeric_limits::max(), "index range size overflow"); GuestMemory::CheckRange(reinterpret_cast(address), static_cast(bytes), indexSize); - APS5_LOG_OUT_DEBUG("ResolveDraw context targetMask=0x%x shaderMask=0x%x indexCount=%u indexType=%u instances=%u", queue.context.contains(0x8e) ? queue.context.at(0x8e) : 0u, queue.context.contains(0x8f) ? queue.context.at(0x8f) : 0u, packet[3], queue.indexType, queue.instanceCount); return {address, packet[3], indexSize, queue.instanceCount, packet[4]}; } @@ -324,7 +321,6 @@ void Execute(std::span packet, QueueState& queue) { queue.markers.pop_back(); return; case 0x1a: - APS5_LOG_OUT_DEBUG("CONTEXT_STATE operation=%u targetMaskBefore=0x%x shaderMaskBefore=0x%x", packet[1], queue.context.contains(0x8e) ? queue.context.at(0x8e) : 0u, queue.context.contains(0x8f) ? queue.context.at(0x8f) : 0u); switch (packet[1]) { case 0: queue.ClearContext(); break; case 1: case 3: @@ -338,7 +334,6 @@ void Execute(std::span packet, QueueState& queue) { queue.savedContext.reset(); break; } - APS5_LOG_OUT_DEBUG("CONTEXT_STATE done operation=%u targetMaskAfter=0x%x shaderMaskAfter=0x%x", packet[1], queue.context.contains(0x8e) ? queue.context.at(0x8e) : 0u, queue.context.contains(0x8f) ? queue.context.at(0x8f) : 0u); return; default: throw std::runtime_error("custom packet requires driver execution"); } @@ -346,7 +341,6 @@ void Execute(std::span packet, QueueState& queue) { ((packet[0] & 2u) == 0 ? queue.drawIndirectBase : queue.dispatchIndirectBase) = address(packet[2], packet[3]); return; case 0x12: - APS5_LOG_OUT_DEBUG("CLEAR_STATE targetMaskBefore=0x%x shaderMaskBefore=0x%x", queue.context.contains(0x8e) ? queue.context.at(0x8e) : 0u, queue.context.contains(0x8f) ? queue.context.at(0x8f) : 0u); queue.ClearContext(); return; case 0x13: queue.indexBufferSize = packet[1]; return; case 0x26: queue.indexBase = address(packet[1], packet[2]); return; diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp index c3581b8a2..be8cffde0 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp @@ -102,9 +102,7 @@ struct VulkanDevice::State { } void Upload(std::span pixels) { - APS5_LOG_OUT("Upload pixels=%zu uploadSize=%llu buffer=%p memory=%p mapping=%p", pixels.size(), static_cast(uploadSize), reinterpret_cast(uploadBuffer), reinterpret_cast(uploadMemory), uploadMapping); if (uploadSize < pixels.size()) { - APS5_LOG_OUT("Upload reallocating oldSize=%llu newSize=%zu", static_cast(uploadSize), pixels.size()); if (uploadMapping) DeviceFunction("vkUnmapMemory")(device, uploadMemory); uploadMapping = nullptr; if (uploadBuffer) DeviceFunction("vkDestroyBuffer")(device, uploadBuffer, nullptr); @@ -128,7 +126,6 @@ struct VulkanDevice::State { } } require(memoryType < memoryProperties.memoryTypeCount, "coherent host upload memory is unavailable"); - APS5_LOG_OUT("Upload requirements size=%llu alignment=%llu typeBits=0x%x memoryType=%u", static_cast(requirements.size), static_cast(requirements.alignment), requirements.memoryTypeBits, memoryType); VkMemoryAllocateInfo allocation{VK_STRUCTURE_TYPE_MEMORY_ALLOCATE_INFO}; allocation.allocationSize = requirements.size; allocation.memoryTypeIndex = memoryType; @@ -136,10 +133,8 @@ struct VulkanDevice::State { check(DeviceFunction("vkBindBufferMemory")(device, uploadBuffer, uploadMemory, 0), "vkBindBufferMemory display upload"); check(DeviceFunction("vkMapMemory")(device, uploadMemory, 0, pixels.size(), 0, &uploadMapping), "vkMapMemory display upload"); uploadSize = pixels.size(); - APS5_LOG_OUT("Upload allocation complete buffer=%p memory=%p mapping=%p size=%llu", reinterpret_cast(uploadBuffer), reinterpret_cast(uploadMemory), uploadMapping, static_cast(uploadSize)); } std::memcpy(uploadMapping, pixels.data(), pixels.size()); - APS5_LOG_OUT("Upload memcpy complete bytes=%zu", pixels.size()); } void DestroyRetiredSwapchains() { @@ -195,7 +190,6 @@ struct VulkanDevice::State { }; VulkanDevice::VulkanDevice(const PresentationWindow* window) : state(std::make_unique()) { - APS5_LOG_OUT("VulkanDevice constructor window=%p", static_cast(window)); #ifdef _WIN32 state->library = SDL_LoadObject("vulkan-1.dll"); #else @@ -204,7 +198,6 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window) : state(std::make_u if (state->library == nullptr) { throw std::runtime_error(std::string("Vulkan loader: ") + SDL_GetError()); } - APS5_LOG_OUT("Vulkan loader loaded library=%p", state->library); state->instanceProc = reinterpret_cast(SDL_LoadFunction(state->library, "vkGetInstanceProcAddr")); if (state->instanceProc == nullptr) { throw std::runtime_error("Vulkan loader: vkGetInstanceProcAddr missing"); @@ -216,7 +209,6 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window) : state(std::make_u create.pApplicationInfo = &application; std::vector instanceExtensions; if (window != nullptr) { - APS5_LOG_OUT("Presentation window context=%p extent=%ux%u extensions=%zu", window->context, window->width, window->height, window->extensions.size()); require(window->context && window->createSurface && window->getDrawableSize && window->width && window->height, "invalid window descriptor"); instanceExtensions.assign(window->extensions.begin(), window->extensions.end()); std::uint32_t availableCount = 0; @@ -234,18 +226,15 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window) : state(std::make_u create.ppEnabledExtensionNames = instanceExtensions.data(); } check(state->InstanceFunction("vkCreateInstance")(&create, nullptr, &state->instance), "vkCreateInstance"); - APS5_LOG_OUT("Vulkan instance created instance=%p", reinterpret_cast(state->instance)); if (window != nullptr) { state->surface = window->createSurface(window->context, state->instance); require(state->surface != VK_NULL_HANDLE, "window returned a null surface"); state->window = window->context; - APS5_LOG_OUT("Vulkan surface created surface=%p window=%p", reinterpret_cast(state->surface), state->window); } state->deviceProc = state->InstanceFunction("vkGetDeviceProcAddr"); const auto enumerate = state->InstanceFunction("vkEnumeratePhysicalDevices"); std::uint32_t count = 0; check(enumerate(state->instance, &count, nullptr), "vkEnumeratePhysicalDevices"); - APS5_LOG_OUT("Physical device count=%u", count); std::vector devices(count); check(enumerate(state->instance, &count, devices.data()), "vkEnumeratePhysicalDevices"); devices.resize(count); @@ -255,7 +244,6 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window) : state(std::make_u for (auto physical : devices) { VkPhysicalDeviceProperties properties{}; state->InstanceFunction("vkGetPhysicalDeviceProperties")(physical, &properties); - APS5_LOG_OUT("Physical device candidate=%p name=%s api=0x%x", reinterpret_cast(physical), properties.deviceName, properties.apiVersion); if (properties.apiVersion < VK_API_VERSION_1_1) { continue; } @@ -294,7 +282,6 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window) : state(std::make_u if (selected == VK_NULL_HANDLE) { throw std::runtime_error(window ? "Vulkan: no Vulkan 1.1 device with graphics, compute and swapchain presentation" : "Vulkan: no Vulkan 1.1 graphics and compute queue"); } - APS5_LOG_OUT("Physical device selected physical=%p queueFamily=%u", reinterpret_cast(selected), family); VkPhysicalDeviceProperties2 properties{VK_STRUCTURE_TYPE_PHYSICAL_DEVICE_PROPERTIES_2}; properties.pNext = &state->subgroup; state->InstanceFunction("vkGetPhysicalDeviceProperties2")(selected, &properties); @@ -305,7 +292,6 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window) : state(std::make_u if ((state->subgroup.supportedOperations & VK_SUBGROUP_FEATURE_BALLOT_BIT) != 0) state->capabilities.push_back(spv::CapabilityGroupNonUniformBallot); if ((state->subgroup.supportedOperations & VK_SUBGROUP_FEATURE_SHUFFLE_BIT) != 0) state->capabilities.push_back(spv::CapabilityGroupNonUniformShuffle); } - APS5_LOG_OUT("Selected GPU name=%s vendor=0x%x device=0x%x subgroup=%u", state->properties.deviceName, state->properties.vendorID, state->properties.deviceID, state->subgroup.subgroupSize); state->InstanceFunction("vkGetPhysicalDeviceMemoryProperties")(selected, &state->memoryProperties); std::uint32_t extensionCount = 0; const auto enumerateDeviceExtensions = state->InstanceFunction("vkEnumerateDeviceExtensionProperties"); @@ -369,7 +355,6 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window) : state(std::make_u state->capabilities.push_back(5283); state->spirvExtensions.push_back("SPV_EXT_mesh_shader"); } - APS5_LOG_OUT("Vulkan features tessellationAvailable=%u mesh=%u depthClip=%u depthRangeUnrestricted=%u", static_cast(state->tessellationShader), static_cast(state->meshShader), static_cast(state->depthClipControl), static_cast(state->depthRangeUnrestricted)); const float priority = 1.0f; VkDeviceQueueCreateInfo queueInfo{VK_STRUCTURE_TYPE_DEVICE_QUEUE_CREATE_INFO}; queueInfo.queueFamilyIndex = family; @@ -413,7 +398,6 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window) : state(std::make_u deviceInfo.pNext = &bdaFeatures; check(state->InstanceFunction("vkCreateDevice")(selected, &deviceInfo, nullptr, &state->device), "vkCreateDevice"); state->DeviceFunction("vkGetDeviceQueue")(state->device, family, 0, &state->queue); - APS5_LOG_OUT("Vulkan device ready device=%p queue=%p family=%u", reinterpret_cast(state->device), reinterpret_cast(state->queue), family); VkCommandPoolCreateInfo poolInfo{VK_STRUCTURE_TYPE_COMMAND_POOL_CREATE_INFO}; poolInfo.flags = VK_COMMAND_POOL_CREATE_RESET_COMMAND_BUFFER_BIT; poolInfo.queueFamilyIndex = family; @@ -432,7 +416,6 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window) : state(std::make_u VkSurfaceCapabilitiesKHR surface{}; check(state->InstanceFunction("vkGetPhysicalDeviceSurfaceCapabilitiesKHR")(selected, state->surface, &surface), "vkGetPhysicalDeviceSurfaceCapabilitiesKHR"); state->extent = {drawableWidth, drawableHeight}; - APS5_LOG_OUT("Surface capabilities drawable=%ux%u min=%ux%u max=%ux%u minImages=%u maxImages=%u usage=0x%x", drawableWidth, drawableHeight, surface.minImageExtent.width, surface.minImageExtent.height, surface.maxImageExtent.width, surface.maxImageExtent.height, surface.minImageCount, surface.maxImageCount, surface.supportedUsageFlags); require(surface.currentExtent.width == std::numeric_limits::max() || (surface.currentExtent.width == drawableWidth && surface.currentExtent.height == drawableHeight), "window extent differs from the real drawable size"); require(drawableWidth >= surface.minImageExtent.width && drawableWidth <= surface.maxImageExtent.width && drawableHeight >= surface.minImageExtent.height && drawableHeight <= surface.maxImageExtent.height, "unsupported output extent"); require((surface.supportedUsageFlags & VK_IMAGE_USAGE_TRANSFER_DST_BIT) != 0, "surface does not support transfer destination images"); @@ -463,7 +446,6 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window) : state(std::make_u check(getImages(state->device, state->swapchain, &imageCount, nullptr), "vkGetSwapchainImagesKHR"); state->images.resize(imageCount); check(getImages(state->device, state->swapchain, &imageCount, state->images.data()), "vkGetSwapchainImagesKHR"); - APS5_LOG_OUT("Swapchain created swapchain=%p extent=%ux%u images=%u", reinterpret_cast(state->swapchain), state->extent.width, state->extent.height, imageCount); VkFenceCreateInfo fence{VK_STRUCTURE_TYPE_FENCE_CREATE_INFO}; for (auto* destination : {&state->acquireFence, &state->renderFence}) { check(state->DeviceFunction("vkCreateFence")(state->device, &fence, nullptr, destination), "vkCreateFence"); @@ -482,9 +464,8 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window) : state(std::make_u VulkanDevice::~VulkanDevice() = default; void VulkanDevice::WaitIdle() { - APS5_LOG_CHARS_OUT_DEBUG("VulkanDevice::WaitIdle begin"); + PerformanceTimer timing("Vulkan.WaitIdle"); check(state->DeviceFunction("vkDeviceWaitIdle")(state->device), "vkDeviceWaitIdle"); - APS5_LOG_CHARS_OUT_DEBUG("VulkanDevice::WaitIdle complete"); } void* VulkanDevice::Window() const { @@ -492,7 +473,6 @@ void* VulkanDevice::Window() const { } void VulkanDevice::Resize(std::uint32_t width, std::uint32_t height) { - APS5_LOG_OUT_DEBUG("Resize requested=%ux%u current=%ux%u", width, height, state->extent.width, state->extent.height); require(state->swapchain != VK_NULL_HANDLE, "cannot resize an unavailable swapchain"); if (width == 0 || height == 0) { state->extent = {0, 0}; @@ -531,7 +511,6 @@ void VulkanDevice::Resize(std::uint32_t width, std::uint32_t height) { check(getImages(state->device, replacement, &count, state->images.data()), "vkGetSwapchainImagesKHR resize"); state->images.resize(count); state->rendered.assign(count, VK_NULL_HANDLE); - APS5_LOG_OUT_DEBUG("Resize complete swapchain=%p extent=%ux%u images=%u", reinterpret_cast(state->swapchain), state->extent.width, state->extent.height, count); } bool VulkanDevice::Presentable() const { @@ -539,12 +518,10 @@ bool VulkanDevice::Presentable() const { } void VulkanDevice::PresentClear(std::uint32_t width, std::uint32_t height, bool opaque) { - APS5_LOG_OUT_DEBUG("PresentClear width=%u height=%u opaque=%u", width, height, static_cast(opaque)); present(width, height, opaque, {}); } void VulkanDevice::PresentPixels(std::uint32_t width, std::uint32_t height, std::span pixels) { - APS5_LOG_OUT("PresentPixels width=%u height=%u pixels=%zu expected=%llu", width, height, pixels.size(), static_cast(width) * height * 4u); require(width != 0 && height != 0 && width <= 16384 && height <= 16384, "invalid display image extent"); require(pixels.size() == static_cast(width) * height * 4, "invalid display pixel buffer size"); present(width, height, true, pixels); @@ -556,7 +533,6 @@ void VulkanDevice::PresentDisplayBuffer(const DisplayBuffer& buffer) { void VulkanDevice::present(std::uint32_t width, std::uint32_t height, bool opaque, std::span pixels, const DisplayBuffer* display) { PerformanceTimer timing("Vulkan.Present"); - APS5_LOG_OUT_DEBUG("present begin width=%u height=%u opaque=%u pixels=%zu", width, height, static_cast(opaque), pixels.size()); require(state->swapchain != VK_NULL_HANDLE, "device has no swapchain"); require(state->extent.width != 0 && state->extent.height != 0, "output window is minimized"); if (display != nullptr) { @@ -565,20 +541,16 @@ void VulkanDevice::present(std::uint32_t width, std::uint32_t height, bool opaqu } if (!pixels.empty()) state->Upload(pixels); timing.Mark("pixel_upload"); - APS5_LOG_OUT_DEBUG("present source=%s bytes=%zu", pixels.empty() ? "clear" : "pixels", pixels.size()); auto wait = state->DeviceFunction("vkWaitForFences"); auto reset = state->DeviceFunction("vkResetFences"); const std::array fences{state->acquireFence, state->renderFence}; check(reset(state->device, static_cast(fences.size()), fences.data()), "vkResetFences"); - APS5_LOG_CHARS_OUT_DEBUG("present fences reset"); std::uint32_t index = 0; timing.Mark("fence_reset"); check(state->DeviceFunction("vkAcquireNextImageKHR")(state->device, state->swapchain, 5'000'000'000ULL, VK_NULL_HANDLE, state->acquireFence, &index), "vkAcquireNextImageKHR"); timing.Mark("acquire_image"); - APS5_LOG_OUT_DEBUG("vkAcquireNextImageKHR index=%u imageCount=%zu", index, state->images.size()); check(wait(state->device, 1, &state->acquireFence, VK_TRUE, std::numeric_limits::max()), "vkWaitForFences acquire"); timing.Mark("acquire_fence_wait"); - APS5_LOG_OUT_DEBUG("Acquire fence complete index=%u", index); require(index < state->images.size() && index < state->rendered.size(), "acquired image index is out of range"); auto& rendered = state->rendered[index]; if (rendered != VK_NULL_HANDLE) { @@ -593,7 +565,6 @@ void VulkanDevice::present(std::uint32_t width, std::uint32_t height, bool opaqu VkCommandBufferBeginInfo begin{VK_STRUCTURE_TYPE_COMMAND_BUFFER_BEGIN_INFO}; begin.flags = VK_COMMAND_BUFFER_USAGE_ONE_TIME_SUBMIT_BIT; check(state->DeviceFunction("vkBeginCommandBuffer")(commands, &begin), "vkBeginCommandBuffer"); - APS5_LOG_OUT_DEBUG("Presentation command buffer begin commands=%p image=%p", reinterpret_cast(commands), reinterpret_cast(state->images[index])); VkImageMemoryBarrier barrier{VK_STRUCTURE_TYPE_IMAGE_MEMORY_BARRIER}; barrier.dstAccessMask = VK_ACCESS_TRANSFER_WRITE_BIT; barrier.oldLayout = VK_IMAGE_LAYOUT_UNDEFINED; @@ -605,12 +576,10 @@ void VulkanDevice::present(std::uint32_t width, std::uint32_t height, bool opaqu auto pipelineBarrier = state->DeviceFunction("vkCmdPipelineBarrier"); pipelineBarrier(commands, VK_PIPELINE_STAGE_TOP_OF_PIPE_BIT, VK_PIPELINE_STAGE_TRANSFER_BIT, 0, 0, nullptr, 0, nullptr, 1, &barrier); if (pixels.empty() && display == nullptr) { - APS5_LOG_OUT_DEBUG("Recording swapchain clear opaque=%u image=%p", static_cast(opaque), reinterpret_cast(barrier.image)); VkClearColorValue clear{}; clear.float32[3] = opaque ? 1.0f : 0.0f; state->DeviceFunction("vkCmdClearColorImage")(commands, barrier.image, VK_IMAGE_LAYOUT_TRANSFER_DST_OPTIMAL, &clear, 1, &barrier.subresourceRange); } else { - APS5_LOG_OUT_DEBUG("Recording swapchain scaled blit width=%u height=%u bytes=%zu buffer=%p image=%p", width, height, pixels.size(), reinterpret_cast(state->uploadBuffer), reinterpret_cast(barrier.image)); require(state->scaler != nullptr, "presentation scaler is unavailable"); state->scaler->EnsureSourceImage(width, height); if (display != nullptr) { @@ -638,7 +607,6 @@ void VulkanDevice::present(std::uint32_t width, std::uint32_t height, bool opaqu barrier.newLayout = VK_IMAGE_LAYOUT_PRESENT_SRC_KHR; pipelineBarrier(commands, VK_PIPELINE_STAGE_TRANSFER_BIT, VK_PIPELINE_STAGE_BOTTOM_OF_PIPE_BIT, 0, 0, nullptr, 0, nullptr, 1, &barrier); check(state->DeviceFunction("vkEndCommandBuffer")(commands), "vkEndCommandBuffer"); - APS5_LOG_CHARS_OUT_DEBUG("Presentation command buffer recorded"); VkSubmitInfo submit{VK_STRUCTURE_TYPE_SUBMIT_INFO}; submit.commandBufferCount = 1; submit.pCommandBuffers = &commands; @@ -647,10 +615,8 @@ void VulkanDevice::present(std::uint32_t width, std::uint32_t height, bool opaqu timing.Mark("command_record_scale"); check(state->DeviceFunction("vkQueueSubmit")(state->queue, 1, &submit, state->renderFence), "vkQueueSubmit clear"); timing.Mark("queue_submit"); - APS5_LOG_CHARS_OUT_DEBUG("Presentation vkQueueSubmit OK"); check(wait(state->device, 1, &state->renderFence, VK_TRUE, std::numeric_limits::max()), "vkWaitForFences clear"); timing.Mark("render_fence_wait"); - APS5_LOG_CHARS_OUT_DEBUG("Presentation render fence complete"); VkPresentInfoKHR present{VK_STRUCTURE_TYPE_PRESENT_INFO_KHR}; present.waitSemaphoreCount = 1; present.pWaitSemaphores = &rendered; @@ -659,7 +625,6 @@ void VulkanDevice::present(std::uint32_t width, std::uint32_t height, bool opaqu present.pImageIndices = &index; check(state->DeviceFunction("vkQueuePresentKHR")(state->queue, &present), "vkQueuePresentKHR"); timing.Mark("queue_present"); - APS5_LOG_OUT_DEBUG("vkQueuePresentKHR queued imageIndex=%u", index); } ShaderRecompiler::SpirvTarget VulkanDevice::Target() const { @@ -703,15 +668,12 @@ Graphics::Context VulkanDevice::graphicsContext() const { } void VulkanDevice::Draw(const Graphics::State& graphics, const Pm4::DrawParameters& draw, std::span shaders, std::span snapshots) { - APS5_LOG_OUT("VulkanDevice::Draw indices=%u instances=%u indexSize=%u address=0x%llx shaders=%zu colorTarget=%u", draw.indexCount, draw.instanceCount, draw.indexSize, static_cast(draw.indexAddress), shaders.size(), static_cast(graphics.hasColorTarget)); const auto context = graphicsContext(); Graphics::Draw(context, graphics, draw, shaders, snapshots); - APS5_LOG_CHARS_OUT("VulkanDevice::Draw complete"); } void VulkanDevice::Dispatch(const ShaderRecompiler::RecompileResult& shader, std::uint32_t x, std::uint32_t y, std::uint32_t z, std::span snapshots) { PerformanceTimer timing("Vulkan.Dispatch"); - APS5_LOG_OUT_DEBUG("Dispatch groups=%ux%ux%u spirvWords=%zu bindings=%zu pushConstants=%zu", x, y, z, shader.spirv.size(), shader.bindings.size(), shader.pushConstants.size()); if (shader.spirv.size() < 5 || shader.spirv[0] != 0x07230203u) { throw std::runtime_error("Vulkan dispatch: invalid SPIR-V"); } @@ -800,7 +762,6 @@ void VulkanDevice::Dispatch(const ShaderRecompiler::RecompileResult& shader, std timing.Mark("command_record"); check(submit(state->queue, 1, &submission, fence), "vkQueueSubmit"); timing.Mark("queue_submit"); - APS5_LOG_OUT_DEBUG("Dispatch submitted groups=%ux%ux%u", x, y, z); const auto result = wait(state->device, 1, &fence, VK_TRUE, std::numeric_limits::max()); timing.Mark("fence_wait"); if (result != VK_SUCCESS && result != VK_ERROR_DEVICE_LOST) { @@ -810,7 +771,6 @@ void VulkanDevice::Dispatch(const ShaderRecompiler::RecompileResult& shader, std check(result, "vkWaitForFences"); resources.WriteBack(); timing.Mark("resources_writeback"); - APS5_LOG_OUT_DEBUG("Dispatch complete groups=%ux%ux%u", x, y, z); } catch (...) { cleanup(); throw; diff --git a/core/libs/prx/libSceAgcDriver/Graphics/src/Draw.cpp b/core/libs/prx/libSceAgcDriver/Graphics/src/Draw.cpp index 623426b8b..473f5bb3d 100644 --- a/core/libs/prx/libSceAgcDriver/Graphics/src/Draw.cpp +++ b/core/libs/prx/libSceAgcDriver/Graphics/src/Draw.cpp @@ -29,10 +29,6 @@ void imageBarrier(const Context& context, VkCommandBuffer commands, VkImage imag void Draw(const Context& context, const State& state, const Pm4::DrawParameters& draw, std::span shaders, std::span snapshots) { PerformanceTimer timing("Graphics.Draw"); - APS5_LOG_OUT("Draw indices=%u instances=%u indexSize=%u flags=%u indexAddress=0x%llx", draw.indexCount, draw.instanceCount, draw.indexSize, draw.flags, static_cast(draw.indexAddress)); - APS5_LOG_OUT_DEBUG("State colorTarget=%u render=%ux%u colorAddress=0x%llx colorBytes=%llu colorExtent=%ux%u", state.hasColorTarget ? 1u : 0u, state.renderExtent.width, state.renderExtent.height, static_cast(state.color.address), static_cast(state.color.bytes), state.color.extent.width, state.color.extent.height); - APS5_LOG_OUT_DEBUG("Viewport x=%f y=%f w=%f h=%f minDepth=%f maxDepth=%f", state.viewport.x, state.viewport.y, state.viewport.width, state.viewport.height, state.viewport.minDepth, state.viewport.maxDepth); - APS5_LOG_OUT_DEBUG("Scissor x=%d y=%d w=%u h=%u topology=%u cullMode=0x%x frontFace=%u", state.scissor.offset.x, state.scissor.offset.y, state.scissor.extent.width, state.scissor.extent.height, static_cast(state.topology), static_cast(state.cullMode), static_cast(state.frontFace)); Require(draw.indexed ? draw.flags == 0 : (draw.flags & ~0x20u) == 0, "draw modifiers are unsupported"); if (draw.indexed) { Require(draw.indexSize == 2 || draw.indexSize == 4, "only uint16 and uint32 index buffers are supported"); @@ -45,21 +41,15 @@ void Draw(const Context& context, const State& state, const Pm4::DrawParameters& } Require(draw.indexCount != 0 && draw.instanceCount != 0, "zero-count indexed draws are unsupported"); const auto indexBytes = static_cast(draw.indexCount) * draw.indexSize; - APS5_LOG_OUT_DEBUG("Index buffer bytes=%llu", static_cast(indexBytes)); Require(indexBytes <= std::numeric_limits::max(), "index buffer size overflow"); if (draw.indexed) GuestMemory::CheckRange(reinterpret_cast(draw.indexAddress), static_cast(indexBytes), draw.indexSize); - APS5_LOG_CHARS_OUT_DEBUG("Index buffer range OK"); Require(!draw.indexed || !state.hasColorTarget || draw.indexAddress + indexBytes <= state.color.address || state.color.address + state.color.bytes <= draw.indexAddress, "index buffer aliases the render target"); if (state.rectList) Require(draw.indexCount % 3 == 0, "incomplete rect-list primitive"); - APS5_LOG_CHARS_OUT_DEBUG("ValidateShaders"); ValidateShaders(shaders, state, context.subgroup, context.fragmentShaderBarycentric); - APS5_LOG_CHARS_OUT_DEBUG("ValidateShaders OK"); const auto shaderStages = PipelineStages(shaders); - APS5_LOG_OUT_DEBUG("PipelineStages=0x%x", static_cast(shaderStages)); std::uint32_t meshGroups = 0; if (state.stages.mesh) { Require(draw.firstVertex == 0 && draw.firstInstance == 0, "mesh draw offsets are unsupported"); - APS5_LOG_CHARS_OUT_DEBUG("Mesh path"); Require(context.meshShader, "device does not support mesh shaders"); const auto& mesh = *state.stages.mesh; const auto inputSize = mesh.inputPrimitive == 1 ? 1u : mesh.inputPrimitive == 2 ? 2u : 3u; @@ -67,7 +57,6 @@ void Draw(const Context& context, const State& state, const Pm4::DrawParameters& const auto step = mesh.inputPrimitive == 6 ? 1u : inputSize; const auto primitives = (draw.indexCount - inputSize) / step + 1u; meshGroups = (primitives - 1u) / mesh.primitivesPerGroup + 1u; - APS5_LOG_OUT_DEBUG("Mesh primitives=%u groups=%u", primitives, meshGroups); Require(meshGroups <= context.meshLimits.maxMeshWorkGroupCount[0] && draw.instanceCount <= context.meshLimits.maxMeshWorkGroupCount[1] && static_cast(meshGroups) * draw.instanceCount <= context.meshLimits.maxMeshWorkGroupTotalCount, "mesh draw exceeds workgroup count limits"); } if (state.stages.tessellation) Require(draw.indexCount % state.stages.tessellation->inputControlPoints == 0, "incomplete tessellation patch"); @@ -90,7 +79,6 @@ void Draw(const Context& context, const State& state, const Pm4::DrawParameters& maxIndex = std::max(maxIndex, index); } } - APS5_LOG_CHARS_OUT_DEBUG("Index validation OK"); timing.Mark("index_upload"); const auto& attributes = shaders.front().program->vertexAttributes; static_cast(BuildVertexInputLayout(context, attributes)); @@ -111,55 +99,37 @@ void Draw(const Context& context, const State& state, const Pm4::DrawParameters& timing.Mark("vertex_upload"); RenderTarget* target = nullptr; if (state.hasColorTarget) { - APS5_LOG_OUT_DEBUG("Creating color target address=0x%llx bytes=%llu extent=%ux%u", static_cast(state.color.address), static_cast(state.color.bytes), state.color.extent.width, state.color.extent.height); const ColorTargetLayout colorLayout(state.color.extent.width, state.color.extent.height, state.color.tileMode); Require(context.colorTransfer != nullptr, "device color transfer is unavailable"); Require(state.color.bytes == colorLayout.Bytes(), "color target transfer size mismatch"); context.colorTransfer->Upload(state.color.address, state.color.extent.width, state.color.extent.height, state.color.tileMode); timing.Mark("color_upload"); - APS5_LOG_CHARS_OUT_DEBUG("Color target read from guest memory"); target = &context.colorTransfer->Target(state.color, state.blend.blendEnable != 0); timing.Mark("render_target_create"); - APS5_LOG_CHARS_OUT_DEBUG("RenderTarget created"); } - APS5_LOG_OUT_DEBUG("Color target object=%u", target ? 1u : 0u); - APS5_LOG_CHARS_OUT_DEBUG("Creating ShaderResources"); ShaderResources resources(context, shaders, state.color, draw.indexAddress, static_cast(indexBytes), snapshots); timing.Mark("shader_resources"); - APS5_LOG_CHARS_OUT_DEBUG("ShaderResources created"); - APS5_LOG_CHARS_OUT_DEBUG("Creating Pipeline"); Pipeline pipeline(context, state, target, resources, shaders); timing.Mark("pipeline_create"); - APS5_LOG_CHARS_OUT_DEBUG("Pipeline created"); - APS5_LOG_CHARS_OUT_DEBUG("Creating CommandBatch"); CommandBatch batch(context); const auto commands = batch.Handle(); - APS5_LOG_CHARS_OUT_DEBUG("CommandBatch created"); VkMemoryBarrier upload{VK_STRUCTURE_TYPE_MEMORY_BARRIER}; upload.srcAccessMask = VK_ACCESS_HOST_WRITE_BIT; upload.dstAccessMask = VK_ACCESS_TRANSFER_READ_BIT | VK_ACCESS_INDEX_READ_BIT | VK_ACCESS_VERTEX_ATTRIBUTE_READ_BIT | VK_ACCESS_UNIFORM_READ_BIT | VK_ACCESS_SHADER_READ_BIT | VK_ACCESS_SHADER_WRITE_BIT; context.Function("vkCmdPipelineBarrier")(commands, VK_PIPELINE_STAGE_HOST_BIT, VK_PIPELINE_STAGE_TRANSFER_BIT | VK_PIPELINE_STAGE_VERTEX_INPUT_BIT | shaderStages, 0, 1, &upload, 0, nullptr, 0, nullptr); - APS5_LOG_CHARS_OUT_DEBUG("Upload barrier recorded"); VkBufferImageCopy copy{}; copy.imageSubresource = {VK_IMAGE_ASPECT_COLOR_BIT, 0, 0, 1}; copy.imageExtent = {state.color.extent.width, state.color.extent.height, 1}; if (state.hasColorTarget) { - APS5_LOG_CHARS_OUT_DEBUG("Copying guest color target to Vulkan image"); context.colorTransfer->Detile(commands); imageBarrier(context, commands, target->Image(), VK_IMAGE_LAYOUT_UNDEFINED, VK_IMAGE_LAYOUT_TRANSFER_DST_OPTIMAL, VK_PIPELINE_STAGE_TOP_OF_PIPE_BIT, VK_PIPELINE_STAGE_TRANSFER_BIT, 0, VK_ACCESS_TRANSFER_WRITE_BIT); context.Function("vkCmdCopyBufferToImage")(commands, context.colorTransfer->LinearBuffer(), target->Image(), VK_IMAGE_LAYOUT_TRANSFER_DST_OPTIMAL, 1, ©); imageBarrier(context, commands, target->Image(), VK_IMAGE_LAYOUT_TRANSFER_DST_OPTIMAL, VK_IMAGE_LAYOUT_COLOR_ATTACHMENT_OPTIMAL, VK_PIPELINE_STAGE_TRANSFER_BIT, VK_PIPELINE_STAGE_COLOR_ATTACHMENT_OUTPUT_BIT, VK_ACCESS_TRANSFER_WRITE_BIT, VK_ACCESS_COLOR_ATTACHMENT_READ_BIT | VK_ACCESS_COLOR_ATTACHMENT_WRITE_BIT); - APS5_LOG_CHARS_OUT_DEBUG("Guest color target upload recorded"); } - APS5_LOG_OUT_DEBUG("Beginning pipeline renderExtent=%ux%u", state.renderExtent.width, state.renderExtent.height); pipeline.Begin(commands, state.renderExtent); - APS5_LOG_CHARS_OUT_DEBUG("Pipeline Begin OK"); resources.Bind(commands, VK_PIPELINE_BIND_POINT_GRAPHICS, pipeline.Layout()); - APS5_LOG_CHARS_OUT_DEBUG("Resources bound"); pipeline.PushConstants(commands, shaders); - APS5_LOG_CHARS_OUT_DEBUG("Push constants recorded"); if (state.stages.mesh) { - APS5_LOG_OUT_DEBUG("vkCmdDrawMeshTasksEXT groups=%u instances=%u", meshGroups, draw.instanceCount); context.Function("vkCmdDrawMeshTasksEXT")(commands, meshGroups, draw.instanceCount, 1); } else { if (!vertexHandles.empty()) context.Function("vkCmdBindVertexBuffers")(commands, 0, static_cast(vertexHandles.size()), vertexHandles.data(), vertexOffsets.data()); @@ -170,11 +140,8 @@ void Draw(const Context& context, const State& state, const Pm4::DrawParameters& context.Function("vkCmdDraw")(commands, draw.indexCount, draw.instanceCount, draw.firstVertex, draw.firstInstance); } } - APS5_LOG_CHARS_OUT_DEBUG("Draw recorded"); context.Function("vkCmdEndRenderPass")(commands); - APS5_LOG_CHARS_OUT_DEBUG("Render pass ended"); if (state.hasColorTarget) { - APS5_LOG_CHARS_OUT_DEBUG("Copying Vulkan image back to guest color target"); imageBarrier(context, commands, target->Image(), VK_IMAGE_LAYOUT_COLOR_ATTACHMENT_OPTIMAL, VK_IMAGE_LAYOUT_TRANSFER_SRC_OPTIMAL, VK_PIPELINE_STAGE_COLOR_ATTACHMENT_OUTPUT_BIT, VK_PIPELINE_STAGE_TRANSFER_BIT, VK_ACCESS_COLOR_ATTACHMENT_WRITE_BIT, VK_ACCESS_TRANSFER_READ_BIT); VkBufferMemoryBarrier reuse{VK_STRUCTURE_TYPE_BUFFER_MEMORY_BARRIER}; reuse.srcAccessMask = VK_ACCESS_TRANSFER_READ_BIT; @@ -186,29 +153,20 @@ void Draw(const Context& context, const State& state, const Pm4::DrawParameters& context.Function("vkCmdPipelineBarrier")(commands, VK_PIPELINE_STAGE_TRANSFER_BIT, VK_PIPELINE_STAGE_TRANSFER_BIT, 0, 0, nullptr, 1, &reuse, 0, nullptr); context.Function("vkCmdCopyImageToBuffer")(commands, target->Image(), VK_IMAGE_LAYOUT_TRANSFER_SRC_OPTIMAL, context.colorTransfer->LinearBuffer(), 1, ©); context.colorTransfer->Tile(commands); - APS5_LOG_CHARS_OUT_DEBUG("Color target copy-back recorded"); } VkMemoryBarrier download{VK_STRUCTURE_TYPE_MEMORY_BARRIER}; download.srcAccessMask = VK_ACCESS_TRANSFER_WRITE_BIT | VK_ACCESS_SHADER_WRITE_BIT; download.dstAccessMask = VK_ACCESS_HOST_READ_BIT; context.Function("vkCmdPipelineBarrier")(commands, VK_PIPELINE_STAGE_TRANSFER_BIT | shaderStages, VK_PIPELINE_STAGE_HOST_BIT, 0, 1, &download, 0, nullptr, 0, nullptr); - APS5_LOG_CHARS_OUT_DEBUG("Download barrier recorded"); - APS5_LOG_CHARS_OUT_DEBUG("SubmitAndWait"); timing.Mark("command_record"); batch.SubmitAndWait(); timing.Mark("submit_wait"); - APS5_LOG_CHARS_OUT_DEBUG("SubmitAndWait OK"); if (state.hasColorTarget) GuestMemory::CheckRange(reinterpret_cast(state.color.address), state.color.bytes, 256, true); - if (state.hasColorTarget) APS5_LOG_CHARS_OUT_DEBUG("Color target guest range OK"); timing.Mark("color_range_check"); - APS5_LOG_CHARS_OUT_DEBUG("Shader resources WriteBack"); resources.WriteBack(); timing.Mark("resources_writeback"); - APS5_LOG_CHARS_OUT_DEBUG("Shader resources WriteBack OK"); if (state.hasColorTarget) context.colorTransfer->WriteBack(state.color.address); timing.Mark("color_writeback"); - if (state.hasColorTarget) APS5_LOG_OUT_DEBUG("Color target written to guest address=0x%llx bytes=%llu", static_cast(state.color.address), static_cast(state.color.bytes)); - APS5_LOG_CHARS_OUT("Draw finished"); } } diff --git a/core/libs/prx/libSceAgcDriver/Graphics/src/GpuColorTransfer.cpp b/core/libs/prx/libSceAgcDriver/Graphics/src/GpuColorTransfer.cpp index cb7404ace..00b01079a 100644 --- a/core/libs/prx/libSceAgcDriver/Graphics/src/GpuColorTransfer.cpp +++ b/core/libs/prx/libSceAgcDriver/Graphics/src/GpuColorTransfer.cpp @@ -2,6 +2,7 @@ #include "prx/libSceAgcDriver/Graphics/shaders/ColorTransfer_spv.h" #include "prx/libSceAgcDriver/Execution/include/GuestMemory.hpp" #include +#include "prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp" namespace AgcDriver::Graphics { @@ -91,9 +92,12 @@ void GpuColorTransfer::prepare(std::uint32_t newWidth, std::uint32_t newHeight, } void GpuColorTransfer::Upload(std::uint64_t address, std::uint32_t newWidth, std::uint32_t newHeight, ColorTileMode newMode) { + PerformanceTimer timing("ColorTransfer.Upload"); prepare(newWidth, newHeight, newMode); + timing.Mark("prepare"); const ColorTargetLayout layout(width, height, mode); GuestMemory::Read(address, tiled->Bytes(), layout.Alignment()); + timing.Mark("guest_read", layout.Bytes()); } void GpuColorTransfer::convert(VkCommandBuffer commands, bool toTiled, bool swapRedBlue) { @@ -123,9 +127,12 @@ void GpuColorTransfer::Tile(VkCommandBuffer commands) { } void GpuColorTransfer::WriteBack(std::uint64_t address) { + PerformanceTimer timing("ColorTransfer.WriteBack"); Require(tiled != nullptr, "color transfer is not prepared for writeback"); const ColorTargetLayout layout(width, height, mode); + timing.Mark("validate"); GuestMemory::Write(address, tiled->Bytes(), layout.Alignment()); + timing.Mark("guest_write", layout.Bytes()); } VkBuffer GpuColorTransfer::LinearBuffer() const { diff --git a/core/libs/prx/libSceAgcDriver/Graphics/src/State.cpp b/core/libs/prx/libSceAgcDriver/Graphics/src/State.cpp index 4f6a7aecc..c7b4efdde 100644 --- a/core/libs/prx/libSceAgcDriver/Graphics/src/State.cpp +++ b/core/libs/prx/libSceAgcDriver/Graphics/src/State.cpp @@ -95,7 +95,6 @@ ShaderStages DecodeShaderStages(const QueueState& queue) { validate(!tessellation || !geometry, "combined tessellation and geometry is unsupported by the reference path"); const auto path = tessellation ? ShaderPath::Tessellation : geometry ? ShaderPath::Geometry : ShaderPath::Vertex; ShaderStages result{path, value, (value & 0x00400000u) != 0 ? 32u : 64u, (read(queue.context, 0x1b6) & 0x8000u) != 0 ? 32u : 64u, {}, {}}; - APS5_LOG_OUT_DEBUG("DecodeShaderStages value=0x%x primitive=%u path=%u vertexWave=%u", value, primitive, static_cast(result.path), result.vertexWaveSize); if (path == ShaderPath::Vertex) { validate((value & 0x2000u) != 0, "legacy vertex routing without PRIMGEN_EN is unsupported"); validate((value & ~0x02402010u) == 0, "unsupported vertex routing, scheduling or wave-ID state"); @@ -133,7 +132,6 @@ State DecodeState(const QueueState& queue) { State result{}; result.stages = DecodeShaderStages(queue); const auto primitive = read(queue.userConfig, 0x242, "user-config"); - APS5_LOG_OUT_DEBUG("DecodeState primitive=%u path=%u vertexWave=%u", primitive, static_cast(result.stages.path), result.stages.vertexWaveSize); switch (primitive) { case 1: Require(result.stages.mesh.has_value(), "point-list vertex rendering requires point-size output support"); result.topology = VK_PRIMITIVE_TOPOLOGY_POINT_LIST; break; case 2: result.topology = VK_PRIMITIVE_TOPOLOGY_LINE_LIST; break; @@ -149,7 +147,6 @@ State DecodeState(const QueueState& queue) { case 6: result.topology = VK_PRIMITIVE_TOPOLOGY_TRIANGLE_STRIP; break; default: throw std::runtime_error("AGC graphics: unsupported primitive type " + std::to_string(primitive)); } - APS5_LOG_OUT_DEBUG("Topology=%u", static_cast(result.topology)); zero(queue.userConfig, 0x24b, ~0u, "primitive restart (GE_MULTI_PRIM_IB_RESET_EN)", "user-config"); zero(cx, 0x207, ~0u, "clip distances, layer, viewport or auxiliary vertex exports"); zero(cx, 0x200, ~0x007007f0u, "depth, stencil or conditional color writes"); @@ -178,30 +175,24 @@ State DecodeState(const QueueState& queue) { result.cullMode = ((raster & 1u) != 0 ? VK_CULL_MODE_FRONT_BIT : 0u) | ((raster & 2u) != 0 ? VK_CULL_MODE_BACK_BIT : 0u); if (result.rectList) result.cullMode = VK_CULL_MODE_NONE; result.frontFace = (raster & 4u) != 0 ? VK_FRONT_FACE_CLOCKWISE : VK_FRONT_FACE_COUNTER_CLOCKWISE; - APS5_LOG_OUT("Raster=0x%x cullMode=0x%x frontFace=%u negativeOneToOne=%u", raster, static_cast(result.cullMode), static_cast(result.frontFace), result.negativeOneToOne ? 1u : 0u); const auto targetMask = read(cx, 0x8e); const auto shaderMask = read(cx, 0x8f); - APS5_LOG_OUT("CB_TARGET_MASK=0x%x CB_SHADER_MASK=0x%x", targetMask, shaderMask); if ((targetMask & ~0xfu) != 0 || (shaderMask & ~0xfu) != 0) { std::ostringstream message; message << "AGC graphics: only color target zero is supported: CB_TARGET_MASK=0x" << std::hex << targetMask << ", CB_SHADER_MASK=0x" << shaderMask; throw std::runtime_error(message.str()); } result.hasColorTarget = targetMask != 0; - APS5_LOG_OUT("hasColorTarget=%u", result.hasColorTarget ? 1u : 0u); Require(!result.hasColorTarget || shaderMask == 0xfu, "partial shader color exports are unsupported"); Require(read(cx, 0x202) == 0xcc0010u, "only normal color rendering with copy ROP is supported"); zero(cx, 0x1c4, ~0u, "depth or sample-mask export"); const auto exportFormat = read(cx, 0x1c5); - APS5_LOG_OUT_DEBUG("Export format=%u", exportFormat); Require(exportFormat == 4 || exportFormat == 9, "only FP16_ABGR or 32_ABGR color export is supported"); Require(read(cx, 0x1c3) == 4, "additional position exports are unsupported"); if (result.hasColorTarget) { - APS5_LOG_CHARS_OUT_DEBUG("Decoding color target"); const auto info = read(cx, 0x31c); const auto number = (info >> 8u) & 7u; const auto swap = (info >> 11u) & 3u; - APS5_LOG_OUT("Color info=0x%x number=%u swap=%u", info, number, swap); Require(((info >> 2u) & 0x1fu) == 10 && (number == 0 || number == 6) && swap <= 1, "unsupported color format or component order"); Require((info & ~0x00029f7cu) == 0, "color compression, DCC, endian conversion, nonstandard rounding or color optimization is unsupported"); Require((info & 0x8000u) != 0, "unclamped normalized color is unsupported"); @@ -212,25 +203,18 @@ State DecodeState(const QueueState& queue) { const auto attrib3 = read(cx, 0x3b8); result.color.tileMode = DecodeColorTileMode(attrib3); result.color.extent = {((attrib2 >> 14u) & 0x3fffu) + 1u, (attrib2 & 0x3fffu) + 1u}; - APS5_LOG_OUT_DEBUG("Color extent=%ux%u attrib2=0x%x attrib3=0x%x", result.color.extent.width, result.color.extent.height, attrib2, attrib3); const ColorTargetLayout colorLayout(result.color.extent.width, result.color.extent.height, result.color.tileMode); const auto high = read(cx, 0x390); Require((high & ~0xffu) == 0, "invalid color address extension"); result.color.address = (static_cast(high) << 40u) | (static_cast(read(cx, 0x318)) << 8u); - APS5_LOG_OUT_DEBUG("Color address=0x%llx high=0x%x low=0x%x", static_cast(result.color.address), high, read(cx, 0x318)); result.color.bytes = colorLayout.Bytes(); - APS5_LOG_OUT_DEBUG("Color bytes=%llu", static_cast(result.color.bytes)); GuestMemory::CheckRange(reinterpret_cast(result.color.address), result.color.bytes, colorLayout.Alignment(), true); result.color.format = swap == 0 ? (number == 0 ? VK_FORMAT_R8G8B8A8_UNORM : VK_FORMAT_R8G8B8A8_SRGB) : (number == 0 ? VK_FORMAT_B8G8R8A8_UNORM : VK_FORMAT_B8G8R8A8_SRGB); result.color.componentMapping = 0xe4u; - APS5_LOG_OUT_DEBUG("Color VkFormat=%u", static_cast(result.color.format)); result.renderExtent = result.color.extent; - APS5_LOG_OUT_DEBUG("Render extent from color target=%ux%u", result.renderExtent.width, result.renderExtent.height); } else { const auto screenBottomRight = read(cx, 0xd); - APS5_LOG_OUT("No color target, screen BR register=0x%x", screenBottomRight); result.renderExtent = {screenBottomRight & 0xffffu, screenBottomRight >> 16u}; - APS5_LOG_OUT_DEBUG("Render extent from screen=%ux%u", result.renderExtent.width, result.renderExtent.height); Require(result.renderExtent.width != 0 && result.renderExtent.height != 0, "empty framebuffer extent for a draw without color writes"); } const auto xs = readFloat(cx, 0x10f); @@ -241,7 +225,6 @@ State DecodeState(const QueueState& queue) { const auto zo = readFloat(cx, 0x114); const auto minDepth = result.negativeOneToOne ? zo - zs : zo; const auto maxDepth = zo + zs; - APS5_LOG_OUT_DEBUG("Viewport transform scale=(%f,%f,%f) offset=(%f,%f,%f) depth=(%f,%f)", xs, ys, zs, xo, yo, zo, minDepth, maxDepth); if (!(xs > 0 && ys != 0 && std::isfinite(minDepth) && std::isfinite(maxDepth))) { std::ostringstream message; message << "AGC graphics: unsupported viewport transform: scale=(" << xs << ", " << ys << ", " << zs << "), offset=(" << xo << ", " << yo << ", " << zo << "), depth=(" << minDepth << ", " << maxDepth << "), negativeOneToOne=" << result.negativeOneToOne; @@ -249,20 +232,16 @@ State DecodeState(const QueueState& queue) { } Require(readFloat(cx, 0xb4) <= readFloat(cx, 0xb5), "inverted viewport depth clamp bounds"); result.viewport = {xo - xs, yo - ys, 2 * xs, 2 * ys, minDepth, maxDepth}; - APS5_LOG_OUT_DEBUG("Viewport x=%f y=%f w=%f h=%f minDepth=%f maxDepth=%f", result.viewport.x, result.viewport.y, result.viewport.width, result.viewport.height, result.viewport.minDepth, result.viewport.maxDepth); result.scissor = {{0, 0}, result.renderExtent}; intersect(result.scissor, cx, 0xc, true); intersect(result.scissor, cx, 0x81, false); intersect(result.scissor, cx, 0x90, false); if ((read(cx, 0x292) & 2u) != 0) intersect(result.scissor, cx, 0x94, false); - APS5_LOG_OUT_DEBUG("Scissor offset=(%d,%d) extent=%ux%u", result.scissor.offset.x, result.scissor.offset.y, result.scissor.extent.width, result.scissor.extent.height); if (result.hasColorTarget) { const auto blend = read(cx, 0x1e0); - APS5_LOG_OUT_DEBUG("Blend control=0x%x", blend); Require((blend & 0x0000e000u) == 0, "reserved blend control bits"); result.blend.colorWriteMask = targetMask; result.blend.blendEnable = (blend >> 30u) & 1u; - APS5_LOG_OUT_DEBUG("Blend enable=%u colorWriteMask=0x%x", result.blend.blendEnable ? 1u : 0u, result.blend.colorWriteMask); if (result.blend.blendEnable) { Require((read(cx, 0x31c) & 0x10000u) == 0, "blend bypass conflicts with enabled blending"); result.blend.srcColorBlendFactor = blendFactor(blend & 0x1fu); @@ -275,7 +254,6 @@ State DecodeState(const QueueState& queue) { for (std::uint32_t i = 0; i < 4; ++i) result.blendConstants[i] = readFloat(cx, 0x105 + i); } } - APS5_LOG_OUT_DEBUG("DecodeState done colorTarget=%u render=%ux%u topology=%u", result.hasColorTarget ? 1u : 0u, result.renderExtent.width, result.renderExtent.height, static_cast(result.topology)); return result; } diff --git a/core/libs/prx/libSceAgcDriver/tests/Flip.cpp b/core/libs/prx/libSceAgcDriver/tests/Flip.cpp index 01e1a4a6a..b2030621f 100644 --- a/core/libs/prx/libSceAgcDriver/tests/Flip.cpp +++ b/core/libs/prx/libSceAgcDriver/tests/Flip.cpp @@ -45,7 +45,7 @@ class Request final : public AgcDriver::IFlipRequest { public: explicit Request(std::shared_ptr value) : state(std::move(value)) { ++state->alive; } ~Request() override { --state->alive; } - void GpuReady() override { + void GpuReady(const std::shared_ptr&) override { std::unique_lock lock(state->mutex); if (state->checkSelfWait) { check(expectFailure([] { AgcDriverSuspendPoint_nid_postfix(); }).find("itself") != std::string::npos, "self suspend was not rejected"); diff --git a/core/libs/prx/libSceAgcDriver/tests/Pm4.cpp b/core/libs/prx/libSceAgcDriver/tests/Pm4.cpp index 7ab1cafef..4331fba30 100644 --- a/core/libs/prx/libSceAgcDriver/tests/Pm4.cpp +++ b/core/libs/prx/libSceAgcDriver/tests/Pm4.cpp @@ -66,6 +66,10 @@ void testCatalog() { void testRegisters() { AgcDriver::QueueState state; + execute(state, makePacket(0x79, {0x242, 4})); + check(state.userConfig.at(0x242) == 4, "primitive type register write was lost"); + execute(state, makePacket(0x79, {0x242, 6})); + check(state.userConfig.at(0x242) == 6, "primitive type register update was lost"); const std::array indirectOpcodes{0x9f, 0x63, 0x64}; for (auto opcode : indirectOpcodes) { std::array pairs{0x10, 41, 0x11, 42, 0x10, 43}; diff --git a/core/libs/prx/libSceVideoOut/include/VideoOutDriver.hpp b/core/libs/prx/libSceVideoOut/include/VideoOutDriver.hpp index 6a6a049fd..e9212806f 100644 --- a/core/libs/prx/libSceVideoOut/include/VideoOutDriver.hpp +++ b/core/libs/prx/libSceVideoOut/include/VideoOutDriver.hpp @@ -2,6 +2,7 @@ #define CORE_LIBS_PRX_LIBSCEVIDEOOUT_INCLUDE_VIDEOOUTDRIVER_HPP #include +#include #include #include #include @@ -100,6 +101,7 @@ struct VideoOutConfig { std::exception_ptr failure; int flipRate = 0; uint64_t lastFlipVblank = 0; + std::chrono::steady_clock::time_point lastTimingFlip{}; uint64_t outputMode = VIDEO_OUT_OUTPUT_MODE_DEFAULT; float gamma = 1.0f; @@ -123,6 +125,7 @@ struct FlipRequest final : AgcDriver::IFlipRequest, std::enable_shared_from_this std::shared_ptr cfg; std::shared_ptr queue; uint64_t generation = 0; + std::uint32_t outputHandle = 0; int index = 0; int flipMode = 0; int flipRate = 0; @@ -136,8 +139,11 @@ struct FlipRequest final : AgcDriver::IFlipRequest, std::enable_shared_from_this bool gpuComplete = false; bool terminal = false; + std::shared_ptr timing; + std::chrono::steady_clock::time_point queuedAt; + ~FlipRequest() override; - void GpuReady() override; + void GpuReady(const std::shared_ptr& frameTiming) override; void Fail(std::exception_ptr error) noexcept override; }; diff --git a/core/libs/prx/libSceVideoOut/src/VideoOutDriver.cpp b/core/libs/prx/libSceVideoOut/src/VideoOutDriver.cpp index a9e83cee3..3e267222a 100644 --- a/core/libs/prx/libSceVideoOut/src/VideoOutDriver.cpp +++ b/core/libs/prx/libSceVideoOut/src/VideoOutDriver.cpp @@ -10,6 +10,7 @@ #include "prx/libSceVideoOut/include/VideoOutDriver.hpp" #include "prx/libSceAgcDriver/Execution/include/Driver.hpp" #include "prx/libSceAgcDriver/Execution/include/Presentation.hpp" +#include "prx/libSceAgcDriver/Execution/include/PerformanceTimer.hpp" #include "prx/libSceAgcDriver/Submit/include/Dcb.hpp" #include "prx/libc/include/Shutdown.hpp" @@ -34,6 +35,7 @@ public: request->cfg = cfg; request->queue = queue; request->index = info.index; + request->outputHandle = info.handle; request->flipMode = static_cast(info.mode); request->flipArg = info.argument; std::lock_guard queueLock(queue->mutex); @@ -97,14 +99,20 @@ FlipRequest::~FlipRequest() { } } -void FlipRequest::GpuReady() { +void FlipRequest::GpuReady(const std::shared_ptr& frameTiming) { + require(frameTiming != nullptr, "missing frame timing"); + timing = frameTiming; { + AgcDriver::PerformanceContext timingContext(timing.get()); + AgcDriver::PerformanceTimer readiness("VideoOut.Readiness"); std::lock_guard queueLock(queue->mutex); if (queue->failure) std::rethrow_exception(queue->failure); require(!queue->stopping, "GPU flip during shutdown"); std::lock_guard lock(cfg->mutex); checkConfig(*cfg); require(reserved && !ready && !terminal && cfg->generation == generation, "invalid flip readiness transition"); + readiness.Mark("locks_validate"); + queuedAt = AgcDriver::FrameTiming::Clock::now(); queue->requests.push_back(shared_from_this()); ready = true; } @@ -312,14 +320,19 @@ void VideoOutDriver::vblankEnd() { } void VideoOutDriver::processFlip(FlipRequest& req) { + AgcDriver::PerformanceContext timingContext(req.timing.get()); + AgcDriver::PerformanceTimer timing("VideoOut.Flip"); { std::unique_lock lock(req.cfg->mutex); + timing.Mark("config_mutex_wait"); checkConfig(*req.cfg); require(req.ready && !req.terminal && req.generation == req.cfg->generation, "stale or incomplete flip request"); const auto interval = static_cast(req.flipRate + 1); require(req.cfg->lastFlipVblank <= std::numeric_limits::max() - interval, "flip interval overflow"); const auto target = req.cfg->lastFlipVblank + interval; + timing.Mark("validate"); req.cfg->vblankCond.wait(lock, [&] { return req.cfg->vblankStatus.count >= target || req.cfg->failure || req.cfg->closing; }); + timing.Mark("vblank_wait"); checkConfig(*req.cfg); } require(req.width != 0 && req.height != 0 && req.width <= static_cast(std::numeric_limits::max()) && req.height <= static_cast(std::numeric_limits::max()), "invalid window dimensions"); @@ -339,7 +352,8 @@ void VideoOutDriver::processFlip(FlipRequest& req) { SDL_Vulkan_GetDrawableSize(static_cast(context), &drawableWidth, &drawableHeight); *width = drawableWidth > 0 ? static_cast(drawableWidth) : 0; *height = drawableHeight > 0 ? static_cast(drawableHeight) : 0; - }, req.width, req.height}; + }, req.width, req.height, req.timing}; + timing.Mark("window_prepare"); const auto gpuReady = [](void* context) { auto& request = *static_cast(context); std::lock_guard lock(request.cfg->mutex); @@ -354,8 +368,11 @@ void VideoOutDriver::processFlip(FlipRequest& req) { } else { AgcDriverPresentClear_nid_postfix(target, req.index == VIDEO_OUT_BUFFER_INDEX_BLACK, gpuReady, &req); } + timing.Mark("present"); window.UpdateTitle(); + timing.Mark("window_title"); std::lock_guard lock(req.cfg->mutex); + timing.Mark("completion_mutex_wait"); checkConfig(*req.cfg); require(!req.terminal && req.cfg->generation == req.generation, "flip cancelled during presentation"); require(req.gpuComplete, "flip submitted before GPU completion"); @@ -374,6 +391,7 @@ void VideoOutDriver::processFlip(FlipRequest& req) { if (req.index >= 0) --req.cfg->bufferPending[req.index]; req.terminal = true; req.cfg->vblankCond.notify_all(); + timing.Mark("notify_game"); } void VideoOutDriver::presentLoop(std::stop_token token) { @@ -390,7 +408,21 @@ void VideoOutDriver::presentLoop(std::stop_token token) { flipQueue->requests.pop_front(); } } - if (current) processFlip(*current); + if (current) { + require(current->timing != nullptr, "missing presentation timing"); + const auto dequeued = AgcDriver::FrameTiming::Clock::now(); + current->timing->Add(current->timing->Get("VideoOut", "queue"), dequeued - current->queuedAt); + processFlip(*current); + const auto finished = AgcDriver::FrameTiming::Clock::now(); + AgcDriver::FrameTiming::Clock::duration interval{}; + { + std::lock_guard lock(current->cfg->mutex); + const auto previous = current->cfg->lastTimingFlip; + 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); + } current.reset(); SDL_Event event; while (SDL_PollEvent(&event)) { diff --git a/core/libs/prx/libSceVideoOut/tests/Flip.cpp b/core/libs/prx/libSceVideoOut/tests/Flip.cpp index bf7d99bb2..e67aa6a13 100644 --- a/core/libs/prx/libSceVideoOut/tests/Flip.cpp +++ b/core/libs/prx/libSceVideoOut/tests/Flip.cpp @@ -37,7 +37,7 @@ public: std::condition_variable changed; bool released = false; std::shared_ptr Reserve(const AgcDriver::FlipInfo&) override { return shared_from_this(); } - void GpuReady() override { + void GpuReady(const std::shared_ptr&) override { std::unique_lock lock(mutex); if (!changed.wait_for(lock, std::chrono::seconds(10), [&] { return released; })) throw std::runtime_error("test gate timed out"); } diff --git a/core/shader/recompiler/Recompiler.cpp b/core/shader/recompiler/Recompiler.cpp index 4a9e3d1a1..7b4364931 100644 --- a/core/shader/recompiler/Recompiler.cpp +++ b/core/shader/recompiler/Recompiler.cpp @@ -22,9 +22,7 @@ #include "SpirvBackend/SpirvMemory/SpirvInputOutput.hpp" #include "Translation/include/Translation/InstructionTranslator.hpp" #include "Translation/include/Translation/ShaderInputInfoBuilder.hpp" -#include #include -#include #include #include #include @@ -124,7 +122,6 @@ IrProgram PrepareResourceProgram(const RecompileRequest& request) { namespace { RecompileResult RecompileImpl(const RecompileRequest& request) { - const auto recompileStart = std::chrono::steady_clock::now(); auto program = PrepareResourceProgram(request); const auto inputInfo = BuildShaderStageInputInfo(toShaderStageKind(request.shader.stage), request.context); @@ -166,9 +163,7 @@ RecompileResult RecompileImpl(const RecompileRequest& request) { result.spirv = spirvEmitter.Emit(program, inputInfo, bindings, targetOptions); #if ANYPS5_ENABLE_SPIRV_TOOLS - const auto validationStart = std::chrono::steady_clock::now(); result.spirv = ValidateAndOptimizeSpirv(result.spirv, request.target.vulkanVersion, request.target.spirvVersion); - const auto validationEnd = std::chrono::steady_clock::now(); #endif result.bdaAbiVersion = program.Info().usesDma ? request.target.bdaAbiVersion : 0u; @@ -189,15 +184,6 @@ RecompileResult RecompileImpl(const RecompileRequest& request) { } } - const auto recompileEnd = std::chrono::steady_clock::now(); - const auto recompileTime = std::chrono::duration(recompileEnd - recompileStart).count(); -#if ANYPS5_ENABLE_SPIRV_TOOLS - const auto validationTime = std::chrono::duration(validationEnd - validationStart).count(); - std::fprintf(stdout, "[RecompileImpl] shader recompiled in %.3f ms, ValidateAndOptimizeSpirv %.3f ms\n", recompileTime, validationTime); -#else - std::fprintf(stdout, "[RecompileImpl] shader recompiled in %.3f ms, SPIRV-Tools disabled\n", recompileTime); -#endif - std::fflush(stdout); return result; }