Roll named beaver rows up to their kind (NF1)

CLAUDE.md

@@ -83,6 +83,10 @@ To read the game's own code (the way every patch target here was checked): `ilsp
   `is IEarlyTickableSingleton` and a wrapper would hide the type and change tick order. The reference to the wrapped service is weak. There is no Harmony patch in the hot loop, so
   nothing depends on the runtime not inlining a method, and a mod's own patch on the singleton is inside the measurement. Entity kinds are the one place a per-call patch is unavoidable
   (`TickableEntity.Tick`), so that is sampled.
+- **An entity is keyed by its kind, not by the name the tick system recorded** (`Profile.EntityKindOf`: the name up to its first space or `(`). The game renames a character loaded from a
+  save to `<template> <its own name>` before the tick system records it, and one made during play is `<template>(Clone)`, so up to 0.1.3 every loaded beaver was its own row and beavers
+  ranked far too low. `tools/perflog.py` (`entity_kind`) applies the same rule to older recordings, so compare lines old and new up: change both together. Its known-issue
+  note is printed only when a recording's entity rows really are split. No template name in the game or the installed mods contains a space or `(`; a modded template whose name did would be cut short.
 - **Saves are timed at three hooks** (`SaveQueued`, `SaveInstantlySkippingNameValidation`, `SaveWriter.WriteToSaveStream`); whichever is entered first owns the save (`SaveTracker`), and a save open for
   a minute is treated as abandoned (the game's save throws on an IO error and skips its postfix). BeaverBuddies defers the real save, so the `SaveWriter` hook is what times it.
 - **Nothing a session holds may outlive it**: `Session.Stop` clears `services` (its delegates reach the whole colony), the colony sampler, the mod resolver and the milestones, and `Session.Start`

docs/TESTING.md

@@ -6,14 +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` (91 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (44 checks).
+`dotnet run --project tests -c Release` (92 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (48 checks).
 
 | What | How |
 |---|---|
 | Frame accounting: slots are exclusive and add up to the frame; unbalanced scopes; other threads ignored; allocation attribution; flags; ticks and buckets; Unity phases; summaries and histograms | Real `Probe` against a scripted clock (`CoreTests`) |
 | The per-frame path allocates nothing | `GC.GetAllocatedBytesForCurrentThread` around 2000 frames; also for a wrapper with the log off |
 | Failure containment: a failing clock switches the probe off, a full ring drops rows and counts them | `CoreTests` |
-| The profile: exact singleton timing, scaled sampling, random gaps that do not alias with a repeating pattern, budget adaptation, spike attribution, mod resolution | `ProfileTests` |
+| 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` |
 | The files: header, columns, invariant number format in any language, text tails, events, a file rewritten whole, an unopenable path, dropped rows, flush on stop | `WriterTests` |
 | `summary.md`, `README.md` and `columns.md` generation | `SummaryTests`, `WriterTests.EndToEnd` |
 | Every patch target exists in the installed game (1.1.2.4), has no exception filter, and takes only parameters Harmony can supply | `GameBindingTests.TargetsResolve` |
@@ -104,6 +104,8 @@ What it shows, and the line that shows it:
    readable text, and that a value changed there actually reaches `Session.Start` — change `SlowFrameMs`, load a save, and check `frames.csv`'s `# thresholdMs`
    header line against what was set. Every 0.1.3 recording so far has the default `# thresholdMs: 50`. (`PerformanceSettings.Load()` against the real
    `ISettings`/`ModRepository`/`ModSettingsOwnerRegistry` is verified in the game, above.)
+8. **Entity rows keyed by kind (not yet played)**: every entity name in the recordings made up to 0.1.3 was `<template>(Clone)` or `<template> <a beaver's name>`,
+   and the checks cover both; that a new recording from a loaded save has one row per kind is step 7 below.
 
 ## Five-minute check in a game
 
@@ -122,7 +124,8 @@ What it shows, and the line that shows it:
    `# capability-final|patchCalls|...` lines at the end say non-zero counts, and none says `never ran`, including `MeteredTickableComponent.Tick (sampled calls)`.
    `singleton wrappers put in place` should be a handful (one or two per array). `# capability|workingSet|...` should say `from Windows`.
    `# capability-final|profilerRecorder|...` and `frameTiming` may legitimately say `never produced a value` in a release build.
-7. `profile.csv` has rows of kind `component`, not just `entity`.
+7. `profile.csv` has rows of kind `component`, not just `entity`, and its `entity` rows are kinds: one `BeaverAdult`, not a `BeaverAdult(Clone)` and a row per beaver
+   (`BeaverAdult Malak`). `summary.md`'s entity table says the same.
 8. Compare the frame rate the game shows with `summary.md`'s mean; they should agree.
 9. Run `python tools/perflog.py report <folder>` and confirm it reads the folder without complaint.
 10. To see the cost, play the same save for the same time at the same speed with the mod turned off in the mod manager and compare the frame rate with something outside the mod (Steam's

source/Core/Profile.cs

@@ -100,6 +100,7 @@ sealed class Entry
         static readonly List<Entry> entries = new List<Entry>();
         static readonly Dictionary<(ProfileKind, Type), int> idsByType = new Dictionary<(ProfileKind, Type), int>();
         static readonly Dictionary<(ProfileKind, string), int> idsByName = new Dictionary<(ProfileKind, string), int>();
+        static readonly char[] entityKindEnds = { ' ', '(' };
 
         // Per key, for the window being collected.
         static long[] calls = new long[64], timed = new long[64], ticks = new long[64], allocN = new long[64], allocB = new long[64], max = new long[64];
@@ -207,16 +208,38 @@ public static int IdFor(ProfileKind kind, Type type)
             return id;
         }
 
-        /// <summary>The id of a named key (an entity's prefab, a method), registering it on first use. Game thread only.</summary>
+        /// <summary>The id of a named key (an entity's kind, a method), registering it on first use. Game thread only.</summary>
         public static int IdFor(ProfileKind kind, string name, string assembly = "")
         {
             string key = name ?? "?";
             if (idsByName.TryGetValue((kind, key), out int id)) return id;
-            id = Register(kind, key, assembly ?? "");
+            // An entity is keyed by its kind, not by its own name (see EntityKindOf). The name is remembered as well, so this runs once
+            // per name and every later tick of it is the lookup above, which allocates nothing.
+            string keyName = kind == ProfileKind.Entity ? EntityKindOf(key) : key;
+            if (!idsByName.TryGetValue((kind, keyName), out id))
+            {
+                id = Register(kind, keyName, assembly ?? "");
+                idsByName[(kind, keyName)] = id;
+            }
             idsByName[(kind, key)] = id;
             return id;
         }
 
+        /// <summary>
+        /// The kind of entity a tickable entity's name stands for: the text before its first space or '(', trimmed, or the whole name if that
+        /// leaves nothing. The tick system records a character's name after the game has renamed one loaded from a save to
+        /// "&lt;template&gt; &lt;its own name&gt;" (NamedEntityGameObjectSynchronizer), while one made during play keeps Unity's "&lt;template&gt;(Clone)",
+        /// so "BeaverAdult Malak" and "BeaverAdult(Clone)" are both "BeaverAdult". tools/perflog.py (entity_kind) applies the same rule to
+        /// recordings made before the mod did, so change both together.
+        /// </summary>
+        internal static string EntityKindOf(string name)
+        {
+            string trimmed = name.Trim();
+            int cut = trimmed.IndexOfAny(entityKindEnds);
+            string kind = cut < 0 ? trimmed : trimmed.Substring(0, cut).Trim();
+            return kind.Length > 0 ? kind : name;
+        }
+
         static string SafeAssemblyName(Type type)
         {
             try { return type.Assembly.GetName().Name ?? ""; }

tests/CoreTests.cs

@@ -199,7 +199,7 @@ static void WordsAndTails()
             var tiny = new char[8];
             Check(!Profile.Table.TryFormatRow(row, tiny, out _), "a row that does not fit is refused, not cut");
             var text = new System.Text.StringBuilder();
-            int id = Profile.IdFor(ProfileKind.Entity, "Beaver, \"Adult\"|x");
+            int id = Profile.IdFor(ProfileKind.Method, "Beaver, \"Adult\"|x");   // not an entity: an entity is keyed by the text before its first space
             row[3] = id;
             Profile.AppendProfileText(row, text);
             Equal(",Beaver; 'Adult' x,,", text.ToString());

tests/ProfileTests.cs

@@ -18,6 +18,7 @@ internal static class ProfileTests
             yield return ("Profile: a slow frame names the singletons that took its time, biggest first", SpikeAttribution);
             yield return ("Profile: an ordinary frame writes no spike rows but still forgets its times", NoSpikeForFastFrames);
             yield return ("Profile: the same class gets the same id, and Reset makes cached ids stale", IdsAreStable);
+            yield return ("Profile: a beaver's own name and Unity's '(Clone)' are counted under the entity's kind, and only for entities", EntityNamesRollUp);
             yield return ("Profile: sampling widens with load and stays inside the budget", SamplingAdapts);
             yield return ("Profile: sampling never goes below one and ignores an unmeasured cost", SamplingBounds);
             yield return ("Profile: load steps are written straight to the file as window 0", LoadRows);
@@ -225,6 +226,53 @@ static void IdsAreStable()
             }
         }
 
+        static void EntityNamesRollUp()
+        {
+            Prepare(out Rig rig);
+            using (rig)
+            {
+                // The game renames a character loaded from a save to "<template> <name>" before the tick system records its name; one born
+                // during play keeps Unity's "(Clone)". The 0.1.3 recording of a real game had 316 such keys, and beavers ranked far too low.
+                foreach (string name in new[] { "BeaverAdult Malak", "BeaverAdult(Clone)", "BeaverAdult Zengu", "BeaverChild Malak", "DistrictCenter.Folktails(Clone)" })
+                {
+                    Sample s = Profile.BeginEntity();
+                    rig.Advance(1);
+                    Profile.EndEntity(name, s);
+                }
+                Profile.FlushWindow(1, 1, 10, rig.Prof);
+                List<double[]> rows = rig.ProfileRows();
+                string names = string.Join(",", rows.Select(r => Profile.NameOf((int)r[3])).OrderBy(n => n, StringComparer.Ordinal));
+                Equal("BeaverAdult,BeaverChild,DistrictCenter.Folktails", names, "one row per kind of entity");
+                double[] adult = rows.Single(r => Profile.NameOf((int)r[3]) == "BeaverAdult");
+                Equal(3.0, adult[5], "all three adults' samples are in the one row");
+                Near(3, adult[6], .001);
+                int kind = Profile.IdFor(ProfileKind.Entity, "BeaverAdult");
+                Equal((double)kind, adult[3], "a name that is already a kind is the same key");
+                Equal(kind, Profile.IdFor(ProfileKind.Entity, "BeaverAdult Malak"));
+                Equal(kind, Profile.IdFor(ProfileKind.Entity, " BeaverAdult (Clone)"), "spaces around the kind are not part of it");
+                Check(kind != Profile.IdFor(ProfileKind.Entity, "BeaverAdultX"), "only the text after the kind is cut");
+                Equal("(Clone)", Profile.NameOf(Profile.IdFor(ProfileKind.Entity, "(Clone)")), "a name with nothing before the cut keeps itself");
+                Equal("?", Profile.NameOf(Profile.IdFor(ProfileKind.Entity, (string)null)));
+                // tools/perflog.py rolls up older recordings by the same rule; test_perflog.py checks these same cases.
+                foreach ((string name, string expected) in new[] { ("BeaverAdult Malak", "BeaverAdult"), ("BeaverAdult(Clone)", "BeaverAdult"),
+                    (" BeaverAdult (Clone)", "BeaverAdult"), ("DistrictCenter.Folktails(Clone)", "DistrictCenter.Folktails"), ("BeaverAdult", "BeaverAdult"),
+                    ("BeaverAdultX", "BeaverAdultX"), ("(Clone)", "(Clone)"), ("?", "?"), ("", "") })
+                    Equal(expected, Profile.EntityKindOf(name), "'" + name + "'");
+                // Only entities: a watched method's, a load step's or a singleton's name is its own key.
+                Equal("Some.Type.Method(int)", Profile.NameOf(Profile.IdFor(ProfileKind.Method, "Some.Type.Method(int)")));
+                Equal("Some Loader (step)", Profile.NameOf(Profile.IdFor(ProfileKind.Load, "Some Loader (step)")));
+                Equal("Mod.Singleton Thing", Profile.NameOf(Profile.IdFor(ProfileKind.TickSingleton, "Mod.Singleton Thing")));
+                // A name seen once is looked up again on every sampled tick: that must allocate nothing.
+                long before = GC.GetAllocatedBytesForCurrentThread();
+                for (int i = 0; i < 1000; i++)
+                {
+                    Sample s = Profile.BeginEntity();
+                    Profile.EndEntity(i % 2 == 0 ? "BeaverAdult Malak" : "BeaverAdult(Clone)", s);
+                }
+                Equal(0L, GC.GetAllocatedBytesForCurrentThread() - before, "bytes allocated by 1000 sampled ticks of names already seen");
+            }
+        }
+
         static void SamplingAdapts()
         {
             Prepare(out Rig rig);

tools/perflog.py

@@ -47,6 +47,13 @@
 SLOW_MEAN_MS = 20.0
 LOAD_KINDS = ("load", "load-non-singleton", "post-load", "post-load-non-singleton")
 
+# Printed only for a recording whose entity rows really are split (KNOWN_ISSUE_APPLIES): a build of the fix that still carries an older version number
+# writes kinds already.
+ENTITY_SPLIT_NOTE = ("Entity rows are split by name: a beaver or bot loaded from the save is keyed by its own name ('BeaverAdult <name>'; the game renames "
+                     "characters as it loads them) and one born during play by 'BeaverAdult(Clone)', so profile.csv has rows named after single beavers and "
+                     "the summary.md written in the game ranks beavers far too low. This report adds entity rows up by kind (the name up to its first space "
+                     "or '('); the recording's own files do not.")
+
 # What is wrong with recordings made by an older Performance Log, found when a recording was first read. Each entry is (fixed in, note): the note
 # is printed at the top of the report for a recording made by an earlier version, so nobody trusts a figure that was known to be off.
 KNOWN_ISSUES = [
@@ -59,8 +66,18 @@
     ("0.1.1", "prDraw and prBatches are 0: Unity 6 has no counter by those names (its draw calls are split into several). The other columns are unaffected."),
     ("0.1.1", "While the game ran, frames.csv, profile.csv, spikes.csv and events.csv were held open by the mod, so copying or zipping the folder could leave them out "
               "(the folder listing shows size 0). Exit the game first, or read them with shared access."),
+    ("0.1.4", ENTITY_SPLIT_NOTE),
 ]
 
+
+def _entity_rows_are_split(session):
+    return any(r["kind"] == "entity" and entity_kind(r.get("name", "")) != r.get("name", "") for r in session.profile)
+
+
+# Notes that only some recordings of the versions they name have, each with the check that finds the problem in a recording (a note not listed
+# here is printed for every recording made before its fix).
+KNOWN_ISSUE_APPLIES = {ENTITY_SPLIT_NOTE: _entity_rows_are_split}
+
 GAME_ASSEMBLY_PREFIXES = ("Timberborn.", "Bindito.", "UnityEngine", "Unity.", "System")
 
 
@@ -79,7 +96,7 @@ def known_issues(session):
     have = version_tuple(session.h("mod"))
     if have is None:
         return []
-    return [note for fixed, note in KNOWN_ISSUES if have < version_tuple(fixed)]
+    return [note for fixed, note in KNOWN_ISSUES if have < version_tuple(fixed) and KNOWN_ISSUE_APPLIES.get(note, lambda _: True)(session)]
 
 
 # ---------------------------------------------------------------- reading
@@ -318,18 +335,32 @@ def __init__(self, kind, name, mod, assembly):
         self.ms = self.kb = self.calls = self.sampled = self.max_ms = 0.0
 
 
+def entity_kind(name):
+    """The kind of entity an entity row's name stands for: the text before its first space or '(', trimmed, or the whole name if that leaves
+    nothing. Up to 0.1.3 the mod keyed a character loaded from a save by its own name ('BeaverAdult Malak') and one born during play by
+    'BeaverAdult(Clone)'; it now applies this same rule itself (Profile.EntityKindOf), so recordings old and new line up. Change both together."""
+    trimmed = name.strip()
+    cut = re.search(r"[ (]", trimmed)
+    kind = trimmed[:cut.start()].strip() if cut else trimmed
+    return kind or name
+
+
 def profile_totals(session, tick_from=0, tick_to=None):
-    """Totals per (kind, name) over the profile windows that end after tick_from (load rows, window 0, are separate)."""
+    """Totals per (kind, name) over the profile windows that end after tick_from (load rows, window 0, are separate). Entity rows are added up
+    by kind (entity_kind)."""
     totals = collections.OrderedDict()
     for r in session.profile:
         if r.get("window", 0) == 0:
             continue
         if r["tick"] < tick_from or (tick_to is not None and r["tick"] > tick_to):
             continue
-        key = (r["kind"], r.get("name", ""))
+        name = r.get("name", "")
+        if r["kind"] == "entity":
+            name = entity_kind(name)
+        key = (r["kind"], name)
         t = totals.get(key)
         if t is None:
-            t = totals[key] = KeyTotal(r["kind"], r.get("name", ""), r.get("mod", ""), r.get("assembly", ""))
+            t = totals[key] = KeyTotal(r["kind"], name, r.get("mod", ""), r.get("assembly", ""))
         t.ms += r["ms"]; t.kb += r["allocKB"]; t.calls += r["calls"]; t.sampled += r["sampled"]; t.max_ms = max(t.max_ms, r["maxMs"])
     return totals