refactor(log): remove extra logs + refactor timing logging

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;
 }
 

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;
 }
 

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 <atomic>
+#include <algorithm>
 #include <chrono>
 #include <cstddef>
+#include <cstdint>
 #include <cstdio>
-#include <exception>
+#include <iomanip>
+#include <locale>
+#include <map>
+#include <memory>
+#include <mutex>
+#include <sstream>
 #include <stdexcept>
+#include <string_view>
+#include <utility>
 
 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<double, std::milli>(elapsed).count();
+    }
+
+    std::mutex mutex;
+    std::map<std::pair<std::string_view, std::string_view>, 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<std::size_t>(count) >= sizeof(stages) - used) {
-            throw std::runtime_error("PerformanceTimer: timing log capacity exceeded");
-        }
-        used += static_cast<std::size_t>(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<double, std::milli>(duration).count();
-    }
-
-    inline static std::atomic<unsigned long long> 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;
 };
 
 }

core/libs/prx/libSceAgcDriver/Execution/include/Presentation.hpp

@@ -6,10 +6,13 @@
 #include <cstdint>
 #include <exception>
 #include <span>
+#include <memory>
 #include "prx/libSceAgcDriver/Execution/include/DisplayBuffer.hpp"
 
 namespace AgcDriver {
 
+class FrameTiming;
+
 struct PresentationWindow {
     void* context;
     std::span<const char* const> 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<FrameTiming> timing;
 };
 
 }

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<FrameTiming>& timing) = 0;
     virtual void Fail(std::exception_ptr error) noexcept = 0;
 };
 

core/libs/prx/libSceAgcDriver/Execution/src/Driver.cpp

@@ -49,6 +49,11 @@ struct Submission {
     std::map<std::uint64_t, std::shared_ptr<const ShaderSnapshot>> shaders;
     std::map<std::size_t, std::shared_ptr<IFlipRequest>> 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<std::size_t>::max() / sizeof(std::uint32_t), "command size overflow");
             GuestMemory::CheckRange(descriptor.addr, static_cast<std::size_t>(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> frameTiming;
+    std::uint64_t frameSerial = 0;
     std::thread worker;
 
     Driver() : worker([this] { run(); }) {
@@ -302,7 +320,9 @@ private:
     }
 
     void dispatch(QueueState& queue, std::span<const std::uint32_t> packet, const Submission& submission) {
+        PerformanceTimer timing("Driver.Dispatch");
         std::lock_guard gpuLock(gpuMutex);
+        timing.Mark("gpu_mutex_wait");
         const auto address = (static_cast<std::uint64_t>(readRegister(queue.shader, 0x20c)) << 8u) | (static_cast<std::uint64_t>(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<Graphics::GuestMemorySnapshot> 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<const std::uint32_t> 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<std::uint32_t>(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<std::uint64_t>::max(), "frame serial overflow");
+            frameTiming = std::make_shared<FrameTiming>(++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<std::size_t>((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;
                 }

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 <algorithm>
 #include <cstring>
 #include <limits>
@@ -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<std::byte> destination, std::size_t alignment) {
+    PerformanceTimer timing("GuestMemory.Read");
     if (destination.empty()) return;
     const auto* source = reinterpret_cast<const void*>(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<const std::byte> source, std::size_t alignment) {
+    PerformanceTimer timing("GuestMemory.Write");
     if (source.empty()) return;
     auto* destination = reinterpret_cast<void*>(address);
     CheckRange(destination, source.size(), alignment, true);
+    timing.Mark("range_check");
     std::memcpy(destination, source.data(), source.size());
+    timing.Mark("copy", source.size());
 }
 
 }

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<const std::uint32_t> packet, const QueueSta
     const auto bytes = static_cast<std::uint64_t>(packet[3]) * indexSize;
     require(bytes <= std::numeric_limits<std::size_t>::max(), "index range size overflow");
     GuestMemory::CheckRange(reinterpret_cast<const void*>(address), static_cast<std::size_t>(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<const std::uint32_t> 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<const std::uint32_t> 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<const std::uint32_t> 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;

core/libs/prx/libSceAgcDriver/Execution/src/VulkanDevice.cpp

@@ -102,9 +102,7 @@ struct VulkanDevice::State {
     }
 
     void Upload(std::span<const std::byte> pixels) {
-        APS5_LOG_OUT("Upload pixels=%zu uploadSize=%llu buffer=%p memory=%p mapping=%p", pixels.size(), static_cast<unsigned long long>(uploadSize), reinterpret_cast<void*>(uploadBuffer), reinterpret_cast<void*>(uploadMemory), uploadMapping);
         if (uploadSize < pixels.size()) {
-            APS5_LOG_OUT("Upload reallocating oldSize=%llu newSize=%zu", static_cast<unsigned long long>(uploadSize), pixels.size());
             if (uploadMapping) DeviceFunction<PFN_vkUnmapMemory>("vkUnmapMemory")(device, uploadMemory);
             uploadMapping = nullptr;
             if (uploadBuffer) DeviceFunction<PFN_vkDestroyBuffer>("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<unsigned long long>(requirements.size), static_cast<unsigned long long>(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<PFN_vkBindBufferMemory>("vkBindBufferMemory")(device, uploadBuffer, uploadMemory, 0), "vkBindBufferMemory display upload");
             check(DeviceFunction<PFN_vkMapMemory>("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<void*>(uploadBuffer), reinterpret_cast<void*>(uploadMemory), uploadMapping, static_cast<unsigned long long>(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<State>()) {
-    APS5_LOG_OUT("VulkanDevice constructor window=%p", static_cast<const void*>(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<PFN_vkGetInstanceProcAddr>(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<const char*> 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<PFN_vkCreateInstance>("vkCreateInstance")(&create, nullptr, &state->instance), "vkCreateInstance");
-    APS5_LOG_OUT("Vulkan instance created instance=%p", reinterpret_cast<void*>(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<void*>(state->surface), state->window);
     }
     state->deviceProc = state->InstanceFunction<PFN_vkGetDeviceProcAddr>("vkGetDeviceProcAddr");
     const auto enumerate = state->InstanceFunction<PFN_vkEnumeratePhysicalDevices>("vkEnumeratePhysicalDevices");
     std::uint32_t count = 0;
     check(enumerate(state->instance, &count, nullptr), "vkEnumeratePhysicalDevices");
-    APS5_LOG_OUT("Physical device count=%u", count);
     std::vector<VkPhysicalDevice> 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<PFN_vkGetPhysicalDeviceProperties>("vkGetPhysicalDeviceProperties")(physical, &properties);
-        APS5_LOG_OUT("Physical device candidate=%p name=%s api=0x%x", reinterpret_cast<void*>(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<void*>(selected), family);
     VkPhysicalDeviceProperties2 properties{VK_STRUCTURE_TYPE_PHYSICAL_DEVICE_PROPERTIES_2};
     properties.pNext = &state->subgroup;
     state->InstanceFunction<PFN_vkGetPhysicalDeviceProperties2>("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<PFN_vkGetPhysicalDeviceMemoryProperties>("vkGetPhysicalDeviceMemoryProperties")(selected, &state->memoryProperties);
     std::uint32_t extensionCount = 0;
     const auto enumerateDeviceExtensions = state->InstanceFunction<PFN_vkEnumerateDeviceExtensionProperties>("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<unsigned>(state->tessellationShader), static_cast<unsigned>(state->meshShader), static_cast<unsigned>(state->depthClipControl), static_cast<unsigned>(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<PFN_vkCreateDevice>("vkCreateDevice")(selected, &deviceInfo, nullptr, &state->device), "vkCreateDevice");
     state->DeviceFunction<PFN_vkGetDeviceQueue>("vkGetDeviceQueue")(state->device, family, 0, &state->queue);
-    APS5_LOG_OUT("Vulkan device ready device=%p queue=%p family=%u", reinterpret_cast<void*>(state->device), reinterpret_cast<void*>(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<PFN_vkGetPhysicalDeviceSurfaceCapabilitiesKHR>("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<std::uint32_t>::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<void*>(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<PFN_vkCreateFence>("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<PFN_vkDeviceWaitIdle>("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<void*>(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<unsigned>(opaque));
     present(width, height, opaque, {});
 }
 
 void VulkanDevice::PresentPixels(std::uint32_t width, std::uint32_t height, std::span<const std::byte> pixels) {
-    APS5_LOG_OUT("PresentPixels width=%u height=%u pixels=%zu expected=%llu", width, height, pixels.size(), static_cast<unsigned long long>(width) * height * 4u);
     require(width != 0 && height != 0 && width <= 16384 && height <= 16384, "invalid display image extent");
     require(pixels.size() == static_cast<std::uint64_t>(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<const std::byte> 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<unsigned>(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<PFN_vkWaitForFences>("vkWaitForFences");
     auto reset = state->DeviceFunction<PFN_vkResetFences>("vkResetFences");
     const std::array<VkFence, 2> fences{state->acquireFence, state->renderFence};
     check(reset(state->device, static_cast<std::uint32_t>(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<PFN_vkAcquireNextImageKHR>("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<std::uint64_t>::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<PFN_vkBeginCommandBuffer>("vkBeginCommandBuffer")(commands, &begin), "vkBeginCommandBuffer");
-    APS5_LOG_OUT_DEBUG("Presentation command buffer begin commands=%p image=%p", reinterpret_cast<void*>(commands), reinterpret_cast<void*>(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<PFN_vkCmdPipelineBarrier>("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<unsigned>(opaque), reinterpret_cast<void*>(barrier.image));
         VkClearColorValue clear{};
         clear.float32[3] = opaque ? 1.0f : 0.0f;
         state->DeviceFunction<PFN_vkCmdClearColorImage>("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<void*>(state->uploadBuffer), reinterpret_cast<void*>(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<PFN_vkEndCommandBuffer>("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<PFN_vkQueueSubmit>("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<std::uint64_t>::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<PFN_vkQueuePresentKHR>("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<const Graphics::CompiledShader> shaders, std::span<const Graphics::GuestMemorySnapshot> 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<unsigned long long>(draw.indexAddress), shaders.size(), static_cast<unsigned>(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<const Graphics::GuestMemorySnapshot> 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<std::uint64_t>::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;

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<const CompiledShader> shaders, std::span<const GuestMemorySnapshot> 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<unsigned long long>(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<unsigned long long>(state.color.address), static_cast<unsigned long long>(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<unsigned>(state.topology), static_cast<unsigned>(state.cullMode), static_cast<unsigned>(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<std::uint64_t>(draw.indexCount) * draw.indexSize;
-    APS5_LOG_OUT_DEBUG("Index buffer bytes=%llu", static_cast<unsigned long long>(indexBytes));
     Require(indexBytes <= std::numeric_limits<std::size_t>::max(), "index buffer size overflow");
     if (draw.indexed) GuestMemory::CheckRange(reinterpret_cast<const void*>(draw.indexAddress), static_cast<std::size_t>(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<unsigned>(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<std::uint64_t>(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<void>(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<unsigned long long>(state.color.address), static_cast<unsigned long long>(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<std::size_t>(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<PFN_vkCmdPipelineBarrier>("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<PFN_vkCmdCopyBufferToImage>("vkCmdCopyBufferToImage")(commands, context.colorTransfer->LinearBuffer(), target->Image(), VK_IMAGE_LAYOUT_TRANSFER_DST_OPTIMAL, 1, &copy);
         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<PFN_vkCmdDrawMeshTasksEXT>("vkCmdDrawMeshTasksEXT")(commands, meshGroups, draw.instanceCount, 1);
     } else {
         if (!vertexHandles.empty()) context.Function<PFN_vkCmdBindVertexBuffers>("vkCmdBindVertexBuffers")(commands, 0, static_cast<std::uint32_t>(vertexHandles.size()), vertexHandles.data(), vertexOffsets.data());
@@ -170,11 +140,8 @@ void Draw(const Context& context, const State& state, const Pm4::DrawParameters&
             context.Function<PFN_vkCmdDraw>("vkCmdDraw")(commands, draw.indexCount, draw.instanceCount, draw.firstVertex, draw.firstInstance);
         }
     }
-    APS5_LOG_CHARS_OUT_DEBUG("Draw recorded");
     context.Function<PFN_vkCmdEndRenderPass>("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<PFN_vkCmdPipelineBarrier>("vkCmdPipelineBarrier")(commands, VK_PIPELINE_STAGE_TRANSFER_BIT, VK_PIPELINE_STAGE_TRANSFER_BIT, 0, 0, nullptr, 1, &reuse, 0, nullptr);
         context.Function<PFN_vkCmdCopyImageToBuffer>("vkCmdCopyImageToBuffer")(commands, target->Image(), VK_IMAGE_LAYOUT_TRANSFER_SRC_OPTIMAL, context.colorTransfer->LinearBuffer(), 1, &copy);
         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<PFN_vkCmdPipelineBarrier>("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<const void*>(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<unsigned long long>(state.color.address), static_cast<unsigned long long>(state.color.bytes));
-    APS5_LOG_CHARS_OUT("Draw finished");
 }
 
 }

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 <array>
+#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 {

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<unsigned>(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<unsigned>(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<unsigned>(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<unsigned>(result.cullMode), static_cast<unsigned>(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<std::uint64_t>(high) << 40u) | (static_cast<std::uint64_t>(read(cx, 0x318)) << 8u);
-        APS5_LOG_OUT_DEBUG("Color address=0x%llx high=0x%x low=0x%x", static_cast<unsigned long long>(result.color.address), high, read(cx, 0x318));
         result.color.bytes = colorLayout.Bytes();
-        APS5_LOG_OUT_DEBUG("Color bytes=%llu", static_cast<unsigned long long>(result.color.bytes));
         GuestMemory::CheckRange(reinterpret_cast<const void*>(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<unsigned>(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<unsigned>(result.topology));
     return result;
 }
 

core/libs/prx/libSceAgcDriver/tests/Flip.cpp

@@ -45,7 +45,7 @@ class Request final : public AgcDriver::IFlipRequest {
 public:
     explicit Request(std::shared_ptr<State> value) : state(std::move(value)) { ++state->alive; }
     ~Request() override { --state->alive; }
-    void GpuReady() override {
+    void GpuReady(const std::shared_ptr<AgcDriver::FrameTiming>&) 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");

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<std::uint32_t, 3> indirectOpcodes{0x9f, 0x63, 0x64};
     for (auto opcode : indirectOpcodes) {
         std::array<std::uint32_t, 6> pairs{0x10, 41, 0x11, 42, 0x10, 43};

core/libs/prx/libSceVideoOut/include/VideoOutDriver.hpp

@@ -2,6 +2,7 @@
 #define CORE_LIBS_PRX_LIBSCEVIDEOOUT_INCLUDE_VIDEOOUTDRIVER_HPP
 
 #include <array>
+#include <chrono>
 #include <condition_variable>
 #include <cstdint>
 #include <list>
@@ -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<VideoOutConfig> cfg;
     std::shared_ptr<FlipQueue> 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<AgcDriver::FrameTiming> timing;
+    std::chrono::steady_clock::time_point queuedAt;
+
     ~FlipRequest() override;
-    void GpuReady() override;
+    void GpuReady(const std::shared_ptr<AgcDriver::FrameTiming>& frameTiming) override;
     void Fail(std::exception_ptr error) noexcept override;
 };
 

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<int>(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<AgcDriver::FrameTiming>& 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<uint64_t>(req.flipRate + 1);
         require(req.cfg->lastFlipVblank <= std::numeric_limits<uint64_t>::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<uint32_t>(std::numeric_limits<int>::max()) && req.height <= static_cast<uint32_t>(std::numeric_limits<int>::max()), "invalid window dimensions");
@@ -339,7 +352,8 @@ void VideoOutDriver::processFlip(FlipRequest& req) {
         SDL_Vulkan_GetDrawableSize(static_cast<SDL_Window*>(context), &drawableWidth, &drawableHeight);
         *width = drawableWidth > 0 ? static_cast<std::uint32_t>(drawableWidth) : 0;
         *height = drawableHeight > 0 ? static_cast<std::uint32_t>(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<FlipRequest*>(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)) {

core/libs/prx/libSceVideoOut/tests/Flip.cpp

@@ -37,7 +37,7 @@ public:
     std::condition_variable changed;
     bool released = false;
     std::shared_ptr<AgcDriver::IFlipRequest> Reserve(const AgcDriver::FlipInfo&) override { return shared_from_this(); }
-    void GpuReady() override {
+    void GpuReady(const std::shared_ptr<AgcDriver::FrameTiming>&) 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");
     }

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 <chrono>
 #include <exception>
-#include <cstdio>
 #include <stdexcept>
 #include <string>
 #include <ControlFlow/RequestSerializer.hpp>
@@ -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<double, std::milli>(recompileEnd - recompileStart).count();
-#if ANYPS5_ENABLE_SPIRV_TOOLS
-    const auto validationTime = std::chrono::duration<double, std::milli>(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;
 }