diff --git a/CHANGELOG.md b/CHANGELOG.md index bf9e497..e4efdea 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,6 @@ # Changelog -## 0.1.3 (preview, not yet played) +## 0.1.3 (preview) **The defaults now capture the most detail a session can hold without anyone touching a setting**, so every recording made from a plain install is as informative as this mod can make it. @@ -17,7 +17,8 @@ install is as informative as this mod can make it. rather than the depth of any one row, and the budget system above already throttles itself if measuring gets expensive, so there was no clear "more detail" case for moving them, only a "more rows" one. - Expect a real, measurable increase in the mod's own cost from this alone — deep's component sampling plus double the sampling budget. - Nobody has played it yet; the five-minute check in `docs/TESTING.md` now starts by checking `overheadUs` is still reasonable. + Nobody had played it when it was released (it has been since: see `docs/TESTING.md`); step 10 of the five-minute check there measures + what it costs. ## 0.1.2 (preview, not yet played) @@ -43,7 +44,7 @@ that recording. Each one that can be checked outside the game has a check that f figures and the garbage-collection section**; `tools/perflog.py` says so. - **Files are no longer held open.** 0.1.0 kept `frames.csv`, `profile.csv`, `spikes.csv` and `events.csv` open for writing, so zipping or copying the folder while the game ran silently left them out (and a folder listing showed size 0). They are now opened, appended to and closed on each write, shared with readers, and retried if someone else holds them. -- **Every singleton of the game itself was labelled with no mod ("(unknown)")**; the mod map was installed without the game's own assemblies. They are now `game`. The analysis tool applies the same +- **Every singleton of the game itself was labeled with no mod ("(unknown)")**; the mod map was installed without the game's own assemblies. They are now `game`. The analysis tool applies the same rule to older recordings. - **`workingMB` was always 0** (Unity's Mono reports 0 for the process's memory). It now asks Windows, and the header says where the figure comes from (`# capability|workingSet|...`). - **Loading steps now record how much the managed heap grew** during each one (`allocKB` of the load rows, "heap grew MB" in `summary.md`, and a finding in the report). The first recording's diff --git a/CLAUDE.md b/CLAUDE.md index 0b0e53b..28291cd 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -47,7 +47,7 @@ packaging/ manifest.json, PerformanceLog.cfg. build.ps1 builds, tests and ``` .\build.ps1 -SkipTests build + package -dotnet run --project tests -c Release all C# checks (about 70) +dotnet run --project tests -c Release all C# checks (91 at 0.1.3; docs/TESTING.md keeps the current count) python -m unittest discover -s tools -p "test_perflog.py" dotnet run --project tests -c Release -- --print-columns dotnet run --project tests -c Release -- --write-sample tests/fixtures/sample-with-mod @@ -106,12 +106,13 @@ To read the game's own code (the way every patch target here was checked): `ilsp ## What is and is not verified -0.1.0 was run once in the real game (2026-09-20, 31 minutes, nine mods including BeaverBuddies, clean exit). Its recording is why 0.1.1 exists: see `CHANGELOG.md` and `docs/TESTING.md` -(what that run proved, what it broke, and what is still unproven). When you are given a recording, start with the `# capability` and `# capability-final` lines in the `frames.csv` -header and the "Read first" section of `summary.md`: they say which parts worked. `python tools/perflog.py report ` prints a `KNOWN ISSUE` line for every known defect of the -version that made it (`KNOWN_ISSUES` in `tools/perflog.py`); add to that list whenever a version is found to record something wrong. +0.1.0 was first run in the real game on 2026-09-20 (31 minutes, nine mods including BeaverBuddies, clean exit). Its recording is why 0.1.1 exists; 0.1.1 and 0.1.3 have been +recorded in the game since. See `CHANGELOG.md` and `docs/TESTING.md` (what those runs proved, what the first one broke, and what is still unproven). When you are given a +recording, start with the `# capability` and `# capability-final` lines in the `frames.csv` header and the "Read first" section of `summary.md`: they say which parts worked. +`python tools/perflog.py report ` prints a `KNOWN ISSUE` line for every known defect of the version that made it (`KNOWN_ISSUES` in `tools/perflog.py`); add to that list +whenever a version is found to record something wrong. -Two lessons from that run that shape how to change this code: +Lessons from the first run that shape how to change this code: - **Count what a patch really does.** `# capability-final|patchCalls|...` showed 488601 wrapper swaps in 122150 frames: the hit counters are how a defect that only exists in the game shows up. Keep a counter for anything done once per game or per frame. - **The game keeps more than one singleton service alive** (the application's and the game's, both updated every frame), so anything remembered "per service" must hold several diff --git a/LICENSE b/LICENSE index 889aa57..9e2e92d 100644 --- a/LICENSE +++ b/LICENSE @@ -1,6 +1,6 @@ MIT License -Copyright (c) 2026 Kyler Ramsey +Copyright (c) 2026 Timbermods Permission is hereby granted, free of charge, to any person obtaining a copy of this software and associated documentation files (the "Software"), to deal diff --git a/README.md b/README.md index 8701ad6..47ef4e1 100644 --- a/README.md +++ b/README.md @@ -4,25 +4,31 @@ A Timberborn 1.1 mod (built against **1.1.2.4**) that measures **where the game' person, or an AI assistant such as Claude, can read to find out why a game is slow. It is a diagnostic tool for finding performance problems in the game and in other mods. It does nothing else. -Version **0.1.2** is a **preview**. Its automated checks run against the game's real assemblies, and version 0.1.0 has been played once (a 31 minute session with -nine mods, ending in a normal exit): every patch applied and the recording was complete. That first recording also showed several defects, fixed in 0.1.1; 0.1.2 -adds an in-game settings page and has not itself been played yet. See [CHANGELOG.md](CHANGELOG.md) for what changed in each version. If a part fails to start it -says so in the log and the summary, that part stays off, and the game carries on. Read [docs/TESTING.md](docs/TESTING.md) for what is and is not verified, and -how to check it in a game in five minutes. +Version **0.1.3** is a **preview**, published as a pre-release. Its automated checks run against the game's real assemblies. +Version 0.1.0 was the first to be played (a 31 minute session with nine mods, ending in a normal exit): every patch applied and the recording was complete. +That first recording also showed several defects, fixed in 0.1.1. 0.1.2 added an in-game settings page, and 0.1.3 made the most detailed profile the default. +0.1.1 and 0.1.3 have been played since. A 44 minute 0.1.3 recording with ten mods shows the new defaults working, and every 0.1.1 fix that a recording can show. +Not verified yet: whether a value changed on the settings page reaches a recording. + +See [CHANGELOG.md](CHANGELOG.md) for what changed in each version, and [docs/TESTING.md](docs/TESTING.md) for what is and is not verified and how to check +it in a game in five minutes. If a part fails to start, it says so in the log and the summary, that part stays off, and the game carries on. It only observes. It never records or replays an action, never uses the game's random numbers and never touches anything the simulation reads, so it should not cause a desync in co-op. (That has not been played in co-op yet.) ## Install -1. Close Timberborn. Extract the release ZIP into `Documents\Timberborn\Mods`. It contains one `PerformanceLog` folder. -2. It requires the **Harmony** mod (2.4.1 or newer) and the **Mod Settings** mod (1.1.0.0 or newer) from the Steam Workshop. -3. Launch Timberborn, enable **Performance Log** in the mod manager, and restart. -4. Play. Leave normally (menu → exit) so the files are finished; if the game crashes the files are still readable and the summary is at most a - minute stale. (From 0.1.1 you can also copy or zip the folder while the game runs; 0.1.0 held four of its files open, so a zip made then left them out.) Look for `[PerformanceLog]` lines in `Player.log` - (`%USERPROFILE%\AppData\LocalLow\Mechanistry\Timberborn\Player.log`). +1. Open the [Releases page](https://github.com/timbermods/PerformanceLog/releases) and pick the newest pre-release (there is no stable release yet). + Under **Assets**, download `PerformanceLog-.zip`, not "Source code". +2. Close Timberborn. Extract the ZIP into `Documents\Timberborn\Mods`. It contains one `PerformanceLog` folder. +3. Subscribe to the **Harmony** mod (2.4.1 or newer) and the **Mod Settings** mod (1.1.0.0 or newer) on the Steam Workshop. Performance Log needs both. +4. Launch Timberborn, enable **Performance Log** in the mod manager, and restart. +5. Play. Leave normally (menu → exit) so the files are finished. If the game crashes, the files are still readable and the summary is at most a + minute stale. You can also copy or zip the folder while the game runs (0.1.0 could not: it held four of its files open, so a zip left them out). + Look for `[PerformanceLog]` lines in `Player.log` (`%USERPROFILE%\AppData\LocalLow\Mechanistry\Timberborn\Player.log`). -Recordings go to `Documents\Timberborn\PerformanceLog\\`, one folder per game session (a session is from a save finishing loading to leaving it). +Recordings go to `Documents\Timberborn\PerformanceLog\\` (for example `2026-09-21_14-05-33`, local time), one folder per game session. +A session runs from a save finishing loading to leaving it. The `OutputFolder` setting can move them. ## What to do with a recording @@ -40,8 +46,9 @@ python tools/perflog.py compare python tools/perflog.py list ``` -`report` says what stands out, with the evidence and what to check next; `compare` lines up two sessions and says what changed and what else differed -(different mods, game speed, colony size, computer). The tool is also in the release ZIP, in `PerformanceLog\tools`. For a fair comparison, record the +`report` says what stands out, with the evidence and what to check next. `compare` lines up two sessions and says what changed and what else differed +(different mods, game speed, colony size, computer). `list` shows every session in `Documents\Timberborn\PerformanceLog`, or in a folder you name. +The tool is also in the release ZIP, in `PerformanceLog\tools`. For a fair comparison, record the same save at the same game speed for at least three minutes each, with the window in front, and change one thing. ## What it records @@ -85,7 +92,7 @@ Nothing here changes what the game simulates, so co-op players may use different | `SpikeContributors` | `8` | .cfg or Mod Settings | How many of the biggest contributors to each slow frame are written to `spikes.csv` (8 is the most it can hold). | | `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`. | +| `Watch` | *(none)* | .cfg only | Full names of methods to time: `Namespace.Type.Method`, separated by `;`, on as many lines as you like (at most 40 methods; every overload of a name is watched). Rows appear in `profile.csv` as kind `method`. | 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). @@ -96,16 +103,17 @@ To measure another mod's method, for example: Watch = LateGamePerformance.HaulCache.OnTickStarted; LateGamePerformance.MetricsDump.OnTickStarted ``` -The mod must be enabled so its type can be found. Every call of a watched method pays for a Harmony wrapper and a lookup even when it is not timed, so watching a method that runs thousands of times a tick costs -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. +The mod must be enabled so its type can be found. Every call of a watched method pays for a Harmony wrapper and a lookup even when it is not timed, so watching a +method that runs thousands of times a tick costs 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). A `# watch|` line in the `frames.csv` header, and the "What each measurement source +could do" section of `summary.md`, say for each name whether it is being watched or why not. ## 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. +The mod puts a timing wrapper in front of each of the game's singletons. It does this 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 the +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. ## What it costs, and what it cannot see @@ -120,7 +128,7 @@ Everything is timed on the game thread only. ## How it relates to the BeaverBuddies frame rate log -The measuring core is the frame rate log built for the BeaverBuddies Stability Fork in `1.0.10-perflog-preview` and `preview2` +The measuring core is the frame rate log built for the BeaverBuddies Stability Fork in `v1.0.10-perflog-preview` and `v1.0.10-perflog-preview2` ([`perflog-preview` branch](https://github.com/timbermods/BeaverBuddies-Stability-Fork/tree/perflog-preview)), rebuilt as a standalone mod that works in single player and with any mods. What is new: it hooks the game itself (no other mod's code has to be edited), attributes time to mods, records loading and saves, generates its own readme and summary, and comes with the analysis tool. What is left out because it is about the co-op layer: the network and event-hash @@ -128,19 +136,23 @@ timings, waits for the other player, and the garbage collection experiment (this ## Build from source -Install the .NET 8 SDK and Python 3, and have Timberborn (and the Harmony Workshop mod) installed: +Install the .NET 8 SDK and Python 3, and have Timberborn and the **Harmony** and **Mod Settings** Workshop mods installed (the build references their DLLs): ```powershell .\build.ps1 -GameDir 'C:\Program Files (x86)\Steam\steamapps\common\Timberborn' ``` -builds the mod, runs the checks, and creates `dist\PerformanceLog-0.1.2.zip`. `.\build.ps1 -Install` also copies it into your `Mods` folder. The checks alone: +builds the mod, runs the checks, and creates `dist\PerformanceLog-.zip` (the version in `packaging/manifest.json`). `.\build.ps1 -Install` also copies it into +your `Mods` folder. The checks alone: ``` dotnet run --project tests -c Release python -m unittest discover -s tools -p "test_perflog.py" ``` +If Timberborn is not in the default Steam folder, pass `-GameDir` to `build.ps1` as above. To run the checks alone, give them the game folder too: +`dotnet run --project tests -c Release -p:GameDir='' -- --managed '\Timberborn_Data\Managed'`. + No game, Unity or Harmony DLLs are redistributed; they are only build references. See [CLAUDE.md](CLAUDE.md) for how the code is laid out and how to change it. ## License diff --git a/docs/SESSION-README.md b/docs/SESSION-README.md index d6f7769..a418c49 100644 --- a/docs/SESSION-README.md +++ b/docs/SESSION-README.md @@ -5,7 +5,7 @@ only. The mod never changes what the game simulates, so a recording shows the ga **If you are a Claude chat asked to find out why this session was slow: read `summary.md` first, then this file's "Diagnosing" section, then dig into the CSV files with the questions it gives you.** Nothing here is a verdict. The numbers say where time and -memory went; what to change is a judgement you make from them, and you should say how sure you are. +memory went; what to change is a judgment you make from them, and you should say how sure you are. ## The files @@ -56,9 +56,9 @@ Start by writing down what the complaint is, because the causes differ: 1. **`otherMs` is the biggest part**, and `plPost` (or `ftWait`, `ftGpu`) is large: the game thread is waiting for the graphics card or vertical sync, not computing. Look at `mainCpuMs` against `frameMs`: a game thread far under 100% busy confirms it. **First rule out that this is vertical sync - doing its job:** with vsync on (`# display|` says `vSyncCount=1`) frames sit at the refresh interval (16.7 ms at 60 Hz) whenever the computer has time to + doing its job:** with vsync on (`# display:` says `vSyncCount=1`) frames sit at the refresh interval (16.7 ms at 60 Hz) whenever the computer has time to spare, and that wait is healthy, not slowness. It only points at the graphics card when the frames are *longer* than the sync interval (or vsync is off) and the - game thread is still not busy. Then check `prDraw`/`prSetPass`/`prBatches`/`prTris` (a lot of drawing), the resolution and `# gpu|`. This is a + game thread is still not busy. Then check `prDraw`/`prSetPass`/`prBatches`/`prTris` (a lot of drawing), the resolution and `# gpu:`. This is a graphics-settings problem, not a mod problem, unless a mod adds drawing. When frames are pinned at the sync interval, **compare work, not frame time**: the sum of the timed parts (everything but `otherMs`) is what a change in the game or a mod moves. 2. **`updMs` is big**: per-frame singleton updates (the user interface, the camera, input, and many mods). `profile.csv` rows of kind @@ -73,16 +73,22 @@ Start by writing down what the complaint is, because the causes differ: 4. **`saveMs`**: the game saving. `events.csv` has each save with its stages. (A mod that defers the save to the end of a tick, such as BeaverBuddies, makes the `queued save` event read about 0 ms; the `save (writing the world)` event is the real one.) 5. **Garbage collection**: `gcDelta` > 0 in slow frames; a sawtooth `heapMB`; large allocation per tick (`tickKB`, `singKB`, `entKB`, and `allocKB` per - second in `summary.md`). Long collection pauses on one computer and not another point at settings (`# gc|`, `# bootconfig|` for + second in `summary.md`). Long collection pauses on one computer and not another point at settings (`# gc:`, `# bootconfig|` for `gc-max-time-slice`, `# cmdline|`). Which singleton or entity kind allocates the most is in `profile.csv` (`allocKB`). ### Which mod is it? - `profile.csv` and `spikes.csv` carry `mod`. Add up `ms` per mod within a kind (do not add kinds together where they overlap: `entity` and `component` rows both live inside `entMs`). -- `# 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`). +- `# patch|` lines in the `frames.csv` header list which mod patches which hot method (`hot`), which methods several mods patch (`shared`), every + other method another mod patches (`other`), 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`). +- **A mod's patch on an event handler is charged to whatever raised the event.** The game calls a handler (an `[OnEvent]` method, or one hooked to a + C# event, such as `StockpileVisualizers.OnInventoryChanged`) at once, inside the code that changed something, so the patch has no row of its own: its + time is in whatever was running (an entity's tick, in `entMs` and that entity's `entity` and `component` rows; a singleton's row; or `otherMs` when + nothing timed was running). An event posted while the game loads waits for `EventBus`'s `post-load` step, so its `[OnEvent]` handlers are charged + there. The `# patch|other|` and `# patch|shared|` lines name these handlers in full; a `Watch` entry with that name times one, with every patch on it + (kind `method`). - 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 776e3c4..8a0002b 100644 --- a/docs/TESTING.md +++ b/docs/TESTING.md @@ -1,8 +1,8 @@ # What has been checked, and how to check the rest in a game -Version 0.1.0 was run in a game once (the first recording, below); 0.1.1 fixed what that showed, 0.1.2 added an in-game settings page, and 0.1.3 changed -the defaults to `Profile = deep` and a wider sampling budget, for the most detail with nothing configured. Nothing from 0.1.1 onward has been tested with -the game running. This is the honest list. +Version 0.1.0 was the first to run in a game (the first recording, below). 0.1.1 fixed what that showed, 0.1.2 added an in-game settings page, and 0.1.3 +changed the defaults to `Profile = deep` and a wider sampling budget, for the most detail with nothing configured. 0.1.1 and 0.1.3 have both been played +since. A 0.1.3 recording (below) shows the `deep` default working, and every 0.1.1 fix that a recording can show. This is the honest list. ## Verified by the automated checks @@ -52,17 +52,46 @@ Worked: - **Loading steps and the milestones**, and the summary rewritten every minute. - **Coexisting with Late Game Performance** (which patches the same save methods): both mods' patches were installed on the same methods without a failure; the header lists them side by side. -Did not work, or was wrong (all fixed in 0.1.1, see the changelog): the wrapper swapping four times a frame, every game singleton labelled unknown, `workingMB` 0, files held open, no allocation on +Did not work, or was wrong (all fixed in 0.1.1, see the changelog): the wrapper swapping four times a frame, every game singleton labeled unknown, `workingMB` 0, files held open, no allocation on loading steps, the `LoadAll never ran` counter, and `prDraw`/`prBatches` 0. Not available in this game, and not going to be: `GC Allocated In Frame`, `GC Allocation In Frame Count` and `Batches Count` do not exist in Unity 6's player (they are not in `UnityPlayer.dll`), and -the mod's probe rejected `GC.GetAllocatedBytesForCurrentThread` (the method is in the game's `mscorlib.dll` and Mono runtime; 0.1.0 did not record why, 0.1.1 does), so **allocation is the size of the managed -heap and is coarse**. The per-singleton `KB/s` figures are therefore only good in aggregate. +the mod's probe rejected `GC.GetAllocatedBytesForCurrentThread` (the method is in the game's `mscorlib.dll` and Mono runtime; 0.1.0 did not record why, and every recording since says it +`did not count a 64 KB allocation (read 0, then 0)`), so **allocation is the size of the managed heap and is coarse**. The per-singleton `KB/s` figures are therefore only good in aggregate. + +## Verified in a real game: 0.1.3 with its defaults (2026-09-21) + +Session `2026-09-21_23-13-11`: the same computer, game and Unity as the first recording, ten mods (BeaverBuddies MultiColony 1.4.0-beta2, Late Game Performance 0.4.23, +MixedStorage 0.5.8, Hungry Pathing 0.1.0, Optimized Local Housing 1.0.1, Persistent Work Areas 0.1.3, The Tipsy Tail 0.2.7.0, Mod Settings, Harmony and this mod) and every +setting at its default (the `# config:` header line). 43.9 minutes: 236917 frames and 25511 ticks (76% of the frames at speed 7), a colony of 359 beavers and 11.7 thousand +entities, nine saves (eight queued, one on exit) and a normal exit (`session-end`, "the game was left"). The window was in the background for 81% of the frames, so this +recording says little about the frame rate. + +What it shows, and the line that shows it: +- **The 0.1.1 fixes** (item 1 of the list below until this recording; zipping a folder while the game runs is still there): + - Each singleton service is wrapped once: `# capability-final|patchCalls|singleton wrappers put in place|3` for the whole recording (0.1.0: 488601 in 122150 frames). Every 0.1.1 and + 0.1.3 recording that reached its closing lines says 2 to 5. + - `workingMB` is 5587 to 7090 in the `S` rows, and `# capability|workingSet|from Windows`. + - The game's own singletons are labeled `game`: no singleton row in `profile.csv` has an empty `mod`. + - Loading steps carry the heap growth: 310 of the 618 loading rows in `profile.csv` have a non-zero `allocKB`, and `summary.md` lists the steps that grew the heap most + (`WorldEntitiesLoader` 411 MB of 2212 MB in all steps). + - `prDraw` is non-zero: `# capability-final|profilerRecorder|Draw Calls Count|produced values, largest 37554`, about 16.6 thousand draw calls a frame on average. + - `# capability-final|patchCalls|SingletonLifecycleService.LoadAll|1`, not `never ran`, and the allocation source line says why the exact counter is not used (above). +- **`Profile = deep` as the default** (item 8 of the list below until this recording): `# capability|patch|TickableEntity.Tick|installed` and + `# capability|patch|MeteredTickableComponent.Tick|installed`, `# capability-final|patchCalls|MeteredTickableComponent.Tick (sampled calls)|47081184`, and 3475 `component` + rows in `profile.csv` for 47 component classes (`BehaviorManager` the biggest). All eight 0.1.3 recordings so far say `# profile: deep`. +- **The settings page's `Load()` against the real Mod Settings services** (part of item 7): `profile.csv` has a `load` row for `PerformanceLog.PerformanceSettings` + (once, 0.10 ms), and the `# config:` header line has the six numbers at their defaults after `PerformanceSettings.ApplyTo` ran on them; a setting `Load()` had not + filled would have read 0 and been clamped to its minimum (`SlowFrameMs` 1, `SpikeContributors` 0). `Player.log` (it keeps only the latest launch, session + `2026-09-22_00-39-06`) has no warning or exception from this mod or Mod Settings. +- **What measuring cost, by the mod's own estimate:** `overheadUs` + `probeUs` averaged 50 µs of an 11.1 ms frame, 0.45% (0.5% in the windows at speed 7 with the game in front, + 0.8% in the costliest window), under the report's 2% line. That estimate rests on a patch cost the calibration read as 0 (`# calibration|...|patchCallNs|0`, as in every + recording so far), which charges each per-call patch either the 40 ns default or next to nothing, not a measurement; item 2 still stands. ## Still not verified: needs the running game -1. **The 0.1.1 fixes themselves**: that each service is wrapped once (`# capability-final|patchCalls|singleton wrappers put in place` should be a handful, not hundreds of thousands), that the four files - can be zipped while the game runs, that `workingMB` is non-zero, that game singletons show `game`, that loading steps show a heap growth, and that `prDraw` is non-zero. +1. **Copying or zipping a session folder while the game runs** (0.1.1): a recording cannot show it. `WriterTests.ReadableWhileRunning` and `RetriesWhenHeld` check it outside + the game. The other 0.1.1 fixes are verified in the game (above). 2. **Overhead** measured against a game running without the mod. The mod's own estimate (0.1.0: 0.3% of a frame paused, 0.8% at speed 7) left out the wrapper swapping and used a default cost for a patch; 0.1.1 measures the patch cost, but nobody has compared the frame rate with the mod off. See the checklist. 3. **Co-op**: with BeaverBuddies actually connected to another player. It has only been seen running with BeaverBuddies loaded in a single-player game. @@ -71,16 +100,10 @@ heap and is coarse**. The per-singleton `KB/s` figures are therefore only good i a mod whose DLL is not in its own folder may still read as unknown. 6. **The report's advice on a bad recording.** The first recording was mostly paused and in the background, so the findings for real problems (a slow simulation, a saving hitch, a memory leak, a mod that costs too much) have been exercised on made-up sessions and one real, healthy one. -7. **The in-game settings page (0.1.2, entirely unplayed)**: that Mod Settings actually shows it, that `RangeIntModSetting` renders as something usable and - the readonly note as readable text, and that `PerformanceSettings.Load()` does not throw against the real `ISettings`/`ModRepository`/`ModSettingsOwnerRegistry` - (only checked against `null`s standing in for them, which never calls `Load()`; see `Settings.cs`'s own notes). Then that a value changed there actually - reaches `Session.Start` — change `SlowFrameMs`, load a save, and check `frames.csv`'s `# thresholdMs` header line against what was set. -8. **`Profile = deep` as the default (0.1.3, entirely unplayed)**: the first recording used `standard`, so the patch on `MeteredTickableComponent.Tick` - (every entity component, sampled) has never actually run in a real game — only had its target validated against the real assemblies. Check that it - installs (`# capability|patch|TickableEntity.Tick`/`MeteredTickableComponent.Tick|installed` in the header) and that `profile.csv` gets `component` - rows. Check the real cost too: the wider sampling budget (0.5% → 1%) plus component sampling should cost more than the first recording's 0.3-0.8% of - 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. +7. **The in-game settings page (0.1.2)**: that Mod Settings actually shows it, that `RangeIntModSetting` renders as something usable and the readonly note as + readable text, and that a value changed there actually reaches `Session.Start` — change `SlowFrameMs`, load a save, and check `frames.csv`'s `# thresholdMs` + header line against what was set. Every 0.1.3 recording so far has the default `# thresholdMs: 50`. (`PerformanceSettings.Load()` against the real + `ISettings`/`ModRepository`/`ModSettingsOwnerRegistry` is verified in the game, above.) ## Five-minute check in a game @@ -93,7 +116,7 @@ heap and is coarse**. The per-singleton `KB/s` figures are therefore only good i - **Where an average frame goes** has non-zero `tickMs`/`entMs`/`updMs` and the parts add up (`otherMs` is the remainder). - **Simulation ticks** says a plausible number of ticks per second (about 3.3 at speed 1 if the tick is 0.3 s). - **Where the time goes** lists singletons with their mods (the game's own show as `game`; a mod you have enabled should show under its id). - - The **mod list** matches what you enabled. + - **Mods enabled** matches what you enabled. 6. In the `frames.csv` header: `# thresholdMs: 77` (the value set in step 1, proving the settings page reached the session). Every `# capability|patch|...` line says `installed`, **including `MeteredTickableComponent.Tick`** (deep is the default now, so this should install without being asked); the `# capability-final|patchCalls|...` lines at the end say non-zero counts, and none says `never ran`, including `MeteredTickableComponent.Tick (sampled calls)`. diff --git a/tests/fixtures/sample-with-mod/README.md b/tests/fixtures/sample-with-mod/README.md index 2687cb5..f1c7da9 100644 --- a/tests/fixtures/sample-with-mod/README.md +++ b/tests/fixtures/sample-with-mod/README.md @@ -5,7 +5,7 @@ only. The mod never changes what the game simulates, so a recording shows the ga **If you are a Claude chat asked to find out why this session was slow: read `summary.md` first, then this file's "Diagnosing" section, then dig into the CSV files with the questions it gives you.** Nothing here is a verdict. The numbers say where time and -memory went; what to change is a judgement you make from them, and you should say how sure you are. +memory went; what to change is a judgment you make from them, and you should say how sure you are. ## The files @@ -56,9 +56,9 @@ Start by writing down what the complaint is, because the causes differ: 1. **`otherMs` is the biggest part**, and `plPost` (or `ftWait`, `ftGpu`) is large: the game thread is waiting for the graphics card or vertical sync, not computing. Look at `mainCpuMs` against `frameMs`: a game thread far under 100% busy confirms it. **First rule out that this is vertical sync - doing its job:** with vsync on (`# display|` says `vSyncCount=1`) frames sit at the refresh interval (16.7 ms at 60 Hz) whenever the computer has time to + doing its job:** with vsync on (`# display:` says `vSyncCount=1`) frames sit at the refresh interval (16.7 ms at 60 Hz) whenever the computer has time to spare, and that wait is healthy, not slowness. It only points at the graphics card when the frames are *longer* than the sync interval (or vsync is off) and the - game thread is still not busy. Then check `prDraw`/`prSetPass`/`prBatches`/`prTris` (a lot of drawing), the resolution and `# gpu|`. This is a + game thread is still not busy. Then check `prDraw`/`prSetPass`/`prBatches`/`prTris` (a lot of drawing), the resolution and `# gpu:`. This is a graphics-settings problem, not a mod problem, unless a mod adds drawing. When frames are pinned at the sync interval, **compare work, not frame time**: the sum of the timed parts (everything but `otherMs`) is what a change in the game or a mod moves. 2. **`updMs` is big**: per-frame singleton updates (the user interface, the camera, input, and many mods). `profile.csv` rows of kind @@ -73,16 +73,22 @@ Start by writing down what the complaint is, because the causes differ: 4. **`saveMs`**: the game saving. `events.csv` has each save with its stages. (A mod that defers the save to the end of a tick, such as BeaverBuddies, makes the `queued save` event read about 0 ms; the `save (writing the world)` event is the real one.) 5. **Garbage collection**: `gcDelta` > 0 in slow frames; a sawtooth `heapMB`; large allocation per tick (`tickKB`, `singKB`, `entKB`, and `allocKB` per - second in `summary.md`). Long collection pauses on one computer and not another point at settings (`# gc|`, `# bootconfig|` for + second in `summary.md`). Long collection pauses on one computer and not another point at settings (`# gc:`, `# bootconfig|` for `gc-max-time-slice`, `# cmdline|`). Which singleton or entity kind allocates the most is in `profile.csv` (`allocKB`). ### Which mod is it? - `profile.csv` and `spikes.csv` carry `mod`. Add up `ms` per mod within a kind (do not add kinds together where they overlap: `entity` and `component` rows both live inside `entMs`). -- `# 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`). +- `# patch|` lines in the `frames.csv` header list which mod patches which hot method (`hot`), which methods several mods patch (`shared`), every + other method another mod patches (`other`), 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`). +- **A mod's patch on an event handler is charged to whatever raised the event.** The game calls a handler (an `[OnEvent]` method, or one hooked to a + C# event, such as `StockpileVisualizers.OnInventoryChanged`) at once, inside the code that changed something, so the patch has no row of its own: its + time is in whatever was running (an entity's tick, in `entMs` and that entity's `entity` and `component` rows; a singleton's row; or `otherMs` when + nothing timed was running). An event posted while the game loads waits for `EventBus`'s `post-load` step, so its `[OnEvent]` handlers are charged + there. The `# patch|other|` and `# patch|shared|` lines name these handlers in full; a `Watch` entry with that name times one, with every patch on it + (kind `method`). - 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 2687cb5..f1c7da9 100644 --- a/tests/fixtures/sample-without-mod/README.md +++ b/tests/fixtures/sample-without-mod/README.md @@ -5,7 +5,7 @@ only. The mod never changes what the game simulates, so a recording shows the ga **If you are a Claude chat asked to find out why this session was slow: read `summary.md` first, then this file's "Diagnosing" section, then dig into the CSV files with the questions it gives you.** Nothing here is a verdict. The numbers say where time and -memory went; what to change is a judgement you make from them, and you should say how sure you are. +memory went; what to change is a judgment you make from them, and you should say how sure you are. ## The files @@ -56,9 +56,9 @@ Start by writing down what the complaint is, because the causes differ: 1. **`otherMs` is the biggest part**, and `plPost` (or `ftWait`, `ftGpu`) is large: the game thread is waiting for the graphics card or vertical sync, not computing. Look at `mainCpuMs` against `frameMs`: a game thread far under 100% busy confirms it. **First rule out that this is vertical sync - doing its job:** with vsync on (`# display|` says `vSyncCount=1`) frames sit at the refresh interval (16.7 ms at 60 Hz) whenever the computer has time to + doing its job:** with vsync on (`# display:` says `vSyncCount=1`) frames sit at the refresh interval (16.7 ms at 60 Hz) whenever the computer has time to spare, and that wait is healthy, not slowness. It only points at the graphics card when the frames are *longer* than the sync interval (or vsync is off) and the - game thread is still not busy. Then check `prDraw`/`prSetPass`/`prBatches`/`prTris` (a lot of drawing), the resolution and `# gpu|`. This is a + game thread is still not busy. Then check `prDraw`/`prSetPass`/`prBatches`/`prTris` (a lot of drawing), the resolution and `# gpu:`. This is a graphics-settings problem, not a mod problem, unless a mod adds drawing. When frames are pinned at the sync interval, **compare work, not frame time**: the sum of the timed parts (everything but `otherMs`) is what a change in the game or a mod moves. 2. **`updMs` is big**: per-frame singleton updates (the user interface, the camera, input, and many mods). `profile.csv` rows of kind @@ -73,16 +73,22 @@ Start by writing down what the complaint is, because the causes differ: 4. **`saveMs`**: the game saving. `events.csv` has each save with its stages. (A mod that defers the save to the end of a tick, such as BeaverBuddies, makes the `queued save` event read about 0 ms; the `save (writing the world)` event is the real one.) 5. **Garbage collection**: `gcDelta` > 0 in slow frames; a sawtooth `heapMB`; large allocation per tick (`tickKB`, `singKB`, `entKB`, and `allocKB` per - second in `summary.md`). Long collection pauses on one computer and not another point at settings (`# gc|`, `# bootconfig|` for + second in `summary.md`). Long collection pauses on one computer and not another point at settings (`# gc:`, `# bootconfig|` for `gc-max-time-slice`, `# cmdline|`). Which singleton or entity kind allocates the most is in `profile.csv` (`allocKB`). ### Which mod is it? - `profile.csv` and `spikes.csv` carry `mod`. Add up `ms` per mod within a kind (do not add kinds together where they overlap: `entity` and `component` rows both live inside `entMs`). -- `# 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`). +- `# patch|` lines in the `frames.csv` header list which mod patches which hot method (`hot`), which methods several mods patch (`shared`), every + other method another mod patches (`other`), 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`). +- **A mod's patch on an event handler is charged to whatever raised the event.** The game calls a handler (an `[OnEvent]` method, or one hooked to a + C# event, such as `StockpileVisualizers.OnInventoryChanged`) at once, inside the code that changed something, so the patch has no row of its own: its + time is in whatever was running (an entity's tick, in `entMs` and that entity's `entity` and `component` rows; a singleton's row; or `otherMs` when + nothing timed was running). An event posted while the game loads waits for `EventBus`'s `post-load` step, so its `[OnEvent]` handlers are charged + there. The `# patch|other|` and `# patch|shared|` lines name these handlers in full; a `Watch` entry with that name times one, with every patch on it + (kind `method`). - 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.