Release 0.1.4

CHANGELOG.md

@@ -1,5 +1,47 @@
 # Changelog
 
+## 0.1.4 (preview, not yet played)
+
+Fixes for what the first 0.1.3 recording (`2026-09-21_23-13-11`, 44 minutes, ten mods) showed, a more honest estimate of what the mod itself
+costs, and one new opt-in setting. Nothing here changes what the game simulates. Each fix has a check that fails without it; what needs the game
+to prove is listed in `docs/TESTING.md`.
+
+**Recording**
+- **Entity kinds are one row each again.** A beaver or bot loaded from a save was keyed by its own name (`BeaverAdult Malak`) and one born during
+  play by `BeaverAdult(Clone)`, so beavers ranked far too low: 14% of entity time instead of 85% in that recording. Entities are now keyed by kind
+  (the name up to its first space or `(`).
+- **`overheadUs` includes what the per-call patches really cost.** `patchCallNs` is now the real entity patch bodies (new `patchBodyNs` in the
+  `# calibration|` line) plus what Harmony adds. Up to 0.1.3 it timed an empty patch, so every recording shows `patchCallNs|0` and `overheadUs`
+  charged those calls either an assumed 40 ns or almost nothing. A watched method's call is charged the same figure and costs a little more, so
+  with `Watch` entries it is still slightly undercharged.
+- **Watched methods (`Watch`) are sampled at their own call rate**, chosen again every window they run in and sharing the watched methods' budget
+  between them. One busy method no longer leaves every watched method timed on about 1 call in 30 for the rest of the session. Every window a
+  watched method ran in has a row; a window where none of its calls could be timed is written with `sampled` 0 and no longer adds its calls at
+  0 ms to the totals.
+- **With the heap-size allocation counter** (every game so far), a frame with a garbage collection is counted as "allocation not measured", in a
+  new `# capability-final|allocSource|` line and in `summary.md`, and left out of the allocation-per-second figures instead of being read as 0 KB.
+- **New setting `AutoWatch`** (`PerformanceLog.cfg` only, **off by default**). It times the prefixes, postfixes and finalizers other mods put on the
+  game's hot methods, in the Watch slots the `Watch` entries leave (40 in all): first those on the methods behind the profile's rows (a
+  singleton's `Tick`/`UpdateSingleton`/`LateUpdateSingleton`/`StartParallelTick`, an entity's or component's `Tick`), then the rest of the hot
+  list, in name order. Patches on the random numbers, `Guid.NewGuid` and `DateTime.ToString` (BeaverBuddies' co-op code) are left out. Each gets
+  a `method` row and a `# watch|...|auto|...` header line; a prefix that can skip the game's method is marked `(can replace it)`. It patches once,
+  when the first game loads, changes no other mod's patch, and puts the game's random state back afterwards so BeaverBuddies co-op stays in
+  step. **Keep it off in co-op until it has been played in a two-player game** (`docs/TESTING.md`, item 10).
+
+**summary.md and `perflog.py`**
+- A slow frame is blamed on a singleton only if it took at least 10% of the frame or 5 ms. Otherwise the Blame cell says no singleton stood out,
+  and whether the frame had a save or a garbage collection (a 1 ms singleton was named as the cause of a 1.1 s save). A frame with no singleton
+  timed says nothing.
+- `otherMs` is split by Unity phase: the Update phase less the timed parts in it, the LateUpdate phase less `lateMs`, `plPost`, the phases
+  before Update, and the time between phases. The "not the game's code" finding now points at scripts when that is where the time is, and keeps
+  pointing at the graphics card or vertical sync when the wait is in `plPost` or before Update.
+- `report` names the other mods whose Harmony patches run inside a singleton's time and lists the hot methods other mods patch; `compare` lists
+  the other mods' patches that only one session has. A recording that could not list its patches says so.
+- Watched methods are named by class and method (`TickableEntityTickPatcher.Prefix(TickableEntity)`, not `Prefix(TickableEntity)`), and
+  `compare` no longer counts a method only one side watched as extra time.
+- Older recordings: `perflog.py` adds their entity rows up by kind, so `compare` lines 0.1.3 and 0.1.4 up, and prints a `KNOWN ISSUE` when a
+  recording's entity rows are split or its `overheadUs` understated the patches (or was a 40 ns guess).
+
 ## 0.1.3 (preview)
 
 **The defaults now capture the most detail a session can hold without anyone touching a setting**, so every recording made from a plain

CLAUDE.md

@@ -48,7 +48,7 @@ packaging/       manifest.json, PerformanceLog.cfg. build.ps1 builds, tests and
 
 ```
 .\build.ps1 -SkipTests                                  build + package
-dotnet run --project tests -c Release                   all C# checks (91 at 0.1.3; docs/TESTING.md keeps the current count)
+dotnet run --project tests -c Release                   all C# checks (113 at 0.1.4; docs/TESTING.md keeps the current count)
 python -m unittest discover -s tools -p "test_perflog.py"
 dotnet run --project tests -c Release -- --print-columns
 dotnet run --project tests -c Release -- --write-sample tests/fixtures/sample-with-mod

README.md

@@ -4,17 +4,19 @@ A Timberborn 1.1 mod (built against **1.1.2.4**) that measures **where the game'
 person, or an AI assistant such as Claude, can read to find out why a game is slow. It is a diagnostic tool for finding performance problems in
 the game and in other mods. It does nothing else.
 
-Version **0.1.3** is a **preview**, published as a pre-release. Its automated checks run against the game's real assemblies.
+Version **0.1.4** is a **preview**, published as a pre-release. Its automated checks run against the game's real assemblies.
 Version 0.1.0 was the first to be played (a 31 minute session with nine mods, ending in a normal exit): every patch applied and the recording was complete.
 That first recording also showed several defects, fixed in 0.1.1. 0.1.2 added an in-game settings page, and 0.1.3 made the most detailed profile the default.
 0.1.1 and 0.1.3 have been played since. A 44 minute 0.1.3 recording with ten mods shows the new defaults working, and every 0.1.1 fix that a recording can show.
-Not verified yet: whether a value changed on the settings page reaches a recording.
+0.1.4 fixes what that recording showed (beavers split into one row each, the mod's own cost undercounted, slow frames blamed on the wrong singleton) and
+adds the opt-in `AutoWatch`; it has not been played yet. Not verified yet either: whether a value changed on the settings page reaches a recording.
 
 See [CHANGELOG.md](CHANGELOG.md) for what changed in each version, and [docs/TESTING.md](docs/TESTING.md) for what is and is not verified and how to check
 it in a game in five minutes. If a part fails to start, it says so in the log and the summary, that part stays off, and the game carries on.
 
 It only observes. It never records or replays an action, never uses the game's random numbers and never touches anything the simulation reads, so
-it should not cause a desync in co-op. (That has not been played in co-op yet.)
+it should not cause a desync in co-op. (That has not been played in co-op yet.) The one exception to watch is `AutoWatch`, off by default: under
+BeaverBuddies making a Harmony patch draws random numbers, so it puts them back after its patches (see below); keep it off in co-op until that has been played.
 
 ## Install
 
@@ -117,8 +119,9 @@ is otherwise invisible. When the first game is loaded, the mod reads Harmony's l
 first those on the per-tick and per-frame methods behind the profile's own rows (a singleton's `Tick`, `UpdateSingleton`, `LateUpdateSingleton` or
 `StartParallelTick`, an entity's or a component's `Tick`), then those on the rest of the hot methods the header lists, in name order, in the slots the
 `Watch` entries leave free (40 methods in all; your `Watch` entries always come first). Patches on the game's random numbers, `Guid.NewGuid` and
-`DateTime.ToString` are left out (BeaverBuddies' co-op code, called very often); a `Watch` entry can still name one. Each gets a `method` row in `profile.csv`, named after the patch
-method and tagged with its mod, and a `# watch|...|auto|...` line in the `frames.csv` header saying which hot method it is on; the ones left out say why.
+`DateTime.ToString` are left out (BeaverBuddies' co-op code, called very often); a `Watch` entry can still name one. Each gets a `method` row in
+`profile.csv`, named after the patch method and tagged with its mod, and a `# watch|...|auto|...` line in the `frames.csv` header saying which hot
+method it is on; the ones left out say why.
 It only adds its own timing patch around each patch method: no other mod's patch is removed, reordered or changed. It is off by default because every
 call of a watched method pays for the watch, and some of these run tens of thousands of times a second or more; compare `overheadUs` with it on and off. A
 patch another mod makes after the game has loaded is not seen, and a very small patch method may have been copied into the method it patches by the

docs/TESTING.md

@@ -2,7 +2,9 @@
 
 Version 0.1.0 was the first to run in a game (the first recording, below). 0.1.1 fixed what that showed, 0.1.2 added an in-game settings page, and 0.1.3
 changed the defaults to `Profile = deep` and a wider sampling budget, for the most detail with nothing configured. 0.1.1 and 0.1.3 have both been played
-since. A 0.1.3 recording (below) shows the `deep` default working, and every 0.1.1 fix that a recording can show. This is the honest list.
+since. A 0.1.3 recording (below) shows the `deep` default working, and every 0.1.1 fix that a recording can show. 0.1.4 fixes what that recording showed
+and adds the opt-in `AutoWatch`; it has not been played yet, so every 0.1.4 change still needs a recording to confirm it (the list and the five-minute
+check below say what to look for). This is the honest list.
 
 ## Verified by the automated checks
 
@@ -27,7 +29,7 @@ since. A 0.1.3 recording (below) shows the `deep` default working, and every 0.1
 | The resolver the game side installs names a mod's DLL, `game` for the game's own and leaves the rest unknown; loading steps carry the heap growth | `ProfileTests` |
 | Profile = off leaves the entity tick unpatched; an abandoned save does not block the next; the parallel tick figure is not counted twice; slow-frame rows are limited per minute; the summary is made on the writer thread | `GameBindingTests`, `CoreTests`, `WriterTests` |
 | The config file, the watch list resolution against the real game types | `GameBindingTests` |
-| The auto watch (`AutoWatch = true`): only other mods' prefixes, postfixes and finalizers on the methods behind the profile's rows or on the hot list are taken, in name order whatever order Harmony lists them in, one watch per patch method; never more than the slots the Watch entries left, a Watch entry's method is not watched twice, and a refused or failed patch takes no slot; a patch is examined (label, exception filter, generic) the way a Watch entry is, against real methods; a watched patch method is counted, timed and named in `profile.csv`, and its watch allocates nothing; a prefix that can skip the method it patches is marked `(can replace it)`; the header's `# watch|` and `# capability|autoWatch|` lines and the end's never-called list; every patch is made, and Harmony's registry read, inside `Watch.KeepUnityRandom`, which reads `UnityEngine.Random.state` before and writes it back in a `finally` (checked in its IL; Unity itself cannot run here); the report, `compare` and `summary.md` name each by its class, and `compare` does not count a method only one side watched as extra time | `AutoWatchTests`, `SummaryTests`, `test_perflog` |
+| The auto watch (`AutoWatch = true`): only other mods' prefixes, postfixes and finalizers on the methods behind the profile's rows or on the hot list are taken, in name order whatever order Harmony lists them in, one watch per patch method; never more than the slots the Watch entries left, a Watch entry's method is not watched twice, and a refused or failed patch takes no slot, nor does one on the random numbers, `Guid` or `DateTime`; a patch is examined (label, exception filter, generic) the way a Watch entry is, against real methods; a watched patch method is counted, timed and named in `profile.csv`, and its watch allocates nothing; a prefix that can skip the method it patches is marked `(can replace it)`; the header's `# watch|` and `# capability|autoWatch|` lines and the end's never-called list; every patch is made, and Harmony's registry read, inside `Watch.KeepUnityRandom`, which reads `UnityEngine.Random.state` before and writes it back in a `finally` (checked in its IL; Unity itself cannot run here); the report, `compare` and `summary.md` name each by its class, and `compare` does not count a method only one side watched as extra time | `AutoWatchTests`, `SummaryTests`, `test_perflog` |
 | The analysis tool reads what the mod writes (fixtures come from the real writer) and each finding fires on its situation and not on a healthy one | `tools/test_perflog.py`, `WriterTests.FixturesAreCurrent` |
 | The in-game settings panel's values are clamped onto a `Config` the same way `PerformanceLog.cfg` is, only the six settings that can be, and the panel starts from what the .cfg file already had | `GameBindingTests.SettingsApplyTo`, `SettingsSeedFromTheCfgFile` |
 | A fresh `Config` (nothing set) is `Profile = deep`, `SpikeContributors = 8` and `OverheadBudgetPercent = 1`; a bad or missing `Profile` line falls back to `deep`, not `standard` | `GameBindingTests.ConfigParsing`, `ConfigProblems` |

packaging/manifest.json

@@ -1,6 +1,6 @@
 {
   "Name": "Performance Log",
-  "Version": "0.1.3",
+  "Version": "0.1.4",
   "Id": "kyler.performancelog",
   "MinimumGameVersion": "1.1.2.4",
   "Description": "Preview. Measures where Timberborn's time and memory go and writes it, session by session, to Documents/Timberborn/PerformanceLog: frame times and where each frame went, the cost of every singleton, kind of entity and mod, garbage collection, saves and loading, with a readme and summary that a person or an AI assistant can use to diagnose slowness. Deep profiling by default, for the most detail with nothing configured. It only observes: it never changes what the game simulates, so it is safe in multiplayer. Slow-frame threshold, window sizes and row limits can be set from the Mod Settings menu.",

source/PerformanceLog.csproj

@@ -5,7 +5,7 @@
     <RootNamespace>PerformanceLog</RootNamespace>
     <LangVersion>latest</LangVersion>
     <Nullable>disable</Nullable>
-    <Version>0.1.3</Version>
+    <Version>0.1.4</Version>
     <GenerateAssemblyInfo>true</GenerateAssemblyInfo>
     <!-- Report exactly the version above, without a +<commit> suffix. -->
     <IncludeSourceRevisionInInformationalVersion>false</IncludeSourceRevisionInInformationalVersion>

tests/SampleSession.cs

@@ -42,7 +42,7 @@ public static void Write(string directory, bool withMod = true, int seed = 7)
             var header = new HeaderBuilder("frames", HeaderBuilder.FramesFormat);
             header.Add("session", "sample-" + (withMod ? "with-mod" : "without-mod"));
             header.Add("started", "2026-01-01 12:00:00 +00:00 local, 2026-01-01 12:00:00 UTC");
-            header.Add("mod", "0.1.3");
+            header.Add("mod", "0.1.4");
             header.Add("game", "1.1.2.4 (this is a made-up sample, not a game)");
             header.Add("unity", "6000.0.0f1");
             header.Add("os", "Windows 11 (10.0.26200) 64bit");
@@ -220,8 +220,8 @@ void Work(int id, double ms)
             writer.SetFile(summary, Summary.Render(BuildInput(withMod, "finished")));
             writer.Stop();
             if (writer.Failure != null) throw new Exception("the sample writer failed: " + writer.Failure);
-            File.WriteAllText(Path.Combine(directory, "README.md"), SessionReadme.Render(ReadTemplate(), "0.1.3"));
-            File.WriteAllText(Path.Combine(directory, "columns.md"), SessionReadme.RenderColumns("0.1.3"));
+            File.WriteAllText(Path.Combine(directory, "README.md"), SessionReadme.Render(ReadTemplate(), "0.1.4"));
+            File.WriteAllText(Path.Combine(directory, "columns.md"), SessionReadme.RenderColumns("0.1.4"));
             Probe.TestClock = null;
             Probe.HeavySampler = null;
             Alloc.Init();
@@ -232,7 +232,7 @@ static SummaryInput BuildInput(bool withMod, string status)
         {
             var input = new SummaryInput
             {
-                SessionId = "sample-" + (withMod ? "with-mod" : "without-mod"), Status = status, ModVersion = "0.1.3", GameVersion = "1.1.2.4 (sample)",
+                SessionId = "sample-" + (withMod ? "with-mod" : "without-mod"), Status = status, ModVersion = "0.1.4", GameVersion = "1.1.2.4 (sample)",
                 StartedLocal = "2026-01-01 12:00:00", Seconds = Probe.SessionSeconds, Ticks = Probe.TickCount, Row = Probe.SessionRow(), Stats = Probe.Stats,
                 Worst = Probe.WorstFrames(), Windows = Probe.Windows(), Totals = Profile.Totals(), TickIntervalSeconds = 0.3, Folder = "sample",
                 Colony = "240 beavers, 12 bots, 9000 entities, day 20",

tests/fixtures/sample-with-mod/README.md

@@ -1,6 +1,6 @@
 # Timberborn performance log: how to read this folder
 
-This folder is one recording of one Timberborn session, made by the **Performance Log** mod (version 0.1.3). It holds measurements
+This folder is one recording of one Timberborn session, made by the **Performance Log** mod (version 0.1.4). It holds measurements
 only. The mod never changes what the game simulates, so a recording shows the game as it was with the mods that were enabled.
 
 **If you are a Claude chat asked to find out why this session was slow: read `summary.md` first, then this file's "Diagnosing"

tests/fixtures/sample-with-mod/columns.md

@@ -1,4 +1,4 @@
-# Columns of the Performance Log files (version 0.1.3)
+# Columns of the Performance Log files (version 0.1.4)
 
 Generated from the mod's own column definitions. `README.md` explains how to read the numbers; this file only says what each column is.