From 78752137bf5c96b3d795b0ff81d432476b781192 Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 04:56:16 -0700 Subject: [PATCH 1/8] PL4: blame a slow frame only on a singleton that took a real part of it summary.md's Blame column and section 5 of `perflog.py report` named the biggest singletons of every slow frame however small they were. In the real 0.1.3 session 2026-09-21_23-13-11 each of the nine 1.1-1.9 s save frames read "<- AnimatorRegistry 1-2 ms", and the sample session blamed PanelStack (1 ms) for a 132 ms garbage-collection frame. A singleton is now named only when it took at least 10% of the frame or at least 5 ms (Summary.BlameMinShare / BlameMinMs, and BLAME_MIN_SHARE / BLAME_MIN_MS in perflog.py). Otherwise the cell says that no singleton stood out, with the largest one's time and share of the frame, and whether the frame had a save or a garbage collection, which no singleton's time shows. spikes.csv stays raw data, and the findings already required a 40% share. Tests (both failed before, naming AnimatorRegistry in the 1142 ms save frame): SummaryTests "a slow frame's Blame names only a singleton that took a real part of it" and test_perflog test_slow_frames_blame_only_a_singleton_that_took_a_real_part. The fixtures' summary.md "slowest frames" sections are regenerated (only that section, so the test process's own heap figures do not churn). Co-Authored-By: Claude Opus 5 --- docs/TESTING.md | 2 +- source/Core/Summary.cs | 39 +++++++++++++++--- tests/SummaryTests.cs | 43 ++++++++++++++++++++ tests/fixtures/sample-with-mod/summary.md | 20 ++++----- tests/fixtures/sample-without-mod/summary.md | 16 ++++---- tools/perflog.py | 29 ++++++++++++- tools/test_perflog.py | 30 ++++++++++++++ 7 files changed, 153 insertions(+), 26 deletions(-) diff --git a/docs/TESTING.md b/docs/TESTING.md index 776e3c4..ba91137 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` (92 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (45 checks). | What | How | |---|---| diff --git a/source/Core/Summary.cs b/source/Core/Summary.cs index 7cac956..7e4d985 100644 --- a/source/Core/Summary.cs +++ b/source/Core/Summary.cs @@ -331,7 +331,8 @@ static void WorstFrames(StringBuilder t, SummaryInput s) t.Append("## The slowest frames\n\n"); if (s.Worst.Count == 0) { t.Append("No frame reached the slow-frame threshold.\n\n"); return; } t.Append("`frames.csv` has a row for every slow frame and `spikes.csv` the biggest contributors to each; these are the worst ").Append(s.Worst.Count) - .Append(". `Biggest parts` are the timed slots of the frame; `Blame` are the singletons that spent the most time in it.\n\n"); + .Append(". `Biggest parts` are the timed slots of the frame; `Blame` names the singletons that took at least ").Append(F(100 * BlameMinShare, 0)) + .Append("% of the frame or ").Append(F(BlameMinMs, 0)).Append(" ms, biggest first. When none did, it says so, and whether the frame had a save or a garbage collection, which no singleton's time shows.\n\n"); t.Append("| Frame | Tick | Frame ms | Speed | Ticks | GC | Save | Biggest parts | Blame |\n|---|---|---|---|---|---|---|---|---|\n"); foreach (WorstFrame w in s.Worst) { @@ -340,16 +341,44 @@ static void WorstFrames(StringBuilder t, SummaryInput s) for (int i = 0; i < Columns.SlotCount; i++) parts.Add(new KeyValuePair(Columns.SlotTimeNames[i], r[Columns.SlotBase + i])); parts.Add(new KeyValuePair("otherMs", r[Columns.OtherMs])); string top = string.Join(", ", parts.OrderByDescending(p => p.Value).Take(3).Select(p => p.Key + " " + F(p.Value, 0))); - var blame = new List(); - for (int i = 0; i < w.TopIds.Length && i < 3; i++) - blame.Add(Short(Profile.NameOf(w.TopIds[i])) + " " + F(w.TopMs[i], 0)); t.Append("| ").Append(F(r[Columns.Frame], 0)).Append(" | ").Append(F(r[Columns.Tick], 0)).Append(" | ").Append(F(r[Columns.FrameMs], 0)).Append(" | ") .Append(F(r[Columns.Speed], 0)).Append(" | ").Append(F(r[Columns.Ticks], 0)).Append(" | ").Append(r[Columns.GcDelta] > 0 ? "yes" : "").Append(" | ") - .Append(r[Columns.Saving] > 0 ? "yes" : "").Append(" | ").Append(top).Append(" | ").Append(string.Join(", ", blame)).Append(" |\n"); + .Append(r[Columns.Saving] > 0 ? "yes" : "").Append(" | ").Append(top).Append(" | ").Append(Blame(w)).Append(" |\n"); } t.Append('\n'); } + /// + /// A singleton is blamed for a slow frame only when it took at least this share of the frame, or at least . + /// The biggest singleton of a frame that a save or a collection made slow is usually a millisecond or two of it, and naming it sends the + /// reader after the wrong thing. tools/perflog.py uses the same two numbers. + /// + public const double BlameMinShare = 0.10; + /// A singleton this long is worth naming in a frame of any length. See . + public const double BlameMinMs = 5; + + /// The Blame cell of a slow frame: the singletons that took a real part of it, or that none did and what else the frame had. + static string Blame(WorstFrame w) + { + double[] r = w.Row; + double frameMs = r[Columns.FrameMs]; + var named = new List(); + // TopIds are biggest first, so the first one below both limits ends the list. + for (int i = 0; i < w.TopIds.Length && i < 3; i++) + { + if (w.TopMs[i] < BlameMinMs && w.TopMs[i] < BlameMinShare * frameMs) break; + named.Add(Short(Profile.NameOf(w.TopIds[i])) + " " + F(w.TopMs[i], 0)); + } + if (named.Count > 0) return string.Join(", ", named); + string text = "no singleton stood out"; + if (w.TopIds.Length > 0) text += " (largest " + F(w.TopMs[0]) + " ms, " + Pct(w.TopMs[0], frameMs) + " of the frame)"; + var had = new List(); + if (r[Columns.Saving] > 0) had.Add("a save"); + if (r[Columns.GcDelta] > 0) had.Add("a garbage collection"); + if (had.Count > 0) text += "; the frame had " + string.Join(" and ", had); + return text; + } + static void Tail(StringBuilder t, SummaryInput s) { if (s.Capabilities.Count > 0) diff --git a/tests/SummaryTests.cs b/tests/SummaryTests.cs index e35ea3c..74ec3b8 100644 --- a/tests/SummaryTests.cs +++ b/tests/SummaryTests.cs @@ -15,6 +15,7 @@ internal static class SummaryTests yield return ("Summary: a session with no profile and no slow frames still renders", NothingSlow); yield return ("Summary: component time is rolled up by mod, and load steps are listed slowest first", ComponentAndLoadTables); yield return ("Summary: slow frames without a row of their own are said to be counted", SkippedRowsAreExplained); + yield return ("Summary: a slow frame's Blame names only a singleton that took a real part of it, else says what the frame had", BlameNeedsARealShare); yield return ("Summary: long class names are shortened and short ones kept", ShortNames); yield return ("Readme: placeholders are filled and no placeholder is left", ReadmePlaceholders); } @@ -120,6 +121,48 @@ static void SkippedRowsAreExplained() finally { rig.Dispose(); } } + static void BlameNeedsARealShare() + { + var rig = new Rig(thresholdMs: 1000); + try + { + for (int i = 0; i < 5; i++) { rig.Advance(16); rig.Frame(); } + int animators = Profile.IdFor(ProfileKind.UpdateSingleton, "Timberborn.TimbermeshAnimations.AnimatorRegistry", "Timberborn.TimbermeshAnimations"); + int panels = Profile.IdFor(ProfileKind.UpdateSingleton, "Timberborn.CoreUI.PanelStack", "Timberborn.CoreUI"); + int routes = Profile.IdFor(ProfileKind.UpdateSingleton, "LateGamePerformance.RouteMapsBackground", "LateGamePerformance"); + int districts = Profile.IdFor(ProfileKind.TickSingleton, "Timberborn.GameDistricts.DistrictCitizenAssigner", "Timberborn.GameDistricts"); + WorstFrame Slow(int frame, double frameMs, double gcDelta, double saveMs, int[] ids, double[] ms) + { + var row = new double[Columns.Count]; + row[Columns.Type] = Columns.FrameRow; row[Columns.Frame] = frame; row[Columns.FrameMs] = frameMs; row[Columns.GcDelta] = gcDelta; + row[Columns.SlotBase + (int)Slot.Save] = saveMs; row[Columns.Saving] = saveMs > 0 ? 1 : 0; + row[Columns.SlotBase + (int)Slot.Update] = ms.Sum(); row[Columns.OtherMs] = frameMs - saveMs - ms.Sum(); + return new WorstFrame { Row = row, TopIds = ids, TopMs = ms }; + } + var input = new SummaryInput { SessionId = "blame", Row = Probe.SessionRow(), Stats = Probe.Stats, Seconds = 60 }; + // As in the real 0.1.3 session: a save of over a second, and the biggest singleton of the frame took about 1 ms of it. + input.Worst.Add(Slow(101, 1142, 1, 1133, new[] { animators }, new[] { 1.4 })); + // As in the sample session: a collection, and a singleton that took 1 ms of 132. + input.Worst.Add(Slow(102, 132, 1, 0, new[] { panels }, new[] { 1.0 })); + // A mod's hitch: one singleton took nearly all of the frame; the one behind it took 1%. + input.Worst.Add(Slow(103, 99, 0, 0, new[] { routes, panels }, new[] { 95.0, 1.0 })); + // 6 ms of a 215 ms frame is under 10% but over 5 ms: a singleton that long is worth naming in any frame. + input.Worst.Add(Slow(104, 215, 1, 0, new[] { districts, panels }, new[] { 6.0, 1.0 })); + string text = Summary.Render(input); + string Row(int frame) => text.Split('\n').Single(l => l.StartsWith("| " + frame + " | ")); + + string save = Row(101), gc = Row(102), hitch = Row(103), mixed = Row(104); + Check(!save.Contains("AnimatorRegistry"), "a 1 ms singleton is not blamed for a 1142 ms save: " + save); + Check(save.Contains("no singleton stood out") && save.Contains("save"), "the save frame says no singleton stood out, and that it had a save: " + save); + Check(!gc.Contains("PanelStack"), "a 1 ms singleton is not blamed for a 132 ms collection: " + gc); + Check(gc.Contains("no singleton stood out") && gc.Contains("garbage collection"), "the collection frame says so: " + gc); + Check(hitch.Contains("RouteMapsBackground 95"), "the singleton that took the frame is named: " + hitch); + Check(!hitch.Contains("PanelStack") && !hitch.Contains("stood out"), "and only it: " + hitch); + Check(mixed.Contains("DistrictCitizenAssigner 6") && !mixed.Contains("PanelStack"), "5 ms or more is named whatever the share: " + mixed); + } + finally { rig.Dispose(); } + } + static void ShortNames() { Equal("Timberborn.Foo.Bar", Summary.Short("Timberborn.Foo.Bar")); diff --git a/tests/fixtures/sample-with-mod/summary.md b/tests/fixtures/sample-with-mod/summary.md index a035517..3d811e1 100644 --- a/tests/fixtures/sample-with-mod/summary.md +++ b/tests/fixtures/sample-with-mod/summary.md @@ -139,19 +139,19 @@ Processor time was not available on this computer. ## The slowest frames -`frames.csv` has a row for every slow frame and `spikes.csv` the biggest contributors to each; these are the worst 9. `Biggest parts` are the timed slots of the frame; `Blame` are the singletons that spent the most time in it. +`frames.csv` has a row for every slow frame and `spikes.csv` the biggest contributors to each; these are the worst 9. `Biggest parts` are the timed slots of the frame; `Blame` names the singletons that took at least 10% of the frame or 5 ms, biggest first. When none did, it says so, and whether the frame had a save or a garbage collection, which no singleton's time shows. | Frame | Tick | Frame ms | Speed | Ticks | GC | Save | Biggest parts | Blame | |---|---|---|---|---|---|---|---|---| -| 7140 | 795 | 437 | 3 | 1 | | yes | saveMs 430, entMs 2, updMs 2 | Timberborn.WaterSystem.WaterSimulator 1, Timberborn.CoreUI.PanelStack 1, Timberborn.Navigation.NavigationSynchronizer 0 | -| 5099 | 454 | 132 | 3 | 0 | yes | | otherMs 128, entMs 2, updMs 2 | Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0, LateGamePerformance.RouteMapsBackground 0 | -| 1499 | 83 | 125 | 1 | 0 | yes | | otherMs 122, updMs 2, entMs 1 | Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0, LateGamePerformance.RouteMapsBackground 0 | -| 2599 | 144 | 124 | 1 | 0 | yes | | otherMs 121, updMs 2, entMs 1 | Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0, LateGamePerformance.RouteMapsBackground 0 | -| 3899 | 253 | 112 | 3 | 0 | yes | | otherMs 108, entMs 2, updMs 2 | Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0, LateGamePerformance.RouteMapsBackground 0 | -| 6799 | 738 | 107 | 3 | 1 | yes | | otherMs 100, entMs 2, singMs 2 | Timberborn.WaterSystem.WaterSimulator 1, Timberborn.CoreUI.PanelStack 1, Timberborn.Navigation.NavigationSynchronizer 0 | -| 699 | 38 | 105 | 1 | 0 | yes | | otherMs 102, updMs 2, entMs 1 | Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0, LateGamePerformance.RouteMapsBackground 0 | -| 4699 | 387 | 99 | 3 | 0 | | | updMs 97, entMs 2, otherMs 0 | LateGamePerformance.RouteMapsBackground 95, Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0 | -| 3299 | 183 | 97 | 1 | 0 | | | updMs 96, entMs 1, otherMs 0 | LateGamePerformance.RouteMapsBackground 95, Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0 | +| 7140 | 795 | 437 | 3 | 1 | | yes | saveMs 430, entMs 2, updMs 2 | no singleton stood out (largest 1.2 ms, 0.3% of the frame); the frame had a save | +| 5099 | 454 | 132 | 3 | 0 | yes | | otherMs 128, entMs 2, updMs 2 | no singleton stood out (largest 0.9 ms, 0.7% of the frame); the frame had a garbage collection | +| 1499 | 83 | 125 | 1 | 0 | yes | | otherMs 122, updMs 2, entMs 1 | no singleton stood out (largest 0.9 ms, 0.7% of the frame); the frame had a garbage collection | +| 2599 | 144 | 124 | 1 | 0 | yes | | otherMs 121, updMs 2, entMs 1 | no singleton stood out (largest 1.0 ms, 0.8% of the frame); the frame had a garbage collection | +| 3899 | 253 | 112 | 3 | 0 | yes | | otherMs 108, entMs 2, updMs 2 | no singleton stood out (largest 0.9 ms, 0.8% of the frame); the frame had a garbage collection | +| 6799 | 738 | 107 | 3 | 1 | yes | | otherMs 100, entMs 2, singMs 2 | no singleton stood out (largest 1.1 ms, 1.0% of the frame); the frame had a garbage collection | +| 699 | 38 | 105 | 1 | 0 | yes | | otherMs 102, updMs 2, entMs 1 | no singleton stood out (largest 1.1 ms, 1.0% of the frame); the frame had a garbage collection | +| 4699 | 387 | 99 | 3 | 0 | | | updMs 97, entMs 2, otherMs 0 | LateGamePerformance.RouteMapsBackground 95 | +| 3299 | 183 | 97 | 1 | 0 | | | updMs 96, entMs 1, otherMs 0 | LateGamePerformance.RouteMapsBackground 95 | ## What each measurement source could do diff --git a/tests/fixtures/sample-without-mod/summary.md b/tests/fixtures/sample-without-mod/summary.md index 06755c7..cebd173 100644 --- a/tests/fixtures/sample-without-mod/summary.md +++ b/tests/fixtures/sample-without-mod/summary.md @@ -136,17 +136,17 @@ Processor time was not available on this computer. ## The slowest frames -`frames.csv` has a row for every slow frame and `spikes.csv` the biggest contributors to each; these are the worst 7. `Biggest parts` are the timed slots of the frame; `Blame` are the singletons that spent the most time in it. +`frames.csv` has a row for every slow frame and `spikes.csv` the biggest contributors to each; these are the worst 7. `Biggest parts` are the timed slots of the frame; `Blame` names the singletons that took at least 10% of the frame or 5 ms, biggest first. When none did, it says so, and whether the frame had a save or a garbage collection, which no singleton's time shows. | Frame | Tick | Frame ms | Speed | Ticks | GC | Save | Biggest parts | Blame | |---|---|---|---|---|---|---|---|---| -| 7153 | 796 | 433 | 3 | 0 | | yes | saveMs 430, entMs 2, updMs 1 | Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0, Timberborn.TimeSystem.SpeedManager 0 | -| 1499 | 83 | 121 | 1 | 0 | yes | | otherMs 119, updMs 1, entMs 1 | Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0, Timberborn.TimeSystem.SpeedManager 0 | -| 6799 | 737 | 121 | 3 | 0 | yes | | otherMs 117, entMs 2, updMs 1 | Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0, Timberborn.TimeSystem.SpeedManager 0 | -| 5099 | 453 | 109 | 3 | 0 | yes | | otherMs 105, entMs 2, updMs 1 | Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0, Timberborn.TimeSystem.SpeedManager 0 | -| 699 | 38 | 106 | 1 | 0 | yes | | otherMs 104, updMs 1, entMs 0 | Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0, Timberborn.TimeSystem.SpeedManager 0 | -| 3899 | 253 | 105 | 3 | 1 | yes | | otherMs 99, entMs 2, singMs 2 | Timberborn.WaterSystem.WaterSimulator 1, Timberborn.CoreUI.PanelStack 1, Timberborn.Navigation.NavigationSynchronizer 0 | -| 2599 | 144 | 97 | 1 | 0 | yes | | otherMs 95, updMs 1, entMs 1 | Timberborn.CoreUI.PanelStack 1, Timberborn.CameraSystem.CameraService 0, Timberborn.TimeSystem.SpeedManager 0 | +| 7153 | 796 | 433 | 3 | 0 | | yes | saveMs 430, entMs 2, updMs 1 | no singleton stood out (largest 0.9 ms, 0.2% of the frame); the frame had a save | +| 1499 | 83 | 121 | 1 | 0 | yes | | otherMs 119, updMs 1, entMs 1 | no singleton stood out (largest 0.9 ms, 0.7% of the frame); the frame had a garbage collection | +| 6799 | 737 | 121 | 3 | 0 | yes | | otherMs 117, entMs 2, updMs 1 | no singleton stood out (largest 1.1 ms, 0.9% of the frame); the frame had a garbage collection | +| 5099 | 453 | 109 | 3 | 0 | yes | | otherMs 105, entMs 2, updMs 1 | no singleton stood out (largest 1.1 ms, 1.0% of the frame); the frame had a garbage collection | +| 699 | 38 | 106 | 1 | 0 | yes | | otherMs 104, updMs 1, entMs 0 | no singleton stood out (largest 0.9 ms, 0.9% of the frame); the frame had a garbage collection | +| 3899 | 253 | 105 | 3 | 1 | yes | | otherMs 99, entMs 2, singMs 2 | no singleton stood out (largest 1.3 ms, 1.3% of the frame); the frame had a garbage collection | +| 2599 | 144 | 97 | 1 | 0 | yes | | otherMs 95, updMs 1, entMs 1 | no singleton stood out (largest 0.9 ms, 0.9% of the frame); the frame had a garbage collection | ## What each measurement source could do diff --git a/tools/perflog.py b/tools/perflog.py index 39bd17f..4c7f40a 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -45,6 +45,10 @@ ]) # A session whose mean frame is faster than this (50 fps) is not what anyone complains about, so a share of its frame is not a finding. SLOW_MEAN_MS = 20.0 +# A singleton is blamed for a slow frame only when it took at least this share of the frame (percent) or this many milliseconds, as in the +# mod's summary.md (Summary.BlameMinShare, BlameMinMs): the biggest singleton of a frame a save or a collection made slow is a millisecond or two. +BLAME_MIN_SHARE = 10.0 +BLAME_MIN_MS = 5.0 LOAD_KINDS = ("load", "load-non-singleton", "post-load", "post-load-non-singleton") # 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 @@ -605,6 +609,28 @@ def findings_for(session, args): # ---------------------------------------------------------------- report +def blame_text(frame_row, spikes): + """What a slow frame is blamed on in section 5: the singletons that took a real part of it, or that none did and what else the frame had. + Empty when spikes.csv has nothing for the frame (no singleton was timed in it).""" + ranked = sorted(spikes, key=lambda x: x["rank"]) + if not ranked: + return "" + frame_ms = frame_row["frameMs"] + + def share(x): + return x["share"] if "share" in x else (100.0 * x["ms"] / frame_ms if frame_ms else 0.0) + named = [] + for x in ranked[:2]: + if x["ms"] < BLAME_MIN_MS and share(x) < BLAME_MIN_SHARE: + break # biggest first, so nothing after it is bigger + named.append(x) + if named: + return " <- " + ", ".join("%s %.0f ms" % (short(x.get("name", "?"), 40), x["ms"]) for x in named) + had = [what for what, on in (("a save", frame_row["saving"]), ("a garbage collection", frame_row["gcDelta"] > 0)) if on] + return " <- no singleton stood out (largest %.1f ms, %.1f%% of the frame)%s" % (ranked[0]["ms"], share(ranked[0]), + "; the frame had " + " and ".join(had) if had else "") + + def report(session, args, out): p = lambda text="": out.write(text + "\n") S = steady(session, args.warmup) @@ -692,10 +718,9 @@ def report(session, args, out): why.append("background") if r["paused"]: why.append("paused") - b = sorted(blame.get(int(r["frame"]), []), key=lambda x: x["rank"])[:2] p(" frame %-6d tick %-6d %6.0f ms speed %g %s%s%s" % (r["frame"], r["tick"], r["frameMs"], r["speed"], "[" + ",".join(why) + "] " if why else "", ", ".join("%s %.0f" % (s, v) for v, s in parts), - (" <- " + ", ".join("%s %.0f ms" % (short(x.get("name", "?"), 40), x["ms"]) for x in b)) if b else "")) + blame_text(r, blame.get(int(r["frame"]), [])))) p() first = S[0]["tick"] - 1 if S else 0 diff --git a/tools/test_perflog.py b/tools/test_perflog.py index 72d3064..51a37f9 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -570,6 +570,36 @@ def test_quiet_session_says_nothing_stands_out(self): text = self.report(s) self.assertIn("Nothing stands out", text) + def test_slow_frames_blame_only_a_singleton_that_took_a_real_part(self): + s = Synthetic() + for _ in range(6): + s.window() + # As in the real 0.1.3 session: a save of over a second whose biggest singleton took about 1 ms; as in the sample, a collection + # whose biggest singleton took 1 ms of 132; a mod's hitch; and a 6 ms singleton in a 215 ms frame (under 10%, but 5 ms or more). + save = s.slow_frame(1142.0, saving=1.0, saveMs=1133.0, gcDelta=1.0, otherMs=7.6) + gc = s.slow_frame(132.0, gcDelta=1.0, otherMs=131.0) + hitch = s.slow_frame(99.0, updMs=96.0, otherMs=3.0) + mixed = s.slow_frame(215.0, gcDelta=1.0, singMs=7.0, otherMs=208.0) + for row, rank, name, ms in ((save, 1, "Timberborn.TimbermeshAnimations.AnimatorRegistry", 1.4), (gc, 1, "Timberborn.CoreUI.PanelStack", 1.0), + (hitch, 1, "LateGamePerformance.RouteMapsBackground", 95.0), (hitch, 2, "Timberborn.CoreUI.PanelStack", 1.0), + (mixed, 1, "Timberborn.GameDistricts.DistrictCitizenAssigner", 6.0), (mixed, 2, "Timberborn.CoreUI.PanelStack", 1.0)): + s.spikes.append({"frame": row["frame"], "tick": row["tick"], "utcMs": row["utcMs"], "frameMs": row["frameMs"], "rank": rank, "kind": "update-singleton", + "id": rank, "ms": ms, "share": 100.0 * ms / row["frameMs"], "name": name, "mod": "game"}) + text = self.report(s) + section = text.split("5. THE SLOWEST FRAMES")[1].split("\n\n")[0] + + def line(row): + return [l for l in section.splitlines() if l.strip().startswith("frame %d " % row["frame"])][0] + self.assertNotIn("AnimatorRegistry", line(save), "a 1 ms singleton is not blamed for a 1142 ms save") + self.assertIn("no singleton stood out", line(save)) + self.assertIn("save", line(save).split("<-")[1]) + self.assertNotIn("PanelStack", line(gc), "a 1 ms singleton is not blamed for a 132 ms collection") + self.assertIn("garbage collection", line(gc).split("<-")[1]) + self.assertIn("<- LateGamePerformance.RouteMapsBackground 95 ms", line(hitch)) + self.assertNotIn("PanelStack", line(hitch), "the 1 ms one behind it is not named") + self.assertIn("DistrictCitizenAssigner 6 ms", line(mixed), "5 ms or more is named whatever the share") + self.assertNotIn("PanelStack", line(mixed)) + def test_hitches_on_a_rhythm_are_matched_to_the_autosave(self): s = Synthetic() for i in range(12): From 793fcd4d81fcf9fc2ad73d00cabdd771b76f8124 Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 05:01:09 -0700 Subject: [PATCH 2/8] PL5: split otherMs by Unity phase otherMs (frame time outside every timed part) was reported as one number, and when it dominated a slow session the report always said "Most of the frame is not the game's or any mod's code ... likely the graphics card", even when the time was script code in Unity's Update phase. The phase columns already recorded say where it went: the game's tick loop and singleton updates run inside plUpdate (Ticker.Update, SingletonLifecycleUnityAdapter.Update), the late singletons inside plLate, and drawing and the vsync wait are plPost. summary.md ("Where an average frame goes") and section 3 of `perflog.py report` now split otherMs into: plUpdate less the timed parts that run in it (other scripts' Update: the game's and mods' MonoBehaviours, coroutines); plLate less lateMs, labelled "other work in Unity's LateUpdate phase" (animation, UI Toolkit, scripts' LateUpdate), not mods; plPost; the phases before Update; and what falls between the phases. saveMs runs in LateUpdate for the game's own save (GameSaverUnityAdapter.LateUpdate) and in Update when BeaverBuddies defers it to a tick (the real 0.1.3 session has both), so it is taken out of the phase with more room left. On the real session 2026-09-21_23-13-11 the split reads 1.33 / 1.14 / 3.91 / 0.16 / 0.13 ms of 6.67 ms. Summary.OtherByPhase and perflog.split_other use the same rule; the report applies it per summary row, the summary to the session row. It is printed only when phases were measured, so older recordings read as before. The "not the game's code" finding now looks at the split: when the Update or LateUpdate remainder is bigger than plPost it points at scripts running every frame (or animation and UI), not the graphics card. report --json gains otherMsByPhase. SESSION-README (and so the fixtures' README.md) explains the split. Tests (failed before: no split in the summary or report, no split_other, and the GPU finding for a frame spent in Update): SummaryTests "otherMs is split by Unity phase", test_perflog test_other_ms_is_split_by_unity_phase, test_the_report_splits_other_ms_by_unity_phase and test_other_ms_in_the_update_phase_points_at_scripts_not_the_graphics_card. Co-Authored-By: Claude Opus 5 --- docs/SESSION-README.md | 4 + docs/TESTING.md | 2 +- source/Core/Summary.cs | 44 +++++++++++ tests/SummaryTests.cs | 49 ++++++++++++ tests/fixtures/sample-with-mod/README.md | 4 + tests/fixtures/sample-with-mod/summary.md | 10 +++ tests/fixtures/sample-without-mod/README.md | 4 + tests/fixtures/sample-without-mod/summary.md | 10 +++ tools/perflog.py | 83 ++++++++++++++++++-- tools/test_perflog.py | 45 +++++++++++ 10 files changed, 247 insertions(+), 8 deletions(-) diff --git a/docs/SESSION-README.md b/docs/SESSION-README.md index d6f7769..0e9754a 100644 --- a/docs/SESSION-README.md +++ b/docs/SESSION-README.md @@ -61,6 +61,10 @@ Start by writing down what the complaint is, because the causes differ: game thread is still not busy. Then check `prDraw`/`prSetPass`/`prBatches`/`prTris` (a lot of drawing), the resolution and `# gpu|`. This is a graphics-settings problem, not a mod problem, unless a mod adds drawing. When frames are pinned at the sync interval, **compare work, not frame time**: the sum of the timed parts (everything but `otherMs`) is what a change in the game or a mod moves. + **If `otherMs` is big but `plPost` is not**, the time is code, not drawing. `summary.md` (and `perflog.py report`) split `otherMs` by phase: + `plUpdate` less the timed parts that run in it (`tickMs` to `parStartMs`, `updMs`) is other scripts' Update (the game's own MonoBehaviours, mods' + scripts, coroutines); `plLate` less `lateMs` is other work in Unity's LateUpdate phase (animation, UI Toolkit, scripts' LateUpdate), which is not + necessarily a mod. A save runs in `plLate` for the game's own and in `plUpdate` when a mod defers it to the end of a tick. 2. **`updMs` is big**: per-frame singleton updates (the user interface, the camera, input, and many mods). `profile.csv` rows of kind `update-singleton` name them, with `mod`. 3. **`tickMs`, `singMs`, `entMs`, `parWaitMs`, `parStartMs` are big**: the simulation. Divide by `ticks` to get ms per tick. diff --git a/docs/TESTING.md b/docs/TESTING.md index ba91137..b1af224 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` (92 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (45 checks). +`dotnet run --project tests -c Release` (93 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (48 checks). | What | How | |---|---| diff --git a/source/Core/Summary.cs b/source/Core/Summary.cs index 7e4d985..b987522 100644 --- a/source/Core/Summary.cs +++ b/source/Core/Summary.cs @@ -155,10 +155,54 @@ static void WhereFramesGo(StringBuilder t, SummaryInput s, double[] r) t.Append("| `").Append(Columns.PhaseNames[i]).Append("` | ").Append(F(ms, 2)).Append(" | ").Append(Pct(ms, mean)).Append(" |\n"); } t.Append('\n'); + double[] split = OtherByPhase(r); + t.Append("How `otherMs` splits by Unity phase (each phase less the timed parts that run in it):\n\n| Part of `otherMs` | ms per frame | Share of `otherMs` |\n|---|---|---|\n"); + for (int i = 0; i < OtherSplitNames.Length; i++) + t.Append("| ").Append(OtherSplitNames[i]).Append(" | ").Append(F(split[i], 2)).Append(" | ").Append(Pct(split[i], r[Columns.OtherMs])).Append(" |\n"); + t.Append('\n'); } else t.Append("_Unity's frame phases were not measured (see the capabilities below)._\n\n"); } + static readonly int UpdatePhase = Array.IndexOf(Columns.PhaseNames, "plUpdate"), LatePhase = Array.IndexOf(Columns.PhaseNames, "plLate"), + PostPhase = Array.IndexOf(Columns.PhaseNames, "plPost"); + + static readonly string[] OtherSplitNames = + { + "Update phase outside the timed parts: other scripts' Update (the game's and mods' MonoBehaviours) and coroutines", + "LateUpdate phase outside `lateMs`: other work in Unity's LateUpdate phase (animation, UI Toolkit, scripts' LateUpdate)", + "`plPost`: drawing, presenting the frame and the wait for vertical sync", + "Unity's other phases (`plTime` to `plPre`: time, input, physics)", + "Between the phases", + }; + + /// + /// otherMs of a row split by Unity phase, in the order of : the Update phase less the timed parts that run + /// in it (the tick loop with its parts, and the singleton updates), the LateUpdate phase less lateMs, plPost, the phases before + /// Update, and what falls between the phases. The game saves in its LateUpdate and a mod that defers the save to the end of a tick + /// (BeaverBuddies) in Update; the row does not say which, so saveMs is taken out of the phase with more room left. That is the phase it + /// ran in, except for a save shorter than the gap between the two phases' own remainders, and then the error is less than the save. + /// tools/perflog.py (split_other) splits the same way. + /// + static double[] OtherByPhase(double[] r) + { + double update = r[Columns.PhaseBase + UpdatePhase], late = r[Columns.PhaseBase + LatePhase] - r[Columns.SlotBase + (int)Slot.LateUpdate]; + for (int i = 0; i <= (int)Slot.Update; i++) update -= r[Columns.SlotBase + i]; + double save = r[Columns.SlotBase + (int)Slot.Save]; + if (save > 0) + { + if (late >= update) late -= save; + else update -= save; + } + var split = new double[OtherSplitNames.Length]; + split[0] = Math.Max(0, update); + split[1] = Math.Max(0, late); + split[2] = r[Columns.PhaseBase + PostPhase]; + for (int i = 0; i < UpdatePhase; i++) split[3] += r[Columns.PhaseBase + i]; + split[4] = Math.Max(0, r[Columns.OtherMs] - split[0] - split[1] - split[2] - split[3]); + return split; + } + static void Ticks(StringBuilder t, SummaryInput s, double[] r) { double frames = r[Columns.Frames], ticks = r[Columns.Ticks]; diff --git a/tests/SummaryTests.cs b/tests/SummaryTests.cs index 74ec3b8..c489e3a 100644 --- a/tests/SummaryTests.cs +++ b/tests/SummaryTests.cs @@ -16,6 +16,7 @@ internal static class SummaryTests yield return ("Summary: component time is rolled up by mod, and load steps are listed slowest first", ComponentAndLoadTables); yield return ("Summary: slow frames without a row of their own are said to be counted", SkippedRowsAreExplained); yield return ("Summary: a slow frame's Blame names only a singleton that took a real part of it, else says what the frame had", BlameNeedsARealShare); + yield return ("Summary: otherMs is split by Unity phase, each phase less the timed parts that run in it", OtherSplitByPhase); yield return ("Summary: long class names are shortened and short ones kept", ShortNames); yield return ("Readme: placeholders are filled and no placeholder is left", ReadmePlaceholders); } @@ -163,6 +164,54 @@ WorstFrame Slow(int frame, double frameMs, double gcDelta, double saveMs, int[] finally { rig.Dispose(); } } + static void OtherSplitByPhase() + { + var rig = new Rig(thresholdMs: 1000); + try + { + // A 20 ms frame, laid out as Unity runs it: 0.2 ms of plTime; a 9 ms Update phase holding 2 ms of singleton updates and 4 ms of + // entity ticks; a 2.5 ms LateUpdate phase holding 0.5 ms of late singletons; 0.8 ms between the phases; 7.5 ms of plPost. + for (int i = 0; i < 5; i++) + { + Probe.PhaseMark(0, true); rig.Advance(0.2); Probe.PhaseMark(0, false); + Probe.PhaseMark(5, true); + long update = Probe.Begin(Slot.Update); rig.Advance(2); Probe.End(update); + long entities = Probe.Begin(Slot.Entities); rig.Advance(4); Probe.End(entities); + rig.Advance(3); + Probe.PhaseMark(5, false); + Probe.PhaseMark(6, true); + long late = Probe.Begin(Slot.LateUpdate); rig.Advance(0.5); Probe.End(late); + rig.Advance(2); + Probe.PhaseMark(6, false); + rig.Advance(0.8); + Probe.PhaseMark(7, true); rig.Advance(7.5); Probe.PhaseMark(7, false); + rig.Frame(); + } + double[] row = Probe.SessionRow(); + Near(13.5, row[Columns.OtherMs], .001, "otherMs is the time no part covers"); + string text = Summary.Render(new SummaryInput { SessionId = "phases", Row = row, Stats = Probe.Stats, Seconds = 1 }); + Check(text.Contains("How `otherMs` splits by Unity phase"), "the split is not in the summary"); + string Line(string summary, string start) => summary.Split('\n').Single(l => l.StartsWith("| " + start)); + Check(Line(text, "Update phase").Contains("| 3.00 |"), "the Update phase less the timed parts in it: " + Line(text, "Update phase")); + Check(Line(text, "LateUpdate phase").Contains("| 2.00 |"), "the LateUpdate phase less lateMs: " + Line(text, "LateUpdate phase")); + Check(Line(text, "LateUpdate phase").Contains("other work in Unity's LateUpdate phase"), "and it is not called mods' work"); + Check(Line(text, "`plPost`:").Contains("| 7.50 |"), Line(text, "`plPost`:")); + Check(Line(text, "Unity's other phases").Contains("| 0.20 |"), Line(text, "Unity's other phases")); + Check(Line(text, "Between the phases").Contains("| 0.80 |"), Line(text, "Between the phases")); + + // A save is taken out of the phase it ran in: LateUpdate for the game's own, Update when a mod defers it to the end of a tick. + foreach (int phase in new[] { 6, 5 }) + { + double[] saved = (double[])row.Clone(); + saved[Columns.SlotBase + (int)Slot.Save] = 3; saved[Columns.PhaseBase + phase] += 3; saved[Columns.FrameMs] += 3; + string withSave = Summary.Render(new SummaryInput { SessionId = "save", Row = saved, Stats = Probe.Stats, Seconds = 1 }); + Check(Line(withSave, "Update phase").Contains("| 3.00 |") && Line(withSave, "LateUpdate phase").Contains("| 2.00 |"), + "a save in " + Columns.PhaseNames[phase] + " is taken out of that phase: " + Line(withSave, "Update phase") + " / " + Line(withSave, "LateUpdate phase")); + } + } + finally { rig.Dispose(); } + } + static void ShortNames() { Equal("Timberborn.Foo.Bar", Summary.Short("Timberborn.Foo.Bar")); diff --git a/tests/fixtures/sample-with-mod/README.md b/tests/fixtures/sample-with-mod/README.md index 2687cb5..b5b7ce6 100644 --- a/tests/fixtures/sample-with-mod/README.md +++ b/tests/fixtures/sample-with-mod/README.md @@ -61,6 +61,10 @@ Start by writing down what the complaint is, because the causes differ: game thread is still not busy. Then check `prDraw`/`prSetPass`/`prBatches`/`prTris` (a lot of drawing), the resolution and `# gpu|`. This is a graphics-settings problem, not a mod problem, unless a mod adds drawing. When frames are pinned at the sync interval, **compare work, not frame time**: the sum of the timed parts (everything but `otherMs`) is what a change in the game or a mod moves. + **If `otherMs` is big but `plPost` is not**, the time is code, not drawing. `summary.md` (and `perflog.py report`) split `otherMs` by phase: + `plUpdate` less the timed parts that run in it (`tickMs` to `parStartMs`, `updMs`) is other scripts' Update (the game's own MonoBehaviours, mods' + scripts, coroutines); `plLate` less `lateMs` is other work in Unity's LateUpdate phase (animation, UI Toolkit, scripts' LateUpdate), which is not + necessarily a mod. A save runs in `plLate` for the game's own and in `plUpdate` when a mod defers it to the end of a tick. 2. **`updMs` is big**: per-frame singleton updates (the user interface, the camera, input, and many mods). `profile.csv` rows of kind `update-singleton` name them, with `mod`. 3. **`tickMs`, `singMs`, `entMs`, `parWaitMs`, `parStartMs` are big**: the simulation. Divide by `ticks` to get ms per tick. diff --git a/tests/fixtures/sample-with-mod/summary.md b/tests/fixtures/sample-with-mod/summary.md index 3d811e1..d168518 100644 --- a/tests/fixtures/sample-with-mod/summary.md +++ b/tests/fixtures/sample-with-mod/summary.md @@ -55,6 +55,16 @@ Unity's phases of a frame (the wait for vertical sync is in one of them, usually | `plUpdate` | 3.75 | 22.3% | | `plPost` | 12.75 | 76.0% | +How `otherMs` splits by Unity phase (each phase less the timed parts that run in it): + +| Part of `otherMs` | ms per frame | Share of `otherMs` | +|---|---|---| +| Update phase outside the timed parts: other scripts' Update (the game's and mods' MonoBehaviours) and coroutines | 0.02 | 0.1% | +| LateUpdate phase outside `lateMs`: other work in Unity's LateUpdate phase (animation, UI Toolkit, scripts' LateUpdate) | 0.00 | 0.0% | +| `plPost`: drawing, presenting the frame and the wait for vertical sync | 12.75 | 98.2% | +| Unity's other phases (`plTime` to `plPre`: time, input, physics) | 0.20 | 1.5% | +| Between the phases | 0.02 | 0.2% | + ## Simulation ticks - 2440 ticks in 300 s, so 8.1 ticks per second on average. The game's tick is 0.30 s of game time, so at speed 1 it runs 3.3 ticks per second, proportionally more at higher speeds. diff --git a/tests/fixtures/sample-without-mod/README.md b/tests/fixtures/sample-without-mod/README.md index 2687cb5..b5b7ce6 100644 --- a/tests/fixtures/sample-without-mod/README.md +++ b/tests/fixtures/sample-without-mod/README.md @@ -61,6 +61,10 @@ Start by writing down what the complaint is, because the causes differ: game thread is still not busy. Then check `prDraw`/`prSetPass`/`prBatches`/`prTris` (a lot of drawing), the resolution and `# gpu|`. This is a graphics-settings problem, not a mod problem, unless a mod adds drawing. When frames are pinned at the sync interval, **compare work, not frame time**: the sum of the timed parts (everything but `otherMs`) is what a change in the game or a mod moves. + **If `otherMs` is big but `plPost` is not**, the time is code, not drawing. `summary.md` (and `perflog.py report`) split `otherMs` by phase: + `plUpdate` less the timed parts that run in it (`tickMs` to `parStartMs`, `updMs`) is other scripts' Update (the game's own MonoBehaviours, mods' + scripts, coroutines); `plLate` less `lateMs` is other work in Unity's LateUpdate phase (animation, UI Toolkit, scripts' LateUpdate), which is not + necessarily a mod. A save runs in `plLate` for the game's own and in `plUpdate` when a mod defers it to the end of a tick. 2. **`updMs` is big**: per-frame singleton updates (the user interface, the camera, input, and many mods). `profile.csv` rows of kind `update-singleton` name them, with `mod`. 3. **`tickMs`, `singMs`, `entMs`, `parWaitMs`, `parStartMs` are big**: the simulation. Divide by `ticks` to get ms per tick. diff --git a/tests/fixtures/sample-without-mod/summary.md b/tests/fixtures/sample-without-mod/summary.md index cebd173..0b6a750 100644 --- a/tests/fixtures/sample-without-mod/summary.md +++ b/tests/fixtures/sample-without-mod/summary.md @@ -55,6 +55,16 @@ Unity's phases of a frame (the wait for vertical sync is in one of them, usually | `plUpdate` | 3.40 | 20.3% | | `plPost` | 13.10 | 78.2% | +How `otherMs` splits by Unity phase (each phase less the timed parts that run in it): + +| Part of `otherMs` | ms per frame | Share of `otherMs` | +|---|---|---| +| Update phase outside the timed parts: other scripts' Update (the game's and mods' MonoBehaviours) and coroutines | 0.03 | 0.2% | +| LateUpdate phase outside `lateMs`: other work in Unity's LateUpdate phase (animation, UI Toolkit, scripts' LateUpdate) | 0.00 | 0.0% | +| `plPost`: drawing, presenting the frame and the wait for vertical sync | 13.10 | 98.2% | +| Unity's other phases (`plTime` to `plPre`: time, input, physics) | 0.20 | 1.5% | +| Between the phases | 0.01 | 0.1% | + ## Simulation ticks - 2441 ticks in 300 s, so 8.1 ticks per second on average. The game's tick is 0.30 s of game time, so at speed 1 it runs 3.3 ticks per second, proportionally more at higher speeds. diff --git a/tools/perflog.py b/tools/perflog.py index 4c7f40a..feb5933 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -31,6 +31,18 @@ "otherMs": "the rest: drawing, other scripts, other mods, the system", } PHASES = ["plTime", "plInit", "plEarly", "plFixed", "plPre", "plUpdate", "plLate", "plPost"] +# The timed parts that run inside Unity's Update phase (the game's tick loop and its singleton updates). lateMs runs in the LateUpdate phase +# (plLate); nothing this mod times runs in the phases before Update. +UPDATE_PHASE_SLOTS = TICK_SLOTS + ["updMs"] +EARLY_PHASES = ["plTime", "plInit", "plEarly", "plFixed", "plPre"] +# How otherMs splits by phase: (key, label, what it is). Summary.OtherByPhase in the mod splits the same way. +OTHER_SPLIT = [ + ("update", "Update phase, outside the timed parts", "other scripts' Update (the game's and mods' MonoBehaviours) and coroutines"), + ("late", "LateUpdate phase, outside lateMs", "other work in Unity's LateUpdate phase: animation, UI Toolkit, scripts' LateUpdate"), + ("post", "plPost", "drawing, presenting the frame and the wait for vertical sync"), + ("phases", "Unity's other phases", "plTime to plPre: time, input, physics"), + ("between", "between the phases", "what falls between Unity's phases"), +] FRAME_EDGES_DEFAULT = [4, 6, 8.5, 11.5, 14, 17.5, 21, 25, 30, 35, 42, 50, 75, 100, 200, 400] REQUIRED = ["type", "frame", "tick", "utcMs", "frames", "frameMs", "maxFrameMs", "ticks", "speed", "paused", "saving", "unfocused"] + SLOTS + \ ["otherMs", "gcDelta", "heapMB", "allocKB", "overheadUs", "probeUs"] @@ -255,6 +267,39 @@ def seconds_of(rows): return sum(r["frameMs"] * r["frames"] for r in rows) / 1000.0 +def phases_measured(session, rows): + """True when the recording timed Unity's phases (the playerLoop capability), so otherMs can be split by them.""" + return all(p in session.columns for p in PHASES) and sum(wmean(rows, p) for p in PHASES) > 0 + + +def split_other(r): + """otherMs of one row (times per frame) by Unity phase: each phase less the timed parts that run in it, plPost, the phases before Update, + and what falls between the phases. The game saves in its LateUpdate and a mod that defers the save to the end of a tick (BeaverBuddies) + in Update; the row does not say which, so saveMs is taken out of the phase with more room left. That is the phase it ran in, except for a + save shorter than the gap between the two phases' own remainders, and then the error is less than the save.""" + update = r.get("plUpdate", 0.0) - sum(r[s] for s in UPDATE_PHASE_SLOTS) + late = r.get("plLate", 0.0) - r["lateMs"] + if r["saveMs"] > 0: + if late >= update: + late -= r["saveMs"] + else: + update -= r["saveMs"] + parts = collections.OrderedDict([("update", max(0.0, update)), ("late", max(0.0, late)), ("post", r.get("plPost", 0.0)), + ("phases", sum(r.get(p, 0.0) for p in EARLY_PHASES))]) + parts["between"] = max(0.0, r["otherMs"] - sum(parts.values())) + return parts + + +def other_by_phase(rows): + """split_other over summary rows, in ms per frame (each row weighted by its frames).""" + frames = sum(r["frames"] for r in rows) + out = collections.OrderedDict((key, 0.0) for key, _, _ in OTHER_SPLIT) + for r in rows: + for key, value in split_other(r).items(): + out[key] += value * r["frames"] + return collections.OrderedDict((k, v / frames) for k, v in out.items()) if frames else out + + def frame_edges(session): for p in session.pipe("histogram", "frameEdgesMs"): try: @@ -514,13 +559,30 @@ def findings_for(session, args): "That wait is free: the computer had time to spare. Look for slowness in the slow frames and in the simulation instead.")) elif other >= 0.5 and mean >= SLOW_MEAN_MS: evidence = "%.0f%% of an average frame is outside every part this mod times" % (100 * other) - if plpost >= 0.4: - evidence += "; %.0f%% of it is Unity's post-late-update phase (drawing, presenting, the wait for vertical sync)" % (100 * plpost) - if busy is not None: - evidence += "; the game thread was busy for only %.0f%% of the frame" % (100 * busy) - display = session.h("display") - out.append(Finding("high" if plpost >= 0.4 or (busy is not None and busy < 0.7) else "info", "Most of the frame is not the game's or any mod's code", - evidence + ".", "Likely the graphics card or vertical sync (%s). Check draw calls (prDraw, prSetPass), the resolution and quality settings; a mod is unlikely to be the cause." % (display or "display settings not recorded"), key="gpu")) + # Which phase holds it decides where to look: plPost is drawing and waiting, the other two are code that runs every frame. + split = other_by_phase(S) if phases_measured(session, S) else None + biggest = max(("update", "late", "post"), key=lambda k: split[k]) if split else "post" + if biggest != "post": + evidence += ("; per frame, %.1f ms of it is in Unity's Update phase outside the timed parts, %.1f ms in the LateUpdate phase outside lateMs " + "and %.1f ms in plPost (drawing and the wait for vertical sync)" % (split["update"], split["late"], split["post"])) + if biggest == "update": + title = "Most of the frame is other work in Unity's Update phase, outside every part this mod times" + check = ("That is code that runs every frame beside the game's tick loop and singletons: the game's own and other mods' scripts " + "(MonoBehaviour Update, coroutines). The graphics card is not what holds the frame. Compare a recording without a suspected " + "mod, or time a suspect method with a Watch entry.") + else: + title = "Most of the frame is other work in Unity's LateUpdate phase, outside every part this mod times" + check = ("Unity's animation and user interface (UI Toolkit) run in this phase beside scripts' LateUpdate, and grow with what is on screen. " + "Compare a recording with fewer animated characters in view or no panel open, and one without a suspected mod.") + out.append(Finding("high" if split[biggest] / mean >= 0.4 else "info", title, evidence + ".", check, key="other-" + biggest)) + else: + if plpost >= 0.4: + evidence += "; %.0f%% of it is Unity's post-late-update phase (drawing, presenting, the wait for vertical sync)" % (100 * plpost) + if busy is not None: + evidence += "; the game thread was busy for only %.0f%% of the frame" % (100 * busy) + display = session.h("display") + out.append(Finding("high" if plpost >= 0.4 or (busy is not None and busy < 0.7) else "info", "Most of the frame is not the game's or any mod's code", + evidence + ".", "Likely the graphics card or vertical sync (%s). Check draw calls (prDraw, prSetPass), the resolution and quality settings; a mod is unlikely to be the cause." % (display or "display settings not recorded"), key="gpu")) if shares["updMs"] >= 0.15 and mean >= SLOW_MEAN_MS * 0.8: out.append(Finding("high" if shares["updMs"] >= 0.3 else "info", "Per-frame singleton updates take %.0f%% of a frame (%.1f ms)" % (100 * shares["updMs"], wmean(S, "updMs")), "These run every frame whatever the game speed: the user interface, the camera, input and many mods.", @@ -686,6 +748,12 @@ def report(session, args, out): ph = {x: wmean(body, x) for x in PHASES if x in session.columns} if ph and sum(ph.values()) > 0: p(" Unity's phases: " + ", ".join("%s %.2f ms" % (k, v) for k, v in ph.items() if v >= 0.05) + " (the wait for vertical sync is in one of them, usually plPost)") + if phases_measured(session, body): + other = wmean(body, "otherMs") + split = other_by_phase(body) + p(" otherMs by Unity phase (each phase less the timed parts that run in it):") + for key, label, meaning in OTHER_SPLIT: + p(" %-38s %6.2f ms %4s %s" % (label, split[key], pct(split[key], other), meaning)) if wmean(body, "mainCpuMs") > 0: p(" the game thread was busy %.0f%% of the frame (%.1f of %.1f ms); the process used %.1f cores' worth" % ( 100 * wmean(body, "mainCpuMs") / mean, wmean(body, "mainCpuMs"), mean, wmean(body, "procCpuMs") / mean if mean else 0)) @@ -806,6 +874,7 @@ def report_json(session, args): "meanFrameMs": mean, "p50": percentile(session, S, 0.5), "p90": percentile(session, S, 0.9), "p99": percentile(session, S, 0.99), "slowFrames": len(session.slow), "knownIssues": known_issues(session), "slotsMsPerFrame": {s: wmean(S, s) for s in SLOTS + ["otherMs"]}, + "otherMsByPhase": dict(other_by_phase(S)) if phases_measured(session, S) else None, "collections": total(S, "gcDelta"), "findings": [{"severity": f.severity, "title": f.title, "evidence": f.evidence, "check": f.check} for f in findings_for(session, args)], } diff --git a/tools/test_perflog.py b/tools/test_perflog.py index 51a37f9..c260e85 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -390,6 +390,26 @@ def test_change_and_short(self): self.assertEqual("TheClass", perflog.short("Some.Very.Long.Namespace.That.Goes.On.And.On.Forever.And.Ever.TheClass", 40)) self.assertEqual("Short.Name", perflog.short("Short.Name")) + def test_other_ms_is_split_by_unity_phase(self): + # A 20 ms frame: 4 ms of entity ticks and 2 ms of singleton updates inside a 9 ms Update phase, 0.5 ms of late singletons inside a + # 2.5 ms LateUpdate phase, 7.5 ms of plPost, 0.2 ms of plTime and 0.8 ms between the phases. otherMs is the 13.5 ms not timed. + def row(**columns): + r = {"frames": 100.0, "frameMs": 20.0, "tickMs": 0.0, "singMs": 0.0, "entMs": 4.0, "parWaitMs": 0.0, "parStartMs": 0.0, "updMs": 2.0, + "lateMs": 0.5, "saveMs": 0.0, "plTime": 0.2, "plInit": 0.0, "plEarly": 0.0, "plFixed": 0.0, "plPre": 0.0, "plUpdate": 9.0, + "plLate": 2.5, "plPost": 7.5} + r.update(columns) + r["otherMs"] = r["frameMs"] - sum(r[s] for s in perflog.SLOTS) + return r + expect = {"update": 3.0, "late": 2.0, "post": 7.5, "phases": 0.2, "between": 0.8} + for name, r in (("no save", row()), + ("a save deferred to the end of a tick runs in Update", row(frameMs=23.0, saveMs=3.0, plUpdate=12.0)), + ("the game's own save runs in LateUpdate", row(frameMs=23.0, saveMs=3.0, plLate=5.5))): + got = perflog.split_other(r) + for key, value in expect.items(): + self.assertAlmostEqual(value, got[key], places=6, msg="%s: %s" % (name, key)) + both = perflog.other_by_phase([row(), row(frames=300.0, plUpdate=11.0, frameMs=22.0)]) + self.assertAlmostEqual((3.0 * 100 + 5.0 * 300) / 400, both["update"], places=6, msg="weighted by frames") + def test_steady_leaves_out_warm_up_paused_and_background(self): s = Synthetic() try: @@ -422,6 +442,31 @@ def test_graphics_bound_without_vsync(self): self.assertIn("Most of the frame is not the game's or any mod's code", text) self.assertIn("busy for only", text) + def test_the_report_splits_other_ms_by_unity_phase(self): + s = Synthetic() + for _ in range(8): + s.window(frame_ms=20.0, entMs=4.0, updMs=2.0, lateMs=0.5, plTime=0.2, plUpdate=9.0, plLate=2.5, plPost=7.5) + text = self.report(s) + section = text.split("3. WHERE AN AVERAGE FRAME GOES")[1].split("4. WHAT THIS POINTS TO")[0] + self.assertIn("otherMs by Unity phase", section) + + def part(label): + return [l for l in section.splitlines() if l.strip().startswith(label)][0] + self.assertIn("3.00 ms", part("Update phase")) + self.assertIn("2.00 ms", part("LateUpdate phase")) + self.assertIn("other work in Unity's LateUpdate phase", part("LateUpdate phase"), "not blamed on mods") + self.assertIn("7.50 ms", part("plPost")) + self.assertIn("0.80 ms", part("between the phases")) + + def test_other_ms_in_the_update_phase_points_at_scripts_not_the_graphics_card(self): + s = Synthetic() + for _ in range(8): + s.window(frame_ms=40.0, updMs=1.0, entMs=1.0, plUpdate=31.0, plLate=1.0, plPost=4.0, mainCpuMs=38.0, procCpuMs=40.0) + text = self.report(s) + self.assertIn("Most of the frame is other work in Unity's Update phase", text) + self.assertNotIn("Most of the frame is not the game's or any mod's code", text) + self.assertNotIn("Likely the graphics card", text) + def test_vsync_capped_is_healthy(self): s = Synthetic(header={"display": "vSyncCount=1 targetFrameRate=-1 resolution=1920x1080 refreshHz=60.00 fullScreen=Windowed"}) for _ in range(8): From 26682e7ff19c26932a6cdda2b2fdb84f38e706d9 Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 05:04:18 -0700 Subject: [PATCH 3/8] PL6: read the patch header lines in the analyzer Every recording's frames.csv header lists Harmony's patches ('# patch|tag|method|kind|owner|...': every hot method, and every method another mod patches; 501 lines in the real 0.1.3 session), but perflog.py stored them and never read them. The report listed InputService (16 ms/s, 10% of per-frame updates) under mod "game" with no word that MixedStorage and BeaverBuddies patch its UpdateSingleton, and compare did not notice two sessions patching different things. report, section 6: a singleton row now ends "(includes patches by X, Y)" when another mod patches the method that row's kind times (Tick, UpdateSingleton, LateUpdateSingleton or StartParallelTick): the wrapper calls the patched method, so those patches are inside the row's time. Patches on the class's other methods are not listed on it, and this mod's own (kyler.performancelog*) never are. The section ends with the hot methods other mods patch, owner and patch kinds each (methods several mods patch first, --top of them unless --all), and a note when the header was truncated. A session without a profile still gets that list under its own heading. compare, section 1: patches only one session has are listed per session, with a count per owner and a few examples. A patch is (method, kind, owner); the tag is left out because it changes when a second mod starts patching the same method. Older recordings have the same line format (checked on 0.1.0, 0.1.1 and 0.1.3 recordings) and read as before otherwise. Tests (failed before: the InputService row did not mention its patcher, and compare listed no patch difference): test_singletons_other_mods_patch_are_marked_and_hot_patches_listed and test_patches_that_differ_are_listed. Co-Authored-By: Claude Opus 5 --- README.md | 5 ++- docs/TESTING.md | 2 +- tools/perflog.py | 87 ++++++++++++++++++++++++++++++++++++++++++- tools/test_perflog.py | 62 ++++++++++++++++++++++++++++++ 4 files changed, 151 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index 8701ad6..1891281 100644 --- a/README.md +++ b/README.md @@ -41,8 +41,9 @@ python tools/perflog.py list ``` `report` says what stands out, with the evidence and what to check next; `compare` lines up two sessions and says what changed and what else differed -(different mods, game speed, colony size, computer). The tool is also in the release ZIP, in `PerformanceLog\tools`. For a fair comparison, record the -same save at the same game speed for at least three minutes each, with the window in front, and change one thing. +(different mods or Harmony patches, game speed, colony size, computer), and `report` names the other mods whose patches run inside a singleton's time. +The tool is also in the release ZIP, in `PerformanceLog\tools`. For a fair comparison, record the same save at the same game speed for at least three +minutes each, with the window in front, and change one thing. ## What it records diff --git a/docs/TESTING.md b/docs/TESTING.md index b1af224..43779c6 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` (93 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (48 checks). +`dotnet run --project tests -c Release` (93 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (50 checks). | What | How | |---|---| diff --git a/tools/perflog.py b/tools/perflog.py index feb5933..3aed52d 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -398,6 +398,67 @@ def mod_of(session, t): return t.mod or ("(unknown)" if t.kind not in ("entity",) else "") +# ---------------------------------------------------------------- other mods' patches (the '# patch|' header lines) + +# The Harmony id this mod patches under; its own patches are how it measures, not something to point at. +OWN_OWNER = "kyler.performancelog" +# The method a singleton row of each kind times: the wrapper calls it, so another mod's patch on it runs inside that row's time. +SINGLETON_METHOD = {"tick-singleton": "Tick", "update-singleton": "UpdateSingleton", "late-singleton": "LateUpdateSingleton", + "parallel-start": "StartParallelTick"} + + +def patch_map(session): + """The '# patch|tag|method|kind|owner|...' header lines as method -> [(tag, kind, owner)], in the order the header lists them. The header + lists every method another mod patches, and every hot one (one that runs every tick or frame), up to a limit (patches-truncated).""" + out = collections.OrderedDict() + for p in session.pipe("patch"): + if len(p) >= 4 and p[1]: + out.setdefault(p[1], []).append((p[0], p[2], p[3])) + return out + + +def other_patchers(entries): + """The owners of patches that are not this mod's, each with its kinds of patch, in the order listed.""" + owners = collections.OrderedDict() + for _, kind, owner in entries: + if owner and not owner.startswith(OWN_OWNER): + kinds = owners.setdefault(owner, []) + if kind not in kinds: + kinds.append(kind) + return owners + + +def singleton_patchers(patches, t): + """Other mods whose patches run inside a singleton row's time: the ones patching the method that row's kind times.""" + method = SINGLETON_METHOD.get(t.kind) + return other_patchers(patches.get(t.name + "." + method, [])) if method else {} + + +def short_method(name, width=58): + """A method's full name, cut to its class and method when it is long.""" + if len(name) <= width: + return name + tail = ".".join(name.split(".")[-2:]) + return tail if len(tail) <= width else tail[-width:] + + +def hot_patches(p, session, hot, args): + """Prints the hot methods (run every tick or frame) that other mods patch, with who patches them and how.""" + p(" hot methods other mods patch (the patches run inside whatever part of the frame calls the method):") + shown = hot if args.all else hot[:args.top] + for method, owners in shown: + p(" %-58s %s" % (short_method(method), "; ".join("%s (%s)" % (owner, ", ".join(kinds)) for owner, kinds in owners.items()))) + if len(shown) < len(hot): + p(" ... and %d more (--all lists them)" % (len(hot) - len(shown))) + if session.h("patches-truncated"): + p(" (the header lists only part of the patches: %s)" % session.h("patches-truncated")) + + +def patch_set(session): + """Every patch in the header as (method, kind, owner). The tag is left out: it changes when another mod starts patching the same method.""" + return {(method, kind, owner) for method, entries in patch_map(session).items() for _, kind, owner in entries} + + # ---------------------------------------------------------------- findings class Finding: @@ -794,9 +855,14 @@ def report(session, args, out): first = S[0]["tick"] - 1 if S else 0 totals = profile_totals(session, tick_from=first) window_secs = profile_window_seconds(session, body, first) or secs + patches = patch_map(session) + hot = [(method, owners) for method, owners in ((m, other_patchers(e)) for m, e in patches.items() if any(tag == "hot" for tag, _, _ in e)) if owners] + hot.sort(key=lambda h: -len(h[1])) # methods several mods patch first; otherwise in the header's order (by name) if totals and window_secs > 0: p("6. WHERE THE TIME GOES, BY SINGLETON, ENTITY KIND AND METHOD (steady state, %.0f s of profile windows)" % window_secs) p(" ms/s = milliseconds of game-thread time per second of play; 'calls' are exact for singletons and watched methods, estimated for sampled kinds.") + if any(other_patchers(e) for e in patches.values()): + p(" A singleton's time includes other mods' patches on the method it times; its row names them ('includes patches by').") for kind, title in KIND_TITLES.items(): rows = sorted((t for t in totals.values() if t.kind == kind), key=lambda t: -t.ms) if not rows: @@ -804,8 +870,10 @@ 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)) + by = singleton_patchers(patches, t) + 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, + " (includes patches by %s)" % ", ".join(by) if by else "")) mods = collections.defaultdict(lambda: [0.0, 0.0]) for t in totals.values(): if t.kind in ("tick-singleton", "update-singleton", "late-singleton"): @@ -824,6 +892,11 @@ def report(session, args, out): p(" entity component time by mod (sampled; these tick inside entMs, so do not add them to the singletons above):") for mod, (ms, kb) in sorted(comp_mods.items(), key=lambda kv: -kv[1][0])[:args.top]: p(" %-34s %8.2f ms/s %8.1f KB/s" % (mod, ms / window_secs, kb / window_secs)) + hot_patches(p, session, hot, args) + p() + elif hot: + p("6. HOT METHODS OTHER MODS PATCH (this session has no profile)") + hot_patches(p, session, hot, args) p() watched = [t for t in totals.values() if t.kind == "method"] if not watched and session.pipe("watch"): @@ -899,6 +972,16 @@ def env_differences(a, b): ba, bb = {x[0] for x in a.pipe("bootconfig")}, {x[0] for x in b.pipe("bootconfig")} if ba != bb: lines.append("boot.config differs: only in %s: %s; only in %s: %s" % (a.label, sorted(ba - bb), b.label, sorted(bb - ba))) + pa, pb = patch_set(a), patch_set(b) + for session, only in ((a, pa - pb), (b, pb - pa)): + if not only: + continue + owners = collections.Counter(owner for _, _, owner in only) + examples = sorted(only)[:3] + lines.append("only %s has %d patch%s (%s), e.g. %s%s" % ( + session.label, len(only), "" if len(only) == 1 else "es", ", ".join("%s %d" % kv for kv in sorted(owners.items(), key=lambda kv: (-kv[1], kv[0]))[:4]), + "; ".join("%s %s by %s" % (short_method(m), kind, owner) for m, kind, owner in examples), + " (the header of one lists only part of its patches)" if a.h("patches-truncated") or b.h("patches-truncated") else "")) return lines diff --git a/tools/test_perflog.py b/tools/test_perflog.py index c260e85..0c371a3 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -236,6 +236,33 @@ def test_comparing_a_session_with_itself_says_nothing_changed(self): self.assertIn("inside the noise", text) self.assertNotIn("Only A has these", text) + def test_patches_that_differ_are_listed(self): + a, b = Synthetic(), Synthetic() + try: + shared = ["patch", "hot", "Timberborn.TickSystem.TickableEntity.Tick", "prefix", "same.mod", "priority=400", "index=0", "before=", "after=", "Same", "Same.P"] + a.pipes.append(shared) + b.pipes.append(["patch", "shared"] + shared[2:]) # the same patch, listed under another tag, is not a difference + a.pipes.append(["patch", "hot", "Timberborn.InputSystem.InputService.UpdateSingleton", "prefix", "old.mod", "priority=400", "index=0", "before=", "after=", "Old", "Old.P"]) + b.pipes.append(["patch", "other", "Timberborn.Navigation.NavigationSynchronizer.Tick", "postfix", "new.mod", "priority=400", "index=0", "before=", "after=", "New", "New.P"]) + b.pipes.append(["patch", "other", "Timberborn.Navigation.NavigationSynchronizer.LateUpdateSingleton", "postfix", "new.mod", "priority=400", "index=0", "before=", "after=", "New", "New.P"]) + for _ in range(8): + a.window() + b.window() + _, text = run("compare", a.write(), b.write(), "--warmup", "0") + section = text.split("1. ARE THE TWO SESSIONS COMPARABLE?")[1].split("2. FRAME TIME")[0] + only_a = [l for l in section.splitlines() if "only %s has" % os.path.basename(a.dir) in l and "patch" in l] + only_b = [l for l in section.splitlines() if "only %s has" % os.path.basename(b.dir) in l and "patch" in l] + self.assertEqual(1, len(only_a), section) + self.assertIn("1 patch", only_a[0]) + self.assertIn("old.mod", only_a[0]) + self.assertIn("InputService.UpdateSingleton", only_a[0]) + self.assertEqual(1, len(only_b), section) + self.assertIn("2 patches", only_b[0]) + self.assertIn("new.mod 2", only_b[0]) + self.assertNotIn("same.mod", section, "a patch both have is not a difference") + finally: + a.cleanup(); b.cleanup() + def test_cautions_for_different_workloads(self): a, b = Synthetic(), Synthetic() try: @@ -645,6 +672,41 @@ def line(row): self.assertIn("DistrictCitizenAssigner 6 ms", line(mixed), "5 ms or more is named whatever the share") self.assertNotIn("PanelStack", line(mixed)) + def test_singletons_other_mods_patch_are_marked_and_hot_patches_listed(self): + s = Synthetic(mods=[("Harmony", "Harmony", "v"), ("some.mod", "Some Mod", "v1"), ("other.mod", "Other Mod", "v1"), ("third.mod", "Third Mod", "v1")]) + + def patch(tag, method, kind, owner): + s.pipes.append(["patch", tag, method, kind, owner, "priority=400", "index=0", "before=", "after=", owner.split(".")[0], owner + ".Patch." + kind]) + patch("hot", "Timberborn.InputSystem.InputService.UpdateSingleton", "prefix", "some.mod") + patch("hot", "Timberborn.InputSystem.InputService.UpdateSingleton", "finalizer", "some.mod") + patch("shared", "Timberborn.Navigation.NavigationSynchronizer.Tick", "prefix", "other.mod") + patch("shared", "Timberborn.Navigation.NavigationSynchronizer.Tick", "postfix", "kyler.performancelog") + patch("other", "Timberborn.Navigation.NavigationSynchronizer.LateUpdateSingleton", "prefix", "third.mod") # not the Tick row's method + patch("hot", "Timberborn.TickSystem.Ticker.Update", "prefix", "kyler.performancelog") # this mod's own + patch("hot", "Timberborn.TickSystem.TickableEntity.Tick", "prefix", "other.mod") + for w in range(1, 9): + s.window(frame_ms=16.7, updMs=3.0, singMs=1.0) + for i, (kind, name) in enumerate((("update-singleton", "Timberborn.InputSystem.InputService"), ("tick-singleton", "Timberborn.Navigation.NavigationSynchronizer"), + ("update-singleton", "Timberborn.CameraSystem.CameraService"))): + s.profile.append({"kind": kind, "window": w, "tick": s.tick, "id": i, "calls": 600, "sampled": 600, "ms": 300.0 - 50 * i, "allocKB": 1, + "maxMs": 1, "name": name, "assembly": name.rsplit(".", 1)[0], "mod": "game"}) + text = self.report(s) + section = text.split("6. WHERE THE TIME GOES")[1].split("7. GARBAGE COLLECTION")[0] + + def row(name): + return [l for l in section.splitlines() if l.strip().startswith(name)][0] + self.assertIn("some.mod", row("Timberborn.InputSystem.InputService"), "a singleton whose UpdateSingleton another mod patches says so") + self.assertIn("other.mod", row("Timberborn.Navigation.NavigationSynchronizer")) + self.assertNotIn("third.mod", row("Timberborn.Navigation.NavigationSynchronizer"), "a patch on its LateUpdateSingleton is not in its tick time") + self.assertNotIn("kyler.performancelog", row("Timberborn.Navigation.NavigationSynchronizer"), "this mod's own patches are not listed") + self.assertNotIn("patch", row("Timberborn.CameraSystem.CameraService"), "an unpatched singleton says nothing") + hot = section.split("hot methods other mods patch")[1] + self.assertIn("InputService.UpdateSingleton", hot) + self.assertIn("some.mod (prefix, finalizer)", hot) + self.assertIn("TickableEntity.Tick", hot) + self.assertNotIn("Ticker.Update", hot, "a hot method only this mod patches is not listed") + self.assertNotIn("LateUpdateSingleton", hot, "only hot methods are listed") + def test_hitches_on_a_rhythm_are_matched_to_the_autosave(self): s = Synthetic() for i in range(12): From ad7f364fea9f3870381d8d3970d7061f8ba9e77a Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 05:10:16 -0700 Subject: [PATCH 4/8] PL3: mark heap-mode frames with a collection as not measured Every real recording reads allocation from the heap size (GC.GetTotalMemory(false): the game's Mono does not count bytes per thread), and the heap size falls at a garbage collection. A frame with one lost what it allocated: otherKB and the slot KB columns were clamped to 0 (or read low) and nothing told that zero from a measurement. The comment on the otherKB computation claimed the counter "never goes down at a collection", which is only true of the exact per-thread counter. The probe now counts such frames (SessionStats.AllocUnmeasuredFrames and AllocUnmeasuredMs): a frame is not measured when the counter fell inside a timed part or over the frame, or, with the heap size, when a collection ran. No column is added and the fixtures do not change; the session ends with a new line, '# capability-final|allocSource|heap size|allocation not measured in N frames (X s) with a garbage collection: ... the rows with gcDelta above 0 or a negative allocKB' (or '...|measured in every frame'), from Probe.AllocFinalLine. summary.md says so when it happens and leaves those frames' time out of "allocated about X KB per second". perflog.py leaves the slow frames with a collection (heap mode: gcDelta > 0 or a negative allocKB) out of every allocation-per-second figure (section 7, the garbage-collection finding and compare) and says how many frames were not measured: the mod's count when the recording has the new line, else "at least" its slow rows with one, so older recordings are read the same way. The freed bytes are not added back. Alloc.UseTestSource can now stand in for the heap size (asHeapSize), so the heap-mode rule is tested. Tests (the first failed before: "the frame with the collection reads otherKB 0 and nothing says its allocation was not measured"; the Python one read 100 KB/s, not 109): tests/HeapModeTests.cs (3 checks) and test_perflog test_heap_mode_leaves_frames_with_a_collection_out_of_allocation_per_second. Co-Authored-By: Claude Opus 5 --- docs/TESTING.md | 3 +- source/Core/Alloc.cs | 17 +++++-- source/Core/Probe.cs | 35 ++++++++++++- source/Core/Summary.cs | 8 ++- source/Game/Session.cs | 1 + tests/HeapModeTests.cs | 108 +++++++++++++++++++++++++++++++++++++++++ tests/Program.cs | 1 + tools/perflog.py | 68 ++++++++++++++++++++++++-- tools/test_perflog.py | 21 ++++++++ 9 files changed, 251 insertions(+), 11 deletions(-) create mode 100644 tests/HeapModeTests.cs diff --git a/docs/TESTING.md b/docs/TESTING.md index 43779c6..aebd54b 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` (93 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (50 checks). +`dotnet run --project tests -c Release` (96 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (51 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` | +| A frame whose allocation counter falls (the heap size at a collection, the source the game gets) is counted as not measured and left out of the allocation rate, not read as 0 | `HeapModeTests`, `tools/test_perflog.py` | | The profile: exact singleton timing, scaled sampling, random gaps that do not alias with a repeating pattern, budget adaptation, spike attribution, mod resolution | `ProfileTests` | | 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` | diff --git a/source/Core/Alloc.cs b/source/Core/Alloc.cs index 66151ea..5e2690a 100644 --- a/source/Core/Alloc.cs +++ b/source/Core/Alloc.cs @@ -27,6 +27,8 @@ public static class Alloc public static string Describe() => Note.Length == 0 ? ModeName : ModeName + "; " + Note; static Func threadBytes; + // A test's stand-in for the heap size (see UseTestSource); null in a game. + static Func heapBytes; /// True when allocation can be measured at all. public static bool Enabled => Mode != ModeNone; @@ -35,6 +37,7 @@ public static class Alloc public static void Init(bool preferHeap = false) { threadBytes = null; + heapBytes = null; Mode = ModeNone; Note = ""; try @@ -66,12 +69,16 @@ public static void Init(bool preferHeap = false) } } - /// Replaces the counter with one the caller moves by hand. For tests only. Null goes back to . - public static void UseTestSource(Func source) + /// + /// Replaces the counter with one the caller moves by hand. For tests only. Null goes back to . With + /// it stands in for the heap size (), the counter the game gets. + /// + public static void UseTestSource(Func source, bool asHeapSize = false) { if (source == null) { Init(); return; } - threadBytes = source; - Mode = ModeThread; + threadBytes = asHeapSize ? null : source; + heapBytes = asHeapSize ? source : null; + Mode = asHeapSize ? ModeHeap : ModeThread; } /// The counter now, in bytes. Differences between two readings are what matters. @@ -80,7 +87,7 @@ public static long Read() switch (Mode) { case ModeThread: return threadBytes(); - case ModeHeap: return GC.GetTotalMemory(false); + case ModeHeap: return heapBytes != null ? heapBytes() : GC.GetTotalMemory(false); default: return 0; } } diff --git a/source/Core/Probe.cs b/source/Core/Probe.cs index 08c88a7..c5ba4dd 100644 --- a/source/Core/Probe.cs +++ b/source/Core/Probe.cs @@ -55,6 +55,12 @@ public sealed class SessionStats public long SlowRowsSkipped; public double SlowMs; public double FirstFrameMs; + /// + /// Frames whose allocation could not be measured, and their time: the allocation counter fell during them. With the heap size as the + /// counter () that is every frame with a garbage collection, which loses what the frame allocated. + /// + public long AllocUnmeasuredFrames; + public double AllocUnmeasuredMs; /// A copy that another thread can read while the game thread goes on counting. public SessionStats Clone() @@ -150,6 +156,8 @@ public static class Probe static int frameTicks, frameBuckets, frameScopes, bucketsInTick; static double frameParTickMs; + // The allocation counter went down inside a timed scope this frame (a collection, when it is the heap size). + static bool frameAllocFell; const int WorstKept = 10; static readonly List worst = new List(); @@ -325,6 +333,7 @@ static void EndCore(long token) long passUp; if (a0 >= 0) { + if (allocNow < a0) frameAllocFell = true; long elapsedAlloc = Math.Max(0, allocNow - a0); frameAlloc[stackSlot[d]] += Math.Max(0, elapsedAlloc - childAlloc); passUp = elapsedAlloc; @@ -496,8 +505,12 @@ static void Frame(float speed, bool focused) r[Columns.OtherMs] = Math.Max(0, frameMs - accounted); double allocKb = (memory - lastMemory) / 1024.0; - // What was allocated outside every measured section, from the same counter the sections use (which never goes down at a collection). + // What was allocated outside every measured section, from the same counter the sections use. Only the exact per-thread counter never + // goes down; the heap size (Alloc.ModeHeap, what the game's Mono offers) falls at a collection, and a frame with one has lost what it + // allocated, so its KB columns read low (0 when the heap shrank). No column says so: the frame is counted instead (SessionStats. + // AllocUnmeasuredFrames, and the capability-final line from AllocFinalLine), and its row is the one with gcDelta > 0 or a negative allocKB. long allocSource = Alloc.Enabled ? Alloc.Read() : 0; + bool allocUnmeasured = Alloc.Enabled && (frameAllocFell || allocSource < lastAllocSource || (Alloc.Mode == Alloc.ModeHeap && gc != lastGc)); r[Columns.OtherKB] = Math.Max(0, (allocSource - lastAllocSource) / 1024.0 - allocAccounted); lastAllocSource = allocSource; r[Columns.GcDelta] = gc - lastGc; @@ -535,6 +548,7 @@ static void Frame(float speed, bool focused) if (sessionFrames == 0 || heapMb < s.HeapMinMB) s.HeapMinMB = heapMb; if (heapMb > s.HeapMaxMB) s.HeapMaxMB = heapMb; if (sessionFrames == 0) s.FirstFrameMs = frameMs; + if (allocUnmeasured) { s.AllocUnmeasuredFrames++; s.AllocUnmeasuredMs += frameMs; } if (slow) { s.SlowFrames++; s.SlowMs += frameMs; @@ -577,6 +591,7 @@ static void ResetFrame() Array.Clear(framePhase, 0, framePhase.Length); depth = 0; generation++; frameTicks = 0; frameBuckets = 0; frameScopes = 0; frameParTickMs = 0; + frameAllocFell = false; } static void Accumulate(double[] into, double[] r, bool first) @@ -693,6 +708,24 @@ public static double[] SessionRow() /// Counts over the session so far. The object is replaced when a new log starts. public static SessionStats Stats => stats; + /// + /// The # capability-final|allocSource| line: whether allocation was measured in every frame. The frames it was not measured in + /// (see ) are counted here rather than in a column, so the file format stays the same. + /// + public static string AllocFinalLine() + { + const string head = "# capability-final|allocSource|"; + if (!Alloc.Enabled) return head + "none|allocation was not measured"; + bool heap = Alloc.Mode == Alloc.ModeHeap; + long frames = stats.AllocUnmeasuredFrames; + if (frames == 0) return head + (heap ? "heap size" : "exact") + "|measured in every frame"; + string count = "allocation not measured in " + frames + (frames == 1 ? " frame (" : " frames (") + + (stats.AllocUnmeasuredMs / 1000).ToString("F1", System.Globalization.CultureInfo.InvariantCulture) + " s)"; + if (!heap) return head + "exact|" + count + ": the counter fell during them, so their KB columns read low"; + return head + "heap size|" + count + " with a garbage collection: the heap-size counter falls at one, so what they allocated is lost and their KB " + + "columns read low. In frames.csv they are the rows with gcDelta above 0 or a negative allocKB."; + } + static double UnixMs() { Func clock = TestClock; diff --git a/source/Core/Summary.cs b/source/Core/Summary.cs index b987522..e0c11ff 100644 --- a/source/Core/Summary.cs +++ b/source/Core/Summary.cs @@ -262,8 +262,14 @@ static void Memory(StringBuilder t, SummaryInput s, double[] r) double seconds = Math.Max(1, s.Seconds); SessionStats st = s.Stats; t.Append("## Garbage collection and memory\n\n"); + // A frame whose allocation was lost to a collection (heap-size counter) is left out of the rate: its allocation is not in the total. + double measuredSeconds = Math.Max(1, s.Seconds - st.AllocUnmeasuredMs / 1000); t.Append("- ").Append(F(gc, 0)).Append(" garbage collections (").Append(F(gc / (seconds / 60), 1)).Append(" per minute). The game allocated about ") - .Append(F(r[Columns.AllocKB] / seconds, 0)).Append(" KB per second (").Append(F(r[Columns.AllocKB] / Math.Max(1, r[Columns.Ticks]), 0)).Append(" KB per tick).\n"); + .Append(F(r[Columns.AllocKB] / measuredSeconds, 0)).Append(" KB per second (").Append(F(r[Columns.AllocKB] / Math.Max(1, r[Columns.Ticks]), 0)).Append(" KB per tick).\n"); + if (st.AllocUnmeasuredFrames > 0) + t.Append("- Allocation was **not measured in ").Append(st.AllocUnmeasuredFrames).Append(st.AllocUnmeasuredFrames == 1 ? " frame" : " frames") + .Append("** (").Append(F(st.AllocUnmeasuredMs / 1000, 1)).Append(" s): the allocation counter fell during them, as the heap size does at a garbage collection, so what ") + .Append("those frames allocated is lost and their KB columns read low. They are left out of the per-second figure above; in `frames.csv` they are the rows with `gcDelta` above 0 or a negative `allocKB`.\n"); t.Append("- Managed heap ranged ").Append(F(st.HeapMinMB, 0)).Append(" to ").Append(F(st.HeapMaxMB, 0)).Append(" MB; at the last sample Unity's managed heap was ") .Append(F(r[Columns.HeavyBase], 0)).Append(" MB reserved, ").Append(F(r[Columns.HeavyBase + 1], 0)).Append(" MB in use, ").Append(F(r[Columns.HeavyBase + 2], 0)) .Append(" MB in all with native memory, and the process held ").Append(F(r[Columns.HeavyBase + 3], 0)).Append(" MB in RAM.\n"); diff --git a/source/Game/Session.cs b/source/Game/Session.cs index 754db5f..9550ac1 100644 --- a/source/Game/Session.cs +++ b/source/Game/Session.cs @@ -391,6 +391,7 @@ internal static void Stop(string reason, bool quitting = false) // What each source produced has to be read here, on the game thread, before they are shut down. var final = new List(UnityExtras.FinalLines()); final.Add("# capability-final|playerLoop|" + (PlayerLoopTiming.Installed > 0 ? "timed " + PlayerLoopTiming.Installed + " phases" : "not installed")); + final.Add(Probe.AllocFinalLine()); for (int i = 0; i < Instrumentation.HitCount; i++) final.Add("# capability-final|patchCalls|" + Instrumentation.HitName(i) + "|" + (Instrumentation.InstalledHit[i] ? Instrumentation.Hits[i] + (Instrumentation.Hits[i] == 0 ? "|never ran" : "") : "0|patch not installed")); diff --git a/tests/HeapModeTests.cs b/tests/HeapModeTests.cs new file mode 100644 index 0000000..903760f --- /dev/null +++ b/tests/HeapModeTests.cs @@ -0,0 +1,108 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using static PerformanceLog.Tests.Assert; + +namespace PerformanceLog.Tests +{ + /// + /// Allocation read from the size of the managed heap (the only source the game's Mono offers, see the allocSource capability line) falls at + /// a garbage collection, so a frame that has one loses what it allocated. Such a frame must be counted as not measured, not read as having + /// allocated nothing, and without a new column: the count goes into the capability-final line and the summary. + /// + internal static class HeapModeTests + { + public static IEnumerable<(string, Action)> All() + { + yield return ("Heap mode: a frame whose allocation counter falls at a collection is marked as not measured, not read as 0", CounterThatFalls); + yield return ("Heap mode: a frame with a collection is not measured even when the heap still grew; an exact counter is not affected", CollectionWithGrowth); + yield return ("Heap mode: the summary's allocation per second leaves out the frames that were not measured", SummaryRate); + } + + static void CounterThatFalls() + { + var rig = new Rig(); + try + { + rig.Bytes = 500L * 1024 * 1024; + rig.Advance(10); rig.Frame(); + rig.FrameRows(); + rig.Bytes += 300 * 1024; // 300 KB allocated outside every section + rig.Bytes -= 100L * 1024 * 1024; // then a collection frees 100 MB, and a heap-size counter falls + rig.Advance(60); rig.Frame(); // slow, so it gets an F row + double[] f = rig.FrameRows().Single(r => r[Columns.Type] == Columns.FrameRow); + string summary = Summary.Render(new SummaryInput { SessionId = "gc", Row = Probe.SessionRow(), Stats = Probe.Stats, Seconds = 1 }); + Check(f[Columns.OtherKB] > 0 || summary.Contains("not measured in 1 frame"), + "the frame with the collection reads otherKB " + f[Columns.OtherKB] + " and nothing says its allocation was not measured"); + Equal(1L, Probe.Stats.AllocUnmeasuredFrames, "frames counted as not measured"); + Near(60, Probe.Stats.AllocUnmeasuredMs, .001, "and their time"); + Check(Probe.AllocFinalLine().StartsWith("# capability-final|allocSource|") && Probe.AllocFinalLine().Contains("not measured in 1 frame (0.1 s)"), Probe.AllocFinalLine()); + + // A counter that also falls inside a timed part, with the frame as a whole still growing, is caught there. + long scope = Probe.Begin(Slot.Update); + rig.Bytes -= 1024 * 1024; + Probe.End(scope); + rig.Bytes += 4 * 1024 * 1024; + rig.Advance(16); rig.Frame(); + Equal(2L, Probe.Stats.AllocUnmeasuredFrames, "a fall inside a timed part"); + + // Ordinary frames are measured, and not counted. + for (int i = 0; i < 5; i++) { rig.Bytes += 64 * 1024; rig.Advance(16); rig.Frame(); } + Equal(2L, Probe.Stats.AllocUnmeasuredFrames, "frames whose counter only grew"); + } + finally { rig.Dispose(); } + + rig = new Rig(); + try + { + for (int i = 0; i < 5; i++) { rig.Bytes += 64 * 1024; rig.Advance(16); rig.Frame(); } + Equal("# capability-final|allocSource|exact|measured in every frame", Probe.AllocFinalLine()); + } + finally { rig.Dispose(); } + } + + static void CollectionWithGrowth() + { + var rig = new Rig(); + try + { + // The exact counter does not lose anything at a collection, so a collection alone is not a reason to doubt it. + rig.Bytes += 64 * 1024; rig.Advance(16); rig.Frame(); + GC.Collect(0); + rig.Bytes += 64 * 1024; rig.Advance(16); rig.Frame(); + Equal(0L, Probe.Stats.AllocUnmeasuredFrames, "a collection under the exact counter"); + + // The heap size: a collection that freed less than the frame allocated still took some of it away. + Alloc.UseTestSource(() => rig.Bytes, asHeapSize: true); + Equal(Alloc.ModeHeap, Alloc.Mode); + rig.Bytes += 64 * 1024; rig.Advance(16); rig.Frame(); + long before = Probe.Stats.AllocUnmeasuredFrames; + GC.Collect(0); + rig.Bytes += 64 * 1024; rig.Advance(16); rig.Frame(); + Check(Probe.Stats.AllocUnmeasuredFrames == before + 1, "a frame with a collection is not measured when the counter is the heap size"); + Check(Probe.AllocFinalLine().Contains("|heap size|allocation not measured in") && Probe.AllocFinalLine().Contains("with a garbage collection"), Probe.AllocFinalLine()); + } + finally { rig.Dispose(); } + } + + static void SummaryRate() + { + var rig = new Rig(thresholdMs: 1000); + try + { + for (int i = 0; i < 5; i++) { rig.Advance(16); rig.Frame(); } + double[] row = Probe.SessionRow(); + row[Columns.AllocKB] = 6000; // 6000 KB over 60 s + SessionStats stats = Probe.Stats.Clone(); + string text = Summary.Render(new SummaryInput { SessionId = "rate", Row = row, Stats = stats, Seconds = 60 }); + Check(text.Contains("allocated about 100 KB per second"), "every frame measured: 6000 KB in 60 s"); + Check(!text.Contains("not measured in"), "and nothing said about unmeasured frames"); + stats.AllocUnmeasuredFrames = 2; stats.AllocUnmeasuredMs = 5000; + text = Summary.Render(new SummaryInput { SessionId = "rate", Row = row, Stats = stats, Seconds = 60 }); + Check(text.Contains("allocated about 109 KB per second"), "6000 KB over the 55 s whose allocation was measured"); + Check(text.Contains("not measured in 2 frames"), "and the summary says why"); + } + finally { rig.Dispose(); } + } + } +} diff --git a/tests/Program.cs b/tests/Program.cs index 19aae02..a05265d 100644 --- a/tests/Program.cs +++ b/tests/Program.cs @@ -62,6 +62,7 @@ static int Run(string[] args) tests.AddRange(ProfileTests.All()); tests.AddRange(WriterTests.All()); tests.AddRange(SummaryTests.All()); + tests.AddRange(HeapModeTests.All()); tests.AddRange(GameBindingTests.All(managed)); int failures = 0; diff --git a/tools/perflog.py b/tools/perflog.py index 3aed52d..fde0c48 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -12,6 +12,7 @@ evidence it rests on and what to check next, and the tool never claims more than the data supports. """ import argparse +import bisect import collections import csv import json @@ -267,6 +268,64 @@ def seconds_of(rows): return sum(r["frameMs"] * r["frames"] for r in rows) / 1000.0 +def heap_alloc(session): + """True when allocation was read from the size of the managed heap (the allocSource capability), which falls at a garbage collection.""" + return any(len(p) >= 2 and p[1].startswith("GC.GetTotalMemory") for p in session.pipe("capability", "allocSource")) + + +def alloc_unmeasured(session, rows): + """The slow frames inside the summary rows `rows` whose allocation was not measured, and their milliseconds. With the heap size as the + counter a frame with a collection loses what it allocated; its row has gcDelta > 0 or (the heap shrank) a negative allocKB. That holds for + recordings of every version. Frames too short to have a row of their own are not known here; they are short.""" + if not heap_alloc(session) or not rows: + return 0, 0.0 + ordered = sorted(rows, key=lambda r: r["frame"]) + ends = [r["frame"] for r in ordered] + count, ms = 0, 0.0 + for f in session.slow: + if f["gcDelta"] <= 0 and f["allocKB"] >= 0: + continue + i = bisect.bisect_left(ends, f["frame"]) # the first window that ends at or after the frame; a window covers (frame - frames, frame] + if i < len(ends) and ordered[i]["frame"] - ordered[i]["frames"] < f["frame"]: + count += 1 + ms += f["frameMs"] + return count, ms + + +def alloc_seconds(session, rows): + """Seconds of the rows whose allocation was measured: a rate of allocation divides by these, since the lost frames add nothing to it.""" + return max(0.0, seconds_of(rows) - alloc_unmeasured(session, rows)[1] / 1000.0) + + +def alloc_rate(session, rows): + """KB allocated per second over the rows (allocKB, the heap growth), leaving out the frames whose allocation was not measured.""" + secs = alloc_seconds(session, rows) + return total(rows, "allocKB") / secs if secs > 0 else 0.0 + + +def alloc_unmeasured_note(session, rows): + """What the report says about frames whose allocation was not measured (heap-size counter), or None. The mod counts them in its + '# capability-final|allocSource|' line; a recording made before it did has only its slow rows to go on.""" + if not heap_alloc(session): + return None + counted = None + for p in session.pipe("capability-final", "allocSource"): + found = re.search(r"not measured in (\d+) frame", "|".join(p)) + if found: + counted = int(found.group(1)) + source = "" + if counted is None: + counted = sum(1 for f in session.slow if f["gcDelta"] > 0 or f["allocKB"] < 0) + if not counted: + return None + source = " (this recording does not count them, so this is its slow rows with a collection)" + frames = "at least %d frame%s" % (counted, "" if counted == 1 else "s") + else: + frames = "%d frame%s" % (counted, "" if counted == 1 else "s") + return ("allocation not measured in %s with a collection%s: the heap-size counter falls at one, so what was allocated in them is lost. " + "The per-second figure leaves out the %.1f s of those that have a row in these windows." % (frames, source, alloc_unmeasured(session, rows)[1] / 1000.0)) + + def phases_measured(session, rows): """True when the recording timed Unity's phases (the playerLoop capability), so otherMs can be split by them.""" return all(p in session.columns for p in PHASES) and sum(wmean(rows, p) for p in PHASES) > 0 @@ -569,7 +628,7 @@ def findings_for(session, args): out.append(Finding("high", "Garbage collection causes most of the hitches", "%d of %d slow frames contain a collection (median %.0f ms, worst %.0f ms); the game collects %.1f times a minute and allocates about %.0f KB per second." % (len(gc_rows), len(slow), gm, max(r["frameMs"] for r in gc_rows), total(S, "gcDelta") / (secs / 60) if secs else 0, - total(S, "allocKB") / secs if secs else 0), + alloc_rate(session, S)), gc_advice(session, inc) + "Find what allocates most: the allocation table in the report and allocKB in profile.csv.", key="gc")) if save_rows: ev = [e for e in session.events if e["kind"] == "save"] @@ -906,9 +965,12 @@ def report(session, args, out): p("7. GARBAGE COLLECTION AND MEMORY") gc = total(body, "gcDelta") p(" %d collections (%.1f per minute); the game allocated about %.0f KB per second (%.0f KB per tick); managed heap %.0f-%.0f MB" % ( - gc, gc / (seconds_of(body) / 60) if seconds_of(body) else 0, total(body, "allocKB") / seconds_of(body) if seconds_of(body) else 0, + gc, gc / (seconds_of(body) / 60) if seconds_of(body) else 0, alloc_rate(session, body), total(body, "allocKB") / max(1, sum(r["ticks"] for r in body)), min(r["heapMB"] for r in body if r["heapMB"] > 0) if any(r["heapMB"] > 0 for r in body) else 0, max(r["heapMB"] for r in body))) + note = alloc_unmeasured_note(session, body) + if note: + p(" " + note) ticks = max(1, sum(r["ticks"] for r in body)) alloc = {} for s in SLOTS: @@ -1045,7 +1107,7 @@ def compare(a, b, args, out): if ta and tb: rows.append(("ms per tick (game thread)", sum(wsum(Sa, s) for s in TICK_SLOTS) / ta, sum(wsum(Sb, s) for s in TICK_SLOTS) / tb)) rows.append(("collections per minute", total(Sa, "gcDelta") / (seconds_of(Sa) / 60) if seconds_of(Sa) else 0, total(Sb, "gcDelta") / (seconds_of(Sb) / 60) if seconds_of(Sb) else 0)) - rows.append(("allocation KB per second", total(Sa, "allocKB") / seconds_of(Sa) if seconds_of(Sa) else 0, total(Sb, "allocKB") / seconds_of(Sb) if seconds_of(Sb) else 0)) + rows.append(("allocation KB per second", alloc_rate(a, Sa), alloc_rate(b, Sb))) for label, va, vb in rows: p(" %-26s %10.2f %10.2f %10s" % (label, va, vb, change(va, vb))) speeds_a = collections.defaultdict(list) diff --git a/tools/test_perflog.py b/tools/test_perflog.py index 0c371a3..1c90a3b 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -707,6 +707,27 @@ def row(name): self.assertNotIn("Ticker.Update", hot, "a hot method only this mod patches is not listed") self.assertNotIn("LateUpdateSingleton", hot, "only hot methods are listed") + def test_heap_mode_leaves_frames_with_a_collection_out_of_allocation_per_second(self): + def session(source, final=None): + s = Synthetic() + s.pipes.append(["capability", "allocSource", source]) + if final: + s.pipes.append(["capability-final", "allocSource", "heap size", final]) + for i in range(6): + if i == 3: + s.slow_frame(5000.0, gcDelta=1.0, allocKB=-100000.0) # a 5 s frame with a collection: the heap shrank, what it allocated is lost + s.window(allocKB=1000.0) + return s + heap = "GC.GetTotalMemory(false) (coarse: moves only when the heap grows)" + text = self.report(session(heap)) + self.assertIn("allocated about 109 KB per second", text, "6000 KB over the 55 s whose allocation was measured") + self.assertIn("not measured in at least 1 frame", text, "an older recording does not count them, so the slow rows are the evidence") + text = self.report(session(heap, "allocation not measured in 2 frames (5.0 s)")) + self.assertIn("not measured in 2 frames", text, "the mod's own count is used when the recording has it") + text = self.report(session("GC.GetAllocatedBytesForCurrentThread (exact)")) + self.assertIn("allocated about 100 KB per second", text, "an exact counter does not fall at a collection") + self.assertNotIn("not measured in", text) + def test_hitches_on_a_rhythm_are_matched_to_the_autosave(self): s = Synthetic() for i in range(12): From cc384d0d36088d1677c9e2f270f5255886370c3e Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 05:27:31 -0700 Subject: [PATCH 5/8] PL5: keep the graphics-card finding when the wait is outside Update The PL5 finding picked the biggest of only the Update remainder, the LateUpdate remainder and plPost. Unity can wait for the last frame to be presented in its first phase (plTime, TimeUpdate), so in a GPU-bound session whose wait lands there, a small Update remainder that still beat plPost turned the high-severity "not the game's or any mod's code, likely the graphics card" finding into an info finding that said "the graphics card is not what holds the frame". The choice now also weighs the phases before Update and the time between phases, and those keep the graphics-card finding (its evidence says how much is in the phases before Update). When the Update or LateUpdate remainder is biggest but the game thread is busy for less than 70% of the frame, the finding says a script there is waiting, not that the graphics card is ruled out. The split_other docstring and Summary.OtherByPhase comment said a save taken out of the wrong phase makes an error "less than the save"; it is up to the save, and the two splits (session mean in C#, per window in Python) can differ in a session with both kinds of save. Found by the adversarial review of this branch. Co-Authored-By: Claude Opus 5 --- docs/TESTING.md | 2 +- source/Core/Summary.cs | 5 +++-- tools/perflog.py | 25 +++++++++++++++++++------ tools/test_perflog.py | 23 +++++++++++++++++++++++ 4 files changed, 46 insertions(+), 9 deletions(-) diff --git a/docs/TESTING.md b/docs/TESTING.md index aebd54b..d7e30d9 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"` (51 checks). +`dotnet run --project tests -c Release` (96 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (53 checks). | What | How | |---|---| diff --git a/source/Core/Summary.cs b/source/Core/Summary.cs index e0c11ff..42e3c12 100644 --- a/source/Core/Summary.cs +++ b/source/Core/Summary.cs @@ -181,8 +181,9 @@ static void WhereFramesGo(StringBuilder t, SummaryInput s, double[] r) /// in it (the tick loop with its parts, and the singleton updates), the LateUpdate phase less lateMs, plPost, the phases before /// Update, and what falls between the phases. The game saves in its LateUpdate and a mod that defers the save to the end of a tick /// (BeaverBuddies) in Update; the row does not say which, so saveMs is taken out of the phase with more room left. That is the phase it - /// ran in, except for a save shorter than the gap between the two phases' own remainders, and then the error is less than the save. - /// tools/perflog.py (split_other) splits the same way. + /// ran in, except for a save shorter than the gap between the two phases' own remainders: then one phase reads high and the other low by up + /// to the save. A row that holds both kinds of save is split approximately. tools/perflog.py (split_other) splits the same way, but per + /// summary window, where this splits the session's mean row, so the two can differ in a session that has both kinds. /// static double[] OtherByPhase(double[] r) { diff --git a/tools/perflog.py b/tools/perflog.py index fde0c48..2ce7df6 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -335,7 +335,9 @@ def split_other(r): """otherMs of one row (times per frame) by Unity phase: each phase less the timed parts that run in it, plPost, the phases before Update, and what falls between the phases. The game saves in its LateUpdate and a mod that defers the save to the end of a tick (BeaverBuddies) in Update; the row does not say which, so saveMs is taken out of the phase with more room left. That is the phase it ran in, except for a - save shorter than the gap between the two phases' own remainders, and then the error is less than the save.""" + save shorter than the gap between the two phases' own remainders: then one phase reads high and the other low by up to the save. A summary + row that holds both kinds of save is split approximately, and the mod's summary.md (Summary.OtherByPhase) splits the session's mean row, + this report each window, so the two can differ by as much in a session that has both.""" update = r.get("plUpdate", 0.0) - sum(r[s] for s in UPDATE_PHASE_SLOTS) late = r.get("plLate", 0.0) - r["lateMs"] if r["saveMs"] > 0: @@ -679,23 +681,34 @@ def findings_for(session, args): "That wait is free: the computer had time to spare. Look for slowness in the slow frames and in the simulation instead.")) elif other >= 0.5 and mean >= SLOW_MEAN_MS: evidence = "%.0f%% of an average frame is outside every part this mod times" % (100 * other) - # Which phase holds it decides where to look: plPost is drawing and waiting, the other two are code that runs every frame. + # Which part holds it decides where to look. The Update and LateUpdate remainders are code that runs every frame; plPost is drawing and + # waiting, and Unity can also wait for the last frame to be presented in its first phase (plTime), so the phases before Update and + # what falls between phases point at the graphics card or vertical sync as plPost does. split = other_by_phase(S) if phases_measured(session, S) else None - biggest = max(("update", "late", "post"), key=lambda k: split[k]) if split else "post" - if biggest != "post": + biggest = max(("update", "late", "post", "phases", "between"), key=lambda k: split[k]) if split else "post" + if biggest in ("update", "late"): evidence += ("; per frame, %.1f ms of it is in Unity's Update phase outside the timed parts, %.1f ms in the LateUpdate phase outside lateMs " "and %.1f ms in plPost (drawing and the wait for vertical sync)" % (split["update"], split["late"], split["post"])) + # A game thread that is mostly idle is waiting inside that phase (on another thread, the disk or the graphics card), not working. + idle = busy is not None and busy < 0.7 + if idle: + evidence += "; the game thread was busy for only %.0f%% of the frame" % (100 * busy) if biggest == "update": title = "Most of the frame is other work in Unity's Update phase, outside every part this mod times" check = ("That is code that runs every frame beside the game's tick loop and singletons: the game's own and other mods' scripts " - "(MonoBehaviour Update, coroutines). The graphics card is not what holds the frame. Compare a recording without a suspected " - "mod, or time a suspect method with a Watch entry.") + "(MonoBehaviour Update, coroutines). " + + ("The game thread is idle for much of it, so a script there is waiting: on another thread, the disk or the graphics card. " if idle + else "The graphics card is not what holds the frame. ") + + "Compare a recording without a suspected mod, or time a suspect method with a Watch entry.") else: title = "Most of the frame is other work in Unity's LateUpdate phase, outside every part this mod times" check = ("Unity's animation and user interface (UI Toolkit) run in this phase beside scripts' LateUpdate, and grow with what is on screen. " "Compare a recording with fewer animated characters in view or no panel open, and one without a suspected mod.") out.append(Finding("high" if split[biggest] / mean >= 0.4 else "info", title, evidence + ".", check, key="other-" + biggest)) else: + if split and biggest == "phases": + evidence += ("; %.0f%% of it is in Unity's phases before Update (plTime to plPre), where Unity also waits for the last frame to be presented" + % (100 * split["phases"] / mean)) if plpost >= 0.4: evidence += "; %.0f%% of it is Unity's post-late-update phase (drawing, presenting, the wait for vertical sync)" % (100 * plpost) if busy is not None: diff --git a/tools/test_perflog.py b/tools/test_perflog.py index 1c90a3b..500532e 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -494,6 +494,29 @@ def test_other_ms_in_the_update_phase_points_at_scripts_not_the_graphics_card(se self.assertNotIn("Most of the frame is not the game's or any mod's code", text) self.assertNotIn("Likely the graphics card", text) + def test_a_wait_before_the_update_phase_still_points_at_the_graphics_card(self): + # Unity can wait for the last frame to be presented in its first phase (plTime), not plPost. Here that wait holds 14 of 25 ms and the + # game thread is busy for 40% of the frame, while the Update phase's untimed 2 ms is still more than plPost's 1 ms. + s = Synthetic() + for _ in range(8): + s.window(frame_ms=25.0, updMs=3.0, entMs=3.0, plTime=14.0, plUpdate=8.0, plLate=1.5, plPost=1.0, mainCpuMs=10.0, procCpuMs=12.0) + text = self.report(s) + self.assertIn("[!] Most of the frame is not the game's or any mod's code", text, "the high-severity graphics card finding stays") + self.assertIn("before Update", text, "the evidence says where the time is") + self.assertNotIn("other work in Unity's Update phase, outside", text) + self.assertNotIn("The graphics card is not what holds the frame", text) + + def test_update_phase_time_with_an_idle_game_thread_is_not_called_work(self): + # Most of the frame is in the Update phase, outside the timed parts, but the game thread is busy for only 30% of it: something there + # waits. The finding still points at the Update phase, and does not rule the graphics card out. + s = Synthetic() + for _ in range(8): + s.window(frame_ms=40.0, updMs=1.0, entMs=1.0, plUpdate=31.0, plLate=1.0, plPost=4.0, mainCpuMs=12.0, procCpuMs=14.0) + text = self.report(s) + self.assertIn("Most of the frame is other work in Unity's Update phase", text) + self.assertNotIn("The graphics card is not what holds the frame", text) + self.assertIn("busy for only 30%", text) + def test_vsync_capped_is_healthy(self): s = Synthetic(header={"display": "vSyncCount=1 targetFrameRate=-1 resolution=1920x1080 refreshHz=60.00 fullScreen=Windowed"}) for _ in range(8): From cc6743af70aa5e26ba13b5f46aa25edf2dcdde46 Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 05:28:37 -0700 Subject: [PATCH 6/8] PL6: leave this mod's patches out of compare, skip an empty hot list compare's patch diff counted Performance Log's own measuring patches (kyler.performancelog*), which report section 6 already leaves out. Two recordings that differ only in this mod's Profile setting or version listed those patches as a difference and they inflated the per-owner count; the Profile difference is already reported as a header key. patch_set now drops them, by the same rule as other_patchers. Report section 6 printed the "hot methods other mods patch" heading over an empty list, which reads as "nothing hot is patched" even when the recording could not list the patches. The heading now appears only over a list, and a recording with '# patches-unavailable' says the patches were not recorded, in the report and in compare (which no longer lists every patch of the other session as missing). Found by the adversarial review of this branch. Co-Authored-By: Claude Opus 5 --- docs/TESTING.md | 2 +- tools/perflog.py | 18 ++++++++++++++---- tools/test_perflog.py | 36 ++++++++++++++++++++++++++++++++++++ 3 files changed, 51 insertions(+), 5 deletions(-) diff --git a/docs/TESTING.md b/docs/TESTING.md index d7e30d9..07bc07d 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"` (53 checks). +`dotnet run --project tests -c Release` (96 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (55 checks). | What | How | |---|---| diff --git a/tools/perflog.py b/tools/perflog.py index 2ce7df6..eb10154 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -504,7 +504,12 @@ def short_method(name, width=58): def hot_patches(p, session, hot, args): - """Prints the hot methods (run every tick or frame) that other mods patch, with who patches them and how.""" + """Prints the hot methods (run every tick or frame) that other mods patch, with who patches them and how. Nothing when there are none, and + a note instead when the recording could not list the patches (patches-unavailable), so an empty list is not read as 'nothing is patched'.""" + if session.h("patches-unavailable"): + p(" (the patches were not recorded, so this report cannot say which other mods patch what: %s)" % session.h("patches-unavailable")) + if not hot: + return p(" hot methods other mods patch (the patches run inside whatever part of the frame calls the method):") shown = hot if args.all else hot[:args.top] for method, owners in shown: @@ -516,8 +521,10 @@ def hot_patches(p, session, hot, args): def patch_set(session): - """Every patch in the header as (method, kind, owner). The tag is left out: it changes when another mod starts patching the same method.""" - return {(method, kind, owner) for method, entries in patch_map(session).items() for _, kind, owner in entries} + """Every other mod's patch in the header as (method, kind, owner). The tag is left out: it changes when another mod starts patching the same + method. This mod's own patches are left out as in other_patchers: they follow its Profile setting and version, which compare lists apart.""" + return {(method, kind, owner) for method, entries in patch_map(session).items() for _, kind, owner in entries + if owner and not owner.startswith(OWN_OWNER)} # ---------------------------------------------------------------- findings @@ -1047,7 +1054,10 @@ def env_differences(a, b): ba, bb = {x[0] for x in a.pipe("bootconfig")}, {x[0] for x in b.pipe("bootconfig")} if ba != bb: lines.append("boot.config differs: only in %s: %s; only in %s: %s" % (a.label, sorted(ba - bb), b.label, sorted(bb - ba))) - pa, pb = patch_set(a), patch_set(b) + unrecorded = [s.label for s in (a, b) if s.h("patches-unavailable")] + if unrecorded: + lines.append("the patches by other mods were not recorded in %s, so they cannot be compared" % " or ".join(unrecorded)) + pa, pb = (patch_set(a), patch_set(b)) if not unrecorded else (set(), set()) for session, only in ((a, pa - pb), (b, pb - pa)): if not only: continue diff --git a/tools/test_perflog.py b/tools/test_perflog.py index 500532e..98c59d0 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -245,6 +245,10 @@ def test_patches_that_differ_are_listed(self): a.pipes.append(["patch", "hot", "Timberborn.InputSystem.InputService.UpdateSingleton", "prefix", "old.mod", "priority=400", "index=0", "before=", "after=", "Old", "Old.P"]) b.pipes.append(["patch", "other", "Timberborn.Navigation.NavigationSynchronizer.Tick", "postfix", "new.mod", "priority=400", "index=0", "before=", "after=", "New", "New.P"]) b.pipes.append(["patch", "other", "Timberborn.Navigation.NavigationSynchronizer.LateUpdateSingleton", "postfix", "new.mod", "priority=400", "index=0", "before=", "after=", "New", "New.P"]) + # This mod's own measuring patches (Profile = deep in B only) are how it measures, not a difference between the games. + for kind in ("prefix", "postfix"): + b.pipes.append(["patch", "hot", "Timberborn.TickSystem.MeteredTickableComponent.Tick", kind, "kyler.performancelog", "priority=800", "index=0", "before=", "after=", + "PerformanceLog", "PerformanceLog.P"]) for _ in range(8): a.window() b.window() @@ -260,6 +264,21 @@ def test_patches_that_differ_are_listed(self): self.assertIn("2 patches", only_b[0]) self.assertIn("new.mod 2", only_b[0]) self.assertNotIn("same.mod", section, "a patch both have is not a difference") + self.assertNotIn("kyler.performancelog", section, "this mod's own patches are not a difference") + finally: + a.cleanup(); b.cleanup() + + def test_patches_are_not_compared_when_one_session_did_not_record_them(self): + a, b = Synthetic(), Synthetic(header={"patches-unavailable": "InvalidOperationException no"}) + try: + a.pipes.append(["patch", "hot", "Timberborn.TickSystem.TickableEntity.Tick", "prefix", "some.mod", "priority=400", "index=0", "before=", "after=", "Some", "Some.P"]) + for _ in range(8): + a.window() + b.window() + _, text = run("compare", a.write(), b.write(), "--warmup", "0") + section = text.split("1. ARE THE TWO SESSIONS COMPARABLE?")[1].split("2. FRAME TIME")[0] + self.assertIn("not recorded in %s" % os.path.basename(b.dir), section) + self.assertNotIn("some.mod", section, "a missing list is not a list of missing patches") finally: a.cleanup(); b.cleanup() @@ -730,6 +749,23 @@ def row(name): self.assertNotIn("Ticker.Update", hot, "a hot method only this mod patches is not listed") self.assertNotIn("LateUpdateSingleton", hot, "only hot methods are listed") + def test_no_hot_patch_list_without_hot_patches_by_other_mods(self): + def session(header=None): + s = Synthetic(header=header) + s.pipes.append(["patch", "hot", "Timberborn.TickSystem.Ticker.Update", "prefix", "kyler.performancelog", "priority=400", "index=0", "before=", "after=", + "PerformanceLog", "PerformanceLog.P"]) # only this mod's own + for w in range(1, 9): + s.window(frame_ms=16.7, updMs=3.0) + s.profile.append({"kind": "update-singleton", "window": w, "tick": s.tick, "id": 0, "calls": 600, "sampled": 600, "ms": 300.0, "allocKB": 1, + "maxMs": 1, "name": "Timberborn.InputSystem.InputService", "assembly": "Timberborn.InputSystem", "mod": "game"}) + return s + section = self.report(session()).split("6. WHERE THE TIME GOES")[1].split("7. GARBAGE COLLECTION")[0] + self.assertNotIn("hot methods other mods patch", section, "no heading over an empty list") + self.assertNotIn("not recorded", section) + section = self.report(session({"patches-unavailable": "InvalidOperationException no"})).split("6. WHERE THE TIME GOES")[1].split("7. GARBAGE COLLECTION")[0] + self.assertNotIn("hot methods other mods patch (", section) + self.assertIn("patches were not recorded", section, "a recording without the patch list says so, not that nothing is patched") + def test_heap_mode_leaves_frames_with_a_collection_out_of_allocation_per_second(self): def session(source, final=None): s = Synthetic() From 1d1affba23c7545b84abcb8588cb6e21a2b507bd Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 05:32:27 -0700 Subject: [PATCH 7/8] PL3: scope the unmeasured-frame note, drop lost frames' growth from rates Follow-ups from the adversarial review of this branch: - Report section 7 put the unmeasured-frame count (the mod's whole-session count, or for an older recording every slow row with a collection, paused and background ones included) right after the steady-state collection count, so the two could not be reconciled. The note now says the count is the whole session's and how many of those slow frames fall in the windows the figures cover. - The allocation rate left an unmeasured frame's time out but kept whatever positive heap growth it still showed, since allocKB sums its positive part. Probe now also counts that growth (SessionStats.AllocUnmeasuredKB), summary.md subtracts it, and perflog.py subtracts it for the slow rows it knows. - The capability-final line and summary.md said the unmeasured frames "are the rows with gcDelta above 0 or a negative allocKB"; only slow frames have rows, so they now say the slow ones are those F rows. - HeapModeTests' first check ran under the exact test counter although its name says heap mode. It now uses the heap-size stand-in inside a no-GC region (so the test process's own collections do not count), and asserts the '|heap size|' final line and the heap-mode "measured in every frame" line. - Alloc.ModeName wrote "(coarse: moves only when the heap grows)" into every heap-mode recording's allocSource line; the heap size also falls at a collection, which is this item's bug. The text now says so. The analyzers match only the "GC.GetTotalMemory" prefix, and no fixture holds this text. - docs/TESTING.md: the five-minute check gains a step for the new capability-final line and the otherMs split, which no game has shown yet. No column or fixture change. Co-Authored-By: Claude Opus 5 --- docs/TESTING.md | 6 +++- source/Core/Alloc.cs | 6 ++-- source/Core/Probe.cs | 12 ++++++-- source/Core/Summary.cs | 8 +++-- tests/HeapModeTests.cs | 66 +++++++++++++++++++++++++++++++++++++----- tools/perflog.py | 33 ++++++++++++--------- tools/test_perflog.py | 16 ++++++++++ 7 files changed, 116 insertions(+), 31 deletions(-) diff --git a/docs/TESTING.md b/docs/TESTING.md index 07bc07d..f128b59 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"` (55 checks). +`dotnet run --project tests -c Release` (96 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (56 checks). | What | How | |---|---| @@ -107,5 +107,9 @@ heap and is coarse**. The per-singleton `KB/s` figures are therefore only good i or the game's own FPS counter). At the new, deeper defaults the mod costs more than the 0.3-0.8% of a frame the first recording measured at the old ones; the report still warns if `overheadUs` + `probeUs` are more than 2% of a frame, and `OverheadBudgetPercent` is the setting to lower if it runs that high. (With `Enabled = false` the mod writes no session at all, so there is nothing to `compare`.) +11. Not yet seen in a game, only in the automated checks with a stand-in counter: the last lines of `frames.csv` should include + `# capability-final|allocSource|heap size|...`, saying either `measured in every frame` or `allocation not measured in N frames (X s) with a garbage + collection`, where N is at least the number of `F` rows with `gcDelta` above 0 (a save usually brings a collection). `summary.md`'s garbage-collection + section should give the same N. In `summary.md`, the parts of **How `otherMs` splits by Unity phase** should add up to `otherMs` within about 0.1 ms. If something is wrong, send Claude the session folder and the `[PerformanceLog]` lines from `Player.log`. diff --git a/source/Core/Alloc.cs b/source/Core/Alloc.cs index 5e2690a..e3bf90d 100644 --- a/source/Core/Alloc.cs +++ b/source/Core/Alloc.cs @@ -7,8 +7,8 @@ namespace PerformanceLog /// /// How many bytes this program has allocated, as cheaply as the runtime allows. Differences of it say which sections allocate. /// Unity's Mono may or may not have a per-thread counter, so it is tried, checked against a known allocation, and otherwise the - /// size of the managed heap is used (which only moves when the heap takes new blocks, so individual readings are coarse and only - /// sums over many readings mean anything). + /// size of the managed heap is used (which grows only when the heap takes new blocks and falls at a garbage collection, so individual + /// readings are coarse, a frame with a collection loses what it allocated, and only sums over many readings mean anything). /// public static class Alloc { @@ -18,7 +18,7 @@ public static class Alloc public static int Mode { get; private set; } public static string ModeName => Mode == ModeThread ? "GC.GetAllocatedBytesForCurrentThread (exact)" : - Mode == ModeHeap ? "GC.GetTotalMemory(false) (coarse: moves only when the heap grows)" : "none"; + Mode == ModeHeap ? "GC.GetTotalMemory(false) (coarse: grows with allocation, falls at a garbage collection)" : "none"; /// Why the exact counter was not used, when it was tried and rejected. Empty otherwise. For the header. public static string Note { get; private set; } = ""; diff --git a/source/Core/Probe.cs b/source/Core/Probe.cs index c5ba4dd..06e4d96 100644 --- a/source/Core/Probe.cs +++ b/source/Core/Probe.cs @@ -61,6 +61,11 @@ public sealed class SessionStats /// public long AllocUnmeasuredFrames; public double AllocUnmeasuredMs; + /// + /// The heap growth those frames still showed (their positive allocKB, which the session's allocKB total holds). A collection + /// took an unknown part of what they allocated, so an allocation rate leaves this out along with their time. + /// + public double AllocUnmeasuredKB; /// A copy that another thread can read while the game thread goes on counting. public SessionStats Clone() @@ -508,7 +513,8 @@ static void Frame(float speed, bool focused) // What was allocated outside every measured section, from the same counter the sections use. Only the exact per-thread counter never // goes down; the heap size (Alloc.ModeHeap, what the game's Mono offers) falls at a collection, and a frame with one has lost what it // allocated, so its KB columns read low (0 when the heap shrank). No column says so: the frame is counted instead (SessionStats. - // AllocUnmeasuredFrames, and the capability-final line from AllocFinalLine), and its row is the one with gcDelta > 0 or a negative allocKB. + // AllocUnmeasuredFrames, and the capability-final line from AllocFinalLine), and if it is slow its F row is one with gcDelta > 0 or a + // negative allocKB. long allocSource = Alloc.Enabled ? Alloc.Read() : 0; bool allocUnmeasured = Alloc.Enabled && (frameAllocFell || allocSource < lastAllocSource || (Alloc.Mode == Alloc.ModeHeap && gc != lastGc)); r[Columns.OtherKB] = Math.Max(0, (allocSource - lastAllocSource) / 1024.0 - allocAccounted); @@ -548,7 +554,7 @@ static void Frame(float speed, bool focused) if (sessionFrames == 0 || heapMb < s.HeapMinMB) s.HeapMinMB = heapMb; if (heapMb > s.HeapMaxMB) s.HeapMaxMB = heapMb; if (sessionFrames == 0) s.FirstFrameMs = frameMs; - if (allocUnmeasured) { s.AllocUnmeasuredFrames++; s.AllocUnmeasuredMs += frameMs; } + if (allocUnmeasured) { s.AllocUnmeasuredFrames++; s.AllocUnmeasuredMs += frameMs; s.AllocUnmeasuredKB += Math.Max(0, allocKb); } if (slow) { s.SlowFrames++; s.SlowMs += frameMs; @@ -723,7 +729,7 @@ public static string AllocFinalLine() (stats.AllocUnmeasuredMs / 1000).ToString("F1", System.Globalization.CultureInfo.InvariantCulture) + " s)"; if (!heap) return head + "exact|" + count + ": the counter fell during them, so their KB columns read low"; return head + "heap size|" + count + " with a garbage collection: the heap-size counter falls at one, so what they allocated is lost and their KB " + - "columns read low. In frames.csv they are the rows with gcDelta above 0 or a negative allocKB."; + "columns read low. In frames.csv the slow ones are the F rows with gcDelta above 0 or a negative allocKB."; } static double UnixMs() diff --git a/source/Core/Summary.cs b/source/Core/Summary.cs index 42e3c12..a61620b 100644 --- a/source/Core/Summary.cs +++ b/source/Core/Summary.cs @@ -263,14 +263,16 @@ static void Memory(StringBuilder t, SummaryInput s, double[] r) double seconds = Math.Max(1, s.Seconds); SessionStats st = s.Stats; t.Append("## Garbage collection and memory\n\n"); - // A frame whose allocation was lost to a collection (heap-size counter) is left out of the rate: its allocation is not in the total. + // A frame whose allocation was lost to a collection (heap-size counter) is left out of the rate: its time, and whatever growth the heap + // still showed in it, which the allocKB total holds but is not what the frame allocated. double measuredSeconds = Math.Max(1, s.Seconds - st.AllocUnmeasuredMs / 1000); + double measuredKb = Math.Max(0, r[Columns.AllocKB] - st.AllocUnmeasuredKB); t.Append("- ").Append(F(gc, 0)).Append(" garbage collections (").Append(F(gc / (seconds / 60), 1)).Append(" per minute). The game allocated about ") - .Append(F(r[Columns.AllocKB] / measuredSeconds, 0)).Append(" KB per second (").Append(F(r[Columns.AllocKB] / Math.Max(1, r[Columns.Ticks]), 0)).Append(" KB per tick).\n"); + .Append(F(measuredKb / measuredSeconds, 0)).Append(" KB per second (").Append(F(r[Columns.AllocKB] / Math.Max(1, r[Columns.Ticks]), 0)).Append(" KB per tick).\n"); if (st.AllocUnmeasuredFrames > 0) t.Append("- Allocation was **not measured in ").Append(st.AllocUnmeasuredFrames).Append(st.AllocUnmeasuredFrames == 1 ? " frame" : " frames") .Append("** (").Append(F(st.AllocUnmeasuredMs / 1000, 1)).Append(" s): the allocation counter fell during them, as the heap size does at a garbage collection, so what ") - .Append("those frames allocated is lost and their KB columns read low. They are left out of the per-second figure above; in `frames.csv` they are the rows with `gcDelta` above 0 or a negative `allocKB`.\n"); + .Append("those frames allocated is lost and their KB columns read low. They are left out of the per-second figure above; in `frames.csv` the slow ones are the `F` rows with `gcDelta` above 0 or a negative `allocKB`.\n"); t.Append("- Managed heap ranged ").Append(F(st.HeapMinMB, 0)).Append(" to ").Append(F(st.HeapMaxMB, 0)).Append(" MB; at the last sample Unity's managed heap was ") .Append(F(r[Columns.HeavyBase], 0)).Append(" MB reserved, ").Append(F(r[Columns.HeavyBase + 1], 0)).Append(" MB in use, ").Append(F(r[Columns.HeavyBase + 2], 0)) .Append(" MB in all with native memory, and the process held ").Append(F(r[Columns.HeavyBase + 3], 0)).Append(" MB in RAM.\n"); diff --git a/tests/HeapModeTests.cs b/tests/HeapModeTests.cs index 903760f..0e95321 100644 --- a/tests/HeapModeTests.cs +++ b/tests/HeapModeTests.cs @@ -21,22 +21,32 @@ internal static class HeapModeTests static void CounterThatFalls() { + // The heap size is the counter the game gets. No collection may run while it is read here, or the test process's own collections + // would count as well: the region is opened before the rig, so a collection it needs first happens before the probe's first reading. + bool noGc = StartNoGc(); var rig = new Rig(); try { + Alloc.UseTestSource(() => rig.Bytes, asHeapSize: true); + Equal(Alloc.ModeHeap, Alloc.Mode); rig.Bytes = 500L * 1024 * 1024; rig.Advance(10); rig.Frame(); rig.FrameRows(); rig.Bytes += 300 * 1024; // 300 KB allocated outside every section - rig.Bytes -= 100L * 1024 * 1024; // then a collection frees 100 MB, and a heap-size counter falls + rig.Bytes -= 100L * 1024 * 1024; // then a collection frees 100 MB, and the heap-size counter falls rig.Advance(60); rig.Frame(); // slow, so it gets an F row double[] f = rig.FrameRows().Single(r => r[Columns.Type] == Columns.FrameRow); string summary = Summary.Render(new SummaryInput { SessionId = "gc", Row = Probe.SessionRow(), Stats = Probe.Stats, Seconds = 1 }); Check(f[Columns.OtherKB] > 0 || summary.Contains("not measured in 1 frame"), "the frame with the collection reads otherKB " + f[Columns.OtherKB] + " and nothing says its allocation was not measured"); - Equal(1L, Probe.Stats.AllocUnmeasuredFrames, "frames counted as not measured"); - Near(60, Probe.Stats.AllocUnmeasuredMs, .001, "and their time"); - Check(Probe.AllocFinalLine().StartsWith("# capability-final|allocSource|") && Probe.AllocFinalLine().Contains("not measured in 1 frame (0.1 s)"), Probe.AllocFinalLine()); + if (noGc) + { + Equal(1L, Probe.Stats.AllocUnmeasuredFrames, "frames counted as not measured"); + Near(60, Probe.Stats.AllocUnmeasuredMs, .001, "and their time"); + Check(Probe.AllocFinalLine().StartsWith("# capability-final|allocSource|heap size|allocation not measured in 1 frame (0.1 s) with a garbage collection"), + Probe.AllocFinalLine()); + } + long before = Probe.Stats.AllocUnmeasuredFrames; // A counter that also falls inside a timed part, with the frame as a whole still growing, is caught there. long scope = Probe.Begin(Slot.Update); @@ -44,13 +54,26 @@ static void CounterThatFalls() Probe.End(scope); rig.Bytes += 4 * 1024 * 1024; rig.Advance(16); rig.Frame(); - Equal(2L, Probe.Stats.AllocUnmeasuredFrames, "a fall inside a timed part"); + Equal(before + 1, Probe.Stats.AllocUnmeasuredFrames, "a fall inside a timed part"); // Ordinary frames are measured, and not counted. + if (noGc) + { + for (int i = 0; i < 5; i++) { rig.Bytes += 64 * 1024; rig.Advance(16); rig.Frame(); } + Equal(before + 1, Probe.Stats.AllocUnmeasuredFrames, "frames whose counter only grew"); + } + } + finally { rig.Dispose(); EndNoGc(noGc); } + + noGc = StartNoGc(); + rig = new Rig(); + try + { + Alloc.UseTestSource(() => rig.Bytes, asHeapSize: true); for (int i = 0; i < 5; i++) { rig.Bytes += 64 * 1024; rig.Advance(16); rig.Frame(); } - Equal(2L, Probe.Stats.AllocUnmeasuredFrames, "frames whose counter only grew"); + if (noGc) Equal("# capability-final|allocSource|heap size|measured in every frame", Probe.AllocFinalLine()); } - finally { rig.Dispose(); } + finally { rig.Dispose(); EndNoGc(noGc); } rig = new Rig(); try @@ -61,6 +84,23 @@ static void CounterThatFalls() finally { rig.Dispose(); } } + // A region in which the runtime runs no collection, as long as less than this much is allocated in it. False when it could not start one; + // the checks that need it are then skipped rather than made to fail by a collection of the test process. + static bool StartNoGc() + { + bool started; + try { started = GC.TryStartNoGCRegion(64L * 1024 * 1024); } + catch (InvalidOperationException) { started = false; } + if (!started) Console.WriteLine(" info: the runtime would not hold off collections here, so the heap-mode counts are not checked"); + return started; + } + + static void EndNoGc(bool started) + { + if (started && System.Runtime.GCSettings.LatencyMode == System.Runtime.GCLatencyMode.NoGCRegion) + try { GC.EndNoGCRegion(); } catch (InvalidOperationException) { } + } + static void CollectionWithGrowth() { var rig = new Rig(); @@ -76,10 +116,15 @@ static void CollectionWithGrowth() Alloc.UseTestSource(() => rig.Bytes, asHeapSize: true); Equal(Alloc.ModeHeap, Alloc.Mode); rig.Bytes += 64 * 1024; rig.Advance(16); rig.Frame(); + rig.FrameRows(); long before = Probe.Stats.AllocUnmeasuredFrames; + double kbBefore = Probe.Stats.AllocUnmeasuredKB; GC.Collect(0); - rig.Bytes += 64 * 1024; rig.Advance(16); rig.Frame(); + rig.Bytes += 64 * 1024; rig.Advance(60); rig.Frame(); // slow, so its F row shows the allocKB the frame was charged Check(Probe.Stats.AllocUnmeasuredFrames == before + 1, "a frame with a collection is not measured when the counter is the heap size"); + // Whatever growth the heap still showed in it is in the session's allocKB total, and counted here so the rate can take it out again. + double[] f = rig.FrameRows().Single(r => r[Columns.Type] == Columns.FrameRow); + Near(Math.Max(0, f[Columns.AllocKB]), Probe.Stats.AllocUnmeasuredKB - kbBefore, .001, "the lost frame's heap growth"); Check(Probe.AllocFinalLine().Contains("|heap size|allocation not measured in") && Probe.AllocFinalLine().Contains("with a garbage collection"), Probe.AllocFinalLine()); } finally { rig.Dispose(); } @@ -101,6 +146,11 @@ static void SummaryRate() text = Summary.Render(new SummaryInput { SessionId = "rate", Row = row, Stats = stats, Seconds = 60 }); Check(text.Contains("allocated about 109 KB per second"), "6000 KB over the 55 s whose allocation was measured"); Check(text.Contains("not measured in 2 frames"), "and the summary says why"); + Check(text.Contains("the slow ones are the `F` rows"), "and that only the slow ones have rows"); + // A frame whose collection freed less than it allocated still grew the heap; that growth is in the total but is not its allocation. + stats.AllocUnmeasuredKB = 500; + text = Summary.Render(new SummaryInput { SessionId = "rate", Row = row, Stats = stats, Seconds = 60 }); + Check(text.Contains("allocated about 100 KB per second"), "(6000 - 500) KB over the 55 s whose allocation was measured"); } finally { rig.Dispose(); } } diff --git a/tools/perflog.py b/tools/perflog.py index eb10154..39f6c52 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -274,14 +274,15 @@ def heap_alloc(session): def alloc_unmeasured(session, rows): - """The slow frames inside the summary rows `rows` whose allocation was not measured, and their milliseconds. With the heap size as the - counter a frame with a collection loses what it allocated; its row has gcDelta > 0 or (the heap shrank) a negative allocKB. That holds for - recordings of every version. Frames too short to have a row of their own are not known here; they are short.""" + """The slow frames inside the summary rows `rows` whose allocation was not measured: how many, their milliseconds, and the heap growth + they still showed (their positive allocKB, which the rows' allocKB totals hold). With the heap size as the counter a frame with a + collection loses what it allocated; its row has gcDelta > 0 or (the heap shrank) a negative allocKB. That holds for recordings of every + version. Frames too short to have a row of their own are not known here; they are short.""" if not heap_alloc(session) or not rows: - return 0, 0.0 + return 0, 0.0, 0.0 ordered = sorted(rows, key=lambda r: r["frame"]) ends = [r["frame"] for r in ordered] - count, ms = 0, 0.0 + count, ms, kb = 0, 0.0, 0.0 for f in session.slow: if f["gcDelta"] <= 0 and f["allocKB"] >= 0: continue @@ -289,7 +290,8 @@ def alloc_unmeasured(session, rows): if i < len(ends) and ordered[i]["frame"] - ordered[i]["frames"] < f["frame"]: count += 1 ms += f["frameMs"] - return count, ms + kb += max(0.0, f["allocKB"]) + return count, ms, kb def alloc_seconds(session, rows): @@ -298,14 +300,16 @@ def alloc_seconds(session, rows): def alloc_rate(session, rows): - """KB allocated per second over the rows (allocKB, the heap growth), leaving out the frames whose allocation was not measured.""" + """KB allocated per second over the rows (allocKB, the heap growth), leaving out the frames whose allocation was not measured: both their + time and what growth they still showed, since a collection took away an unknown part of what they allocated.""" secs = alloc_seconds(session, rows) - return total(rows, "allocKB") / secs if secs > 0 else 0.0 + return max(0.0, total(rows, "allocKB") - alloc_unmeasured(session, rows)[2]) / secs if secs > 0 else 0.0 def alloc_unmeasured_note(session, rows): - """What the report says about frames whose allocation was not measured (heap-size counter), or None. The mod counts them in its - '# capability-final|allocSource|' line; a recording made before it did has only its slow rows to go on.""" + """What the report says about frames whose allocation was not measured (heap-size counter), or None. The mod counts them over the whole + session in its '# capability-final|allocSource|' line; a recording made before it did has only its slow rows to go on. Either way the + figures above cover only the rows `rows`, so the note also says how many of the frames are in them.""" if not heap_alloc(session): return None counted = None @@ -318,12 +322,15 @@ def alloc_unmeasured_note(session, rows): counted = sum(1 for f in session.slow if f["gcDelta"] > 0 or f["allocKB"] < 0) if not counted: return None - source = " (this recording does not count them, so this is its slow rows with a collection)" + source = " (this recording does not count them, so these are its slow rows with a collection)" frames = "at least %d frame%s" % (counted, "" if counted == 1 else "s") else: frames = "%d frame%s" % (counted, "" if counted == 1 else "s") - return ("allocation not measured in %s with a collection%s: the heap-size counter falls at one, so what was allocated in them is lost. " - "The per-second figure leaves out the %.1f s of those that have a row in these windows." % (frames, source, alloc_unmeasured(session, rows)[1] / 1000.0)) + inside, inside_ms, _ = alloc_unmeasured(session, rows) + scope = ("The per-second figure leaves out the %d slow frame%s (%.1f s) of them in these windows." % (inside, "" if inside == 1 else "s", inside_ms / 1000.0) + if inside else "None of the slow ones is in these windows.") + return ("allocation not measured in %s in the whole session, each with a collection%s: the heap-size counter falls at one, so what was " + "allocated in them is lost. %s" % (frames, source, scope)) def phases_measured(session, rows): diff --git a/tools/test_perflog.py b/tools/test_perflog.py index 98c59d0..de2a789 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -787,6 +787,22 @@ def session(source, final=None): self.assertIn("allocated about 100 KB per second", text, "an exact counter does not fall at a collection") self.assertNotIn("not measured in", text) + def test_heap_mode_counts_are_scoped_and_a_lost_frames_growth_is_left_out(self): + heap = "GC.GetTotalMemory(false) (coarse: grows with allocation, falls at a garbage collection)" + s = Synthetic() + s.pipes.append(["capability", "allocSource", heap]) + for i in range(7): + if i == 1: + s.slow_frame(3000.0, gcDelta=1.0, allocKB=-50000.0, paused=1.0) # in a paused window, which the steady state leaves out + if i == 4: + s.slow_frame(5000.0, gcDelta=1.0, allocKB=500.0) # a collection that freed less than the frame allocated + s.window(allocKB=1000.0, paused=10 * 1000.0 / 16.7 if i == 1 else 0.0) + text = self.report(s) + section = text.split("7. GARBAGE COLLECTION")[1].split("8. WHAT EACH SOURCE")[0] + self.assertIn("allocated about 100 KB per second", section, "(6000 - 500) KB over the 55 s whose allocation was measured") + self.assertIn("at least 2 frames in the whole session", section, "the count says it is the whole session's") + self.assertIn("leaves out the 1 slow frame (5.0 s) of them in these windows", section, "and how many of them are in the windows the figures cover") + def test_hitches_on_a_rhythm_are_matched_to_the_autosave(self): s = Synthetic() for i in range(12): From 26747ecda734b289ab62962f3aed51a08128508e Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 12:44:15 -0700 Subject: [PATCH 8/8] PL4/PL6: say nothing for a frame no singleton was timed in; note unrecorded patches without a profile Summary.Blame wrote 'no singleton stood out' for a slow frame with no timed singleton, reading nothing as a measurement; it now leaves the cell empty, as perflog.py's blame_text does. The report's 'patches were not recorded' note was only printed inside section 6's profile branch; a recording with no profile now gets it too. Co-Authored-By: Claude Opus 5.5 --- source/Core/Summary.cs | 5 +++-- tests/SummaryTests.cs | 4 ++++ tools/perflog.py | 2 +- tools/test_perflog.py | 4 ++++ 4 files changed, 12 insertions(+), 3 deletions(-) diff --git a/source/Core/Summary.cs b/source/Core/Summary.cs index a61620b..c2d741b 100644 --- a/source/Core/Summary.cs +++ b/source/Core/Summary.cs @@ -423,8 +423,9 @@ static string Blame(WorstFrame w) named.Add(Short(Profile.NameOf(w.TopIds[i])) + " " + F(w.TopMs[i], 0)); } if (named.Count > 0) return string.Join(", ", named); - string text = "no singleton stood out"; - if (w.TopIds.Length > 0) text += " (largest " + F(w.TopMs[0]) + " ms, " + Pct(w.TopMs[0], frameMs) + " of the frame)"; + // No singleton was timed in the frame: nothing to say, as perflog.py's blame_text (a zero is not a measurement). + if (w.TopIds.Length == 0) return ""; + string text = "no singleton stood out (largest " + F(w.TopMs[0]) + " ms, " + Pct(w.TopMs[0], frameMs) + " of the frame)"; var had = new List(); if (r[Columns.Saving] > 0) had.Add("a save"); if (r[Columns.GcDelta] > 0) had.Add("a garbage collection"); diff --git a/tests/SummaryTests.cs b/tests/SummaryTests.cs index c489e3a..7e17f7e 100644 --- a/tests/SummaryTests.cs +++ b/tests/SummaryTests.cs @@ -149,6 +149,8 @@ WorstFrame Slow(int frame, double frameMs, double gcDelta, double saveMs, int[] input.Worst.Add(Slow(103, 99, 0, 0, new[] { routes, panels }, new[] { 95.0, 1.0 })); // 6 ms of a 215 ms frame is under 10% but over 5 ms: a singleton that long is worth naming in any frame. input.Worst.Add(Slow(104, 215, 1, 0, new[] { districts, panels }, new[] { 6.0, 1.0 })); + // A save frame in which no singleton was timed at all: nothing was measured, so nothing is said (as perflog.py's blame_text). + input.Worst.Add(Slow(105, 800, 1, 790, new int[0], new double[0])); string text = Summary.Render(input); string Row(int frame) => text.Split('\n').Single(l => l.StartsWith("| " + frame + " | ")); @@ -160,6 +162,8 @@ WorstFrame Slow(int frame, double frameMs, double gcDelta, double saveMs, int[] Check(hitch.Contains("RouteMapsBackground 95"), "the singleton that took the frame is named: " + hitch); Check(!hitch.Contains("PanelStack") && !hitch.Contains("stood out"), "and only it: " + hitch); Check(mixed.Contains("DistrictCitizenAssigner 6") && !mixed.Contains("PanelStack"), "5 ms or more is named whatever the share: " + mixed); + string untimed = Row(105); + Check(!untimed.Contains("stood out"), "a frame with no singleton timed does not say none stood out: " + untimed); } finally { rig.Dispose(); } } diff --git a/tools/perflog.py b/tools/perflog.py index 2f2b99b..94d37c4 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -1073,7 +1073,7 @@ def report(session, args, out): p(" %-34s %8.2f ms/s %8.1f KB/s" % (mod, ms / window_secs, kb / window_secs)) hot_patches(p, session, hot, args) p() - elif hot: + elif hot or session.h("patches-unavailable"): p("6. HOT METHODS OTHER MODS PATCH (this session has no profile)") hot_patches(p, session, hot, args) p() diff --git a/tools/test_perflog.py b/tools/test_perflog.py index 96149e1..df6cdc4 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -888,6 +888,10 @@ def session(header=None): section = self.report(session({"patches-unavailable": "InvalidOperationException no"})).split("6. WHERE THE TIME GOES")[1].split("7. GARBAGE COLLECTION")[0] self.assertNotIn("hot methods other mods patch (", section) self.assertIn("patches were not recorded", section, "a recording without the patch list says so, not that nothing is patched") + bare = Synthetic(header={"patches-unavailable": "InvalidOperationException no"}) # no profile at all + for _ in range(8): + bare.window(frame_ms=16.7) + self.assertIn("patches were not recorded", self.report(bare), "and so does one without a profile") def test_heap_mode_leaves_frames_with_a_collection_out_of_allocation_per_second(self): def session(source, final=None):