Sample watched methods at their own rate (PL1); charge patch calls what they cost (NF2)

docs/SESSION-README.md

@@ -32,7 +32,8 @@ memory went; what to change is a judgment you make from them, and you should say
    sources worked on this computer. `prGcBytes`, `ftGpu` and friends are 0 when Unity's release build does not provide them; `mainCpuMs` is 0
    off Windows.
 7. **`profile.csv` is partly estimated.** Singletons are timed on every call. Entity kinds, components and watched methods are timed on every Nth
-   call and scaled up (`sampled` says how many real timings a row rests on; a small number means a rough figure). `allocKB` is coarse when the
+   call and scaled up (`sampled` says how many real timings a row rests on; a small number means a rough figure, and a watched method's row with
+   `sampled` 0 was not timed at all, so its `ms` is unknown, not 0). `allocKB` is coarse when the
    allocation source is the heap size (see the `allocSource` capability line).
 8. **Measuring costs something.** `overheadUs` (the estimate) plus `probeUs` (closing the frame) are microseconds per frame that the mod itself used.
    If they are more than about 2% of `frameMs`, say so before trusting small differences.

docs/TESTING.md

@@ -6,14 +6,16 @@ since. A 0.1.3 recording (below) shows the `deep` default working, and every 0.1
 
 ## Verified by the automated checks
 
-`dotnet run --project tests -c Release` (92 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (48 checks).
+`dotnet run --project tests -c Release` (101 checks) and `python -m unittest discover -s tools -p "test_perflog.py"` (50 checks).
 
 | What | How |
 |---|---|
 | Frame accounting: slots are exclusive and add up to the frame; unbalanced scopes; other threads ignored; allocation attribution; flags; ticks and buckets; Unity phases; summaries and histograms | Real `Probe` against a scripted clock (`CoreTests`) |
 | The per-frame path allocates nothing | `GC.GetAllocatedBytesForCurrentThread` around 2000 frames; also for a wrapper with the log off |
 | Failure containment: a failing clock switches the probe off, a full ring drops rows and counts them | `CoreTests` |
+| The cost charged for each patch call (`patchCallNs`) is at least what the entity patch's own bodies take on a call that is not sampled, timed with the log on and sampling held off (the part Harmony adds needs the game); the `# calibration|` line names both, or says `unmeasured` | `CoreTests.UnsampledBodyTiming`, `CoreTests.CalibrationLine`, `GameBindingTests.PatchCostCoversTheBodies` |
 | The profile: exact singleton timing, scaled sampling, random gaps that do not alias with a repeating pattern, budget adaptation, spike attribution, mod resolution, entities keyed by kind and not by a beaver's own name (`perflog.py` adds up older recordings' rows the same way) | `ProfileTests`, `test_perflog.EntityRollupTests` |
+| Watched methods: each is sampled at its own rate, widening with its own load inside the budget, kept through windows it is not called in (so bursts stay inside it too) and coming back down when it runs less, with a row (and at least one timing) for every window it ran in; calls nobody timed get a `sampled` 0 row and stay out of the totals | `WatchSamplingTests`, `test_perflog` |
 | The files: header, columns, invariant number format in any language, text tails, events, a file rewritten whole, an unopenable path, dropped rows, flush on stop | `WriterTests` |
 | `summary.md`, `README.md` and `columns.md` generation | `SummaryTests`, `WriterTests.EndToEnd` |
 | Every patch target exists in the installed game (1.1.2.4), has no exception filter, and takes only parameters Harmony can supply | `GameBindingTests.TargetsResolve` |
@@ -93,7 +95,11 @@ What it shows, and the line that shows it:
 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.
+   patch. 0.1.1 to 0.1.3 measured the patch cost on an empty patch, which shows 0 in every recording (`patchCallNs|0`): where it read exactly 0 the per-call patches were still charged the
+   40 ns default, where it read a fraction of a nanosecond they were charged almost nothing (`perflog.py` says which when a recording's rows show it). The cost is now the real bodies
+   (`patchBodyNs`) plus what Harmony adds (`patchCallNs`), but that has not run in a game yet, and nobody has compared the frame rate with the mod off. See the checklist. The figure is
+   the entity patch's; a watched method's call (config `Watch`) costs somewhat more (a lookup, and Harmony passing `__originalMethod`) and is charged the same, so with `Watch`
+   entries `overheadUs` still undercharges a little.
 3. **Co-op**: with BeaverBuddies actually connected to another player. It has only been seen running with BeaverBuddies loaded in a single-player game.
 4. **`Ticker.FinishFullTick`** (one of the four save-stage patches) is counted inside `save stages`, so it has not been seen separately; the stages of three saves were recorded.
 5. **The mod attribution** (which DLL belongs to which mod) worked for the mods in the first recording (`beaverbuddies`, `Kyler.OptimizedLocalHousing`, `eMka.ModSettings`, `kyler.persistentworkareas`);
@@ -124,6 +130,7 @@ What it shows, and the line that shows it:
    `# capability-final|patchCalls|...` lines at the end say non-zero counts, and none says `never ran`, including `MeteredTickableComponent.Tick (sampled calls)`.
    `singleton wrappers put in place` should be a handful (one or two per array). `# capability|workingSet|...` should say `from Windows`.
    `# capability-final|profilerRecorder|...` and `frameTiming` may legitimately say `never produced a value` in a release build.
+   `# calibration|...` has `patchBodyNs` and `patchCallNs` of a few nanoseconds each (not `0` and not `unmeasured`), `patchCallNs` at least `patchBodyNs`.
 7. `profile.csv` has rows of kind `component`, not just `entity`, and its `entity` rows are kinds: one `BeaverAdult`, not a `BeaverAdult(Clone)` and a row per beaver
    (`BeaverAdult Malak`). `summary.md`'s entity table says the same.
 8. Compare the frame rate the game shows with `summary.md`'s mean; they should agree.

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 and every Nth is timed.",
+            "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.",
             "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).",

source/Core/Probe.cs

@@ -92,7 +92,7 @@ public static class Probe
         /// <summary>Fills the heavy extras. Called only when a row is about to be written.</summary>
         public static Action<double[]> HeavySampler;
 
-        // What measuring costs, in Stopwatch ticks. Set by Calibrate (and PatchCallTicks by the game side).
+        // What measuring costs, in Stopwatch ticks. Set by Calibrate (and the two patch costs by the game side, with MeasureUnsampled).
         public static double ClockReadTicks { get; set; }
         public static double AllocReadTicks { get; set; }
         /// <summary>One timed scope: Begin and End.</summary>
@@ -103,8 +103,26 @@ public static class Probe
         public static double AllocPairTicks { get; set; }
         /// <summary>One call of a singleton that is always timed, without the allocation readings.</summary>
         public static double ExactCallTicks { get; set; }
-        /// <summary>Running one of this mod's Harmony patches that does nothing.</summary>
+        /// <summary>The bodies of this mod's per-call patch (the entity tick's prefix and postfix) on a call that is not sampled, which is almost every call.</summary>
+        public static double PatchBodyTicks { get; set; }
+        /// <summary>One call of this mod's per-call patches: <see cref="PatchBodyTicks"/> plus what Harmony adds to call a prefix and a postfix. 0 if not measured.</summary>
         public static double PatchCallTicks { get; set; }
+        /// <summary>What each patch call is charged in overheadUs: <see cref="PatchCallTicks"/>, or 40 ns when it could not be measured (the calibration line says so).</summary>
+        public static double PatchCallTicksCharged => PatchCallTicks > 0 ? PatchCallTicks : 40e-9 * Stopwatch.Frequency;
+
+        /// <summary>
+        /// The header's `# calibration|` line after its kind: what each part of measuring costs, in nanoseconds. patchBodyNs is the entity tick's
+        /// prefix and postfix on a call that is not sampled; patchCallNs is that plus what Harmony adds, which is what overheadUs charges each patch
+        /// call. Up to 0.1.3 there was no patchBodyNs and patchCallNs (an empty patch) read 0; tools/perflog.py tells the two apart by patchBodyNs.
+        /// </summary>
+        public static string[] CalibrationParts() => new[]
+        {
+            "clockReadNs", Ns(ClockReadTicks), "allocReadNs", Ns(AllocReadTicks), "scopePairNs", Ns(ScopePairTicks), "samplePairNs", Ns(SamplePairTicks),
+            "patchBodyNs", PatchBodyTicks > 0 ? Ns(PatchBodyTicks, "F1") : "unmeasured",
+            "patchCallNs", PatchCallTicks > 0 ? Ns(PatchCallTicks, "F1") : "unmeasured (" + Ns(PatchCallTicksCharged) + " assumed)",
+        };
+
+        static string Ns(double ticks, string format = "F0") => (ticks * 1e9 / Stopwatch.Frequency).ToString(format, System.Globalization.CultureInfo.InvariantCulture);
 
         public static bool OnGameThread => Environment.CurrentManagedThreadId == mainThreadId;
 
@@ -210,6 +228,45 @@ public static void Calibrate()
             catch (Exception e) { LastFailure = e.Message; }
         }
 
+        /// <summary>
+        /// Stopwatch ticks for one of the calls <paramref name="calls"/> makes when asked for n, timed the way a patch body runs on almost every
+        /// call while a log is on: the probe switched on, and entity and component sampling held off so that no call is one of the sampled ones
+        /// (those are charged separately). The fastest of a few rounds after a warm-up, so compiling and the scheduler do not decide the figure.
+        /// Only while no log is running (0 otherwise, or if it fails); the probe is off and the profile empty afterwards, as a log start expects.
+        /// </summary>
+        public static double MeasureUnsampled(Action<int> calls, int repeats = 4000, int rounds = 5)
+        {
+            if (Enabled || calls == null) return 0;
+            int savedThread = mainThreadId;
+            Func<long> savedClock = TestClock;
+            double best = 0;
+            try
+            {
+                mainThreadId = Environment.CurrentManagedThreadId;
+                TestClock = null;
+                Enabled = true;
+                Profile.HoldSampling();
+                calls(repeats / 10 + 1);
+                best = double.MaxValue;
+                for (int round = 0; round < rounds; round++)
+                {
+                    long t0 = Stopwatch.GetTimestamp();
+                    calls(repeats);
+                    best = Math.Min(best, (Stopwatch.GetTimestamp() - t0) / (double)repeats);
+                }
+            }
+            catch (Exception e) { LastFailure = e.Message; best = 0; }
+            finally
+            {
+                Enabled = false;
+                TestClock = savedClock;
+                mainThreadId = savedThread;
+                Array.Clear(counters, 0, counters.Length);
+                Profile.Reset();
+            }
+            return best;
+        }
+
         public static void Start(ProbeSettings settings)
         {
             Stop();
@@ -504,7 +561,7 @@ static void Frame(float speed, bool focused)
             r[Columns.HeapMB] = memory / 1048576.0;
             r[Columns.AllocKB] = allocKb;
             r[Columns.Dropped] = frameRing != null ? frameRing.Dropped : 0;
-            double patchTicks = counters[(int)Counter.PatchCalls] * (PatchCallTicks > 0 ? PatchCallTicks : 0.00000004 * Stopwatch.Frequency);
+            double patchTicks = counters[(int)Counter.PatchCalls] * PatchCallTicksCharged;
             r[Columns.OverheadUs] = (frameScopes * ScopePairTicks + profileCost + patchTicks) * msPerTick * 1000;
 
             for (int i = 0; i < Columns.CounterCount; i++) r[Columns.CounterBase + i] = counters[i];