Analyzer diagnostics: blame only real culprits, split otherMs by Unity phase, read patch headers, mark GC frames in heap mode (PL4, PL5, PL6, PL3)

[kramsey458]

Summary

Four analyzer and summary fixes from the review of the first real 0.1.3 recording (2026-09-21_23-13-11), plus follow-ups from an adversarial review of this branch. Performance Log only observes, so nothing here touches simulation, co-op or other mods' patches. The column layout and frames.csv format are unchanged, and the analyzer still reads 0.1.0, 0.1.1 and 0.1.3 recordings.

• PL4: summary.md's Blame column and report section 5 no longer name a 1 ms singleton as the cause of a 1.1 s save frame.
• PL5: otherMs is split by Unity phase, so "the rest" points at scripts' Update, LateUpdate work (animation, UI Toolkit), drawing, or the phases before Update.
• PL6: the analyzer reads the # patch| header lines. It names other mods whose patches run inside a singleton's time, lists hot methods other mods patch, and compare lists patches that only one session has.
• PL3: with the heap-size allocation counter (the only one the game's Mono gives), a frame with a garbage collection loses what it allocated. Such frames are now counted in a new # capability-final|allocSource| line and left out of the allocation-per-second figures, where they used to be read as 0 KB.

Items

PL4: Blame names only a singleton that took a real part of the frame

• What changed: Blame (C# Summary.Blame, Python section 5) names a singleton only if it took at least 10% of the frame or at least 5 ms (Summary.BlameMinShare/BlameMinMs, BLAME_MIN_SHARE/BLAME_MIN_MS). Otherwise it says no singleton stood out (largest X ms, Y% of the frame), plus the frame had a save and/or a garbage collection. spikes.csv is unchanged. In the fixtures' summary.md, only the slowest-frames section changed.
• Tests: SummaryTests "a slow frame's Blame names only a singleton that took a real part of it, else says what the frame had"; FindingTests.test_slow_frames_blame_only_a_singleton_that_took_a_real_part.
• Failed before: | 101 | 0 | 1142 | ... | Timberborn.TimbermeshAnimations.AnimatorRegistry 1 |, and in Python [GC,save] saveMs 1133 ... <- AnimatorRegistry 1 ms. Passes after. On the real session, all 9 save frames now read no singleton stood out (largest 0.3-2.1 ms, 0.0-0.2%); the frame had a save and a garbage collection.

PL5: split otherMs by Unity phase

• What changed: summary.md ("How otherMs splits by Unity phase") and report section 3 split otherMs into five parts:

  • the Update phase minus the timed parts inside it
  • the LateUpdate phase minus lateMs, labelled "other work in Unity's LateUpdate phase (animation, UI Toolkit, scripts' LateUpdate)", not "mods"
  • plPost
  • the phases before Update
  • time between phases

  saveMs is taken out of whichever phase has more room. The decompiled GameSaverUnityAdapter.LateUpdate calls SaveQueued, so the game's own save runs in LateUpdate, while BeaverBuddies defers it into Update. The real session has both kinds. report --json gains otherMsByPhase. SESSION-README explains the split, so the fixtures' README.md was regenerated. On the real session the split is 1.33 / 1.14 / 3.91 / 0.16 / 0.13 ms of otherMs 6.67 ms.

• Finding (report section 4): when the Update or LateUpdate remainder holds most of the frame, the finding points at scripts, not at the graphics card. Review follow-up:

  • The finding now also weighs the phases before Update and the time between phases. Unity can wait for the last frame to be presented in plTime, so those keep the high-severity "likely the graphics card or vertical sync" finding.
  • When the game thread is less than 70% busy, the Update-phase finding says a script there is waiting. It no longer says the graphics card is ruled out.

• Tests:

  • SummaryTests "otherMs is split by Unity phase, each phase less the timed parts that run in it"
  • HelperTests.test_other_ms_is_split_by_unity_phase
  • FindingTests.test_the_report_splits_other_ms_by_unity_phase
  • FindingTests.test_other_ms_in_the_update_phase_points_at_scripts_not_the_graphics_card
  • FindingTests.test_a_wait_before_the_update_phase_still_points_at_the_graphics_card (new)
  • FindingTests.test_update_phase_time_with_an_idle_game_thread_is_not_called_work (new)

• Failed before:

  • C#: "the split is not in the summary".
  • Python: module 'perflog' has no attribute 'split_other', and a 40 ms frame with 31 ms in Update was reported as "Likely the graphics card".
  • Follow-up tests: a session with 14 of 25 ms in plTime and the thread 40% busy got [ ] Most of the frame is other work in Unity's Update phase ... The graphics card is not what holds the frame.

  Passes after.

PL6: read the # patch| header lines

• What changed in the report:

  • A singleton row in section 6 ends with (includes patches by X, Y) when another mod patches the method that row's kind times (Tick, UpdateSingleton, LateUpdateSingleton or StartParallelTick).
  • Section 6 then lists the hot methods other mods patch, with owners and patch kinds.

• What changed in compare: section 1 lists the patches only one session has, counted per owner, with examples. The comparison key is (method, kind, owner), without the tag.

• What is left out: this mod's own patches (kyler.performancelog*) never appear.

• Review follow-up:

  • compare also leaves out this mod's own patches. They follow its Profile setting, which compare already reports as a header key.
  • The hot-methods heading appears only over a non-empty list.
  • A recording with # patches-unavailable says the patches were not recorded, in both the report and compare.

• Tests:

  • FindingTests.test_singletons_other_mods_patch_are_marked_and_hot_patches_listed
  • FindingTests.test_no_hot_patch_list_without_hot_patches_by_other_mods (new)
  • CompareTests.test_patches_that_differ_are_listed (extended with a kyler.performancelog patch in one session only)
  • CompareTests.test_patches_are_not_compared_when_one_session_did_not_record_them (new)

• Failed before:

  • 'some.mod' not found in ' Timberborn.InputSystem.InputService game 30.00 ms/s ...', and compare gave 1 != 0.
  • Follow-ups: only ... has 4 patches (kyler.performancelog 2, new.mod 2); the heading printed over an empty list; 'not recorded in ...' not found.

  Passes after.

• On the real sessions: InputService shows (includes patches by kyler.mixedstorage, timbermods.BeaverBuddiesMultiColony). Comparing 0.1.1 17-13-43 with 0.1.3 23-05-35 now lists 60 patches, not 62; the two dropped are this mod's own.

• Limitation: patch lines name the declaring type, so a patch on an inherited base-class method is not matched to a derived singleton's row.

PL3: heap-mode frames with a collection are counted as not measured

• What changed in the probe: Probe counts a frame as not measured when its allocation counter fell. That covers a fall inside a timed part, a fall over the whole frame, and, in heap mode, any collection. The counts are SessionStats.AllocUnmeasuredFrames, AllocUnmeasuredMs and (follow-up) AllocUnmeasuredKB. There is no new column.

• New header line: Session.Stop writes # capability-final|allocSource|heap size|allocation not measured in N frames (X s) with a garbage collection: ..., or |measured in every frame (Probe.AllocFinalLine).

• summary.md: says how many frames were not measured and leaves them out of "allocated about X KB per second". It leaves out their time and, after the follow-up, the positive heap growth they still showed.

• perflog.py: does the same for heap-mode slow rows with gcDelta > 0 or allocKB < 0, in section 7, the GC finding and compare. It uses the mod's count when the recording has one, and "at least N" for older recordings.

• Code and test cleanup: the Probe.cs comment is corrected, and Alloc.UseTestSource(source, asHeapSize) is added for tests.

• Review follow-up:

  • The section 7 note says its count covers the whole session, and how many of those slow frames fall in the windows the figures cover.
  • The texts say "the slow ones are the F rows".
  • HeapModeTests' first check now actually runs under the heap-size stand-in, inside a no-GC region.
  • Alloc.ModeName now says (coarse: grows with allocation, falls at a garbage collection), replacing "moves only when the heap grows". The analyzers match only the GC.GetTotalMemory prefix, and no fixture holds this text.

• Tests:

  • New file tests/HeapModeTests.cs (3 checks, registered in tests/Program.cs; no PL1 content).
  • FindingTests.test_heap_mode_leaves_frames_with_a_collection_out_of_allocation_per_second
  • FindingTests.test_heap_mode_counts_are_scoped_and_a_lost_frames_growth_is_left_out (new)

• Failed before:

  • "the frame with the collection reads otherKB 0 and nothing says its allocation was not measured".
  • Python read 100 KB/s instead of 109.
  • Follow-ups: first a compile error on the missing AllocUnmeasuredKB. With only the field declared, "the lost frame's heap growth: expected about 363.6, got 0" and "only the slow ones have rows" failed. Python read 109 KB/s instead of 100.

  Passes after. A mutant that ignores a falling counter is caught by the heap-mode check.

• Unchanged: columns and fixtures. Regenerating the samples gives identical summary.md, README.md and columns.md, and WriterTests.FixturesAreCurrent passes.

Tests

Suite	Before (a1c6d1c)	After (1d1affb)
C# dotnet run --project tests -c Release	91/91	96/96
Python python -W error::ResourceWarning -m unittest discover -s tools -p test_perflog.py	44 OK	56 OK
Mod build dotnet build source/PerformanceLog.csproj -c Release (offline)	0 errors	0 errors, 0 warnings

docs/TESTING.md check counts are updated in each commit. perflog.py report and report --json ran on all 26 real recordings (0.1.0, 0.1.1 and 0.1.3) without error, and compare ran across versions. Against the pre-follow-up head, the only report change on those recordings is the reworded section-7 note. Both Python files parse as Python 3.8.

While running the C# suite, two WriterTests file-sharing checks each failed once, in separate runs, with "being used by another process" on a fresh temp file. Neither recurred on the re-runs. This PR does not touch the writer. The likely cause is another process (a virus scanner, or the many parallel builds on this machine) opening the temp file.

Co-op impact

None. Performance Log only observes: no simulation change, no wire-format change, and no Harmony patch added, removed or reordered. The frame path still allocates nothing (its check passes). The new per-frame work is one bool and a few adds.

Proposed CHANGELOG lines

• summary.md and perflog.py report blame a slow frame on a singleton only if it took at least 10% of the frame or 5 ms. Otherwise they say no singleton stood out, and whether the frame had a save or a garbage collection.
• summary.md and the report split otherMs by Unity phase: the Update phase minus the timed parts inside it, the LateUpdate phase minus lateMs, plPost, the earlier phases, and time between phases. When scripts' Update or LateUpdate work holds the time, the "not the game's code" pointer now points there. When the wait is in plPost or the phases before Update, it keeps pointing at the graphics card or vertical sync.
• perflog.py report names the other mods whose Harmony patches run inside a singleton's time and lists the hot methods other mods patch. compare lists the other mods' patches that only one session has.
• With the heap-size allocation counter (every game so far), a frame with a garbage collection is counted as "allocation not measured", in a new # capability-final|allocSource| line and in summary.md. Its time and heap growth are left out of the allocation-per-second figures; perflog.py does the same for older recordings. The allocSource capability line now says the heap size falls at a collection.

Needs in-game testing

Solo is enough; there is no co-op change.

• PL3: record a session long enough to include a garbage collection (a save usually brings one). frames.csv should end with # capability-final|allocSource|heap size|allocation not measured in N frames (X s) with a garbage collection ..., with N at least the number of F rows with gcDelta > 0, and summary.md's garbage-collection section should give the same N. A session with no collection should show |heap size|measured in every frame. The header's # capability|allocSource| should read (coarse: grows with allocation, falls at a garbage collection).
• PL5: in summary.md, the parts of "How otherMs splits by Unity phase" should add up to otherMs within about 0.1 ms. A save deferred by BeaverBuddies should come out of the Update phase, and a manual save while paused out of LateUpdate.
• PL4: in a recording with an autosave, the save frames' Blame cell should read no singleton stood out (...); the frame had a save.
• PL6: python tools/perflog.py report <folder> on a new recording should mark InputService and NavigationSynchronizer with the mods that patch them.

Review

Three adversarial reviewers approved the branch: determinism and co-op, save compatibility and cross-mod interaction, and whether the tests are real. They reported nothing major or worse. Each item's tests failed when only that item's fix was reverted, and several mutants were caught. What they found, and what happened:

Fixed:

• Minor (PL5): the finding picked only among update, late and post, so a GPU-bound session whose wait sits in plTime lost the high-severity graphics-card finding. Fixed in cc384d0: the finding now weighs the phases before Update and between phases, and gates on how busy the game thread was.
• Nit (PL5): the "error is less than the save" comments. Fixed in cc384d0: they now say "up to the save" and note that the per-window and session-mean splits can differ.
• Minor (PL6): compare counted this mod's own patches. Fixed in cc6743a.
• Minor (PL6): the hot-methods heading printed over an empty list. Fixed in cc6743a, which also covers # patches-unavailable.
• Nits (PL3), fixed in 1d1affb:
  • The section-7 note mixed a whole-session count with a steady-state count.
  • The rate numerator kept lost frames' growth.
  • The texts said "the rows" where only slow frames have rows.
  • HeapModeTests' first check ran under the exact counter.
  • Alloc.ModeName said the heap size "moves only when the heap grows".
• Nit (docs): TESTING.md did not say that the new line and the split are not yet seen in a game. 1d1affb adds a step to the five-minute check instead of an item to the "still not verified" list, because the docs PR (claude/docs-refresh) rewrites that list's items 7 and 8, and an item appended there would conflict.

Declined:

• CLAUDE.md's "about 70" checks count belongs to the docs PR, which already replaces it with a pointer to docs/TESTING.md.
• Section 6's per-singleton KB/s is not adjusted for collections. A collection inside a singleton's call already clamps that call's allocation to 0, and there is no per-singleton time to take out. On the real session the unmeasured time is 0.4 s of 2615 s.

Merge note: claude/sampling-calibration and claude/beaver-rollup also edit tools/perflog.py, tools/test_perflog.py, tests/Program.cs and the check counts in docs/TESTING.md, so expect textual conflicts when these PRs land after one another.

🤖 Generated with Claude Code