From 9ed9f2ee6570a87944ab3fa67fb7184a0d114586 Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 08:05:38 -0700 Subject: [PATCH 1/3] AUTOWATCH: time other mods' patch methods on hot methods in free Watch slots A mod's prefix on every entity's tick (BeaverBuddies) or on a singleton's Tick (Late Game Performance) runs inside a profile row that names the game or the singleton, so its cost never shows. Watch could time it, but only if the user named each patch method. New setting AutoWatch (PerformanceLog.cfg only, off by default). When the first log of a run starts (every mod has started and the game has loaded, so Harmony's registry holds their patches, and nothing ticks yet), the mod reads the registry and puts its own Watch prefix and postfix around other mods' prefixes, postfixes and finalizers on hot methods. It fills only the Watch slots the Watch entries left (40 methods in all). It never unpatches, reorders or changes another mod's patch, and never calls UnpatchAll. The choice is pure code (AutoWatch.Plan) and goes in name order, whatever order Harmony lists the patches in. It takes the patches on the methods behind the profile's own rows first (a singleton's Tick, UpdateSingleton, LateUpdateSingleton or StartParallelTick, or an entity's or component's Tick), then the rest of PatchFormat's hot list. Within each group it goes by patched method, then prefix, postfix, finalizer, then patch method. One patch method is one watch, however many hot methods it is on. A method a Watch entry already watches is not watched twice. A refused or failed patch takes no slot. It does not rank by measured time: that would mean patching while the game runs, which this mod avoids (parallel-tick work spans frames). The header gets # capability|autoWatch| and one # watch|...|auto|| line per patch method, including the ones left out and why. The end of the log gets # capability-final|autoWatch| with how many were seen called. A tiny patch method that the runtime inlined into its target cannot be seen, and a zero there is not a measurement. The frame path is unchanged and allocation-free, and a check measures that for a watched patch method. perflog.py names a watched method by Class.Method(...) instead of the bare "Prefix(...)", and says which hot method each auto-watched one is on. Tests: AutoWatchTests (cap, Watch entries win, name order under any input order, examining patches against real methods, and the wiring with no allocation), config checks, and a test_perflog report check. C# 99 -> 104, Python 46 -> 47. Fixtures' README.md and columns.md regenerated for the method kind's new text. Docs: README, SESSION-README, CLAUDE.md, TESTING.md (in-game check 9), packaging cfg. Co-Authored-By: Claude Opus 5 --- CLAUDE.md | 8 +- README.md | 18 +- docs/SESSION-README.md | 9 + docs/TESTING.md | 11 +- packaging/PerformanceLog.cfg | 11 +- source/Core/AutoWatch.cs | 158 ++++++++++++ source/Core/Columns.cs | 2 +- source/Core/Profile.cs | 3 + source/Core/Summary.cs | 2 +- source/Game/Config.cs | 5 +- source/Game/Session.cs | 12 + source/Game/Watch.cs | 222 ++++++++++++++-- tests/AutoWatchTests.cs | 257 +++++++++++++++++++ tests/GameBindingTests.cs | 17 +- tests/Program.cs | 1 + tests/fixtures/sample-with-mod/README.md | 11 +- tests/fixtures/sample-with-mod/columns.md | 2 +- tests/fixtures/sample-without-mod/README.md | 11 +- tests/fixtures/sample-without-mod/columns.md | 2 +- tools/perflog.py | 42 ++- tools/test_perflog.py | 28 ++ 21 files changed, 790 insertions(+), 42 deletions(-) create mode 100644 source/Core/AutoWatch.cs create mode 100644 tests/AutoWatchTests.cs diff --git a/CLAUDE.md b/CLAUDE.md index 0b0e53b..787e539 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -27,13 +27,14 @@ source/Core/ Pure C# (netstandard2.1), no Unity or Timberborn types: this is Profile.cs Keyed profile (singletons, entity kinds, components, watched methods): exact and sampled timing, budgeted sampling, spike attribution. LogWriter.cs One thread that writes every file (tables from rings, an events queue, files rewritten whole). Never blocks the game thread. Summary.cs summary.md (pure formatting). Header.cs: header lines, and README.md / columns.md text. PatchReport.cs: which mod patches which hot method. + AutoWatch.cs Which of other mods' patch methods the auto watch (AutoWatch = true) times, in the free Watch slots. Alloc/Cpu/Milestones/Ring.cs Small sources. source/Game/ The Timberborn side (needs the game's assemblies to compile). Plugin.cs IModStarter, and the Bindito configurators. Reads config, installs patches. SessionService Bindito singleton: PostLoad starts a Session, Unload stops it. Session.cs One log from load to unload: folders, header, writer, probe start/stop, summary refresh, events. Instrumentation.cs The Harmony patch list (CreateSpecs) and every patch body. Wrappers.cs: timing wrappers put into the game's singleton arrays, LoadRecorder, SaveTracker. - Watch.cs Config-driven method timing. PlayerLoopTiming.cs: Unity phase markers and the frame boundary. UnityExtras.cs: profiler counters, frame timing. + Watch.cs Config-driven method timing, and the auto watch's patches on other mods' patch methods. PlayerLoopTiming.cs: Unity phase markers and the frame boundary. UnityExtras.cs: profiler counters, frame timing. Environment.cs Computer/game facts, mod list, assembly-to-mod map, Harmony patch reader. Config.cs: PerformanceLog.cfg. Settings.cs The in-game settings page (the Mod Settings mod). The only file that touches ModSettings.Core/.Common types. tests/ .NET 8 console checks (no test framework). Core checks run for real; game checks run against the installed game's real assemblies. @@ -101,6 +102,11 @@ To read the game's own code (the way every patch target here was checked): `ilsp `SpikeContributors`, `MaxSlowRowsPerMinute`) are in the menu; `SessionService.PostLoad` calls `PerformanceSettings.ApplyTo` to fold them onto `Plugin.Config` before each `Session.Start`. A `ModSetting`'s `.Value` is `default(T)` until Mod Settings calls `Load()` (which needs a real `ISettings`/`ModRepository`); what this mod controls at construction, and what `Load()` seeds `.Value` from the first time, is `.DefaultValue` — tests read that, not `.Value`. +- **The auto watch is the one patching done after `StartMod`** (`Watch.AutoInstall`, from `Session.Start` when `AutoWatch = true`): once per run of the + game, when the first log starts, because only then are other mods' patches (made at their start and while the game loads) in Harmony's registry, and + nothing ticks yet. It only adds this mod's own prefix and postfix (id `kyler.performancelog.watch`) around another mod's patch method; it never unpatches, + reorders or changes anyone else's patch. Which methods it takes is decided in `AutoWatch.Plan` (pure, tested in `AutoWatchTests`): name order, not time, + because ranking by what the recording measured would mean patching while the game runs. - Colony and memory columns are read only when a row is written and carried over otherwise (`lastHeavy` in `Probe`). - The tests run each check on a thread-pool thread, and `Probe` is static and remembers the game thread's id: every check that uses it goes through `Rig` in `CoreTests.cs`. diff --git a/README.md b/README.md index 8701ad6..e6260c6 100644 --- a/README.md +++ b/README.md @@ -60,7 +60,8 @@ same save at the same game speed for at least three minutes each, with the windo - **What each measurement source could do** and whether it actually produced anything, so a zero is never mistaken for a measurement. - **What measuring itself costs**, per frame, in the file. -Any method can also be timed by name (`Watch` in the config). See the file. +Any method can also be timed by name (`Watch` in the config), and with `AutoWatch = true` so can the patch methods other mods put on the game's +hot methods, each on its own row. See the file. ## Settings @@ -70,7 +71,7 @@ rather than a rough scale-up. This costs a bit more than a lighter profile — s ever matters more than the detail. Six of the settings can be changed from Timberborn's **Mod Settings** menu, with no restart: they take effect from the next game or save you load. -The rest — `Enabled`, `Profile`, `Watch` and `OutputFolder` — decide which parts of the game get patched, which is settled before that menu exists, +The rest — `Enabled`, `Profile`, `Watch`, `AutoWatch` and `OutputFolder` — decide which parts of the game get patched, which is settled before that menu exists, so they live only in `PerformanceLog.cfg` (next to `manifest.json` in the mod's `version-1.1` folder) and need the game restarted after editing. Nothing here changes what the game simulates, so co-op players may use different values. @@ -86,6 +87,7 @@ Nothing here changes what the game simulates, so co-op players may use different | `MaxSlowRowsPerMinute` | `300` | .cfg or Mod Settings | At most this many slow frames get a row a minute; the rest are only counted, so a game that is slow all the time cannot fill the disk. | | `OutputFolder` | *(empty)* | .cfg only | Where session folders go. Empty = `Documents\Timberborn\PerformanceLog`. | | `Watch` | *(none)* | .cfg only | Full names of methods to time: `Namespace.Type.Method`, separated by `;`, on as many lines as you like. Rows appear in `profile.csv` as kind `method`. | +| `AutoWatch` | `false` | .cfg only | `true` = also time the patch methods other mods put on the game's hot methods, in the Watch slots the `Watch` entries leave (40 in all). See below. | The first time you open the Mod Settings page it starts from whatever `PerformanceLog.cfg` already says; after that, whatever you set there is what is used, and editing that number in the file no longer does anything (Mod Settings remembers it, not this mod). @@ -100,6 +102,18 @@ The mod must be enabled so its type can be found. Every call of a watched method more than watching a rare one; the cost is in `overheadUs`. Methods with a `catch ... when` clause are refused (Harmony cannot patch them under Mono and the attempt can crash the game) and the log says so. +**`AutoWatch = true`** does this for the patches other mods put on the game's hot methods, without naming them. A mod's prefix on every entity's tick +(BeaverBuddies has one) or on a singleton's `Tick` (Late Game Performance has several) runs inside a row that names the game or the singleton, so its cost +is otherwise invisible. When the first game is loaded, the mod reads Harmony's list of patches and times other mods' prefixes, postfixes and finalizers: +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). 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 +runtime, where no watch can see it (`# capability-final|autoWatch|` lists any that were never seen called). + ## Working with other mods The mod puts a timing wrapper in front of each of the game's singletons, but only on the first tick and first frame of a game, after every other mod's `Load` patches have run, so a mod that looks at diff --git a/docs/SESSION-README.md b/docs/SESSION-README.md index 7eee81d..9b88b53 100644 --- a/docs/SESSION-README.md +++ b/docs/SESSION-README.md @@ -84,6 +84,15 @@ Start by writing down what the complaint is, because the causes differ: - `# patch|` lines in the `frames.csv` header list which mod patches which hot method (`hot`), which methods several mods patch (`shared`), and the order they run in. A mod patching `Ticker.Update` or `TickableEntity.Tick` puts its cost into `tickMs` or `entMs` without a row of its own; a `Watch` entry in the config (see the repo's README) times such a method directly (kind `method`). +- With `AutoWatch = true` in the config (the `# capability|autoWatch|` line says whether it was on and what it did), the patch methods other mods put on + hot methods are timed themselves: a `method` row each, named after the patch method (its class says what it is for, e.g. + `...TickableEntityTickPatcher.Prefix(TickableEntity)`, and `mod` is the mod that patches), and a `# watch||watching|auto||` line each in the header. It takes the patches on the methods behind the profile's own rows first (a singleton's + `Tick`, `UpdateSingleton`, `LateUpdateSingleton` or `StartParallelTick`, an entity's or component's `Tick`, whose time is otherwise inside a row that + names the game or the singleton's own mod), then the rest of the hot methods, in name order, in the Watch slots the config's `Watch` entries left + (40 in all); the `# watch|` lines of the ones left out say why. A patch method's time is inside the row of what it patches, so do not add the two. + One that `# capability-final|autoWatch|` lists as never seen called was either not called or so small that the runtime copied it into the method it + patches, where no watch can see it: a missing row there is not a measurement of 0. - To be sure it is a mod, **compare two recordings** of the same save at the same speed with and without it: `python tools/perflog.py compare ` (in the Performance Log repository). Say what else differed. diff --git a/docs/TESTING.md b/docs/TESTING.md index d1069a9..e716730 100644 --- a/docs/TESTING.md +++ b/docs/TESTING.md @@ -6,7 +6,7 @@ the game running. This is the honest list. ## Verified by the automated checks -`dotnet run --project tests -c Release` (99 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (46 checks). +`dotnet run --project tests -c Release` (104 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (47 checks). | What | How | |---|---| @@ -26,6 +26,7 @@ the game running. This is the honest list. | 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; the report names each by its class and the hot method it is on | `AutoWatchTests`, `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` | @@ -86,6 +87,14 @@ heap and is coarse**. The per-singleton `KB/s` figures are therefore only good i a frame, and `overheadUs`/`probeUs` should still land well under the report's 2% warning line — if not, that is exactly what `OverheadBudgetPercent` is for, and it is worth lowering the default again. +9. **`AutoWatch = true` (not yet played)**: Harmony cannot apply a patch in the test process, so that the auto watch's patches on other mods' patch methods + are made, and that Harmony hands them the method the watch looks up, is only reasoned, not seen. Set `AutoWatch = true` in `PerformanceLog.cfg`, restart, + load a save with BeaverBuddies (or any mod that patches `TickableEntity.Tick`) and play 3 minutes. Check that `Player.log` says `Auto watch: watching N of M + patch methods...` with N > 0 and no warning, that the `frames.csv` header has `# capability|autoWatch|watching ...` and a `# watch|...|watching|auto|...` + line per method, that `profile.csv` has `method` rows for them (BeaverBuddies' `TickableEntityTickPatcher.Prefix` should be one of the busiest), that + `# capability-final|autoWatch|` says most of them were called, and what `overheadUs` costs compared with the same save with `AutoWatch = false`. A patch + method listed there as never seen called is either not called or inlined by the runtime into the method it patches, which no watch can see. + ## Five-minute check in a game 1. Install (README, now including the **Mod Settings** mod), enable, open Mod Settings from the main menu and confirm **Performance Log** is listed with diff --git a/packaging/PerformanceLog.cfg b/packaging/PerformanceLog.cfg index 1848238..9ab35ab 100644 --- a/packaging/PerformanceLog.cfg +++ b/packaging/PerformanceLog.cfg @@ -7,8 +7,8 @@ # SlowFrameMs, SummarySeconds, ProfileSeconds, OverheadBudgetPercent, SpikeContributors and MaxSlowRowsPerMinute can also be set from # Timberborn's Mod Settings menu (no restart needed there; it takes effect from the next game or save you load). The first time you open # that menu it starts from whatever is below; after that, whatever you set there is what is used, and editing the number here no longer -# does anything for that one setting. Enabled, Profile, Watch and OutputFolder decide which parts of the game get patched, which happens -# before Mod Settings exists, so they are only ever read from here. +# does anything for that one setting. Enabled, Profile, Watch, AutoWatch and OutputFolder decide which parts of the game get patched, which +# happens before Mod Settings exists, so they are only ever read from here. # false = the mod does nothing at all (no patches, no files). Enabled = true @@ -50,3 +50,10 @@ OutputFolder = # Examples (remove the # to use): # Watch = Timberborn.TickSystem.Ticker.Update # Watch = LateGamePerformance.HaulCache.OnTickStarted; LateGamePerformance.MetricsDump.OnTickStarted + +# true = also time the patch methods other mods put on the game's hot methods, each on a row of its own (kind 'method'), so a mod's cost that +# runs inside a game row (a prefix on every entity's tick, say) is seen. It fills the Watch slots the Watch lines above leave free (40 methods in +# all): first patches on the per-tick and per-frame methods of singletons, entities and components, then those on the other hot methods, in +# name order; the frames.csv header lists what it took and what it left out. It adds only its own timing patch around each patch method, when +# the first game is loaded, and changes no other mod's patch. Off by default: every call of a watched method costs a little (see overheadUs). +AutoWatch = false diff --git a/source/Core/AutoWatch.cs b/source/Core/AutoWatch.cs new file mode 100644 index 0000000..78d33dd --- /dev/null +++ b/source/Core/AutoWatch.cs @@ -0,0 +1,158 @@ +using System; +using System.Collections.Generic; +using System.Linq; + +// Decides which of other mods' patch methods the auto watch (AutoWatch = true) times, from plain records: no Unity, Timberborn or Harmony +// types, so it can be tested on its own. The game side reads Harmony's registry, says which patched methods a profile row times, and makes +// the patches this chooses (Watch.AutoInstall). +namespace PerformanceLog +{ + /// One patch in Harmony's registry, as the auto watch sees it. + public sealed class AutoWatchCandidate + { + /// The patch method, named the way a Watch entry is (Namespace.Type.Method(ParameterTypes)): its key, and its row's name in profile.csv. + public string Label; + /// The DLL the patch method lives in, which names the mod. + public string Assembly; + /// The Harmony id that made the patch. + public string Owner; + /// prefix, postfix, finalizer or transpiler. + public string Kind; + /// The patched method: its declaring type's short name, its name, and the full name the log shows. + public string TypeName, MethodName, Target; + /// + /// The patched method is one a profile row times: a singleton's Tick, UpdateSingleton, LateUpdateSingleton or StartParallelTick, or an + /// entity's or component's Tick. A patch there is inside that row, which names the game or the singleton's own mod, not the patching mod. + /// + public bool ProfileRow; + /// Why the patch method cannot be watched, said the way Watch says it for a config entry; null if it can be. + public string Refused; + /// The game side's handle on the patch method. Carried through, never read here. + public object Method; + } + + /// What the auto watch did with one patch method. + public sealed class AutoWatchResult + { + /// The patch (the first in the order, when the patch method is on several hot methods). + public AutoWatchCandidate Candidate; + /// Every hot method the patch method is on, as "prefix on Namespace.Type.Method", joined with "; ". + public string On; + /// "watching", or why not. + public string Status; + public bool Watching; + } + + public static class AutoWatch + { + public const string Watching = "watching"; + public const string NamedByWatch = "watched by a Watch entry"; + public const string NoFreeSlot = "skipped: no free Watch slot"; + + sealed class Group + { + public string Label; + public AutoWatchCandidate First; + public int Tier, KindOrder; + public readonly SortedSet On = new SortedSet(StringComparer.Ordinal); + public string Refused; + } + + /// + /// Chooses and watches other mods' patch methods on hot methods, in Watch slots at most (the slots the + /// config's Watch entries left). Candidates are the prefixes, postfixes and finalizers (a transpiler runs once, when its patch is made, + /// so there is nothing to time) of every owner but , on a method a profile row times or on + /// 's hot list. One patch method is one watch, however many hot methods it is on. The order is by name, so + /// the same patches give the same choice whatever order Harmony lists them in: first the patches on the methods behind the profile's + /// rows (their time is inside a row that names someone else), then the rest of the hot list; within each, by the patched method's + /// full name, then prefix, postfix, finalizer, then the patch method's name. A patch method a Watch entry already watches + /// (, by label) keeps that watch; one that is refused, or that could not + /// patch (it returns why, or null once it has), takes no slot. The results are in that order, one for each patch method. + /// + public static List Plan(IEnumerable patches, string ownOwner, ICollection watchedAlready, + int freeSlots, Func watch) + { + var groups = new Dictionary(StringComparer.Ordinal); + foreach (AutoWatchCandidate c in patches ?? Enumerable.Empty()) + { + if (c == null || string.IsNullOrEmpty(c.Label)) continue; + int kindOrder = KindOrder(c.Kind); + if (kindOrder < 0) continue; + if (!string.IsNullOrEmpty(ownOwner) && (c.Owner ?? "").StartsWith(ownOwner, StringComparison.Ordinal)) continue; + int tier = c.ProfileRow ? 0 : PatchFormat.IsHot(c.TypeName, c.MethodName) ? 1 : -1; + if (tier < 0) continue; + if (!groups.TryGetValue(c.Label, out Group g)) groups[c.Label] = g = new Group { Label = c.Label, Tier = int.MaxValue }; + g.On.Add(c.Kind + " on " + c.Target); + if (Before(c, tier, kindOrder, g)) { g.First = c; g.Tier = tier; g.KindOrder = kindOrder; } + // Why a patch method cannot be watched does not depend on the hot method it is on; if the records disagree, the same one is kept whatever their order. + if (c.Refused != null && (g.Refused == null || string.CompareOrdinal(c.Refused, g.Refused) < 0)) g.Refused = c.Refused; + } + var ordered = groups.Values.ToList(); + ordered.Sort((a, b) => + { + int by = a.Tier.CompareTo(b.Tier); + if (by == 0) by = string.CompareOrdinal(a.First.Target, b.First.Target); + if (by == 0) by = a.KindOrder.CompareTo(b.KindOrder); + if (by == 0) by = string.CompareOrdinal(a.Label, b.Label); + return by; + }); + + var results = new List(); + int used = 0; + foreach (Group g in ordered) + { + var r = new AutoWatchResult { Candidate = g.First, On = string.Join("; ", g.On) }; + if (watchedAlready != null && watchedAlready.Contains(g.Label)) r.Status = NamedByWatch; + else if (g.Refused != null) r.Status = g.Refused; + else if (used >= freeSlots) r.Status = NoFreeSlot; + else + { + string failure; + try { failure = watch(g.First); } + catch (Exception e) { failure = (e.InnerException ?? e).Message ?? e.GetType().Name; } + if (failure == null) { used++; r.Status = Watching; r.Watching = true; } + else r.Status = "could not be patched: " + failure; + } + results.Add(r); + } + return results; + } + + /// Whether a patch of the method comes before the group's first so far: by tier, patched method, kind, then owner. + static bool Before(AutoWatchCandidate c, int tier, int kindOrder, Group g) + { + if (g.First == null) return true; + if (tier != g.Tier) return tier < g.Tier; + int by = string.CompareOrdinal(c.Target, g.First.Target); + if (by == 0) by = kindOrder.CompareTo(g.KindOrder); + if (by == 0) by = string.CompareOrdinal(c.Owner, g.First.Owner); + return by < 0; + } + + static int KindOrder(string kind) + { + switch (kind) + { + case "prefix": return 0; + case "postfix": return 1; + case "finalizer": return 2; + default: return -1; + } + } + + /// One line for the header and the summary: how many patch methods were found and watched, and why the rest were not. + public static string Describe(List results) + { + if (results == null) return "not run"; + int watching = results.Count(r => r.Watching); + int named = results.Count(r => r.Status == NamedByWatch); + int noSlot = results.Count(r => r.Status == NoFreeSlot); + int other = results.Count - watching - named - noSlot; + var text = new List { "watching " + watching + " of " + results.Count + " patch methods other mods put on hot methods" }; + if (named > 0) text.Add(named + " named by a Watch entry"); + if (noSlot > 0) text.Add(noSlot + " left out: no free Watch slot"); + if (other > 0) text.Add(other + " refused or could not be patched"); + return string.Join("; ", text); + } + } +} diff --git a/source/Core/Columns.cs b/source/Core/Columns.cs index 8068533..933aec4 100644 --- a/source/Core/Columns.cs +++ b/source/Core/Columns.cs @@ -415,7 +415,7 @@ public static class ProfileKinds "A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed.", "All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled').", "All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep.", - "One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in.", + "One method from the Watch list in the config, or (with AutoWatch) another mod's patch method on a hot method, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in.", "A singleton's Load while the game was loading (one row per singleton, window 0).", "A non-singleton loader's LoadNonSingletons while the game was loading (window 0).", "A singleton's PostLoad while the game was loading (window 0).", diff --git a/source/Core/Profile.cs b/source/Core/Profile.cs index 783323c..2f94d73 100644 --- a/source/Core/Profile.cs +++ b/source/Core/Profile.cs @@ -351,6 +351,9 @@ public static void EndMethod(int id, in Sample s) catch (Exception) { } } + /// A key's calls so far this session: the windows written and the one being collected. Game thread. + public static double CallsSoFar(int id) => id >= 0 && id < calls.Length ? totalCalls[id] + calls[id] : 0; + /// Registers a watched method and returns its key id. Game thread, before its patch is applied. public static int RegisterMethod(string name, string assembly, int interval) { diff --git a/source/Core/Summary.cs b/source/Core/Summary.cs index 7cac956..481deac 100644 --- a/source/Core/Summary.cs +++ b/source/Core/Summary.cs @@ -287,7 +287,7 @@ void Table(string title, Func where, int take) Table("Parallel singletons: the game thread starting them", x => x.Kind == ProfileKind.ParallelStart, 8); Table("Entity kinds (sampled)", x => x.Kind == ProfileKind.Entity, 15); Table("Entity components (sampled; Profile = deep only)", x => x.Kind == ProfileKind.Component, 15); - Table("Watched methods (config Watch)", x => x.Kind == ProfileKind.Method, 15); + Table("Watched methods (config Watch and AutoWatch)", x => x.Kind == ProfileKind.Method, 15); var mods = s.Totals.Where(x => x.Kind == ProfileKind.TickSingleton || x.Kind == ProfileKind.UpdateSingleton || x.Kind == ProfileKind.LateSingleton) .GroupBy(x => string.IsNullOrEmpty(x.Mod) ? "(unknown)" : x.Mod).Select(g => new { Mod = g.Key, Ms = g.Sum(x => x.Ms), Kb = g.Sum(x => x.Kb) }) diff --git a/source/Game/Config.cs b/source/Game/Config.cs index b870260..5c9c34a 100644 --- a/source/Game/Config.cs +++ b/source/Game/Config.cs @@ -43,6 +43,8 @@ internal sealed class Config public int MaxSlowRowsPerMinute = MaxSlowRowsPerMinuteDefault; public string OutputFolder = ""; public readonly List Watch = new List(); + /// Also time the patch methods other mods put on hot methods, in the Watch slots the Watch entries leave (Watch.AutoInstall). + public bool AutoWatch = false; /// Lines of the file that were not understood, for the log. public readonly List Problems = new List(); @@ -94,6 +96,7 @@ public void Apply(List> pairs) switch (key.ToLowerInvariant()) { case "enabled": Enabled = Bool(key, value, Enabled); break; + case "autowatch": AutoWatch = Bool(key, value, AutoWatch); break; case "slowframems": SlowFrameMs = Clamp(Number(key, value, SlowFrameMs), SlowFrameMsMin, SlowFrameMsMax); break; case "summaryseconds": SummarySeconds = Clamp(Number(key, value, SummarySeconds), SummarySecondsMin, SummarySecondsMax); break; case "profileseconds": ProfileSeconds = Clamp(Number(key, value, ProfileSeconds), ProfileSecondsMin, ProfileSecondsMax); break; @@ -143,6 +146,6 @@ public override string ToString() => "Enabled=" + Enabled + ", Profile=" + Profile + ", SlowFrameMs=" + SlowFrameMs.ToString(CultureInfo.InvariantCulture) + ", SummarySeconds=" + SummarySeconds.ToString(CultureInfo.InvariantCulture) + ", ProfileSeconds=" + ProfileSeconds.ToString(CultureInfo.InvariantCulture) + ", OverheadBudgetPercent=" + OverheadBudgetPercent.ToString(CultureInfo.InvariantCulture) + ", SpikeContributors=" + SpikeContributors + ", MaxSlowRowsPerMinute=" + MaxSlowRowsPerMinute + - ", Watch=" + (Watch.Count == 0 ? "(none)" : string.Join(";", Watch)); + ", Watch=" + (Watch.Count == 0 ? "(none)" : string.Join(";", Watch)) + ", AutoWatch=" + AutoWatch; } } diff --git a/source/Game/Session.cs b/source/Game/Session.cs index 759a556..6d50c6b 100644 --- a/source/Game/Session.cs +++ b/source/Game/Session.cs @@ -62,6 +62,14 @@ internal static void Start(Config cfg, SessionServices context, string modVersio Milestones.Mark("session-start"); warnings.Clear(); finalLines = new List(); lastColony = null; Instrumentation.ResetForSession(); + // The one moment for the auto watch's patches: every mod has started and the game has loaded, so Harmony's registry holds + // the patches it looks for, and nothing ticks yet. Only the first log makes them; they stay for the next save, as the Watch + // entries' do. Before the header is written, which lists them. + if (cfg.AutoWatch) + { + Watch.AutoInstall(); + if (Watch.Count > 0) Instrumentation.InstalledHit[Instrumentation.HitWatch] = true; + } // What does not change during a session is read once, so refreshing the summary does not have to ask the system again. environment = EnvironmentInfo.Collect(); modList = services.Mods != null ? EnvironmentInfo.Mods(services.Mods) : new List(); @@ -206,6 +214,8 @@ static List BuildHeader(string modVersion) header.Pipe("capability", "patch", parts[0], parts.Length > 1 ? parts[1] : "", parts.Length > 2 ? parts[2] : ""); } foreach (string result in Watch.Results) { string[] parts = result.Split('|'); header.Pipe("watch", parts[0], parts.Length > 1 ? parts[1] : ""); } + header.Pipe("capability", "autoWatch", Watch.AutoCapability(config)); + foreach (string[] line in Watch.AutoLines()) header.Pipe("watch", line); header.Pipe("calibration", Probe.CalibrationParts()); header.Pipe("sampling", "budgetPercent", config.OverheadBudgetPercent.ToString(CultureInfo.InvariantCulture), "note", "the intervals are chosen again every profile window; profile.csv says how many calls each row rests on"); @@ -351,6 +361,7 @@ static SummaryInput BuildSummaryInput(string status) foreach (string line in UnityExtras.StartLines()) input.Capabilities.Add(line.Replace("# capability|", "").Replace("|", ": ")); input.Capabilities.Add("patches on the game: " + Instrumentation.Installed + " installed, " + Instrumentation.Failed + " could not be made; each patch's calls so far are listed at the end of frames.csv"); foreach (string line in Watch.Results) input.Capabilities.Add("watch " + line.Replace("|", ": ")); + input.Capabilities.Add("auto watch: " + Watch.AutoCapability(config) + (config.AutoWatch ? " (each is a # watch| line in frames.csv)" : "")); foreach (string w in warnings) input.Warnings.Add(w); foreach (string result in Instrumentation.Results) @@ -392,6 +403,7 @@ internal static void Stop(string reason, bool quitting = false) final.Add("# capability-final|patchCalls|" + Instrumentation.HitName(i) + "|" + (Instrumentation.InstalledHit[i] ? Instrumentation.Hits[i] + (Instrumentation.Hits[i] == 0 ? "|never ran" : "") : "0|patch not installed")); final.Add("# capability-final|profile|" + Profile.Totals().Count + " keys were timed"); + final.Add("# capability-final|autoWatch|" + (config != null && config.AutoWatch ? Watch.AutoFinal() : "off")); finalLines = final; Event("session-end", 0, reason); // Not while the game is quitting: the engine may already be taking the player loop down. diff --git a/source/Game/Watch.cs b/source/Game/Watch.cs index fc2a378..393989e 100644 --- a/source/Game/Watch.cs +++ b/source/Game/Watch.cs @@ -1,7 +1,10 @@ using System; using System.Collections.Generic; +using System.Linq; using System.Reflection; using HarmonyLib; +using Timberborn.SingletonSystem; +using Timberborn.TickSystem; namespace PerformanceLog { @@ -10,6 +13,10 @@ namespace PerformanceLog /// them. This is how to measure a mod's own work, or a game method that other mods patch, without editing any code. Calls are /// counted exactly and every Nth is timed (see ), so a hot method costs little. The result is rows of kind /// 'method' in profile.csv. + /// + /// With AutoWatch = true it also times, in the slots the Watch entries left free, the patch methods other mods put on hot methods + /// (; which ones is decided in ). A patch method is watched like any other + /// method: a prefix and a postfix of this mod's own around it. The patch it belongs to, and every other patch, stay as they were. /// internal static class Watch { @@ -17,11 +24,13 @@ sealed class Watched { public MethodBase Method; public string Name, Assembly; + public bool Auto; } static readonly List watched = new List(); // Read by the patches on every call, replaced whole when a log starts and never changed in place. static Dictionary ids = new Dictionary(); + static Harmony harmony; /// One line for each watched method, saying whether it was patched, for the header. internal static readonly List Results = new List(); @@ -55,11 +64,12 @@ internal static List Resolve(IEnumerable entries) foreach (MethodBase method in methods) { var c = new Candidate { Method = method, Label = Label(type, method), Assembly = type.Assembly.GetName().Name }; - if (method.IsAbstract || method.ContainsGenericParameters || method.IsGenericMethodDefinition) c.Reason = "skipped: abstract or generic"; - else if (method.GetMethodBody() == null) c.Reason = "skipped: it has no body Harmony can patch"; - else if (Reflect.HasExceptionFilter(method)) c.Reason = "skipped: it has a catch ... when clause, which Harmony cannot patch under Mono"; - else if (accepted >= Config.MaxWatched) c.Reason = "skipped: too many watched methods"; - else accepted++; + c.Reason = Refusal(method); + if (c.Reason == null) + { + if (accepted >= Config.MaxWatched) c.Reason = "skipped: too many watched methods"; + else accepted++; + } found.Add(c); } } @@ -68,28 +78,47 @@ internal static List Resolve(IEnumerable entries) return found; } + /// Why a method cannot be watched, or null if it can. The same rules for a Watch entry and for the auto watch. + static string Refusal(MethodBase method) + { + if (method.IsAbstract || method.ContainsGenericParameters || method.IsGenericMethodDefinition) return "skipped: abstract or generic"; + if (method.GetMethodBody() == null) return "skipped: it has no body Harmony can patch"; + if (Reflect.HasExceptionFilter(method)) return "skipped: it has a catch ... when clause, which Harmony cannot patch under Mono"; + return null; + } + /// Patches every method the config names that can be patched. Returns the number patched. internal static int Install(Harmony harmony, Config config) { watched.Clear(); Results.Clear(); + Watch.harmony = harmony; int patched = 0; - MethodInfo prefix = Reflect.Own(typeof(Watch), nameof(WatchPrefix)); - MethodInfo postfix = Reflect.Own(typeof(Watch), nameof(WatchPostfix)); foreach (Candidate c in Resolve(config.Watch)) { if (!c.Ok) { Results.Add(c.Label + "|" + c.Reason); continue; } - try - { - harmony.Patch(c.Method, new HarmonyMethod(prefix) { priority = Priority.First }, new HarmonyMethod(postfix) { priority = Priority.Last }); - watched.Add(new Watched { Method = c.Method, Name = c.Label, Assembly = c.Assembly }); - Results.Add(c.Label + "|watching"); - patched++; - } - catch (Exception e) { Results.Add(c.Label + "|could not be patched: " + (e.InnerException ?? e).Message); } + string failure = Patch(c.Method); + if (failure != null) { Results.Add(c.Label + "|could not be patched: " + failure); continue; } + watched.Add(new Watched { Method = c.Method, Name = c.Label, Assembly = c.Assembly }); + Results.Add(c.Label + "|watching"); + patched++; } return patched; } + /// Puts the watch's prefix (before every other) and postfix (after every other) on a method. Returns null, or why it could not. + static string Patch(MethodBase method) + { + try + { + if (harmony == null) harmony = new Harmony(Instrumentation.HarmonyId + ".watch"); + MethodInfo prefix = Reflect.Own(typeof(Watch), nameof(WatchPrefix)); + MethodInfo postfix = Reflect.Own(typeof(Watch), nameof(WatchPostfix)); + harmony.Patch(method, new HarmonyMethod(prefix) { priority = Priority.First }, new HarmonyMethod(postfix) { priority = Priority.Last }); + return null; + } + catch (Exception e) { return (e.InnerException ?? e).Message; } + } + static string Label(Type type, MethodBase method) { var parameters = new List(); @@ -106,7 +135,7 @@ internal static void OnSessionStart() ids = map; } - static void WatchPrefix(MethodBase __originalMethod, out Sample __state) + internal static void WatchPrefix(MethodBase __originalMethod, out Sample __state) { __state = default; if (!Probe.Enabled || !Probe.OnGameThread) return; @@ -115,11 +144,170 @@ static void WatchPrefix(MethodBase __originalMethod, out Sample __state) __state = Profile.BeginMethod(id); } - static void WatchPostfix(MethodBase __originalMethod, Sample __state) + internal static void WatchPostfix(MethodBase __originalMethod, Sample __state) { if (!__state.On) return; Instrumentation.Hits[Instrumentation.HitWatch]++; if (ids.TryGetValue(__originalMethod, out int id)) Profile.EndMethod(id, __state); } + + // ---- the auto watch ---- + + static bool autoTried; + static string autoFailure; + static List autoResults; + + /// + /// Chooses and patches the auto watch's methods, once per run of the game (the patches stay for the next save loaded, as the Watch + /// entries' do). Called when the first log starts: every mod has started and the game has loaded, so Harmony's registry holds the + /// patches other mods make at start-up and while a game loads, and nothing ticks yet (no tick or parallel tick is running a patch + /// method; only a thread another mod runs of its own could be). A patch another mod makes later is not seen. Only this mod's own + /// patches are added; nothing of any other patch is removed, reordered or changed. + /// + internal static void AutoInstall() + { + if (autoTried) return; + autoTried = true; + try + { + AutoInstall(AutoCandidates(), Patch); + Log.Info("Auto watch: " + AutoWatch.Describe(autoResults) + "."); + } + catch (Exception e) + { + autoFailure = (e.InnerException ?? e).Message; + Log.Warning("The auto watch could not run: " + autoFailure); + } + } + + /// Plans the auto watch over these patches and watches what it chooses, patching each with (null, or why not). + internal static void AutoInstall(List candidates, Func patch) + { + var named = new HashSet(watched.Select(w => w.Name), StringComparer.Ordinal); + autoResults = AutoWatch.Plan(candidates, Instrumentation.HarmonyId, named, Config.MaxWatched - watched.Count, c => + { + if (!(c.Method is MethodBase method)) return "the patch method could not be found"; + string failure = patch(method); + if (failure == null) watched.Add(new Watched { Method = method, Name = c.Label, Assembly = c.Assembly, Auto = true }); + return failure; + }); + } + + /// Every prefix, postfix and finalizer in Harmony's registry on a method that runs behind a profile row or is on the hot list. + static List AutoCandidates() + { + var candidates = new List(); + foreach (MethodBase target in Harmony.GetAllPatchedMethods().ToList()) + { + try + { + if (!PatchFormat.IsHot(target.DeclaringType?.Name, target.Name) && !RunsBehindAProfileRow(target)) continue; + Patches info = Harmony.GetPatchInfo(target); + if (info == null) continue; + AddCandidates(candidates, target, "prefix", info.Prefixes); + AddCandidates(candidates, target, "postfix", info.Postfixes); + AddCandidates(candidates, target, "finalizer", info.Finalizers); + } + catch (Exception) { /* a method Harmony cannot describe is left out */ } + } + return candidates; + } + + static void AddCandidates(List candidates, MethodBase target, string kind, IEnumerable patches) + { + if (patches == null) return; + foreach (Patch patch in patches) candidates.Add(Examine(target, kind, patch.owner, patch.PatchMethod)); + } + + /// One patch as an auto watch candidate: its label, mod and owner, what it patches, and why it cannot be watched, if it cannot. Nothing is patched. + internal static AutoWatchCandidate Examine(MethodBase target, string kind, string owner, MethodInfo patchMethod) + { + var c = new AutoWatchCandidate + { + Kind = kind, Owner = owner, TypeName = target?.DeclaringType?.Name, MethodName = target?.Name, + Target = (target?.DeclaringType?.FullName ?? "?") + "." + target?.Name, ProfileRow = RunsBehindAProfileRow(target), + }; + try + { + Type type = patchMethod?.DeclaringType; + if (type == null) return c; // no label: never a candidate + c.Label = Label(type, patchMethod); + c.Assembly = type.Assembly.GetName().Name; + c.Method = patchMethod; + c.Refused = Refusal(patchMethod); + // Harmony hands its patches the method they are on as MethodBase.GetMethodFromHandle gives it, so that is the key the watch + // looks up; the MethodInfo in Harmony's registry is the same method, but may be a different object. + if (c.Refused == null && !type.IsGenericType) c.Method = MethodBase.GetMethodFromHandle(patchMethod.MethodHandle) ?? patchMethod; + } + catch (Exception e) { c.Refused = "could not be examined: " + (e.InnerException ?? e).Message; } + return c; + } + + /// + /// Whether a method is one a profile row times: a singleton's Tick, UpdateSingleton, LateUpdateSingleton or StartParallelTick, or an + /// entity's or component's Tick. Another mod's patch on one of these runs inside that row, which names the game or the singleton's own mod. + /// + internal static bool RunsBehindAProfileRow(MethodBase method) + { + try + { + Type type = method?.DeclaringType; + if (type == null || method.IsStatic || method.GetParameters().Length != 0) return false; + switch (method.Name) + { + case "Tick": + return type == typeof(TickableEntity) || type == typeof(MeteredTickableComponent) || + typeof(TickableComponent).IsAssignableFrom(type) || typeof(ITickableSingleton).IsAssignableFrom(type); + case "UpdateSingleton": return typeof(IUpdatableSingleton).IsAssignableFrom(type); + case "LateUpdateSingleton": return typeof(ILateUpdatableSingleton).IsAssignableFrom(type); + case "StartParallelTick": return typeof(IParallelTickableSingleton).IsAssignableFrom(type); + default: return false; + } + } + catch (Exception) { return false; } + } + + /// For the header's and the summary's capability lines: whether the auto watch ran and what it did. + internal static string AutoCapability(Config config) + { + if (config == null || !config.AutoWatch) return "off (AutoWatch = false in " + Config.FileName + ")"; + if (autoFailure != null) return "could not run: " + autoFailure; + return AutoWatch.Describe(autoResults); + } + + /// A # watch| line for each patch method the auto watch looked at: label, status, "auto", the hot methods it is on, its owner. + internal static IEnumerable AutoLines() + { + if (autoResults == null) yield break; + foreach (AutoWatchResult r in autoResults) + yield return new[] { r.Candidate.Label, r.Status, "auto", r.On, r.Candidate.Owner ?? "" }; + } + + /// For the capability-final line: how many of the auto-watched patch methods were called, and which were not. + internal static string AutoFinal() + { + var never = new List(); + int auto = 0; + foreach (Watched w in watched) + { + if (!w.Auto) continue; + auto++; + if (!ids.TryGetValue(w.Method, out int id) || Profile.CallsSoFar(id) <= 0) never.Add(w.Name); + } + if (autoResults == null && auto == 0) return autoFailure != null ? "could not run: " + autoFailure : "off"; + string text = (auto - never.Count) + " of " + auto + " watched patch methods were called"; + if (never.Count > 0) + text += "|never seen called (not called, or so small that the runtime copied it into the method it patches, where no watch sees it): " + string.Join("; ", never.Take(12)) + + (never.Count > 12 ? "; and " + (never.Count - 12) + " more" : ""); + return text; + } + + /// Test-only: forgets every watched method and the auto watch's choice. + internal static void ResetForTest() + { + watched.Clear(); Results.Clear(); + ids = new Dictionary(); + autoTried = false; autoFailure = null; autoResults = null; + } } } diff --git a/tests/AutoWatchTests.cs b/tests/AutoWatchTests.cs new file mode 100644 index 0000000..04ea5d9 --- /dev/null +++ b/tests/AutoWatchTests.cs @@ -0,0 +1,257 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Reflection; +using HarmonyLib; +using Timberborn.SingletonSystem; +using Timberborn.TickSystem; +using static PerformanceLog.Tests.Assert; + +namespace PerformanceLog.Tests +{ + // AutoWatch = true: the patch methods other mods put on hot methods are timed in the Watch slots the config left free. Which ones is + // decided from plain records (AutoWatch.Plan), so the choice is checked here without Harmony; the game side is checked against real + // methods, with the patching itself done by hand, because Harmony cannot apply a patch in this process. + internal static class AutoWatchTests + { + public static IEnumerable<(string, Action)> All() + { + yield return ("AutoWatch: other mods' patches fill only the free Watch slots; one that is refused or cannot be patched takes none", CapIsRespected); + yield return ("AutoWatch: a method a Watch entry names is not watched twice, and the Watch entries take their slots first", WatchEntriesWin); + yield return ("AutoWatch: the choice is in name order whatever order Harmony lists the patches in, the methods behind the profile's rows first", OrderIsByName); + yield return ("AutoWatch: a patch is examined the way a Watch entry is, and the methods behind the profile's rows are recognised", PatchesAreExamined); + yield return ("AutoWatch: a watched patch method is registered with the log, counted and timed, and its watch allocates nothing", WatchedPatchIsTimed); + } + + const string Own = "kyler.performancelog"; + const string EntityTick = "Timberborn.TickSystem.TickableEntity.Tick"; + const string Panel = "Timberborn.EntityPanelSystem.EntityPanel.UpdateSingleton"; + const string Input = "Timberborn.InputSystem.InputService.UpdateSingleton"; + const string Range = "Timberborn.Common.RandomNumberGenerator.Range"; + const string Connected = "Timberborn.GameDistricts.DistrictConnections.AreDistrictsConnected"; + const string ConnectedWith = "Timberborn.GameDistricts.DistrictConnections.GetDistrictsConnectedWith"; + const string TickerUpdate = "Timberborn.TickSystem.Ticker.Update"; + const string Strength = "Timberborn.WaterSourceSystem.WaterDepthStrengthModifier.GetStrengthModifier"; + const string Visuals = "Timberborn.StockpileVisualization.StockpileVisualizers.OnInventoryChanged"; + + /// One patch as the game side reports it. The assembly is the label's first part, the owner made up from it unless given. + static AutoWatchCandidate C(string label, string kind, string target, bool row = false, string owner = null, string refused = null) + { + int dot = target.LastIndexOf('.'); + string type = target.Substring(0, dot); + string assembly = label.Substring(0, label.IndexOf('.')); + return new AutoWatchCandidate + { + Label = label, Assembly = assembly, Owner = owner ?? assembly.ToLowerInvariant() + ".mod", Kind = kind, + TypeName = type.Substring(type.LastIndexOf('.') + 1), MethodName = target.Substring(dot + 1), Target = target, + ProfileRow = row, Refused = refused, Method = label, + }; + } + + // Shaped like the patches in a real recording (BeaverBuddies, LateGamePerformance and MixedStorage on the same game). + static List Patches() => new List + { + C("BB.EntityPatch.Prefix(TickableEntity)", "prefix", EntityTick, row: true), + C("BB.EntityPatch.Postfix(TickableEntity)", "postfix", EntityTick, row: true), + C("BB.RandomPatch.Prefix(Int32,Int32)", "prefix", Range), + C("BB.DistrictFix.Finalizer(Exception)", "finalizer", Connected), + C("BB.DistrictFix.Finalizer(Exception)", "finalizer", ConnectedWith), + C("LGP.UiThrottle.PanelPrefix()", "prefix", Panel, row: true, owner: "kyler.lategameperformance.UiThrottle"), + C("LGP.Timing.UpdatePrefix()", "prefix", TickerUpdate, owner: "kyler.lategameperformance.Timing"), + C("MS.TextEditingInputPatch.Finalizer(Exception)", "finalizer", Input, row: true), + C("MS.TextEditingInputPatch.Prefix()", "prefix", Input, row: true), + // Never taken: this mod's own patches (its measuring and its watch), a transpiler (it runs once, when the patch is made, so + // there is nothing to time), and a patch on a method that is neither behind a profile row nor on the hot list. + C("PerformanceLog.Instrumentation.EntityPrefix(Sample&)", "prefix", EntityTick, row: true, owner: Own), + C("PerformanceLog.Watch.WatchPrefix(MethodBase,Sample&)", "prefix", TickerUpdate, owner: Own + ".watch"), + C("BB.WaterSourceTimingFix.Transpiler(IEnumerable`1)", "transpiler", Strength), + C("MS.Visuals.Postfix()", "postfix", Visuals), + }; + + // Name order: the methods behind the profile's own rows first (by the patched method's name, then prefix, postfix, finalizer), then + // the rest of the hot list the same way. One patch method on two hot methods is one watch, placed by the first of them. + static readonly string[] Expected = + { + "LGP.UiThrottle.PanelPrefix()", + "MS.TextEditingInputPatch.Prefix()", + "MS.TextEditingInputPatch.Finalizer(Exception)", + "BB.EntityPatch.Prefix(TickableEntity)", + "BB.EntityPatch.Postfix(TickableEntity)", + "BB.RandomPatch.Prefix(Int32,Int32)", + "BB.DistrictFix.Finalizer(Exception)", + "LGP.Timing.UpdatePrefix()", + }; + + static string Labels(IEnumerable results) => string.Join(", ", results.Select(r => r.Candidate.Label + " [" + r.Status + "]")); + + static void CapIsRespected() + { + List patches = Patches(); + // First in name order, and refused (the game side says why, as Watch does for a config entry). + patches.Add(C("LGP.Generic.Prefix()", "prefix", Panel, row: true, owner: "kyler.lategameperformance.UiThrottle", refused: "skipped: abstract or generic")); + var tried = new List(); + List results = AutoWatch.Plan(patches, Own, new List(), 3, c => + { + tried.Add(c.Label); + return c.Label == "MS.TextEditingInputPatch.Prefix()" ? "boom" : null; + }); + Equal(9, results.Count, "one result for each patch method on a hot method: " + Labels(results)); + Equal(3, results.Count(r => r.Watching), "watching: " + Labels(results)); + Check(tried.SequenceEqual(new[] { "LGP.UiThrottle.PanelPrefix()", "MS.TextEditingInputPatch.Prefix()", "MS.TextEditingInputPatch.Finalizer(Exception)", "BB.EntityPatch.Prefix(TickableEntity)" }), + "a refused method is never patched, a failed patch leaves its slot to the next, and nothing is patched once the slots are used: " + string.Join(", ", tried)); + Equal("skipped: abstract or generic", results.Single(r => r.Candidate.Label == "LGP.Generic.Prefix()").Status); + Equal("could not be patched: boom", results.Single(r => r.Candidate.Label == "MS.TextEditingInputPatch.Prefix()").Status); + Check(results.Where(r => !r.Watching && tried.IndexOf(r.Candidate.Label) < 0 && r.Candidate.Refused == null).All(r => r.Status.StartsWith("skipped: no free Watch slot")), + "the rest say there was no free slot: " + Labels(results)); + Equal(4, results.Count(r => r.Status.StartsWith("skipped: no free Watch slot"))); + Check(AutoWatch.Describe(results).StartsWith("watching 3 of 9 "), AutoWatch.Describe(results)); + + foreach (int free in new[] { 0, -2 }) + { + bool called = false; + List none = AutoWatch.Plan(Patches(), Own, new List(), free, c => { called = true; return null; }); + Check(!called && none.Count == Expected.Length && none.All(r => !r.Watching && r.Status.StartsWith("skipped: no free Watch slot")), + "with no free slot (" + free + ") nothing is patched: " + Labels(none)); + } + } + + static void WatchEntriesWin() + { + // The Watch entries resolved to 38 methods, one of them a patch the auto watch would have taken, so 2 slots are left. + var named = new List { "BB.EntityPatch.Prefix(TickableEntity)" }; + var tried = new List(); + List results = AutoWatch.Plan(Patches(), Own, named, Config.MaxWatched - 38, c => { tried.Add(c.Label); return null; }); + AutoWatchResult entry = results.Single(r => r.Candidate.Label == "BB.EntityPatch.Prefix(TickableEntity)"); + Check(!entry.Watching && entry.Status == "watched by a Watch entry", "the Watch entry's own watch is kept: " + entry.Status); + Check(tried.SequenceEqual(new[] { "LGP.UiThrottle.PanelPrefix()", "MS.TextEditingInputPatch.Prefix()" }), "only the free slots are filled: " + string.Join(", ", tried)); + Equal(2, results.Count(r => r.Watching)); + Check(AutoWatch.Describe(results).Contains("1 named by a Watch entry"), AutoWatch.Describe(results)); + } + + static void OrderIsByName() + { + List first = AutoWatch.Plan(Patches(), Own, new List(), Config.MaxWatched, c => null); + Check(first.Select(r => r.Candidate.Label).SequenceEqual(Expected), "in name order: " + Labels(first)); + Check(first.All(r => r.Watching && r.Status == AutoWatch.Watching), Labels(first)); + Equal("finalizer on " + Connected + "; finalizer on " + ConnectedWith, first.Single(r => r.Candidate.Label == "BB.DistrictFix.Finalizer(Exception)").On, + "one watch for a patch method on two hot methods, naming both"); + Equal("prefix on " + EntityTick, first.Single(r => r.Candidate.Label == "BB.EntityPatch.Prefix(TickableEntity)").On); + string[] expected = first.Select(r => r.Candidate.Label + "|" + r.Status + "|" + r.On).ToArray(); + var random = new Random(7); + for (int round = 0; round < 20; round++) + { + List shuffled = Patches().OrderBy(_ => random.Next()).ToList(); + string[] again = AutoWatch.Plan(shuffled, Own, new List(), Config.MaxWatched, c => null).Select(r => r.Candidate.Label + "|" + r.Status + "|" + r.On).ToArray(); + Check(again.SequenceEqual(expected), "the same choice whatever order the patches come in: " + string.Join(", ", again)); + } + // With fewer slots it is the front of the same order that is taken. + List five = AutoWatch.Plan(Patches().AsEnumerable().Reverse(), Own, new List(), 5, c => null); + Check(five.Where(r => r.Watching).Select(r => r.Candidate.Label).SequenceEqual(Expected.Take(5)), Labels(five)); + } + + // ---- the game side ---- + + static void PatchesAreExamined() + { + MethodInfo entityTick = typeof(TickableEntity).GetMethod("Tick", BindingFlags.Instance | BindingFlags.Public); + Check(entityTick != null, "TickableEntity.Tick exists"); + MethodInfo prefix = typeof(AutoWatchFakePatches).GetMethod(nameof(AutoWatchFakePatches.Prefix)); + AutoWatchCandidate c = Watch.Examine(entityTick, "prefix", "other.mod", prefix); + Equal("PerformanceLog.Tests.AutoWatchFakePatches.Prefix(Int32,String)", c.Label, "labelled the way a Watch entry is"); + Equal("PerformanceLog.Tests", c.Assembly); + Equal("other.mod", c.Owner); Equal("prefix", c.Kind); + Equal("TickableEntity", c.TypeName); Equal("Tick", c.MethodName); Equal(EntityTick, c.Target); + Check(c.ProfileRow, "TickableEntity.Tick is what the entity rows time"); + Check(c.Refused == null, "a plain static method can be watched: " + c.Refused); + Check(Equals(MethodBase.GetMethodFromHandle(prefix.MethodHandle), c.Method), "the key is the method Harmony hands a patch as __originalMethod"); + + MethodInfo generic = typeof(AutoWatchFakePatches).GetMethod(nameof(AutoWatchFakePatches.Generic)); + Check((Watch.Examine(entityTick, "postfix", "other.mod", generic).Refused ?? "").Contains("abstract or generic")); + MethodBase filtered = Reflect.Overloads(AccessTools.TypeByName("Timberborn.GameSaveRuntimeSystem.GameSaver"), "Save").First(Reflect.HasExceptionFilter); + Check((Watch.Examine(entityTick, "prefix", "other.mod", (MethodInfo)filtered).Refused ?? "").Contains("catch ... when"), + "a patch method with an exception filter is refused, as a Watch entry is"); + + // The methods whose time a profile row already holds: a singleton's per-tick and per-frame methods, an entity's and a component's tick. + Check(Watch.RunsBehindAProfileRow(typeof(AutoWatchFakeTickable).GetMethod("Tick")), "ITickableSingleton.Tick"); + Check(Watch.RunsBehindAProfileRow(typeof(AutoWatchFakeUpdatable).GetMethod("UpdateSingleton")), "IUpdatableSingleton.UpdateSingleton"); + Check(Watch.RunsBehindAProfileRow(typeof(AutoWatchFakeUpdatable).GetMethod("LateUpdateSingleton")), "ILateUpdatableSingleton.LateUpdateSingleton"); + Check(Watch.RunsBehindAProfileRow(typeof(AutoWatchFakeParallel).GetMethod("StartParallelTick")), "IParallelTickableSingleton.StartParallelTick"); + Check(Watch.RunsBehindAProfileRow(entityTick), "TickableEntity.Tick"); + Check(Watch.RunsBehindAProfileRow(typeof(MeteredTickableComponent).GetMethod("Tick")), "MeteredTickableComponent.Tick"); + Check(!Watch.RunsBehindAProfileRow(typeof(Ticker).GetMethod("Update")), "Ticker.Update is on the hot list, not behind a row"); + Check(!Watch.RunsBehindAProfileRow(typeof(AutoWatchFakeTickable).GetMethod("Tock")), "another method of a singleton"); + Check(!Watch.RunsBehindAProfileRow(typeof(AutoWatchFakePatches).GetMethod(nameof(AutoWatchFakePatches.Tick))), "a static Tick of a class that is no singleton"); + Check(!Watch.RunsBehindAProfileRow(null)); + } + + static void WatchedPatchIsTimed() + { + var rig = new Rig(); + try + { + Watch.ResetForTest(); + MethodInfo entityTick = typeof(TickableEntity).GetMethod("Tick", BindingFlags.Instance | BindingFlags.Public); + MethodInfo prefix = typeof(AutoWatchFakePatches).GetMethod(nameof(AutoWatchFakePatches.Prefix)); + MethodInfo refused = typeof(AutoWatchFakePatches).GetMethod(nameof(AutoWatchFakePatches.Generic)); + var patched = new List(); + Watch.AutoInstall(new List + { + Watch.Examine(entityTick, "prefix", "other.mod", prefix), + Watch.Examine(entityTick, "postfix", "other.mod", refused), + }, m => { patched.Add(m); return null; }); + Equal(1, patched.Count, "only the method that can be watched is patched"); + Equal(1, Watch.Count); + Watch.OnSessionStart(); // what Session.Start does once the profile is reset + + // Harmony hands the patch the method it is on, as MethodBase.GetMethodFromHandle gives it. + MethodBase original = MethodBase.GetMethodFromHandle(prefix.MethodHandle); + for (int i = 0; i < 100; i++) { Watch.WatchPrefix(original, out Sample warm); rig.Advance(0.01); Watch.WatchPostfix(original, warm); } + long before = GC.GetAllocatedBytesForCurrentThread(); + for (int i = 0; i < 2000; i++) + { + Watch.WatchPrefix(original, out Sample s); + rig.Advance(0.01); + Watch.WatchPostfix(original, s); + } + Equal(0L, GC.GetAllocatedBytesForCurrentThread() - before, "bytes allocated by 2000 calls of a watched patch method"); + Check(Watch.AutoFinal().StartsWith("1 of 1 "), "the end of the log says the watched patch method ran: " + Watch.AutoFinal()); + + Profile.FlushWindow(1, 0, 10, rig.Prof); + double[] row = rig.ProfileRows().Single(r => (ProfileKind)(int)r[0] == ProfileKind.Method); + Equal(2100.0, row[4], "every call counted"); + Check(row[5] >= 1 && row[6] > 0, "some calls timed"); + Equal("PerformanceLog.Tests.AutoWatchFakePatches.Prefix(Int32,String)", Profile.NameOf((int)row[3])); + Equal("PerformanceLog.Tests", Profile.AssemblyOf((int)row[3]), "the row names the patch's own DLL, so the mod column is the patching mod"); + } + finally + { + Watch.ResetForTest(); + rig.Dispose(); + } + } + } + + internal static class AutoWatchFakePatches + { + public static void Prefix(int a, string b) { } + public static void Generic() { } + public static void Tick() { } + } + + internal sealed class AutoWatchFakeTickable : ITickableSingleton + { + public void Tick() { } + public void Tock() { } + } + + internal sealed class AutoWatchFakeUpdatable : IUpdatableSingleton, ILateUpdatableSingleton + { + public void UpdateSingleton() { } + public void LateUpdateSingleton() { } + } + + internal sealed class AutoWatchFakeParallel : IParallelTickableSingleton + { + public void StartParallelTick() { } + } +} diff --git a/tests/GameBindingTests.cs b/tests/GameBindingTests.cs index cbb00ca..78116c8 100644 --- a/tests/GameBindingTests.cs +++ b/tests/GameBindingTests.cs @@ -662,6 +662,7 @@ static void ConfigParsing() Equal(true, config.Enabled); Equal(Config.ProfileDeep, config.Profile); Equal(50.0, config.SlowFrameMs); Equal(PerformanceLog.Profile.TopK, config.SpikeContributors); Equal(1.0, config.OverheadBudgetPercent); Check(config.Deep && config.SamplesEntities, "deep by default"); + Equal(false, config.AutoWatch, "the auto watch adds per-call patches on other mods' code, so it is asked for, not on by default"); config.Apply(Config.Parse(new[] { "# a comment", @@ -670,6 +671,7 @@ static void ConfigParsing() "OverheadBudgetPercent = 1", "OutputFolder = D:\\logs", "MaxSlowRowsPerMinute = 5", "Watch = A.B.C; D.E.F", "Watch = G.H.I", + "AutoWatch = true", "no equals sign", "=novalue", })); Equal(33.5, config.SlowFrameMs); @@ -682,6 +684,8 @@ static void ConfigParsing() Equal("D:\\logs", config.OutputFolder); Equal(10, config.MaxSlowRowsPerMinute); // clamped up Check(config.Watch.SequenceEqual(new[] { "A.B.C", "D.E.F", "G.H.I" }), "Watch may repeat and use ;"); + Equal(true, config.AutoWatch); + Check(config.ToString().Contains("AutoWatch=True"), "the header's config line says whether the auto watch was on: " + config); Equal(0, config.Problems.Count); var off = new Config(); off.Apply(Config.Parse(new[] { "Profile=off" })); @@ -691,9 +695,10 @@ static void ConfigParsing() static void ConfigProblems() { var config = new Config(); - config.Apply(Config.Parse(new[] { "Enabled = maybe", "SlowFrameMs = fast", "Profile = extreme", "Surprise = 1" })); - Equal(true, config.Enabled); Equal(50.0, config.SlowFrameMs); Equal(Config.ProfileDeep, config.Profile); - Equal(4, config.Problems.Count); + config.Apply(Config.Parse(new[] { "Enabled = maybe", "SlowFrameMs = fast", "Profile = extreme", "Surprise = 1", "AutoWatch = sometimes" })); + Equal(true, config.Enabled); Equal(50.0, config.SlowFrameMs); Equal(Config.ProfileDeep, config.Profile); Equal(false, config.AutoWatch); + Equal(5, config.Problems.Count); + Check(config.Problems.Any(p => p.Contains("AutoWatch = sometimes")), string.Join("; ", config.Problems)); Check(config.Problems.Any(p => p.Contains("Enabled")) && config.Problems.Any(p => p.Contains("unknown setting Surprise"))); var many = new Config(); many.Apply(Config.Parse(new[] { "Watch = " + string.Join(";", Enumerable.Range(0, 60).Select(i => "T.T" + i + ".M")) })); @@ -724,7 +729,7 @@ static void SettingsApplyTo() owner.SpikeContributors.SetValue(-3); // clamped to 0 owner.MaxSlowRowsPerMinute.SetValue(1); // clamped to Config.MaxSlowRowsPerMinuteMin owner.OverheadBudgetPercent.SetValue(999f); // not self-clamping: ApplyTo must clamp it - var cfg = new Config(); + var cfg = new Config { AutoWatch = true }; owner.ApplyTo(cfg); Equal(Config.SlowFrameMsMax, cfg.SlowFrameMs); Equal(Config.SummarySecondsMin, cfg.SummarySeconds); @@ -732,8 +737,8 @@ static void SettingsApplyTo() Equal(0, cfg.SpikeContributors); Equal((int)Config.MaxSlowRowsPerMinuteMin, cfg.MaxSlowRowsPerMinute); Equal(Config.OverheadBudgetPercentMax, cfg.OverheadBudgetPercent); - // Enabled, Profile, Watch and OutputFolder decide which patches exist, so ApplyTo must never touch them. - Equal(true, cfg.Enabled); Equal(Config.ProfileDeep, cfg.Profile); Equal(0, cfg.Watch.Count); Equal("", cfg.OutputFolder); + // Enabled, Profile, Watch, AutoWatch and OutputFolder decide which patches exist, so ApplyTo must never touch them. + Equal(true, cfg.Enabled); Equal(Config.ProfileDeep, cfg.Profile); Equal(0, cfg.Watch.Count); Equal(true, cfg.AutoWatch); Equal("", cfg.OutputFolder); } static void SettingsSeedFromTheCfgFile() diff --git a/tests/Program.cs b/tests/Program.cs index cfb9f8a..8db5001 100644 --- a/tests/Program.cs +++ b/tests/Program.cs @@ -64,6 +64,7 @@ static int Run(string[] args) tests.AddRange(WriterTests.All()); tests.AddRange(SummaryTests.All()); tests.AddRange(GameBindingTests.All(managed)); + tests.AddRange(AutoWatchTests.All()); int failures = 0; foreach (var test in tests) diff --git a/tests/fixtures/sample-with-mod/README.md b/tests/fixtures/sample-with-mod/README.md index 1676913..8b93929 100644 --- a/tests/fixtures/sample-with-mod/README.md +++ b/tests/fixtures/sample-with-mod/README.md @@ -84,6 +84,15 @@ Start by writing down what the complaint is, because the causes differ: - `# patch|` lines in the `frames.csv` header list which mod patches which hot method (`hot`), which methods several mods patch (`shared`), and the order they run in. A mod patching `Ticker.Update` or `TickableEntity.Tick` puts its cost into `tickMs` or `entMs` without a row of its own; a `Watch` entry in the config (see the repo's README) times such a method directly (kind `method`). +- With `AutoWatch = true` in the config (the `# capability|autoWatch|` line says whether it was on and what it did), the patch methods other mods put on + hot methods are timed themselves: a `method` row each, named after the patch method (its class says what it is for, e.g. + `...TickableEntityTickPatcher.Prefix(TickableEntity)`, and `mod` is the mod that patches), and a `# watch||watching|auto||` line each in the header. It takes the patches on the methods behind the profile's own rows first (a singleton's + `Tick`, `UpdateSingleton`, `LateUpdateSingleton` or `StartParallelTick`, an entity's or component's `Tick`, whose time is otherwise inside a row that + names the game or the singleton's own mod), then the rest of the hot methods, in name order, in the Watch slots the config's `Watch` entries left + (40 in all); the `# watch|` lines of the ones left out say why. A patch method's time is inside the row of what it patches, so do not add the two. + One that `# capability-final|autoWatch|` lists as never seen called was either not called or so small that the runtime copied it into the method it + patches, where no watch can see it: a missing row there is not a measurement of 0. - To be sure it is a mod, **compare two recordings** of the same save at the same speed with and without it: `python tools/perflog.py compare ` (in the Performance Log repository). Say what else differed. @@ -117,7 +126,7 @@ the last bucket is everything above), and `th0`..`th5` count frames that ran 0, - `parallel-start`: A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed. - `entity`: All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled'). - `component`: All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep. -- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in. +- `method`: One method from the Watch list in the config, or (with AutoWatch) another mod's patch method on a hot method, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in. - `load`: A singleton's Load while the game was loading (one row per singleton, window 0). - `load-non-singleton`: A non-singleton loader's LoadNonSingletons while the game was loading (window 0). - `post-load`: A singleton's PostLoad while the game was loading (window 0). diff --git a/tests/fixtures/sample-with-mod/columns.md b/tests/fixtures/sample-with-mod/columns.md index 4587124..f6e9bfc 100644 --- a/tests/fixtures/sample-with-mod/columns.md +++ b/tests/fixtures/sample-with-mod/columns.md @@ -112,7 +112,7 @@ One row per key per window. The last three columns (`name`, `assembly`, `mod`) a - `parallel-start`: A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed. - `entity`: All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled'). - `component`: All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep. -- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in. +- `method`: One method from the Watch list in the config, or (with AutoWatch) another mod's patch method on a hot method, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in. - `load`: A singleton's Load while the game was loading (one row per singleton, window 0). - `load-non-singleton`: A non-singleton loader's LoadNonSingletons while the game was loading (window 0). - `post-load`: A singleton's PostLoad while the game was loading (window 0). diff --git a/tests/fixtures/sample-without-mod/README.md b/tests/fixtures/sample-without-mod/README.md index 1676913..8b93929 100644 --- a/tests/fixtures/sample-without-mod/README.md +++ b/tests/fixtures/sample-without-mod/README.md @@ -84,6 +84,15 @@ Start by writing down what the complaint is, because the causes differ: - `# patch|` lines in the `frames.csv` header list which mod patches which hot method (`hot`), which methods several mods patch (`shared`), and the order they run in. A mod patching `Ticker.Update` or `TickableEntity.Tick` puts its cost into `tickMs` or `entMs` without a row of its own; a `Watch` entry in the config (see the repo's README) times such a method directly (kind `method`). +- With `AutoWatch = true` in the config (the `# capability|autoWatch|` line says whether it was on and what it did), the patch methods other mods put on + hot methods are timed themselves: a `method` row each, named after the patch method (its class says what it is for, e.g. + `...TickableEntityTickPatcher.Prefix(TickableEntity)`, and `mod` is the mod that patches), and a `# watch||watching|auto||` line each in the header. It takes the patches on the methods behind the profile's own rows first (a singleton's + `Tick`, `UpdateSingleton`, `LateUpdateSingleton` or `StartParallelTick`, an entity's or component's `Tick`, whose time is otherwise inside a row that + names the game or the singleton's own mod), then the rest of the hot methods, in name order, in the Watch slots the config's `Watch` entries left + (40 in all); the `# watch|` lines of the ones left out say why. A patch method's time is inside the row of what it patches, so do not add the two. + One that `# capability-final|autoWatch|` lists as never seen called was either not called or so small that the runtime copied it into the method it + patches, where no watch can see it: a missing row there is not a measurement of 0. - To be sure it is a mod, **compare two recordings** of the same save at the same speed with and without it: `python tools/perflog.py compare ` (in the Performance Log repository). Say what else differed. @@ -117,7 +126,7 @@ the last bucket is everything above), and `th0`..`th5` count frames that ran 0, - `parallel-start`: A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed. - `entity`: All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled'). - `component`: All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep. -- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in. +- `method`: One method from the Watch list in the config, or (with AutoWatch) another mod's patch method on a hot method, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in. - `load`: A singleton's Load while the game was loading (one row per singleton, window 0). - `load-non-singleton`: A non-singleton loader's LoadNonSingletons while the game was loading (window 0). - `post-load`: A singleton's PostLoad while the game was loading (window 0). diff --git a/tests/fixtures/sample-without-mod/columns.md b/tests/fixtures/sample-without-mod/columns.md index 4587124..f6e9bfc 100644 --- a/tests/fixtures/sample-without-mod/columns.md +++ b/tests/fixtures/sample-without-mod/columns.md @@ -112,7 +112,7 @@ One row per key per window. The last three columns (`name`, `assembly`, `mod`) a - `parallel-start`: A parallel singleton's StartParallelTick on the game thread: scheduling only, the work itself runs on worker threads and is not visible here. Every call is timed. - `entity`: All the ticks of one kind of entity (a prefab such as a beaver or a farm house). Only every Nth call is timed and the result is scaled up (see 'sampled'). - `component`: All the ticks of one kind of entity component (a class such as Walker). Only every Nth call is timed and the result is scaled up. Only recorded with Profile = deep. -- `method`: One method from the Watch list in the config, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in. +- `method`: One method from the Watch list in the config, or (with AutoWatch) another mod's patch method on a hot method, timed including everything inside it and every patch on it. Calls are counted exactly; the first call in each window and about every Nth after it are timed. N is chosen from the method's own calls in the last window it ran in and the share of the budget it splits with the other watched methods that ran then, so it widens while the method is busy or many watched methods are. It has a row for every window it ran in. - `load`: A singleton's Load while the game was loading (one row per singleton, window 0). - `load-non-singleton`: A non-singleton loader's LoadNonSingletons while the game was loading (window 0). - `post-load`: A singleton's PostLoad while the game was loading (window 0). diff --git a/tools/perflog.py b/tools/perflog.py index 23f09f0..a83e535 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -41,7 +41,7 @@ ("parallel-start", "Parallel singletons: the game thread starting them"), ("entity", "Entity kinds (sampled)"), ("component", "Entity components (sampled; Profile = deep)"), - ("method", "Watched methods (config Watch)"), + ("method", "Watched methods (config Watch and AutoWatch)"), ]) # 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 @@ -368,6 +368,33 @@ def short(name, width=60): return tail if len(tail) <= width else tail[:width] +def short_method(name, width=60): + """A watched method's label (Namespace.Type.Method(Parameters)) cut to Type.Method(Parameters), keeping the class: an auto-watched patch + method is nearly always called Prefix or Postfix, so the method name alone says nothing.""" + if len(name) <= width: + return name + head, paren, params = name.partition("(") + parts = head.split(".") + cls = parts[-2].rsplit("+", 1)[-1] if len(parts) >= 2 else "" + shorter = (cls + "." if cls else "") + parts[-1] + paren + params + if len(shorter) > width and paren: + shorter = (cls + "." if cls else "") + parts[-1] + "(...)" + return shorter if len(shorter) <= width else shorter[:width] + + +def short_key(kind, name, width=60): + return short_method(name, width) if kind == "method" else short(name, width) + + +def auto_watch_notes(session): + """The auto watch's own # watch| lines (label|status|auto|what it is on|owner), by the name profile.csv gives the method (commas become ;).""" + notes = {} + for w in session.pipe("watch"): + if len(w) >= 4 and w[2] == "auto": + notes[w[0].replace(",", ";")] = "%s (%s)" % (w[3], w[4]) if len(w) >= 5 and w[4] else w[3] + return notes + + # ---------------------------------------------------------------- the profile class KeyTotal: @@ -766,6 +793,7 @@ def report(session, args, out): 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.") + auto_notes = auto_watch_notes(session) 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: @@ -774,8 +802,10 @@ def report(session, args, out): 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" % ( - 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 "")) + short_key(kind, 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 "")) + if kind == "method" and t.name in auto_notes: + p(" auto watch: %s" % auto_notes[t.name]) mods = collections.defaultdict(lambda: [0.0, 0.0]) for t in totals.values(): if t.kind in ("tick-singleton", "update-singleton", "late-singleton"): @@ -976,7 +1006,7 @@ def compare(a, b, args, out): p(" %-58s %-22s %9s %9s %9s" % ("", "mod", "A ms/s", "B ms/s", "change")) for delta, k, va, vb, t in movers[:args.top]: note = " (only in B)" if k not in pa else " (only in A)" if k not in pb else "" - p(" %-58s %-22s %9.2f %9.2f %+9.2f%s" % ("[%s] %s" % (k[0].split("-")[0], short(k[1], 52)), (mod_of(a, t) or "")[:22], va, vb, delta, note)) + p(" %-58s %-22s %9.2f %9.2f %+9.2f%s" % ("[%s] %s" % (k[0].split("-")[0], short_key(k[0], k[1], 52)), (mod_of(a, t) or "")[:22], va, vb, delta, note)) mods = collections.defaultdict(lambda: [0.0, 0.0]) for k, t in pa.items(): if k[0] in ("tick-singleton", "update-singleton", "late-singleton"): @@ -1034,9 +1064,9 @@ def compare_pointers(a, b, Sa, Sb, diffs, cautions, rows, movers=()): gone = [(k, va_) for _, k, va_, vb_, t in movers if vb_ == 0 and va_ >= 0.5] added = [(k, vb_) for _, k, va_, vb_, t in movers if va_ == 0 and vb_ >= 0.5] if gone: - lines.append("Only A has these (the ones above 0.5 ms/s): " + "; ".join("%s (%.1f ms/s)" % (short(k[1], 48), v) for k, v in gone[:4]) + ". Time they took is time B does not spend.") + lines.append("Only A has these (the ones above 0.5 ms/s): " + "; ".join("%s (%.1f ms/s)" % (short_key(k[0], k[1], 48), v) for k, v in gone[:4]) + ". Time they took is time B does not spend.") if added: - lines.append("Only B has these (the ones above 0.5 ms/s): " + "; ".join("%s (%.1f ms/s)" % (short(k[1], 48), v) for k, v in added[:4]) + ". Time B spends that A does not.") + lines.append("Only B has these (the ones above 0.5 ms/s): " + "; ".join("%s (%.1f ms/s)" % (short_key(k[0], k[1], 48), v) for k, v in added[:4]) + ". Time B spends that A does not.") only_a = [m for m in a.mods if m not in b.mods] only_b = [m for m in b.mods if m not in a.mods] if only_a or only_b: diff --git a/tools/test_perflog.py b/tools/test_perflog.py index 4fe58fd..64c8e12 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -389,6 +389,12 @@ def test_change_and_short(self): self.assertEqual("-", perflog.change(0, 0)) 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")) + # A watched method keeps its class (a patch method is nearly always called Prefix or Postfix), and drops its parameters only if it must. + self.assertEqual("TickableEntityTickPatcher.Prefix(TickableEntity)", + perflog.short_method("BeaverBuddies.DeterminismService+TickableEntityTickPatcher.Prefix(TickableEntity)", 58)) + self.assertEqual("VeryLongClassNameForTesting.Method(...)", + perflog.short_method("A.B.VeryLongClassNameForTesting.Method(Int32,String,Boolean,Single,Double,Int64)", 40)) + self.assertEqual("Some.Mod.Method()", perflog.short_method("Some.Mod.Method()")) def test_steady_leaves_out_warm_up_paused_and_background(self): s = Synthetic() @@ -590,6 +596,28 @@ def test_a_watched_method_window_nobody_timed_is_not_counted_at_0_ms(self): text = self.report(s) self.assertRegex(text, r"Some\.Mod\.Method\(\).*\b500\.0 us/call.*\(\+40 calls never timed\)") + def test_auto_watched_patch_methods_say_which_hot_method_they_are_on(self): + s = Synthetic(header={"mod": "0.1.3"}) + # What the mod writes with AutoWatch = true: a # watch| line for each patch method it chose, and profile.csv rows named like a Watch entry + # (whose commas the CSV turns into ;). + entity = "BeaverBuddies.DeterminismService+TickableEntityTickPatcher.Prefix(TickableEntity)" + panel = "LateGamePerformance.UiThrottle.PanelPrefix(EntityPanel,Boolean)" + s.pipes.append(["watch", entity, "watching", "auto", "prefix on Timberborn.TickSystem.TickableEntity.Tick", "timbermods.BeaverBuddiesMultiColony"]) + s.pipes.append(["watch", panel, "watching", "auto", "prefix on Timberborn.EntityPanelSystem.EntityPanel.UpdateSingleton", "kyler.lategameperformance.UiThrottle"]) + s.pipes.append(["watch", "Some.Mod.Method()", "watching"]) + for w in range(1, 7): + s.window() + for i, (name, assembly) in enumerate(((entity, "BeaverBuddies"), (panel.replace(",", ";"), "LateGamePerformance"), ("Some.Mod.Method()", "SomeMod"))): + s.profile.append({"kind": "method", "window": w, "tick": s.tick, "id": 5 + i, "calls": 1000, "sampled": 50, "ms": 20.0 - i, "allocKB": 0, + "maxMs": 0.1, "name": name, "assembly": assembly, "mod": assembly.lower()}) + text = self.report(s) + # A patch method is named by its class, not only as "Prefix", and says which hot method it is on and whose patch it is. + self.assertIn("TickableEntityTickPatcher.Prefix(TickableEntity)", text) + self.assertIn("auto watch: prefix on Timberborn.TickSystem.TickableEntity.Tick (timbermods.BeaverBuddiesMultiColony)", text) + self.assertIn("auto watch: prefix on Timberborn.EntityPanelSystem.EntityPanel.UpdateSingleton (kyler.lategameperformance.UiThrottle)", text) + self.assertRegex(text, r"Some\.Mod\.Method\(\)") + self.assertEqual(2, text.count("auto watch: "), "a method the config's Watch named is not called an auto watch") + def test_loading_that_grew_the_heap_is_reported(self): s = Synthetic() for _ in range(6): From 6ea149834cc5fc91e1258425f5bfe266c08eb383 Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 08:37:03 -0700 Subject: [PATCH 2/3] AUTOWATCH: put the game's random state back after the auto watch patches Review found a co-op desync. The auto watch makes its Harmony patches at the first PostLoad, after BeaverBuddies has seeded UnityEngine.Random for the game (DeterminismService's constructor). Every Harmony.Patch builds a MonoMod DynamicMethodDefinition, whose field initializer calls Guid.NewGuid(), and BeaverBuddies' GuidPatcher turns each NewGuid into 16 draws from UnityEngine.Random, the state Timberborn's RandomNumberGenerator uses. So a player with AutoWatch = true (or with a different number of patches made) would start the first tick with a different random state. Watch.AutoInstall now reads Harmony's registry and makes every patch inside Watch.AroundAutoPatching, which in the game is KeepUnityRandom: it reads UnityEngine.Random.state before anything runs and writes it back in a finally, so the patches leave the game's random numbers exactly as they found them. If the state cannot be read, nothing is patched. The config Watch entries are patched at StartMod, before any seed, and are unchanged. CLAUDE.md now says that any patch after a game starts loading must run in that guard, and that nothing may be patched mid-game. Review follow-ups in the same change: - A prefix that returns bool (it can skip the method it patches) is marked "(can replace it)" in its # watch| line and the report, and README and SESSION-README say its time is work done instead of the game's. - perflog.py compare no longer counts a method only one side watched as time that side spends (its time is inside the row of what runs it); it says the Watch or AutoWatch settings differ, and notes [method] rows in section 4. The report's "no rows" line no longer blames Watch entries when only the auto watch was on. - summary.md names watched methods by Class.Method(...) (Summary. ShortMethod), as perflog.py already does. - The in-game settings note, Settings.cs and CLAUDE.md list AutoWatch among the cfg-only settings; README "Working with other mods" says what the auto watch adds. - AutoFinal and the docs say a never-seen method may be called only off the game thread. Tests: GameRandomIsKept (the default guard is KeepUnityRandom, whose IL reads the state before its try and writes it in its finally; every patch and the registry read happen inside the guard), EntriesKeepTheirSlots (Watch entries' slots and names through AutoInstall), and more checks in OrderIsByName (a patch method on several hot methods is placed by the first of them under 20 shuffles; the replace mark), PatchesAreExamined (bool prefix, Walker.Tick as a real component), WatchedPatchIsTimed (header lines, the never-called list), SummaryTests.ShortNames, and two test_perflog cases (AutoWatch off versus on in compare; the report's line without rows). C# 104 -> 106, Python 47 -> 49. Fixture README.md files regenerated for the SESSION-README text. Co-Authored-By: Claude Opus 5 --- CLAUDE.md | 7 +- README.md | 11 +- docs/SESSION-README.md | 7 +- docs/TESTING.md | 13 +- packaging/PerformanceLog.cfg | 3 +- source/Core/AutoWatch.cs | 13 +- source/Core/Summary.cs | 23 ++- source/Game/Session.cs | 3 +- source/Game/SessionService.cs | 2 +- source/Game/Settings.cs | 7 +- source/Game/Watch.cs | 57 ++++-- tests/AutoWatchTests.cs | 183 +++++++++++++++++++- tests/SummaryTests.cs | 9 +- tests/fixtures/sample-with-mod/README.md | 7 +- tests/fixtures/sample-without-mod/README.md | 7 +- tools/perflog.py | 16 +- tools/test_perflog.py | 39 ++++- 17 files changed, 360 insertions(+), 47 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 787e539..42a82a0 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -96,7 +96,7 @@ To read the game's own code (the way every patch target here was checked): `ilsp (`ProfileTests.NoAliasing`). - **`Columns` is initialised in textual order** (C# static field initialisers). Declare arrays before the groups that use them. - **Only some settings can live in the in-game Mod Settings menu** (`Settings.cs`, `PerformanceSettings`). `Plugin.StartMod` reads `PerformanceLog.cfg` - and decides `Enabled`/`Profile`/`Watch` (which Harmony patches get made, including whether the entity tick is patched at all) before Bindito, and so + and decides `Enabled`/`Profile`/`Watch`/`AutoWatch` (which Harmony patches get made, including whether the entity tick is patched at all) before Bindito, and so Mod Settings, exists; making those live would mean re-patching the game while it runs or always paying for the entity-tick patch even when `Profile = off` asks not to. Only the six numbers `Session.Start` reads fresh each session (`SlowFrameMs`, `SummarySeconds`, `ProfileSeconds`, `OverheadBudgetPercent`, `SpikeContributors`, `MaxSlowRowsPerMinute`) are in the menu; `SessionService.PostLoad` calls `PerformanceSettings.ApplyTo` to fold them onto `Plugin.Config` @@ -107,6 +107,11 @@ To read the game's own code (the way every patch target here was checked): `ilsp nothing ticks yet. It only adds this mod's own prefix and postfix (id `kyler.performancelog.watch`) around another mod's patch method; it never unpatches, reorders or changes anyone else's patch. Which methods it takes is decided in `AutoWatch.Plan` (pure, tested in `AutoWatchTests`): name order, not time, because ranking by what the recording measured would mean patching while the game runs. +- **Under BeaverBuddies, making a Harmony patch draws from the game's random numbers.** Every `Harmony.Patch` builds a MonoMod `DynamicMethodDefinition`, + which calls `Guid.NewGuid()`, and BeaverBuddies' `GuidPatcher` turns each `Guid.NewGuid()` into 16 draws from `UnityEngine.Random`, the state the + simulation's `RandomNumberGenerator` uses and that BeaverBuddies seeds when a game loads. Patching at `StartMod` is harmless (the seed comes later); + any patch made after a game has started loading must run inside `Watch.KeepUnityRandom` (which puts `UnityEngine.Random.state` back as it was), or + one player's random numbers move and co-op desyncs. Never patch mid-game, not even with that guard (it is only proven at load, before the first tick). - Colony and memory columns are read only when a row is written and carried over otherwise (`lastHeavy` in `Probe`). - The tests run each check on a thread-pool thread, and `Probe` is static and remembers the game thread's id: every check that uses it goes through `Rig` in `CoreTests.cs`. diff --git a/README.md b/README.md index e6260c6..3ada5dd 100644 --- a/README.md +++ b/README.md @@ -112,14 +112,21 @@ method and tagged with its mod, and a `# watch|...|auto|...` line in the `frames 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 -runtime, where no watch can see it (`# capability-final|autoWatch|` lists any that were never seen called). +runtime, where no watch can see it (`# capability-final|autoWatch|` lists any that were never seen called). A prefix marked `(can replace it)` may skip +the game's method and do its work itself, so its time is that work done instead of the game's, not on top of it. + +With BeaverBuddies, making any Harmony patch uses up some of the game's random numbers (BeaverBuddies makes `Guid.NewGuid` draw from them, and Harmony +calls it for every patch), and the auto watch patches after the game has been seeded for co-op. It therefore puts the random state back exactly as it +was once its patches are made, so the game plays out the same with it on or off and co-op players may still set it differently. That is reasoned from +the code and not yet seen in a two-player game (`docs/TESTING.md`, item 10). ## Working with other mods The mod puts a timing wrapper in front of each of the game's singletons, but only on the first tick and first frame of a game, after every other mod's `Load` patches have run, so a mod that looks at those singletons (BeaverBuddies reorders the once-per-tick ones by their type) still sees the game's own and tick order is what it would be without this mod. It never replaces a game method and never skips the original. When another mod defers the game's save to the end of a tick (BeaverBuddies does), the `queued save` event reads about 0 ms and the real one is the `save (writing the world)` -event. +event. With `AutoWatch = true` it also puts its own timing prefix and postfix (Harmony id `kyler.performancelog.watch`) around other mods' patch methods on hot methods, when the +first game loads; the other mods' patches, and the order they run in, stay as they were. ## What it costs, and what it cannot see diff --git a/docs/SESSION-README.md b/docs/SESSION-README.md index 9b88b53..7699dcd 100644 --- a/docs/SESSION-README.md +++ b/docs/SESSION-README.md @@ -91,8 +91,11 @@ Start by writing down what the complaint is, because the causes differ: `Tick`, `UpdateSingleton`, `LateUpdateSingleton` or `StartParallelTick`, an entity's or component's `Tick`, whose time is otherwise inside a row that names the game or the singleton's own mod), then the rest of the hot methods, in name order, in the Watch slots the config's `Watch` entries left (40 in all); the `# watch|` lines of the ones left out say why. A patch method's time is inside the row of what it patches, so do not add the two. - One that `# capability-final|autoWatch|` lists as never seen called was either not called or so small that the runtime copied it into the method it - patches, where no watch can see it: a missing row there is not a measurement of 0. + One that `# capability-final|autoWatch|` lists as never seen called was either not called, called only off the game thread (the watch times the game + thread only), or so small that the runtime copied it into the method it patches, where no watch can see it: a missing row there is not a measurement of 0. + A `# watch|` line that says `(can replace it)` is a prefix that returns a bool: when it returns false the game's own method does not run, and the + prefix's row holds the work it did instead, so that time is the mod doing the game's job, not cost on top of it (compare a recording without that + mod to see what it saves or costs in all). A prefix that replaces a tick loop (`TickableBucketService.TickBuckets`, say) holds nearly the whole tick. - To be sure it is a mod, **compare two recordings** of the same save at the same speed with and without it: `python tools/perflog.py compare ` (in the Performance Log repository). Say what else differed. diff --git a/docs/TESTING.md b/docs/TESTING.md index e716730..facdcf3 100644 --- a/docs/TESTING.md +++ b/docs/TESTING.md @@ -6,7 +6,7 @@ the game running. This is the honest list. ## Verified by the automated checks -`dotnet run --project tests -c Release` (104 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (47 checks). +`dotnet run --project tests -c Release` (106 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (49 checks). | What | How | |---|---| @@ -26,7 +26,7 @@ the game running. This is the honest list. | 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; the report names each by its class and the hot method it is on | `AutoWatchTests`, `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; 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` | @@ -93,7 +93,14 @@ heap and is coarse**. The per-singleton `KB/s` figures are therefore only good i patch methods...` with N > 0 and no warning, that the `frames.csv` header has `# capability|autoWatch|watching ...` and a `# watch|...|watching|auto|...` line per method, that `profile.csv` has `method` rows for them (BeaverBuddies' `TickableEntityTickPatcher.Prefix` should be one of the busiest), that `# capability-final|autoWatch|` says most of them were called, and what `overheadUs` costs compared with the same save with `AutoWatch = false`. A patch - method listed there as never seen called is either not called or inlined by the runtime into the method it patches, which no watch can see. + method listed there as never seen called is either not called, called only off the game thread, or inlined by the runtime into the method it patches, + which no watch can see. A row whose `# watch|` line says `(can replace it)` is a prefix that may skip the game's method and do the work itself. + +10. **`AutoWatch` in co-op (not yet played)**: under BeaverBuddies every Harmony patch draws from the game's random numbers (MonoMod's + `DynamicMethodDefinition` calls `Guid.NewGuid`, which BeaverBuddies routes through `UnityEngine.Random`), and the auto watch patches after BeaverBuddies + has seeded them for the game. `Watch.KeepUnityRandom` puts the state back, so the game should play out the same; that is reasoned from the code, not seen. + Play two players connected with BeaverBuddies for 10 minutes or more, with `AutoWatch = true` for one player only (the case a difference would show + first), some of it at speed 3 or more, including a save: there must be no desync, and BeaverBuddies' own behaviour and `Player.log` must be as without it. ## Five-minute check in a game diff --git a/packaging/PerformanceLog.cfg b/packaging/PerformanceLog.cfg index 9ab35ab..54ca10d 100644 --- a/packaging/PerformanceLog.cfg +++ b/packaging/PerformanceLog.cfg @@ -55,5 +55,6 @@ OutputFolder = # runs inside a game row (a prefix on every entity's tick, say) is seen. It fills the Watch slots the Watch lines above leave free (40 methods in # all): first patches on the per-tick and per-frame methods of singletons, entities and components, then those on the other hot methods, in # name order; the frames.csv header lists what it took and what it left out. It adds only its own timing patch around each patch method, when -# the first game is loaded, and changes no other mod's patch. Off by default: every call of a watched method costs a little (see overheadUs). +# the first game is loaded, changes no other mod's patch, and leaves the game's random numbers as it found them (BeaverBuddies co-op). +# Off by default: every call of a watched method costs a little (see overheadUs). AutoWatch = false diff --git a/source/Core/AutoWatch.cs b/source/Core/AutoWatch.cs index 78d33dd..c335a1a 100644 --- a/source/Core/AutoWatch.cs +++ b/source/Core/AutoWatch.cs @@ -25,6 +25,11 @@ public sealed class AutoWatchCandidate /// entity's or component's Tick. A patch there is inside that row, which names the game or the singleton's own mod, not the patching mod. /// public bool ProfileRow; + /// + /// A prefix that returns bool: it can return false and skip the method it patches (and every later prefix), doing that work itself. + /// Its time is then work done instead of the game's, not on top of it. + /// + public bool CanReplace; /// Why the patch method cannot be watched, said the way Watch says it for a config entry; null if it can be. public string Refused; /// The game side's handle on the patch method. Carried through, never read here. @@ -36,7 +41,10 @@ public sealed class AutoWatchResult { /// The patch (the first in the order, when the patch method is on several hot methods). public AutoWatchCandidate Candidate; - /// Every hot method the patch method is on, as "prefix on Namespace.Type.Method", joined with "; ". + /// + /// Every hot method the patch method is on, as "prefix on Namespace.Type.Method", joined with "; ". A prefix that can skip the method + /// it patches (it returns bool) says so: "prefix on Namespace.Type.Method (can replace it)". + /// public string On; /// "watching", or why not. public string Status; @@ -48,6 +56,7 @@ public static class AutoWatch public const string Watching = "watching"; public const string NamedByWatch = "watched by a Watch entry"; public const string NoFreeSlot = "skipped: no free Watch slot"; + public const string CanReplaceNote = "(can replace it)"; sealed class Group { @@ -82,7 +91,7 @@ public static List Plan(IEnumerable patches int tier = c.ProfileRow ? 0 : PatchFormat.IsHot(c.TypeName, c.MethodName) ? 1 : -1; if (tier < 0) continue; if (!groups.TryGetValue(c.Label, out Group g)) groups[c.Label] = g = new Group { Label = c.Label, Tier = int.MaxValue }; - g.On.Add(c.Kind + " on " + c.Target); + g.On.Add(c.Kind + " on " + c.Target + (c.CanReplace && kindOrder == 0 ? " " + CanReplaceNote : "")); if (Before(c, tier, kindOrder, g)) { g.First = c; g.Tier = tier; g.KindOrder = kindOrder; } // Why a patch method cannot be watched does not depend on the hot method it is on; if the records disagree, the same one is kept whatever their order. if (c.Refused != null && (g.Refused == null || string.CompareOrdinal(c.Refused, g.Refused) < 0)) g.Refused = c.Refused; diff --git a/source/Core/Summary.cs b/source/Core/Summary.cs index 481deac..90b0dd9 100644 --- a/source/Core/Summary.cs +++ b/source/Core/Summary.cs @@ -277,7 +277,7 @@ void Table(string title, Func where, int take) double all = s.Totals.Where(where).Sum(x => x.Ms); t.Append("**").Append(title).Append("** (together ").Append(F(all / seconds)).Append(" ms/s)\n\n| Name | Mod | ms/s | Share | calls/s | us per call | KB/s | slowest call ms |\n|---|---|---|---|---|---|---|---|\n"); foreach (Profile.Total x in rows) - t.Append("| `").Append(Short(x.Name)).Append("` | ").Append(x.Mod).Append(" | ").Append(F(x.Ms / seconds, 2)).Append(" | ").Append(Pct(x.Ms, all)).Append(" | ") + t.Append("| `").Append(x.Kind == ProfileKind.Method ? ShortMethod(x.Name) : Short(x.Name)).Append("` | ").Append(x.Mod).Append(" | ").Append(F(x.Ms / seconds, 2)).Append(" | ").Append(Pct(x.Ms, all)).Append(" | ") .Append(F(x.Calls / seconds, 0)).Append(" | ").Append(x.Calls > 0 ? F(x.Ms * 1000 / x.Calls, 1) : "").Append(" | ").Append(F(x.Kb / seconds, 1)).Append(" | ").Append(F(x.MaxMs, 2)).Append(" |\n"); t.Append('\n'); } @@ -381,6 +381,27 @@ public static string Short(string name) return tail.Length > 60 ? tail.Substring(0, 60) : tail; } + /// + /// A watched method's name (Namespace.Type.Method(Parameters)) cut, when it is long, to Type.Method(Parameters), keeping the class: + /// an auto-watched patch method is nearly always called Prefix or Postfix, so the method's own name alone says nothing. The + /// parameters become "(...)" only if the name is still too long. The same rule as short_method in tools/perflog.py. + /// + public static string ShortMethod(string name) + { + if (string.IsNullOrEmpty(name)) return "?"; + if (name.Length <= 48) return name; + int paren = name.IndexOf('('); + string head = paren >= 0 ? name.Substring(0, paren) : name, parameters = paren >= 0 ? name.Substring(paren) : ""; + string[] parts = head.Split('.'); + string cls = parts.Length >= 2 ? parts[parts.Length - 2] : ""; + int plus = cls.LastIndexOf('+'); + if (plus >= 0) cls = cls.Substring(plus + 1); + string method = (cls.Length > 0 ? cls + "." : "") + parts[parts.Length - 1]; + string shorter = method + parameters; + if (shorter.Length > 60 && paren >= 0) shorter = method + "(...)"; + return shorter.Length > 60 ? shorter.Substring(0, 60) : shorter; + } + /// /// The frame time below which the fraction of the frames fell, worked out from the histogram /// (linear inside a bucket). The last bucket is open at the top, so stands in for its upper edge. diff --git a/source/Game/Session.cs b/source/Game/Session.cs index 6d50c6b..3e286ce 100644 --- a/source/Game/Session.cs +++ b/source/Game/Session.cs @@ -64,7 +64,8 @@ internal static void Start(Config cfg, SessionServices context, string modVersio Instrumentation.ResetForSession(); // The one moment for the auto watch's patches: every mod has started and the game has loaded, so Harmony's registry holds // the patches it looks for, and nothing ticks yet. Only the first log makes them; they stay for the next save, as the Watch - // entries' do. Before the header is written, which lists them. + // entries' do. Before the header is written, which lists them. BeaverBuddies has already seeded the game's random numbers + // by now, and making a patch draws from them under BeaverBuddies; AutoInstall puts them back (Watch.KeepUnityRandom). if (cfg.AutoWatch) { Watch.AutoInstall(); diff --git a/source/Game/SessionService.cs b/source/Game/SessionService.cs index 30fbb39..0881533 100644 --- a/source/Game/SessionService.cs +++ b/source/Game/SessionService.cs @@ -39,7 +39,7 @@ public void PostLoad() Milestones.Mark("post-load"); try { - // The six numbers the in-game settings panel controls (Settings.cs); Enabled/Profile/Watch/OutputFolder came from + // The six numbers the in-game settings panel controls (Settings.cs); Enabled/Profile/Watch/AutoWatch/OutputFolder came from // PerformanceLog.cfg already, at StartMod, and are untouched here. settings?.ApplyTo(Plugin.Config); Session.Start(Plugin.Config, new SessionServices diff --git a/source/Game/Settings.cs b/source/Game/Settings.cs index d85aa1a..d359568 100644 --- a/source/Game/Settings.cs +++ b/source/Game/Settings.cs @@ -10,8 +10,9 @@ namespace PerformanceLog /// /// The in-game settings page (the Mod Settings mod, a required dependency). Only the six numbers reads /// fresh at the start of every session are here, because they are the only ones that can change without restarting Timberborn: - /// , and decide which Harmony patches this mod - /// makes, in , which runs before Bindito (and so before Mod Settings) exists, so those three and + /// , , and decide which + /// Harmony patches this mod makes, from the config reads before Bindito (and so before Mod Settings) + /// exists (the auto watch's patches are made when the first game loads, once per run of the game), so those four and /// (a folder path; Mod Settings has no free-text widget that works with the game's own settings /// storage) stay in PerformanceLog.cfg only. This class is the only place that touches Mod Settings types, so nothing else /// depends on that assembly being loadable (it always is: a required mod). @@ -19,7 +20,7 @@ namespace PerformanceLog public class PerformanceSettings : ModSettingsOwner { public ReadonlyTextModSetting Note { get; } = new ReadonlyTextModSetting( - ModSettingDescriptor.Create("Enabled, Profile, Watch and OutputFolder are set in PerformanceLog.cfg, next to this mod's manifest, " + + ModSettingDescriptor.Create("Enabled, Profile, Watch, AutoWatch and OutputFolder are set in PerformanceLog.cfg, next to this mod's manifest, " + "and need Timberborn restarted (they decide which parts of the game get patched, before this menu exists). Everything below " + "applies to the next game or save you load."), new ReadonlyTextModSetting.TextSettings()); diff --git a/source/Game/Watch.cs b/source/Game/Watch.cs index 393989e..26119db 100644 --- a/source/Game/Watch.cs +++ b/source/Game/Watch.cs @@ -162,7 +162,8 @@ internal static void WatchPostfix(MethodBase __originalMethod, Sample __state) /// entries' do). Called when the first log starts: every mod has started and the game has loaded, so Harmony's registry holds the /// patches other mods make at start-up and while a game loads, and nothing ticks yet (no tick or parallel tick is running a patch /// method; only a thread another mod runs of its own could be). A patch another mod makes later is not seen. Only this mod's own - /// patches are added; nothing of any other patch is removed, reordered or changed. + /// patches are added; nothing of any other patch is removed, reordered or changed. All of it runs inside + /// , which leaves the game's random state as it found it (see there: this is what keeps co-op in step). /// internal static void AutoInstall() { @@ -170,7 +171,7 @@ internal static void AutoInstall() autoTried = true; try { - AutoInstall(AutoCandidates(), Patch); + AutoInstall(AutoCandidates, Patch); Log.Info("Auto watch: " + AutoWatch.Describe(autoResults) + "."); } catch (Exception e) @@ -180,19 +181,48 @@ internal static void AutoInstall() } } - /// Plans the auto watch over these patches and watches what it chooses, patching each with (null, or why not). - internal static void AutoInstall(List candidates, Func patch) + /// + /// Plans the auto watch over these patches and watches what it chooses, patching each with (null, or why + /// not). The patches are read and made inside . + /// + internal static void AutoInstall(Func> candidates, Func patch) { - var named = new HashSet(watched.Select(w => w.Name), StringComparer.Ordinal); - autoResults = AutoWatch.Plan(candidates, Instrumentation.HarmonyId, named, Config.MaxWatched - watched.Count, c => + AroundAutoPatching(() => { - if (!(c.Method is MethodBase method)) return "the patch method could not be found"; - string failure = patch(method); - if (failure == null) watched.Add(new Watched { Method = method, Name = c.Label, Assembly = c.Assembly, Auto = true }); - return failure; + var named = new HashSet(watched.Select(w => w.Name), StringComparer.Ordinal); + autoResults = AutoWatch.Plan(candidates(), Instrumentation.HarmonyId, named, Config.MaxWatched - watched.Count, c => + { + if (!(c.Method is MethodBase method)) return "the patch method could not be found"; + string failure = patch(method); + if (failure == null) watched.Add(new Watched { Method = method, Name = c.Label, Assembly = c.Assembly, Auto = true }); + return failure; + }); }); } + /// + /// Runs the auto watch's patching. In the game it is ; a test replaces it for a while (and puts it + /// back), because Unity's random state cannot be read outside the game. + /// + internal static Action AroundAutoPatching = KeepUnityRandom; + + /// + /// Runs and then puts UnityEngine.Random's state back exactly as it was, even if it throws. + /// Every Harmony.Patch builds a MonoMod DynamicMethodDefinition, whose field initializer calls Guid.NewGuid(), + /// and BeaverBuddies (its GuidPatcher) turns every Guid.NewGuid() into 16 draws from UnityEngine.Random, the + /// state Timberborn's RandomNumberGenerator uses for the simulation. When the first log starts, BeaverBuddies has already + /// seeded that state for the game (in DeterminismService's constructor), so without this a player with AutoWatch = true, or + /// with a different number of patches made, would enter the first tick with a different random state from the other players: a + /// co-op desync. The Watch entries' patches are made at StartMod, before any game seeds it, so they need no such care. If the + /// state cannot be read, nothing is patched. + /// + static void KeepUnityRandom(Action patching) + { + UnityEngine.Random.State state = UnityEngine.Random.state; + try { patching(); } + finally { UnityEngine.Random.state = state; } + } + /// Every prefix, postfix and finalizer in Harmony's registry on a method that runs behind a profile row or is on the hot list. static List AutoCandidates() { @@ -235,6 +265,7 @@ internal static AutoWatchCandidate Examine(MethodBase target, string kind, strin c.Assembly = type.Assembly.GetName().Name; c.Method = patchMethod; c.Refused = Refusal(patchMethod); + c.CanReplace = kind == "prefix" && patchMethod.ReturnType == typeof(bool); // Harmony hands its patches the method they are on as MethodBase.GetMethodFromHandle gives it, so that is the key the watch // looks up; the MethodInfo in Harmony's registry is the same method, but may be a different object. if (c.Refused == null && !type.IsGenericType) c.Method = MethodBase.GetMethodFromHandle(patchMethod.MethodHandle) ?? patchMethod; @@ -297,7 +328,7 @@ internal static string AutoFinal() if (autoResults == null && auto == 0) return autoFailure != null ? "could not run: " + autoFailure : "off"; string text = (auto - never.Count) + " of " + auto + " watched patch methods were called"; if (never.Count > 0) - text += "|never seen called (not called, or so small that the runtime copied it into the method it patches, where no watch sees it): " + string.Join("; ", never.Take(12)) + + text += "|never seen called (not called, called only off the game thread, or so small that the runtime copied it into the method it patches, where no watch sees it): " + string.Join("; ", never.Take(12)) + (never.Count > 12 ? "; and " + (never.Count - 12) + " more" : ""); return text; } @@ -309,5 +340,9 @@ internal static void ResetForTest() ids = new Dictionary(); autoTried = false; autoFailure = null; autoResults = null; } + + /// Test-only: a method watched the way a Watch entry's is after has patched it. + internal static void AddEntryForTest(MethodBase method, string name, string assembly) => + watched.Add(new Watched { Method = method, Name = name, Assembly = assembly }); } } diff --git a/tests/AutoWatchTests.cs b/tests/AutoWatchTests.cs index 04ea5d9..0778b55 100644 --- a/tests/AutoWatchTests.cs +++ b/tests/AutoWatchTests.cs @@ -2,6 +2,7 @@ using System.Collections.Generic; using System.Linq; using System.Reflection; +using System.Reflection.Emit; using HarmonyLib; using Timberborn.SingletonSystem; using Timberborn.TickSystem; @@ -21,6 +22,8 @@ internal static class AutoWatchTests yield return ("AutoWatch: the choice is in name order whatever order Harmony lists the patches in, the methods behind the profile's rows first", OrderIsByName); yield return ("AutoWatch: a patch is examined the way a Watch entry is, and the methods behind the profile's rows are recognised", PatchesAreExamined); yield return ("AutoWatch: a watched patch method is registered with the log, counted and timed, and its watch allocates nothing", WatchedPatchIsTimed); + yield return ("AutoWatch: the patches are made in the slots the Watch entries left, never on a method one of them watches", EntriesKeepTheirSlots); + yield return ("AutoWatch: every patch is made inside the guard that puts the game's random state back (co-op stays in step)", GameRandomIsKept); } const string Own = "kyler.performancelog"; @@ -35,7 +38,7 @@ internal static class AutoWatchTests const string Visuals = "Timberborn.StockpileVisualization.StockpileVisualizers.OnInventoryChanged"; /// One patch as the game side reports it. The assembly is the label's first part, the owner made up from it unless given. - static AutoWatchCandidate C(string label, string kind, string target, bool row = false, string owner = null, string refused = null) + static AutoWatchCandidate C(string label, string kind, string target, bool row = false, string owner = null, string refused = null, bool replaces = false) { int dot = target.LastIndexOf('.'); string type = target.Substring(0, dot); @@ -44,7 +47,7 @@ static AutoWatchCandidate C(string label, string kind, string target, bool row = { Label = label, Assembly = assembly, Owner = owner ?? assembly.ToLowerInvariant() + ".mod", Kind = kind, TypeName = type.Substring(type.LastIndexOf('.') + 1), MethodName = target.Substring(dot + 1), Target = target, - ProfileRow = row, Refused = refused, Method = label, + ProfileRow = row, Refused = refused, Method = label, CanReplace = replaces, }; } @@ -57,7 +60,7 @@ static AutoWatchCandidate C(string label, string kind, string target, bool row = C("BB.DistrictFix.Finalizer(Exception)", "finalizer", Connected), C("BB.DistrictFix.Finalizer(Exception)", "finalizer", ConnectedWith), C("LGP.UiThrottle.PanelPrefix()", "prefix", Panel, row: true, owner: "kyler.lategameperformance.UiThrottle"), - C("LGP.Timing.UpdatePrefix()", "prefix", TickerUpdate, owner: "kyler.lategameperformance.Timing"), + C("LGP.Timing.UpdatePrefix()", "prefix", TickerUpdate, owner: "kyler.lategameperformance.Timing", replaces: true), C("MS.TextEditingInputPatch.Finalizer(Exception)", "finalizer", Input, row: true), C("MS.TextEditingInputPatch.Prefix()", "prefix", Input, row: true), // Never taken: this mod's own patches (its measuring and its watch), a transpiler (it runs once, when the patch is made, so @@ -136,6 +139,8 @@ static void OrderIsByName() Equal("finalizer on " + Connected + "; finalizer on " + ConnectedWith, first.Single(r => r.Candidate.Label == "BB.DistrictFix.Finalizer(Exception)").On, "one watch for a patch method on two hot methods, naming both"); Equal("prefix on " + EntityTick, first.Single(r => r.Candidate.Label == "BB.EntityPatch.Prefix(TickableEntity)").On); + Equal("prefix on " + TickerUpdate + " (can replace it)", first.Single(r => r.Candidate.Label == "LGP.Timing.UpdatePrefix()").On, + "a prefix that can skip the method it patches says so, since its time is then work done instead of the game's"); string[] expected = first.Select(r => r.Candidate.Label + "|" + r.Status + "|" + r.On).ToArray(); var random = new Random(7); for (int round = 0; round < 20; round++) @@ -147,6 +152,40 @@ static void OrderIsByName() // With fewer slots it is the front of the same order that is taken. List five = AutoWatch.Plan(Patches().AsEnumerable().Reverse(), Own, new List(), 5, c => null); Check(five.Where(r => r.Watching).Select(r => r.Candidate.Label).SequenceEqual(Expected.Take(5)), Labels(five)); + + // A patch method on several hot methods is placed by the first of them in that same order, whichever Harmony lists first: one on + // a method behind a profile row and on a hot-list method whose name sorts first goes with the rows, and one on two row methods + // goes with the one whose name sorts first. + var several = new List + { + C("BB.Both.Prefix()", "prefix", Range), + C("BB.Both.Prefix()", "prefix", EntityTick, row: true), + C("BB.Two.Postfix()", "postfix", Input, row: true), + C("BB.Two.Postfix()", "postfix", Panel, row: true), + }; + string[] expectedSeveral = + { + "LGP.UiThrottle.PanelPrefix()", + "BB.Two.Postfix()", + "MS.TextEditingInputPatch.Prefix()", + "MS.TextEditingInputPatch.Finalizer(Exception)", + "BB.Both.Prefix()", + "BB.EntityPatch.Prefix(TickableEntity)", + "BB.EntityPatch.Postfix(TickableEntity)", + "BB.RandomPatch.Prefix(Int32,Int32)", + "BB.DistrictFix.Finalizer(Exception)", + "LGP.Timing.UpdatePrefix()", + }; + for (int round = 0; round < 20; round++) + { + List shuffled = Patches().Concat(several).OrderBy(_ => random.Next()).ToList(); + List placed = AutoWatch.Plan(shuffled, Own, new List(), Config.MaxWatched, c => null); + Check(placed.Select(r => r.Candidate.Label).SequenceEqual(expectedSeveral), "placed by its first hot method: " + Labels(placed)); + AutoWatchResult both = placed.Single(r => r.Candidate.Label == "BB.Both.Prefix()"); + Equal(EntityTick, both.Candidate.Target, "the patch that places it"); + Equal("prefix on " + Range + "; prefix on " + EntityTick, both.On); + Equal(Panel, placed.Single(r => r.Candidate.Label == "BB.Two.Postfix()").Candidate.Target); + } } // ---- the game side ---- @@ -163,7 +202,13 @@ static void PatchesAreExamined() Equal("TickableEntity", c.TypeName); Equal("Tick", c.MethodName); Equal(EntityTick, c.Target); Check(c.ProfileRow, "TickableEntity.Tick is what the entity rows time"); Check(c.Refused == null, "a plain static method can be watched: " + c.Refused); - Check(Equals(MethodBase.GetMethodFromHandle(prefix.MethodHandle), c.Method), "the key is the method Harmony hands a patch as __originalMethod"); + Check(Equals(MethodBase.GetMethodFromHandle(prefix.MethodHandle), c.Method), + "the key is the method as MethodBase.GetMethodFromHandle gives it, which is what Harmony hands a patch as __originalMethod " + + "(on .NET 8 that is the registry's own object anyway; only the game's Mono could tell them apart, see TESTING.md)"); + Check(!c.CanReplace, "a prefix that returns nothing cannot skip the method it patches"); + MethodInfo skip = typeof(AutoWatchFakePatches).GetMethod(nameof(AutoWatchFakePatches.Skip)); + Check(Watch.Examine(entityTick, "prefix", "other.mod", skip).CanReplace, "a prefix that returns bool can skip the method it patches"); + Check(!Watch.Examine(entityTick, "postfix", "other.mod", skip).CanReplace, "a postfix never can"); MethodInfo generic = typeof(AutoWatchFakePatches).GetMethod(nameof(AutoWatchFakePatches.Generic)); Check((Watch.Examine(entityTick, "postfix", "other.mod", generic).Refused ?? "").Contains("abstract or generic")); @@ -178,6 +223,10 @@ static void PatchesAreExamined() Check(Watch.RunsBehindAProfileRow(typeof(AutoWatchFakeParallel).GetMethod("StartParallelTick")), "IParallelTickableSingleton.StartParallelTick"); Check(Watch.RunsBehindAProfileRow(entityTick), "TickableEntity.Tick"); Check(Watch.RunsBehindAProfileRow(typeof(MeteredTickableComponent).GetMethod("Tick")), "MeteredTickableComponent.Tick"); + Type walker = Assembly.Load("Timberborn.WalkingSystem").GetType("Timberborn.WalkingSystem.Walker", true); + Check(typeof(TickableComponent).IsAssignableFrom(walker), "Walker is one of the game's own components"); + Check(Watch.RunsBehindAProfileRow(walker.GetMethod("Tick", BindingFlags.Instance | BindingFlags.Public, null, Type.EmptyTypes, null)), + "a component's own Tick (Walker.Tick): the component rows time it"); Check(!Watch.RunsBehindAProfileRow(typeof(Ticker).GetMethod("Update")), "Ticker.Update is on the hot list, not behind a row"); Check(!Watch.RunsBehindAProfileRow(typeof(AutoWatchFakeTickable).GetMethod("Tock")), "another method of a singleton"); Check(!Watch.RunsBehindAProfileRow(typeof(AutoWatchFakePatches).GetMethod(nameof(AutoWatchFakePatches.Tick))), "a static Tick of a class that is no singleton"); @@ -187,20 +236,36 @@ static void PatchesAreExamined() static void WatchedPatchIsTimed() { var rig = new Rig(); + Action guard = Watch.AroundAutoPatching; try { Watch.ResetForTest(); MethodInfo entityTick = typeof(TickableEntity).GetMethod("Tick", BindingFlags.Instance | BindingFlags.Public); MethodInfo prefix = typeof(AutoWatchFakePatches).GetMethod(nameof(AutoWatchFakePatches.Prefix)); MethodInfo refused = typeof(AutoWatchFakePatches).GetMethod(nameof(AutoWatchFakePatches.Generic)); + MethodInfo unused = typeof(AutoWatchFakePatches).GetMethod(nameof(AutoWatchFakePatches.Unused)); var patched = new List(); - Watch.AutoInstall(new List + Watch.AroundAutoPatching = run => run(); // Unity's random state cannot be read here; GameRandomIsKept checks the real guard + Watch.AutoInstall(() => new List { Watch.Examine(entityTick, "prefix", "other.mod", prefix), Watch.Examine(entityTick, "postfix", "other.mod", refused), + Watch.Examine(entityTick, "postfix", "other.mod", unused), }, m => { patched.Add(m); return null; }); - Equal(1, patched.Count, "only the method that can be watched is patched"); - Equal(1, Watch.Count); + Equal(2, patched.Count, "only the methods that can be watched are patched"); + Equal(2, Watch.Count); + + // What the header says: one capability line, and a # watch| line per patch method (label, status, auto, what it is on, owner), + // in the order perflog.py reads them. + string capability = Watch.AutoCapability(new Config { AutoWatch = true }); + Check(capability.StartsWith("watching 2 of 3 patch methods other mods put on hot methods") && capability.Contains("1 refused or could not be patched"), capability); + Check(Watch.AutoCapability(new Config()).StartsWith("off"), "AutoWatch = false says off"); + List lines = Watch.AutoLines().ToList(); + Equal(3, lines.Count, "a # watch| line for each patch method, the refused one too"); + Check(lines[0].SequenceEqual(new[] { "PerformanceLog.Tests.AutoWatchFakePatches.Prefix(Int32,String)", "watching", "auto", "prefix on " + EntityTick, "other.mod" }), + string.Join("|", lines[0])); + Check(lines[1][0].EndsWith(".Generic()") && lines[1][1].Contains("abstract or generic") && lines[1][2] == "auto", string.Join("|", lines[1])); + Check(lines[2][0].EndsWith(".Unused()") && lines[2][1] == "watching" && lines[2][3] == "postfix on " + EntityTick, string.Join("|", lines[2])); Watch.OnSessionStart(); // what Session.Start does once the profile is reset // Harmony hands the patch the method it is on, as MethodBase.GetMethodFromHandle gives it. @@ -214,10 +279,12 @@ static void WatchedPatchIsTimed() Watch.WatchPostfix(original, s); } Equal(0L, GC.GetAllocatedBytesForCurrentThread() - before, "bytes allocated by 2000 calls of a watched patch method"); - Check(Watch.AutoFinal().StartsWith("1 of 1 "), "the end of the log says the watched patch method ran: " + Watch.AutoFinal()); + string final = Watch.AutoFinal(); + Check(final.StartsWith("1 of 2 watched patch methods were called|never seen called"), "the end of the log says which ran and which never did: " + final); + Check(final.EndsWith(": PerformanceLog.Tests.AutoWatchFakePatches.Unused()"), "the one never called is named: " + final); Profile.FlushWindow(1, 0, 10, rig.Prof); - double[] row = rig.ProfileRows().Single(r => (ProfileKind)(int)r[0] == ProfileKind.Method); + double[] row = rig.ProfileRows().Single(r => (ProfileKind)(int)r[0] == ProfileKind.Method && r[4] > 0); Equal(2100.0, row[4], "every call counted"); Check(row[5] >= 1 && row[6] > 0, "some calls timed"); Equal("PerformanceLog.Tests.AutoWatchFakePatches.Prefix(Int32,String)", Profile.NameOf((int)row[3])); @@ -226,9 +293,104 @@ static void WatchedPatchIsTimed() finally { Watch.ResetForTest(); + Watch.AroundAutoPatching = guard; rig.Dispose(); } } + + static void EntriesKeepTheirSlots() + { + Action guard = Watch.AroundAutoPatching; + try + { + Watch.ResetForTest(); + Watch.AroundAutoPatching = run => run(); + MethodInfo entityTick = typeof(TickableEntity).GetMethod("Tick", BindingFlags.Instance | BindingFlags.Public); + MethodInfo prefix = typeof(AutoWatchFakePatches).GetMethod(nameof(AutoWatchFakePatches.Prefix)); + // The Watch entries resolved to 38 methods, one of them a patch method the auto watch finds, so 2 slots are left. + AutoWatchCandidate named = Watch.Examine(entityTick, "prefix", "other.mod", prefix); + Watch.AddEntryForTest((MethodBase)named.Method, named.Label, named.Assembly); + for (int i = 1; i < 38; i++) Watch.AddEntryForTest(entityTick, "Some.Mod.Entry" + i + "()", "SomeMod"); + var patched = new List(); + Watch.AutoInstall(() => new[] { nameof(AutoWatchFakePatches.Unused), nameof(AutoWatchFakePatches.Tick), nameof(AutoWatchFakePatches.Skip), nameof(AutoWatchFakePatches.Other) } + .Select(n => Watch.Examine(entityTick, "postfix", "other.mod", typeof(AutoWatchFakePatches).GetMethod(n))) + .Append(named).ToList(), m => { patched.Add(m.Name); return null; }); + Check(patched.SequenceEqual(new[] { "Other", "Skip" }), "only the 2 free slots are filled, in name order: " + string.Join(", ", patched)); + Equal(Config.MaxWatched, Watch.Count, "40 watched in all"); + List lines = Watch.AutoLines().ToList(); + Equal(AutoWatch.NamedByWatch, lines.Single(l => l[0] == named.Label)[1], "the Watch entry keeps its own watch"); + Equal(2, lines.Count(l => l[1] == AutoWatch.NoFreeSlot), "the rest say there was no free slot"); + } + finally { Watch.ResetForTest(); Watch.AroundAutoPatching = guard; } + } + + static void GameRandomIsKept() + { + Action guard = Watch.AroundAutoPatching; + try + { + // In the game the guard is KeepUnityRandom: it reads UnityEngine.Random.state before it runs anything, and writes it back in a + // finally, so a Harmony patch's draws (BeaverBuddies turns MonoMod's Guid.NewGuid into Unity random numbers) are undone. + Watch.ResetForTest(); + MethodInfo keep = typeof(Watch).GetMethod("KeepUnityRandom", BindingFlags.NonPublic | BindingFlags.Static); + Check(keep != null, "Watch.KeepUnityRandom exists"); + Check(guard.Method == keep, "the auto watch's patching runs inside KeepUnityRandom (the checks before this one put it back)"); + ExceptionHandlingClause restore = keep.GetMethodBody().ExceptionHandlingClauses.Single(c => c.Flags == ExceptionHandlingClauseOptions.Finally); + List<(int At, MethodBase Method)> calls = Calls(keep); + List At(Type type, string name) => calls.Where(c => c.Method.DeclaringType?.FullName == type.FullName && c.Method.Name == name).Select(c => c.At).ToList(); + List get = At(typeof(UnityEngine.Random), "get_state"), set = At(typeof(UnityEngine.Random), "set_state"), run = At(typeof(Action), "Invoke"); + Check(get.Count == 1 && get[0] < restore.TryOffset, "the state is read once, before anything runs: at " + string.Join(",", get) + ", try at " + restore.TryOffset); + Check(run.Count == 1 && run[0] >= restore.TryOffset && run[0] < restore.TryOffset + restore.TryLength, "the patching runs inside the try"); + Check(set.Count == 1 && set[0] >= restore.HandlerOffset && set[0] < restore.HandlerOffset + restore.HandlerLength, + "the state is written back in the finally: at " + string.Join(",", set) + ", finally at " + restore.HandlerOffset); + + // Every patch the auto watch makes, and its reading of Harmony's registry, happen inside the guard. + int entered = 0; + bool inside = false; + var outside = new List(); + Watch.AroundAutoPatching = patching => { entered++; inside = true; try { patching(); } finally { inside = false; } }; + MethodInfo entityTick = typeof(TickableEntity).GetMethod("Tick", BindingFlags.Instance | BindingFlags.Public); + var patched = new List(); + Watch.AutoInstall(() => + { + if (!inside) outside.Add("reading the registry"); + return new[] { nameof(AutoWatchFakePatches.Prefix), nameof(AutoWatchFakePatches.Unused) } + .Select(n => Watch.Examine(entityTick, "prefix", "other.mod", typeof(AutoWatchFakePatches).GetMethod(n))).ToList(); + }, m => { if (!inside) outside.Add("patching " + m.Name); patched.Add(m.Name); return null; }); + Equal(1, entered, "the guard is entered once"); + Equal(2, patched.Count, "patches were made"); + Check(outside.Count == 0, "nothing is done outside the guard: " + string.Join(", ", outside)); + } + finally { Watch.ResetForTest(); Watch.AroundAutoPatching = guard; } + } + + /// Every call in a method's IL, with the offset of its instruction. + static List<(int At, MethodBase Method)> Calls(MethodInfo method) + { + var codes = new Dictionary(); + foreach (FieldInfo f in typeof(OpCodes).GetFields(BindingFlags.Public | BindingFlags.Static)) + if (f.GetValue(null) is OpCode op) codes[(ushort)op.Value] = op; + byte[] il = method.GetMethodBody().GetILAsByteArray(); + var calls = new List<(int, MethodBase)>(); + for (int i = 0; i < il.Length;) + { + int at = i; + int value = il[i++]; + if (value == 0xFE) value = 0xFE00 | il[i++]; + OpCode op = codes[value]; + switch (op.OperandType) + { + case OperandType.InlineNone: break; + case OperandType.ShortInlineBrTarget: case OperandType.ShortInlineI: case OperandType.ShortInlineVar: i += 1; break; + case OperandType.InlineVar: i += 2; break; + case OperandType.InlineI8: case OperandType.InlineR: i += 8; break; + case OperandType.InlineSwitch: i += 4 + 4 * BitConverter.ToInt32(il, i); break; + case OperandType.InlineMethod: calls.Add((at, method.Module.ResolveMethod(BitConverter.ToInt32(il, i)))); i += 4; break; + default: i += 4; break; + } + } + return calls; + } } internal static class AutoWatchFakePatches @@ -236,6 +398,9 @@ internal static class AutoWatchFakePatches public static void Prefix(int a, string b) { } public static void Generic() { } public static void Tick() { } + public static void Unused() { } + public static void Other() { } + public static bool Skip() => true; } internal sealed class AutoWatchFakeTickable : ITickableSingleton diff --git a/tests/SummaryTests.cs b/tests/SummaryTests.cs index e35ea3c..d8d93fa 100644 --- a/tests/SummaryTests.cs +++ b/tests/SummaryTests.cs @@ -15,7 +15,7 @@ internal static class SummaryTests yield return ("Summary: a session with no profile and no slow frames still renders", NothingSlow); yield return ("Summary: component time is rolled up by mod, and load steps are listed slowest first", ComponentAndLoadTables); yield return ("Summary: slow frames without a row of their own are said to be counted", SkippedRowsAreExplained); - yield return ("Summary: long class names are shortened and short ones kept", ShortNames); + yield return ("Summary: long class names are shortened and short ones kept; a watched method keeps its class", ShortNames); yield return ("Readme: placeholders are filled and no placeholder is left", ReadmePlaceholders); } @@ -126,6 +126,13 @@ static void ShortNames() string longName = "Some.Very.Long.Namespace.That.Goes.On.And.On.Forever.And.Ever.TheClass"; Equal("TheClass", Summary.Short(longName)); Equal("?", Summary.Short(null)); + // A watched method keeps its class (an auto-watched patch method is nearly always called Prefix or Postfix), as perflog.py's short_method does. + Equal("TickableEntityTickPatcher.Prefix(TickableEntity)", Summary.ShortMethod("BeaverBuddies.DeterminismService+TickableEntityTickPatcher.Prefix(TickableEntity)")); + Equal("TextEditingInputPatch.Finalizer(Exception)", Summary.ShortMethod("MixedStorage.TextEditingInputPatch.Finalizer(Exception)")); + Equal("VeryLongClassNameForTestingTheSummaryTable.Method(...)", + Summary.ShortMethod("A.B.VeryLongClassNameForTestingTheSummaryTable.Method(Int32,String,Boolean,Single,Double,Int64)")); + Equal("Some.Mod.Method()", Summary.ShortMethod("Some.Mod.Method()")); + Equal("?", Summary.ShortMethod(null)); } static void ReadmePlaceholders() diff --git a/tests/fixtures/sample-with-mod/README.md b/tests/fixtures/sample-with-mod/README.md index 8b93929..1a6b156 100644 --- a/tests/fixtures/sample-with-mod/README.md +++ b/tests/fixtures/sample-with-mod/README.md @@ -91,8 +91,11 @@ Start by writing down what the complaint is, because the causes differ: `Tick`, `UpdateSingleton`, `LateUpdateSingleton` or `StartParallelTick`, an entity's or component's `Tick`, whose time is otherwise inside a row that names the game or the singleton's own mod), then the rest of the hot methods, in name order, in the Watch slots the config's `Watch` entries left (40 in all); the `# watch|` lines of the ones left out say why. A patch method's time is inside the row of what it patches, so do not add the two. - One that `# capability-final|autoWatch|` lists as never seen called was either not called or so small that the runtime copied it into the method it - patches, where no watch can see it: a missing row there is not a measurement of 0. + One that `# capability-final|autoWatch|` lists as never seen called was either not called, called only off the game thread (the watch times the game + thread only), or so small that the runtime copied it into the method it patches, where no watch can see it: a missing row there is not a measurement of 0. + A `# watch|` line that says `(can replace it)` is a prefix that returns a bool: when it returns false the game's own method does not run, and the + prefix's row holds the work it did instead, so that time is the mod doing the game's job, not cost on top of it (compare a recording without that + mod to see what it saves or costs in all). A prefix that replaces a tick loop (`TickableBucketService.TickBuckets`, say) holds nearly the whole tick. - To be sure it is a mod, **compare two recordings** of the same save at the same speed with and without it: `python tools/perflog.py compare ` (in the Performance Log repository). Say what else differed. diff --git a/tests/fixtures/sample-without-mod/README.md b/tests/fixtures/sample-without-mod/README.md index 8b93929..1a6b156 100644 --- a/tests/fixtures/sample-without-mod/README.md +++ b/tests/fixtures/sample-without-mod/README.md @@ -91,8 +91,11 @@ Start by writing down what the complaint is, because the causes differ: `Tick`, `UpdateSingleton`, `LateUpdateSingleton` or `StartParallelTick`, an entity's or component's `Tick`, whose time is otherwise inside a row that names the game or the singleton's own mod), then the rest of the hot methods, in name order, in the Watch slots the config's `Watch` entries left (40 in all); the `# watch|` lines of the ones left out say why. A patch method's time is inside the row of what it patches, so do not add the two. - One that `# capability-final|autoWatch|` lists as never seen called was either not called or so small that the runtime copied it into the method it - patches, where no watch can see it: a missing row there is not a measurement of 0. + One that `# capability-final|autoWatch|` lists as never seen called was either not called, called only off the game thread (the watch times the game + thread only), or so small that the runtime copied it into the method it patches, where no watch can see it: a missing row there is not a measurement of 0. + A `# watch|` line that says `(can replace it)` is a prefix that returns a bool: when it returns false the game's own method does not run, and the + prefix's row holds the work it did instead, so that time is the mod doing the game's job, not cost on top of it (compare a recording without that + mod to see what it saves or costs in all). A prefix that replaces a tick loop (`TickableBucketService.TickBuckets`, say) holds nearly the whole tick. - To be sure it is a mod, **compare two recordings** of the same save at the same speed with and without it: `python tools/perflog.py compare ` (in the Performance Log repository). Say what else differed. diff --git a/tools/perflog.py b/tools/perflog.py index a83e535..fa198be 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -827,7 +827,7 @@ def report(session, args, out): p() watched = [t for t in totals.values() if t.kind == "method"] if not watched and session.pipe("watch"): - p(" (Watch entries were configured, but none produced rows: %s)" % "; ".join("|".join(w) for w in session.pipe("watch")[:3])) + p(" (watched methods were set up (Watch entries or AutoWatch), but none produced rows: %s)" % "; ".join("|".join(w) for w in session.pipe("watch")[:3])) p() p("7. GARBAGE COLLECTION AND MEMORY") @@ -1007,6 +1007,8 @@ def compare(a, b, args, out): for delta, k, va, vb, t in movers[:args.top]: note = " (only in B)" if k not in pa else " (only in A)" if k not in pb else "" p(" %-58s %-22s %9.2f %9.2f %+9.2f%s" % ("[%s] %s" % (k[0].split("-")[0], short_key(k[0], k[1], 52)), (mod_of(a, t) or "")[:22], va, vb, delta, note)) + if any(k[0] == "method" for _, k, _, _, _ in movers[:args.top]): + p(" [method] rows are watched methods (Watch or AutoWatch): their time is inside the row of whatever runs them, so it is not extra time.") mods = collections.defaultdict(lambda: [0.0, 0.0]) for k, t in pa.items(): if k[0] in ("tick-singleton", "update-singleton", "late-singleton"): @@ -1061,12 +1063,20 @@ def compare_pointers(a, b, Sa, Sb, diffs, cautions, rows, movers=()): for s in biggest: if abs(sb[s] - sa[s]) >= 0.1: lines.append("Most of the difference is in %s (%s): %.2f ms per frame in A, %.2f ms in B." % (s, SLOT_MEANING[s], sa[s], sb[s])) - gone = [(k, va_) for _, k, va_, vb_, t in movers if vb_ == 0 and va_ >= 0.5] - added = [(k, vb_) for _, k, va_, vb_, t in movers if va_ == 0 and vb_ >= 0.5] + # A watched method's time is already inside the row of whatever runs it (a patch method's inside the method it patches), in both + # recordings, so one that only one side watched is a difference in what was measured, not in what the game did. + gone = [(k, va_) for _, k, va_, vb_, t in movers if vb_ == 0 and va_ >= 0.5 and k[0] != "method"] + added = [(k, vb_) for _, k, va_, vb_, t in movers if va_ == 0 and vb_ >= 0.5 and k[0] != "method"] if gone: lines.append("Only A has these (the ones above 0.5 ms/s): " + "; ".join("%s (%.1f ms/s)" % (short_key(k[0], k[1], 48), v) for k, v in gone[:4]) + ". Time they took is time B does not spend.") if added: lines.append("Only B has these (the ones above 0.5 ms/s): " + "; ".join("%s (%.1f ms/s)" % (short_key(k[0], k[1], 48), v) for k, v in added[:4]) + ". Time B spends that A does not.") + for side, watched in (("A", [(k, va_) for _, k, va_, vb_, t in movers if vb_ == 0 and va_ >= 0.5 and k[0] == "method"]), + ("B", [(k, vb_) for _, k, va_, vb_, t in movers if va_ == 0 and vb_ >= 0.5 and k[0] == "method"])): + if watched: + lines.append("Only %s watched these methods (the ones above 0.5 ms/s): %s. Their time is inside the rows of what runs them in both recordings, so " + "it is not time only %s spends: the Watch or AutoWatch settings differ." % ( + side, "; ".join("%s (%.1f ms/s)" % (short_key(k[0], k[1], 48), v) for k, v in watched[:4]), side)) only_a = [m for m in a.mods if m not in b.mods] only_b = [m for m in b.mods if m not in a.mods] if only_a or only_b: diff --git a/tools/test_perflog.py b/tools/test_perflog.py index 64c8e12..2b65eef 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -249,6 +249,29 @@ def test_cautions_for_different_workloads(self): finally: a.cleanup(); b.cleanup() + def test_turning_the_auto_watch_on_is_not_extra_time(self): + # The cost check the auto watch asks for: the same play with AutoWatch off (A) and on (B). The entity rows are the same; B also has a row + # for BeaverBuddies' prefix on every entity's tick, whose time is already inside those entity rows. + a, b = Synthetic(), Synthetic() + entity = "BeaverBuddies.DeterminismService+TickableEntityTickPatcher.Prefix(TickableEntity)" + try: + b.pipes.append(["watch", entity, "watching", "auto", "prefix on Timberborn.TickSystem.TickableEntity.Tick", "timbermods.BeaverBuddiesMultiColony"]) + for w in range(1, 9): + for s in (a, b): + s.window() + s.profile.append({"kind": "entity", "window": w, "tick": s.tick, "id": 1, "calls": 5000, "sampled": 100, "ms": 500.0, "allocKB": 0, + "maxMs": 0.2, "name": "BeaverAdult", "assembly": "Timberborn.Beavers", "mod": "game"}) + b.profile.append({"kind": "method", "window": w, "tick": b.tick, "id": 2, "calls": 5000, "sampled": 100, "ms": 20.0, "allocKB": 0, + "maxMs": 0.1, "name": entity, "assembly": "BeaverBuddies", "mod": "beaverbuddies"}) + _, text = run("compare", a.write(), b.write(), "--warmup", "0") + self.assertIn("[method] TickableEntityTickPatcher.Prefix(TickableEntity)", text, "named by class and method in the table") + self.assertIn("rows are watched methods (Watch or AutoWatch): their time is inside the row of whatever runs them", text) + self.assertIn("Only B watched these methods (the ones above 0.5 ms/s): TickableEntityTickPatcher.Prefix(TickableEntity) (2.0 ms/s)", text) + self.assertNotIn("Only B has these", text, "a watched method is not time B spends on top") + self.assertNotIn("Time B spends that A does not", text) + finally: + a.cleanup(); b.cleanup() + class RobustnessTests(unittest.TestCase): def setUp(self): @@ -603,7 +626,8 @@ def test_auto_watched_patch_methods_say_which_hot_method_they_are_on(self): entity = "BeaverBuddies.DeterminismService+TickableEntityTickPatcher.Prefix(TickableEntity)" panel = "LateGamePerformance.UiThrottle.PanelPrefix(EntityPanel,Boolean)" s.pipes.append(["watch", entity, "watching", "auto", "prefix on Timberborn.TickSystem.TickableEntity.Tick", "timbermods.BeaverBuddiesMultiColony"]) - s.pipes.append(["watch", panel, "watching", "auto", "prefix on Timberborn.EntityPanelSystem.EntityPanel.UpdateSingleton", "kyler.lategameperformance.UiThrottle"]) + s.pipes.append(["watch", panel, "watching", "auto", "prefix on Timberborn.EntityPanelSystem.EntityPanel.UpdateSingleton (can replace it)", + "kyler.lategameperformance.UiThrottle"]) s.pipes.append(["watch", "Some.Mod.Method()", "watching"]) for w in range(1, 7): s.window() @@ -614,10 +638,21 @@ def test_auto_watched_patch_methods_say_which_hot_method_they_are_on(self): # A patch method is named by its class, not only as "Prefix", and says which hot method it is on and whose patch it is. self.assertIn("TickableEntityTickPatcher.Prefix(TickableEntity)", text) self.assertIn("auto watch: prefix on Timberborn.TickSystem.TickableEntity.Tick (timbermods.BeaverBuddiesMultiColony)", text) - self.assertIn("auto watch: prefix on Timberborn.EntityPanelSystem.EntityPanel.UpdateSingleton (kyler.lategameperformance.UiThrottle)", text) + self.assertIn("auto watch: prefix on Timberborn.EntityPanelSystem.EntityPanel.UpdateSingleton (can replace it) (kyler.lategameperformance.UiThrottle)", text) self.assertRegex(text, r"Some\.Mod\.Method\(\)") self.assertEqual(2, text.count("auto watch: "), "a method the config's Watch named is not called an auto watch") + def test_auto_watch_lines_without_rows_do_not_blame_watch_entries(self): + s = Synthetic(header={"mod": "0.1.3"}) + s.pipes.append(["watch", "Some.Mod.Patch.Prefix()", "watching", "auto", "prefix on Timberborn.TickSystem.Ticker.Update", "some.mod"]) + for w in range(1, 7): + s.window() + s.profile.append({"kind": "entity", "window": w, "tick": s.tick, "id": 1, "calls": 100, "sampled": 10, "ms": 5.0, "allocKB": 0, + "maxMs": 0.1, "name": "BeaverAdult", "assembly": "Timberborn.Beavers", "mod": "game"}) + text = self.report(s) + self.assertIn("(watched methods were set up (Watch entries or AutoWatch), but none produced rows: ", text) + self.assertNotIn("Watch entries were configured", text) + def test_loading_that_grew_the_heap_is_reported(self): s = Synthetic() for _ in range(6): From 97ec2503e7d48aca7ce5f7a75889f40c1622ff7f Mon Sep 17 00:00:00 2001 From: Kyler Ramsey Date: Tue, 22 Sep 2026 12:48:19 -0700 Subject: [PATCH 3/3] AUTOWATCH: leave the co-op RNG, Guid and clock patches out; keep the watch from throwing - AutoWatch.Plan no longer takes patches on RandomNumberGenerator, Guid and DateTime by itself (status 'left out: ...'). In name order System.* sorts first, so BeaverBuddies' determinism patches, among the most-called methods in the game, took the free slots ahead of Ticker.Update and TickBuckets. A Watch entry can still name one. - WatchPrefix/WatchPostfix now sit inside other mods' hot patch methods, so both are wrapped in try/catch and tolerate a null __originalMethod. Co-Authored-By: Claude Opus 5.5 --- README.md | 3 ++- docs/SESSION-README.md | 2 +- source/Core/AutoWatch.cs | 11 ++++++++++- source/Game/Watch.cs | 21 +++++++++++++++------ tests/AutoWatchTests.cs | 13 ++++++++----- tests/fixtures/sample-with-mod/README.md | 2 +- tests/fixtures/sample-without-mod/README.md | 2 +- 7 files changed, 38 insertions(+), 16 deletions(-) diff --git a/README.md b/README.md index 270218e..af75959 100644 --- a/README.md +++ b/README.md @@ -116,7 +116,8 @@ could do" section of `summary.md`, say for each name whether it is being watched is otherwise invisible. When the first game is loaded, the mod reads Harmony's list of patches and times other mods' prefixes, postfixes and finalizers: 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). Each gets a `method` row in `profile.csv`, named after the patch +`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. 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 diff --git a/docs/SESSION-README.md b/docs/SESSION-README.md index c222ed9..a9de4db 100644 --- a/docs/SESSION-README.md +++ b/docs/SESSION-README.md @@ -100,7 +100,7 @@ Start by writing down what the complaint is, because the causes differ: Namespace.Type.Method>|` line each in the header. It takes the patches on the methods behind the profile's own rows first (a singleton's `Tick`, `UpdateSingleton`, `LateUpdateSingleton` or `StartParallelTick`, an entity's or component's `Tick`, whose time is otherwise inside a row that names the game or the singleton's own mod), then the rest of the hot methods, in name order, in the Watch slots the config's `Watch` entries left - (40 in all); the `# watch|` lines of the ones left out say why. A patch method's time is inside the row of what it patches, so do not add the two. + (40 in all), leaving out patches on the random numbers, `Guid.NewGuid` and `DateTime.ToString`; the `# watch|` lines of the ones left out say why. A patch method's time is inside the row of what it patches, so do not add the two. One that `# capability-final|autoWatch|` lists as never seen called was either not called, called only off the game thread (the watch times the game thread only), or so small that the runtime copied it into the method it patches, where no watch can see it: a missing row there is not a measurement of 0. A `# watch|` line that says `(can replace it)` is a prefix that returns a bool: when it returns false the game's own method does not run, and the diff --git a/source/Core/AutoWatch.cs b/source/Core/AutoWatch.cs index c335a1a..1684306 100644 --- a/source/Core/AutoWatch.cs +++ b/source/Core/AutoWatch.cs @@ -57,6 +57,11 @@ public static class AutoWatch public const string NamedByWatch = "watched by a Watch entry"; public const string NoFreeSlot = "skipped: no free Watch slot"; public const string CanReplaceNote = "(can replace it)"; + public const string LeftOut = "left out: a patch on the random numbers, Guid or clock co-op depends on (a Watch entry can still name it)"; + + // Hot methods whose patches the auto watch never takes by itself. BeaverBuddies patches these to keep co-op in step, they run very + // often, and in name order (System.* first) they would take the free slots ahead of the tick-loop patches the auto watch is for. + static readonly HashSet leftOutTypes = new HashSet(StringComparer.Ordinal) { "RandomNumberGenerator", "Guid", "DateTime" }; sealed class Group { @@ -65,6 +70,7 @@ sealed class Group public int Tier, KindOrder; public readonly SortedSet On = new SortedSet(StringComparer.Ordinal); public string Refused; + public bool LeftOut; } /// @@ -76,7 +82,8 @@ sealed class Group /// rows (their time is inside a row that names someone else), then the rest of the hot list; within each, by the patched method's /// full name, then prefix, postfix, finalizer, then the patch method's name. A patch method a Watch entry already watches /// (, by label) keeps that watch; one that is refused, or that could not - /// patch (it returns why, or null once it has), takes no slot. The results are in that order, one for each patch method. + /// patch (it returns why, or null once it has), takes no slot, and so does a patch on the random numbers, Guid or DateTime + /// (). The results are in that order, one for each patch method. /// public static List Plan(IEnumerable patches, string ownOwner, ICollection watchedAlready, int freeSlots, Func watch) @@ -91,6 +98,7 @@ public static List Plan(IEnumerable patches int tier = c.ProfileRow ? 0 : PatchFormat.IsHot(c.TypeName, c.MethodName) ? 1 : -1; if (tier < 0) continue; if (!groups.TryGetValue(c.Label, out Group g)) groups[c.Label] = g = new Group { Label = c.Label, Tier = int.MaxValue }; + if (tier == 1 && c.TypeName != null && leftOutTypes.Contains(c.TypeName)) g.LeftOut = true; g.On.Add(c.Kind + " on " + c.Target + (c.CanReplace && kindOrder == 0 ? " " + CanReplaceNote : "")); if (Before(c, tier, kindOrder, g)) { g.First = c; g.Tier = tier; g.KindOrder = kindOrder; } // Why a patch method cannot be watched does not depend on the hot method it is on; if the records disagree, the same one is kept whatever their order. @@ -113,6 +121,7 @@ public static List Plan(IEnumerable patches var r = new AutoWatchResult { Candidate = g.First, On = string.Join("; ", g.On) }; if (watchedAlready != null && watchedAlready.Contains(g.Label)) r.Status = NamedByWatch; else if (g.Refused != null) r.Status = g.Refused; + else if (g.LeftOut && g.Tier == 1) r.Status = LeftOut; // one also behind a profile row is placed, and watched, with the rows else if (used >= freeSlots) r.Status = NoFreeSlot; else { diff --git a/source/Game/Watch.cs b/source/Game/Watch.cs index 26119db..cb2969c 100644 --- a/source/Game/Watch.cs +++ b/source/Game/Watch.cs @@ -135,20 +135,29 @@ internal static void OnSessionStart() ids = map; } + // Both run inside the watched method, which may be another mod's patch on a hot method: nothing may escape them into the game. internal static void WatchPrefix(MethodBase __originalMethod, out Sample __state) { __state = default; - if (!Probe.Enabled || !Probe.OnGameThread) return; - if (!ids.TryGetValue(__originalMethod, out int id)) return; - Probe.Count(Counter.PatchCalls); - __state = Profile.BeginMethod(id); + try + { + if (!Probe.Enabled || !Probe.OnGameThread || __originalMethod == null) return; + if (!ids.TryGetValue(__originalMethod, out int id)) return; + Probe.Count(Counter.PatchCalls); + __state = Profile.BeginMethod(id); + } + catch (Exception) { __state = default; } } internal static void WatchPostfix(MethodBase __originalMethod, Sample __state) { if (!__state.On) return; - Instrumentation.Hits[Instrumentation.HitWatch]++; - if (ids.TryGetValue(__originalMethod, out int id)) Profile.EndMethod(id, __state); + try + { + Instrumentation.Hits[Instrumentation.HitWatch]++; + if (__originalMethod != null && ids.TryGetValue(__originalMethod, out int id)) Profile.EndMethod(id, __state); + } + catch (Exception) { } } // ---- the auto watch ---- diff --git a/tests/AutoWatchTests.cs b/tests/AutoWatchTests.cs index 0778b55..f6accb6 100644 --- a/tests/AutoWatchTests.cs +++ b/tests/AutoWatchTests.cs @@ -104,16 +104,18 @@ static void CapIsRespected() "a refused method is never patched, a failed patch leaves its slot to the next, and nothing is patched once the slots are used: " + string.Join(", ", tried)); Equal("skipped: abstract or generic", results.Single(r => r.Candidate.Label == "LGP.Generic.Prefix()").Status); Equal("could not be patched: boom", results.Single(r => r.Candidate.Label == "MS.TextEditingInputPatch.Prefix()").Status); - Check(results.Where(r => !r.Watching && tried.IndexOf(r.Candidate.Label) < 0 && r.Candidate.Refused == null).All(r => r.Status.StartsWith("skipped: no free Watch slot")), - "the rest say there was no free slot: " + Labels(results)); - Equal(4, results.Count(r => r.Status.StartsWith("skipped: no free Watch slot"))); + Check(results.Where(r => !r.Watching && tried.IndexOf(r.Candidate.Label) < 0 && r.Candidate.Refused == null && r.Status != AutoWatch.LeftOut) + .All(r => r.Status.StartsWith("skipped: no free Watch slot")), "the rest say there was no free slot: " + Labels(results)); + Equal(3, results.Count(r => r.Status.StartsWith("skipped: no free Watch slot"))); + Equal(AutoWatch.LeftOut, results.Single(r => r.Candidate.Label == "BB.RandomPatch.Prefix(Int32,Int32)").Status, + "a patch on the random numbers co-op depends on is left out, whatever the slots"); Check(AutoWatch.Describe(results).StartsWith("watching 3 of 9 "), AutoWatch.Describe(results)); foreach (int free in new[] { 0, -2 }) { bool called = false; List none = AutoWatch.Plan(Patches(), Own, new List(), free, c => { called = true; return null; }); - Check(!called && none.Count == Expected.Length && none.All(r => !r.Watching && r.Status.StartsWith("skipped: no free Watch slot")), + Check(!called && none.Count == Expected.Length && none.All(r => !r.Watching && (r.Status.StartsWith("skipped: no free Watch slot") || r.Status == AutoWatch.LeftOut)), "with no free slot (" + free + ") nothing is patched: " + Labels(none)); } } @@ -135,7 +137,8 @@ static void OrderIsByName() { List first = AutoWatch.Plan(Patches(), Own, new List(), Config.MaxWatched, c => null); Check(first.Select(r => r.Candidate.Label).SequenceEqual(Expected), "in name order: " + Labels(first)); - Check(first.All(r => r.Watching && r.Status == AutoWatch.Watching), Labels(first)); + Check(first.All(r => r.Candidate.Label == "BB.RandomPatch.Prefix(Int32,Int32)" ? r.Status == AutoWatch.LeftOut && !r.Watching + : r.Watching && r.Status == AutoWatch.Watching), Labels(first)); Equal("finalizer on " + Connected + "; finalizer on " + ConnectedWith, first.Single(r => r.Candidate.Label == "BB.DistrictFix.Finalizer(Exception)").On, "one watch for a patch method on two hot methods, naming both"); Equal("prefix on " + EntityTick, first.Single(r => r.Candidate.Label == "BB.EntityPatch.Prefix(TickableEntity)").On); diff --git a/tests/fixtures/sample-with-mod/README.md b/tests/fixtures/sample-with-mod/README.md index da72fa9..c61a05c 100644 --- a/tests/fixtures/sample-with-mod/README.md +++ b/tests/fixtures/sample-with-mod/README.md @@ -100,7 +100,7 @@ Start by writing down what the complaint is, because the causes differ: Namespace.Type.Method>|` line each in the header. It takes the patches on the methods behind the profile's own rows first (a singleton's `Tick`, `UpdateSingleton`, `LateUpdateSingleton` or `StartParallelTick`, an entity's or component's `Tick`, whose time is otherwise inside a row that names the game or the singleton's own mod), then the rest of the hot methods, in name order, in the Watch slots the config's `Watch` entries left - (40 in all); the `# watch|` lines of the ones left out say why. A patch method's time is inside the row of what it patches, so do not add the two. + (40 in all), leaving out patches on the random numbers, `Guid.NewGuid` and `DateTime.ToString`; the `# watch|` lines of the ones left out say why. A patch method's time is inside the row of what it patches, so do not add the two. One that `# capability-final|autoWatch|` lists as never seen called was either not called, called only off the game thread (the watch times the game thread only), or so small that the runtime copied it into the method it patches, where no watch can see it: a missing row there is not a measurement of 0. A `# watch|` line that says `(can replace it)` is a prefix that returns a bool: when it returns false the game's own method does not run, and the diff --git a/tests/fixtures/sample-without-mod/README.md b/tests/fixtures/sample-without-mod/README.md index da72fa9..c61a05c 100644 --- a/tests/fixtures/sample-without-mod/README.md +++ b/tests/fixtures/sample-without-mod/README.md @@ -100,7 +100,7 @@ Start by writing down what the complaint is, because the causes differ: Namespace.Type.Method>|` line each in the header. It takes the patches on the methods behind the profile's own rows first (a singleton's `Tick`, `UpdateSingleton`, `LateUpdateSingleton` or `StartParallelTick`, an entity's or component's `Tick`, whose time is otherwise inside a row that names the game or the singleton's own mod), then the rest of the hot methods, in name order, in the Watch slots the config's `Watch` entries left - (40 in all); the `# watch|` lines of the ones left out say why. A patch method's time is inside the row of what it patches, so do not add the two. + (40 in all), leaving out patches on the random numbers, `Guid.NewGuid` and `DateTime.ToString`; the `# watch|` lines of the ones left out say why. A patch method's time is inside the row of what it patches, so do not add the two. One that `# capability-final|autoWatch|` lists as never seen called was either not called, called only off the game thread (the watch times the game thread only), or so small that the runtime copied it into the method it patches, where no watch can see it: a missing row there is not a measurement of 0. A `# watch|` line that says `(can replace it)` is a prefix that returns a bool: when it returns false the game's own method does not run, and the