diff --git a/README.md b/README.md index 47ef4e1..0063fde 100644 --- a/README.md +++ b/README.md @@ -46,10 +46,11 @@ python tools/perflog.py compare 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). `list` shows every session in `Documents\Timberborn\PerformanceLog`, or in a folder you name. -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. +`report` says what stands out, with the evidence and what to check next, and names the other mods whose patches run inside a singleton's time. +`compare` lines up two sessions and says what changed and what else differed (different mods or Harmony patches, game speed, colony size, computer). +`list` shows every session in `Documents\Timberborn\PerformanceLog`, or in a folder you name. 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/SESSION-README.md b/docs/SESSION-README.md index 4570cb5..e023397 100644 --- a/docs/SESSION-README.md +++ b/docs/SESSION-README.md @@ -62,6 +62,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 7c57096..203f7e5 100644 --- a/docs/TESTING.md +++ b/docs/TESTING.md @@ -6,13 +6,14 @@ since. A 0.1.3 recording (below) shows the `deep` default working, and every 0.1 ## Verified by the automated checks -`dotnet run --project tests -c Release` (101 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (50 checks). +`dotnet run --project tests -c Release` (106 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (62 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 cost charged for each patch call (`patchCallNs`) is at least what the entity patch's own bodies take on a call that is not sampled, timed with the log on and sampling held off (the part Harmony adds needs the game); the `# calibration|` line names both, or says `unmeasured` | `CoreTests.UnsampledBodyTiming`, `CoreTests.CalibrationLine`, `GameBindingTests.PatchCostCoversTheBodies` | | The profile: exact singleton timing, scaled sampling, random gaps that do not alias with a repeating pattern, budget adaptation, spike attribution, mod resolution, entities keyed by kind and not by a beaver's own name (`perflog.py` adds up older recordings' rows the same way) | `ProfileTests`, `test_perflog.EntityRollupTests` | | Watched methods: each is sampled at its own rate, widening with its own load inside the budget, kept through windows it is not called in (so bursts stay inside it too) and coming back down when it runs less, with a row (and at least one timing) for every window it ran in; calls nobody timed get a `sampled` 0 row and stay out of the totals | `WatchSamplingTests`, `test_perflog` | @@ -139,5 +140,9 @@ What it shows, and the line that shows it: 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 66151ea..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; } = ""; @@ -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 ddfca17..bcb9b7e 100644 --- a/source/Core/Probe.cs +++ b/source/Core/Probe.cs @@ -55,6 +55,17 @@ 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; + /// + /// 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() @@ -168,6 +179,8 @@ public static string[] CalibrationParts() => new[] 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(); @@ -382,6 +395,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; @@ -553,8 +567,13 @@ 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 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); lastAllocSource = allocSource; r[Columns.GcDelta] = gc - lastGc; @@ -592,6 +611,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; s.AllocUnmeasuredKB += Math.Max(0, allocKb); } if (slow) { s.SlowFrames++; s.SlowMs += frameMs; @@ -634,6 +654,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) @@ -750,6 +771,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 the slow ones are the F 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 7cac956..c2d741b 100644 --- a/source/Core/Summary.cs +++ b/source/Core/Summary.cs @@ -155,10 +155,55 @@ 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: 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) + { + 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]; @@ -218,8 +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 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] / 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(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` 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"); @@ -331,7 +384,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 +394,45 @@ 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); + // 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"); + 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/source/Game/Session.cs b/source/Game/Session.cs index 759a556..3b5a04b 100644 --- a/source/Game/Session.cs +++ b/source/Game/Session.cs @@ -388,6 +388,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..0e95321 --- /dev/null +++ b/tests/HeapModeTests.cs @@ -0,0 +1,158 @@ +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() + { + // 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 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"); + 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); + rig.Bytes -= 1024 * 1024; + Probe.End(scope); + rig.Bytes += 4 * 1024 * 1024; + rig.Advance(16); rig.Frame(); + 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(); } + if (noGc) Equal("# capability-final|allocSource|heap size|measured in every frame", Probe.AllocFinalLine()); + } + finally { rig.Dispose(); EndNoGc(noGc); } + + 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(); } + } + + // 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(); + 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(); + rig.FrameRows(); + long before = Probe.Stats.AllocUnmeasuredFrames; + double kbBefore = Probe.Stats.AllocUnmeasuredKB; + GC.Collect(0); + 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(); } + } + + 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"); + 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/tests/Program.cs b/tests/Program.cs index cfb9f8a..792ff55 100644 --- a/tests/Program.cs +++ b/tests/Program.cs @@ -63,6 +63,7 @@ static int Run(string[] args) tests.AddRange(WatchSamplingTests.All()); tests.AddRange(WriterTests.All()); tests.AddRange(SummaryTests.All()); + tests.AddRange(HeapModeTests.All()); tests.AddRange(GameBindingTests.All(managed)); int failures = 0; diff --git a/tests/SummaryTests.cs b/tests/SummaryTests.cs index e35ea3c..7e17f7e 100644 --- a/tests/SummaryTests.cs +++ b/tests/SummaryTests.cs @@ -15,6 +15,8 @@ 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: 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); } @@ -120,6 +122,100 @@ 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 })); + // 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 + " | ")); + + 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); + 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(); } + } + + 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 5e8fadc..4de174d 100644 --- a/tests/fixtures/sample-with-mod/README.md +++ b/tests/fixtures/sample-with-mod/README.md @@ -62,6 +62,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 a035517..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. @@ -139,19 +149,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/README.md b/tests/fixtures/sample-without-mod/README.md index 5e8fadc..4de174d 100644 --- a/tests/fixtures/sample-without-mod/README.md +++ b/tests/fixtures/sample-without-mod/README.md @@ -62,6 +62,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 06755c7..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. @@ -136,17 +146,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 821ac4a..94d37c4 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 @@ -31,6 +32,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"] @@ -45,6 +58,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") # Up to 0.1.3 the `# calibration|` line's patchCallNs timed an empty patch instead of the patch bodies, and every recording shows 0 there. What @@ -325,6 +342,106 @@ 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: 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, 0.0 + ordered = sorted(rows, key=lambda r: r["frame"]) + ends = [r["frame"] for r in ordered] + count, ms, kb = 0, 0.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"] + kb += max(0.0, f["allocKB"]) + return count, ms, kb + + +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: 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 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 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 + 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 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") + 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): + """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: 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: + 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: @@ -441,6 +558,74 @@ 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. 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: + 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 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 class Finding: @@ -551,7 +736,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"] @@ -602,13 +787,41 @@ 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 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", "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 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: + 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.", @@ -697,6 +910,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) @@ -752,6 +987,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)) @@ -784,18 +1025,22 @@ 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 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: @@ -803,9 +1048,11 @@ 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%s" % ( + 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%s" % ( short(t.name, 58), (mod_of(session, t) or "")[:26], t.ms / window_secs, pct(t.ms, all_ms), t.ms * 1000 / t.calls if t.calls else 0, t.kb / window_secs, t.max_ms, - " (+%d calls never timed)" % t.untimed if t.untimed else "")) + " (+%d calls never timed)" % t.untimed if t.untimed else "", + " (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 +1071,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 or session.h("patches-unavailable"): + 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"): @@ -833,9 +1085,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: @@ -874,6 +1129,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)], } @@ -898,6 +1154,19 @@ 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))) + 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 + 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 @@ -961,7 +1230,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 f2dcd55..df6cdc4 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -236,6 +236,52 @@ 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"]) + # 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() + _, 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") + 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() + def test_cautions_for_different_workloads(self): a, b = Synthetic(), Synthetic() try: @@ -390,6 +436,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: @@ -497,6 +563,54 @@ 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_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): @@ -693,6 +807,129 @@ 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_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_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") + 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): + 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_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):