chore(agc): merge current main for pending identity test

core/libs/prx/libSceAgcDriver/CMakeLists.txt

@@ -348,6 +348,18 @@ 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)
+    add_test(NAME agc_async_log_fatal COMMAND agc_async_log_tests fatal)
+    set_tests_properties(agc_async_log agc_async_log_fatal PROPERTIES TIMEOUT 20)
+    if(WIN32)
+        set_tests_properties(agc_async_log agc_async_log_fatal 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,401 @@
+#pragma once
+
+#include "prx/libc/include/Shutdown.hpp"
+#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 constexpr std::size_t Capacity = 16u * 1024u * 1024u;
+
+    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);
+        const auto target = queued.load(std::memory_order_relaxed);
+        idle.wait(lock, [&] { return finished.load(std::memory_order_relaxed) >= target; });
+    }
+
+    bool FlushFor(std::chrono::milliseconds limit) {
+        if (!asynchronous) return true;
+        const auto target = queued.load(std::memory_order_acquire);
+        const auto deadline = Clock::now() + limit;
+        while (finished.load(std::memory_order_acquire) < target) {
+            if (Clock::now() >= deadline) return false;
+            std::this_thread::sleep_for(std::chrono::milliseconds(1));
+        }
+        return true;
+    }
+
+private:
+    struct Window {
+        Clock::time_point first;
+        std::uint64_t seen;
+        std::uint64_t suppressed;
+    };
+
+    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};
+    static constexpr std::chrono::milliseconds EndFlushLimit{2000};
+
+    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();
+        LibcSetEndFlush_nid_no_patch(&AsyncLog::FlushAtEnd);
+    }
+
+    static void FlushAtEnd() {
+        auto& log = Get();
+        if (log.abandoned.load(std::memory_order_acquire)) return;
+        if (!log.FlushFor(EndFlushLimit)) log.abandoned.store(true, std::memory_order_release);
+    }
+
+    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));
+            queued.fetch_add(1, std::memory_order_release);
+            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;
+            }
+            space.notify_all();
+            if (!batch.empty()) {
+                const auto start = Clock::now();
+                const auto count = batch.size();
+                try {
+                    Drain(batch, buffer);
+                } catch (...) {
+                    buffer.clear();
+                }
+                batch.clear();
+                loggerNanoseconds.fetch_add(Elapsed(start), std::memory_order_relaxed);
+                {
+                    std::lock_guard lock(mutex);
+                    finished.fetch_add(count, std::memory_order_release);
+                }
+                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;
+    std::atomic<std::uint64_t> queued{0};
+    std::atomic<std::uint64_t> finished{0};
+    std::atomic<bool> abandoned{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"
@@ -3840,7 +3841,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,337 @@
+#include "prx/libSceAgcDriver/Execution/include/AsyncLog.hpp"
+#include <atomic>
+#include <chrono>
+#include <csignal>
+#include <cstdio>
+#include <cstdlib>
+#include <cstring>
+#include <filesystem>
+#include <fstream>
+#include <iostream>
+#include <iterator>
+#include <stdexcept>
+#include <string>
+#include <system_error>
+#include <thread>
+#ifdef _WIN32
+#ifndef NOMINMAX
+#define NOMINMAX
+#endif
+#ifndef WIN32_LEAN_AND_MEAN
+#define WIN32_LEAN_AND_MEAN
+#endif
+#include <windows.h>
+#else
+#include <sys/resource.h>
+#endif
+
+namespace {
+
+using namespace std::chrono_literals;
+using Clock = AgcDriver::AsyncLog::Clock;
+
+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;
+}
+
+std::string ReadFile(const std::filesystem::path& path) {
+    std::ifstream stream(path, std::ios::binary);
+    return std::string(std::istreambuf_iterator<char>(stream), std::istreambuf_iterator<char>());
+}
+
+void ClearLogEnvironment() {
+#ifdef _WIN32
+    _putenv("APS5_LOG_SYNC=");
+    _putenv("APS5_LOG_TIMESTAMPS=");
+#else
+    unsetenv("APS5_LOG_SYNC");
+    unsetenv("APS5_LOG_TIMESTAMPS");
+#endif
+}
+
+void LockStream(std::FILE* file) {
+#ifdef _WIN32
+    _lock_file(file);
+#else
+    flockfile(file);
+#endif
+}
+
+void UnlockStream(std::FILE* file) {
+#ifdef _WIN32
+    _unlock_file(file);
+#else
+    funlockfile(file);
+#endif
+}
+
+class HeldStream {
+public:
+    explicit HeldStream(std::FILE* file) : file(file) {
+        holder = std::thread([this] {
+            LockStream(this->file);
+            held.store(true);
+            while (!releaseRequested.load()) std::this_thread::sleep_for(1ms);
+            released.store(true);
+            UnlockStream(this->file);
+        });
+        while (!held.load()) std::this_thread::sleep_for(1ms);
+    }
+
+    HeldStream(const HeldStream&) = delete;
+    HeldStream& operator=(const HeldStream&) = delete;
+
+    ~HeldStream() {
+        Release();
+        holder.join();
+    }
+
+    void Release() {
+        releaseRequested.store(true);
+    }
+
+    bool Released() const {
+        return released.load();
+    }
+
+private:
+    std::FILE* file;
+    std::atomic<bool> held{false};
+    std::atomic<bool> releaseRequested{false};
+    std::atomic<bool> released{false};
+    std::thread holder;
+};
+
+std::string LargeLine(std::size_t index, std::size_t bytes) {
+    std::string line = "large " + std::to_string(index) + " ";
+    line.resize(bytes - 1, 'x');
+    line += '\n';
+    return line;
+}
+
+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");
+}
+
+void FlushWaitsForHeldStream() {
+    std::FILE* file = std::tmpfile();
+    Check(file != nullptr, "temporary file");
+    auto& log = AgcDriver::AsyncLog::Get();
+    {
+        HeldStream held(file);
+        log.Defer(file, "held %d %s\n", 7, AgcDriver::LogLiteral{"line"});
+        std::thread releaser([&] {
+            std::this_thread::sleep_for(2400ms);
+            held.Release();
+        });
+        log.Flush();
+        const bool waited = held.Released();
+        releaser.join();
+        Check(waited, "Flush returned while the logger still waited for the stream");
+    }
+    Check(ReadAll(file) == "held 7 line\n", "the line queued behind a held stream changed");
+    std::fclose(file);
+}
+
+void BoundedFlushGivesUp() {
+    std::FILE* file = std::tmpfile();
+    Check(file != nullptr, "temporary file");
+    auto& log = AgcDriver::AsyncLog::Get();
+    Check(log.FlushFor(0ms), "FlushFor waited with nothing queued");
+    {
+        HeldStream held(file);
+        log.Defer(file, "bounded %d\n", 1);
+        Check(!log.FlushFor(100ms), "FlushFor reported a line written while its stream was held");
+        held.Release();
+        Check(log.FlushFor(10s), "FlushFor missed the line written after the stream was released");
+    }
+    Check(ReadAll(file) == "bounded 1\n", "the line queued behind a held stream changed");
+    std::fclose(file);
+}
+
+void FullQueueBlocksCaller() {
+    std::FILE* file = std::tmpfile();
+    Check(file != nullptr, "temporary file");
+    auto& log = AgcDriver::AsyncLog::Get();
+    constexpr std::size_t lineBytes = 1024 * 1024;
+    constexpr std::size_t lines = 2 * AgcDriver::AsyncLog::Capacity / lineBytes + 4;
+    constexpr std::size_t filled = AgcDriver::AsyncLog::Capacity / lineBytes / 2;
+    std::atomic<std::size_t> queued{0};
+    bool blocked = false;
+    {
+        HeldStream held(file);
+        std::thread producer([&] {
+            for (std::size_t i = 0; i < lines; ++i) {
+                const std::string line = LargeLine(i, lineBytes);
+                log.Write(file, line.data(), line.size());
+                queued.store(i + 1);
+            }
+        });
+        auto last = queued.load();
+        auto changedAt = Clock::now();
+        const auto deadline = changedAt + 10s;
+        while (last < lines && Clock::now() < deadline && (last < filled || Clock::now() - changedAt < 500ms)) {
+            std::this_thread::sleep_for(5ms);
+            const auto now = queued.load();
+            if (now != last) {
+                last = now;
+                changedAt = Clock::now();
+            }
+        }
+        blocked = last >= filled && last < lines && Clock::now() - changedAt >= 500ms;
+        held.Release();
+        producer.join();
+    }
+    Check(blocked, "the caller was not blocked by a full queue");
+    log.Flush();
+    std::fflush(file);
+    std::rewind(file);
+    std::string line;
+    for (std::size_t i = 0; i < lines; ++i) {
+        const std::string expected = LargeLine(i, lineBytes);
+        line.resize(expected.size());
+        Check(std::fread(line.data(), 1, line.size(), file) == line.size() && line == expected, "a line written through a full queue changed or went missing");
+    }
+    Check(std::fgetc(file) == EOF, "a full queue wrote extra output");
+    std::fclose(file);
+}
+
+constexpr int ChildLines = 50;
+
+[[noreturn]] void EndChild(const std::string& mode, const char* output) {
+    std::FILE* file = std::fopen(output, "wb");
+    Check(file != nullptr, "child output file");
+#ifdef _WIN32
+    SetErrorMode(SEM_FAILCRITICALERRORS | SEM_NOGPFAULTERRORBOX);
+    _set_abort_behavior(0, _WRITE_ABORT_MSG | _CALL_REPORTFAULT);
+#else
+    const rlimit noCore{0, 0};
+    setrlimit(RLIMIT_CORE, &noCore);
+#endif
+    std::thread([] {
+        std::this_thread::sleep_for(8s);
+        std::_Exit(99);
+    }).detach();
+    AgcDriver::InstallAsyncLog_nid_no_patch();
+    auto& log = AgcDriver::AsyncLog::Get();
+    HeldStream held(file);
+    for (int i = 0; i < ChildLines; ++i) {
+        log.Defer(file, "deferred %d\n", i);
+        WriteLogLine(file, "plain %d\n", i);
+    }
+    std::thread releaser([&] {
+        std::this_thread::sleep_for(100ms);
+        if (mode != "blocked") held.Release();
+    });
+    if (mode == "terminate") std::terminate();
+#ifdef _WIN32
+    if (mode == "fault") RaiseException(EXCEPTION_ACCESS_VIOLATION, EXCEPTION_NONCONTINUABLE, 0, nullptr);
+#else
+    if (mode == "raise") {
+        std::raise(SIGABRT);
+        std::_Exit(0);
+    }
+#endif
+    std::abort();
+}
+
+std::string Quote(const std::string& text) {
+    return "\"" + text + "\"";
+}
+
+void LinesSurviveEnd(const std::string& self, const std::string& mode) {
+    const auto output = std::filesystem::temp_directory_path() / ("aps5-async-log-" + mode + "-" + std::to_string(Clock::now().time_since_epoch().count()) + ".txt");
+    std::string command = Quote(self) + " child " + mode + " " + Quote(output.string());
+#ifdef _WIN32
+    command = Quote(command);
+#endif
+    const auto start = Clock::now();
+    const int status = std::system(command.c_str());
+    const auto lived = Clock::now() - start;
+    std::error_code error;
+    const bool started = std::filesystem::exists(output, error);
+    const std::string text = started ? ReadFile(output) : std::string();
+    std::filesystem::remove(output, error);
+    Check(started, "the child did not start");
+    Check(status != 0, "the child did not end abnormally");
+    Check(lived < 6s, "the child took too long to end");
+    if (mode == "blocked") {
+        Check(lived >= 1900ms, "the child ended before the flush gave up");
+        Check(text.empty(), "the child wrote through a held stream");
+        return;
+    }
+    std::string expected;
+    for (int i = 0; i < ChildLines; ++i) expected += "deferred " + std::to_string(i) + "\nplain " + std::to_string(i) + "\n";
+    Check(text == expected, "lines queued before the process ended were lost or changed");
+}
+
+}
+
+int main(int argc, char** argv) {
+    try {
+        ClearLogEnvironment();
+        if (argc == 4 && std::strcmp(argv[1], "child") == 0) EndChild(argv[2], argv[3]);
+        if (argc == 2 && std::strcmp(argv[1], "fatal") == 0) {
+            LinesSurviveEnd(argv[0], "abort");
+            LinesSurviveEnd(argv[0], "terminate");
+#ifdef _WIN32
+            LinesSurviveEnd(argv[0], "fault");
+#else
+            LinesSurviveEnd(argv[0], "raise");
+#endif
+            LinesSurviveEnd(argv[0], "blocked");
+            return 0;
+        }
+        OrderPerThread();
+        LongLine();
+        Coalescing();
+        FlushWaitsForHeldStream();
+        BoundedFlushGivesUp();
+        FullQueueBlocksCaller();
+    } catch (const std::exception& error) {
+        std::cerr << error.what() << std::endl;
+        return 1;
+    }
+    return 0;
+}

core/libs/prx/libc/include/Shutdown.hpp

@@ -14,5 +14,7 @@ extern "C" [[noreturn]] void LibcAwaitExit_nid_postfix();
 extern "C" [[noreturn]] void LibcExit_nid_no_patch(int code);
 extern "C" [[noreturn]] void LibcExitWithoutHandlers_nid_no_patch(int code);
 extern "C" [[noreturn]] void LibcTerminate_nid_no_patch(int code);
+extern "C" void LibcSetEndFlush_nid_no_patch(void (*flush)());
+extern "C" void LibcRunEndFlush_nid_no_patch();
 
 #endif

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

core/libs/prx/libc/src/Process.cpp

@@ -1,3 +1,4 @@
+#include <csignal>
 #include <cstdint>
 #include <cstdio>
 #include <cstdlib>
@@ -98,6 +99,38 @@ extern "C" void LibcRunShutdown_nid_postfix() {
 
 namespace {
 
+std::atomic<void (*)()> endFlush{nullptr};
+void (*previousAbortHandler)(int) = SIG_DFL;
+
+void FlushOnAbort(int number) {
+    LibcRunEndFlush_nid_no_patch();
+    if (previousAbortHandler == SIG_IGN) return;
+    if (previousAbortHandler != SIG_DFL && previousAbortHandler != SIG_ERR) {
+        previousAbortHandler(number);
+        return;
+    }
+#ifndef _WIN32
+    std::signal(number, SIG_DFL);
+    std::raise(number);
+#endif
+}
+
+}
+
+extern "C" void LibcSetEndFlush_nid_no_patch(void (*flush)()) {
+    if (flush == nullptr) throw std::runtime_error("libc: invalid end flush registration");
+    void (*registered)() = nullptr;
+    if (!endFlush.compare_exchange_strong(registered, flush) && registered != flush) throw std::runtime_error("libc: end flush already registered");
+    static std::once_flag installed;
+    std::call_once(installed, [] { previousAbortHandler = std::signal(SIGABRT, FlushOnAbort); });
+}
+
+extern "C" void LibcRunEndFlush_nid_no_patch() {
+    if (const auto flush = endFlush.load(std::memory_order_acquire)) flush();
+}
+
+namespace {
+
 void StartExit() {
     exitRequested.store(true);
     if (exitStarted.exchange(true)) {
@@ -122,6 +155,7 @@ extern "C" {
 }
 
 [[noreturn]] void LibcTerminate_nid_no_patch(int code) {
+    LibcRunEndFlush_nid_no_patch();
 #ifdef _WIN32
     TerminateProcess(GetCurrentProcess(), static_cast<UINT>(code));
 #endif
@@ -159,6 +193,7 @@ void APS5_VABI exit_nid_postfix(int code) {
 ) {
     (void)arg0; (void)arg1; (void)arg2;
     (void)arg3; (void)arg4; (void)arg5;
+    LibcRunEndFlush_nid_no_patch();
     std::fprintf(stderr, "[libc] abort() called from %p\n", __builtin_return_address(0));
     std::fflush(nullptr);
     std::abort();

core/libs/prx/libc/src/specifics/windows/CrashReport.cpp

@@ -3,6 +3,7 @@
 #include <tlhelp32.h>
 #include "prx/libc/include/CallTrace.hpp"
 #include "prx/libc/include/GuestArena.hpp"
+#include "prx/libc/include/Shutdown.hpp"
 #include <algorithm>
 #include <atomic>
 #include <chrono>
@@ -304,6 +305,7 @@ LONG WINAPI ReportCrash(EXCEPTION_POINTERS* info) {
         // Another thread is already reporting; let it finish before this fault ends the process.
         Sleep(INFINITE);
     }
+    LibcRunEndFlush_nid_no_patch();
     const auto* context = info->ContextRecord;
     char line[MAX_PATH + 64];
     char threadName[128] = "";

docs/dev/ARCHITECTURE.md

@@ -109,6 +109,25 @@ flowchart LR
 - Guest memory reaches the GPU through host imports (`VK_EXT_external_memory_host`) where the driver accepts them, and through copies otherwise ([`GuestBufferMemory.cpp`](../../core/libs/prx/libSceAgcDriver/Graphics/src/GuestBufferMemory.cpp)). A registered range larger than the import window (64 MiB) is imported per window for buffer and fill accesses and whole for an address-based build. Live imports stay under a budget, with the least recently used import retired first (see TechnicalDebt, Host import windows and budget).
 - On Windows, a host import of private `MEM_WRITE_WATCH` memory (singly mapped direct memory) stays on `GetWriteWatch` when `ProbeImportWriteProtection` shows the driver reports nothing written after the second GPU read and a GPU write, and a CPU store is collected (`decideImportWatch`). The driver marks every page of such an import written, asynchronously, until its first GPU use completes, so `settleImport` in [`GuestBufferMemory.cpp`](../../core/libs/prx/libSceAgcDriver/Graphics/src/GuestBufferMemory.cpp) copies 4 bytes out of the new import on a second queue of the graphics family, or on a queue of another copy-capable family when the graphics family has only one (`Context::settleQueue`, own pool and mutex) inside `ImportWatched`'s window and waits for it, only for imports of 1 MiB or more (a smaller import is compared, so a title that maps, imports and unmaps a small buffer around every submission does not block its mapping thread); the main queue can't be used there because `importAllocation` holds the imports lock and `GpuMutex` comes before it in the lock order. Imports through a section alias keep tracking on the guest views, and every other Windows host import is compared. A device without such a queue keeps the comparisons.
 
+### Log output
+
+```mermaid
+flowchart LR
+    callers["Any thread:<br/>WriteLogLine,<br/>AGC_LOG_DEFERRED"] --> queue["Queue, 16 MiB:<br/>a full queue blocks the caller"]
+    queue --> logger["Logger thread:<br/>format, join lines per stream,<br/>fwrite and flush"]
+    logger --> streams["stdout, stderr"]
+    exits["Abort, terminate, crash report,<br/>_Exit"] -- "bounded flush, 2 s" --> queue
+```
+
+`WriteLogLine` ([`LogMacros.hpp`](../../core/libs/prx/libc/include/general/LogMacros.hpp), behind `APS5_LOG_OUT` and `APS5_LOG_ERR`) formats a line on the calling thread and hands it to the module's `LogSink()` when one is installed; without a sink it writes and flushes it there. `Driver` installs [`AsyncLog`](../../core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp) as the sink of `libSceAgcDriver`, so the queue workers no longer wait for the console or the log file for those lines. `APS5_LOG_SYNC` (any value) skips the installation and restores the synchronous path.
+
+- **Queue.** One logger thread drains a queue that holds at most 16 MiB of waiting lines; the batch the logger is writing comes on top. A caller that finds the queue full blocks until the logger has taken the pending batch, so no line is dropped. The logger writes entries in queue order and joins consecutive entries of one stream; it writes them with one `fwrite` and flush when the text reaches 64 KiB, the stream changes or the batch ends. `AGC_LOG_DEFERRED` queues the format string with numeric, enum and `LogLiteral` arguments and formats them on the logger thread; `APS5_LOG_TIMESTAMPS` stamps a line when it is queued.
+- **Order.** Lines that pass through the sink, on stdout and stderr alike, appear in call order. A direct `fprintf(stderr, ...)` or `printf` does not pass through it and is written at once, so it can appear before older queued lines; the coalesced `deferred write-back failed` notes are of this kind. `APS5_LOG_SYNC=1` keeps one order for all of them.
+- **Flush.** `Flush` waits without a limit until every line queued before the call has been written, including while another thread holds the stream. It runs when the driver fails, in `Driver::stop` and at exit. `AsyncLog` also registers a bounded flush (`FlushFor`, 2 s) with `LibcSetEndFlush_nid_no_patch`; libc runs it where the process ends without those: `abort()` and `std::terminate` (a `SIGABRT` handler that the first registration chains in front of the previous one, so `raise(SIGABRT)` still ends the process), guest `abort()`, the Windows crash report of a fatal exception and guest `_Exit`. A title that installs its own `SIGABRT` disposition replaces that handler. The bounded flush polls two counters and takes no lock, so a thread that dies holding the queue lock or a stream cannot stall it. After 2 s it gives up, later calls return at once, and the lines still queued are lost.
+- **Statistics.** A `[log]` line every 10 s in which lines were logged reports lines, bytes, the time spent by the callers and by the logger, and the queue peak; `APS5_LOG_STATS=0` hides it. Identical `deferred write-back failed` notes print three times per 10 s and are then counted in one `repeated N more times` line.
+
+`agc_async_log` checks the order of deferred and written lines, long lines, the repeat limit, a `Flush` that waits for a held stream, a bounded flush that gives up, and a full queue that blocks its caller. `agc_async_log_fatal` starts the test executable as a child that queues lines behind a held stream and then calls `abort()`, calls `std::terminate()`, raises an access violation (Windows) or `SIGABRT` (elsewhere), or aborts without ever releasing the stream; the first four must leave every line in the file in order, the last must still end after the bound.
+
 ### Runtime image and sampler tables
 
 A T# or S# that a shader loads from a buffer at a runtime offset (`key * stride + addend`, or `(key << n) & mask`) is not a direct descriptor. [`ResourceTracker.cpp`](../../core/shader/recompiler/Optimization/src/ResourceTracker.cpp) plans it as a table column (`TableColumn`): the heap V#'s descriptor source, the record stride and addend, the descriptor's offset in the record, and the key domains that may narrow it. Accesses with the same heap and record shape share one column. The shader keeps computing the offset and indexes a table binding: images use one variable-count `SAMPLED_IMAGE` array (`RuntimeAbi::ImageTableBinding`, in the fragment set when pipeline libraries split the sets), samplers a `SAMPLER` array (`Binding::SamplerTable`). Devices without `runtimeDescriptorArray`, `descriptorBindingPartiallyBound` and `descriptorBindingVariableDescriptorCount` refuse such shaders.