diff --git a/docs/SESSION-README.md b/docs/SESSION-README.md index a418c49..4570cb5 100644 --- a/docs/SESSION-README.md +++ b/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. diff --git a/docs/TESTING.md b/docs/TESTING.md index 535579c..7c57096 100644 --- a/docs/TESTING.md +++ b/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. diff --git a/source/Core/Columns.cs b/source/Core/Columns.cs index 9f68d59..8068533 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 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).", diff --git a/source/Core/Probe.cs b/source/Core/Probe.cs index 08c88a7..ddfca17 100644 --- a/source/Core/Probe.cs +++ b/source/Core/Probe.cs @@ -92,7 +92,7 @@ public static class Probe /// Fills the heavy extras. Called only when a row is about to be written. public static Action 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; } /// One timed scope: Begin and End. @@ -103,8 +103,26 @@ public static class Probe public static double AllocPairTicks { get; set; } /// One call of a singleton that is always timed, without the allocation readings. public static double ExactCallTicks { get; set; } - /// Running one of this mod's Harmony patches that does nothing. + /// 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. + public static double PatchBodyTicks { get; set; } + /// One call of this mod's per-call patches: plus what Harmony adds to call a prefix and a postfix. 0 if not measured. public static double PatchCallTicks { get; set; } + /// What each patch call is charged in overheadUs: , or 40 ns when it could not be measured (the calibration line says so). + public static double PatchCallTicksCharged => PatchCallTicks > 0 ? PatchCallTicks : 40e-9 * Stopwatch.Frequency; + + /// + /// 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. + /// + 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; } } + /// + /// Stopwatch ticks for one of the 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. + /// + public static double MeasureUnsampled(Action calls, int repeats = 4000, int rounds = 5) + { + if (Enabled || calls == null) return 0; + int savedThread = mainThreadId; + Func 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]; diff --git a/source/Core/Profile.cs b/source/Core/Profile.cs index 3b5f0a8..c355870 100644 --- a/source/Core/Profile.cs +++ b/source/Core/Profile.cs @@ -41,7 +41,7 @@ public static class Profile new Column { Name = "tick", Kind = ColumnKind.Int, Aggregate = Aggregate.Last, Unit = "count", Description = "Simulation ticks since the log started, at the end of the window." }, new Column { Name = "id", Kind = ColumnKind.Int, Aggregate = Aggregate.Last, Unit = "", Description = "The key's number, the same in profile.csv and spikes.csv." }, new Column { Name = "calls", Kind = ColumnKind.Int, Aggregate = Aggregate.Sum, Unit = "count", Description = "Calls in the window. Exact for singletons and watched methods, estimated (samples times the interval) for entities and components." }, - new Column { Name = "sampled", Kind = ColumnKind.Int, Aggregate = Aggregate.Sum, Unit = "count", Description = "Calls that were actually timed. ms and allocKB are scaled up from these, so a small number means a rough estimate." }, + new Column { Name = "sampled", Kind = ColumnKind.Int, Aggregate = Aggregate.Sum, Unit = "count", Description = "Calls that were actually timed. ms and allocKB are scaled up from these, so a small number means a rough estimate. 0 (a watched method whose timed calls all threw) means none was: ms and allocKB are then unknown, not zero." }, new Column { Name = "ms", Kind = ColumnKind.Fixed2, Aggregate = Aggregate.Sum, Unit = "ms", Description = "Time spent in all the calls in the window (scaled up from the sampled ones), including everything inside them." }, new Column { Name = "allocKB", Kind = ColumnKind.Fixed1, Aggregate = Aggregate.Sum, Unit = "KB", Description = "Managed memory allocated by all the calls in the window (scaled up). Coarse when the allocation source is the heap size. For load steps (window 0) it is how much the managed heap grew during the step; a collection in the middle makes it read low." }, new Column { Name = "maxMs", Kind = ColumnKind.Fixed2, Aggregate = Aggregate.Max, Unit = "ms", Description = "The slowest timed call in the window. A large value with a small ms is a rare hitch." }, @@ -93,7 +93,8 @@ sealed class Entry public string Name = ""; public string Assembly = ""; public string Mod = ""; - public int MethodInterval = 8; + /// A watched method's interval for this window, and the one it was registered with (the least it goes back to). + public int MethodInterval = 8, GivenInterval = 8; } static readonly object gate = new object(); @@ -116,7 +117,7 @@ sealed class Entry // same order every frame, and a fixed stride can land on the same few of them every time and never on the rest. static int entityCountdown = 1, componentCountdown = 1, allocCountdown = 1; static uint random = 2463534242; - static long windowEntityCalls, windowComponentCalls, windowExactCalls, windowMethodCalls; + static long windowEntityCalls, windowComponentCalls, windowExactCalls; static int frameExact, frameAllocPairs, frameSampledPairs; static readonly double[] row = new double[Table.Count]; static readonly double[] spikeRow = new double[SpikeTable.Count]; @@ -165,7 +166,7 @@ public static void Reset() Array.Clear(totalCalls, 0, totalCalls.Length); Array.Clear(totalMax, 0, totalMax.Length); touchedCount = 0; TopCount = 0; SeedSampling(2463534242); - windowEntityCalls = 0; windowComponentCalls = 0; windowExactCalls = 0; windowMethodCalls = 0; + windowEntityCalls = 0; windowComponentCalls = 0; windowExactCalls = 0; frameExact = 0; frameAllocPairs = 0; frameSampledPairs = 0; EntityInterval = 16; ComponentInterval = 64; AllocEvery = 4; entityCountdown = Gap(EntityInterval); componentCountdown = Gap(ComponentInterval); allocCountdown = Gap(AllocEvery); @@ -195,6 +196,15 @@ public static void Configure(int entityInterval, int componentInterval, int allo entityCountdown = Gap(EntityInterval); componentCountdown = Gap(ComponentInterval); allocCountdown = Gap(AllocEvery); } + /// + /// Holds entity and component sampling off, so no call is one of the sampled ones, until the next or + /// . For timing what the patch bodies cost on the calls that are not sampled (). + /// + internal static void HoldSampling() + { + entityCountdown = int.MaxValue; componentCountdown = int.MaxValue; + } + // ---- keys ---- /// The id of a class's key, registering it on first use. Game thread only. @@ -341,10 +351,9 @@ public static void EndComponent(Type component, in Sample s) catch (Exception) { } } - /// Called before a watched method runs: counts the call exactly and times every Nth. + /// Called before a watched method runs: counts the call exactly, and times the first call of each window and about every Nth after it. public static Sample BeginMethod(int id) { - windowMethodCalls++; calls[id]++; if (--methodCounter[id] > 0) return default; methodCounter[id] = Gap(entries[id].MethodInterval); @@ -369,7 +378,7 @@ public static void EndMethod(int id, in Sample s) public static int RegisterMethod(string name, string assembly, int interval) { int id = IdFor(ProfileKind.Method, name, assembly); - lock (gate) entries[id].MethodInterval = Math.Max(1, interval); + lock (gate) entries[id].MethodInterval = entries[id].GivenInterval = Math.Max(1, interval); return id; } @@ -467,15 +476,28 @@ public static void FlushWindow(int window, int tick, double windowSeconds, Ring double msPerTick = 1000.0 / Stopwatch.Frequency; int count; lock (gate) count = entries.Count; + AdaptMethods(windowSeconds); for (int id = 0; id < count; id++) { if (calls[id] == 0 && timed[id] == 0) continue; - double factor = timed[id] > 0 ? (double)Math.Max(calls[id], timed[id]) / timed[id] : 0; + if (timed[id] == 0) + { + // Counted but never timed: a watched method whose timed calls all threw (Harmony skips the postfix then). The row says so + // with sampled 0; its time is unknown, so the session totals get nothing rather than these calls at 0 ms. + Array.Clear(row, 0, row.Length); + row[0] = (int)KindOf(id); row[1] = window; row[2] = tick; row[3] = id; row[4] = calls[id]; + target?.TryPush(row); + calls[id] = 0; ticks[id] = 0; allocN[id] = 0; allocB[id] = 0; max[id] = 0; + continue; + } + double factor = (double)Math.Max(calls[id], timed[id]) / timed[id]; double ms = ticks[id] * msPerTick * factor; double kb = allocN[id] > 0 ? allocB[id] / 1024.0 * ((double)Math.Max(calls[id], allocN[id]) / allocN[id]) : 0; double maxMs = max[id] * msPerTick; totalMs[id] += ms; totalKb[id] += kb; totalCalls[id] += calls[id]; if (maxMs > totalMax[id]) totalMax[id] = maxMs; - if (ms >= 0.005 || kb >= 0.5 || maxMs >= 0.5) + // A watched method gets a row for every window it ran in, however little it took (there are at most a few dozen), so a + // missing row always means it was not called. + if (ms >= 0.005 || kb >= 0.5 || maxMs >= 0.5 || KindOf(id) == ProfileKind.Method) { Array.Clear(row, 0, row.Length); row[0] = (int)KindOf(id); row[1] = window; row[2] = tick; row[3] = id; @@ -500,21 +522,45 @@ static void Adapt(double windowSeconds) ComponentInterval = Clamp((int)Math.Ceiling(windowComponentCalls / windowSeconds * pairSeconds / (budget * BudgetShareComponent)), 1, 8192); double allocPairSeconds = Math.Max(Probe.AllocPairTicks / frequency, 20e-9); AllocEvery = Clamp((int)Math.Ceiling(windowExactCalls / windowSeconds * allocPairSeconds / (budget * BudgetShareAlloc)), 1, 1024); - // Watched methods keep the interval they were given unless they turn out to be very hot. - lock (gate) + } + } + catch (Exception) { } + windowEntityCalls = 0; windowComponentCalls = 0; windowExactCalls = 0; + } + + /// + /// Chooses each watched method's interval for the next window from that method's own calls in this one, before they are forgotten. + /// It is set again every window the method ran in and never below the interval the method was given, so a method that was busy once + /// comes back down when it runs less, and a rare one next to a busy one keeps its own. A window it did not run in says nothing about + /// its rate, so its interval is kept: a method that is busy in bursts is timed at the interval its last burst needed, not at the given + /// one. The methods' share of the budget is split between the methods that ran. Each countdown starts again at 1, so a method that + /// runs in the next window has its first call timed. + /// + static void AdaptMethods(double windowSeconds) + { + try + { + lock (gate) + { + int ran = 0; + for (int id = 0; id < entries.Count; id++) + if (entries[id].Kind == ProfileKind.Method && calls[id] > 0) ran++; + bool measured = windowSeconds > 0 && Probe.SamplePairTicks > 0; + double pairSeconds = Probe.SamplePairTicks / Stopwatch.Frequency + 100e-9; // the key lookup too + double budget = BudgetFraction * BudgetShareMethod / Math.Max(1, ran); + for (int id = 0; id < entries.Count; id++) { - foreach (Entry e in entries) - { - if (e.Kind != ProfileKind.Method) continue; - double perSecond = windowMethodCalls / windowSeconds; - int wanted = Clamp((int)Math.Ceiling(perSecond * pairSeconds / (budget * BudgetShareMethod)), 1, 4096); - if (wanted > e.MethodInterval) e.MethodInterval = wanted; - } + Entry e = entries[id]; + if (e.Kind != ProfileKind.Method) continue; + methodCounter[id] = 1; + if (calls[id] == 0) continue; + double wanted = measured ? Math.Ceiling(calls[id] / windowSeconds * pairSeconds / budget) : 0; + int most = Math.Max(e.GivenInterval, 4096); + e.MethodInterval = wanted >= most ? most : Math.Max(e.GivenInterval, (int)wanted); } } } catch (Exception) { } - windowEntityCalls = 0; windowComponentCalls = 0; windowExactCalls = 0; windowMethodCalls = 0; } static int Clamp(int value, int low, int high) => value < low ? low : value > high ? high : value; diff --git a/source/Game/Instrumentation.cs b/source/Game/Instrumentation.cs index 425f188..029c674 100644 --- a/source/Game/Instrumentation.cs +++ b/source/Game/Instrumentation.cs @@ -284,13 +284,22 @@ static void InstallOne(PatchSpec spec) } /// - /// What running one of these patches costs when it does nothing, by patching a method of our own. Both loops are warmed up first (the first - /// call of a method is compiled, and a patched one goes through a freshly made wrapper), and the least of a few rounds is taken, so - /// one-off costs and the scheduler do not decide the figure. In the first game recording this read 0 because the unwarmed baseline - /// included the compile. + /// What each call of the per-call patches (entity ticks, components, watched methods) costs, for overheadUs. Two parts: the bodies of the + /// entity tick's prefix and postfix on a call that is not sampled (almost every call; a sampled call's extra cost is charged separately), + /// timed directly with the log on; and what Harmony adds to call a prefix and a postfix, by patching a method of our own with empty ones + /// of the same shape (patched minus unpatched, never below 0). Up to 0.1.3 only the second part was measured, and every recording says + /// patchCallNs 0: a reading of exactly 0 was charged as an assumed 40 ns, one just above 0 (under half a nanosecond) as itself, so overheadUs + /// charged the patches either a guess or almost nothing. Both loops of the second part are warmed + /// up first (the first call of a method is compiled, and a patched one goes through a freshly made wrapper), and the least of a few rounds + /// is taken, so one-off costs and the scheduler do not decide the figure. Every patch call is charged this one figure, so a call of a + /// watched method (whose prefix also looks the method up, and needs Harmony to pass __originalMethod) is still charged somewhat less + /// than it costs. /// internal static void MeasurePatchCost() { + double body = Probe.MeasureUnsampled(UnsampledEntityCalls); + if (body <= 0) Log.Warning("Could not measure what a patch body costs" + (Probe.LastFailure != null ? ": " + Probe.LastFailure : "") + "; overheadUs assumes 40 ns a patch call."); + double trampoline = 0; try { MethodInfo target = Reflect.Own(typeof(Instrumentation), nameof(CostTarget)); @@ -301,9 +310,21 @@ internal static void MeasurePatchCost() for (int i = 0; i < 400; i++) CostTarget(i); double patched = TimeCostTarget(repeats, rounds); harmony.Unpatch(target, HarmonyPatchType.All, HarmonyId); - Probe.PatchCallTicks = Math.Max(0, patched - baseline); + trampoline = Math.Max(0, patched - baseline); + } + catch (Exception e) { Log.Warning("Could not measure what Harmony adds to a patched call (only the patch bodies are counted): " + e.Message); } + Probe.PatchBodyTicks = body; + Probe.PatchCallTicks = body > 0 ? body + trampoline : 0; + } + + /// The entity tick's prefix and postfix, times, as Harmony calls them around a tick that is not sampled. + static void UnsampledEntityCalls(int calls) + { + for (int i = 0; i < calls; i++) + { + EntityPrefix(out Sample state); + EntityPostfix(null, state); } - catch (Exception e) { Log.Warning("Could not measure what a patch costs: " + e.Message); } } /// Stopwatch ticks for one call of : the fastest of several rounds. @@ -322,8 +343,9 @@ static double TimeCostTarget(int repeats, int rounds) static long costSink; [System.Runtime.CompilerServices.MethodImpl(System.Runtime.CompilerServices.MethodImplOptions.NoInlining)] static void CostTarget(int i) { costSink += i; } - internal static void CostPrefix(out long __state) { __state = 0; } - internal static void CostPostfix(long __state) { costSink += __state; } + // The same shape as the entity tick's pair (a Sample handed from prefix to postfix), with nothing in the bodies. + internal static void CostPrefix(out Sample __state) { __state = default; } + internal static void CostPostfix(Sample __state) { if (__state.On) costSink++; } // ---- the patch bodies ---- // Each starts with a read of Probe.Enabled. Nothing here may throw into the game, so anything that reads the game's own objects is diff --git a/source/Game/Session.cs b/source/Game/Session.cs index 754db5f..759a556 100644 --- a/source/Game/Session.cs +++ b/source/Game/Session.cs @@ -206,8 +206,7 @@ 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("calibration", "clockReadNs", Ns(Probe.ClockReadTicks), "allocReadNs", Ns(Probe.AllocReadTicks), "scopePairNs", Ns(Probe.ScopePairTicks), - "samplePairNs", Ns(Probe.SamplePairTicks), "patchCallNs", Ns(Probe.PatchCallTicks)); + 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"); header.Pipe("histogram", "frameEdgesMs", string.Join(",", Columns.FrameEdgesMs.Select(e => e.ToString(CultureInfo.InvariantCulture)))); @@ -225,8 +224,6 @@ static List BuildHeader(string modVersion) return header.Lines; } - static string Ns(double ticks) => (ticks * 1e9 / Stopwatch.Frequency).ToString("F0", CultureInfo.InvariantCulture); - // ---- during the game ---- /// Called at the start of each of Unity's frames, from the player loop. diff --git a/tests/CoreTests.cs b/tests/CoreTests.cs index 68e7d59..bdf5153 100644 --- a/tests/CoreTests.cs +++ b/tests/CoreTests.cs @@ -24,7 +24,7 @@ public Rig(double thresholdMs = 50, double summarySeconds = 100000, double profi Probe.Stop(); Probe.TestClock = () => Now; Alloc.UseTestSource(() => Bytes); - Probe.ScopePairTicks = 0; Probe.SamplePairTicks = 0; Probe.ExactCallTicks = 0; Probe.AllocPairTicks = 0; Probe.PatchCallTicks = 0; + Probe.ScopePairTicks = 0; Probe.SamplePairTicks = 0; Probe.ExactCallTicks = 0; Probe.AllocPairTicks = 0; Probe.PatchCallTicks = 0; Probe.PatchBodyTicks = 0; Probe.HeavySampler = null; Probe.Start(new ProbeSettings { @@ -92,6 +92,8 @@ internal static class CoreTests yield return ("Probe: a copy of the session counts does not change when the original does", StatsCloneIsIndependent); yield return ("Probe: measuring cost is estimated for each frame", OverheadEstimate); yield return ("Probe: calibration measures something and leaves the probe clean", CalibrationWorks); + yield return ("Probe: a patch body is timed with the log on and no call sampled, and the probe is left off and clean", UnsampledBodyTiming); + yield return ("Header: the calibration line names the patch body and patch call costs, and says when they were not measured", CalibrationLine); yield return ("Alloc: a counter is chosen, and a test source is followed", AllocSources); yield return ("Milestones: marks are kept in order and safe for the header", MilestoneLines); yield return ("PatchBuilder: hot, shared and other patches are listed, the mod's own are only counted", PatchReport); @@ -635,6 +637,63 @@ static void CalibrationWorks() Check(!Probe.Enabled, "and does not switch the probe on"); } + static void UnsampledBodyTiming() + { + Probe.Stop(); + Alloc.Init(); + Profile.Configure(1, 1, 1); + bool wasOn = true; + int sampled = 0, calls = 0; + double ticks = Probe.MeasureUnsampled(n => + { + for (int i = 0; i < n; i++) + { + wasOn &= Probe.Enabled; + Probe.Count(Counter.PatchCalls); + if (Profile.BeginEntity().On) sampled++; + if (Profile.BeginComponent().On) sampled++; + calls++; + } + }, 1000, 3); + Check(ticks > 0, "the calls took some time"); + Check(calls > 3000, "a warm-up and three rounds ran: " + calls); + Check(wasOn, "the probe was on while they ran, so the bodies took the path they take in a log"); + Equal(0, sampled, "no call was one of the sampled ones, although the intervals were 1"); + Check(!Probe.Enabled, "the probe is off afterwards"); + Equal(0, Profile.Count, "no keys are left behind"); + Equal(16, Profile.EntityInterval, "the sampling is back to where a log starts it"); + Check(Probe.MeasureUnsampled(n => throw new InvalidOperationException("broken")) == 0 && !Probe.Enabled, "a body that throws measures 0 and leaves the probe off"); + using (new Rig()) + { + Equal(0.0, Probe.MeasureUnsampled(n => calls++), "nothing is measured while a log runs"); + Check(Probe.Enabled, "and the log is left running"); + } + } + + static void CalibrationLine() + { + double body = Probe.PatchBodyTicks, call = Probe.PatchCallTicks; + try + { + // tools/perflog.py tells a recording that measured the patch bodies from an older one by the patchBodyNs name in this line. + double ticksPerNs = Stopwatch.Frequency / 1e9; + Probe.PatchBodyTicks = 8.27 * ticksPerNs; + Probe.PatchCallTicks = 8.97 * ticksPerNs; + string[] parts = Probe.CalibrationParts(); + Equal("clockReadNs samplePairNs patchBodyNs patchCallNs", string.Join(" ", parts[0], parts[6], parts[8], parts[10]), "names"); + Equal(12, parts.Length, "six name and value pairs"); + Equal("8.3", parts[9], "patchBodyNs, to a tenth of a nanosecond"); + Equal("9.0", parts[11], "patchCallNs, to a tenth of a nanosecond"); + Probe.PatchBodyTicks = 0; + Probe.PatchCallTicks = 0; + parts = Probe.CalibrationParts(); + Equal("unmeasured", parts[9], "patchBodyNs not measured"); + Equal("unmeasured (40 assumed)", parts[11], "patchCallNs not measured says what overheadUs charges instead"); + Check(parts.All(p => p.Length > 0 && p.IndexOf('|') < 0 && p.IndexOf(',') < 0 && p.IndexOf('\n') < 0), "no part holds a separator"); + } + finally { Probe.PatchBodyTicks = body; Probe.PatchCallTicks = call; } + } + // ---- allocation counter, milestones ---- static void AllocSources() diff --git a/tests/GameBindingTests.cs b/tests/GameBindingTests.cs index b280c47..cbb00ca 100644 --- a/tests/GameBindingTests.cs +++ b/tests/GameBindingTests.cs @@ -47,6 +47,7 @@ internal static class GameBindingTests yield return ("Game: a wrapper passes through exceptions and still times the call", WrapperExceptions); yield return ("Game: a wrapper does nothing extra when the log is off", WrapperWhenOff); yield return ("Game: patch bodies pair up and hand the scope token from prefix to postfix", PatchBodiesPair); + yield return ("Game: the cost charged for each patch call covers what the entity patch's own bodies take on a call that is not sampled", PatchCostCoversTheBodies); yield return ("Game: the game's own empty entity bucket is measured by the entity bucket patch", EntityBucketPatch); yield return ("Game: a save is tracked from its patch bodies into an event", SaveTracking); yield return ("Watch: named methods are found, and the ones that cannot be patched say why", WatchResolution); @@ -534,6 +535,47 @@ static void PatchBodiesPair() } } + static void PatchCostCoversTheBodies() + { + Action warnings = Log.WarningSink; + Log.WarningSink = _ => { }; + try + { + Probe.Stop(); + Probe.PatchCallTicks = 0; + // Harmony cannot patch in this process, so what needs a real patch is not measured here; the rest is. + Instrumentation.MeasurePatchCost(); + double charged = Probe.PatchCallTicks; + Check(Probe.PatchBodyTicks > 0, "the bodies were measured"); + Check(charged >= Probe.PatchBodyTicks, "a patch call is charged its bodies plus what Harmony adds, never less"); + Check(!Probe.Enabled, "measuring leaves the probe off"); + Equal(0, Profile.Count, "and leaves no keys behind"); + // The same bodies timed here directly, the way the game runs them on almost every call: the log on, and the call not one of the + // sampled ones (an interval of 4096 samples about one call in 4096; those few cost more, which only makes this figure larger). + // The fastest of ten rounds, as the calibration takes the fastest of its rounds: one long loop is slowed by any other program + // that takes the CPU for a moment, and that would decide the comparison. + double body = double.MaxValue; + using (new Rig()) + { + Profile.Configure(4096, 4096, 1); + const int calls = 100000, rounds = 10; + for (int i = 0; i < calls; i++) { Instrumentation.EntityPrefix(out Sample sample); Instrumentation.EntityPostfix(null, sample); } + for (int round = 0; round < rounds; round++) + { + long t0 = System.Diagnostics.Stopwatch.GetTimestamp(); + for (int i = 0; i < calls; i++) { Instrumentation.EntityPrefix(out Sample sample); Instrumentation.EntityPostfix(null, sample); } + body = Math.Min(body, (System.Diagnostics.Stopwatch.GetTimestamp() - t0) / (double)calls); + } + } + double ns = 1e9 / System.Diagnostics.Stopwatch.Frequency; + Console.WriteLine(" charged per patch call " + (charged * ns).ToString("F2") + " ns; the entity patch bodies timed here " + (body * ns).ToString("F2") + " ns"); + Check(body > 0, "the bodies take some time"); + // Half, because the two are timed separately and the machine may be busy with other work in between. + Check(charged >= 0.5 * body, "each patch call is charged " + (charged * ns).ToString("F2") + " ns, less than its own bodies take (" + (body * ns).ToString("F2") + " ns): overheadUs leaves the patches out"); + } + finally { Log.WarningSink = warnings; } + } + static void EntityBucketPatch() { Rig rig = StartRig(out _); diff --git a/tests/PL1WatchSamplingTests.cs b/tests/PL1WatchSamplingTests.cs new file mode 100644 index 0000000..53eecff --- /dev/null +++ b/tests/PL1WatchSamplingTests.cs @@ -0,0 +1,215 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; +using static PerformanceLog.Tests.Assert; + +namespace PerformanceLog.Tests +{ + // PL1: a watched method's sampling interval follows that method's own call rate, in both directions, and every window it ran in has a row. + internal static class WatchSamplingTests + { + public static IEnumerable<(string, Action)> All() + { + yield return ("Profile: a rare watched method next to a hot one is still timed in every window it runs", Restoring(RareMethodNextToHotOne)); + yield return ("Profile: a watched method's interval widens with its own load, inside the budget, and comes back down when the load goes away", Restoring(IntervalFollowsTheLoad)); + yield return ("Profile: a watched method called fewer times a window than its interval still has a call timed in every window", Restoring(FewCallsEveryWindow)); + yield return ("Profile: a watched method that is busy in bursts keeps the interval its bursts need through the windows it is not called", Restoring(BurstsStayInsideTheBudget)); + yield return ("Profile: a watched method that ran but was never timed gets a row with sampled 0 and adds no made-up 0 ms to the totals", Restoring(UntimedWindowIsWrittenNotGuessed)); + yield return ("Profile: several busy watched methods share the watched methods' budget between them, not each take all of it", Restoring(BusyMethodsShareTheBudget)); + } + + // Prepare sets the static budget; put the default back so the checks that run after these see what they would alone. + static Action Restoring(Action check) => () => + { + double budget = Profile.BudgetFraction; + try { check(); } + finally { Profile.BudgetFraction = budget; } + }; + + const double PairNs = 50; // what the real recordings calibrate for a sampled pair (samplePairNs) + + static Rig rig; + + static void Prepare() + { + rig = new Rig(); + Profile.Configure(1, 1, 1); + Profile.BudgetFraction = 0.01; + Profile.ModResolver = null; + Profile.SeedSampling(12345); + // A double, not Rig.Ms: Rig.Ms truncates to whole Stopwatch ticks, and 50 ns is 0 ticks at 10 MHz, which switches the adaptation off. + Probe.SamplePairTicks = PairNs * 1e-9 * Stopwatch.Frequency; + } + + static void Call(int id, double ms) + { + Sample s = Profile.BeginMethod(id); + rig.Advance(ms); + Profile.EndMethod(id, s); + } + + static double[] RowOf(List rows, int id) => rows.FirstOrDefault(r => (int)r[3] == id); + + static void RareMethodNextToHotOne() + { + Prepare(); + using (rig) + { + int hot = Profile.RegisterMethod("Hot.Method", "M", 8); + int rare = Profile.RegisterMethod("Rare.Method", "M", 8); + // Window 1: the hot one runs 2 million times in 10 s (200,000 a second, 1 us a call); the rare one once. + Call(rare, 5); + for (int i = 0; i < 2000000; i++) Call(hot, 0.001); + Profile.FlushWindow(1, 1, 10, rig.Prof); + rig.ProfileRows(); + // Windows 2 to 5: only the rare one runs, 20 times a window at 5 ms a call. Its own rate (2 a second) needs no more than the + // interval it was given (8), so every window times its first call and, with gaps of at most 15, at least one more. + for (int w = 2; w <= 5; w++) + { + for (int i = 0; i < 20; i++) Call(rare, 5); + Profile.FlushWindow(w, w, 10, rig.Prof); + double[] row = RowOf(rig.ProfileRows(), rare); + Console.WriteLine(" window " + w + ": rare method " + (row == null ? "has no row" : "calls=" + row[4] + " sampled=" + row[5] + " ms=" + row[6])); + Check(row != null, "window " + w + ": the rare method's 20 calls of 5 ms left no row (none was timed)"); + Equal(20.0, row[4], "window " + w + ": calls"); + Check(row[5] >= 2, "window " + w + ": only " + row[5] + " of 20 calls were timed; the interval is still the one the hot method needed"); + Near(100, row[6], .01, "window " + w + ": 20 calls of 5 ms"); + } + Profile.Total total = Profile.Totals().Single(t => t.Id == rare); + Equal(81.0, total.Calls, "session calls"); + Near(405, total.Ms, .01, "session ms: 5 ms, then four windows of 100 ms"); + } + } + + static void IntervalFollowsTheLoad() + { + Prepare(); + using (rig) + { + int hot = Profile.RegisterMethod("Hot.Method", "M", 8); + // Two busy windows of 200,000 calls a second: the second is timed at the interval the first asked for, which keeps measuring inside + // the watched methods' share of the budget (1% of a second, a tenth of it for methods). + double[] busy = null; + for (int w = 1; w <= 2; w++) + { + for (int i = 0; i < 2000000; i++) Call(hot, 0.001); + Profile.FlushWindow(w, w, 10, rig.Prof); + busy = RowOf(rig.ProfileRows(), hot); + Check(busy != null, "busy window " + w + ": no row"); + } + double pairSeconds = PairNs * 1e-9 + 100e-9; // the pair plus the key lookup, as Profile charges it + double share = busy[5] * pairSeconds / 10; + Console.WriteLine(" busy window: " + busy[5] + " of 2000000 calls timed, " + (share * 100).ToString("F3") + "% of a second"); + Check(busy[5] < 2000000 / 20.0, "a hot method's interval widens: " + busy[5] + " of 2000000 calls were timed"); + Check(share <= 0.01 * Profile.BudgetShareMethod * 1.05, "measuring stays inside the methods' share of the budget: " + share); + // Then the load goes away: 100 calls of 1 ms a window. The first quiet window is still timed at the busy interval; after it the + // interval is back to 8, so each later window times its first call and, with gaps of at most 15, at least six more. + for (int w = 3; w <= 6; w++) + { + for (int i = 0; i < 100; i++) Call(hot, 1); + Profile.FlushWindow(w, w, 10, rig.Prof); + double[] row = RowOf(rig.ProfileRows(), hot); + Console.WriteLine(" quiet window " + w + ": sampled=" + (row == null ? "no row" : row[5].ToString()) + " of 100 calls"); + Check(row != null, "window " + w + ": no row"); + Near(100, row[6], .01, "window " + w + ": 100 calls of 1 ms"); + if (w >= 4) Check(row[5] >= 7, "window " + w + ": only " + row[5] + " of 100 calls were timed; the interval never came back down after the busy windows"); + } + } + } + + static void FewCallsEveryWindow() + { + Prepare(); + using (rig) + { + // 3 calls a window at an interval of 8: without each window's countdown starting again at 1, whole windows go by untimed. + int id = Profile.RegisterMethod("Few.Method", "M", 8); + for (int w = 1; w <= 20; w++) + { + for (int i = 0; i < 3; i++) Call(id, 1); + Profile.FlushWindow(w, w, 10, rig.Prof); + double[] row = RowOf(rig.ProfileRows(), id); + Check(row != null && row[5] >= 1, "window " + w + ": 3 calls, none timed (" + (row == null ? "no row" : "sampled " + row[5]) + ")"); + Near(3, row[6], .01, "window " + w + ": 3 calls of 1 ms"); + } + } + } + + static void BurstsStayInsideTheBudget() + { + Prepare(); + using (rig) + { + // Busy in the odd windows (200,000 calls in a 1 s window), not called at all in the even ones. The first burst is timed at the + // given interval, as nothing is known yet; every later one at the interval the burst before it asked for, which a window with no + // calls does not undo. + int id = Profile.RegisterMethod("Bursty.Method", "M", 8); + double pairSeconds = PairNs * 1e-9 + 100e-9; + for (int w = 1; w <= 5; w++) + { + bool busy = w % 2 == 1; + if (busy) for (int i = 0; i < 200000; i++) Call(id, 0.001); + Profile.FlushWindow(w, w, 1, rig.Prof); + double[] row = RowOf(rig.ProfileRows(), id); + if (!busy) { Check(row == null, "window " + w + ": a row for a window the method was not called in"); continue; } + Check(row != null, "window " + w + ": no row"); + Near(200, row[6], .01, "window " + w + ": 200,000 calls of 1 us"); + double share = row[5] * pairSeconds; + Console.WriteLine(" burst window " + w + ": " + row[5] + " of 200000 calls timed, " + (share * 100).ToString("F3") + "% of a second"); + if (w >= 3) + Check(share <= 0.01 * Profile.BudgetShareMethod * 1.05, "burst window " + w + ": measuring took " + (share * 100).ToString("F3") + + "% of a second, over the watched methods' share of the budget: the quiet window before it undid the interval"); + } + } + } + + static void BusyMethodsShareTheBudget() + { + Prepare(); + using (rig) + { + // Four methods, each called 200,000 times in a 1 s window. After the first window each is timed at the interval that keeps all four + // together inside the methods' share of the budget; without the split each would take the whole share, four times over. + int[] ids = Enumerable.Range(0, 4).Select(i => Profile.RegisterMethod("Busy.Method" + i, "M", 8)).ToArray(); + double pairSeconds = PairNs * 1e-9 + 100e-9; + for (int w = 1; w <= 3; w++) + { + foreach (int id in ids) for (int i = 0; i < 200000; i++) Call(id, 0.001); + Profile.FlushWindow(w, w, 1, rig.Prof); + List rows = rig.ProfileRows(); + double share = ids.Sum(id => RowOf(rows, id)[5]) * pairSeconds; + Console.WriteLine(" window " + w + ": the four methods' timing took " + (share * 100).ToString("F3") + "% of a second"); + if (w >= 2) + Check(share <= 0.01 * Profile.BudgetShareMethod * 1.05, "window " + w + ": measuring the four took " + (share * 100).ToString("F3") + + "% of a second, over the watched methods' share of the budget: each took the whole share"); + } + } + } + + static void UntimedWindowIsWrittenNotGuessed() + { + Prepare(); + using (rig) + { + int id = Profile.RegisterMethod("Throwing.Method", "M", 8); + Call(id, 2); + Profile.FlushWindow(1, 1, 10, rig.Prof); + double[] first = RowOf(rig.ProfileRows(), id); + Check(first != null && first[5] == 1, "window 1: the one call was timed"); + // Window 2: three calls whose postfix never runs (the method threw, and Harmony skips a postfix then), so none is timed. + for (int i = 0; i < 3; i++) Profile.BeginMethod(id); + Profile.FlushWindow(2, 2, 10, rig.Prof); + double[] row = RowOf(rig.ProfileRows(), id); + Console.WriteLine(" untimed window: " + (row == null ? "no row" : "calls=" + row[4] + " sampled=" + row[5] + " ms=" + row[6])); + Check(row != null, "window 2: the method ran 3 times and left no row, which reads as 'not called'"); + Equal(3.0, row[4], "calls are still exact"); + Equal(0.0, row[5], "sampled 0 says nothing was timed"); + Profile.Total total = Profile.Totals().Single(t => t.Id == id); + Console.WriteLine(" totals: calls=" + total.Calls + " ms=" + total.Ms); + Equal(1.0, total.Calls, "the session totals leave out the calls nobody timed, instead of adding them at 0 ms"); + Near(2, total.Ms, .001, "session ms"); + } + } + } +} diff --git a/tests/Program.cs b/tests/Program.cs index 19aae02..cfb9f8a 100644 --- a/tests/Program.cs +++ b/tests/Program.cs @@ -60,6 +60,7 @@ static int Run(string[] args) var tests = new List<(string Name, Action Run)>(); tests.AddRange(CoreTests.All()); tests.AddRange(ProfileTests.All()); + tests.AddRange(WatchSamplingTests.All()); tests.AddRange(WriterTests.All()); tests.AddRange(SummaryTests.All()); tests.AddRange(GameBindingTests.All(managed)); diff --git a/tests/fixtures/sample-with-mod/README.md b/tests/fixtures/sample-with-mod/README.md index f1c7da9..5e8fadc 100644 --- a/tests/fixtures/sample-with-mod/README.md +++ b/tests/fixtures/sample-with-mod/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. @@ -122,7 +123,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 and every Nth is timed. +- `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. - `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 bbb3b39..4587124 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 and every Nth is timed. +- `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. - `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). @@ -125,7 +125,7 @@ One row per key per window. The last three columns (`name`, `assembly`, `mod`) a | `tick` | count | last | Simulation ticks since the log started, at the end of the window. | | `id` | | last | The key's number, the same in profile.csv and spikes.csv. | | `calls` | count | total | Calls in the window. Exact for singletons and watched methods, estimated (samples times the interval) for entities and components. | -| `sampled` | count | total | Calls that were actually timed. ms and allocKB are scaled up from these, so a small number means a rough estimate. | +| `sampled` | count | total | Calls that were actually timed. ms and allocKB are scaled up from these, so a small number means a rough estimate. 0 (a watched method whose timed calls all threw) means none was: ms and allocKB are then unknown, not zero. | | `ms` | ms | total | Time spent in all the calls in the window (scaled up from the sampled ones), including everything inside them. | | `allocKB` | KB | total | Managed memory allocated by all the calls in the window (scaled up). Coarse when the allocation source is the heap size. For load steps (window 0) it is how much the managed heap grew during the step; a collection in the middle makes it read low. | | `maxMs` | ms | largest | The slowest timed call in the window. A large value with a small ms is a rare hitch. | diff --git a/tests/fixtures/sample-without-mod/README.md b/tests/fixtures/sample-without-mod/README.md index f1c7da9..5e8fadc 100644 --- a/tests/fixtures/sample-without-mod/README.md +++ b/tests/fixtures/sample-without-mod/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. @@ -122,7 +123,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 and every Nth is timed. +- `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. - `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 bbb3b39..4587124 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 and every Nth is timed. +- `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. - `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). @@ -125,7 +125,7 @@ One row per key per window. The last three columns (`name`, `assembly`, `mod`) a | `tick` | count | last | Simulation ticks since the log started, at the end of the window. | | `id` | | last | The key's number, the same in profile.csv and spikes.csv. | | `calls` | count | total | Calls in the window. Exact for singletons and watched methods, estimated (samples times the interval) for entities and components. | -| `sampled` | count | total | Calls that were actually timed. ms and allocKB are scaled up from these, so a small number means a rough estimate. | +| `sampled` | count | total | Calls that were actually timed. ms and allocKB are scaled up from these, so a small number means a rough estimate. 0 (a watched method whose timed calls all threw) means none was: ms and allocKB are then unknown, not zero. | | `ms` | ms | total | Time spent in all the calls in the window (scaled up from the sampled ones), including everything inside them. | | `allocKB` | KB | total | Managed memory allocated by all the calls in the window (scaled up). Coarse when the allocation source is the heap size. For load steps (window 0) it is how much the managed heap grew during the step; a collection in the middle makes it read low. | | `maxMs` | ms | largest | The slowest timed call in the window. A large value with a small ms is a rare hitch. | diff --git a/tools/perflog.py b/tools/perflog.py index ea13ea3..821ac4a 100644 --- a/tools/perflog.py +++ b/tools/perflog.py @@ -47,6 +47,24 @@ SLOW_MEAN_MS = 20.0 LOAD_KINDS = ("load", "load-non-singleton", "post-load", "post-load-non-singleton") +# Up to 0.1.3 the `# calibration|` line's patchCallNs timed an empty patch instead of the patch bodies, and every recording shows 0 there. What +# overheadUs charged each call of the per-call patches then depends on a reading the header rounds away: exactly 0 made the mod charge an assumed +# 40 ns a call, a reading above 0 made it charge that. A reading above 0 in the header, or a row whose overheadUs is below 40 ns a patch call, proves +# the second, and an empty patch leaves the bodies out, so those calls were undercharged. +# Neither note is printed for a recording whose calibration line has patchBodyNs (KNOWN_ISSUE_APPLIES): a build of the fix that still carries an +# older version number measures the patch bodies already. +PATCH_CHARGE_ASSUMED_NS = 40.0 +PATCH_COST_NOTE = ("overheadUs understates what the mod itself cost: every call of its per-call patches (entity ticks, components, watched " + "methods; the patchCalls column) was charged less than they cost. patchCallNs in the `# calibration|` line timed an empty patch " + "instead of the real bodies and came out above 0 (the header says so, or this recording has rows whose overheadUs is below " + "the 40 ns a patch call the mod assumes when that reading is exactly 0), so those calls (about 100,000 a second at speed 7 with Profile = deep) " + "are missing from overheadUs and from the 'measuring cost more than 2% of a frame' warning. The real bodies take a few " + "nanoseconds a call, plus what Harmony adds.") +PATCH_COST_GUESS_NOTE = ("overheadUs's charge for the per-call patches (entity ticks, components, watched methods; the patchCalls column) is not " + "a measurement. patchCallNs|0 in the `# calibration|` line timed an empty patch instead of the real bodies: a reading of " + "exactly 0 made the mod charge an assumed 40 ns a call, one just above 0 made it charge almost nothing, and no row in " + "this recording shows which. The real bodies take a few nanoseconds a call, plus what Harmony adds.") + # Printed only for a recording whose entity rows really are split (KNOWN_ISSUE_APPLIES): a build of the fix that still carries an older version number # writes kinds already. ENTITY_SPLIT_NOTE = ("Entity rows are split by name: a beaver or bot loaded from the save is keyed by its own name ('BeaverAdult '; the game renames " @@ -66,17 +84,56 @@ ("0.1.1", "prDraw and prBatches are 0: Unity 6 has no counter by those names (its draw calls are split into several). The other columns are unaffected."), ("0.1.1", "While the game ran, frames.csv, profile.csv, spikes.csv and events.csv were held open by the mod, so copying or zipping the folder could leave them out " "(the folder listing shows size 0). Exit the game first, or read them with shared access."), + ("0.1.4", PATCH_COST_NOTE), + ("0.1.4", PATCH_COST_GUESS_NOTE), ("0.1.4", ENTITY_SPLIT_NOTE), ] +def _empty_patch_charges(session): + """For a recording whose `# calibration|` line has patchCallNs and no patchBodyNs (an empty patch was timed, not the bodies): how many + rows ran patches, how many of those were charged less than the 40 ns a patch call assumed for a reading of exactly 0, and the reading. + None otherwise.""" + calibration = session.pipe("calibration") + if not calibration or any("patchBodyNs" in parts for parts in calibration): + return None + reading = [parts[i + 1] for parts in calibration for i in range(len(parts) - 1) if parts[i] == "patchCallNs"] + try: + ns = float(reading[0]) if reading else None + except ValueError: + return None + if ns is None: + return None + ran = below = 0 + for r in session.rows: + calls, frames = r.get("patchCalls", 0.0), r.get("frames", 0.0) + if calls <= 0 or frames <= 0: + continue + ran += 1 + # overheadUs is a mean per frame, written to 0.1 us; patchCalls is the total over the row's frames. + if (r.get("overheadUs", 0.0) + 0.05) * frames < PATCH_CHARGE_ASSUMED_NS / 1000.0 * calls: + below += 1 + return ran, below, ns + + +def _patch_cost_was_understated(session): + charges = _empty_patch_charges(session) + return charges is not None and charges[0] > 0 and (charges[1] > 0 or charges[2] > 0) + + +def _patch_cost_was_a_guess(session): + charges = _empty_patch_charges(session) + return charges is not None and charges[0] > 0 and charges[1] == 0 and charges[2] == 0 + + def _entity_rows_are_split(session): return any(r["kind"] == "entity" and entity_kind(r.get("name", "")) != r.get("name", "") for r in session.profile) # Notes that only some recordings of the versions they name have, each with the check that finds the problem in a recording (a note not listed # here is printed for every recording made before its fix). -KNOWN_ISSUE_APPLIES = {ENTITY_SPLIT_NOTE: _entity_rows_are_split} +KNOWN_ISSUE_APPLIES = {PATCH_COST_NOTE: _patch_cost_was_understated, PATCH_COST_GUESS_NOTE: _patch_cost_was_a_guess, + ENTITY_SPLIT_NOTE: _entity_rows_are_split} GAME_ASSEMBLY_PREFIXES = ("Timberborn.", "Bindito.", "UnityEngine", "Unity.", "System") @@ -333,6 +390,7 @@ class KeyTotal: def __init__(self, kind, name, mod, assembly): self.kind, self.name, self.mod, self.assembly = kind, name, mod, assembly self.ms = self.kb = self.calls = self.sampled = self.max_ms = 0.0 + self.untimed = 0.0 # calls in rows with sampled 0 (a watched method nobody timed in that window): not in calls, so ms/calls stays honest def entity_kind(name): @@ -361,6 +419,9 @@ def profile_totals(session, tick_from=0, tick_to=None): t = totals.get(key) if t is None: t = totals[key] = KeyTotal(r["kind"], name, r.get("mod", ""), r.get("assembly", "")) + if r["sampled"] <= 0 and r["calls"] > 0: + t.untimed += r["calls"] + continue t.ms += r["ms"]; t.kb += r["allocKB"]; t.calls += r["calls"]; t.sampled += r["sampled"]; t.max_ms = max(t.max_ms, r["maxMs"]) return totals @@ -742,8 +803,9 @@ def report(session, args, out): all_ms = sum(t.ms for t in rows) 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" % ( - 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)) + 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 "")) mods = collections.defaultdict(lambda: [0.0, 0.0]) for t in totals.values(): if t.kind in ("tick-singleton", "update-singleton", "late-singleton"): diff --git a/tools/test_perflog.py b/tools/test_perflog.py index f123c66..f2dcd55 100644 --- a/tools/test_perflog.py +++ b/tools/test_perflog.py @@ -612,6 +612,35 @@ def test_an_older_mod_version_gets_its_known_issues_listed(self): s.window() self.assertNotIn("KNOWN ISSUE", self.report(s), "an unreadable version is not guessed at") + def test_a_recording_whose_patch_cost_read_0_is_told_what_overhead_charged_the_patches(self): + old = ["calibration", "clockReadNs", "23", "allocReadNs", "12", "scopePairNs", "109", "samplePairNs", "51", "patchCallNs", "0"] + new = ["calibration", "clockReadNs", "23", "allocReadNs", "12", "scopePairNs", "109", "samplePairNs", "51", "patchBodyNs", "6.2", "patchCallNs", "6.9"] + understated, guess = "overheadUs understates what the mod itself cost", "overheadUs's charge for the per-call patches" + # A 10 s window of 598.8 frames with 1000 patch calls a frame. overheadUs 10 us a frame is 10 ns a patch call, less than the 40 ns the mod + # charged when the empty patch read exactly 0, so the reading was above 0 and the patches were charged almost nothing. 50 us a frame is + # what the 40 ns charge (plus the other costs) gives, and could also be almost nothing plus a lot of sampling: it proves neither. + cheap, dear, none = dict(overheadUs=10.0, patchCalls=598800.0), dict(overheadUs=50.0, patchCalls=598800.0), dict(overheadUs=5.0) + for version, calibration, rows, slow, expect in ( + ("0.1.3", old, cheap, None, understated), + ("0.1.1", old, dear, dict(overheadUs=30.0, patchCalls=1000.0), understated), # one slow frame at 30 ns a call proves it + ("0.1.0", old, dear, dict(overheadUs=45.0, patchCalls=1000.0), guess), + ("0.1.3", old[:-1] + ["2"], dear, None, understated), # read 2 ns: charged that, and the bodies left out + ("0.1.3", old, none, None, None), # no patch ran: nothing to say + ("0.1.3", new, cheap, None, None), # the bodies were measured + ("0.1.3", None, cheap, None, None), + ("0.1.4", old, cheap, None, None)): + s = Synthetic(header={"mod": version}) + if calibration: + s.pipes.append(calibration) + for _ in range(6): + s.window(**rows) + if slow: + s.slow_frame(60.0, **slow) + text = self.report(s) + case = (version, calibration and calibration[-4:], rows, slow) + self.assertEqual(expect == understated, understated in text, case) + self.assertEqual(expect == guess, guess in text, case) + def test_the_loadall_counter_bug_of_0_1_0_is_not_reported_as_a_finding(self): for version, expect in (("0.1.0", False), ("0.1.1", True)): s = Synthetic(header={"mod": version}) @@ -634,6 +663,17 @@ def test_game_singletons_with_an_empty_mod_are_read_as_the_game(self): self.assertRegex(text, r"Timberborn\.SomethingUI\.Panel\s+game\b") self.assertRegex(text, r"Other\.Library\.Thing\s+\(unknown\)") + def test_a_watched_method_window_nobody_timed_is_not_counted_at_0_ms(self): + s = Synthetic() + for w in range(1, 7): + s.window() + # Five windows timed at 0.5 ms a call; in the sixth every timed call threw, so the mod wrote the calls with sampled 0 and no time. + timed = w <= 5 + s.profile.append({"kind": "method", "window": w, "tick": s.tick, "id": 3, "calls": 100 if timed else 40, "sampled": 10 if timed else 0, + "ms": 50.0 if timed else 0.0, "allocKB": 0, "maxMs": 0.6 if timed else 0.0, "name": "Some.Mod.Method()", "assembly": "SomeMod", "mod": "somemod"}) + text = self.report(s) + self.assertRegex(text, r"Some\.Mod\.Method\(\).*\b500\.0 us/call.*\(\+40 calls never timed\)") + def test_loading_that_grew_the_heap_is_reported(self): s = Synthetic() for _ in range(6):