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

README.md

@@ -46,10 +46,11 @@ python tools/perflog.py compare <folder A> <folder B>
 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
 

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.

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`.

source/Core/Alloc.cs

@@ -7,8 +7,8 @@ namespace PerformanceLog
     /// <summary>
     /// 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).
     /// </summary>
     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";
 
         /// <summary>Why the exact counter was not used, when it was tried and rejected. Empty otherwise. For the header.</summary>
         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<long> threadBytes;
+        // A test's stand-in for the heap size (see UseTestSource); null in a game.
+        static Func<long> heapBytes;
 
         /// <summary>True when allocation can be measured at all.</summary>
         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)
             }
         }
 
-        /// <summary>Replaces the counter with one the caller moves by hand. For tests only. Null goes back to <see cref="Init"/>.</summary>
-        public static void UseTestSource(Func<long> source)
+        /// <summary>
+        /// Replaces the counter with one the caller moves by hand. For tests only. Null goes back to <see cref="Init"/>. With
+        /// <paramref name="asHeapSize"/> it stands in for the heap size (<see cref="ModeHeap"/>), the counter the game gets.
+        /// </summary>
+        public static void UseTestSource(Func<long> 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;
         }
 
         /// <summary>The counter now, in bytes. Differences between two readings are what matters.</summary>
@@ -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;
             }
         }

source/Core/Probe.cs

@@ -55,6 +55,17 @@ public sealed class SessionStats
         public long SlowRowsSkipped;
         public double SlowMs;
         public double FirstFrameMs;
+        /// <summary>
+        /// Frames whose allocation could not be measured, and their time: the allocation counter fell during them. With the heap size as the
+        /// counter (<see cref="Alloc.ModeHeap"/>) that is every frame with a garbage collection, which loses what the frame allocated.
+        /// </summary>
+        public long AllocUnmeasuredFrames;
+        public double AllocUnmeasuredMs;
+        /// <summary>
+        /// The heap growth those frames still showed (their positive <c>allocKB</c>, which the session's <c>allocKB</c> total holds). A collection
+        /// took an unknown part of what they allocated, so an allocation rate leaves this out along with their time.
+        /// </summary>
+        public double AllocUnmeasuredKB;
 
         /// <summary>A copy that another thread can read while the game thread goes on counting.</summary>
         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<WorstFrame> worst = new List<WorstFrame>();
@@ -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()
         /// <summary>Counts over the session so far. The object is replaced when a new log starts.</summary>
         public static SessionStats Stats => stats;
 
+        /// <summary>
+        /// The <c># capability-final|allocSource|</c> line: whether allocation was measured in every frame. The frames it was not measured in
+        /// (see <see cref="SessionStats.AllocUnmeasuredFrames"/>) are counted here rather than in a column, so the file format stays the same.
+        /// </summary>
+        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<long> clock = TestClock;