diff --git a/CHANGELOG.md b/CHANGELOG.md index 6a8b4ca..b3a87d8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -16,6 +16,15 @@ is not part of this repository. - A minimised window no longer reads the list of services every second. It reads it again the moment it is restored, so the list is current as soon as it is on screen. A window started minimised, from a shortcut set to "Run: Minimized", reads it once and then waits the same way. +- Stopping, starting and restarting a service, from the window or with `bws`, no longer waits + about a quarter of a second longer than the service needs on every step. A service that stops + in 10 ms is now reported done after a few tens of milliseconds, where it used to be reported + after about 260, so a restart with a cascade of dependents finishes seconds sooner. The + `milliseconds` of each step in the JSON of a plan is smaller for the same reason. How long a + service is given before it is reported as not responding has not changed. +- Reading who depends on each entry - the Required by column, `required:` in a query and + `bws list --required-by` - asks about several entries at once and takes a fraction of the time + it did. ## [0.3.0] - 2026-09-25 diff --git a/src/Bws.Cli/CommandLine.cs b/src/Bws.Cli/CommandLine.cs index 842e9cc..28acd72 100644 --- a/src/Bws.Cli/CommandLine.cs +++ b/src/Bws.Cli/CommandLine.cs @@ -108,9 +108,9 @@ internal sealed partial record CommandLine /// /// Whether the listing should go and read who depends on each entry. /// - /// Asked for rather than always read: a call per entry, measured 2026-09-28 at 148-155 ms over - /// 797 entries, against 107-113 ms for the whole reading on sixteen processors - more than the - /// listing it sits behind. A query naming the + /// Asked for rather than always read: a call per entry, several at once since 2026-09-29 - + /// 19-40 ms over 797 entries on sixteen processors, against 107-113 ms for the whole reading and + /// 155-167 ms when it asked one at a time. A query naming the /// field turns it on by itself, exactly as one about signatures or memory does. /// internal bool RequiredBy { get; private init; } diff --git a/src/Bws.Cli/OptionSurface.cs b/src/Bws.Cli/OptionSurface.cs index 2ae1160..22044d0 100644 --- a/src/Bws.Cli/OptionSurface.cs +++ b/src/Bws.Cli/OptionSurface.cs @@ -153,7 +153,7 @@ internal static readonly (string Option, CommandKind[] Verbs)[] Surface = // Listing only, and NOT the same switch as --dependents further down. That one is an // instruction to a write verb - take the services standing on this one with you. This is - // a reading, and it costs a call per entry: 148-155 ms over 797 entries, 2026-09-28. + // a reading, and it costs a call per entry: 19-40 ms over 797 entries, several at once, 2026-09-29. ("--required-by", [CommandKind.List]), // The two verbs that resolve a launch path against the disk. A plan does not - it diff --git a/src/Bws.Cli/Program.cs b/src/Bws.Cli/Program.cs index a0f10ae..4c8409c 100644 --- a/src/Bws.Cli/Program.cs +++ b/src/Bws.Cli/Program.cs @@ -220,8 +220,8 @@ entries = SecondPass.Fill(entries, new WindowsBinaryInspector(networkPaths)); inspected = stopwatch.ElapsedMilliseconds - before; - // AND WHO DEPENDS ON EACH ENTRY, EVERY TIME, on the argument above and for a twentieth of - // the price - RequiredByPass carries the measurement. No switch here: one taken without it + // AND WHO DEPENDS ON EACH ENTRY, EVERY TIME, on the argument above and for a small fraction + // of the price - RequiredByPass carries the measurement. No switch here: one taken without it // would compare against one that has it as though every service had lost its dependents. entries = RequiredByPass.Fill(entries, catalog!); diff --git a/src/Bws.Core/ManagerBlocks.cs b/src/Bws.Core/ManagerBlocks.cs index 6ea39d8..dda4061 100644 --- a/src/Bws.Core/ManagerBlocks.cs +++ b/src/Bws.Core/ManagerBlocks.cs @@ -261,8 +261,11 @@ internal static unsafe List ReadDependentNames(byte[] buffer, uint count return names; } - internal static unsafe List ReadEnumerationBuffer(byte[] buffer, uint count) + internal static unsafe List ReadEnumerationBuffer(ReadOnlySpan buffer, uint count) { + // A span rather than an array since 2026-09-29, because the block now comes from a pool and + // is CUT to what the manager asked for - WindowsScmCatalog.ReadTurn. The length below is the + // length of that cut, never of the array behind it. // However many records the manager says it wrote, never more than the room it was given. // Trusting the count alone is the shape this project used everywhere and wrote down // nowhere - see ReadConfigurationBuffer for the argument. diff --git a/src/Bws.Core/Planning/PlanRunner.Waiting.cs b/src/Bws.Core/Planning/PlanRunner.Waiting.cs new file mode 100644 index 0000000..e1ead0c --- /dev/null +++ b/src/Bws.Core/Planning/PlanRunner.Waiting.cs @@ -0,0 +1,134 @@ +namespace Bws.Core.Planning; + +/// +/// The half of that watches ONE step on its way to where it was sent - how +/// often the entry is asked, and when it is given up on. +/// +/// Its own file since 2026-09-29, when the pause between two questions stopped being one +/// number and became a ramp with a rule about promises beside it. The rest of the class walks the +/// plan and never waits for anything, so the two halves change for different reasons. +/// +public sealed partial class PlanRunner +{ + /// + /// The longest pause between two questions about where the entry has got to. + /// + /// Our choice, not the system's, and it carries no correctness: the deadline comes from + /// the entry's own wait hint, this only decides how soon we notice. Short because + /// somebody is watching a terminal, and asking is cheap - five calls to the manager (open + /// it, open the entry, close the manager, query, close the entry - WindowsScmControl.Read), + /// 0.19-0.23 ms the lot, measured unelevated on 2026-09-28 with tools/plan-probe/read-cost.ps1. + /// + /// Until 2026-09-29 this was the ONLY pause, and it was most of every wait. Measured on + /// the throwaway machine on 2026-09-28: Spooler and W32Time changed state in 2-50 ms and each + /// step reported 260-289 ms, because the first question goes straight after the request, is + /// almost always too early, and the next one came a whole cadence later. Backlog 466, S-6 of + /// the external performance report. The pauses now start at and + /// double up to this. + /// + internal static readonly TimeSpan Cadence = TimeSpan.FromMilliseconds(250); + + /// + /// The first pause after the question that goes straight after the request. Each pause after + /// it is twice the one before, until . + /// + /// Why doubling, rather than a list of pauses: it keeps one promise that a list would + /// have to be checked for. The looks land at 0, 10, 30, 70, 150 and 310 ms, so an entry that + /// arrives inside that stretch is never left waiting longer than it took to get there, plus + /// this pause. A step that took 40 ms is reported at 70, not at 250. After that the pauses stay + /// at the cadence, so a wait of any length asks the manager at most four more times than it + /// did. + /// + /// Windows sleeps in whole ticks of its clock, about 15.6 ms by default, so on a real + /// machine the first pauses come out nearer 16, 31 and 47 ms. That only moves the looks a + /// little later and changes none of the above. + /// + internal static readonly TimeSpan FirstLook = TimeSpan.FromMilliseconds(10); + + /// + /// Watches an entry on its way, and decides when it has stopped going anywhere. + /// + /// Two deadlines, and the entry's own comes first. Win32 documents the promise: before + /// its wait hint elapses a service will either raise its check point or change state. + /// Keeping that promise buys it a fresh wait hint, so an entry that genuinely needs a + /// minute gets one. Breaking it is the documented signal that something has gone wrong. + /// The cap is ours and only stops a plan hanging a terminal on an entry that reports + /// progress it never finishes. + /// + private StepResult WaitFor(PlanStep step, EntryStatus target, TimeSpan timeout, TimeSpan started) + { + var giveUpAt = started + timeout; + var pause = FirstLook; + var status = EntryStatus.Unknown; + + // Carried alongside the status rather than read again at the end, because the point of it + // is the step that gives up: by then the entry is exactly where nobody can act on it, and + // the last process seen holding it is the only handle a person has on what to do next. + var processId = Reading.NotRead(); + uint? checkPoint = null; + TimeSpan? promisedBy = null; + + while (true) + { + var answer = control.Read(step.ServiceName); + + if (!answer.Worked) + { + return Refused(step, answer, status, processId, started); + } + + var progress = answer.Progress!.Value; + var moved = checkPoint is null || progress.CheckPoint > checkPoint || progress.Status != status; + + status = progress.Status; + processId = Holding(answer); + + if (status == target) + { + return Result(step, StepOutcome.Succeeded, status, processId, Elapsed(started)); + } + + var now = clock.Elapsed; + + if (moved) + { + checkPoint = progress.CheckPoint; + + // A wait hint of zero is what an entry reports when it has nothing pending, + // so it is not a promise to hold anybody to. Then only our own cap applies. + promisedBy = progress.WaitHint > TimeSpan.Zero ? now + Honoured(progress.WaitHint) : null; + } + + if (now >= giveUpAt || (promisedBy is not null && now >= promisedBy)) + { + return Result(step, StepOutcome.TimedOut, status, processId, Elapsed(started)); + } + + clock.Wait(pause); + pause = pause * 2 < Cadence ? pause * 2 : Cadence; + } + } + + /// + /// How long an entry's promise is held open: its wait hint, rounded UP to a whole + /// . + /// + /// This is the line that keeps looking sooner from turning into giving up sooner, and it + /// is new with the doubling pauses, 2026-09-29. Until then the entry was only looked at once a + /// cadence, so a promise was in effect honoured to the next whole cadence - an entry that said + /// 50 ms had 250 to keep its word, and one that said 300 had 500. Services exist that promise + /// less than they need, and to the person reading it a step reported as timed out that then + /// finished is a failure on a machine that is fine. The costly mistake is that one, and waiting + /// a fraction of a second longer on an entry that really has hung is the cheap one. So the + /// deadline stays exactly where it always was, and only how often it is checked changed. + /// + /// Not applied to our own cap, which is not the entry's promise. It is still checked at + /// the first look after it runs out, as it always was. + /// + /// Whole ticks rather than a division of two spans, because a hint that is already a whole + /// cadence has to come back unchanged, and integer arithmetic says so without a rounding + /// question. + /// + private static TimeSpan Honoured(TimeSpan waitHint) => + TimeSpan.FromTicks((waitHint.Ticks + Cadence.Ticks - 1) / Cadence.Ticks * Cadence.Ticks); +} diff --git a/src/Bws.Core/Planning/PlanRunner.cs b/src/Bws.Core/Planning/PlanRunner.cs index 975bac8..4e4f16c 100644 --- a/src/Bws.Core/Planning/PlanRunner.cs +++ b/src/Bws.Core/Planning/PlanRunner.cs @@ -14,25 +14,8 @@ namespace Bws.Core.Planning; /// bulk operations, where there are independent things to run - here the whole plan is one /// service and its cascade, which is a chain by construction. /// -public sealed class PlanRunner(IScmControl control, IClock clock) +public sealed partial class PlanRunner(IScmControl control, IClock clock) { - /// - /// How often the entry is asked where it has got to. - /// - /// Our choice, not the system's, and it carries no correctness: the deadline comes from - /// the entry's own wait hint, this only decides how soon we notice. Short because - /// somebody is watching a terminal and most stops are over in well under a second, and - /// asking is cheap - five calls to the manager (open it, open the entry, close the manager, - /// query, close the entry - WindowsScmControl.Read), not the one call this said until - /// 2026-09-28. - /// - /// Measured on the throwaway machine on 2026-09-28, this cadence is most of every wait: - /// Spooler and W32Time changed state in 2-50 ms and each step reported 260-289 ms, because the - /// first question goes straight after the request, is almost always too early, and the next - /// one is a whole cadence later. Backlog 466, S-6 of the external performance report. - /// - private static readonly TimeSpan Cadence = TimeSpan.FromMilliseconds(250); - /// /// Runs every step, in order. /// @@ -209,17 +192,6 @@ private StepResult RunStep(PlanStep step, TimeSpan timeout) return WaitFor(step, target, timeout, started); } - /// - /// Watches an entry on its way, and decides when it has stopped going anywhere. - /// - /// Two deadlines, and the entry's own comes first. Win32 documents the promise: before - /// its wait hint elapses a service will either raise its check point or change state. - /// Keeping that promise buys it a fresh wait hint, so an entry that genuinely needs a - /// minute gets one. Breaking it is the documented signal that something has gone wrong. - /// The cap is ours and only stops a plan hanging a terminal on an entry that reports - /// progress it never finishes. - /// - /// /// Writes a start type, and says where the entry is while it is at it. /// @@ -240,57 +212,6 @@ private StepResult Configure(PlanStep step, TimeSpan started) ? Result(step, StepOutcome.Succeeded, Where(seen), Holding(seen), Elapsed(started)) : Refused(step, answer, Where(seen), Holding(seen), started); } - private StepResult WaitFor(PlanStep step, EntryStatus target, TimeSpan timeout, TimeSpan started) - { - var giveUpAt = started + timeout; - var status = EntryStatus.Unknown; - - // Carried alongside the status rather than read again at the end, because the point of it - // is the step that gives up: by then the entry is exactly where nobody can act on it, and - // the last process seen holding it is the only handle a person has on what to do next. - var processId = Reading.NotRead(); - uint? checkPoint = null; - TimeSpan? promisedBy = null; - - while (true) - { - var answer = control.Read(step.ServiceName); - - if (!answer.Worked) - { - return Refused(step, answer, status, processId, started); - } - - var progress = answer.Progress!.Value; - var moved = checkPoint is null || progress.CheckPoint > checkPoint || progress.Status != status; - - status = progress.Status; - processId = Holding(answer); - - if (status == target) - { - return Result(step, StepOutcome.Succeeded, status, processId, Elapsed(started)); - } - - var now = clock.Elapsed; - - if (moved) - { - checkPoint = progress.CheckPoint; - - // A wait hint of zero is what an entry reports when it has nothing pending, - // so it is not a promise to hold anybody to. Then only our own cap applies. - promisedBy = progress.WaitHint > TimeSpan.Zero ? now + progress.WaitHint : null; - } - - if (now >= giveUpAt || (promisedBy is not null && now >= promisedBy)) - { - return Result(step, StepOutcome.TimedOut, status, processId, Elapsed(started)); - } - - clock.Wait(Cadence); - } - } /// /// Ends the process the step named, having checked it is still the one the step named. diff --git a/src/Bws.Core/Querying/QueryField.cs b/src/Bws.Core/Querying/QueryField.cs index 796149a..04007e7 100644 --- a/src/Bws.Core/Querying/QueryField.cs +++ b/src/Bws.Core/Querying/QueryField.cs @@ -47,11 +47,12 @@ public enum ExtraRead Memory = 2, /// - /// Who breaks if each entry stops. Measured at 148-155 ms over 797 entries on 2026-09-28. + /// Who breaks if each entry stops. Measured at 19-40 ms over 797 entries on 2026-09-29, asked + /// several at once (148-155 ms one at a time, the day before). /// /// The third family, and the one that shows why this was flags rather than a yes-or-no from - /// the start. It sits between the other two - a hundred and fifty milliseconds against - /// under one and against twelve seconds of processor - so a query about dependents must not send + /// the start. It sits between the other two - tens of milliseconds against under one and + /// against twelve seconds of processor - so a query about dependents must not send /// the window to open eight hundred binaries, and a question about signatures must not walk the /// manager service by service. Each caller asks for what it needs and gets only that, which /// Readings.Fill honours one flag at a time. diff --git a/src/Bws.Core/Querying/QueryFields.cs b/src/Bws.Core/Querying/QueryFields.cs index 38ed480..d49c297 100644 --- a/src/Bws.Core/Querying/QueryFields.cs +++ b/src/Bws.Core/Querying/QueryFields.cs @@ -333,9 +333,9 @@ private static QueryField[] BuildAll() => // and the one services.msc answers only by opening a service and reading a tab. // // IT DECLARES A FAMILY AND THE ONE ABOVE DOES NOT, which is the whole difference - // between the two directions. This takes a call per entry: measured 148-155 ms over - // 797 entries on 2026-09-28, against 107-113 ms for the entire listing. So it is - // asked for rather than always read, exactly as signatures and memory are. + // between the two directions. This takes a call per entry: 19-40 ms over 797 entries + // asked several at once (2026-09-29), against 107-113 ms for the entire listing. So it + // is asked for rather than always read, exactly as signatures and memory are. // // THE FIRST HOP ONLY, which a person reading a member has to know: dependents:spooler // finds what stands directly on Spooler, not the closure. That is what the manager diff --git a/src/Bws.Core/RequiredByPass.cs b/src/Bws.Core/RequiredByPass.cs index 32489ab..b2f59db 100644 --- a/src/Bws.Core/RequiredByPass.cs +++ b/src/Bws.Core/RequiredByPass.cs @@ -12,6 +12,14 @@ namespace Bws.Core; /// nobody had asked for. That is exactly the trade `ADR-13` refuses, and it is the same argument /// and each make with a different number. /// +/// The number got smaller on 2026-09-29 and the argument with it - S-5 of the external +/// performance report, backlog 466. Asked several entries at once the same pass cost 19-40 ms over +/// the same 797 entries on sixteen processors (median 21.5), against 155-167 ms one at a time in the +/// series just before it. That is a fifth to a third of a listing here, and more of one on a machine +/// with two processors, where nobody has measured it. Whether that still earns a pass of its own +/// was put to the owner the same day, and the answer was yes: it stays asked for, so the listing, +/// the JSON of `list` and the snapshot keep the shape they had. +/// /// It is a DESCRIPTION rather than a measurement, unlike memory, which is why this one may /// go into a snapshot and that one may not. Who depends on a service is configuration: it reads /// the same twice in a row and changes when somebody changes the machine, which is precisely what @@ -45,17 +53,56 @@ public static class RequiredByPass /// is given, because every caller has the whole listing at this point and a second rule about /// when filtering is allowed would be a rule nobody could check. /// - public static IReadOnlyList Fill(IReadOnlyList entries, IScmCatalog catalog) + public static IReadOnlyList Fill(IReadOnlyList entries, IScmCatalog catalog) => + Fill(entries, catalog, DefaultDegreeOfParallelism); + + /// + /// How many entries are asked about at once when nobody says otherwise. + /// + /// The processor count, the answer the listing and each arrived at by + /// sweeping. This pass was NOT swept - it was measured at sixteen, on one machine with + /// sixteen processors, and nowhere else. + /// + public static int DefaultDegreeOfParallelism => Environment.ProcessorCount; + + /// + /// The same, with the number of entries asked about at once given rather than defaulted. + /// + /// It is a parameter because the guard needs it, the argument written on + /// : "threads changed no answer" can only be checked by running both + /// ways. Nothing in the product passes it. + /// + /// Several at once since 2026-09-29, and each call still opens its own manager handle. + /// Both were measured side by side on 2026-09-28 over 797 entries with + /// tools/scm-probe/required-by-timing.ps1: one after another 148-155 ms, this 15-16 ms, and every + /// thread sharing ONE handle 23-24 ms - slower, not faster, which is the opposite of what the + /// report proposed and of what the listing does with its own handle. So the catalogue is not + /// touched. + /// + /// Order is held by index, the same way the listing holds it: each answer lands in the slot + /// its entry came from, so the answer is the sequential one by construction. What a caller + /// must now bring is a catalogue that can be asked from several threads at once. The Windows + /// one opens a handle per call and keeps its last error per thread. An exception from a catalogue + /// arrives wrapped in an AggregateException rather than as itself, and nothing catches one here + /// by type, since the Windows catalogue answers a refusal rather than throwing it. + /// + public static IReadOnlyList Fill( + IReadOnlyList entries, IScmCatalog catalog, int degreeOfParallelism) { ArgumentNullException.ThrowIfNull(entries); ArgumentNullException.ThrowIfNull(catalog); + ArgumentOutOfRangeException.ThrowIfLessThan(degreeOfParallelism, 1); - var filled = new List(entries.Count); + var filled = new ScmEntry[entries.Count]; - foreach (var entry in entries) - { - filled.Add(entry with { RequiredBy = catalog.ReadDependents(entry.ServiceName) }); - } + Parallel.For( + 0, + entries.Count, + new ParallelOptions { MaxDegreeOfParallelism = degreeOfParallelism }, + index => filled[index] = entries[index] with + { + RequiredBy = catalog.ReadDependents(entries[index].ServiceName) + }); return filled; } diff --git a/src/Bws.Core/ScmEntry.cs b/src/Bws.Core/ScmEntry.cs index cf34672..7ae07e7 100644 --- a/src/Bws.Core/ScmEntry.cs +++ b/src/Bws.Core/ScmEntry.cs @@ -146,9 +146,10 @@ public sealed record ScmEntry /// arrives in the configuration structure the start type comes from and costs nothing. This /// takes a call PER ENTRY: the manager is asked, one service at a time, who is standing on it. /// Measured on this machine on 2026-09-28 through the product's own pass, five runs with the - /// first discarded: 148-155 ms over 797 entries. That is more than the whole listing - /// again - 107-113 ms over the same entries - so paying it on every F5 for a column that is - /// off by default is exactly the trade + /// first discarded: 148-155 ms over 797 entries, more than the whole listing again - + /// 107-113 ms over the same entries. Asked several at once since 2026-09-29 it costs 19-40 ms, a + /// fifth to a third of the listing, and paying even that on every F5 for a column that is off + /// by default is the trade /// `ADR-13` refuses. It is read when somebody asks, and is /// how they ask. /// diff --git a/src/Bws.Core/WindowsScmCatalog.Enumerating.cs b/src/Bws.Core/WindowsScmCatalog.Enumerating.cs index d7cc34c..2feae1b 100644 --- a/src/Bws.Core/WindowsScmCatalog.Enumerating.cs +++ b/src/Bws.Core/WindowsScmCatalog.Enumerating.cs @@ -1,3 +1,4 @@ +using System.Buffers; using System.ComponentModel; using System.Runtime.InteropServices; using Windows.Win32; @@ -23,7 +24,7 @@ public sealed partial class WindowsScmCatalog // A list rather than a sequence, because the caller needs a count before it starts and an // index while it runs. It was already building one internally - the sequence was hiding // that behind a type that promised less than it delivered. - private static unsafe List Enumerate(SafeHandle manager) + private static List Enumerate(SafeHandle manager) { uint resume = 0; var results = new List(capacity: 1024); @@ -78,7 +79,62 @@ private static unsafe List Enumerate(SafeHandle manager) break; } - var buffer = new byte[needed]; + var returned = ReadTurn(manager, needed, ref resume, results); + + // THE ONE LOOP IN THIS PROJECT WHOSE ENDING IS DECIDED ENTIRELY BY SOMEBODY ELSE, + // and until 2026-09-02 nothing here insisted that it end. Backlog 304. Both exits + // come from the manager: a size of zero above and a resume handle of zero below. + // A turn that hands over no record and does not move the handle has made no + // progress, and repeating it makes none either - so the loop would spin, taking a + // fresh buffer every time, with the command line hung and the window silently + // stuck on a reading that never returns. + // + // NOBODY HAS SEEN THIS AND THAT IS WRITTEN DOWN RATHER THAN GLOSSED. The manager + // answers in one or two turns. What earns the check is the asymmetry: three lines + // against a hang on somebody's server, in the only place here where the condition + // to continue is a number a different process chose. + if (returned == 0 && resume == before) + { + throw new Win32Exception( + (int)WIN32_ERROR.ERROR_INVALID_DATA, + "The service control manager stopped making progress through its own listing."); + } + + // A resume handle of zero means the manager has nothing left to hand over. + if (resume == 0) + { + break; + } + } + + return results; + } + + /// + /// One turn: the records the manager hands over into a block of exactly the size it asked for. + /// Returns how many it said it wrote. + /// + /// RENTED RATHER THAN NEW SINCE 2026-09-29 - S-3 of the external performance report, + /// backlog 466. The window asks this every second, and over 797 entries the manager wants + /// 129 418 B: past the 85 000 B line, so every tick put a fresh block on the large object heap, + /// and only a full collection gives one back. Measured with tools/scm-probe/tick-alloc.ps1 over + /// 1500 ticks before the change: 347 KB allocated a tick and 34 full collections. + /// + /// The block is cut to what the manager asked for and cleared, and that is what keeps this the + /// reading it was. A pooled array is usually longer than asked and carries whatever its last + /// renter left in it, and bounds every pointer + /// and every count by the length it is handed. Handed the whole array, those checks would be + /// measured against room the manager was never told about. Cut and cleared, the reader sees the + /// same length and the same zeros a new array gave it. + /// + private static unsafe uint ReadTurn(SafeHandle manager, uint needed, ref uint resume, List results) + { + var rented = ArrayPool.Shared.Rent((int)needed); + + try + { + var buffer = rented.AsSpan(0, (int)needed); + buffer.Clear(); // Pinned across the call and the reading, for the reason set out in full at // ReadConfiguration: each record here carries two absolute pointers into this very @@ -99,33 +155,12 @@ private static unsafe List Enumerate(SafeHandle manager) results.AddRange(ManagerBlocks.ReadEnumerationBuffer(buffer, returned)); - // THE ONE LOOP IN THIS PROJECT WHOSE ENDING IS DECIDED ENTIRELY BY SOMEBODY ELSE, - // and until 2026-09-02 nothing here insisted that it end. Backlog 304. Both exits - // come from the manager: a size of zero above and a resume handle of zero below. - // A turn that hands over no record and does not move the handle has made no - // progress, and repeating it makes none either - so the loop would spin, taking a - // fresh buffer every time, with the command line hung and the window silently - // stuck on a reading that never returns. - // - // NOBODY HAS SEEN THIS AND THAT IS WRITTEN DOWN RATHER THAN GLOSSED. The manager - // answers in one or two turns. What earns the check is the asymmetry: three lines - // against a hang on somebody's server, in the only place here where the condition - // to continue is a number a different process chose. - if (returned == 0 && resume == before) - { - throw new Win32Exception( - (int)WIN32_ERROR.ERROR_INVALID_DATA, - "The service control manager stopped making progress through its own listing."); - } - } - - // A resume handle of zero means the manager has nothing left to hand over. - if (resume == 0) - { - break; + return returned; } } - - return results; + finally + { + ArrayPool.Shared.Return(rented); + } } } diff --git a/src/Bws.Core/WindowsScmCatalog.cs b/src/Bws.Core/WindowsScmCatalog.cs index 11a4701..a4f0e07 100644 --- a/src/Bws.Core/WindowsScmCatalog.cs +++ b/src/Bws.Core/WindowsScmCatalog.cs @@ -302,8 +302,8 @@ private static ScmEntry Describe(SafeHandle manager, EnumeratedEntry enumerated, // Filled in by RequiredByPass, and only when asked - the OTHER direction of DependsOn // three fields up, and the reason the two sit apart. That one arrives inside this same - // configuration structure and is free. This one is a call per entry, measured at - // 148-155 ms over 797 entries on 2026-09-28, which is more than the whole listing again. + // configuration structure and is free. This one is a call per entry - 19-40 ms over 797 + // entries asked several at once (2026-09-29), 148-155 ms one at a time the day before. RequiredBy = Reading>.NotRead() }; } diff --git a/src/Bws.Gui/ViewModels/Columns.cs b/src/Bws.Gui/ViewModels/Columns.cs index c7a2369..fbde705 100644 --- a/src/Bws.Gui/ViewModels/Columns.cs +++ b/src/Bws.Gui/ViewModels/Columns.cs @@ -420,8 +420,8 @@ internal static partial class Columns // something. "What needs this" is asked before stopping something, and it is the only // one of the two that can talk somebody out of an action. // - // IT IS THE ONLY COLUMN IN THIS CATALOGUE THAT COSTS A CALL PER ENTRY - 148-155 ms - // over 797 entries, measured 2026-09-28, against 107-113 ms for the whole listing. So + // IT IS THE ONLY COLUMN IN THIS CATALOGUE THAT COSTS A CALL PER ENTRY - 19-40 ms over + // 797 entries asked several at once, 2026-09-29, against 107-113 ms for the listing. So // it declares a family and is read when somebody turns it on, exactly as the four // signature columns and the memory column are. Id = "requiredBy", diff --git a/src/Bws.Gui/ViewModels/Readings.SecondPhase.cs b/src/Bws.Gui/ViewModels/Readings.SecondPhase.cs index d603176..b45c499 100644 --- a/src/Bws.Gui/ViewModels/Readings.SecondPhase.cs +++ b/src/Bws.Gui/ViewModels/Readings.SecondPhase.cs @@ -172,12 +172,12 @@ private IReadOnlyList Fill(IReadOnlyList entries, ExtraRead filled = MemoryPass.Fill(filled, _reader!); } - // THE THIRD FAMILY, 2026-09-06, and it sits between the other two in price: 148-155 ms over - // 797 entries against under a millisecond for memory and about twelve seconds of processor - // for signatures (2026-09-28). Last because it is the only one that goes back to the - // manager, so a run that - // wants all three has already finished with the files and the processes by the time it - // starts walking services one at a time. + // THE THIRD FAMILY, 2026-09-06, and it sits between the other two in price: 19-40 ms over + // 797 entries since it asks several at once (2026-09-29, 155-167 ms one at a time before), + // against under a millisecond for memory and about twelve seconds of processor for + // signatures (2026-09-28). Last because it is the only one that goes back to the manager, + // so a run that wants all three has already finished with the files and the processes by + // the time it starts asking about services. if (wanted.HasFlag(ExtraRead.RequiredBy)) { filled = RequiredByPass.Fill(filled, _catalog); diff --git a/tests/Bws.Architecture.Tests/ConcurrencyGuards.cs b/tests/Bws.Architecture.Tests/ConcurrencyGuards.cs index bda71be..ac364c9 100644 --- a/tests/Bws.Architecture.Tests/ConcurrencyGuards.cs +++ b/tests/Bws.Architecture.Tests/ConcurrencyGuards.cs @@ -42,6 +42,14 @@ public sealed class ConcurrencyGuards "The publisher cache the pass above reads from several threads at once. A plain " + "dictionary here would be the quiet kind of race: right on most runs.", + ["RequiredByPass.cs"] = + "Asking who depends on each entry several entries at a time, added 2026-09-29 (S-5 of " + + "the external performance report). One at a time it measured 155-167 ms over 797 " + + "entries and several at once 19-40 ms, in the same series. Each call opens its own " + + "manager handle, because one handle shared by every thread measured slower. Order is " + + "held by index, and RequiredByPassParallelTests holds both halves: every answer in its " + + "own entry against a single-threaded run, and the questions really going out together.", + ["Readings.cs"] = "Reading the manager off the interface thread, because a full reading takes about " + "half a second and a window that stops answering for half a second looks broken. " + diff --git a/tests/Bws.Core.Tests/Fakes/FakeScmCatalog.cs b/tests/Bws.Core.Tests/Fakes/FakeScmCatalog.cs index c98fcd6..c0b18e5 100644 --- a/tests/Bws.Core.Tests/Fakes/FakeScmCatalog.cs +++ b/tests/Bws.Core.Tests/Fakes/FakeScmCatalog.cs @@ -72,7 +72,13 @@ public IReadOnlyList ReadStatuses() public Reading> ReadDependents(string serviceName) { - DependentsAsked.Add(serviceName); + // LOCKED SINCE 2026-09-29, when RequiredByPass started asking several entries at once. A + // list is not safe to add to from two threads, and a double that loses a name under load + // would make the pass look as if it skipped one. Everything else here is only read. + lock (DependentsAsked) + { + DependentsAsked.Add(serviceName); + } if (RefuseDependentsFor.Contains(serviceName)) { diff --git a/tests/Bws.Core.Tests/Fakes/FakeScmControl.cs b/tests/Bws.Core.Tests/Fakes/FakeScmControl.cs index dd7d7f0..ce0e001 100644 --- a/tests/Bws.Core.Tests/Fakes/FakeScmControl.cs +++ b/tests/Bws.Core.Tests/Fakes/FakeScmControl.cs @@ -16,7 +16,11 @@ namespace Bws.Core.Tests.Fakes; /// anyway would be a preview that lied, which is the failure this whole pattern exists to /// prevent. /// -internal sealed class FakeScmControl : IScmControl +/// +/// The ruler an entry made with keeps time by - the same one the runner +/// under test is given. Only those entries need it. +/// +internal sealed class FakeScmControl(IClock? clock = null) : IScmControl { private readonly Dictionary _entries = new(StringComparer.OrdinalIgnoreCase); @@ -153,6 +157,32 @@ internal FakeScmControl Reaching(string serviceName, params ServiceProgress[] re return this; } + /// + /// An entry that gets there a set time after it was asked, however often anybody looks in + /// between - and until then says . + /// + /// Time rather than a count of looks, since 2026-09-29, because the runner no longer + /// looks at a steady pace. hands out one reading per look, so it can say + /// "arrives at the third look" and cannot say "arrives after 40 ms", which is the only way to + /// ask how soon an arrival is noticed. + /// + internal FakeScmControl Arriving(string serviceName, TimeSpan after, ServiceProgress meanwhile) + { + var ruler = clock + ?? throw new InvalidOperationException("An entry that arrives in time needs the clock the runner is given."); + + Entry(serviceName).Arrival = new Arrival(ruler, after, meanwhile); + return this; + } + + /// + /// How many times anybody asked where an entry is, every entry counted. + /// + /// For the one question the other lists cannot answer: whether looking sooner turned into + /// asking the manager all the time. + /// + internal int Reads { get; private set; } + /// An entry the manager will not move, optionally because it has moved itself. internal FakeScmControl RefusingRequests(string serviceName, int errorCode, EntryStatus? becomes = null) { @@ -187,6 +217,14 @@ public ControlAnswer Request(string serviceName, StepOperation operation) entry.Moving = true; + if (entry.Arrival is { } arrival) + { + entry.AskedAt = arrival.Clock.Elapsed; + entry.Heading = operation == StepOperation.Stop ? EntryStatus.Stopped : EntryStatus.Running; + + return ControlAnswer.Done(); + } + // Nothing scripted means it is there by the time anybody looks, which is what most // services do and what most of these tests are not about. if (entry.AfterRequest is null) @@ -199,6 +237,8 @@ public ControlAnswer Request(string serviceName, StepOperation operation) public ControlAnswer Read(string serviceName) { + Reads++; + var entry = Entry(serviceName); if (entry.ReadRefusedWith is { } refused) @@ -206,6 +246,19 @@ public ControlAnswer Read(string serviceName) return ControlAnswer.Refused(refused, $"refused with {refused}"); } + if (entry.Moving && entry.Arrival is { } arrival) + { + if (arrival.Clock.Elapsed - entry.AskedAt < arrival.After) + { + entry.Status = arrival.Meanwhile.Status; + return ControlAnswer.At(arrival.Meanwhile); + } + + // Arrived, and from here on it is an entry that is where it is. + entry.Status = entry.Heading; + entry.Arrival = null; + } + if (!entry.Moving || entry.AfterRequest is null) { return ControlAnswer.At( @@ -269,5 +322,15 @@ private sealed class Behaviour internal EntryStatus? BecomesOnRefusal { get; set; } internal int? ReadRefusedWith { get; set; } + + internal Arrival? Arrival { get; set; } + + /// When the manager was asked to move it, on the ruler of . + internal TimeSpan AskedAt { get; set; } + + /// Where the request sent it, which is where it ends up once it arrives. + internal EntryStatus Heading { get; set; } } + + private sealed record Arrival(IClock Clock, TimeSpan After, ServiceProgress Meanwhile); } diff --git a/tests/Bws.Core.Tests/PlanRunCadenceTests.cs b/tests/Bws.Core.Tests/PlanRunCadenceTests.cs new file mode 100644 index 0000000..8d15085 --- /dev/null +++ b/tests/Bws.Core.Tests/PlanRunCadenceTests.cs @@ -0,0 +1,108 @@ +using Bws.Core.Planning; +using Bws.Core.Tests.Fakes; + +namespace Bws.Core.Tests; + +/// +/// How soon a step notices that its entry has arrived, and what that must not cost. +/// +/// Written 2026-09-29 with the doubling pauses in - backlog 466, +/// S-6 of the external performance report. On the throwaway machine Spooler and W32Time changed +/// state in 2-50 ms and every step reported 260-289 ms, because the runner looked once straight +/// after the request and then only every quarter of a second. Three things are held here, and +/// only the first is the reason for the change. The other two are what the change could have +/// broken without anybody noticing: giving up sooner on an entry that promised too little, and +/// asking the manager all the time. +/// +/// Every entry here arrives by the clock rather than by the number of looks, because the looks +/// no longer come at a steady pace and "arrived after 40 ms" is the only honest way to ask. +/// +public sealed class PlanRunCadenceTests +{ + private const string Name = "Spooler"; + + [Theory] + [InlineData(0)] + [InlineData(5)] + [InlineData(40)] + [InlineData(120)] + [InlineData(600)] + [InlineData(3000)] + public void An_entry_is_seen_soon_after_it_arrives_rather_than_a_whole_cadence_later(int arrivesAfter) + { + // The promise the doubling keeps: never left waiting longer than the step had already + // taken plus the first pause, and never a whole cadence. Before 2026-09-29 an entry that + // arrived after 5 ms was reported at 250, forty times late. + var clock = new FakeClock(); + var control = Stopping(clock, TimeSpan.FromMilliseconds(arrivesAfter), Pending(TimeSpan.FromSeconds(5))); + + var result = Assert.Single(Run(control, clock).Results); + var late = result.Milliseconds - arrivesAfter; + + Assert.Equal(StepOutcome.Succeeded, result.Outcome); + Assert.True(late >= 0, $"Reported at {result.Milliseconds} ms, before the entry arrived."); + + Assert.True( + late < Math.Min(arrivesAfter + PlanRunner.FirstLook.TotalMilliseconds, PlanRunner.Cadence.TotalMilliseconds), + $"Arrived after {arrivesAfter} ms and was only seen at {result.Milliseconds} ms."); + } + + [Theory] + [InlineData(50, 240)] + [InlineData(300, 480)] + public void An_entry_that_promised_less_than_it_needed_is_given_the_patience_it_always_had( + int promised, int arrivesAfter) + { + // THE MISTAKE LOOKING SOONER COULD HAVE MADE, and the costlier one. Both of these arrived + // without ever raising their check point, so each broke its promise. Looked at once a + // quarter of a second, both were seen arriving and reported as done - so a runner that + // looks sooner and gives up at the promise itself would now report as timed out a step + // that finished, on a machine that is fine. + var clock = new FakeClock(); + + var control = Stopping( + clock, TimeSpan.FromMilliseconds(arrivesAfter), Pending(TimeSpan.FromMilliseconds(promised))); + + Assert.Equal(StepOutcome.Succeeded, Assert.Single(Run(control, clock).Results).Outcome); + } + + [Fact] + public void A_long_wait_asks_the_manager_about_as_often_as_it_always_did() + { + // The cost side. The first pauses are short, and pauses that stayed short would turn a + // thirty second wait into three thousand questions to the manager instead of about a + // hundred and twenty. The doubling adds a handful at the start and nothing after. + var clock = new FakeClock(); + + var control = new FakeScmControl() + .At(Name, EntryStatus.Running) + .Reaching(Name, new ServiceProgress(EntryStatus.StopPending, 0, TimeSpan.Zero, ProcessId: 4812)); + + var run = Run(control, clock, TimeSpan.FromSeconds(30)); + var atTheCadence = (int)(TimeSpan.FromSeconds(30) / PlanRunner.Cadence); + + Assert.Equal(StepOutcome.TimedOut, Assert.Single(run.Results).Outcome); + Assert.InRange(control.Reads, atTheCadence, atTheCadence + 10); + } + + private static ServiceProgress Pending(TimeSpan waitHint) => + new(EntryStatus.StopPending, CheckPoint: 1, waitHint, ProcessId: 4812); + + private static FakeScmControl Stopping(IClock clock, TimeSpan after, ServiceProgress meanwhile) => + new FakeScmControl(clock) + .At(Name, EntryStatus.Running) + .Arriving(Name, after, meanwhile); + + private static PlanRun Run(FakeScmControl control, FakeClock clock, TimeSpan? timeout = null) + { + var plan = new OperationPlan + { + Action = new ServiceAction(ActionKind.Stop, Name), + Steps = [new PlanStep(Name, Name, StepOperation.Stop, StepReason.Requested)], + Warnings = [], + Problems = [] + }; + + return new PlanRunner(control, clock).Run(plan, timeout ?? TimeSpan.FromMinutes(1)); + } +} diff --git a/tests/Bws.Core.Tests/PlanRunnerTests.cs b/tests/Bws.Core.Tests/PlanRunnerTests.cs index 1df6310..9427114 100644 --- a/tests/Bws.Core.Tests/PlanRunnerTests.cs +++ b/tests/Bws.Core.Tests/PlanRunnerTests.cs @@ -154,8 +154,10 @@ public void An_entry_that_keeps_reporting_progress_is_given_more_time_than_it_fi Assert.Equal(StepOutcome.Succeeded, Assert.Single(run.Results).Outcome); - // Twice the hint it first gave, spent on an entry that kept saying it was working. - Assert.Equal(TimeSpan.FromSeconds(10), clock.Waited); + // More than the five seconds it first asked for, spent on an entry that kept saying it was + // working. Said as "more than" since 2026-09-29: this used to be exactly forty looks of a + // quarter of a second each, and how often the runner looks is not what this is about. + Assert.True(clock.Waited > TimeSpan.FromSeconds(5), $"Waited only {clock.Waited}."); } [Fact] @@ -175,7 +177,10 @@ public void An_entry_that_stops_reporting_progress_is_given_up_on_when_its_own_p // Where it was left, which is the half a person needs to decide what to do next. Assert.Equal(EntryStatus.StopPending, result.Status); - Assert.Equal(TimeSpan.FromSeconds(2), clock.Waited); + + // The two seconds, and the first look after them - never less, and never a whole cadence + // more. A range since 2026-09-29, because the looks stopped landing on whole seconds. + Assert.InRange(clock.Waited, TimeSpan.FromSeconds(2), TimeSpan.FromSeconds(2) + PlanRunner.Cadence); // AND WHAT IS HOLDING IT THERE, WHICH IS THE OTHER HALF - 2026-09-06. An entry stuck in // StopPending will not be moved by asking again, so the process is the only thing left a @@ -199,7 +204,7 @@ public void An_entry_that_promises_nothing_at_all_is_given_up_on_at_the_limit_we Plan(ActionKind.Stop, "MRxSmb20", dependents: false), control, clock, TimeSpan.FromSeconds(30)); Assert.Equal(StepOutcome.TimedOut, Assert.Single(run.Results).Outcome); - Assert.Equal(TimeSpan.FromSeconds(30), clock.Waited); + Assert.InRange(clock.Waited, TimeSpan.FromSeconds(30), TimeSpan.FromSeconds(30) + PlanRunner.Cadence); } // -- what happens to the rest ---------------------------------------------------------- diff --git a/tests/Bws.Core.Tests/RequiredByPassParallelTests.cs b/tests/Bws.Core.Tests/RequiredByPassParallelTests.cs new file mode 100644 index 0000000..af7e151 --- /dev/null +++ b/tests/Bws.Core.Tests/RequiredByPassParallelTests.cs @@ -0,0 +1,130 @@ +using Bws.Core.Tests.Fakes; + +namespace Bws.Core.Tests; + +/// +/// Who breaks if an entry stops, asked about several entries at once. +/// +/// Written 2026-09-29 with the pass itself - S-5 of the external performance report, +/// backlog 466. One after another the pass cost 155-167 ms over 797 entries on the machine it was +/// measured on, and the same calls from several threads 19-40 ms. Two things are held here, and +/// they are the two a parallel loop gets wrong without a sound: every answer landing in its own +/// entry rather than a neighbour's, and the questions really going out together rather than a loop +/// that only looks parallel. +/// +[CollectionDefinition("asking about dependents alone", DisableParallelization = true)] +public sealed class AskingAboutDependentsAlone; + +/// +/// Runs with nothing else running, since the day it first ran anywhere but here. +/// +/// Found on the first CI run, 2026-09-29, and the lesson is the one ReadAllContractTests had +/// already paid for. The second test below needs the thread pool to hand the pass a second +/// thread. On sixteen processors it always got one. On the build agent, with the rest of this +/// project's tests running beside it, it waited ten seconds and never did - the guard measured the +/// test runner and called it the product. Alone, a free thread is there to take the work. +/// +[Collection("asking about dependents alone")] +public sealed class RequiredByPassParallelTests +{ + [Fact] + public void Asked_several_at_once_every_entry_keeps_its_own_answer_and_the_order_it_came_in() + { + // Enough entries for the threads to interleave, each with an answer nobody else has - so + // an answer that landed one slot over, or an entry that moved, cannot look right by chance. + // Every third is refused, because a refusal carried to the wrong entry is the worst of these: + // it says "no access" about something that was read and "nobody" about something that was not. + var entries = Enumerable.Range(0, 400) + .Select(index => Entries.Any with { ServiceName = $"Svc{index:000}", DisplayName = $"Service {index}" }) + .ToArray(); + + var catalog = new FakeScmCatalog(entries); + + for (var index = 0; index < entries.Length; index++) + { + if (index % 3 == 0) + { + catalog.RefuseDependentsFor.Add(entries[index].ServiceName); + } + else + { + catalog.DependedOnBy(entries[index].ServiceName, $"Dep{index:000}"); + } + } + + var together = RequiredByPass.Fill(entries, catalog, degreeOfParallelism: 8); + var alone = RequiredByPass.Fill(entries, catalog, degreeOfParallelism: 1); + + Assert.Equal(entries.Select(entry => entry.ServiceName), together.Select(entry => entry.ServiceName)); + + for (var index = 0; index < entries.Length; index++) + { + Assert.Equal(Said(alone[index]), Said(together[index])); + + Assert.Equal( + index % 3 == 0 ? "denied 5" : $"present Dep{index:000}", + Said(together[index])); + } + } + + [Fact] + public void The_entries_are_asked_about_at_the_same_time_rather_than_one_after_another() + { + // The first two questions wait for each other. One after another, the first waits for a + // partner that only comes once it has given up - so a loop that is parallel in name only + // fails here, twenty seconds late, rather than passing quietly. + using var catalog = new Meeting(); + + var entries = Enumerable.Range(0, 4) + .Select(index => Entries.Any with { ServiceName = $"Svc{index}" }) + .ToArray(); + + RequiredByPass.Fill(entries, catalog, degreeOfParallelism: 2); + + Assert.True(catalog.Met, "The first two questions never waited for each other - they were asked one after another."); + } + + /// The answer an entry carries, in one string, so two of them compare in one line. + private static string Said(ScmEntry entry) => entry.RequiredBy.Outcome switch + { + ReadOutcome.Present => "present " + string.Join(",", entry.RequiredBy.Value!), + ReadOutcome.Denied => $"denied {entry.RequiredBy.ErrorCode}", + var outcome => outcome.ToString() + }; + + /// + /// A manager whose first two questions wait for each other, for up to twenty seconds. + /// + /// A deadline rather than a wait with no end, because a test that is meant to go red must not + /// become a run that never finishes - the note at the top of tools/mutate/mutate.ps1 says why. + /// + private sealed class Meeting : IScmCatalog, IDisposable + { + private readonly CountdownEvent _both = new(2); + private int _asked; + + /// False once the first question gave up waiting for the second. + internal bool Met { get; private set; } = true; + + public IReadOnlyList ReadAll() => []; + + public IReadOnlyList ReadStatuses() => []; + + public Reading> ReadDependents(string serviceName) + { + if (Interlocked.Increment(ref _asked) <= 2) + { + _both.Signal(); + + if (!_both.Wait(TimeSpan.FromSeconds(20))) + { + Met = false; + } + } + + return Reading>.Absent(); + } + + public void Dispose() => _both.Dispose(); + } +} diff --git a/tests/Bws.Core.Tests/RequiredByPassTests.cs b/tests/Bws.Core.Tests/RequiredByPassTests.cs index 00b6066..fac9ce2 100644 --- a/tests/Bws.Core.Tests/RequiredByPassTests.cs +++ b/tests/Bws.Core.Tests/RequiredByPassTests.cs @@ -36,7 +36,10 @@ public void Each_entry_is_asked_about_once_and_keeps_its_own_answer() var filled = RequiredByPass.Fill([spooler, other], catalog); - Assert.Equal(["Spooler", "RpcSs"], catalog.DependentsAsked); + // Once each, in whatever order the threads got there - since 2026-09-29 the pass asks + // several at once, and the order of the ASKING was never the claim. The order of the + // ANSWERS is, and it is held just below and in RequiredByPassParallelTests. + Assert.Equal(["RpcSs", "Spooler"], catalog.DependentsAsked.Order(StringComparer.Ordinal)); // Nothing stands on the print spooler on this fixture, and that is an ANSWER rather than // a gap: the manager said so. Absent and refused are told apart below. diff --git a/tests/Bws.Integration.Tests/ListingContractTests.cs b/tests/Bws.Integration.Tests/ListingContractTests.cs index 21c0bda..570d8f3 100644 --- a/tests/Bws.Integration.Tests/ListingContractTests.cs +++ b/tests/Bws.Integration.Tests/ListingContractTests.cs @@ -165,7 +165,8 @@ public void A_partial_answer_is_not_a_failure() /// /// Both halves, because either alone passes over a build that does nothing. A test that /// only asked WITH the switch would pass on one that always read them, which is the cost this - /// family exists to avoid - a call per entry, measured at 236-259 ms over 313 services. A test + /// family exists to avoid - a call per entry, 19-40 ms over 797 entries asked several at once + /// (2026-09-29), 236-259 ms over 313 services when it was first measured one at a time. A test /// that only checked the field was null without it would pass on one that never reads them at /// all. ///