From ba6f353613cad6724566da28e874ff1a279e0395 Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 04:25:17 -0700 Subject: [PATCH 1/5] PL1: sample each watched method at its own rate, both ways Watched methods (config Watch) chose their sampling interval from the call rate of all watched methods together, and the interval 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, so a rare method's 20 calls of 5 ms often produced no timed call at all: its row was dropped (ms rounded to 0) while the session totals still added the calls at 0 ms. Profile.FlushWindow now calls AdaptMethods before the counters are zeroed: each method's interval for the next window comes from its own calls, is set again every window (never below the interval it was registered with, never above 4096), and the methods' share of the budget is split between the methods that ran. Every method's countdown restarts at 1 at each window start, so a method that runs has its first call of the window timed. A watched method gets a row for every window it ran in; 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. tools/perflog.py leaves such rows out of calls and ms the same way and says how many calls were never timed. Tests: WatchSamplingTests (from the PL1 part of the verification harness, with the rare-method check tightened to every window) and a test_perflog check. Column descriptions changed, so the fixtures' columns.md and README.md are regenerated. Co-Authored-By: Claude Opus 5 --- docs/SESSION-README.md | 3 +- docs/TESTING.md | 3 +- source/Core/Columns.cs | 2 +- source/Core/Profile.cs | 72 +++++++--- tests/PL1WatchSamplingTests.cs | 135 +++++++++++++++++++ tests/Program.cs | 1 + tests/fixtures/sample-with-mod/README.md | 5 +- tests/fixtures/sample-with-mod/columns.md | 4 +- tests/fixtures/sample-without-mod/README.md | 5 +- tests/fixtures/sample-without-mod/columns.md | 4 +- tools/perflog.py | 9 +- tools/test_perflog.py | 11 ++ 12 files changed, 222 insertions(+), 32 deletions(-) create mode 100644 tests/PL1WatchSamplingTests.cs diff --git a/docs/SESSION-README.md b/docs/SESSION-README.md index d6f7769..7eee81d 100644 --- a/docs/SESSION-README.md +++ b/docs/SESSION-README.md @@ -32,7 +32,8 @@ memory went; what to change is a judgement you make from them, and you should sa sources worked on this computer. `prGcBytes`, `ftGpu` and friends are 0 when Unity's release build does not provide them; `mainCpuMs` is 0 off Windows. 7. **`profile.csv` is partly estimated.** Singletons are timed on every call. Entity kinds, components and watched methods are timed on every Nth - call and scaled up (`sampled` says how many real timings a row rests on; a small number means a rough figure). `allocKB` is coarse when the + call and scaled up (`sampled` says how many real timings a row rests on; a small number means a rough figure, and a watched method's row with + `sampled` 0 was not timed at all, so its `ms` is unknown, not 0). `allocKB` is coarse when the allocation source is the heap size (see the `allocSource` capability line). 8. **Measuring costs something.** `overheadUs` (the estimate) plus `probeUs` (closing the frame) are microseconds per frame that the mod itself used. If they are more than about 2% of `frameMs`, say so before trusting small differences. diff --git a/docs/TESTING.md b/docs/TESTING.md index 776e3c4..997a9e3 100644 --- a/docs/TESTING.md +++ b/docs/TESTING.md @@ -6,7 +6,7 @@ the game running. This is the honest list. ## Verified by the automated checks -`dotnet run --project tests -c Release` (91 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (44 checks). +`dotnet run --project tests -c Release` (94 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (45 checks). | What | How | |---|---| @@ -14,6 +14,7 @@ the game running. This is the honest list. | The per-frame path allocates nothing | `GC.GetAllocatedBytesForCurrentThread` around 2000 frames; also for a wrapper with the log off | | Failure containment: a failing clock switches the probe off, a full ring drops rows and counts them | `CoreTests` | | The profile: exact singleton timing, scaled sampling, random gaps that do not alias with a repeating pattern, budget adaptation, spike attribution, mod resolution | `ProfileTests` | +| Watched methods: each is sampled at its own rate, widening with its own load inside the budget and coming back down after, with a row (and at least one timing) for every window it ran in; calls nobody timed get a `sampled` 0 row and stay out of the totals | `WatchSamplingTests`, `test_perflog` | | The files: header, columns, invariant number format in any language, text tails, events, a file rewritten whole, an unopenable path, dropped rows, flush on stop | `WriterTests` | | `summary.md`, `README.md` and `columns.md` generation | `SummaryTests`, `WriterTests.EndToEnd` | | Every patch target exists in the installed game (1.1.2.4), has no exception filter, and takes only parameters Harmony can supply | `GameBindingTests.TargetsResolve` | diff --git a/source/Core/Columns.cs b/source/Core/Columns.cs index 9f68d59..0c8fb3a 100644 --- a/source/Core/Columns.cs +++ b/source/Core/Columns.cs @@ -415,7 +415,7 @@ public static class ProfileKinds "A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed.", "All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled').", "All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep.", - "One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly and every Nth is timed.", + "One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed, N widening only while that method itself is busy. It has a row for every window it ran in.", "A singleton's Load while the game was loading (one row per singleton, window 0).", "A non-singleton loader's LoadNonSingletons while the game was loading (window 0).", "A singleton's PostLoad while the game was loading (window 0).", diff --git a/source/Core/Profile.cs b/source/Core/Profile.cs index 6c21a13..7bebd70 100644 --- a/source/Core/Profile.cs +++ b/source/Core/Profile.cs @@ -41,7 +41,7 @@ public static class Profile new Column { Name = "tick", Kind = ColumnKind.Int, Aggregate = Aggregate.Last, Unit = "count", Description = "Simulation ticks since the log started, at the end of the window." }, new Column { Name = "id", Kind = ColumnKind.Int, Aggregate = Aggregate.Last, Unit = "", Description = "The key's number, the same in profile.csv and spikes.csv." }, new Column { Name = "calls", Kind = ColumnKind.Int, Aggregate = Aggregate.Sum, Unit = "count", Description = "Calls in the window. Exact for singletons and watched methods, estimated (samples times the interval) for entities and components." }, - new Column { Name = "sampled", Kind = ColumnKind.Int, Aggregate = Aggregate.Sum, Unit = "count", Description = "Calls that were actually timed. ms and allocKB are scaled up from these, so a small number means a rough estimate." }, + new Column { Name = "sampled", Kind = ColumnKind.Int, Aggregate = Aggregate.Sum, Unit = "count", Description = "Calls that were actually timed. ms and allocKB are scaled up from these, so a small number means a rough estimate. 0 (a watched method whose timed calls all threw) means none was: ms and allocKB are then unknown, not zero." }, new Column { Name = "ms", Kind = ColumnKind.Fixed2, Aggregate = Aggregate.Sum, Unit = "ms", Description = "Time spent in all the calls in the window (scaled up from the sampled ones), including everything inside them." }, new Column { Name = "allocKB", Kind = ColumnKind.Fixed1, Aggregate = Aggregate.Sum, Unit = "KB", Description = "Managed memory allocated by all the calls in the window (scaled up). Coarse when the allocation source is the heap size. For load steps (window 0) it is how much the managed heap grew during the step; a collection in the middle makes it read low." }, new Column { Name = "maxMs", Kind = ColumnKind.Fixed2, Aggregate = Aggregate.Max, Unit = "ms", Description = "The slowest timed call in the window. A large value with a small ms is a rare hitch." }, @@ -93,7 +93,8 @@ sealed class Entry public string Name = ""; public string Assembly = ""; public string Mod = ""; - public int MethodInterval = 8; + /// A watched method's interval for this window, and the one it was registered with (the least it goes back to). + public int MethodInterval = 8, GivenInterval = 8; } static readonly object gate = new object(); @@ -115,7 +116,7 @@ sealed class Entry // same order every frame, and a fixed stride can land on the same few of them every time and never on the rest. static int entityCountdown = 1, componentCountdown = 1, allocCountdown = 1; static uint random = 2463534242; - static long windowEntityCalls, windowComponentCalls, windowExactCalls, windowMethodCalls; + static long windowEntityCalls, windowComponentCalls, windowExactCalls; static int frameExact, frameAllocPairs, frameSampledPairs; static readonly double[] row = new double[Table.Count]; static readonly double[] spikeRow = new double[SpikeTable.Count]; @@ -164,7 +165,7 @@ public static void Reset() Array.Clear(totalCalls, 0, totalCalls.Length); Array.Clear(totalMax, 0, totalMax.Length); touchedCount = 0; TopCount = 0; SeedSampling(2463534242); - windowEntityCalls = 0; windowComponentCalls = 0; windowExactCalls = 0; windowMethodCalls = 0; + windowEntityCalls = 0; windowComponentCalls = 0; windowExactCalls = 0; frameExact = 0; frameAllocPairs = 0; frameSampledPairs = 0; EntityInterval = 16; ComponentInterval = 64; AllocEvery = 4; entityCountdown = Gap(EntityInterval); componentCountdown = Gap(ComponentInterval); allocCountdown = Gap(AllocEvery); @@ -318,10 +319,9 @@ public static void EndComponent(Type component, in Sample s) catch (Exception) { } } - /// Called before a watched method runs: counts the call exactly and times every Nth. + /// Called before a watched method runs: counts the call exactly, and times the first call of each window and about every Nth after it. public static Sample BeginMethod(int id) { - windowMethodCalls++; calls[id]++; if (--methodCounter[id] > 0) return default; methodCounter[id] = Gap(entries[id].MethodInterval); @@ -346,7 +346,7 @@ public static void EndMethod(int id, in Sample s) public static int RegisterMethod(string name, string assembly, int interval) { int id = IdFor(ProfileKind.Method, name, assembly); - lock (gate) entries[id].MethodInterval = Math.Max(1, interval); + lock (gate) entries[id].MethodInterval = entries[id].GivenInterval = Math.Max(1, interval); return id; } @@ -444,15 +444,28 @@ public static void FlushWindow(int window, int tick, double windowSeconds, Ring double msPerTick = 1000.0 / Stopwatch.Frequency; int count; lock (gate) count = entries.Count; + AdaptMethods(windowSeconds); for (int id = 0; id < count; id++) { if (calls[id] == 0 && timed[id] == 0) continue; - double factor = timed[id] > 0 ? (double)Math.Max(calls[id], timed[id]) / timed[id] : 0; + if (timed[id] == 0) + { + // Counted but never timed: a watched method whose timed calls all threw (Harmony skips the postfix then). The row says so + // with sampled 0; its time is unknown, so the session totals get nothing rather than these calls at 0 ms. + Array.Clear(row, 0, row.Length); + row[0] = (int)KindOf(id); row[1] = window; row[2] = tick; row[3] = id; row[4] = calls[id]; + target?.TryPush(row); + calls[id] = 0; ticks[id] = 0; allocN[id] = 0; allocB[id] = 0; max[id] = 0; + continue; + } + double factor = (double)Math.Max(calls[id], timed[id]) / timed[id]; double ms = ticks[id] * msPerTick * factor; double kb = allocN[id] > 0 ? allocB[id] / 1024.0 * ((double)Math.Max(calls[id], allocN[id]) / allocN[id]) : 0; double maxMs = max[id] * msPerTick; totalMs[id] += ms; totalKb[id] += kb; totalCalls[id] += calls[id]; if (maxMs > totalMax[id]) totalMax[id] = maxMs; - if (ms >= 0.005 || kb >= 0.5 || maxMs >= 0.5) + // A watched method gets a row for every window it ran in, however little it took (there are at most a few dozen), so a + // missing row always means it was not called. + if (ms >= 0.005 || kb >= 0.5 || maxMs >= 0.5 || KindOf(id) == ProfileKind.Method) { Array.Clear(row, 0, row.Length); row[0] = (int)KindOf(id); row[1] = window; row[2] = tick; row[3] = id; @@ -477,21 +490,42 @@ static void Adapt(double windowSeconds) ComponentInterval = Clamp((int)Math.Ceiling(windowComponentCalls / windowSeconds * pairSeconds / (budget * BudgetShareComponent)), 1, 8192); double allocPairSeconds = Math.Max(Probe.AllocPairTicks / frequency, 20e-9); AllocEvery = Clamp((int)Math.Ceiling(windowExactCalls / windowSeconds * allocPairSeconds / (budget * BudgetShareAlloc)), 1, 1024); - // Watched methods keep the interval they were given unless they turn out to be very hot. - lock (gate) + } + } + catch (Exception) { } + windowEntityCalls = 0; windowComponentCalls = 0; windowExactCalls = 0; + } + + /// + /// Chooses each watched method's interval for the next window from that method's own calls in this one, before they are forgotten. + /// It is set again every window and never below the interval the method was given, so a method that was busy once comes back down + /// when it quietens, and a rare one next to a busy one keeps its own. The methods' share of the budget is split between the methods + /// that ran. Each countdown starts again at 1, so a method that runs in the next window has its first call timed. + /// + static void AdaptMethods(double windowSeconds) + { + try + { + lock (gate) + { + int ran = 0; + for (int id = 0; id < entries.Count; id++) + if (entries[id].Kind == ProfileKind.Method && calls[id] > 0) ran++; + bool measured = windowSeconds > 0 && Probe.SamplePairTicks > 0; + double pairSeconds = Probe.SamplePairTicks / Stopwatch.Frequency + 100e-9; // the key lookup too + double budget = BudgetFraction * BudgetShareMethod / Math.Max(1, ran); + for (int id = 0; id < entries.Count; id++) { - foreach (Entry e in entries) - { - if (e.Kind != ProfileKind.Method) continue; - double perSecond = windowMethodCalls / windowSeconds; - int wanted = Clamp((int)Math.Ceiling(perSecond * pairSeconds / (budget * BudgetShareMethod)), 1, 4096); - if (wanted > e.MethodInterval) e.MethodInterval = wanted; - } + Entry e = entries[id]; + if (e.Kind != ProfileKind.Method) continue; + double wanted = measured && calls[id] > 0 ? Math.Ceiling(calls[id] / windowSeconds * pairSeconds / budget) : 0; + int most = Math.Max(e.GivenInterval, 4096); + e.MethodInterval = wanted >= most ? most : Math.Max(e.GivenInterval, (int)wanted); + methodCounter[id] = 1; } } } catch (Exception) { } - windowEntityCalls = 0; windowComponentCalls = 0; windowExactCalls = 0; windowMethodCalls = 0; } static int Clamp(int value, int low, int high) => value < low ? low : value > high ? high : value; diff --git a/tests/PL1WatchSamplingTests.cs b/tests/PL1WatchSamplingTests.cs new file mode 100644 index 0000000..8650bf3 --- /dev/null +++ b/tests/PL1WatchSamplingTests.cs @@ -0,0 +1,135 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; +using static PerformanceLog.Tests.Assert; + +namespace PerformanceLog.Tests +{ + // PL1: a watched method's sampling interval follows that method's own call rate, in both directions, and every window it ran in has a row. + internal static class WatchSamplingTests + { + public static IEnumerable<(string, Action)> All() + { + yield return ("Profile: a rare watched method next to a hot one is still timed in every window it runs", RareMethodNextToHotOne); + yield return ("Profile: a watched method's interval widens with its own load, inside the budget, and comes back down when the load goes away", IntervalFollowsTheLoad); + yield return ("Profile: a watched method that ran but was never timed gets a row with sampled 0 and adds no made-up 0 ms to the totals", UntimedWindowIsWrittenNotGuessed); + } + + const double PairNs = 50; // what the real recordings calibrate for a sampled pair (samplePairNs) + + static Rig rig; + + static void Prepare() + { + rig = new Rig(); + Profile.Configure(1, 1, 1); + Profile.BudgetFraction = 0.01; + Profile.ModResolver = null; + Profile.SeedSampling(12345); + // A double, not Rig.Ms: Rig.Ms truncates to whole Stopwatch ticks, and 50 ns is 0 ticks at 10 MHz, which switches the adaptation off. + Probe.SamplePairTicks = PairNs * 1e-9 * Stopwatch.Frequency; + } + + static void Call(int id, double ms) + { + Sample s = Profile.BeginMethod(id); + rig.Advance(ms); + Profile.EndMethod(id, s); + } + + static double[] RowOf(List rows, int id) => rows.FirstOrDefault(r => (int)r[3] == id); + + static void RareMethodNextToHotOne() + { + Prepare(); + using (rig) + { + int hot = Profile.RegisterMethod("Hot.Method", "M", 8); + int rare = Profile.RegisterMethod("Rare.Method", "M", 8); + // Window 1: the hot one runs 2 million times in 10 s (200,000 a second, 1 us a call); the rare one once. + Call(rare, 5); + for (int i = 0; i < 2000000; i++) Call(hot, 0.001); + Profile.FlushWindow(1, 1, 10, rig.Prof); + rig.ProfileRows(); + // Windows 2 to 5: only the rare one runs, 20 times a window at 5 ms a call. Its own rate (2 a second) needs no more than the + // interval it was given (8), so every window times its first call and, with gaps of at most 15, at least one more. + for (int w = 2; w <= 5; w++) + { + for (int i = 0; i < 20; i++) Call(rare, 5); + Profile.FlushWindow(w, w, 10, rig.Prof); + double[] row = RowOf(rig.ProfileRows(), rare); + Console.WriteLine(" window " + w + ": rare method " + (row == null ? "has no row" : "calls=" + row[4] + " sampled=" + row[5] + " ms=" + row[6])); + Check(row != null, "window " + w + ": the rare method's 20 calls of 5 ms left no row (none was timed)"); + Equal(20.0, row[4], "window " + w + ": calls"); + Check(row[5] >= 2, "window " + w + ": only " + row[5] + " of 20 calls were timed; the interval is still the one the hot method needed"); + Near(100, row[6], .01, "window " + w + ": 20 calls of 5 ms"); + } + Profile.Total total = Profile.Totals().Single(t => t.Id == rare); + Equal(81.0, total.Calls, "session calls"); + Near(405, total.Ms, .01, "session ms: 5 ms, then four windows of 100 ms"); + } + } + + static void IntervalFollowsTheLoad() + { + Prepare(); + using (rig) + { + int hot = Profile.RegisterMethod("Hot.Method", "M", 8); + // Two busy windows of 200,000 calls a second: the second is timed at the interval the first asked for, which keeps measuring inside + // the watched methods' share of the budget (1% of a second, a tenth of it for methods). + double[] busy = null; + for (int w = 1; w <= 2; w++) + { + for (int i = 0; i < 2000000; i++) Call(hot, 0.001); + Profile.FlushWindow(w, w, 10, rig.Prof); + busy = RowOf(rig.ProfileRows(), hot); + Check(busy != null, "busy window " + w + ": no row"); + } + double pairSeconds = PairNs * 1e-9 + 100e-9; // the pair plus the key lookup, as Profile charges it + double share = busy[5] * pairSeconds / 10; + Console.WriteLine(" busy window: " + busy[5] + " of 2000000 calls timed, " + (share * 100).ToString("F3") + "% of a second"); + Check(busy[5] < 2000000 / 20.0, "a hot method's interval widens: " + busy[5] + " of 2000000 calls were timed"); + Check(share <= 0.01 * Profile.BudgetShareMethod * 1.05, "measuring stays inside the methods' share of the budget: " + share); + // Then the load goes away: 100 calls of 1 ms a window. The first quiet window is still timed at the busy interval; after it the + // interval is back to 8, so each later window times its first call and, with gaps of at most 15, at least six more. + for (int w = 3; w <= 6; w++) + { + for (int i = 0; i < 100; i++) Call(hot, 1); + Profile.FlushWindow(w, w, 10, rig.Prof); + double[] row = RowOf(rig.ProfileRows(), hot); + Console.WriteLine(" quiet window " + w + ": sampled=" + (row == null ? "no row" : row[5].ToString()) + " of 100 calls"); + Check(row != null, "window " + w + ": no row"); + Near(100, row[6], .01, "window " + w + ": 100 calls of 1 ms"); + if (w >= 4) Check(row[5] >= 7, "window " + w + ": only " + row[5] + " of 100 calls were timed; the interval never came back down after the busy windows"); + } + } + } + + static void UntimedWindowIsWrittenNotGuessed() + { + Prepare(); + using (rig) + { + int id = Profile.RegisterMethod("Throwing.Method", "M", 8); + Call(id, 2); + Profile.FlushWindow(1, 1, 10, rig.Prof); + double[] first = RowOf(rig.ProfileRows(), id); + Check(first != null && first[5] == 1, "window 1: the one call was timed"); + // Window 2: three calls whose postfix never runs (the method threw, and Harmony skips a postfix then), so none is timed. + for (int i = 0; i < 3; i++) Profile.BeginMethod(id); + Profile.FlushWindow(2, 2, 10, rig.Prof); + double[] row = RowOf(rig.ProfileRows(), id); + Console.WriteLine(" untimed window: " + (row == null ? "no row" : "calls=" + row[4] + " sampled=" + row[5] + " ms=" + row[6])); + Check(row != null, "window 2: the method ran 3 times and left no row, which reads as 'not called'"); + Equal(3.0, row[4], "calls are still exact"); + Equal(0.0, row[5], "sampled 0 says nothing was timed"); + Profile.Total total = Profile.Totals().Single(t => t.Id == id); + Console.WriteLine(" totals: calls=" + total.Calls + " ms=" + total.Ms); + Equal(1.0, total.Calls, "the session totals leave out the calls nobody timed, instead of adding them at 0 ms"); + Near(2, total.Ms, .001, "session ms"); + } + } + } +} diff --git a/tests/Program.cs b/tests/Program.cs index 19aae02..cfb9f8a 100644 --- a/tests/Program.cs +++ b/tests/Program.cs @@ -60,6 +60,7 @@ static int Run(string[] args) var tests = new List<(string Name, Action Run)>(); tests.AddRange(CoreTests.All()); tests.AddRange(ProfileTests.All()); + tests.AddRange(WatchSamplingTests.All()); tests.AddRange(WriterTests.All()); tests.AddRange(SummaryTests.All()); tests.AddRange(GameBindingTests.All(managed)); diff --git a/tests/fixtures/sample-with-mod/README.md b/tests/fixtures/sample-with-mod/README.md index 2687cb5..201807a 100644 --- a/tests/fixtures/sample-with-mod/README.md +++ b/tests/fixtures/sample-with-mod/README.md @@ -32,7 +32,8 @@ memory went; what to change is a judgement you make from them, and you should sa sources worked on this computer. `prGcBytes`, `ftGpu` and friends are 0 when Unity's release build does not provide them; `mainCpuMs` is 0 off Windows. 7. **`profile.csv` is partly estimated.** Singletons are timed on every call. Entity kinds, components and watched methods are timed on every Nth - call and scaled up (`sampled` says how many real timings a row rests on; a small number means a rough figure). `allocKB` is coarse when the + call and scaled up (`sampled` says how many real timings a row rests on; a small number means a rough figure, and a watched method's row with + `sampled` 0 was not timed at all, so its `ms` is unknown, not 0). `allocKB` is coarse when the allocation source is the heap size (see the `allocSource` capability line). 8. **Measuring costs something.** `overheadUs` (the estimate) plus `probeUs` (closing the frame) are microseconds per frame that the mod itself used. If they are more than about 2% of `frameMs`, say so before trusting small differences. @@ -116,7 +117,7 @@ the last bucket is everything above), and `th0`..`th5` count frames that ran 0, - `parallel-start`: A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed. - `entity`: All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled'). - `component`: All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep. -- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly and every Nth is timed. +- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed, N widening only while that method itself is busy. It has a row for every window it ran in. - `load`: A singleton's Load while the game was loading (one row per singleton, window 0). - `load-non-singleton`: A non-singleton loader's LoadNonSingletons while the game was loading (window 0). - `post-load`: A singleton's PostLoad while the game was loading (window 0). diff --git a/tests/fixtures/sample-with-mod/columns.md b/tests/fixtures/sample-with-mod/columns.md index bbb3b39..84b2b36 100644 --- a/tests/fixtures/sample-with-mod/columns.md +++ b/tests/fixtures/sample-with-mod/columns.md @@ -112,7 +112,7 @@ One row per key per window. The last three columns (`name`, `assembly`, `mod`) a - `parallel-start`: A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed. - `entity`: All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled'). - `component`: All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep. -- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly and every Nth is timed. +- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed, N widening only while that method itself is busy. It has a row for every window it ran in. - `load`: A singleton's Load while the game was loading (one row per singleton, window 0). - `load-non-singleton`: A non-singleton loader's LoadNonSingletons while the game was loading (window 0). - `post-load`: A singleton's PostLoad while the game was loading (window 0). @@ -125,7 +125,7 @@ One row per key per window. The last three columns (`name`, `assembly`, `mod`) a | `tick` | count | last | Simulation ticks since the log started, at the end of the window. | | `id` | | last | The key's number, the same in profile.csv and spikes.csv. | | `calls` | count | total | Calls in the window. Exact for singletons and watched methods, estimated (samples times the interval) for entities and components. | -| `sampled` | count | total | Calls that were actually timed. ms and allocKB are scaled up from these, so a small number means a rough estimate. | +| `sampled` | count | total | Calls that were actually timed. ms and allocKB are scaled up from these, so a small number means a rough estimate. 0 (a watched method whose timed calls all threw) means none was: ms and allocKB are then unknown, not zero. | | `ms` | ms | total | Time spent in all the calls in the window (scaled up from the sampled ones), including everything inside them. | | `allocKB` | KB | total | Managed memory allocated by all the calls in the window (scaled up). Coarse when the allocation source is the heap size. For load steps (window 0) it is how much the managed heap grew during the step; a collection in the middle makes it read low. | | `maxMs` | ms | largest | The slowest timed call in the window. A large value with a small ms is a rare hitch. | diff --git a/tests/fixtures/sample-without-mod/README.md b/tests/fixtures/sample-without-mod/README.md index 2687cb5..201807a 100644 --- a/tests/fixtures/sample-without-mod/README.md +++ b/tests/fixtures/sample-without-mod/README.md @@ -32,7 +32,8 @@ memory went; what to change is a judgement you make from them, and you should sa sources worked on this computer. `prGcBytes`, `ftGpu` and friends are 0 when Unity's release build does not provide them; `mainCpuMs` is 0 off Windows. 7. **`profile.csv` is partly estimated.** Singletons are timed on every call. Entity kinds, components and watched methods are timed on every Nth - call and scaled up (`sampled` says how many real timings a row rests on; a small number means a rough figure). `allocKB` is coarse when the + call and scaled up (`sampled` says how many real timings a row rests on; a small number means a rough figure, and a watched method's row with + `sampled` 0 was not timed at all, so its `ms` is unknown, not 0). `allocKB` is coarse when the allocation source is the heap size (see the `allocSource` capability line). 8. **Measuring costs something.** `overheadUs` (the estimate) plus `probeUs` (closing the frame) are microseconds per frame that the mod itself used. If they are more than about 2% of `frameMs`, say so before trusting small differences. @@ -116,7 +117,7 @@ the last bucket is everything above), and `th0`..`th5` count frames that ran 0, - `parallel-start`: A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed. - `entity`: All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled'). - `component`: All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep. -- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly and every Nth is timed. +- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed, N widening only while that method itself is busy. It has a row for every window it ran in. - `load`: A singleton's Load while the game was loading (one row per singleton, window 0). - `load-non-singleton`: A non-singleton loader's LoadNonSingletons while the game was loading (window 0). - `post-load`: A singleton's PostLoad while the game was loading (window 0). diff --git a/tests/fixtures/sample-without-mod/columns.md b/tests/fixtures/sample-without-mod/columns.md index bbb3b39..84b2b36 100644 --- a/tests/fixtures/sample-without-mod/columns.md +++ b/tests/fixtures/sample-without-mod/columns.md @@ -112,7 +112,7 @@ One row per key per window. The last three columns (`name`, `assembly`, `mod`) a - `parallel-start`: A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed. - `entity`: All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled'). - `component`: All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep. -- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly and every Nth is timed. +- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed, N widening only while that method itself is busy. It has a row for every window it ran in. - `load`: A singleton's Load while the game was loading (one row per singleton, window 0). - `load-non-singleton`: A non-singleton loader's LoadNonSingletons while the game was loading (window 0). - `post-load`: A singleton's PostLoad while the game was loading (window 0). @@ -125,7 +125,7 @@ One row per key per window. The last three columns (`name`, `assembly`, `mod`) a | `tick` | count | last | Simulation ticks since the log started, at the end of the window. | | `id` | | last | The key's number, the same in profile.csv and spikes.csv. | | `calls` | count | total | Calls in the window. Exact for singletons and watched methods, estimated (samples times the interval) for entities and components. | -| `sampled` | count | total | Calls that were actually timed. ms and allocKB are scaled up from these, so a small number means a rough estimate. | +| `sampled` | count | total | Calls that were actually timed. ms and allocKB are scaled up from these, so a small number means a rough estimate. 0 (a watched method whose timed calls all threw) means none was: ms and allocKB are then unknown, not zero. | | `ms` | ms | total | Time spent in all the calls in the window (scaled up from the sampled ones), including everything inside them. | | `allocKB` | KB | total | Managed memory allocated by all the calls in the window (scaled up). Coarse when the allocation source is the heap size. For load steps (window 0) it is how much the managed heap grew during the step; a collection in the middle makes it read low. | | `maxMs` | ms | largest | The slowest timed call in the window. A large value with a small ms is a rare hitch. | diff --git a/tools/perflog.py b/tools/perflog.py index 39bd17f..f6c5fe1 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -316,6 +316,7 @@ class KeyTotal: def __init__(self, kind, name, mod, assembly): self.kind, self.name, self.mod, self.assembly = kind, name, mod, assembly self.ms = self.kb = self.calls = self.sampled = self.max_ms = 0.0 + self.untimed = 0.0 # calls in rows with sampled 0 (a watched method nobody timed in that window): not in calls, so ms/calls stays honest def profile_totals(session, tick_from=0, tick_to=None): @@ -330,6 +331,9 @@ def profile_totals(session, tick_from=0, tick_to=None): t = totals.get(key) if t is None: t = totals[key] = KeyTotal(r["kind"], r.get("name", ""), r.get("mod", ""), r.get("assembly", "")) + if r["sampled"] <= 0 and r["calls"] > 0: + t.untimed += r["calls"] + continue t.ms += r["ms"]; t.kb += r["allocKB"]; t.calls += r["calls"]; t.sampled += r["sampled"]; t.max_ms = max(t.max_ms, r["maxMs"]) return totals @@ -711,8 +715,9 @@ def report(session, args, out): all_ms = sum(t.ms for t in rows) p(" %s: %.1f ms/s in all" % (title, all_ms / window_secs)) for t in rows[:(len(rows) if args.all else args.top)]: - p(" %-58s %-26s %8.2f ms/s %4s %6.1f us/call %7.1f KB/s slowest %.2f ms" % ( - short(t.name, 58), (mod_of(session, t) or "")[:26], t.ms / window_secs, pct(t.ms, all_ms), t.ms * 1000 / t.calls if t.calls else 0, t.kb / window_secs, t.max_ms)) + p(" %-58s %-26s %8.2f ms/s %4s %6.1f us/call %7.1f KB/s slowest %.2f ms%s" % ( + short(t.name, 58), (mod_of(session, t) or "")[:26], t.ms / window_secs, pct(t.ms, all_ms), t.ms * 1000 / t.calls if t.calls else 0, t.kb / window_secs, t.max_ms, + " (+%d calls never timed)" % t.untimed if t.untimed else "")) mods = collections.defaultdict(lambda: [0.0, 0.0]) for t in totals.values(): if t.kind in ("tick-singleton", "update-singleton", "late-singleton"): diff --git a/tools/test_perflog.py b/tools/test_perflog.py index 72d3064..f7257e5 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -551,6 +551,17 @@ def test_game_singletons_with_an_empty_mod_are_read_as_the_game(self): self.assertRegex(text, r"Timberborn\.SomethingUI\.Panel\s+game\b") self.assertRegex(text, r"Other\.Library\.Thing\s+\(unknown\)") + def test_a_watched_method_window_nobody_timed_is_not_counted_at_0_ms(self): + s = Synthetic() + for w in range(1, 7): + s.window() + # Five windows timed at 0.5 ms a call; in the sixth every timed call threw, so the mod wrote the calls with sampled 0 and no time. + timed = w <= 5 + s.profile.append({"kind": "method", "window": w, "tick": s.tick, "id": 3, "calls": 100 if timed else 40, "sampled": 10 if timed else 0, + "ms": 50.0 if timed else 0.0, "allocKB": 0, "maxMs": 0.6 if timed else 0.0, "name": "Some.Mod.Method()", "assembly": "SomeMod", "mod": "somemod"}) + text = self.report(s) + self.assertRegex(text, r"Some\.Mod\.Method\(\).*\b500\.0 us/call.*\(\+40 calls never timed\)") + def test_loading_that_grew_the_heap_is_reported(self): s = Synthetic() for _ in range(6): From 4030581e330ff2d2962787f2c525e04d3cc2f72c Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 04:29:34 -0700 Subject: [PATCH 2/5] NF2: charge each patch call what its bodies really cost overheadUs charges every call of the per-call patches (entity ticks, components, watched methods; the patchCalls counter) PatchCallTicks. That was measured by patching a method of our own with an empty prefix and postfix, which came out under half a nanosecond in the game, so every recording up to 0.1.3 says patchCallNs|0 and overheadUs, and the 2% "measuring cost too much" warnings built on it, left out about 100,000 patch calls a second at speed 7. Instrumentation.MeasurePatchCost now times the real EntityPrefix and EntityPostfix on the unsampled path (Probe.MeasureUnsampled: the probe switched on, entity and component sampling held off with Profile.HoldSampling, fastest of five warmed-up rounds, probe and profile left as a log start expects) and adds what Harmony adds to call a prefix and a postfix (the old empty-patch measurement, now with the same Sample state, clamped at 0). The calibration header line gains patchBodyNs, and patchCallNs is written with one decimal; if the body could not be measured both say "unmeasured" and the 40 ns assumption overheadUs then uses is named instead of hidden. tools/perflog.py gets a KNOWN_ISSUES note (fixed in 0.1.4) that overheadUs understates the mod's cost, printed only for recordings whose calibration line has no patchBodyNs, so a build of the fix that still says 0.1.3 is not flagged. docs/TESTING.md no longer claims 0.1.1 measures the patch cost, and the five-minute check looks at the new calibration fields. Co-Authored-By: Claude Opus 5 --- docs/TESTING.md | 7 +++-- source/Core/Probe.cs | 49 +++++++++++++++++++++++++++++++--- source/Core/Profile.cs | 9 +++++++ source/Game/Instrumentation.cs | 35 ++++++++++++++++++------ source/Game/Session.cs | 8 ++++-- tests/CoreTests.cs | 36 ++++++++++++++++++++++++- tests/GameBindingTests.cs | 36 +++++++++++++++++++++++++ tools/perflog.py | 20 +++++++++++++- tools/test_perflog.py | 12 +++++++++ 9 files changed, 195 insertions(+), 17 deletions(-) diff --git a/docs/TESTING.md b/docs/TESTING.md index 997a9e3..86c32ce 100644 --- a/docs/TESTING.md +++ b/docs/TESTING.md @@ -6,13 +6,14 @@ the game running. This is the honest list. ## Verified by the automated checks -`dotnet run --project tests -c Release` (94 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (45 checks). +`dotnet run --project tests -c Release` (96 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (46 checks). | What | How | |---|---| | Frame accounting: slots are exclusive and add up to the frame; unbalanced scopes; other threads ignored; allocation attribution; flags; ticks and buckets; Unity phases; summaries and histograms | Real `Probe` against a scripted clock (`CoreTests`) | | The per-frame path allocates nothing | `GC.GetAllocatedBytesForCurrentThread` around 2000 frames; also for a wrapper with the log off | | Failure containment: a failing clock switches the probe off, a full ring drops rows and counts them | `CoreTests` | +| The cost charged for each patch call (`patchCallNs`) is at least what the entity patch's own bodies take on a call that is not sampled, timed with the log on and sampling held off (the part Harmony adds needs the game) | `CoreTests.UnsampledBodyTiming`, `GameBindingTests.PatchCostCoversTheBodies` | | The profile: exact singleton timing, scaled sampling, random gaps that do not alias with a repeating pattern, budget adaptation, spike attribution, mod resolution | `ProfileTests` | | Watched methods: each is sampled at its own rate, widening with its own load inside the budget and coming back down after, with a row (and at least one timing) for every window it ran in; calls nobody timed get a `sampled` 0 row and stay out of the totals | `WatchSamplingTests`, `test_perflog` | | The files: header, columns, invariant number format in any language, text tails, events, a file rewritten whole, an unopenable path, dropped rows, flush on stop | `WriterTests` | @@ -65,7 +66,8 @@ heap and is coarse**. The per-singleton `KB/s` figures are therefore only good i 1. **The 0.1.1 fixes themselves**: that each service is wrapped once (`# capability-final|patchCalls|singleton wrappers put in place` should be a handful, not hundreds of thousands), that the four files can be zipped while the game runs, that `workingMB` is non-zero, that game singletons show `game`, that loading steps show a heap growth, and that `prDraw` is non-zero. 2. **Overhead** measured against a game running without the mod. The mod's own estimate (0.1.0: 0.3% of a frame paused, 0.8% at speed 7) left out the wrapper swapping and used a default cost for a - patch; 0.1.1 measures the patch cost, but nobody has compared the frame rate with the mod off. See the checklist. + patch. 0.1.1 to 0.1.3 measured the patch cost on an empty patch, which read 0 in every recording (`patchCallNs|0`), so their `overheadUs` leaves the per-call patches out; the cost is now + the real bodies (`patchBodyNs`) plus what Harmony adds (`patchCallNs`), but that has not run in a game yet, and nobody has compared the frame rate with the mod off. See the checklist. 3. **Co-op**: with BeaverBuddies actually connected to another player. It has only been seen running with BeaverBuddies loaded in a single-player game. 4. **`Ticker.FinishFullTick`** (one of the four save-stage patches) is counted inside `save stages`, so it has not been seen separately; the stages of three saves were recorded. 5. **The mod attribution** (which DLL belongs to which mod) worked for the mods in the first recording (`beaverbuddies`, `Kyler.OptimizedLocalHousing`, `eMka.ModSettings`, `kyler.persistentworkareas`); @@ -100,6 +102,7 @@ heap and is coarse**. The per-singleton `KB/s` figures are therefore only good i `# capability-final|patchCalls|...` lines at the end say non-zero counts, and none says `never ran`, including `MeteredTickableComponent.Tick (sampled calls)`. `singleton wrappers put in place` should be a handful (one or two per array). `# capability|workingSet|...` should say `from Windows`. `# capability-final|profilerRecorder|...` and `frameTiming` may legitimately say `never produced a value` in a release build. + `# calibration|...` has `patchBodyNs` and `patchCallNs` of a few nanoseconds each (not `0` and not `unmeasured`), `patchCallNs` at least `patchBodyNs`. 7. `profile.csv` has rows of kind `component`, not just `entity`. 8. Compare the frame rate the game shows with `summary.md`'s mean; they should agree. 9. Run `python tools/perflog.py report ` and confirm it reads the folder without complaint. diff --git a/source/Core/Probe.cs b/source/Core/Probe.cs index 08c88a7..a09e9d3 100644 --- a/source/Core/Probe.cs +++ b/source/Core/Probe.cs @@ -92,7 +92,7 @@ public static class Probe /// Fills the heavy extras. Called only when a row is about to be written. public static Action HeavySampler; - // What measuring costs, in Stopwatch ticks. Set by Calibrate (and PatchCallTicks by the game side). + // What measuring costs, in Stopwatch ticks. Set by Calibrate (and the two patch costs by the game side, with MeasureUnsampled). public static double ClockReadTicks { get; set; } public static double AllocReadTicks { get; set; } /// One timed scope: Begin and End. @@ -103,8 +103,12 @@ public static class Probe public static double AllocPairTicks { get; set; } /// One call of a singleton that is always timed, without the allocation readings. public static double ExactCallTicks { get; set; } - /// Running one of this mod's Harmony patches that does nothing. + /// The bodies of this mod's per-call patch (the entity tick's prefix and postfix) on a call that is not sampled, which is almost every call. + public static double PatchBodyTicks { get; set; } + /// One call of this mod's per-call patches: plus what Harmony adds to call a prefix and a postfix. 0 if not measured. public static double PatchCallTicks { get; set; } + /// What each patch call is charged in overheadUs: , or 40 ns when it could not be measured (the calibration line says so). + public static double PatchCallTicksCharged => PatchCallTicks > 0 ? PatchCallTicks : 40e-9 * Stopwatch.Frequency; public static bool OnGameThread => Environment.CurrentManagedThreadId == mainThreadId; @@ -210,6 +214,45 @@ public static void Calibrate() catch (Exception e) { LastFailure = e.Message; } } + /// + /// Stopwatch ticks for one of the calls makes when asked for n, timed the way a patch body runs on almost every + /// call while a log is on: the probe switched on, and entity and component sampling held off so that no call is one of the sampled ones + /// (those are charged separately). The fastest of a few rounds after a warm-up, so compiling and the scheduler do not decide the figure. + /// Only while no log is running (0 otherwise, or if it fails); the probe is off and the profile empty afterwards, as a log start expects. + /// + public static double MeasureUnsampled(Action calls, int repeats = 4000, int rounds = 5) + { + if (Enabled || calls == null) return 0; + int savedThread = mainThreadId; + Func savedClock = TestClock; + double best = 0; + try + { + mainThreadId = Environment.CurrentManagedThreadId; + TestClock = null; + Enabled = true; + Profile.HoldSampling(); + calls(repeats / 10 + 1); + best = double.MaxValue; + for (int round = 0; round < rounds; round++) + { + long t0 = Stopwatch.GetTimestamp(); + calls(repeats); + best = Math.Min(best, (Stopwatch.GetTimestamp() - t0) / (double)repeats); + } + } + catch (Exception e) { LastFailure = e.Message; best = 0; } + finally + { + Enabled = false; + TestClock = savedClock; + mainThreadId = savedThread; + Array.Clear(counters, 0, counters.Length); + Profile.Reset(); + } + return best; + } + public static void Start(ProbeSettings settings) { Stop(); @@ -504,7 +547,7 @@ static void Frame(float speed, bool focused) r[Columns.HeapMB] = memory / 1048576.0; r[Columns.AllocKB] = allocKb; r[Columns.Dropped] = frameRing != null ? frameRing.Dropped : 0; - double patchTicks = counters[(int)Counter.PatchCalls] * (PatchCallTicks > 0 ? PatchCallTicks : 0.00000004 * Stopwatch.Frequency); + double patchTicks = counters[(int)Counter.PatchCalls] * PatchCallTicksCharged; r[Columns.OverheadUs] = (frameScopes * ScopePairTicks + profileCost + patchTicks) * msPerTick * 1000; for (int i = 0; i < Columns.CounterCount; i++) r[Columns.CounterBase + i] = counters[i]; diff --git a/source/Core/Profile.cs b/source/Core/Profile.cs index 7bebd70..8d96335 100644 --- a/source/Core/Profile.cs +++ b/source/Core/Profile.cs @@ -195,6 +195,15 @@ public static void Configure(int entityInterval, int componentInterval, int allo entityCountdown = Gap(EntityInterval); componentCountdown = Gap(ComponentInterval); allocCountdown = Gap(AllocEvery); } + /// + /// Holds entity and component sampling off, so no call is one of the sampled ones, until the next or + /// . For timing what the patch bodies cost on the calls that are not sampled (). + /// + internal static void HoldSampling() + { + entityCountdown = int.MaxValue; componentCountdown = int.MaxValue; + } + // ---- keys ---- /// The id of a class's key, registering it on first use. Game thread only. diff --git a/source/Game/Instrumentation.cs b/source/Game/Instrumentation.cs index 425f188..645e791 100644 --- a/source/Game/Instrumentation.cs +++ b/source/Game/Instrumentation.cs @@ -284,13 +284,19 @@ static void InstallOne(PatchSpec spec) } /// - /// What running one of these patches costs when it does nothing, by patching a method of our own. Both loops are warmed up first (the first - /// call of a method is compiled, and a patched one goes through a freshly made wrapper), and the least of a few rounds is taken, so - /// one-off costs and the scheduler do not decide the figure. In the first game recording this read 0 because the unwarmed baseline - /// included the compile. + /// What each call of the per-call patches (entity ticks, components, watched methods) costs, for overheadUs. Two parts: the bodies of the + /// entity tick's prefix and postfix on a call that is not sampled (almost every call; a sampled call's extra cost is charged separately), + /// timed directly with the log on; and what Harmony adds to call a prefix and a postfix, by patching a method of our own with empty ones + /// of the same shape (patched minus unpatched, never below 0). Up to 0.1.3 only the second part was measured; in the game it came out + /// under half a nanosecond, so every recording said patchCallNs 0 and overheadUs left the patches out. Both loops of the second part are warmed + /// up first (the first call of a method is compiled, and a patched one goes through a freshly made wrapper), and the least of a few rounds + /// is taken, so one-off costs and the scheduler do not decide the figure. /// internal static void MeasurePatchCost() { + double body = Probe.MeasureUnsampled(UnsampledEntityCalls); + if (body <= 0) Log.Warning("Could not measure what a patch body costs" + (Probe.LastFailure != null ? ": " + Probe.LastFailure : "") + "; overheadUs assumes 40 ns a patch call."); + double trampoline = 0; try { MethodInfo target = Reflect.Own(typeof(Instrumentation), nameof(CostTarget)); @@ -301,9 +307,21 @@ internal static void MeasurePatchCost() for (int i = 0; i < 400; i++) CostTarget(i); double patched = TimeCostTarget(repeats, rounds); harmony.Unpatch(target, HarmonyPatchType.All, HarmonyId); - Probe.PatchCallTicks = Math.Max(0, patched - baseline); + trampoline = Math.Max(0, patched - baseline); + } + catch (Exception e) { Log.Warning("Could not measure what Harmony adds to a patched call (only the patch bodies are counted): " + e.Message); } + Probe.PatchBodyTicks = body; + Probe.PatchCallTicks = body > 0 ? body + trampoline : 0; + } + + /// The entity tick's prefix and postfix, times, as Harmony calls them around a tick that is not sampled. + static void UnsampledEntityCalls(int calls) + { + for (int i = 0; i < calls; i++) + { + EntityPrefix(out Sample state); + EntityPostfix(null, state); } - catch (Exception e) { Log.Warning("Could not measure what a patch costs: " + e.Message); } } /// Stopwatch ticks for one call of : the fastest of several rounds. @@ -322,8 +340,9 @@ static double TimeCostTarget(int repeats, int rounds) static long costSink; [System.Runtime.CompilerServices.MethodImpl(System.Runtime.CompilerServices.MethodImplOptions.NoInlining)] static void CostTarget(int i) { costSink += i; } - internal static void CostPrefix(out long __state) { __state = 0; } - internal static void CostPostfix(long __state) { costSink += __state; } + // The same shape as the entity tick's pair (a Sample handed from prefix to postfix), with nothing in the bodies. + internal static void CostPrefix(out Sample __state) { __state = default; } + internal static void CostPostfix(Sample __state) { if (__state.On) costSink++; } // ---- the patch bodies ---- // Each starts with a read of Probe.Enabled. Nothing here may throw into the game, so anything that reads the game's own objects is diff --git a/source/Game/Session.cs b/source/Game/Session.cs index 754db5f..f879683 100644 --- a/source/Game/Session.cs +++ b/source/Game/Session.cs @@ -206,8 +206,12 @@ static List BuildHeader(string modVersion) header.Pipe("capability", "patch", parts[0], parts.Length > 1 ? parts[1] : "", parts.Length > 2 ? parts[2] : ""); } foreach (string result in Watch.Results) { string[] parts = result.Split('|'); header.Pipe("watch", parts[0], parts.Length > 1 ? parts[1] : ""); } + // patchBodyNs: the entity tick's prefix and postfix on a call that is not sampled; patchCallNs: that plus what Harmony adds, which is + // what overheadUs charges each patch call. Up to 0.1.3 there was no patchBodyNs, and patchCallNs (an empty patch) read 0. header.Pipe("calibration", "clockReadNs", Ns(Probe.ClockReadTicks), "allocReadNs", Ns(Probe.AllocReadTicks), "scopePairNs", Ns(Probe.ScopePairTicks), - "samplePairNs", Ns(Probe.SamplePairTicks), "patchCallNs", Ns(Probe.PatchCallTicks)); + "samplePairNs", Ns(Probe.SamplePairTicks), + "patchBodyNs", Probe.PatchBodyTicks > 0 ? Ns(Probe.PatchBodyTicks, "F1") : "unmeasured", + "patchCallNs", Probe.PatchCallTicks > 0 ? Ns(Probe.PatchCallTicks, "F1") : "unmeasured (" + Ns(Probe.PatchCallTicksCharged) + " assumed)"); header.Pipe("sampling", "budgetPercent", config.OverheadBudgetPercent.ToString(CultureInfo.InvariantCulture), "note", "the intervals are chosen again every profile window; profile.csv says how many calls each row rests on"); header.Pipe("histogram", "frameEdgesMs", string.Join(",", Columns.FrameEdgesMs.Select(e => e.ToString(CultureInfo.InvariantCulture)))); @@ -225,7 +229,7 @@ static List BuildHeader(string modVersion) return header.Lines; } - static string Ns(double ticks) => (ticks * 1e9 / Stopwatch.Frequency).ToString("F0", CultureInfo.InvariantCulture); + static string Ns(double ticks, string format = "F0") => (ticks * 1e9 / Stopwatch.Frequency).ToString(format, CultureInfo.InvariantCulture); // ---- during the game ---- diff --git a/tests/CoreTests.cs b/tests/CoreTests.cs index 7c3ef42..4a5842c 100644 --- a/tests/CoreTests.cs +++ b/tests/CoreTests.cs @@ -24,7 +24,7 @@ public Rig(double thresholdMs = 50, double summarySeconds = 100000, double profi Probe.Stop(); Probe.TestClock = () => Now; Alloc.UseTestSource(() => Bytes); - Probe.ScopePairTicks = 0; Probe.SamplePairTicks = 0; Probe.ExactCallTicks = 0; Probe.AllocPairTicks = 0; Probe.PatchCallTicks = 0; + Probe.ScopePairTicks = 0; Probe.SamplePairTicks = 0; Probe.ExactCallTicks = 0; Probe.AllocPairTicks = 0; Probe.PatchCallTicks = 0; Probe.PatchBodyTicks = 0; Probe.HeavySampler = null; Probe.Start(new ProbeSettings { @@ -92,6 +92,7 @@ internal static class CoreTests yield return ("Probe: a copy of the session counts does not change when the original does", StatsCloneIsIndependent); yield return ("Probe: measuring cost is estimated for each frame", OverheadEstimate); yield return ("Probe: calibration measures something and leaves the probe clean", CalibrationWorks); + yield return ("Probe: a patch body is timed with the log on and no call sampled, and the probe is left off and clean", UnsampledBodyTiming); yield return ("Alloc: a counter is chosen, and a test source is followed", AllocSources); yield return ("Milestones: marks are kept in order and safe for the header", MilestoneLines); yield return ("PatchBuilder: hot, shared and other patches are listed, the mod's own are only counted", PatchReport); @@ -635,6 +636,39 @@ static void CalibrationWorks() Check(!Probe.Enabled, "and does not switch the probe on"); } + static void UnsampledBodyTiming() + { + Probe.Stop(); + Alloc.Init(); + Profile.Configure(1, 1, 1); + bool wasOn = true; + int sampled = 0, calls = 0; + double ticks = Probe.MeasureUnsampled(n => + { + for (int i = 0; i < n; i++) + { + wasOn &= Probe.Enabled; + Probe.Count(Counter.PatchCalls); + if (Profile.BeginEntity().On) sampled++; + if (Profile.BeginComponent().On) sampled++; + calls++; + } + }, 1000, 3); + Check(ticks > 0, "the calls took some time"); + Check(calls > 3000, "a warm-up and three rounds ran: " + calls); + Check(wasOn, "the probe was on while they ran, so the bodies took the path they take in a log"); + Equal(0, sampled, "no call was one of the sampled ones, although the intervals were 1"); + Check(!Probe.Enabled, "the probe is off afterwards"); + Equal(0, Profile.Count, "no keys are left behind"); + Equal(16, Profile.EntityInterval, "the sampling is back to where a log starts it"); + Check(Probe.MeasureUnsampled(n => throw new InvalidOperationException("broken")) == 0 && !Probe.Enabled, "a body that throws measures 0 and leaves the probe off"); + using (new Rig()) + { + Equal(0.0, Probe.MeasureUnsampled(n => calls++), "nothing is measured while a log runs"); + Check(Probe.Enabled, "and the log is left running"); + } + } + // ---- allocation counter, milestones ---- static void AllocSources() diff --git a/tests/GameBindingTests.cs b/tests/GameBindingTests.cs index b280c47..18ef75f 100644 --- a/tests/GameBindingTests.cs +++ b/tests/GameBindingTests.cs @@ -47,6 +47,7 @@ internal static class GameBindingTests yield return ("Game: a wrapper passes through exceptions and still times the call", WrapperExceptions); yield return ("Game: a wrapper does nothing extra when the log is off", WrapperWhenOff); yield return ("Game: patch bodies pair up and hand the scope token from prefix to postfix", PatchBodiesPair); + yield return ("Game: the cost charged for each patch call covers what the entity patch's own bodies take on a call that is not sampled", PatchCostCoversTheBodies); yield return ("Game: the game's own empty entity bucket is measured by the entity bucket patch", EntityBucketPatch); yield return ("Game: a save is tracked from its patch bodies into an event", SaveTracking); yield return ("Watch: named methods are found, and the ones that cannot be patched say why", WatchResolution); @@ -534,6 +535,41 @@ static void PatchBodiesPair() } } + static void PatchCostCoversTheBodies() + { + Action warnings = Log.WarningSink; + Log.WarningSink = _ => { }; + try + { + Probe.Stop(); + Probe.PatchCallTicks = 0; + // Harmony cannot patch in this process, so what needs a real patch is not measured here; the rest is. + Instrumentation.MeasurePatchCost(); + double charged = Probe.PatchCallTicks; + Check(Probe.PatchBodyTicks > 0, "the bodies were measured"); + Check(charged >= Probe.PatchBodyTicks, "a patch call is charged its bodies plus what Harmony adds, never less"); + Check(!Probe.Enabled, "measuring leaves the probe off"); + Equal(0, Profile.Count, "and leaves no keys behind"); + // The same bodies timed here directly, the way the game runs them on almost every call: the log on, and the call not one of the + // sampled ones (an interval of 4096 samples about one call in 4096; those few cost more, which only makes this figure larger). + double body; + using (new Rig()) + { + Profile.Configure(4096, 4096, 1); + const int calls = 1000000; + long t0 = System.Diagnostics.Stopwatch.GetTimestamp(); + for (int i = 0; i < calls; i++) { Instrumentation.EntityPrefix(out Sample sample); Instrumentation.EntityPostfix(null, sample); } + body = (System.Diagnostics.Stopwatch.GetTimestamp() - t0) / (double)calls; + } + double ns = 1e9 / System.Diagnostics.Stopwatch.Frequency; + Console.WriteLine(" charged per patch call " + (charged * ns).ToString("F2") + " ns; the entity patch bodies timed here " + (body * ns).ToString("F2") + " ns"); + Check(body > 0, "the bodies take some time"); + // Half, because the two are timed separately and the machine may be busy with other work in between. + Check(charged >= 0.5 * body, "each patch call is charged " + (charged * ns).ToString("F2") + " ns, less than its own bodies take (" + (body * ns).ToString("F2") + " ns): overheadUs leaves the patches out"); + } + finally { Log.WarningSink = warnings; } + } + static void EntityBucketPatch() { Rig rig = StartRig(out _); diff --git a/tools/perflog.py b/tools/perflog.py index f6c5fe1..2cd71ff 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -47,6 +47,13 @@ SLOW_MEAN_MS = 20.0 LOAD_KINDS = ("load", "load-non-singleton", "post-load", "post-load-non-singleton") +# Printed only for a recording whose calibration line has no patchBodyNs (KNOWN_ISSUE_APPLIES): a build of the fix that still carries an older +# version number measures the patch bodies already. +PATCH_COST_NOTE = ("overheadUs understates what the mod itself cost: every call of its per-call patches (entity ticks, components, watched " + "methods; the patchCalls column) was charged patchCallNs from the `# calibration|` line, which timed an empty patch and " + "read 0, so those calls (about 100,000 a second at speed 7 with Profile = deep) count for nothing in overheadUs and in the " + "'measuring cost more than 2% of a frame' warning. The real bodies take a few nanoseconds a call.") + # What is wrong with recordings made by an older Performance Log, found when a recording was first read. Each entry is (fixed in, note): the note # is printed at the top of the report for a recording made by an earlier version, so nobody trusts a figure that was known to be off. KNOWN_ISSUES = [ @@ -59,8 +66,19 @@ ("0.1.1", "prDraw and prBatches are 0: Unity 6 has no counter by those names (its draw calls are split into several). The other columns are unaffected."), ("0.1.1", "While the game ran, frames.csv, profile.csv, spikes.csv and events.csv were held open by the mod, so copying or zipping the folder could leave them out " "(the folder listing shows size 0). Exit the game first, or read them with shared access."), + ("0.1.4", PATCH_COST_NOTE), ] + +def _patch_cost_was_not_measured(session): + calibration = session.pipe("calibration") + return bool(calibration) and not any("patchBodyNs" in parts for parts in calibration) + + +# Notes that only some recordings of the versions they name have, each with the check that finds the problem in a recording (a note not listed +# here is printed for every recording made before its fix). +KNOWN_ISSUE_APPLIES = {PATCH_COST_NOTE: _patch_cost_was_not_measured} + GAME_ASSEMBLY_PREFIXES = ("Timberborn.", "Bindito.", "UnityEngine", "Unity.", "System") @@ -79,7 +97,7 @@ def known_issues(session): have = version_tuple(session.h("mod")) if have is None: return [] - return [note for fixed, note in KNOWN_ISSUES if have < version_tuple(fixed)] + return [note for fixed, note in KNOWN_ISSUES if have < version_tuple(fixed) and KNOWN_ISSUE_APPLIES.get(note, lambda _: True)(session)] # ---------------------------------------------------------------- reading diff --git a/tools/test_perflog.py b/tools/test_perflog.py index f7257e5..c648ffe 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -529,6 +529,18 @@ def test_an_older_mod_version_gets_its_known_issues_listed(self): s.window() self.assertNotIn("KNOWN ISSUE", self.report(s), "an unreadable version is not guessed at") + def test_a_recording_whose_patch_cost_read_0_is_told_overhead_is_understated(self): + old = ["calibration", "clockReadNs", "23", "allocReadNs", "12", "scopePairNs", "109", "samplePairNs", "51", "patchCallNs", "0"] + new = ["calibration", "clockReadNs", "23", "allocReadNs", "12", "scopePairNs", "109", "samplePairNs", "51", "patchBodyNs", "6.2", "patchCallNs", "6.9"] + for version, calibration, expect in (("0.1.3", old, True), ("0.1.3", new, False), ("0.1.3", None, False), ("0.1.4", old, False)): + s = Synthetic(header={"mod": version}) + if calibration: + s.pipes.append(calibration) + for _ in range(6): + s.window() + text = self.report(s) + self.assertEqual(expect, "overheadUs understates what the mod itself cost" in text, (version, calibration)) + def test_the_loadall_counter_bug_of_0_1_0_is_not_reported_as_a_finding(self): for version, expect in (("0.1.0", False), ("0.1.1", True)): s = Synthetic(header={"mod": version}) From 9edf5434a41edc987d8199cac5974dcb72b23072 Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 04:46:12 -0700 Subject: [PATCH 3/5] PL1: keep a watched method's interval through windows it is not called Review follow-up. AdaptMethods set every watched method's interval from its calls in the window just ended, so one window without calls put it back to the interval it was registered with (8). A method that is busy only in bursts was then timed at about 1 call in 8 in every burst: 3.75 times the watched methods' share of the budget each time. A window with no calls says nothing about the method's rate, so its interval is now kept; the countdown still starts again at 1, so its first call in the next window it runs is timed, and any window in which it runs less still brings the interval back down. Tests: BurstsStayInsideTheBudget (busy in windows 1, 3 and 5, not called in 2 and 4; before: burst window 3 took 0.375% of a second against the 0.1% share; after: 0.100%) and FewCallsEveryWindow (3 calls a window at an interval of 8 are timed in every window, which only holds because each window's countdown restarts at 1; no test covered that before). The 'method' kind description said N widens "only while that method itself is busy", but the budget is split between the watched methods that ran, so N also widens when many of them are busy. It now says so; the fixtures' columns.md and README.md are regenerated. Co-Authored-By: Claude Opus 5 --- docs/TESTING.md | 4 +- source/Core/Columns.cs | 2 +- source/Core/Profile.cs | 13 ++++-- tests/PL1WatchSamplingTests.cs | 48 ++++++++++++++++++++ tests/fixtures/sample-with-mod/README.md | 2 +- tests/fixtures/sample-with-mod/columns.md | 2 +- tests/fixtures/sample-without-mod/README.md | 2 +- tests/fixtures/sample-without-mod/columns.md | 2 +- 8 files changed, 63 insertions(+), 12 deletions(-) diff --git a/docs/TESTING.md b/docs/TESTING.md index 86c32ce..3d47628 100644 --- a/docs/TESTING.md +++ b/docs/TESTING.md @@ -6,7 +6,7 @@ the game running. This is the honest list. ## Verified by the automated checks -`dotnet run --project tests -c Release` (96 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (46 checks). +`dotnet run --project tests -c Release` (98 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (46 checks). | What | How | |---|---| @@ -15,7 +15,7 @@ the game running. This is the honest list. | Failure containment: a failing clock switches the probe off, a full ring drops rows and counts them | `CoreTests` | | The cost charged for each patch call (`patchCallNs`) is at least what the entity patch's own bodies take on a call that is not sampled, timed with the log on and sampling held off (the part Harmony adds needs the game) | `CoreTests.UnsampledBodyTiming`, `GameBindingTests.PatchCostCoversTheBodies` | | The profile: exact singleton timing, scaled sampling, random gaps that do not alias with a repeating pattern, budget adaptation, spike attribution, mod resolution | `ProfileTests` | -| Watched methods: each is sampled at its own rate, widening with its own load inside the budget and coming back down after, with a row (and at least one timing) for every window it ran in; calls nobody timed get a `sampled` 0 row and stay out of the totals | `WatchSamplingTests`, `test_perflog` | +| Watched methods: each is sampled at its own rate, widening with its own load inside the budget, kept through windows it is not called in (so bursts stay inside it too) and coming back down when it runs less, with a row (and at least one timing) for every window it ran in; calls nobody timed get a `sampled` 0 row and stay out of the totals | `WatchSamplingTests`, `test_perflog` | | The files: header, columns, invariant number format in any language, text tails, events, a file rewritten whole, an unopenable path, dropped rows, flush on stop | `WriterTests` | | `summary.md`, `README.md` and `columns.md` generation | `SummaryTests`, `WriterTests.EndToEnd` | | Every patch target exists in the installed game (1.1.2.4), has no exception filter, and takes only parameters Harmony can supply | `GameBindingTests.TargetsResolve` | diff --git a/source/Core/Columns.cs b/source/Core/Columns.cs index 0c8fb3a..8068533 100644 --- a/source/Core/Columns.cs +++ b/source/Core/Columns.cs @@ -415,7 +415,7 @@ public static class ProfileKinds "A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed.", "All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled').", "All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep.", - "One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed, N widening only while that method itself is busy. It has a row for every window it ran in.", + "One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in.", "A singleton's Load while the game was loading (one row per singleton, window 0).", "A non-singleton loader's LoadNonSingletons while the game was loading (window 0).", "A singleton's PostLoad while the game was loading (window 0).", diff --git a/source/Core/Profile.cs b/source/Core/Profile.cs index 8d96335..783323c 100644 --- a/source/Core/Profile.cs +++ b/source/Core/Profile.cs @@ -507,9 +507,11 @@ static void Adapt(double windowSeconds) /// /// Chooses each watched method's interval for the next window from that method's own calls in this one, before they are forgotten. - /// It is set again every window and never below the interval the method was given, so a method that was busy once comes back down - /// when it quietens, and a rare one next to a busy one keeps its own. The methods' share of the budget is split between the methods - /// that ran. Each countdown starts again at 1, so a method that runs in the next window has its first call timed. + /// It is set again every window the method ran in and never below the interval the method was given, so a method that was busy once + /// comes back down when it runs less, and a rare one next to a busy one keeps its own. A window it did not run in says nothing about + /// its rate, so its interval is kept: a method that is busy in bursts is timed at the interval its last burst needed, not at the given + /// one. The methods' share of the budget is split between the methods that ran. Each countdown starts again at 1, so a method that + /// runs in the next window has its first call timed. /// static void AdaptMethods(double windowSeconds) { @@ -527,10 +529,11 @@ static void AdaptMethods(double windowSeconds) { Entry e = entries[id]; if (e.Kind != ProfileKind.Method) continue; - double wanted = measured && calls[id] > 0 ? Math.Ceiling(calls[id] / windowSeconds * pairSeconds / budget) : 0; + methodCounter[id] = 1; + if (calls[id] == 0) continue; + double wanted = measured ? Math.Ceiling(calls[id] / windowSeconds * pairSeconds / budget) : 0; int most = Math.Max(e.GivenInterval, 4096); e.MethodInterval = wanted >= most ? most : Math.Max(e.GivenInterval, (int)wanted); - methodCounter[id] = 1; } } } diff --git a/tests/PL1WatchSamplingTests.cs b/tests/PL1WatchSamplingTests.cs index 8650bf3..153141c 100644 --- a/tests/PL1WatchSamplingTests.cs +++ b/tests/PL1WatchSamplingTests.cs @@ -13,6 +13,8 @@ internal static class WatchSamplingTests { yield return ("Profile: a rare watched method next to a hot one is still timed in every window it runs", RareMethodNextToHotOne); yield return ("Profile: a watched method's interval widens with its own load, inside the budget, and comes back down when the load goes away", IntervalFollowsTheLoad); + yield return ("Profile: a watched method called fewer times a window than its interval still has a call timed in every window", FewCallsEveryWindow); + yield return ("Profile: a watched method that is busy in bursts keeps the interval its bursts need through the windows it is not called", BurstsStayInsideTheBudget); yield return ("Profile: a watched method that ran but was never timed gets a row with sampled 0 and adds no made-up 0 ms to the totals", UntimedWindowIsWrittenNotGuessed); } @@ -107,6 +109,52 @@ static void IntervalFollowsTheLoad() } } + static void FewCallsEveryWindow() + { + Prepare(); + using (rig) + { + // 3 calls a window at an interval of 8: without each window's countdown starting again at 1, whole windows go by untimed. + int id = Profile.RegisterMethod("Few.Method", "M", 8); + for (int w = 1; w <= 20; w++) + { + for (int i = 0; i < 3; i++) Call(id, 1); + Profile.FlushWindow(w, w, 10, rig.Prof); + double[] row = RowOf(rig.ProfileRows(), id); + Check(row != null && row[5] >= 1, "window " + w + ": 3 calls, none timed (" + (row == null ? "no row" : "sampled " + row[5]) + ")"); + Near(3, row[6], .01, "window " + w + ": 3 calls of 1 ms"); + } + } + } + + static void BurstsStayInsideTheBudget() + { + Prepare(); + using (rig) + { + // Busy in the odd windows (200,000 calls in a 1 s window), not called at all in the even ones. The first burst is timed at the + // given interval, as nothing is known yet; every later one at the interval the burst before it asked for, which a window with no + // calls does not undo. + int id = Profile.RegisterMethod("Bursty.Method", "M", 8); + double pairSeconds = PairNs * 1e-9 + 100e-9; + for (int w = 1; w <= 5; w++) + { + bool busy = w % 2 == 1; + if (busy) for (int i = 0; i < 200000; i++) Call(id, 0.001); + Profile.FlushWindow(w, w, 1, rig.Prof); + double[] row = RowOf(rig.ProfileRows(), id); + if (!busy) { Check(row == null, "window " + w + ": a row for a window the method was not called in"); continue; } + Check(row != null, "window " + w + ": no row"); + Near(200, row[6], .01, "window " + w + ": 200,000 calls of 1 us"); + double share = row[5] * pairSeconds; + Console.WriteLine(" burst window " + w + ": " + row[5] + " of 200000 calls timed, " + (share * 100).ToString("F3") + "% of a second"); + if (w >= 3) + Check(share <= 0.01 * Profile.BudgetShareMethod * 1.05, "burst window " + w + ": measuring took " + (share * 100).ToString("F3") + + "% of a second, over the watched methods' share of the budget: the quiet window before it undid the interval"); + } + } + } + static void UntimedWindowIsWrittenNotGuessed() { Prepare(); diff --git a/tests/fixtures/sample-with-mod/README.md b/tests/fixtures/sample-with-mod/README.md index 201807a..1676913 100644 --- a/tests/fixtures/sample-with-mod/README.md +++ b/tests/fixtures/sample-with-mod/README.md @@ -117,7 +117,7 @@ the last bucket is everything above), and `th0`..`th5` count frames that ran 0, - `parallel-start`: A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed. - `entity`: All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled'). - `component`: All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep. -- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed, N widening only while that method itself is busy. It has a row for every window it ran in. +- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in. - `load`: A singleton's Load while the game was loading (one row per singleton, window 0). - `load-non-singleton`: A non-singleton loader's LoadNonSingletons while the game was loading (window 0). - `post-load`: A singleton's PostLoad while the game was loading (window 0). diff --git a/tests/fixtures/sample-with-mod/columns.md b/tests/fixtures/sample-with-mod/columns.md index 84b2b36..4587124 100644 --- a/tests/fixtures/sample-with-mod/columns.md +++ b/tests/fixtures/sample-with-mod/columns.md @@ -112,7 +112,7 @@ One row per key per window. The last three columns (`name`, `assembly`, `mod`) a - `parallel-start`: A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed. - `entity`: All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled'). - `component`: All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep. -- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed, N widening only while that method itself is busy. It has a row for every window it ran in. +- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in. - `load`: A singleton's Load while the game was loading (one row per singleton, window 0). - `load-non-singleton`: A non-singleton loader's LoadNonSingletons while the game was loading (window 0). - `post-load`: A singleton's PostLoad while the game was loading (window 0). diff --git a/tests/fixtures/sample-without-mod/README.md b/tests/fixtures/sample-without-mod/README.md index 201807a..1676913 100644 --- a/tests/fixtures/sample-without-mod/README.md +++ b/tests/fixtures/sample-without-mod/README.md @@ -117,7 +117,7 @@ the last bucket is everything above), and `th0`..`th5` count frames that ran 0, - `parallel-start`: A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed. - `entity`: All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled'). - `component`: All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep. -- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed, N widening only while that method itself is busy. It has a row for every window it ran in. +- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in. - `load`: A singleton's Load while the game was loading (one row per singleton, window 0). - `load-non-singleton`: A non-singleton loader's LoadNonSingletons while the game was loading (window 0). - `post-load`: A singleton's PostLoad while the game was loading (window 0). diff --git a/tests/fixtures/sample-without-mod/columns.md b/tests/fixtures/sample-without-mod/columns.md index 84b2b36..4587124 100644 --- a/tests/fixtures/sample-without-mod/columns.md +++ b/tests/fixtures/sample-without-mod/columns.md @@ -112,7 +112,7 @@ One row per key per window. The last three columns (`name`, `assembly`, `mod`) a - `parallel-start`: A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed. - `entity`: All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled'). - `component`: All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep. -- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed, N widening only while that method itself is busy. It has a row for every window it ran in. +- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in. - `load`: A singleton's Load while the game was loading (one row per singleton, window 0). - `load-non-singleton`: A non-singleton loader's LoadNonSingletons while the game was loading (window 0). - `post-load`: A singleton's PostLoad while the game was loading (window 0). From 2e4d4686bc3c26f239e3e0c09336eb694e6221da Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 04:49:31 -0700 Subject: [PATCH 4/5] NF2: tell an understated patch charge from a 40 ns guess in old recordings Review follow-up. The KNOWN_ISSUES note said every recording up to 0.1.3 charged its patch calls nothing. It did not: patchCallNs is written to whole nanoseconds, and an empty-patch reading of exactly 0 (patched minus unpatched, clamped) made the mod charge an assumed 40 ns a call, while a reading just above 0 charged about nothing. Both show patchCallNs|0. With the 40 ns charge no row's overheadUs can fall below 40 ns per patch call, so a row below it proves the charge was about nothing. perflog.py now prints the "understates" note only for such recordings, and a neutral note (the charge was a guess or about nothing, and no row shows which) for the other old recordings that ran patches. Neither is printed when the calibration line has patchBodyNs or patchCallNs is not 0. On the 26 real recordings: every 0.1.3 one with patch calls and four 0.1.1 ones are flagged as understated; the 0.1.0 ones and the other 0.1.1 ones get the neutral note, where before they were wrongly told they understated. docs/TESTING.md item 2 and the MeasurePatchCost comment say the same. PatchCostCoversTheBodies timed the bodies directly in one loop of a million calls, so a moment of CPU contention could push that figure past twice the calibrated one and fail the check (a reviewer saw it fail in 1 of 3 runs next to a busy loop). It now takes the fastest of ten rounds, as the calibration does. The calibration header line moves into Probe.CalibrationParts, and the new CoreTests.CalibrationLine checks the names perflog.py relies on (patchBodyNs, patchCallNs), the one-decimal values and the "unmeasured" wording. Co-Authored-By: Claude Opus 5 --- docs/TESTING.md | 9 +++--- source/Core/Probe.cs | 14 +++++++++ source/Game/Instrumentation.cs | 5 +-- source/Game/Session.cs | 9 +----- tests/CoreTests.cs | 25 +++++++++++++++ tests/GameBindingTests.cs | 14 ++++++--- tools/perflog.py | 56 +++++++++++++++++++++++++++++----- tools/test_perflog.py | 24 ++++++++++++--- 8 files changed, 126 insertions(+), 30 deletions(-) diff --git a/docs/TESTING.md b/docs/TESTING.md index 3d47628..d1069a9 100644 --- a/docs/TESTING.md +++ b/docs/TESTING.md @@ -6,14 +6,14 @@ the game running. This is the honest list. ## Verified by the automated checks -`dotnet run --project tests -c Release` (98 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (46 checks). +`dotnet run --project tests -c Release` (99 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (46 checks). | What | How | |---|---| | Frame accounting: slots are exclusive and add up to the frame; unbalanced scopes; other threads ignored; allocation attribution; flags; ticks and buckets; Unity phases; summaries and histograms | Real `Probe` against a scripted clock (`CoreTests`) | | The per-frame path allocates nothing | `GC.GetAllocatedBytesForCurrentThread` around 2000 frames; also for a wrapper with the log off | | Failure containment: a failing clock switches the probe off, a full ring drops rows and counts them | `CoreTests` | -| The cost charged for each patch call (`patchCallNs`) is at least what the entity patch's own bodies take on a call that is not sampled, timed with the log on and sampling held off (the part Harmony adds needs the game) | `CoreTests.UnsampledBodyTiming`, `GameBindingTests.PatchCostCoversTheBodies` | +| The cost charged for each patch call (`patchCallNs`) is at least what the entity patch's own bodies take on a call that is not sampled, timed with the log on and sampling held off (the part Harmony adds needs the game); the `# calibration|` line names both, or says `unmeasured` | `CoreTests.UnsampledBodyTiming`, `CoreTests.CalibrationLine`, `GameBindingTests.PatchCostCoversTheBodies` | | The profile: exact singleton timing, scaled sampling, random gaps that do not alias with a repeating pattern, budget adaptation, spike attribution, mod resolution | `ProfileTests` | | Watched methods: each is sampled at its own rate, widening with its own load inside the budget, kept through windows it is not called in (so bursts stay inside it too) and coming back down when it runs less, with a row (and at least one timing) for every window it ran in; calls nobody timed get a `sampled` 0 row and stay out of the totals | `WatchSamplingTests`, `test_perflog` | | The files: header, columns, invariant number format in any language, text tails, events, a file rewritten whole, an unopenable path, dropped rows, flush on stop | `WriterTests` | @@ -66,8 +66,9 @@ heap and is coarse**. The per-singleton `KB/s` figures are therefore only good i 1. **The 0.1.1 fixes themselves**: that each service is wrapped once (`# capability-final|patchCalls|singleton wrappers put in place` should be a handful, not hundreds of thousands), that the four files can be zipped while the game runs, that `workingMB` is non-zero, that game singletons show `game`, that loading steps show a heap growth, and that `prDraw` is non-zero. 2. **Overhead** measured against a game running without the mod. The mod's own estimate (0.1.0: 0.3% of a frame paused, 0.8% at speed 7) left out the wrapper swapping and used a default cost for a - patch. 0.1.1 to 0.1.3 measured the patch cost on an empty patch, which read 0 in every recording (`patchCallNs|0`), so their `overheadUs` leaves the per-call patches out; the cost is now - the real bodies (`patchBodyNs`) plus what Harmony adds (`patchCallNs`), but that has not run in a game yet, and nobody has compared the frame rate with the mod off. See the checklist. + patch. 0.1.1 to 0.1.3 measured the patch cost on an empty patch, which shows 0 in every recording (`patchCallNs|0`): where it read exactly 0 the per-call patches were still charged the + 40 ns default, where it read a fraction of a nanosecond they were charged almost nothing (`perflog.py` says which when a recording's rows show it). The cost is now the real bodies + (`patchBodyNs`) plus what Harmony adds (`patchCallNs`), but that has not run in a game yet, and nobody has compared the frame rate with the mod off. See the checklist. 3. **Co-op**: with BeaverBuddies actually connected to another player. It has only been seen running with BeaverBuddies loaded in a single-player game. 4. **`Ticker.FinishFullTick`** (one of the four save-stage patches) is counted inside `save stages`, so it has not been seen separately; the stages of three saves were recorded. 5. **The mod attribution** (which DLL belongs to which mod) worked for the mods in the first recording (`beaverbuddies`, `Kyler.OptimizedLocalHousing`, `eMka.ModSettings`, `kyler.persistentworkareas`); diff --git a/source/Core/Probe.cs b/source/Core/Probe.cs index a09e9d3..ddfca17 100644 --- a/source/Core/Probe.cs +++ b/source/Core/Probe.cs @@ -110,6 +110,20 @@ public static class Probe /// What each patch call is charged in overheadUs: , or 40 ns when it could not be measured (the calibration line says so). public static double PatchCallTicksCharged => PatchCallTicks > 0 ? PatchCallTicks : 40e-9 * Stopwatch.Frequency; + /// + /// The header's `# calibration|` line after its kind: what each part of measuring costs, in nanoseconds. patchBodyNs is the entity tick's + /// prefix and postfix on a call that is not sampled; patchCallNs is that plus what Harmony adds, which is what overheadUs charges each patch + /// call. Up to 0.1.3 there was no patchBodyNs and patchCallNs (an empty patch) read 0; tools/perflog.py tells the two apart by patchBodyNs. + /// + public static string[] CalibrationParts() => new[] + { + "clockReadNs", Ns(ClockReadTicks), "allocReadNs", Ns(AllocReadTicks), "scopePairNs", Ns(ScopePairTicks), "samplePairNs", Ns(SamplePairTicks), + "patchBodyNs", PatchBodyTicks > 0 ? Ns(PatchBodyTicks, "F1") : "unmeasured", + "patchCallNs", PatchCallTicks > 0 ? Ns(PatchCallTicks, "F1") : "unmeasured (" + Ns(PatchCallTicksCharged) + " assumed)", + }; + + static string Ns(double ticks, string format = "F0") => (ticks * 1e9 / Stopwatch.Frequency).ToString(format, System.Globalization.CultureInfo.InvariantCulture); + public static bool OnGameThread => Environment.CurrentManagedThreadId == mainThreadId; /// Simulation ticks since the log started. diff --git a/source/Game/Instrumentation.cs b/source/Game/Instrumentation.cs index 645e791..906b69e 100644 --- a/source/Game/Instrumentation.cs +++ b/source/Game/Instrumentation.cs @@ -287,8 +287,9 @@ static void InstallOne(PatchSpec spec) /// What each call of the per-call patches (entity ticks, components, watched methods) costs, for overheadUs. Two parts: the bodies of the /// entity tick's prefix and postfix on a call that is not sampled (almost every call; a sampled call's extra cost is charged separately), /// timed directly with the log on; and what Harmony adds to call a prefix and a postfix, by patching a method of our own with empty ones - /// of the same shape (patched minus unpatched, never below 0). Up to 0.1.3 only the second part was measured; in the game it came out - /// under half a nanosecond, so every recording said patchCallNs 0 and overheadUs left the patches out. Both loops of the second part are warmed + /// of the same shape (patched minus unpatched, never below 0). Up to 0.1.3 only the second part was measured, and every recording says + /// patchCallNs 0: a reading of exactly 0 was charged as an assumed 40 ns, one just above 0 (under half a nanosecond) as itself, so overheadUs + /// charged the patches either a guess or almost nothing. Both loops of the second part are warmed /// up first (the first call of a method is compiled, and a patched one goes through a freshly made wrapper), and the least of a few rounds /// is taken, so one-off costs and the scheduler do not decide the figure. /// diff --git a/source/Game/Session.cs b/source/Game/Session.cs index f879683..759a556 100644 --- a/source/Game/Session.cs +++ b/source/Game/Session.cs @@ -206,12 +206,7 @@ static List BuildHeader(string modVersion) header.Pipe("capability", "patch", parts[0], parts.Length > 1 ? parts[1] : "", parts.Length > 2 ? parts[2] : ""); } foreach (string result in Watch.Results) { string[] parts = result.Split('|'); header.Pipe("watch", parts[0], parts.Length > 1 ? parts[1] : ""); } - // patchBodyNs: the entity tick's prefix and postfix on a call that is not sampled; patchCallNs: that plus what Harmony adds, which is - // what overheadUs charges each patch call. Up to 0.1.3 there was no patchBodyNs, and patchCallNs (an empty patch) read 0. - header.Pipe("calibration", "clockReadNs", Ns(Probe.ClockReadTicks), "allocReadNs", Ns(Probe.AllocReadTicks), "scopePairNs", Ns(Probe.ScopePairTicks), - "samplePairNs", Ns(Probe.SamplePairTicks), - "patchBodyNs", Probe.PatchBodyTicks > 0 ? Ns(Probe.PatchBodyTicks, "F1") : "unmeasured", - "patchCallNs", Probe.PatchCallTicks > 0 ? Ns(Probe.PatchCallTicks, "F1") : "unmeasured (" + Ns(Probe.PatchCallTicksCharged) + " assumed)"); + header.Pipe("calibration", Probe.CalibrationParts()); header.Pipe("sampling", "budgetPercent", config.OverheadBudgetPercent.ToString(CultureInfo.InvariantCulture), "note", "the intervals are chosen again every profile window; profile.csv says how many calls each row rests on"); header.Pipe("histogram", "frameEdgesMs", string.Join(",", Columns.FrameEdgesMs.Select(e => e.ToString(CultureInfo.InvariantCulture)))); @@ -229,8 +224,6 @@ static List BuildHeader(string modVersion) return header.Lines; } - static string Ns(double ticks, string format = "F0") => (ticks * 1e9 / Stopwatch.Frequency).ToString(format, CultureInfo.InvariantCulture); - // ---- during the game ---- /// Called at the start of each of Unity's frames, from the player loop. diff --git a/tests/CoreTests.cs b/tests/CoreTests.cs index 4a5842c..dac3813 100644 --- a/tests/CoreTests.cs +++ b/tests/CoreTests.cs @@ -93,6 +93,7 @@ internal static class CoreTests yield return ("Probe: measuring cost is estimated for each frame", OverheadEstimate); yield return ("Probe: calibration measures something and leaves the probe clean", CalibrationWorks); yield return ("Probe: a patch body is timed with the log on and no call sampled, and the probe is left off and clean", UnsampledBodyTiming); + yield return ("Header: the calibration line names the patch body and patch call costs, and says when they were not measured", CalibrationLine); yield return ("Alloc: a counter is chosen, and a test source is followed", AllocSources); yield return ("Milestones: marks are kept in order and safe for the header", MilestoneLines); yield return ("PatchBuilder: hot, shared and other patches are listed, the mod's own are only counted", PatchReport); @@ -669,6 +670,30 @@ static void UnsampledBodyTiming() } } + static void CalibrationLine() + { + double body = Probe.PatchBodyTicks, call = Probe.PatchCallTicks; + try + { + // tools/perflog.py tells a recording that measured the patch bodies from an older one by the patchBodyNs name in this line. + double ticksPerNs = Stopwatch.Frequency / 1e9; + Probe.PatchBodyTicks = 8.27 * ticksPerNs; + Probe.PatchCallTicks = 8.97 * ticksPerNs; + string[] parts = Probe.CalibrationParts(); + Equal("clockReadNs samplePairNs patchBodyNs patchCallNs", string.Join(" ", parts[0], parts[6], parts[8], parts[10]), "names"); + Equal(12, parts.Length, "six name and value pairs"); + Equal("8.3", parts[9], "patchBodyNs, to a tenth of a nanosecond"); + Equal("9.0", parts[11], "patchCallNs, to a tenth of a nanosecond"); + Probe.PatchBodyTicks = 0; + Probe.PatchCallTicks = 0; + parts = Probe.CalibrationParts(); + Equal("unmeasured", parts[9], "patchBodyNs not measured"); + Equal("unmeasured (40 assumed)", parts[11], "patchCallNs not measured says what overheadUs charges instead"); + Check(parts.All(p => p.Length > 0 && p.IndexOf('|') < 0 && p.IndexOf(',') < 0 && p.IndexOf('\n') < 0), "no part holds a separator"); + } + finally { Probe.PatchBodyTicks = body; Probe.PatchCallTicks = call; } + } + // ---- allocation counter, milestones ---- static void AllocSources() diff --git a/tests/GameBindingTests.cs b/tests/GameBindingTests.cs index 18ef75f..cbb00ca 100644 --- a/tests/GameBindingTests.cs +++ b/tests/GameBindingTests.cs @@ -552,14 +552,20 @@ static void PatchCostCoversTheBodies() Equal(0, Profile.Count, "and leaves no keys behind"); // The same bodies timed here directly, the way the game runs them on almost every call: the log on, and the call not one of the // sampled ones (an interval of 4096 samples about one call in 4096; those few cost more, which only makes this figure larger). - double body; + // The fastest of ten rounds, as the calibration takes the fastest of its rounds: one long loop is slowed by any other program + // that takes the CPU for a moment, and that would decide the comparison. + double body = double.MaxValue; using (new Rig()) { Profile.Configure(4096, 4096, 1); - const int calls = 1000000; - long t0 = System.Diagnostics.Stopwatch.GetTimestamp(); + const int calls = 100000, rounds = 10; for (int i = 0; i < calls; i++) { Instrumentation.EntityPrefix(out Sample sample); Instrumentation.EntityPostfix(null, sample); } - body = (System.Diagnostics.Stopwatch.GetTimestamp() - t0) / (double)calls; + for (int round = 0; round < rounds; round++) + { + long t0 = System.Diagnostics.Stopwatch.GetTimestamp(); + for (int i = 0; i < calls; i++) { Instrumentation.EntityPrefix(out Sample sample); Instrumentation.EntityPostfix(null, sample); } + body = Math.Min(body, (System.Diagnostics.Stopwatch.GetTimestamp() - t0) / (double)calls); + } } double ns = 1e9 / System.Diagnostics.Stopwatch.Frequency; Console.WriteLine(" charged per patch call " + (charged * ns).ToString("F2") + " ns; the entity patch bodies timed here " + (body * ns).ToString("F2") + " ns"); diff --git a/tools/perflog.py b/tools/perflog.py index 2cd71ff..23f09f0 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -47,12 +47,22 @@ SLOW_MEAN_MS = 20.0 LOAD_KINDS = ("load", "load-non-singleton", "post-load", "post-load-non-singleton") -# Printed only for a recording whose calibration line has no patchBodyNs (KNOWN_ISSUE_APPLIES): a build of the fix that still carries an older -# version number measures the patch bodies already. +# Up to 0.1.3 the `# calibration|` line's patchCallNs timed an empty patch instead of the patch bodies, and every recording shows 0 there. What +# overheadUs charged each call of the per-call patches then depends on a reading the header rounds away: exactly 0 made the mod charge an assumed +# 40 ns a call, a reading above 0 (under half a nanosecond) made it charge that. A row whose overheadUs is below 40 ns a patch call proves the second. +# Neither note is printed for a recording whose calibration line has patchBodyNs (KNOWN_ISSUE_APPLIES): a build of the fix that still carries an +# older version number measures the patch bodies already. +PATCH_CHARGE_ASSUMED_NS = 40.0 PATCH_COST_NOTE = ("overheadUs understates what the mod itself cost: every call of its per-call patches (entity ticks, components, watched " - "methods; the patchCalls column) was charged patchCallNs from the `# calibration|` line, which timed an empty patch and " - "read 0, so those calls (about 100,000 a second at speed 7 with Profile = deep) count for nothing in overheadUs and in the " - "'measuring cost more than 2% of a frame' warning. The real bodies take a few nanoseconds a call.") + "methods; the patchCalls column) was charged almost nothing. patchCallNs in the `# calibration|` line timed an empty patch " + "instead of the real bodies and came out just above 0 (this recording has rows whose overheadUs is below the 40 ns a patch " + "call the mod assumes when that reading is exactly 0), so those calls (about 100,000 a second at speed 7 with Profile = deep) " + "are missing from overheadUs and from the 'measuring cost more than 2% of a frame' warning. The real bodies take a few " + "nanoseconds a call, plus what Harmony adds.") +PATCH_COST_GUESS_NOTE = ("overheadUs's charge for the per-call patches (entity ticks, components, watched methods; the patchCalls column) is not " + "a measurement. patchCallNs|0 in the `# calibration|` line timed an empty patch instead of the real bodies: a reading of " + "exactly 0 made the mod charge an assumed 40 ns a call, one just above 0 made it charge almost nothing, and no row in " + "this recording shows which. The real bodies take a few nanoseconds a call, plus what Harmony adds.") # What is wrong with recordings made by an older Performance Log, found when a recording was first read. Each entry is (fixed in, note): the note # is printed at the top of the report for a recording made by an earlier version, so nobody trusts a figure that was known to be off. @@ -67,17 +77,47 @@ ("0.1.1", "While the game ran, frames.csv, profile.csv, spikes.csv and events.csv were held open by the mod, so copying or zipping the folder could leave them out " "(the folder listing shows size 0). Exit the game first, or read them with shared access."), ("0.1.4", PATCH_COST_NOTE), + ("0.1.4", PATCH_COST_GUESS_NOTE), ] -def _patch_cost_was_not_measured(session): +def _empty_patch_charges(session): + """For a recording whose `# calibration|` line has patchCallNs 0 and no patchBodyNs (an empty patch was timed, not the bodies): how many + rows ran patches, and how many of those were charged less than the 40 ns a patch call assumed for a reading of exactly 0. None otherwise.""" calibration = session.pipe("calibration") - return bool(calibration) and not any("patchBodyNs" in parts for parts in calibration) + if not calibration or any("patchBodyNs" in parts for parts in calibration): + return None + reading = [parts[i + 1] for parts in calibration for i in range(len(parts) - 1) if parts[i] == "patchCallNs"] + try: + if not reading or float(reading[0]) != 0: + return None + except ValueError: + return None + ran = below = 0 + for r in session.rows: + calls, frames = r.get("patchCalls", 0.0), r.get("frames", 0.0) + if calls <= 0 or frames <= 0: + continue + ran += 1 + # overheadUs is a mean per frame, written to 0.1 us; patchCalls is the total over the row's frames. + if (r.get("overheadUs", 0.0) + 0.05) * frames < PATCH_CHARGE_ASSUMED_NS / 1000.0 * calls: + below += 1 + return ran, below + + +def _patch_cost_was_understated(session): + charges = _empty_patch_charges(session) + return charges is not None and charges[1] > 0 + + +def _patch_cost_was_a_guess(session): + charges = _empty_patch_charges(session) + return charges is not None and charges[0] > 0 and charges[1] == 0 # Notes that only some recordings of the versions they name have, each with the check that finds the problem in a recording (a note not listed # here is printed for every recording made before its fix). -KNOWN_ISSUE_APPLIES = {PATCH_COST_NOTE: _patch_cost_was_not_measured} +KNOWN_ISSUE_APPLIES = {PATCH_COST_NOTE: _patch_cost_was_understated, PATCH_COST_GUESS_NOTE: _patch_cost_was_a_guess} GAME_ASSEMBLY_PREFIXES = ("Timberborn.", "Bindito.", "UnityEngine", "Unity.", "System") diff --git a/tools/test_perflog.py b/tools/test_perflog.py index c648ffe..4fe58fd 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -529,17 +529,33 @@ def test_an_older_mod_version_gets_its_known_issues_listed(self): s.window() self.assertNotIn("KNOWN ISSUE", self.report(s), "an unreadable version is not guessed at") - def test_a_recording_whose_patch_cost_read_0_is_told_overhead_is_understated(self): + def test_a_recording_whose_patch_cost_read_0_is_told_what_overhead_charged_the_patches(self): old = ["calibration", "clockReadNs", "23", "allocReadNs", "12", "scopePairNs", "109", "samplePairNs", "51", "patchCallNs", "0"] new = ["calibration", "clockReadNs", "23", "allocReadNs", "12", "scopePairNs", "109", "samplePairNs", "51", "patchBodyNs", "6.2", "patchCallNs", "6.9"] - for version, calibration, expect in (("0.1.3", old, True), ("0.1.3", new, False), ("0.1.3", None, False), ("0.1.4", old, False)): + understated, guess = "overheadUs understates what the mod itself cost", "overheadUs's charge for the per-call patches" + # A 10 s window of 598.8 frames with 1000 patch calls a frame. overheadUs 10 us a frame is 10 ns a patch call, less than the 40 ns the mod + # charged when the empty patch read exactly 0, so the reading was above 0 and the patches were charged almost nothing. 50 us a frame is + # what the 40 ns charge (plus the other costs) gives, and could also be almost nothing plus a lot of sampling: it proves neither. + cheap, dear, none = dict(overheadUs=10.0, patchCalls=598800.0), dict(overheadUs=50.0, patchCalls=598800.0), dict(overheadUs=5.0) + for version, calibration, rows, slow, expect in ( + ("0.1.3", old, cheap, None, understated), + ("0.1.1", old, dear, dict(overheadUs=30.0, patchCalls=1000.0), understated), # one slow frame at 30 ns a call proves it + ("0.1.0", old, dear, dict(overheadUs=45.0, patchCalls=1000.0), guess), + ("0.1.3", old, none, None, None), # no patch ran: nothing to say + ("0.1.3", new, cheap, None, None), # the bodies were measured + ("0.1.3", None, cheap, None, None), + ("0.1.4", old, cheap, None, None)): s = Synthetic(header={"mod": version}) if calibration: s.pipes.append(calibration) for _ in range(6): - s.window() + s.window(**rows) + if slow: + s.slow_frame(60.0, **slow) text = self.report(s) - self.assertEqual(expect, "overheadUs understates what the mod itself cost" in text, (version, calibration)) + case = (version, calibration and calibration[-4:], rows, slow) + self.assertEqual(expect == understated, understated in text, case) + self.assertEqual(expect == guess, guess in text, case) def test_the_loadall_counter_bug_of_0_1_0_is_not_reported_as_a_finding(self): for version, expect in (("0.1.0", False), ("0.1.1", True)): From 58a466589a2696b71ec4c65814227ac7d7658108 Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 12:46:12 -0700 Subject: [PATCH 5/5] PL1/NF2: review fixes - perflog.py: an old recording whose empty-patch reading was above 0 (any value, not just under half a nanosecond) left the bodies out too, and now gets the 'understates' note; the neutral note is only for a reading of 0. - Say that a watched method's call is charged the entity patch's figure and so is still undercharged a little (MeasurePatchCost, TESTING.md). - WatchSamplingTests: a check that several busy watched methods share the methods' budget (removing the split failed no check before), and put Profile.BudgetFraction back after each check. Co-Authored-By: Claude Opus 5.5 --- docs/TESTING.md | 6 +++-- source/Game/Instrumentation.cs | 4 +++- tests/PL1WatchSamplingTests.cs | 42 ++++++++++++++++++++++++++++++---- tools/perflog.py | 25 +++++++++++--------- tools/test_perflog.py | 1 + 5 files changed, 59 insertions(+), 19 deletions(-) diff --git a/docs/TESTING.md b/docs/TESTING.md index 9b3f403..7c57096 100644 --- a/docs/TESTING.md +++ b/docs/TESTING.md @@ -6,7 +6,7 @@ since. A 0.1.3 recording (below) shows the `deep` default working, and every 0.1 ## Verified by the automated checks -`dotnet run --project tests -c Release` (100 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (50 checks). +`dotnet run --project tests -c Release` (101 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (50 checks). | What | How | |---|---| @@ -97,7 +97,9 @@ What it shows, and the line that shows it: 2. **Overhead** measured against a game running without the mod. The mod's own estimate (0.1.0: 0.3% of a frame paused, 0.8% at speed 7) left out the wrapper swapping and used a default cost for a patch. 0.1.1 to 0.1.3 measured the patch cost on an empty patch, which shows 0 in every recording (`patchCallNs|0`): where it read exactly 0 the per-call patches were still charged the 40 ns default, where it read a fraction of a nanosecond they were charged almost nothing (`perflog.py` says which when a recording's rows show it). The cost is now the real bodies - (`patchBodyNs`) plus what Harmony adds (`patchCallNs`), but that has not run in a game yet, and nobody has compared the frame rate with the mod off. See the checklist. + (`patchBodyNs`) plus what Harmony adds (`patchCallNs`), but that has not run in a game yet, and nobody has compared the frame rate with the mod off. See the checklist. The figure is + the entity patch's; a watched method's call (config `Watch`) costs somewhat more (a lookup, and Harmony passing `__originalMethod`) and is charged the same, so with `Watch` + entries `overheadUs` still undercharges a little. 3. **Co-op**: with BeaverBuddies actually connected to another player. It has only been seen running with BeaverBuddies loaded in a single-player game. 4. **`Ticker.FinishFullTick`** (one of the four save-stage patches) is counted inside `save stages`, so it has not been seen separately; the stages of three saves were recorded. 5. **The mod attribution** (which DLL belongs to which mod) worked for the mods in the first recording (`beaverbuddies`, `Kyler.OptimizedLocalHousing`, `eMka.ModSettings`, `kyler.persistentworkareas`); diff --git a/source/Game/Instrumentation.cs b/source/Game/Instrumentation.cs index 906b69e..029c674 100644 --- a/source/Game/Instrumentation.cs +++ b/source/Game/Instrumentation.cs @@ -291,7 +291,9 @@ static void InstallOne(PatchSpec spec) /// patchCallNs 0: a reading of exactly 0 was charged as an assumed 40 ns, one just above 0 (under half a nanosecond) as itself, so overheadUs /// charged the patches either a guess or almost nothing. Both loops of the second part are warmed /// up first (the first call of a method is compiled, and a patched one goes through a freshly made wrapper), and the least of a few rounds - /// is taken, so one-off costs and the scheduler do not decide the figure. + /// is taken, so one-off costs and the scheduler do not decide the figure. Every patch call is charged this one figure, so a call of a + /// watched method (whose prefix also looks the method up, and needs Harmony to pass __originalMethod) is still charged somewhat less + /// than it costs. /// internal static void MeasurePatchCost() { diff --git a/tests/PL1WatchSamplingTests.cs b/tests/PL1WatchSamplingTests.cs index 153141c..53eecff 100644 --- a/tests/PL1WatchSamplingTests.cs +++ b/tests/PL1WatchSamplingTests.cs @@ -11,13 +11,22 @@ internal static class WatchSamplingTests { public static IEnumerable<(string, Action)> All() { - yield return ("Profile: a rare watched method next to a hot one is still timed in every window it runs", RareMethodNextToHotOne); - yield return ("Profile: a watched method's interval widens with its own load, inside the budget, and comes back down when the load goes away", IntervalFollowsTheLoad); - yield return ("Profile: a watched method called fewer times a window than its interval still has a call timed in every window", FewCallsEveryWindow); - yield return ("Profile: a watched method that is busy in bursts keeps the interval its bursts need through the windows it is not called", BurstsStayInsideTheBudget); - yield return ("Profile: a watched method that ran but was never timed gets a row with sampled 0 and adds no made-up 0 ms to the totals", UntimedWindowIsWrittenNotGuessed); + yield return ("Profile: a rare watched method next to a hot one is still timed in every window it runs", Restoring(RareMethodNextToHotOne)); + yield return ("Profile: a watched method's interval widens with its own load, inside the budget, and comes back down when the load goes away", Restoring(IntervalFollowsTheLoad)); + yield return ("Profile: a watched method called fewer times a window than its interval still has a call timed in every window", Restoring(FewCallsEveryWindow)); + yield return ("Profile: a watched method that is busy in bursts keeps the interval its bursts need through the windows it is not called", Restoring(BurstsStayInsideTheBudget)); + yield return ("Profile: a watched method that ran but was never timed gets a row with sampled 0 and adds no made-up 0 ms to the totals", Restoring(UntimedWindowIsWrittenNotGuessed)); + yield return ("Profile: several busy watched methods share the watched methods' budget between them, not each take all of it", Restoring(BusyMethodsShareTheBudget)); } + // Prepare sets the static budget; put the default back so the checks that run after these see what they would alone. + static Action Restoring(Action check) => () => + { + double budget = Profile.BudgetFraction; + try { check(); } + finally { Profile.BudgetFraction = budget; } + }; + const double PairNs = 50; // what the real recordings calibrate for a sampled pair (samplePairNs) static Rig rig; @@ -155,6 +164,29 @@ static void BurstsStayInsideTheBudget() } } + static void BusyMethodsShareTheBudget() + { + Prepare(); + using (rig) + { + // Four methods, each called 200,000 times in a 1 s window. After the first window each is timed at the interval that keeps all four + // together inside the methods' share of the budget; without the split each would take the whole share, four times over. + int[] ids = Enumerable.Range(0, 4).Select(i => Profile.RegisterMethod("Busy.Method" + i, "M", 8)).ToArray(); + double pairSeconds = PairNs * 1e-9 + 100e-9; + for (int w = 1; w <= 3; w++) + { + foreach (int id in ids) for (int i = 0; i < 200000; i++) Call(id, 0.001); + Profile.FlushWindow(w, w, 1, rig.Prof); + List rows = rig.ProfileRows(); + double share = ids.Sum(id => RowOf(rows, id)[5]) * pairSeconds; + Console.WriteLine(" window " + w + ": the four methods' timing took " + (share * 100).ToString("F3") + "% of a second"); + if (w >= 2) + Check(share <= 0.01 * Profile.BudgetShareMethod * 1.05, "window " + w + ": measuring the four took " + (share * 100).ToString("F3") + + "% of a second, over the watched methods' share of the budget: each took the whole share"); + } + } + } + static void UntimedWindowIsWrittenNotGuessed() { Prepare(); diff --git a/tools/perflog.py b/tools/perflog.py index 9180973..821ac4a 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -49,14 +49,15 @@ # Up to 0.1.3 the `# calibration|` line's patchCallNs timed an empty patch instead of the patch bodies, and every recording shows 0 there. What # overheadUs charged each call of the per-call patches then depends on a reading the header rounds away: exactly 0 made the mod charge an assumed -# 40 ns a call, a reading above 0 (under half a nanosecond) made it charge that. A row whose overheadUs is below 40 ns a patch call proves the second. +# 40 ns a call, a reading above 0 made it charge that. A reading above 0 in the header, or a row whose overheadUs is below 40 ns a patch call, proves +# the second, and an empty patch leaves the bodies out, so those calls were undercharged. # Neither note is printed for a recording whose calibration line has patchBodyNs (KNOWN_ISSUE_APPLIES): a build of the fix that still carries an # older version number measures the patch bodies already. PATCH_CHARGE_ASSUMED_NS = 40.0 PATCH_COST_NOTE = ("overheadUs understates what the mod itself cost: every call of its per-call patches (entity ticks, components, watched " - "methods; the patchCalls column) was charged almost nothing. patchCallNs in the `# calibration|` line timed an empty patch " - "instead of the real bodies and came out just above 0 (this recording has rows whose overheadUs is below the 40 ns a patch " - "call the mod assumes when that reading is exactly 0), so those calls (about 100,000 a second at speed 7 with Profile = deep) " + "methods; the patchCalls column) was charged less than they cost. patchCallNs in the `# calibration|` line timed an empty patch " + "instead of the real bodies and came out above 0 (the header says so, or this recording has rows whose overheadUs is below " + "the 40 ns a patch call the mod assumes when that reading is exactly 0), so those calls (about 100,000 a second at speed 7 with Profile = deep) " "are missing from overheadUs and from the 'measuring cost more than 2% of a frame' warning. The real bodies take a few " "nanoseconds a call, plus what Harmony adds.") PATCH_COST_GUESS_NOTE = ("overheadUs's charge for the per-call patches (entity ticks, components, watched methods; the patchCalls column) is not " @@ -90,17 +91,19 @@ def _empty_patch_charges(session): - """For a recording whose `# calibration|` line has patchCallNs 0 and no patchBodyNs (an empty patch was timed, not the bodies): how many - rows ran patches, and how many of those were charged less than the 40 ns a patch call assumed for a reading of exactly 0. None otherwise.""" + """For a recording whose `# calibration|` line has patchCallNs and no patchBodyNs (an empty patch was timed, not the bodies): how many + rows ran patches, how many of those were charged less than the 40 ns a patch call assumed for a reading of exactly 0, and the reading. + None otherwise.""" calibration = session.pipe("calibration") if not calibration or any("patchBodyNs" in parts for parts in calibration): return None reading = [parts[i + 1] for parts in calibration for i in range(len(parts) - 1) if parts[i] == "patchCallNs"] try: - if not reading or float(reading[0]) != 0: - return None + ns = float(reading[0]) if reading else None except ValueError: return None + if ns is None: + return None ran = below = 0 for r in session.rows: calls, frames = r.get("patchCalls", 0.0), r.get("frames", 0.0) @@ -110,17 +113,17 @@ def _empty_patch_charges(session): # overheadUs is a mean per frame, written to 0.1 us; patchCalls is the total over the row's frames. if (r.get("overheadUs", 0.0) + 0.05) * frames < PATCH_CHARGE_ASSUMED_NS / 1000.0 * calls: below += 1 - return ran, below + return ran, below, ns def _patch_cost_was_understated(session): charges = _empty_patch_charges(session) - return charges is not None and charges[1] > 0 + return charges is not None and charges[0] > 0 and (charges[1] > 0 or charges[2] > 0) def _patch_cost_was_a_guess(session): charges = _empty_patch_charges(session) - return charges is not None and charges[0] > 0 and charges[1] == 0 + return charges is not None and charges[0] > 0 and charges[1] == 0 and charges[2] == 0 def _entity_rows_are_split(session): diff --git a/tools/test_perflog.py b/tools/test_perflog.py index 021562e..f2dcd55 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -624,6 +624,7 @@ def test_a_recording_whose_patch_cost_read_0_is_told_what_overhead_charged_the_p ("0.1.3", old, cheap, None, understated), ("0.1.1", old, dear, dict(overheadUs=30.0, patchCalls=1000.0), understated), # one slow frame at 30 ns a call proves it ("0.1.0", old, dear, dict(overheadUs=45.0, patchCalls=1000.0), guess), + ("0.1.3", old[:-1] + ["2"], dear, None, understated), # read 2 ns: charged that, and the bodies left out ("0.1.3", old, none, None, None), # no patch ran: nothing to say ("0.1.3", new, cheap, None, None), # the bodies were measured ("0.1.3", None, cheap, None, None),