perf(agc): format and write steady-state log lines off the queue worker

Texture creation logged one stdout line per texture and per mip through
WriteLogLine, which formatted with the mingw printf and flushed every
line on the queue worker (about 786k lines in a 25 minute cave run).

AsyncLog keeps a bounded queue and a logger thread. AGC_LOG_DEFERRED
captures numeric arguments on the caller and formats them on the logger
thread; WriteLogLine hands finished lines to a per-module sink in
libc/LogMacros.hpp that AgcDriver installs, so all AgcDriver stdout
lines keep their order and are written one flush per batch. A full queue
blocks the caller, so no line is dropped. Flush runs on driver failure,
shutdown and at exit. APS5_LOG_SYNC=1 restores the synchronous path.

Identical "deferred write-back failed" notes are printed three times per
10 s and then counted into one "repeated N more times" line. A
"[log] 10 s" line reports lines, bytes, caller time and logger time
(APS5_LOG_STATS=0 hides it).

core/libs/prx/libSceAgcDriver/CMakeLists.txt

@@ -348,6 +348,17 @@ if(BUILD_TESTING)
                 "PATH=path_list_prepend:$<TARGET_FILE_DIR:libc>")
     endif()
 
+    add_test_executable(agc_async_log_tests tests/AsyncLog.cpp)
+    target_include_directories(agc_async_log_tests PRIVATE ${LIBS_INCLUDE_DIR})
+    target_link_libraries(agc_async_log_tests PRIVATE libc)
+    configure_windows_unwind(agc_async_log_tests)
+    add_test(NAME agc_async_log COMMAND agc_async_log_tests)
+    set_tests_properties(agc_async_log PROPERTIES TIMEOUT 20)
+    if(WIN32)
+        set_tests_properties(agc_async_log PROPERTIES ENVIRONMENT_MODIFICATION
+                "PATH=path_list_prepend:$<TARGET_FILE_DIR:libc>")
+    endif()
+
     add_test_executable(agc_stack_walk_tests tests/StackWalk.cpp)
     target_include_directories(agc_stack_walk_tests PRIVATE ${LIBS_INCLUDE_DIR})
     target_link_libraries(agc_stack_walk_tests PRIVATE libc)

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

@@ -0,0 +1,376 @@
+#pragma once
+
+#include "prx/libc/include/general/LogMacros.hpp"
+#include <algorithm>
+#include <atomic>
+#include <chrono>
+#include <condition_variable>
+#include <cstdint>
+#include <cstdio>
+#include <cstdlib>
+#include <deque>
+#include <map>
+#include <memory>
+#include <mutex>
+#include <string>
+#include <thread>
+#include <tuple>
+#include <type_traits>
+#include <utility>
+#include <vector>
+
+namespace AgcDriver {
+
+struct LogLiteral {
+    const char* text;
+};
+
+namespace AsyncLogDetail {
+
+template<typename T>
+inline constexpr bool Deferrable = std::is_arithmetic_v<T> || std::is_enum_v<T> || std::is_same_v<T, LogLiteral>;
+
+inline const char* Unwrap(LogLiteral value) {
+    return value.text;
+}
+
+template<typename T>
+T Unwrap(T value) {
+    return value;
+}
+
+class Formatter {
+public:
+    virtual ~Formatter() = default;
+    virtual void Format(std::string& out) const = 0;
+};
+
+template<typename... TArgs>
+class Bound final : public Formatter {
+public:
+    Bound(const char* format, TArgs... args) : format(format), values(args...) {}
+
+    void Format(std::string& out) const override {
+        std::apply([&](const auto&... value) { Append(out, value...); }, values);
+    }
+
+private:
+    void Append(std::string& out, const auto&... value) const {
+        char small[512];
+        const int size = std::snprintf(small, sizeof(small), format, Unwrap(value)...);
+        if (size < 0) return;
+        if (static_cast<std::size_t>(size) < sizeof(small)) {
+            out.append(small, static_cast<std::size_t>(size));
+            return;
+        }
+        std::string large(static_cast<std::size_t>(size) + 1, '\0');
+        std::snprintf(large.data(), large.size(), format, Unwrap(value)...);
+        out.append(large.data(), static_cast<std::size_t>(size));
+    }
+
+    const char* format;
+    std::tuple<TArgs...> values;
+};
+
+struct Entry {
+    std::FILE* stream = nullptr;
+    long long micros = -1;
+    std::string text;
+    std::unique_ptr<Formatter> deferred;
+    std::size_t cost = 0;
+};
+
+}
+
+class AsyncLog {
+public:
+    using Clock = std::chrono::steady_clock;
+
+    static AsyncLog& Get() {
+        static AsyncLog* const instance = new AsyncLog();
+        return *instance;
+    }
+
+    int Write(std::FILE* stream, const char* text, std::size_t length) {
+        const auto start = Clock::now();
+        if (!asynchronous) return WriteNow(stream, text, length);
+        AsyncLogDetail::Entry entry;
+        entry.stream = stream;
+        entry.text.assign(text, length);
+        entry.cost = sizeof(entry) + length;
+        Enqueue(std::move(entry));
+        callerNanoseconds.fetch_add(Elapsed(start), std::memory_order_relaxed);
+        return 0;
+    }
+
+    template<typename... TArgs>
+    void Defer(std::FILE* stream, const char* format, TArgs... args) {
+        static_assert((AsyncLogDetail::Deferrable<TArgs> && ...), "deferred log arguments are numbers, enums or LogLiteral");
+        const auto start = Clock::now();
+        const auto micros = LogTimestampMicros();
+        auto bound = std::make_unique<AsyncLogDetail::Bound<TArgs...>>(format, args...);
+        if (!asynchronous) {
+            std::string text;
+            if (micros >= 0) AppendTimestamp(text, micros);
+            bound->Format(text);
+            WriteNow(stream, text.data(), text.size());
+            return;
+        }
+        AsyncLogDetail::Entry entry;
+        entry.stream = stream;
+        entry.micros = micros;
+        entry.deferred = std::move(bound);
+        entry.cost = sizeof(entry) + sizeof(AsyncLogDetail::Bound<TArgs...>);
+        Enqueue(std::move(entry));
+        callerNanoseconds.fetch_add(Elapsed(start), std::memory_order_relaxed);
+    }
+
+    bool Admit(const std::string& line) {
+        const auto now = Clock::now();
+        std::string summary;
+        {
+            std::lock_guard lock(coalesceMutex);
+            auto found = windows.find(line);
+            if (found == windows.end()) {
+                if (windows.size() >= CoalesceKeys) return true;
+                windows.emplace(line, Window{now, 1, 0});
+                return true;
+            }
+            auto& window = found->second;
+            if (now - window.first < CoalesceWindow) {
+                if (++window.seen <= PrintedRepeats) return true;
+                ++window.suppressed;
+                coalescedTotal.fetch_add(1, std::memory_order_relaxed);
+                return false;
+            }
+            summary = Summary(found->first, window.suppressed);
+            window = Window{now, 1, 0};
+        }
+        if (!summary.empty()) WriteNow(stderr, summary.data(), summary.size());
+        return true;
+    }
+
+    void Flush() {
+        if (!asynchronous) return;
+        std::unique_lock lock(mutex);
+        idle.wait_for(lock, std::chrono::seconds(2), [&] { return pending.empty() && !writing; });
+    }
+
+private:
+    struct Window {
+        Clock::time_point first;
+        std::uint64_t seen;
+        std::uint64_t suppressed;
+    };
+
+    static constexpr std::size_t Capacity = 16u * 1024u * 1024u;
+    static constexpr std::size_t CoalesceKeys = 128;
+    static constexpr std::uint64_t PrintedRepeats = 3;
+    static constexpr std::chrono::seconds CoalesceWindow{10};
+    static constexpr std::chrono::seconds StatsWindow{10};
+    static constexpr std::chrono::milliseconds Tick{500};
+
+    AsyncLog() {
+        asynchronous = std::getenv("APS5_LOG_SYNC") == nullptr;
+        const char* stats = std::getenv("APS5_LOG_STATS");
+        statsEnabled = stats == nullptr || std::string(stats) != "0";
+        lastStats = Clock::now();
+        if (!asynchronous) return;
+        LogSink().store(&AsyncLog::Sink, std::memory_order_release);
+        std::atexit([] { Get().Flush(); });
+        std::thread([this] { Run(); }).detach();
+    }
+
+    static int Sink(std::FILE* stream, const char* text, std::size_t length) {
+        return Get().Write(stream, text, length);
+    }
+
+    static std::uint64_t Elapsed(Clock::time_point start) {
+        return static_cast<std::uint64_t>(std::chrono::duration_cast<std::chrono::nanoseconds>(Clock::now() - start).count());
+    }
+
+    static void AppendTimestamp(std::string& out, long long micros) {
+        char prefix[64];
+        const int size = FormatLogTimestamp(prefix, sizeof(prefix), micros);
+        if (size > 0) out.append(prefix, static_cast<std::size_t>(size));
+    }
+
+    static std::string Summary(const std::string& line, std::uint64_t suppressed) {
+        if (suppressed == 0) return {};
+        std::string text = line;
+        while (!text.empty() && (text.back() == '\n' || text.back() == '\r')) text.pop_back();
+        text += " (repeated " + std::to_string(suppressed) + " more times in the last 10 s)\n";
+        return text;
+    }
+
+    static int WriteNow(std::FILE* stream, const char* text, std::size_t length) {
+        std::fwrite(text, 1, length, stream);
+        return std::fflush(stream);
+    }
+
+    void Enqueue(AsyncLogDetail::Entry&& entry) {
+        bool notify = false;
+        {
+            std::unique_lock lock(mutex);
+            space.wait(lock, [&] { return bytes == 0 || bytes + entry.cost <= Capacity; });
+            bytes += entry.cost;
+            peak = std::max(peak, bytes);
+            pending.push_back(std::move(entry));
+            notify = sleeping;
+            sleeping = false;
+        }
+        if (notify) wake.notify_one();
+    }
+
+    void Run() noexcept {
+        std::deque<AsyncLogDetail::Entry> batch;
+        std::string buffer;
+        for (;;) {
+            {
+                std::unique_lock lock(mutex);
+                sleeping = true;
+                wake.wait_for(lock, Tick, [&] { return !pending.empty(); });
+                sleeping = false;
+                batch.swap(pending);
+                bytes = 0;
+                writing = !batch.empty();
+            }
+            space.notify_all();
+            if (!batch.empty()) {
+                const auto start = Clock::now();
+                try {
+                    Drain(batch, buffer);
+                } catch (...) {
+                    buffer.clear();
+                }
+                batch.clear();
+                loggerNanoseconds.fetch_add(Elapsed(start), std::memory_order_relaxed);
+                {
+                    std::lock_guard lock(mutex);
+                    writing = false;
+                }
+                idle.notify_all();
+            }
+            try {
+                Housekeeping();
+            } catch (...) {
+            }
+        }
+    }
+
+    void Drain(std::deque<AsyncLogDetail::Entry>& batch, std::string& buffer) {
+        std::FILE* current = nullptr;
+        buffer.clear();
+        std::uint64_t outLines = 0;
+        std::uint64_t errLines = 0;
+        std::uint64_t written = 0;
+        const auto emit = [&] {
+            if (current != nullptr && !buffer.empty()) {
+                written += buffer.size();
+                WriteNow(current, buffer.data(), buffer.size());
+            }
+            buffer.clear();
+        };
+        for (auto& entry : batch) {
+            if (entry.stream != current) {
+                emit();
+                current = entry.stream;
+            }
+            if (entry.deferred) {
+                if (entry.micros >= 0) AppendTimestamp(buffer, entry.micros);
+                entry.deferred->Format(buffer);
+            } else {
+                buffer += entry.text;
+            }
+            (entry.stream == stderr ? errLines : outLines) += 1;
+            if (buffer.size() >= 65536) emit();
+        }
+        emit();
+        stdoutLines.fetch_add(outLines, std::memory_order_relaxed);
+        stderrLines.fetch_add(errLines, std::memory_order_relaxed);
+        loggedBytes.fetch_add(written, std::memory_order_relaxed);
+    }
+
+    void Housekeeping() {
+        const auto now = Clock::now();
+        std::vector<std::string> summaries;
+        {
+            std::lock_guard lock(coalesceMutex);
+            for (auto it = windows.begin(); it != windows.end();) {
+                if (now - it->second.first >= CoalesceWindow) {
+                    const auto summary = Summary(it->first, it->second.suppressed);
+                    if (!summary.empty()) summaries.push_back(summary);
+                    it = windows.erase(it);
+                } else {
+                    ++it;
+                }
+            }
+        }
+        for (const auto& summary : summaries) WriteNow(stderr, summary.data(), summary.size());
+        if (now - lastStats < StatsWindow) return;
+        const double seconds = std::chrono::duration<double>(now - lastStats).count();
+        lastStats = now;
+        const auto outLines = stdoutLines.exchange(0, std::memory_order_relaxed);
+        const auto errLines = stderrLines.exchange(0, std::memory_order_relaxed);
+        const auto written = loggedBytes.exchange(0, std::memory_order_relaxed);
+        const auto caller = callerNanoseconds.exchange(0, std::memory_order_relaxed);
+        const auto logger = loggerNanoseconds.exchange(0, std::memory_order_relaxed);
+        const auto coalesced = coalescedTotal.exchange(0, std::memory_order_relaxed);
+        std::size_t high = 0;
+        {
+            std::lock_guard lock(mutex);
+            high = peak;
+            peak = bytes;
+        }
+        if (!statsEnabled || outLines + errLines + coalesced == 0) return;
+        char line[512];
+        const int size = std::snprintf(line, sizeof(line), "[log] %.1f s: %llu lines (%llu stdout, %llu stderr), %.1f KiB written, %llu repeats coalesced; callers spent %.2f ms queueing and formatting (%.3f%% of one thread), logger thread %.2f ms, queue peak %.1f KiB\n", seconds, static_cast<unsigned long long>(outLines + errLines), static_cast<unsigned long long>(outLines), static_cast<unsigned long long>(errLines), static_cast<double>(written) / 1024.0, static_cast<unsigned long long>(coalesced), static_cast<double>(caller) / 1e6, static_cast<double>(caller) / 1e9 / seconds * 100.0, static_cast<double>(logger) / 1e6, static_cast<double>(high) / 1024.0);
+        if (size > 0) WriteNow(stderr, line, std::min(static_cast<std::size_t>(size), sizeof(line) - 1));
+    }
+
+    bool asynchronous = true;
+    bool statsEnabled = true;
+    std::mutex mutex;
+    std::condition_variable wake;
+    std::condition_variable space;
+    std::condition_variable idle;
+    std::deque<AsyncLogDetail::Entry> pending;
+    std::size_t bytes = 0;
+    std::size_t peak = 0;
+    bool sleeping = false;
+    bool writing = false;
+    std::mutex coalesceMutex;
+    std::map<std::string, Window> windows;
+    Clock::time_point lastStats;
+    std::atomic<std::uint64_t> stdoutLines{0};
+    std::atomic<std::uint64_t> stderrLines{0};
+    std::atomic<std::uint64_t> loggedBytes{0};
+    std::atomic<std::uint64_t> callerNanoseconds{0};
+    std::atomic<std::uint64_t> loggerNanoseconds{0};
+    std::atomic<std::uint64_t> coalescedTotal{0};
+};
+
+inline void InstallAsyncLog_nid_no_patch() {
+    static_cast<void>(AsyncLog::Get());
+}
+
+inline void FlushAsyncLog_nid_no_patch() {
+    AsyncLog::Get().Flush();
+}
+
+template<typename... TArgs>
+void LogCoalescedStderr_nid_no_patch(const char* format, TArgs... args) {
+    char small[1024];
+    const int size = std::snprintf(small, sizeof(small), format, args...);
+    if (size < 0) return;
+    std::string line = static_cast<std::size_t>(size) < sizeof(small) ? std::string(small, static_cast<std::size_t>(size)) : std::string(static_cast<std::size_t>(size), '\0');
+    if (static_cast<std::size_t>(size) >= sizeof(small)) std::snprintf(line.data(), line.size() + 1, format, args...);
+    if (!AsyncLog::Get().Admit(line)) return;
+    std::fwrite(line.data(), 1, line.size(), stderr);
+    std::fflush(stderr);
+}
+
+}
+
+#define AGC_LOG_DEFERRED(stream, fmt, ...) \
+::AgcDriver::AsyncLog::Get().Defer(stream, "[%s:%d %s] " fmt "\n", ::AgcDriver::LogLiteral{_APS5_FILE_}, __LINE__, ::AgcDriver::LogLiteral{TrimNidPostfix(__func__)}, __VA_ARGS__)

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

@@ -1,3 +1,4 @@
+#include "prx/libSceAgcDriver/Execution/include/AsyncLog.hpp"
 #include "prx/libSceAgcDriver/Execution/include/Driver/Driver.hpp"
 #include "prx/libSceAgcDriver/Execution/include/Driver/Diagnostics.hpp"
 #include "prx/libSceAgcDriver/Execution/include/Driver/Shaders/ShaderRegistry.hpp"
@@ -38,6 +39,7 @@ void PrintFailure(std::exception_ptr error) {
     } catch (...) {
         std::fprintf(stderr, "[gpu] driver failure with a non-standard exception\n");
     }
+    FlushAsyncLog_nid_no_patch();
     std::fflush(stderr);
 }
 
@@ -119,11 +121,13 @@ void Driver::stop() {
     replacedDevices.clear();
     Graphics::ShutdownGuestBufferWorkers();
     PerformanceTrace::StopOutput();
+    FlushAsyncLog_nid_no_patch();
     StopProfileOutput_nid_no_patch();
     stopped = true;
 }
 
 Driver::Driver() {
+    InstallAsyncLog_nid_no_patch();
     static_cast<void>(GuestMemory::TrackerGeneration());
     ShaderMemory::SetWaitedMsProvider(&Graphics::Recorder::ThreadWaitedMs);
     try {

core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp

@@ -1,3 +1,4 @@
+#include "prx/libSceAgcDriver/Execution/include/AsyncLog.hpp"
 #include "prx/libSceAgcDriver/Execution/include/ProfileOutput.hpp"
 #include "prx/libSceAgcDriver/Execution/include/CaptureTrace.hpp"
 #include "prx/libc/include/HostThreadLocal.hpp"
@@ -3828,7 +3829,7 @@ void Recorder::finish(std::unique_ptr<Batch> batch, bool wait, int source, bool
             try {
                 action();
             } catch (const std::exception& error) {
-                std::fprintf(stderr, "[gpu] deferred write-back failed: %s\n", error.what());
+                AgcDriver::LogCoalescedStderr_nid_no_patch("[gpu] deferred write-back failed: %s\n", error.what());
             }
         }
     }

core/libs/prx/libSceAgcDriver/Graphics/src/Texture.cpp

@@ -1,3 +1,4 @@
+#include "prx/libSceAgcDriver/Execution/include/AsyncLog.hpp"
 #include "prx/libSceAgcDriver/Execution/include/ProfileOutput.hpp"
 #include "prx/libSceAgcDriver/Execution/include/CaptureTrace.hpp"
 #include "prx/libSceAgcDriver/Graphics/include/Texture.hpp"
@@ -259,9 +260,9 @@ Texture::Texture(const Context& context, TextureDetiler& detiler, const GuestTex
         const auto& mips = geometry.mips;
         const auto arrayLayers = geometry.layers;
         const auto elementBytes = BytesPerElement(descriptor.format);
-        APS5_LOG_OUT("Texture address=0x%llx %ux%u mips=%u layers=%u dim=%d tile=%d format=%u vk=%d element=%u", static_cast<unsigned long long>(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, arrayLayers,
+        AGC_LOG_DEFERRED(stdout, "Texture address=0x%llx %ux%u mips=%u layers=%u dim=%d tile=%d format=%u vk=%d element=%u", static_cast<unsigned long long>(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, arrayLayers,
                      static_cast<int>(descriptor.dimension), static_cast<int>(descriptor.tileMode), descriptor.format, static_cast<int>(vkFormat), elementBytes);
-        for (const auto& mip : mips) APS5_LOG_OUT("  mip %ux%u tiled=0x%llx+0x%llx linear=0x%llx+0x%llx blocksPerRow=%u pitch=%u tail=%d", mip.width, mip.height, static_cast<unsigned long long>(mip.tiledOffset), static_cast<unsigned long long>(mip.tiledSize), static_cast<unsigned long long>(mip.linearOffset), static_cast<unsigned long long>(mip.linearSize), mip.blocksPerRow, mip.pitchBytes, mip.tail ? 1 : 0);
+        for (const auto& mip : mips) AGC_LOG_DEFERRED(stdout, "  mip %ux%u tiled=0x%llx+0x%llx linear=0x%llx+0x%llx blocksPerRow=%u pitch=%u tail=%d", mip.width, mip.height, static_cast<unsigned long long>(mip.tiledOffset), static_cast<unsigned long long>(mip.tiledSize), static_cast<unsigned long long>(mip.linearOffset), static_cast<unsigned long long>(mip.linearSize), mip.blocksPerRow, mip.pitchBytes, mip.tail ? 1 : 0);
 
         const auto guestBytes = geometry.guestBytes;
         Require(snapshot.size() == guestBytes, "texture snapshot size mismatch");
@@ -504,7 +505,7 @@ Texture::Texture(const Context& context, const std::shared_ptr<StorageTexture>&
         copyLevels = descriptor.mipCount;
         copyLayers = geometry.imageLayers;
         copyElementBytes = BytesPerElement(descriptor.format);
-        APS5_LOG_OUT("Texture address=0x%llx %ux%u mips=%u layers=%u block copy of storage image (guest format %u -> vk %d)", static_cast<unsigned long long>(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, copyLayers, source->Descriptor().format, static_cast<int>(blockFormat));
+        AGC_LOG_DEFERRED(stdout, "Texture address=0x%llx %ux%u mips=%u layers=%u block copy of storage image (guest format %u -> vk %d)", static_cast<unsigned long long>(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, copyLayers, source->Descriptor().format, static_cast<int>(blockFormat));
 
         VkImageCreateInfo imageInfo{VK_STRUCTURE_TYPE_IMAGE_CREATE_INFO};
         imageInfo.imageType = VK_IMAGE_TYPE_2D;
@@ -560,7 +561,7 @@ Texture::Texture(const Context& context, const std::shared_ptr<StorageTexture>&
         copyLevels = descriptor.mipCount;
         copyLayers = geometry.imageLayers;
         copyElementBytes = BytesPerElement(descriptor.format);
-        APS5_LOG_OUT("Texture address=0x%llx %ux%u mips=%u layers=%u depth copy of storage image (vk=%d -> %d)", static_cast<unsigned long long>(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, copyLayers, static_cast<int>(colorFormat), static_cast<int>(depthFormat));
+        AGC_LOG_DEFERRED(stdout, "Texture address=0x%llx %ux%u mips=%u layers=%u depth copy of storage image (vk=%d -> %d)", static_cast<unsigned long long>(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, copyLayers, static_cast<int>(colorFormat), static_cast<int>(depthFormat));
 
         VkImageCreateInfo imageInfo{VK_STRUCTURE_TYPE_IMAGE_CREATE_INFO};
         imageInfo.flags = descriptor.dimension == TextureDimension::kCube ? VK_IMAGE_CREATE_CUBE_COMPATIBLE_BIT : 0u;
@@ -747,7 +748,7 @@ Texture::Texture(const Context& context, const std::shared_ptr<StorageTexture>&
         Require(source != nullptr && CanCopyFrom(*source, descriptor), "storage image does not match the sampled texture");
         const auto vkFormat = SampledTextureFormat(context, descriptor.format);
         const auto geometry = DescribeSurface(descriptor);
-        APS5_LOG_OUT("Texture address=0x%llx %ux%u mips=%u viewed from storage image (vk=%d)", static_cast<unsigned long long>(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, static_cast<int>(vkFormat));
+        AGC_LOG_DEFERRED(stdout, "Texture address=0x%llx %ux%u mips=%u viewed from storage image (vk=%d)", static_cast<unsigned long long>(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, static_cast<int>(vkFormat));
         // Storage images stay in the general layout; the view samples them there.
         layout = VK_IMAGE_LAYOUT_GENERAL;
         const auto viewLevelCount = std::min(descriptor.lastLevel, descriptor.mipCount - 1u) - descriptor.baseLevel + 1u;
@@ -1087,7 +1088,7 @@ StorageTexture::StorageTexture(const Context& context, TextureDetiler& detiler,
         Require(mipLevel < descriptor.mipCount, "storage texture mip level is outside the texture");
         const auto vkFormat = StorageFormatFor(context, ResolveTextureFormat(descriptor.format));
         storageFormat = vkFormat;
-        APS5_LOG_OUT("StorageTexture address=0x%llx %ux%u mips=%u mip=%u layers=%u base=%u dim=%d tile=%d format=%u vk=%d", static_cast<unsigned long long>(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, mipLevel,
+        AGC_LOG_DEFERRED(stdout, "StorageTexture address=0x%llx %ux%u mips=%u mip=%u layers=%u base=%u dim=%d tile=%d format=%u vk=%d", static_cast<unsigned long long>(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, mipLevel,
                      descriptor.depthOrLastArray, descriptor.baseArray, static_cast<int>(descriptor.dimension), static_cast<int>(descriptor.tileMode), descriptor.format, static_cast<int>(vkFormat));
         geometry = DescribeSurface(descriptor);
         mips = geometry.mips;

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

@@ -0,0 +1,69 @@
+#include "prx/libSceAgcDriver/Execution/include/AsyncLog.hpp"
+#include <iostream>
+#include <stdexcept>
+#include <string>
+
+namespace {
+
+void Check(bool condition, const char* message) {
+    if (!condition) throw std::runtime_error(message);
+}
+
+std::string ReadAll(std::FILE* file) {
+    std::fflush(file);
+    std::rewind(file);
+    std::string text;
+    char buffer[4096];
+    for (std::size_t read = 0; (read = std::fread(buffer, 1, sizeof(buffer), file)) != 0;) text.append(buffer, read);
+    return text;
+}
+
+void OrderPerThread() {
+    std::FILE* file = std::tmpfile();
+    Check(file != nullptr, "temporary file");
+    auto& log = AgcDriver::AsyncLog::Get();
+    std::string expected;
+    for (int i = 0; i < 2000; ++i) {
+        log.Defer(file, "deferred %d %s %llu\n", i, AgcDriver::LogLiteral{"literal"}, static_cast<unsigned long long>(i) * 3ull);
+        expected += "deferred " + std::to_string(i) + " literal " + std::to_string(static_cast<unsigned long long>(i) * 3ull) + "\n";
+        const std::string plain = "plain " + std::to_string(i) + "\n";
+        log.Write(file, plain.data(), plain.size());
+        expected += plain;
+    }
+    log.Flush();
+    Check(ReadAll(file) == expected, "deferred and written lines changed order or content");
+    std::fclose(file);
+}
+
+void LongLine() {
+    std::FILE* file = std::tmpfile();
+    Check(file != nullptr, "temporary file");
+    const std::string longText(3000, 'x');
+    AgcDriver::AsyncLog::Get().Defer(file, "%s|%d\n", AgcDriver::LogLiteral{longText.c_str()}, 7);
+    AgcDriver::AsyncLog::Get().Flush();
+    Check(ReadAll(file) == longText + "|7\n", "a line longer than the stack buffer changed");
+    std::fclose(file);
+}
+
+void Coalescing() {
+    auto& log = AgcDriver::AsyncLog::Get();
+    const std::string line = "[gpu] coalescing test line\n";
+    int printed = 0;
+    for (int i = 0; i < 50; ++i) printed += log.Admit(line) ? 1 : 0;
+    Check(printed == 3, "identical lines in one window were not limited to the first three");
+    Check(log.Admit("[gpu] another line\n"), "a different line was suppressed");
+}
+
+}
+
+int main() {
+    try {
+        OrderPerThread();
+        LongLine();
+        Coalescing();
+    } catch (const std::exception& error) {
+        std::cerr << error.what() << std::endl;
+        return 1;
+    }
+    return 0;
+}

core/libs/prx/libc/include/general/LogMacros.hpp

@@ -1,6 +1,7 @@
 #ifndef CORE_LIBS_PRX_LIBC_INCLUDE_GENERAL_LOGMACROS_HPP
 #define CORE_LIBS_PRX_LIBC_INCLUDE_GENERAL_LOGMACROS_HPP
 
+#include <atomic>
 #include <chrono>
 #include <cstdarg>
 #include <cstdio>
@@ -8,6 +9,25 @@
 #include <cstring>
 #include <string>
 
+using LogSinkFn = int (*)(std::FILE* stream, const char* text, std::size_t length);
+
+inline std::atomic<LogSinkFn>& LogSink() {
+    static std::atomic<LogSinkFn> sink{nullptr};
+    return sink;
+}
+
+inline long long LogTimestampMicros() {
+    static const bool timestamps = std::getenv("APS5_LOG_TIMESTAMPS") != nullptr;
+    if (!timestamps) return -1;
+    using Clock = std::chrono::steady_clock;
+    static const auto started = Clock::now();
+    return static_cast<long long>(std::chrono::duration_cast<std::chrono::microseconds>(Clock::now() - started).count());
+}
+
+inline int FormatLogTimestamp(char* out, std::size_t capacity, long long micros) {
+    return std::snprintf(out, capacity, "[+%llu.%06llu s] ", static_cast<unsigned long long>(micros / 1000000), static_cast<unsigned long long>(micros % 1000000));
+}
+
 #ifdef __MINGW_PRINTF_FORMAT
 [[gnu::format(__MINGW_PRINTF_FORMAT, 2, 3)]]
 #else
@@ -16,14 +36,9 @@
 inline int WriteLogLine(std::FILE* stream, const char* format, ...) {
     char small[1024];
     std::size_t prefixLength = 0;
-    static const bool timestamps = std::getenv("APS5_LOG_TIMESTAMPS") != nullptr;
-    if (timestamps) {
-        using Clock = std::chrono::steady_clock;
-        static const auto started = Clock::now();
-        const auto elapsed = std::chrono::duration_cast<std::chrono::microseconds>(Clock::now() - started).count();
-        const auto seconds = static_cast<unsigned long long>(elapsed / 1000000);
-        const auto microseconds = static_cast<unsigned long long>(elapsed % 1000000);
-        const int written = std::snprintf(small, sizeof(small), "[+%llu.%06llu s] ", seconds, microseconds);
+    const long long micros = LogTimestampMicros();
+    if (micros >= 0) {
+        const int written = FormatLogTimestamp(small, sizeof(small), micros);
         if (written < 0 || written >= static_cast<int>(sizeof(small))) return -1;
         prefixLength = static_cast<std::size_t>(written);
     }
@@ -43,7 +58,9 @@ inline int WriteLogLine(std::FILE* stream, const char* format, ...) {
     va_end(again);
     if (length < 0) return length;
     const auto totalLength = prefixLength + static_cast<std::size_t>(length);
-    std::fwrite(large.empty() ? small : large.data(), 1, totalLength, stream);
+    const char* text = large.empty() ? small : large.data();
+    if (const auto sink = LogSink().load(std::memory_order_acquire)) return sink(stream, text, totalLength);
+    std::fwrite(text, 1, totalLength, stream);
     return std::fflush(stream);
 }