From ad85ed13ac67d9134b7ada42a68bf59fa3664646 Mon Sep 17 00:00:00 2001 From: AlxcBTW <187763517+AlxcBTW@users.noreply.github.com> Date: Thu, 15 Oct 2026 14:50:17 +0200 Subject: [PATCH 1/5] 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 | 11 + .../Execution/include/AsyncLog.hpp | 376 ++++++++++++++++++ .../Execution/src/Driver/Lifecycle.cpp | 4 + .../libSceAgcDriver/Graphics/src/Recorder.cpp | 3 +- .../libSceAgcDriver/Graphics/src/Texture.cpp | 13 +- .../prx/libSceAgcDriver/tests/AsyncLog.cpp | 69 ++++ .../prx/libc/include/general/LogMacros.hpp | 35 +- 7 files changed, 495 insertions(+), 16 deletions(-) create mode 100644 core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp create mode 100644 core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp diff --git a/core/libs/prx/libSceAgcDriver/CMakeLists.txt b/core/libs/prx/libSceAgcDriver/CMakeLists.txt index 251d38d6a1..d1caac1390 100644 --- a/core/libs/prx/libSceAgcDriver/CMakeLists.txt +++ b/core/libs/prx/libSceAgcDriver/CMakeLists.txt @@ -348,6 +348,17 @@ if(BUILD_TESTING) "PATH=path_list_prepend:$") 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:$") + 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) diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp new file mode 100644 index 0000000000..8834650ea2 --- /dev/null +++ b/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp @@ -0,0 +1,376 @@ +#pragma once + +#include "prx/libc/include/general/LogMacros.hpp" +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +namespace AgcDriver { + +struct LogLiteral { + const char* text; +}; + +namespace AsyncLogDetail { + +template +inline constexpr bool Deferrable = std::is_arithmetic_v || std::is_enum_v || std::is_same_v; + +inline const char* Unwrap(LogLiteral value) { + return value.text; +} + +template +T Unwrap(T value) { + return value; +} + +class Formatter { +public: + virtual ~Formatter() = default; + virtual void Format(std::string& out) const = 0; +}; + +template +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(size) < sizeof(small)) { + out.append(small, static_cast(size)); + return; + } + std::string large(static_cast(size) + 1, '\0'); + std::snprintf(large.data(), large.size(), format, Unwrap(value)...); + out.append(large.data(), static_cast(size)); + } + + const char* format; + std::tuple values; +}; + +struct Entry { + std::FILE* stream = nullptr; + long long micros = -1; + std::string text; + std::unique_ptr 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 + void Defer(std::FILE* stream, const char* format, TArgs... args) { + static_assert((AsyncLogDetail::Deferrable && ...), "deferred log arguments are numbers, enums or LogLiteral"); + const auto start = Clock::now(); + const auto micros = LogTimestampMicros(); + auto bound = std::make_unique>(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); + 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::chrono::duration_cast(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(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 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& 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 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(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(outLines + errLines), static_cast(outLines), static_cast(errLines), static_cast(written) / 1024.0, static_cast(coalesced), static_cast(caller) / 1e6, static_cast(caller) / 1e9 / seconds * 100.0, static_cast(logger) / 1e6, static_cast(high) / 1024.0); + if (size > 0) WriteNow(stderr, line, std::min(static_cast(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 pending; + std::size_t bytes = 0; + std::size_t peak = 0; + bool sleeping = false; + bool writing = false; + std::mutex coalesceMutex; + std::map windows; + Clock::time_point lastStats; + std::atomic stdoutLines{0}; + std::atomic stderrLines{0}; + std::atomic loggedBytes{0}; + std::atomic callerNanoseconds{0}; + std::atomic loggerNanoseconds{0}; + std::atomic coalescedTotal{0}; +}; + +inline void InstallAsyncLog_nid_no_patch() { + static_cast(AsyncLog::Get()); +} + +inline void FlushAsyncLog_nid_no_patch() { + AsyncLog::Get().Flush(); +} + +template +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(size) < sizeof(small) ? std::string(small, static_cast(size)) : std::string(static_cast(size), '\0'); + if (static_cast(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__) diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Lifecycle.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Lifecycle.cpp index 8fdd044922..6dc5164943 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/Driver/Lifecycle.cpp +++ b/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(GuestMemory::TrackerGeneration()); ShaderMemory::SetWaitedMsProvider(&Graphics::Recorder::ThreadWaitedMs); try { diff --git a/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp b/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp index b494d51ffe..921505763e 100644 --- a/core/libs/prx/libSceAgcDriver/Graphics/src/Recorder.cpp +++ b/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, 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()); } } } diff --git a/core/libs/prx/libSceAgcDriver/Graphics/src/Texture.cpp b/core/libs/prx/libSceAgcDriver/Graphics/src/Texture.cpp index e71366c10b..2523a53bbf 100644 --- a/core/libs/prx/libSceAgcDriver/Graphics/src/Texture.cpp +++ b/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(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(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, arrayLayers, static_cast(descriptor.dimension), static_cast(descriptor.tileMode), descriptor.format, static_cast(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(mip.tiledOffset), static_cast(mip.tiledSize), static_cast(mip.linearOffset), static_cast(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(mip.tiledOffset), static_cast(mip.tiledSize), static_cast(mip.linearOffset), static_cast(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& 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(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, copyLayers, source->Descriptor().format, static_cast(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(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, copyLayers, source->Descriptor().format, static_cast(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& 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(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, copyLayers, static_cast(colorFormat), static_cast(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(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, copyLayers, static_cast(colorFormat), static_cast(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& 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(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, static_cast(vkFormat)); + AGC_LOG_DEFERRED(stdout, "Texture address=0x%llx %ux%u mips=%u viewed from storage image (vk=%d)", static_cast(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, static_cast(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(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(descriptor.baseAddress), descriptor.width, descriptor.height, descriptor.mipCount, mipLevel, descriptor.depthOrLastArray, descriptor.baseArray, static_cast(descriptor.dimension), static_cast(descriptor.tileMode), descriptor.format, static_cast(vkFormat)); geometry = DescribeSurface(descriptor); mips = geometry.mips; diff --git a/core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp b/core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp new file mode 100644 index 0000000000..280ef53467 --- /dev/null +++ b/core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp @@ -0,0 +1,69 @@ +#include "prx/libSceAgcDriver/Execution/include/AsyncLog.hpp" +#include +#include +#include + +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(i) * 3ull); + expected += "deferred " + std::to_string(i) + " literal " + std::to_string(static_cast(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; +} diff --git a/core/libs/prx/libc/include/general/LogMacros.hpp b/core/libs/prx/libc/include/general/LogMacros.hpp index 46ba77734e..00e511b24b 100644 --- a/core/libs/prx/libc/include/general/LogMacros.hpp +++ b/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 #include #include #include @@ -8,6 +9,25 @@ #include #include +using LogSinkFn = int (*)(std::FILE* stream, const char* text, std::size_t length); + +inline std::atomic& LogSink() { + static std::atomic 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(std::chrono::duration_cast(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(micros / 1000000), static_cast(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(Clock::now() - started).count(); - const auto seconds = static_cast(elapsed / 1000000); - const auto microseconds = static_cast(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(sizeof(small))) return -1; prefixLength = static_cast(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(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); } From 4e264726035e33b477e13a7021c6bbfe26782734 Mon Sep 17 00:00:00 2001 From: AlxcBTW <187763517+AlxcBTW@users.noreply.github.com> Date: Thu, 15 Oct 2026 16:19:45 +0200 Subject: [PATCH 2/5] fix(agc): Flush waits until the logger has written every queued line --- core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp index 8834650ea2..a81897f807 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp +++ b/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp @@ -153,7 +153,7 @@ public: void Flush() { if (!asynchronous) return; std::unique_lock lock(mutex); - idle.wait_for(lock, std::chrono::seconds(2), [&] { return pending.empty() && !writing; }); + idle.wait(lock, [&] { return pending.empty() && !writing; }); } private: From 99ada24cc5fd94567af17ea1ec7d674cf4b7ac72 Mon Sep 17 00:00:00 2001 From: AlxcBTW <187763517+AlxcBTW@users.noreply.github.com> Date: Thu, 15 Oct 2026 20:41:45 +0200 Subject: [PATCH 3/5] test(agc): Flush waits for a held stream and a full queue blocks the caller Flush must not return while the logger still waits for a stream that another thread holds (the regression reported on the pull request: it gave up after two seconds), and a full queue must block its caller instead of dropping a line. AsyncLog::Capacity becomes public so the test sizes its load from it. --- .../Execution/include/AsyncLog.hpp | 3 +- .../prx/libSceAgcDriver/tests/AsyncLog.cpp | 148 ++++++++++++++++++ 2 files changed, 150 insertions(+), 1 deletion(-) diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp index a81897f807..0b135abd59 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp +++ b/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp @@ -86,6 +86,8 @@ 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; @@ -163,7 +165,6 @@ private: 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}; diff --git a/core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp b/core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp index 280ef53467..64edda20f0 100644 --- a/core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp +++ b/core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp @@ -1,10 +1,18 @@ #include "prx/libSceAgcDriver/Execution/include/AsyncLog.hpp" +#include +#include +#include +#include #include #include #include +#include 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); } @@ -18,6 +26,76 @@ std::string ReadAll(std::FILE* file) { return text; } +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 held{false}; + std::atomic releaseRequested{false}; + std::atomic 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"); @@ -54,13 +132,83 @@ void Coalescing() { 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 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 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); +} + } int main() { try { + ClearLogEnvironment(); OrderPerThread(); LongLine(); Coalescing(); + FlushWaitsForHeldStream(); + FullQueueBlocksCaller(); } catch (const std::exception& error) { std::cerr << error.what() << std::endl; return 1; From b82d688ed837ef03356678339ca53f51716809fd Mon Sep 17 00:00:00 2001 From: AlxcBTW <187763517+AlxcBTW@users.noreply.github.com> Date: Thu, 15 Oct 2026 20:41:59 +0200 Subject: [PATCH 4/5] fix(agc): flush the log queue, bounded, where the process ends without exit handlers Lines queued behind the logger were lost when the process ended through abort(), std::terminate, the Windows crash report or a guest _Exit, because only driver failure, Driver::stop and a normal exit flushed the queue. libc keeps one end flush (LibcSetEndFlush_nid_no_patch) and runs it from those paths. Its first registration chains a SIGABRT handler in front of the previous one, so every abort() and std::terminate in the process is covered, on Linux as well; with the default disposition the handler restores it and raises again, so raise(SIGABRT) still ends the process. Guest abort() and _Exit, and ReportCrash for the first fatal exception, run the flush directly. AsyncLog registers a bounded flush (FlushFor, 2 s) that polls two counters and takes no lock, so a dying process cannot hang on a blocked stream or on the queue lock; after its first timeout it returns at once. Flush counts queued and finished entries instead of watching the queue and the writer flag, so it waits for the lines queued before the call and not for a moment in which no thread is logging. agc_async_log_fatal runs the test executable as a child that queues lines behind a held stream and ends in abort(), std::terminate(), raise(SIGABRT) (POSIX) or an access violation (Windows), and once more with the stream never released. The lines of the first four must arrive in order, the last child must end after the bound, and every child has a watchdog. agc_async_log gains the bounded flush case. --- core/libs/prx/libSceAgcDriver/CMakeLists.txt | 5 +- .../Execution/include/AsyncLog.hpp | 32 ++++- .../prx/libSceAgcDriver/tests/AsyncLog.cpp | 122 +++++++++++++++++- core/libs/prx/libc/include/Shutdown.hpp | 2 + core/libs/prx/libc/src/Process.cpp | 35 +++++ .../src/specifics/windows/CrashReport.cpp | 2 + 6 files changed, 191 insertions(+), 7 deletions(-) diff --git a/core/libs/prx/libSceAgcDriver/CMakeLists.txt b/core/libs/prx/libSceAgcDriver/CMakeLists.txt index d1caac1390..29b578d311 100644 --- a/core/libs/prx/libSceAgcDriver/CMakeLists.txt +++ b/core/libs/prx/libSceAgcDriver/CMakeLists.txt @@ -353,9 +353,10 @@ if(BUILD_TESTING) 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) + 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 PROPERTIES ENVIRONMENT_MODIFICATION + set_tests_properties(agc_async_log agc_async_log_fatal PROPERTIES ENVIRONMENT_MODIFICATION "PATH=path_list_prepend:$") endif() diff --git a/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp b/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp index 0b135abd59..383e554f61 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp +++ b/core/libs/prx/libSceAgcDriver/Execution/include/AsyncLog.hpp @@ -1,5 +1,6 @@ #pragma once +#include "prx/libc/include/Shutdown.hpp" #include "prx/libc/include/general/LogMacros.hpp" #include #include @@ -155,7 +156,19 @@ public: void Flush() { if (!asynchronous) return; std::unique_lock lock(mutex); - idle.wait(lock, [&] { return pending.empty() && !writing; }); + 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: @@ -170,6 +183,7 @@ private: 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; @@ -180,6 +194,13 @@ private: 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) { @@ -217,6 +238,7 @@ private: 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; } @@ -234,11 +256,11 @@ private: sleeping = false; batch.swap(pending); bytes = 0; - writing = !batch.empty(); } space.notify_all(); if (!batch.empty()) { const auto start = Clock::now(); + const auto count = batch.size(); try { Drain(batch, buffer); } catch (...) { @@ -248,7 +270,7 @@ private: loggerNanoseconds.fetch_add(Elapsed(start), std::memory_order_relaxed); { std::lock_guard lock(mutex); - writing = false; + finished.fetch_add(count, std::memory_order_release); } idle.notify_all(); } @@ -339,7 +361,9 @@ private: std::size_t bytes = 0; std::size_t peak = 0; bool sleeping = false; - bool writing = false; + std::atomic queued{0}; + std::atomic finished{0}; + std::atomic abandoned{false}; std::mutex coalesceMutex; std::map windows; Clock::time_point lastStats; diff --git a/core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp b/core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp index 64edda20f0..0325795a41 100644 --- a/core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp +++ b/core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp @@ -1,12 +1,29 @@ #include "prx/libSceAgcDriver/Execution/include/AsyncLog.hpp" #include #include +#include #include #include +#include +#include +#include #include +#include #include #include +#include #include +#ifdef _WIN32 +#ifndef NOMINMAX +#define NOMINMAX +#endif +#ifndef WIN32_LEAN_AND_MEAN +#define WIN32_LEAN_AND_MEAN +#endif +#include +#else +#include +#endif namespace { @@ -26,6 +43,11 @@ std::string ReadAll(std::FILE* file) { return text; } +std::string ReadFile(const std::filesystem::path& path) { + std::ifstream stream(path, std::ios::binary); + return std::string(std::istreambuf_iterator(stream), std::istreambuf_iterator()); +} + void ClearLogEnvironment() { #ifdef _WIN32 _putenv("APS5_LOG_SYNC="); @@ -152,6 +174,22 @@ void FlushWaitsForHeldStream() { 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"); @@ -199,15 +237,97 @@ void FullQueueBlocksCaller() { 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(); } -int main() { +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; diff --git a/core/libs/prx/libc/include/Shutdown.hpp b/core/libs/prx/libc/include/Shutdown.hpp index 4bfe737f75..af9ae548d1 100644 --- a/core/libs/prx/libc/include/Shutdown.hpp +++ b/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 diff --git a/core/libs/prx/libc/src/Process.cpp b/core/libs/prx/libc/src/Process.cpp index d4bca7d3f2..8bf2797336 100644 --- a/core/libs/prx/libc/src/Process.cpp +++ b/core/libs/prx/libc/src/Process.cpp @@ -1,3 +1,4 @@ +#include #include #include #include @@ -98,6 +99,38 @@ extern "C" void LibcRunShutdown_nid_postfix() { namespace { +std::atomic 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(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(); diff --git a/core/libs/prx/libc/src/specifics/windows/CrashReport.cpp b/core/libs/prx/libc/src/specifics/windows/CrashReport.cpp index 6491da364c..13c9ee44ec 100644 --- a/core/libs/prx/libc/src/specifics/windows/CrashReport.cpp +++ b/core/libs/prx/libc/src/specifics/windows/CrashReport.cpp @@ -3,6 +3,7 @@ #include #include "prx/libc/include/CallTrace.hpp" #include "prx/libc/include/GuestArena.hpp" +#include "prx/libc/include/Shutdown.hpp" #include #include #include @@ -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] = ""; From e44ab157e05084528940b0546b0d713462042689 Mon Sep 17 00:00:00 2001 From: AlxcBTW <187763517+AlxcBTW@users.noreply.github.com> Date: Thu, 15 Oct 2026 20:41:59 +0200 Subject: [PATCH 5/5] docs: describe the log queue, its flush points and the stream order in ARCHITECTURE.md The logger thread, the bounded queue that blocks its caller, the LogSink hook, APS5_LOG_SYNC and APS5_LOG_STATS, where the queue is flushed and what stays outside it: direct fprintf(stderr) and printf calls are written at once, so they can appear before older queued lines. --- docs/dev/ARCHITECTURE.md | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) diff --git a/docs/dev/ARCHITECTURE.md b/docs/dev/ARCHITECTURE.md index 54b4476de1..0a9a669545 100644 --- a/docs/dev/ARCHITECTURE.md +++ b/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:
WriteLogLine,
AGC_LOG_DEFERRED"] --> queue["Queue, 16 MiB:
a full queue blocks the caller"] + queue --> logger["Logger thread:
format, join lines per stream,
fwrite and flush"] + logger --> streams["stdout, stderr"] + exits["Abort, terminate, crash report,
_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.