diff --git a/core/libs/prx/libSceAgcDriver/CMakeLists.txt b/core/libs/prx/libSceAgcDriver/CMakeLists.txt index 8b7882fe14..d0578a01d4 100644 --- a/core/libs/prx/libSceAgcDriver/CMakeLists.txt +++ b/core/libs/prx/libSceAgcDriver/CMakeLists.txt @@ -348,6 +348,18 @@ 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) + 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:$") + 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..383e554f61 --- /dev/null +++ b/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 +#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 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 + 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); + 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::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)); + queued.fetch_add(1, std::memory_order_release); + 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; + } + 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& 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; + std::atomic queued{0}; + std::atomic finished{0}; + std::atomic abandoned{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 d186a3876d..1f03eea443 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" @@ -3840,7 +3841,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..0325795a41 --- /dev/null +++ b/core/libs/prx/libSceAgcDriver/tests/AsyncLog.cpp @@ -0,0 +1,337 @@ +#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 { + +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(stream), std::istreambuf_iterator()); +} + +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"); + 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"); +} + +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 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; +} 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/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); } diff --git a/core/libs/prx/libc/src/Process.cpp b/core/libs/prx/libc/src/Process.cpp index 78b4e6195e..08aab26c27 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] = ""; 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.