Skip to content

feat(build): build_times.json and the build's last lines say where the time went - #2693

Open
jordanella wants to merge 1 commit into
NotRexed:mainfrom
jordanella:feat/build-phase-times
Open

feat(build): build_times.json and the build's last lines say where the time went#2693
jordanella wants to merge 1 commit into
NotRexed:mainfrom
jordanella:feat/build-phase-times

Conversation

@jordanella

@jordanella jordanella commented Nov 12, 2026

Copy link
Copy Markdown
Contributor

A build says its total and its compile time, and nothing about the rest. On Windows a clean build spends ~20 minutes outside the compile, and a one-file edit's build ~10 s, with no line saying where. This is the dev-loop proposal's A1 (#2636): the measurement the later items wait on.

Change

  • Every stage is timed: make_game.py times checks, read, lift, compile and finish from its own @@stage lines.
  • So are the parts it can see from lines the steps already print:
    • the lift's steps (lift: <step> in Ns, discovered ... (Ns));
    • build.py's planning, from its start to its <n> files, <n> jobs line, when every source has been read and hashed for its object key;
    • the compile (compiled in Ns);
    • each link (linked <file>: ... (Ns)).
  • The times are kept: they go into the build's entry in build_times.json as "phases", and the build ends with a table.
  • Nothing new for the Builders: no new @@ line, they read the same lines as before, and @@times is unchanged.

From a real build on Windows (Ryzen 9 3900X, NVMe), one gpu/vk/vk_draw.cpp edit:

where the time went:
  checks                                  2 s
  read                                    0 s
  lift                                    0 s
  compile                                28 s
    planning                              8 s
    compiling                            18 s
    linking hookshot.exe                  3 s
    linking hookshot_vk.dll               0 s
  finish                                  2 s
the build took 0:00:32, compiled in 0:00:28 (the last one 0:00:21)

The first thing it shows: planning, mostly reading and hashing ~1.4 GB of lifted C to compute object keys, is 7.5 s of a 32 s edit build. That makes A5 (a stat cache in front of the content hash) worth doing next.

Testing

  • tests/test_build_times.py: five new tests.
    • The clock against the real line formats, with a fake time source.
    • A stage entered twice adds up, and planning counts only in the compile stage.
    • The phases are stored with the build, and absent when none are given.
    • run() and say() feed the clock, and no @@phase line exists.
    • They fail against main's make_game.py; with this change all 19 tests pass.
  • A real build with this make_game.py printed the table above and wrote the same phases to build_times.json.
  • Every check that reads make_game.py (52), on Windows, passes apart from test_cpp_preflight, test_linux_update and test_prepare_stall, which fail the same way on a clean main here.
  • Not tested here: the Builder's window with the new lines. They're ordinary log lines, and it acts only on the @@ lines it knows.

🤖 Generated with Claude Code

@jordanella jordanella mentioned this pull request Nov 12, 2026
Merged
@jordanella @claude
feat(build): build_times.json and the build's last lines say where th…
36e680f 
…e time went

A build said its total and its compile time, and nothing of the rest: on Windows a clean build spent ~20 minutes outside
the compile, and an edit's build ~10 s, with no line saying where (the dev-loop proposal's A1, NotRexed#2636).

make_game.py now times each stage (checks, read, lift, compile, finish) from its own @@stage lines, and the parts it
knows from the lines the steps already print: the lift's steps ("lift: <step> in Ns", "discovered ... (Ns)"), build.py's
planning (its start to "<n> files, <n> jobs", where every source is read and hashed for its object key), the compile
("compiled in Ns") and each link ("linked <file>: ... (Ns)"). They go into the build's entry in build_times.json as
"phases", and the build ends with a "where the time went" table. No new @@ line: the builders read the same lines as
before. tests/test_build_times.py checks the clock against those lines, the record, and that run() and say() feed it.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
hckrman101 pushed a commit that referenced this pull request Nov 12, 2026
@jordanella @claude
perf(build): a source whose size, time and id are unchanged is not re…
ba005ca 
…ad again to name its object (#2702)

Every build reads and hashes each source again to name its object, and
the 1.4 GB of lifted C up to three times: `migrate_stamps`, the log's
fingerprint and `plan_jobs`. On Windows that planning was 6–7.5 s of a
one-file renderer edit's ~31 s build, as #2693's table shows. This is
the dev-loop proposal's A5 (#2636).

## Change

- **The record:** `build.py` keeps `<build>/hash_cache.json`. For each
source it holds the size, modification time and file id, the content's
sha1, and the object key worked out from it for each set of flags and
headers (`kept_part`).
- **`key_of()`** returns that key without reading the file while all
three match, and otherwise reads and hashes the file as before.
- **No key changes:** `object_key`, the key's definition, is unchanged,
so every object's key, every object cache and every player's kept
translation stays as it is.
- **The racy rule:** a file written less than 2 s before the record was
is read again, as with git's "racily clean" entries. An untrusted record
whose file turns out to have other content loses its keys.
- **Callers:** `plan_jobs` and the kept list use `key_of`. The log's
fingerprint uses the recorded sha1, so its value changes once, and it
still says which part changed. `migrate_stamps` reads nothing stamped
with today's kind of key, since that key's object is in the cache.
- **When it's saved:** after the plan, which `make_game.py`'s builds run
(`HOOKSHOT_TIMES`). A bare `build.py` run without it hashes in
`compile_one` as before.

## Measured

On Windows (Ryzen 9 3900X, NVMe), three one-file `gpu/vk/vk_draw.cpp`
edit builds in a row, with #2693's table:

| Build | Planning | Compiling | Total |
|---|---|---|---|
| first (the record made) | 6 s | 18 s | 31 s |
| second | **2 s** | 17 s | 26 s |
| third | **2 s** | 19 s | 29 s |

Each build still compiled the edited file.

## Testing

- **`tests/test_build_hash_cache.py` (new, 9 cases):**
- the key equals `object_key`, and the next build doesn't read the
source;
  - another size or time reads it again;
  - other flags or headers are another key, and both are kept;
  - a file written near the record isn't trusted;
  - an untrusted record of other content loses its keys;
  - a record that's broken or of another scheme is ignored;
  - a gone file leaves the record;
- `migrate_stamps` reads nothing already stamped with today's kind of
key;
  - and `main` wires it in that order.

  All fail against `main`'s `build.py`.
- **The checks that cut functions out of `build.py`**
(`test_compile_retry_jobs`, `test_dlss_sdk_cache`,
`test_shader_stamp_cache`) pass unchanged, since `object_key` and
`compile_one` are as they were.
- **Every check that reads `build.py` (39), on Windows,** passes apart
from `test_driver_cache_folder`, `test_fpx_sticky` and
`test_linux_update`, which fail the same way with `main`'s `build.py`
here.
- **Not tested:** Linux. The file id there is the inode, as `os.stat`
gives it.

🤖 Generated with [Claude Code](https://claude.com/claude-code)

Co-authored-by: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
@Jiro131 Jiro131 mentioned this pull request Nov 12, 2026
Merged
hckrman101 pushed a commit that referenced this pull request Nov 12, 2026
@Jiro131 @claude
perf(lift): emit the lifted C in several processes on Windows too (#2748
8c2a3c3 
)

On Windows the lift writes the game's C in one process, because there is
no `fork`: about 65 s of the lift on a 32-thread PC here, and 145–170 s
on the Ryzen 9 3900X of #2636's Phase 0. This is that proposal's item
A3: the emit now runs in several new processes on Windows and writes the
same files, byte for byte.

## Who this reaches

Builds that translate the game again. Since #2324 an update with an
unchanged lift key skips the lift. `nx2/chunks.py` is one of the key's
inputs, so the first build after this lands translates once more.

## Change

`nx2/chunks.py`:
- **New processes where there is no fork** (`spawn_emit`). Each gets the
lifter's small tables once (`EMIT_TABLES`) and, with each run of 2,000
functions, their bodies; it translates that run's words itself. A3
sketched workers that map `image.bin`; sending the bodies needed no
second discovery.
- **Only when the workers' emit is the lift's:** a plain
`a64_lift.Lifter` (no subclass, no `emit_function` of its own), with
`nx2/poll.py` installed exactly when its counter is passed. Otherwise
one process, as before.
- **Each worker checks itself:** it compares where its translator and
emit passes come from with the lift's, and stops if they differ. The
lift then emits the rest itself and says so.
- **The log line says what ran:** `lift: emit and write (16 processes)`
or `(1 process)`. #2693's pattern reads both.
- **Linux and macOS are unchanged:** forked workers, as before.

**One more change, for everyone on Windows:** the available-memory cap
(one process per 2 GB free, from the Steam Deck reports) now applies on
Windows too, where free memory was not read before. It is `file_jobs()`'
cap, so the per-file passes of #2324 are limited by it as well on a PC
with little free memory. That cost is not measured, and I can move it to
its own PR if you prefer.

## Measured

i9-13900K (24 cores, 32 threads), 64 GB, NVMe, Windows 11 Home
10.0.26300. The standalone lift (`nx2/lift.py --standalone --write`) in
its default configuration (polls on, `A64_LOCAL_REGS` unset, no hot
list), `main` (ba005ca) and this branch alternated, three runs each:

| | `emit and write` | whole standalone lift |
|---|---|---|
| `main`, 1 process | 66.5 s, 64.9 s, 66.0 s | 119 s, 117 s, 120 s |
| this branch, 16 processes | 20.9 s, 21.2 s, 21.2 s | 73 s, 73 s, 74 s
|

- **Same output:** the 85 files of the gen folder are SHA-256 identical
between the two.
- **Fewer processes** (an earlier revision of this branch): 38.1 s with
4, 26.1 s with 8.
- **Memory:** about 170 MB per worker. Peak working set summed over the
lift's processes: 5.1–5.9 GB with 1, 7.9 GB with 16.

## In the game

A full build with the Builder's steps (`nx2/make_game.py --nup`, French,
shaders not prepared) from this branch plus one unrelated commit (the
damaged-texture check opening files several at a time, its own PR): the
log says `lift: emit and write (16 processes) in 23.2s`. Build
`v2.1.0-rc.3-256-gf79aa054`, RTX 4090, NVIDIA 621.01, Vulkan 1.4,
Windows 11, 5120x1440, upscaler off, frame generation off, 60 fps cap.
Kokiri Forest from a save: 52–60 fps, no device lost, no stutter seen,
nothing out of place.

## Testing

- **`tests/test_spawn_emit.py` (new, game-free):** a real
`a64_lift.Lifter` over a made-up image of 4,500 functions, written by
`chunks.write` with 1 process and with 3 spawned ones: the same files
and counters. It covers:
  - the plain configuration;
- the lift's default (`poll.install()`, `A64_LOCAL_REGS=4`, comments
on);
- a translator that differs in the workers (the lift falls back and says
so);
  - a `Lifter` subclass (kept in one process).

A fallback cannot pass for the spawn: the "worker process stopped" line
fails the test.
- **Teeth:** each entry of `EMIT_TABLES`, dropped or sent empty, makes
it fail (checked by hand).
- **Where it runs:** it builds the translator in a temporary folder, so
it needs a C++ compiler, as `tests/test_fpx_sticky.py` does. On the
game-free CI (windows-2022 and ubuntu-24.04, Python 3.12) of a private
copy of this branch, it passed on both (15.7 s on Windows; 18.2 s and
8.3 s in two Linux runs). Those two Linux runs each had one other
failure, a different one each time and outside this change:
`tests/test_bake_skeleton.py` stopped at 600 s on a runner where every
check took twice its usual time, then `tests/test_linux_saves_move.py`
(host/hos_main.c) failed once after passing in the first run.
- **`python -I -B tests/run_all.py` on Windows:** 448 passed, 5 failed.
`nx2/test_nup_paths.py` needs the symlink privilege.
`tests/test_bug_report.py` and `tests/test_input_background.py` fail the
same way here without this change. `nx2/test_nup_verify.py` and
`tests/test_prepare_at_build.py` failed once with 32 checks at once and
pass alone.

## Not measured

- `--no-polls`, `A64_LOCAL_REGS` or a hot list on real data (the test
covers the first two on the made-up image).
- A PC with 16 GB or less, where the cap leaves fewer processes.
- The per-file passes under the new Windows cap.

See #2636
See #2324

Assisted-by: Claude Opus 5.5
🤖 Generated with [Claude Code](https://claude.com/claude-code)

---------

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
This was referenced Nov 12, 2026
Open
Open
@Joey-Magnus Joey-Magnus mentioned this pull request Nov 12, 2026
Open
Joey-Magnus
Joey-Magnus approved these changes Nov 12, 2026
View reviewed changes

@Joey-Magnus Joey-Magnus left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I merged this into current main and ran tests/test_build_times.py: 19 tests OK. PhaseClock only reads lines the steps already print, and there's no new @@ line, so the Builders' parsers see the same output as before. In the KEPT_STALE path, make_game.py re-enters "lift" and then "compile", so since resets and the second build.py run's planning time isn't counted from the first one's start. The PLANNED match is limited to the compile stage, so a lift line that happens to look like "N files, N jobs" can't count as planning. I also merged it on top of #2686 and #2706: both merge cleanly and the tests still pass. #2706 doesn't change build.py's "N files, N jobs" or "compiled in" lines, which this depends on. The 7.5 s of planning in a 32 s edit build is a useful number for the next step.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

1 more reviewer
@Joey-Magnus Joey-Magnus Joey-Magnus approved these changes
Reviewers whose approvals may not affect merge requirements

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

2 participants

@jordanella @Joey-Magnus