perf(host): write the log in batches, a few writes a second instead of one per line #1675

Merged

DUDUYG merged 3 commits from perf/log-batch into main

2026-11-10 17:17:06 +00:00

DUDUYG commented

2026-11-10 13:02:59 +00:00

(Migrated from github.com)

The problem

stderr is unbuffered (hos_main.c), so every line the log writer takes is a write of its own. In play that is 30–90 writes a second, each one extending hookshot_log.txt in the game folder.

With the game on a slow disk (a SATA SSD, 90% full, on my PC) those small appends keep the disk busy:

Its 4 KB reads take 10–500 ms, where they normally take 0.4 ms.
What the game reads from that disk meanwhile (pages of hookshot.exe, the game's files) waits just as long.

The fix

log_write joins the lines it is given into one fwrite. On the text-mode stream that is one WriteFile, or a few for a large batch.
After the line it is woken for, log_main waits up to HOS_LOG_BATCH_MS so the lines of that time go out together:
- The default is 250 ms, the most is 2000, and 0 behaves as before.
- The wait is on the existing condition variable: log_queue wakes it at each line.
- When the queue is half full (1,024 lines), the batch goes out at once, before a burst can fill the queue. A full queue would make the thread that logs write the line itself.
Nothing waiting is lost. Every way out already writes the queue first (log_flush at exit, in hos_fatal and at the window's close, and log_crash_filter), and the writer holds no lock while it waits.
A line therefore reaches the file up to 250 ms later than before. A process killed from outside (TerminateProcess) could lose up to that much. Before, it could lose whatever the writer had not reached yet.

Measured

Test setup:

RTX 5070, driver 621.01, Ryzen 7 9800X3D, 31 GB.
Game and its log on a SATA SSD; the test harness's own files on another disk.
Scripted headless route: load a save, then walk outdoors on the Kokiri path. In play = from present 3300 on, about 2,820 frames a run.
3 runs of each version, alternated, on the same build. Both arms also had #1660, so the 1.1 GB pipeline cache rewrite is out of the picture.

	one write per line (`HOS_LOG_BATCH_MS=0`)	batched (default)
game-disk 4 KB reads over 10 ms in play	46 / 12 / 0	0 / 0 / 2
game-disk 4 KB reads over 100 ms	6 / 1 / 0	0 / 0 / 0
worst game-disk read	202 / 526 / 7 ms	3 / 4 / 18 ms
frames over 50 ms	0 / 4 / 2	0 / 1 / 0
worst frame	40 / 111 / 367* ms	41 / 51 / 41 ms

* That 367 ms frame overlapped a page-file read on the other disk (memory pressure), not the game disk.

The effect is intermittent: one of the three unbatched runs was clean. In the second run, a cluster of 40–111 ms frames lined up with game-disk reads of 20–53 ms and with 800–2,000 pages read in by hard faults in each of those frames (hookshot.exe is on that disk). The average stays at 60 fps (capped).

Tests

tests/test_log_batch.py extracts the Windows log block of host/hos_thread.c unmodified, with fputs, fwrite and fflush as spies. It runs on real threads, SRW locks and condition variables, and checks five cases:

batch: with a 1 s wait, the lines of that time go out in one write, in order, and none before the wait ends.
default: with no setting, a line goes out after its 250 ms.
off: 0 writes a line at once.
burst: with a 2 s wait, 1,500 lines queued at once: the first 1,024 go out within 1 s, every line was queued, and none was written by the logging thread.
flush: log_flush writes what waits, and the writer's wait then ends with nothing written twice.

It is Windows only; run_all.py skips it on Linux. GCC's C front end warns that log_main (a for (;;) thread) has no return statement, so the fixture turns -Wreturn-type off around the extracted block only; clang, which builds the game, does not warn.

Results:

This PR passes all 5 cases, 4 times in a row.
main's writer fails batch, default and flush.
A plain Sleep in place of the condition-variable wait fails burst.

Also checked:

host/hos_thread.c compiles with -Wall -Wextra with the same single warning as main (an unused parameter at the file's end).
tests/run_all.py: 225 checks, 33 skipped. test_log_batch.py passes. Two checks fail for reasons of this PC, as on main:
- test_precompile_compute_guard.py needs windows.h for an MSVC target.
- test_nup_paths.py needs the symlink privilege.

🤖 Generated with Claude Code

## The problem `stderr` is unbuffered (`hos_main.c`), so every line the log writer takes is a write of its own. In play that is 30–90 writes a second, each one extending `hookshot_log.txt` in the game folder. With the game on a slow disk (a SATA SSD, 90% full, on my PC) those small appends keep the disk busy: - Its 4 KB reads take 10–500 ms, where they normally take 0.4 ms. - What the game reads from that disk meanwhile (pages of `hookshot.exe`, the game's files) waits just as long. ## The fix - `log_write` joins the lines it is given into one `fwrite`. On the text-mode stream that is one `WriteFile`, or a few for a large batch. - After the line it is woken for, `log_main` waits up to `HOS_LOG_BATCH_MS` so the lines of that time go out together: - The default is 250 ms, the most is 2000, and `0` behaves as before. - The wait is on the existing condition variable: `log_queue` wakes it at each line. - When the queue is half full (1,024 lines), the batch goes out at once, before a burst can fill the queue. A full queue would make the thread that logs write the line itself. - Nothing waiting is lost. Every way out already writes the queue first (`log_flush` at exit, in `hos_fatal` and at the window's close, and `log_crash_filter`), and the writer holds no lock while it waits. - A line therefore reaches the file up to 250 ms later than before. A process killed from outside (`TerminateProcess`) could lose up to that much. Before, it could lose whatever the writer had not reached yet. ## Measured Test setup: - RTX 5070, driver 621.01, Ryzen 7 9800X3D, 31 GB. - Game and its log on a SATA SSD; the test harness's own files on another disk. - Scripted headless route: load a save, then walk outdoors on the Kokiri path. In play = from present 3300 on, about 2,820 frames a run. - 3 runs of each version, alternated, on the same build. Both arms also had #1660, so the 1.1 GB pipeline cache rewrite is out of the picture. | | one write per line (`HOS_LOG_BATCH_MS=0`) | batched (default) | |---|---|---| | game-disk 4 KB reads over 10 ms in play | 46 / 12 / 0 | 0 / 0 / 2 | | game-disk 4 KB reads over 100 ms | 6 / 1 / 0 | 0 / 0 / 0 | | worst game-disk read | 202 / 526 / 7 ms | 3 / 4 / 18 ms | | frames over 50 ms | 0 / 4 / 2 | 0 / 1 / 0 | | worst frame | 40 / 111 / 367\* ms | 41 / 51 / 41 ms | \* That 367 ms frame overlapped a page-file read on the other disk (memory pressure), not the game disk. The effect is intermittent: one of the three unbatched runs was clean. In the second run, a cluster of 40–111 ms frames lined up with game-disk reads of 20–53 ms and with 800–2,000 pages read in by hard faults in each of those frames (`hookshot.exe` is on that disk). The average stays at 60 fps (capped). ## Tests `tests/test_log_batch.py` extracts the Windows log block of `host/hos_thread.c` unmodified, with `fputs`, `fwrite` and `fflush` as spies. It runs on real threads, SRW locks and condition variables, and checks five cases: - **batch:** with a 1 s wait, the lines of that time go out in one write, in order, and none before the wait ends. - **default:** with no setting, a line goes out after its 250 ms. - **off:** `0` writes a line at once. - **burst:** with a 2 s wait, 1,500 lines queued at once: the first 1,024 go out within 1 s, every line was queued, and none was written by the logging thread. - **flush:** `log_flush` writes what waits, and the writer's wait then ends with nothing written twice. It is Windows only; `run_all.py` skips it on Linux. GCC's C front end warns that `log_main` (a `for (;;)` thread) has no return statement, so the fixture turns `-Wreturn-type` off around the extracted block only; clang, which builds the game, does not warn. Results: - This PR passes all 5 cases, 4 times in a row. - `main`'s writer fails `batch`, `default` and `flush`. - A plain `Sleep` in place of the condition-variable wait fails `burst`. Also checked: - `host/hos_thread.c` compiles with `-Wall -Wextra` with the same single warning as `main` (an unused parameter at the file's end). - `tests/run_all.py`: 225 checks, 33 skipped. `test_log_batch.py` passes. Two checks fail for reasons of this PC, as on `main`: - `test_precompile_compute_guard.py` needs `windows.h` for an MSVC target. - `test_nup_paths.py` needs the symlink privilege. 🤖 Generated with [Claude Code](https://claude.com/claude-code)

hckrman101 (Migrated from github.com) approved these changes

2026-11-10 16:40:30 +00:00

hckrman101 (Migrated from github.com) left a comment

Read through the writer changes and I don't see a problem.

The wait uses SleepConditionVariableSRW, so log_lock is released while the writer waits. log_flush, log_crash_filter and log_drain_raw can still take the queue, and log_write_lock is only held during the actual write.
If a flush empties the queue during the wait, the writer wakes with n == 0. log_write then does nothing but an fflush, so nothing is written twice.
The 1024 half-full cut-off leaves room before the 2048 limit, and the malloc failure fallback still writes line by line.
tests/test_log_batch.py is registered in run_all.py and skipped on Linux. The five cases match what the code does.

Nit: the Python source checks are red on both OSes. I couldn't pull the logs (the run was still going), but it looks like the known main breakage from #1764. A merge of main (#1780 is in) should clear it. Worth checking that the Windows job runs test_log_batch.py and passes, since that's the only place it runs.

Read through the writer changes and I don't see a problem. - The wait uses SleepConditionVariableSRW, so log_lock is released while the writer waits. log_flush, log_crash_filter and log_drain_raw can still take the queue, and log_write_lock is only held during the actual write. - If a flush empties the queue during the wait, the writer wakes with n == 0. log_write then does nothing but an fflush, so nothing is written twice. - The 1024 half-full cut-off leaves room before the 2048 limit, and the malloc failure fallback still writes line by line. - tests/test_log_batch.py is registered in run_all.py and skipped on Linux. The five cases match what the code does. Nit: the Python source checks are red on both OSes. I couldn't pull the logs (the run was still going), but it looks like the known main breakage from #1764. A merge of main (#1780 is in) should clear it. Worth checking that the Windows job runs test_log_batch.py and passes, since that's the only place it runs.

Commenting is not possible because the repository is archived.

No reviewers

hckrman101