Sample watched methods at their own rate (PL1); charge patch calls what they cost (NF2)

[kramsey458]

Summary

Two fixes to how Performance Log measures its own work. The mod only observes the game, so nothing here touches simulation.

• PL1: watched methods (config Watch) are sampled at their own rate, and the rate can go down as well as up. Before, the sampling interval came from all watched methods' calls added together, and it could only grow. One busy window, or one busy method, left every watched method timed on about 1 call in 30 for the rest of the session. A rare method's windows then often had no timed call at all: the row was dropped, but the totals still added those calls at 0 ms.
• NF2: overheadUs now charges the per-call patches what they actually cost. patchCallNs used to time an empty patch, and every recording up to 0.1.3 shows patchCallNs|0. It now times the real EntityPrefix/EntityPostfix bodies on the unsampled path, adds what Harmony costs to call them, and writes patchBodyNs next to it. For older recordings, perflog.py explains what their overheadUs really charged.

Items

PL1: per-method watched sampling that can go both ways

What changed (source/Core/Profile.cs):

• Profile.FlushWindow calls a new AdaptMethods before the counters are zeroed. For each watched method, it sets the next window's interval from that method's own calls in the window.
• The interval is recomputed every window the method ran in. It is never lower than the interval the method was registered with and never higher than 4096.
• The watched methods' share of the budget is split among the methods that ran.
• A window with no calls keeps the method's interval (review follow-up). Otherwise a method that is busy only in bursts went back to 1 call in 8 at every burst.
• methodCounter[id] restarts at 1 at every window start, so a method's first call in each window is timed.
• Every window a watched method ran in gets a row. A window where it was counted but never timed (its timed calls threw, so Harmony skipped the postfix) is written with sampled 0 and adds nothing to the session totals.
• perflog.py also leaves sampled 0 rows out of calls and ms, and prints (+N calls never timed).
• The column and kind descriptions, SESSION-README item 7 and TESTING.md are updated. The fixtures' columns.md and README.md are regenerated. Their frames.csv differed only by real-memory noise, so I kept the committed ones.

Tests: tests/PL1WatchSamplingTests.cs (WatchSamplingTests). It holds only the PL1 part of the verification harness, with Probe.SamplePairTicks = 50e-9 * Stopwatch.Frequency as a double; Rig.Ms would truncate that to 0 and switch adaptation off. It has five checks:

• Rare method next to a hot one. The loose assertion is tightened: in every window 2 to 5 there is a row with calls 20, sampled >= 2 and ms 100, and the session totals are 81 calls and 405 ms.
• Interval follows the load. The interval stays inside the budget while the method is busy, and at least 7 of 100 calls are timed again after it quietens.
• Few calls every window. With 3 calls a window at interval 8, every window times a call. This proves the per-window counter reset.
• Bursts stay inside the budget. The method is busy in windows 1, 3 and 5 and not called in 2 and 4. The later bursts stay within the methods' budget share.
• Untimed window. It gets a sampled 0 row, and the totals get no fake 0 ms.

Plus test_perflog.test_a_watched_method_window_nobody_timed_is_not_counted_at_0_ms.

Fail before / pass after:

• On a1c6d1c:
  • window 2: only 1 of 20 calls were timed; the interval is still the one the hot method needed
  • window 4: only 3 of 100 calls were timed; the interval never came back down after the busy windows
  • window 2: the method ran 3 times and left no row
  • Python printed 463.0 us/call instead of 500.0 us/call (a fake 0 ms averaged in).
• On 4030581, before the burst follow-up: burst window 3: measuring took 0.375% of a second, over the watched methods' share of the budget. After: 0.100%.
• Without the counter reset (a reviewer's mutation), FewCallsEveryWindow fails with window 2: 3 calls, none timed.
• All pass at the head.

NF2: honest patch-cost calibration

What changed:

• Instrumentation.MeasurePatchCost times the real EntityPrefix + EntityPostfix on the unsampled path through the new Probe.MeasureUnsampled:
  • the probe is on, and entity/component sampling is held off with the new internal Profile.HoldSampling;
  • it takes the fastest of 5 warmed-up rounds;
  • afterwards the probe is off, the counters are cleared and Profile is reset;
  • it refuses while a log is running.
• It then adds the Harmony call cost: the old empty-patch measurement, now with a Sample state, clamped at 0.
• PatchCallTicks = body + trampoline, and PatchBodyTicks = body.
• The # calibration| line (now built by Probe.CalibrationParts) gains patchBodyNs, and both values are written to one decimal. If the body can't be measured, both say unmeasured, and the 40 ns fallback is named (unmeasured (40 assumed)) instead of hidden.

Old recordings (tools/perflog.py, reworked after review): patchCallNs|0 meant one of two things, and the header rounds away the difference:

• The empty patch read exactly 0. The mod then charged an assumed 40 ns a call.
• It read just above 0. The mod then charged about nothing.

With the 40 ns charge, no row's overheadUs can fall below 40 ns per patch call. So a row below that proves the charge was about nothing. perflog.py now prints:

• "overheadUs understates what the mod itself cost" only for recordings with such a row;
• a neutral note (the charge was a 40 ns guess or about nothing, and no row shows which) for the other pre-0.1.4 recordings that ran patches;
• nothing when the calibration line has patchBodyNs.

On the 26 real recordings (read-only), every 0.1.3 recording with patch calls and four 0.1.1 ones are flagged as understated. The 0.1.0 recordings and the other 0.1.1 ones get the neutral note. TESTING.md item 2 and the MeasurePatchCost comment say the same.

Tests:

• GameBindingTests.PatchCostCoversTheBodies calls MeasurePatchCost. Harmony can't patch in the .NET 8 test process, so only the body part runs there. It then times the real bodies directly, as the fastest of 10 rounds so that CPU contention cannot fail it. It asserts that the charge is at least half the body time, that PatchBodyTicks > 0, and that the probe is left off with no keys.
• CoreTests.UnsampledBodyTiming: the probe is on during the measurement, no call is sampled even at interval 1, the state is restored, a throwing body gives 0, and nothing is measured while a log runs.
• CoreTests.CalibrationLine: the names perflog.py relies on, the one-decimal values and the unmeasured wording.
• test_perflog.test_a_recording_whose_patch_cost_read_0_is_told_what_overhead_charged_the_patches: proven by S rows, proven by one slow frame, a 40 ns-consistent (guess) recording, no patch calls, a new calibration line, no calibration line, and version 0.1.4.

Fail before / pass after:

• a1c6d1c: each patch call is charged 0.00 ns, less than its own bodies take (8.70 ns): overheadUs leaves the patches out. Head: charged per patch call 8.50 ns; the entity patch bodies timed here 9.47 ns.
• The Python test on 4030581's analyzer fails (False != True for the 0.1.0 recording at 45 ns a call, which was wrongly told it understated). It passes at the head.

Tests

Suite	Base a1c6d1c	Head
C# dotnet run --project tests -c Release	91/91	99/99
Python python -W error::ResourceWarning -m unittest discover -s tools -p test_perflog.py	44 OK	46 OK
Mod build dotnet build source/PerformanceLog.csproj -c Release	0 warnings, 0 errors	0 warnings, 0 errors

perflog.py report, report --json and compare exit 0 on all 26 real recordings (read-only).

Co-op impact

None. Both changes stay inside the profiler's own state (the Profile arrays, Probe counters and the calibration header):

• no new game patch;
• no UnpatchAll (the calibration patch on the mod's own CostTarget is removed by its own id);
• no Dictionary/HashSet iteration decides anything;
• MeasureUnsampled runs once at StartMod, on the mod's own methods.

No simulation or wire-format change. Co-op players need not update together.

Proposed CHANGELOG lines

Not written to CHANGELOG.md. The two new KNOWN_ISSUES entries in tools/perflog.py (PATCH_COST_NOTE and PATCH_COST_GUESS_NOTE) hard-code the next release as 0.1.4, as #1's entry does. If the release gets another number, change the "0.1.4" in those entries to match at release time.

• Watched methods (config Watch) are sampled at their own call rate, chosen again every window they run in. One busy method no longer leaves every watched method, or itself after it quietens, timed on about 1 call in 30 for the rest of the session, and a method that is busy in bursts stays inside the budget. Every window a watched method ran in has a row with at least its first call timed. A window where none of its calls could be timed is written with sampled 0 instead of being dropped, and no longer adds its calls at 0 ms to the totals.
• overheadUs now includes what the per-call patches really cost: patchCallNs is measured from the real entity patch bodies (new patchBodyNs in the # calibration| line) plus what Harmony adds. Up to 0.1.3 it timed an empty patch, so every recording shows patchCallNs 0, and overheadUs charged those calls either an assumed 40 ns or almost nothing. perflog.py now says which when a recording's rows show it.

Needs in-game testing

• NF2 (solo, PerformanceLog recording): the new frames.csv header's # calibration|...|patchBodyNs|X|patchCallNs|Y shows X and Y as a few ns each (not 0, not unmeasured), with Y >= X. Player.log has no [PerformanceLog] Could not measure what a patch body costs warning and no Could not measure what Harmony adds... warning. F-row overheadUs / patchCalls is at least patchCallNs / 1000 us.
• NF2 (solo): python tools/perflog.py report <new folder> prints no patch-cost KNOWN ISSUE. On an old 0.1.3 folder it prints "overheadUs understates"; on a 0.1.0 folder, the neutral note.
• PL1 (solo, optional; needs a Watch entry in PerformanceLog.cfg, e.g. one hot and one rare method): profile.csv has a method row for every profile window each method ran in, with sampled >= 1. After a busy period, the method's sampled/calls ratio climbs back toward 1/8.
• PL2 A/B (the user's measurement, not implemented here): with NF2 in, overheadUs is an honest estimate. Compare the frame rate with the mod off vs standard vs deep to judge the real cost.

Review

Three adversarial reviewers looked at 4030581, each through a different lens: determinism/co-op (approve), save compatibility/cross-mod (changes requested) and "is the test real" (approve). They found:

• Major (compatibility), minor (determinism): the old-recording note was wrong for some recordings. patchCallNs|0 did not always mean the patches were charged nothing. Recordings where the empty patch read exactly 0 were charged the 40 ns default; that covers 0.1.0 and several 0.1.1 recordings, and the slow-frame rows prove it. Fixed in 2e4d468: the note is now gated on evidence, with a neutral note for the rest, and TESTING.md and the code comment are corrected.
• Minor (determinism): one window without calls reset a watched method's interval. A method busy in bursts was then timed 3.75 times over its budget share in every burst. Fixed in 9edf543: windows without calls keep the interval, and there is a test.
• Nit (compatibility): the method kind description was wrong. It said N widens "only while that method itself is busy", but the budget is split among the methods that ran. Fixed in 9edf543, with the fixtures regenerated.
• Minor (test): no test covered the per-window counter reset. Fixed: FewCallsEveryWindow, the reviewer's scratch test, is added.
• Minor (test): PatchCostCoversTheBodies was flaky under CPU contention (1 of 3 runs failed next to a pinned busy loop). Fixed: the direct timing is now the fastest of 10 rounds.
• Nit (test): the calibration header line had no C# test. Fixed: it is factored into Probe.CalibrationParts, with CoreTests.CalibrationLine.

Declined: rewording 4030581's commit message, which repeats the old "read 0 in every recording ... left the patches out" claim. The branch keeps its history; 2e4d468's message corrects it, and this description is accurate.

Notes for whoever merges:

• This branch and Roll named beaver rows up to their kind (NF1) #1 (claude/beaver-rollup, NF1) both add a KNOWN_ISSUE_APPLIES mechanism to tools/perflog.py and both edit the check counts and table rows in docs/TESTING.md. The two conflict textually there: keep both sets of entries and add the counts together.
• Out of scope, found while testing: WriterTests.ReadableWhileRunning and WriterTests.RetriesWhenHeld fail sometimes. They read the live frames.csv with File.ReadAllLines (FileShare.Read) while the writer holds it for append. Also, tests/SampleSession.cs sets Probe.PatchCallTicks = Ms(0.00005), which truncates to 0 ticks.

Merge notes

Checked with git merge-tree against the current PR heads.

• With Roll named beaver rows up to their kind (NF1) #1 (claude/beaver-rollup): conflicts in tools/perflog.py and docs/TESTING.md.
  • tools/perflog.py: both add 0.1.4 notes and KNOWN_ISSUES entries, a KNOWN_ISSUE_APPLIES map with its helper functions, and a change to profile_totals (Roll named beaver rows up to their kind (NF1) #1 keys by entity kind; this PR adds the branch for rows that were never timed).
  • docs/TESTING.md: the check counts, the table rows and in-game step 7.
  • Resolution: take the union (all three notes and entries, both apply-map entries and all the helpers, Roll named beaver rows up to their kind (NF1) #1's kind key together with this PR's untimed branch), then re-sum the check counts.
• With Analyzer diagnostics: blame only real culprits, split otherMs by Unity phase, read patch headers, mark GC frames in heap mode (PL4, PL5, PL6, PL3) #3 (claude/analyzer-diagnostics): tools/perflog.py, the singleton row print line (give it both suffixes), and docs/TESTING.md (counts and table rows, resolved the same way).
• Merges cleanly with Docs: 0.1.3 version refs, check count, what the 0.1.3 recording verified, event-handler patches in the session guide (PL8, PL7) #4.

🤖 Generated with Claude Code