Repository navigation
perf(agc): format and write steady-state log lines off the queue worker - #6371
Conversation
|
Evidence from the two cave rows (Sword of the Sea PPSA25344, HD output, console settings, RTX 5070 Laptop, Windows 11), as promised in the description. Before (main 8856f18 + lab commits, row After (same base + this change, row Worker-0 sampling profile before the change (symbolized, inclusive): |
|
Other open pull requests touch the same code. Merging one will break the other, or both implement the same thing. If this one builds on them, list them in Depends on.
Some comparisons could not be completed because a pull request conflicts with the base branch. Review these shared files manually before concluding that there is no overlap.
|
|
Independent Windows validation of head 610c7e4 (AI-assisted). I compiled the actual AsyncLog.hpp and LogMacros.hpp and ran your existing tests/AsyncLog.cpp standalone with WinLibs GCC 15.2 r7 UCRT, -std=c++20 -O2 -DNDEBUG -static -pthread -Wall -Wextra. The author test passes both asynchronously and with APS5_LOG_SYNC=1, with timestamps unset. I also reproduced an incomplete Flush: idle.wait_for returns after two seconds even when writing is still true, and the void API gives its caller no indication that the logger is still using the stream. That means Flush at exit does not guarantee queued output has finished; a client that closes its FILE after Flush may also race the logger. The attached native regression holds a real UCRT FILE lock on another thread for 2400 ms, enqueues one deferred line and calls Flush. On two runs the original returns before the stream is released (2011/2021 ms). It then releases the lock and drains before closing, so the probe does not intentionally access a closed FILE. A one-line candidate replacing idle.wait_for(lock, 2s, predicate) with idle.wait(lock, predicate) passes the same regression (2416/2399 ms, after release, correct line content). Your existing test also passes with that candidate in both async and sync modes. The patch passes git apply --check against the recorded header. There is a shutdown-policy tradeoff: this candidate waits for completion, so permanently blocked output can hold shutdown indefinitely. If a two-second shutdown budget is intentional, an explicit timeout result plus managed worker/stream lifetime would be needed instead. I am sharing this as a review candidate, not claiming that unbounded shutdown is the desired policy. Bundle: source, original/fixed headers, one-line patch, reproduction commands and raw results. No full emulator build, registered CTest run, GPU/title/FPS/performance measurement or Linux/macOS validation; no push to your branch. |
|
Thanks for the independent validation and the regression. Head 103337a takes your candidate: |
adriadam10
left a comment
adriadam10
left a comment
There was a problem hiding this comment.
Checked the head merged onto current main: it builds, agc_async_log passes, and the only other ctest failures are agc_driver_tessellation (SEGFAULT on main too) and agc_driver_store_over_untracked (passes on rerun, load flake). Points to address:
- Lines queued before a crash are lost. Only
PrintFailureandDriver::stopcallFlushAsyncLog_nid_no_patch(Lifecycle.cpp:42,:124). The fatal paths never drain the queue:CrashReport.cpp(abort/fast-fail/hang dump,:510-548),std::terminateinVulkanDevice.cpp:187,std::abortinGuestBufferMemory.cpp:2820. Those are the lines a crash report needs most. Drain the queue (bounded, since the process is dying) from those paths, or write them through the synchronous path, and add a test that exits throughabort()/terminatewith lines queued. - Ordering across streams. Only
WriteLogLine-based stdout lines go through the sink; directfprintf(stderr, ...)/printfcalls in the driver (~500) are written synchronously, so stdout and stderr no longer interleave in call order. State this in the PR or make the sink cover them. docs/dev/ARCHITECTURE.mdneeds a short section for the new logger thread, the bounded queue (blocks the caller when full), theLogSinkhook andAPS5_LOG_SYNC/APS5_LOG_STATS, under the diagram it changes.- Tests:
tests/AsyncLog.cppdoes not coverFlushwaiting for a held stream (the regression simonbronk posted), nor a full queue blocking the caller. Both are cheap to add. - Not verified here: Windows/MinGW behaviour (the
windowsjob is skipped on PR CI), Linux, any title. No FPS change is claimed, so the benefit is lower CPU and 96 MB less output; please keep the PR description to that.
Happy to re-review once these are in.
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).
…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.
…t 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.
…n 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.
103337a to
e44ab15
Compare
|
@adriadam10 Rebased onto 1. Lines queued before a crash One bounded flush, run from the paths that end the process without the exit handlers.
Test: Known limits:
2. Order across streams Not made to cover them. 3. New section "Log output" after the Graphics section: a four-node diagram, the logger thread and the 16 MiB queue that blocks its caller, 4. Tests (
5. Description Edited to the CPU time of the queue worker and the 96 MB of output, with no frame-rate claim. It also states point 2 and the new tests. Run where
Not run: the rest of ctest (your run of the previous head names |
adriadam10
left a comment
adriadam10
left a comment
There was a problem hiding this comment.
Re-checked the new head merged onto current main: it builds, agc_async_log and agc_async_log_fatal pass. All points from the last review are addressed: the bounded end flush on abort/terminate/crash report/_Exit with a test that ends through each path, the stream-order note, the "Log output" section in docs/dev/ARCHITECTURE.md, and tests for Flush on a held stream and a full queue. Windows/MinGW behaviour and the title measurement rest on your fork runs; merging once the full Build is green.
On Windows the atexit handlers of a DLL run after the process has ended its other threads, so the logger thread can be gone with lines still queued and the unbounded Flush waits forever (guest_shader_link timed out on 4 of the last 7 completed main builds since #6371). Run the bounded FlushAtEnd there instead. Co-Authored-By: Claude <noreply@anthropic.com>
3 participants
What
Texture creation logs one stdout line per texture and mip (
Texture address=...) throughWriteLogLine, which formats with the MinGW printf and flushes every line on the calling thread, here the AGC queue worker. In Sword of the Sea (PPSA25344) cave gameplay, queue worker 0 spent 10-17 % of its samples in__mingw_pformat/WriteLogLine, and stdout held 575,778Texture address=lines (96 MB) per 1500 s row.The benefit is less CPU time on the queue worker and 96 MB less output. No frame-rate change is claimed.
AsyncLogkeeps a bounded queue and a logger thread.AGC_LOG_DEFERREDcaptures numeric arguments on the caller and formats them on the logger thread.WriteLogLinehands finished lines to a per-moduleLogSinkinlibc/LogMacros.hppthatAgcDriverinstalls. Lines that go through it keep their call order across stdout and stderr and are written with one flush per batch.Flushwaits, without a limit, until every line queued before the call is written: on driver failure, inDriver::stopand at exit.APS5_LOG_SYNC=1restores the synchronous path.abort()andstd::terminate(libc chains aSIGABRThandler in front of the previous one whenAsyncLogregisters, so everyabortsite is covered, on Linux too;raise(SIGABRT)still ends the process), guestabort(), the Windows crash report of a fatal exception, and guest_Exit. The flush polls two counters and takes no lock, so a stuck stream or a thread that died holding the queue lock cannot hang a dying process, and after its first timeout later calls return at once.AsyncLogregisters it withLibcSetEndFlush_nid_no_patch. A title that installs its ownSIGABRTdisposition through libkernel replaces the handler, as it replaces the crash report's.libSceAgcDriverhas about 220 directfprintf(stderr, ...)calls and onefputs(115APS5_LOG_*sites go through the sink). They are written at once on the calling thread, so for those lines stdout and stderr no longer interleave in call order: a direct stderr line can appear before older queued stdout lines.APS5_LOG_SYNC=1keeps one order for everything. Stated indocs/dev/ARCHITECTURE.md.deferred write-back failednotes print three times per 10 s, then are counted into onerepeated N more timesline.[log] 10 sline reports lines, bytes, caller time and logger time (APS5_LOG_STATS=0hides it).docs/dev/ARCHITECTURE.md, section "Log output": the logger thread, the bounded queue, theLogSinkhook,APS5_LOG_SYNCandAPS5_LOG_STATS, the flush points and the stream order.Tested
Windows 11, MinGW-w64 GCC 15.2, NVIDIA RTX 3060 / 5070 lab machines for the title row. Rebased onto
origin/main44df21632.agc_async_log(3.05 s) andagc_async_log_fatal(2.88 s) pass, with the guest exit tests (guest_exit_order,guest_system_exit,guest_quick_exit,guest_immediate_exit,guest_return_from_main,guest_system_relaunch,guest_nested_exit) as a regression check on the_Exitchange: https://github.com/AlxcBTW/AnyPS5/actions/runs/38787857401. Each of the two tests also passes 45 times (three ctest loops of 15 repeats running at once).libc.dll), fork CI:agc_async_log(3.19 s) andagc_async_log_fatal(2.86 s) pass, including the child that ends in an access violation through the crash report: https://github.com/AlxcBTW/AnyPS5/actions/runs/38787867338. Each also passes 30 times (three loops of 10 repeats at once).libsandrelinkertargets compile on the fork CI: https://github.com/AlxcBTW/AnyPS5/actions/runs/38787881151.tools/check_conventions.py --base origin/mainpasses.agc_async_log: order of deferred and written lines, long lines, the repeat limit,Flushwaiting for a stream another thread holds (2.4 s, longer than the 2 s timeout of the earlier head), a bounded flush that gives up and then succeeds, a full queue blocking its caller.agc_async_log_fatal: a child queues 100 lines behind a held stream and ends inabort(), instd::terminate(), inraise(SIGABRT)(Linux) or in an access violation (Windows); every line must arrive in order. A last child never releases the stream and must end after the 2 s bound with an empty file.Flushtimeout of the earlier head, a queue that does not block, no flush in the abort handler, no flush inReportCrash, noSIGABRThandler, a 0 ms limit, an unbounded wait (the blocked child then hangs). These were run in a standalone build of the test on Windows against the realCrashReport.cpp. On Linux (fork CI), removing the re-raise fails theraisechild (https://github.com/AlxcBTW/AnyPS5/actions/runs/38789705108) and removing the flush from the abort handler fails theabortchild (https://github.com/AlxcBTW/AnyPS5/actions/runs/38790140072).__mingw_pformat/WriteLogLine, and a 1500 s row wrote 575,778Texture address=lines (96 MB). After, 131 lines per 10 s and 0.006 % of worker time ([log]counter). Logs:hdcave-s10-20261015-*/stderr.log, attached as a comment. This row ran on the first head of this PR. The commits added since then are the end flush, two counters in place of the writer flag, tests and docs; the row was not repeated.Checklist
main; no other open PR implements the same functionsNotImplemented_nid_no_patch); silent stubs are listed under Silent stubs in their library's technical debt file.mdfiles or images added to the repository (attach them to this PR)