diff --git a/Darling/Darling.Tests/CollectionLogStoreProbeAttributionTests.cs b/Darling/Darling.Tests/CollectionLogStoreProbeAttributionTests.cs new file mode 100644 index 000000000..ea45dc345 --- /dev/null +++ b/Darling/Darling.Tests/CollectionLogStoreProbeAttributionTests.cs @@ -0,0 +1,532 @@ +/* + * Copyright (c) 2026 Erik Darling, Darling Data LLC + * + * This file is part of the SQL Server Performance Monitor. + * + * Licensed under the MIT License. See LICENSE file in the project root for full license information. + */ + +using System; +using System.ComponentModel; +using System.IO; +using System.Linq; +using System.Reflection; +using PerformanceMonitor.Collectors; +using PerformanceMonitor.Darling.Service; +using PerformanceMonitor.Darling.Service.Mcp; +using PerformanceMonitor.Darling.Storage; +using Xunit; + +namespace Darling.Tests; + +/// +/// collection_log.sql_duration_ms is documented and consumed as the time a collector spent querying +/// the MONITORED SERVER, and on the collectors that fetch plan XML or statement text it is mostly not that +/// (#3192). +/// +/// The mechanism. The enumerated driver's per-item stopwatch wraps the watermark refresh and the +/// whole readItem closure (EnumeratedCollectorDriver.RunAsync), and for query_store that +/// closure calls the deferred plan and text fetches — each of which round-trips the STORE to learn what +/// content is already held before writing back what came off the target. On one measured production run +/// sql_duration_ms was 124,972 ms of which the two store probes were 107,334 ms (86%), against a +/// plan-plus-text target time of 6,494 ms. Fleet-wide the store probe is the largest single term in both +/// fetches: 55.4% of plan_fetch and 80.6% of text_fetch (V110). So the product's own +/// "is the target slow or is the store slow" split pointed the wrong way on its heaviest collector, and the +/// projection comment that states the split's purpose sat directly above the column that inverted it. +/// +/// What was NOT done, which is the load-bearing half of the decision. The obvious fix — subtract +/// the store terms from sql_duration_ms, or exclude the fetches from the driver's slice — changes the +/// meaning of a persisted column, and the past cannot be brought along. CollectorRunResult.SqlMs also +/// feeds collect.collector_cost, which is a 90-day hourly aggregate carrying NO phase split +/// (metric_time, server_id, database_name, collector_name, run_count, total_sql_ms, max_sql_ms, +/// total_storage_ms, total_rows) built by an in-memory accumulator rather than re-aggregated from +/// collection_log — so there is nothing there to subtract and no source to re-derive from. Re-basing +/// would leave 90 days meaning one thing and every row after meaning another, under a Collector Cost +/// Regression self-alert whose baseline window is 14 days, which is a fortnight in which a real target-side +/// regression is measured against an inflated baseline. And it would not help those 90 days at all. +/// +/// So the attribution is PUBLISHED rather than applied: SqlStoreMs derives the store share from +/// the V110 columns already on the row, which makes it retroactive to every row that has them and leaves +/// every persisted column exactly as it was. These tests pin the arithmetic, the emit, the caveats on the two +/// surfaces that drew the wrong inference, and the premise the FLOOR caveat rests on. +/// +public class CollectionLogStoreProbeAttributionTests +{ + /// + /// The arithmetic that IS the feature: probe + write of BOTH halves, and NOT the target halves, which are + /// genuinely the monitored server's work and belong where they are. + /// + /// Every figure is deliberately distinct and no two sum to a third, so an implementation that + /// dropped a term, or added the target halves, or summed only one half, produces a different number + /// rather than a coincidentally equal one. The three NotEquals name the specific wrong + /// implementations: probe-only, whole-fetch (probe+target+write), and plan-half-only. + /// + [Fact] + public void TheStoreShareIsProbePlusWrite_AndExcludesTheTargetHalves() + { + var row = Row( + sqlDurationMs: 124_972, + planProbe: 54_016, planTarget: 4_100, planWrite: 830, + textProbe: 53_318, textTarget: 2_394, textWrite: 190); + + Assert.Equal(54_016 + 830 + 53_318 + 190, row.SqlStoreMs); + Assert.Equal(108_354, row.SqlStoreMs); + + /* Probe alone - the shape that reads "the probe is the problem" and silently drops the write-back. */ + Assert.NotEqual(54_016 + 53_318, row.SqlStoreMs); + + /* The whole fetch, target included - the shape that over-claims and would make + sql_duration_ms - sql_store_ms understate target time instead of bounding it above. */ + Assert.NotEqual(54_016 + 4_100 + 830 + 53_318 + 2_394 + 190, row.SqlStoreMs); + + /* One half only - the plan side, which is the half a copy-paste stops at. */ + Assert.NotEqual(54_016 + 830, row.SqlStoreMs); + + /* And the point of the whole exercise, as a comparison rather than as prose: the store share is the + majority of a figure documented as the monitored server's. */ + Assert.True(row.SqlStoreMs > row.SqlDurationMs / 2, + "The measured run this property exists for had 86% of its 'target-side' figure in the store."); + } + + /// + /// NULL when no deferred fetch ran, which is every collector but the fetching ones and most runs of even + /// those. NULL says "nothing here is attributable", which is a different claim from "the store share was + /// zero" — and only one of them is true, because the per-item watermark refresh is a store read inside + /// the same stopwatch on every query_store item whether a fetch ran or not. + /// + /// Per HALF for the non-null case, matching V110's own contract: a run that fetched text but no + /// plans has one block and not the other, and the store share is still the terms that exist. + /// + [Fact] + public void TheStoreShareIsNullWhenNoFetchRan_AndCountsWhicheverHalvesDidRun() + { + /* A plain single-query collector: no fetch columns at all. */ + Assert.Null(Row(sqlDurationMs: 4_000).SqlStoreMs); + + /* Text only. The plan terms are absent, not zero, and must not be read as measured zeros. */ + var textOnly = Row(sqlDurationMs: 9_000, textProbe: 400, textTarget: 80, textWrite: 20); + Assert.Equal(420, textOnly.SqlStoreMs); + + /* Plan only. */ + var planOnly = Row(sqlDurationMs: 9_000, planProbe: 400, planTarget: 80, planWrite: 20); + Assert.Equal(420, planOnly.SqlStoreMs); + + /* A fetch that ran and cost nothing measurable reports 0, not null: V110's gate cannot separate that + from "no fetch ran", and this property inherits the ambiguity rather than inventing a resolution + for it. Asserted so the inheritance is deliberate and not a coincidence of the expression. */ + var subMillisecond = Row(sqlDurationMs: 9_000, planProbe: 0, planTarget: 0, planWrite: 0); + Assert.Equal(0, subMillisecond.SqlStoreMs); + Assert.NotNull(subMillisecond.SqlStoreMs); + } + + /// + /// The premise the FLOOR caveat rests on, pinned as source so it cannot quietly stop being true. + /// + /// The store share is a floor and not the whole because the per-item watermark refresh — a store + /// read, and a store WRITE on the catch-up/adaptive path — is inside the same stopwatch and reaches no + /// column. Two facts make that so: the ENUMERATED branch never declares V108's phases measured, so + /// watermark_ms is NULL on exactly the rows carrying fetch columns; and + /// CollectorContext.PerItemWatermarkMs reaches only the Debug log lines. If either changes, the + /// caveat on SqlStoreMs and on both tool descriptions is wrong, and this is the test that says + /// so. + /// + [Fact] + public void TheEnumeratedWatermarkIsInsideTheSliceAndReachesNoColumn_WhichIsWhyTheShareIsAFloor() + { + var driver = ReadSource("PerformanceMonitor.Collectors/EnumeratedCollectorDriver.cs"); + + /* The slice really does wrap the watermark delegate, not only the read. Both awaits sit between the + StartNew and the finally that banks it. */ + var start = driver.IndexOf("var sqlSlice = Stopwatch.StartNew();", StringComparison.Ordinal); + var banked = driver.IndexOf("itemSqlMs = sqlSlice.ElapsedMilliseconds;", StringComparison.Ordinal); + Assert.True(start > 0 && banked > start, "Could not locate the driver's per-item SQL slice."); + + var slice = driver[start..banked]; + var watermarkAt = slice.IndexOf("await perItemWatermark(item, itemToken);", StringComparison.Ordinal); + var readAt = slice.IndexOf("batch = await readItem(item, itemToken);", StringComparison.Ordinal); + Assert.True(watermarkAt > 0, "The watermark refresh is no longer inside the driver's SQL slice."); + Assert.True(readAt > watermarkAt, "The read must still follow the watermark refresh inside the slice."); + + /* And the clock is not reset between them. A Restart() after the watermark award would exclude it + from the slice while leaving both awaits textually where they are - the mutation the two + Contains-shaped assertions above cannot see, and the reason they are not the whole check. */ + Assert.DoesNotContain("sqlSlice.Restart()", driver, StringComparison.Ordinal); + Assert.Equal(1, CountOccurrences(driver, "sqlSlice = Stopwatch.StartNew();")); + + /* Positive control for that pair of negatives: the slice's own clock really is a Stopwatch under + that name, so neither assertion is passing against a variable that has been renamed away. */ + Assert.Contains("var sqlSlice = Stopwatch.StartNew();", driver, StringComparison.Ordinal); + + /* The GATE, called on the shipped record rather than asserted about the source: a result that + measured a watermark but did not declare V108's phases measured persists no phase triple at all, + so watermark_ms is NULL however large that read was. The two paths share ONE return statement, so + there is no per-branch literal to assert about - the flag is a variable, and asserting the absence + of "ServerPhasesMeasured: true" at that return would have been a pin that no reachable mutation + could turn red. */ + var enumeratedShape = new CollectorRunResult( + Rows: 11_614, SqlMs: 124_972, StorageMs: 1_500, + Measurements: CollectorContext.NoMeasurements, + ServerPhasesMeasured: false, + ServerWatermarkMs: 50_000, + FetchPhases: new FetchPhaseCost(new FetchPhaseSums(54_016, 4_100, 830, 12, 6_252), null)); + + Assert.Null(enumeratedShape.ServerPhases); + Assert.NotNull(enumeratedShape.FetchPhases); + + /* Positive control for that null: the identical construction WITH the flag does report a triple, so + the assertion above is the gate answering and not a member that has stopped existing. */ + Assert.NotNull((enumeratedShape with { ServerPhasesMeasured = true }).ServerPhases); + + /* And the flag is raised at exactly ONE site, which sits BELOW the enumerated branch's driver call - + so the enumerated path cannot reach it. A second assignment anywhere, including inside that + branch, reds the count. */ + var runner = ReadSource("Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs"); + Assert.Equal(1, CountOccurrences(runner, "serverPhasesMeasured = true;")); + Assert.True( + runner.IndexOf("serverPhasesMeasured = true;", StringComparison.Ordinal) + > runner.IndexOf("EnumeratedCollectorDriver.RunAsync(", StringComparison.Ordinal), + "The measured flag must stay below the enumerated branch, which is what keeps watermark_ms NULL " + + "on precisely the rows sql_store_ms is non-null on - the premise the FLOOR caveat rests on."); + + /* And the stamp reaches no persisted column: the collection_log INSERT names no watermark parameter + fed from the per-item member, so there is nothing to subtract even for a reader who wants to. */ + Assert.DoesNotContain("PerItemWatermarkMs", + ReadSource("Darling/PerformanceMonitor.Darling.Service/DarlingObservability.cs"), + StringComparison.Ordinal); + + /* Positive control: the member exists and the runner really does read it. */ + Assert.Contains("context.PerItemWatermarkMs", runner, StringComparison.Ordinal); + } + + /// + /// Persisting or deriving a figure nothing REPORTS is half a feature — the failure V108 and V109 each + /// shipped on this exact table and V110 fixed in passing. So the emit is pinned, and pinned as a + /// delegation to the shipped property rather than as a recomputation at the projection: a second copy of + /// the arithmetic is a second thing to get wrong, and the SqlOtherMs precedent is that the + /// subtraction has one definition a test can reach. + /// + [Fact] + public void TheProjectionEmitsTheStoreShare_ByDelegatingToTheShippedProperty() + { + var tools = ReadSource("Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpDataTools.cs"); + + Assert.Contains("sql_store_ms = r.SqlStoreMs", tools, StringComparison.Ordinal); + + /* It sits beside the two columns whose comment states the split's purpose, which is the comment the + defect was found under - not buried inside a fetch block that a row without a fetch would null + away along with the attribution. */ + var sqlAt = tools.IndexOf("sql_duration_ms = r.SqlDurationMs", StringComparison.Ordinal); + var storeShareAt = tools.IndexOf("sql_store_ms = r.SqlStoreMs", StringComparison.Ordinal); + var planBlockAt = tools.IndexOf("plan_fetch = r.PlanFetchProbeMs is null", StringComparison.Ordinal); + Assert.True(sqlAt > 0 && storeShareAt > sqlAt && storeShareAt < planBlockAt, + "sql_store_ms must be emitted flat beside sql_duration_ms, not nested in a fetch block."); + + /* No second copy of the arithmetic anywhere in the projection: the terms must not be re-added here. */ + Assert.DoesNotContain("r.PlanFetchProbeMs.Value + r.PlanFetchWriteMs", tools, StringComparison.Ordinal); + } + + /// + /// The two surfaces that drew the target-side inference now refuse to draw it, asserted against the + /// SHIPPED attribute text rather than a source grep — a description is a consumer API for an LLM client, + /// and reading it off the attribute is what a client actually receives. + /// + /// get_collector_cost is the one that mattered most and the one that can do least: its + /// series carries no phase split, so it can only name the caveat and point at the per-run tool. Both of + /// its response shapes carry it, from one constant — the single-collector trend is the shape a regression + /// investigation lands on and it had no caveat at all. + /// + [Fact] + public void NeitherCostSurfaceStillClaimsTheFigureIsTargetSide() + { + var cost = ToolDescription(typeof(DarlingMcpCollectorCostTools), nameof(DarlingMcpCollectorCostTools.GetCollectorCost)); + + /* The exact phrase that made the claim. */ + Assert.DoesNotContain("target-side query duration", cost, StringComparison.OrdinalIgnoreCase); + + /* Positive control for that negative: the description is really being read, and really is the one. */ + Assert.Contains("per-collector cost", cost, StringComparison.OrdinalIgnoreCase); + + Assert.Contains("MONITORING STORE", cost, StringComparison.Ordinal); + Assert.Contains("sql_store_ms", cost, StringComparison.Ordinal); + Assert.Contains("no phase split", cost, StringComparison.OrdinalIgnoreCase); + + /* Both response shapes carry the caveat, and from ONE constant rather than two copies that could + drift - the trend shape is the one a regression lands on. */ + var source = ReadSource("Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpCollectorCostTools.cs"); + Assert.Equal(2, CountOccurrences(source, "+ StoreProbeCaveat")); + Assert.DoesNotContain("target-side query DURATION", source, StringComparison.Ordinal); + + /* The READER the fixed tool calls through, and the evaluator doc sitting above the fixed alert text. + Review found three copies in the first and one in the second, uncorrected - a description that + refuses the claim while the code it reads through still asserts it is the same defect one file + over, so the sweep is by PHRASE across the whole call path rather than per site. */ + foreach (var path in new[] + { + "Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCollectorCostReader.cs", + "Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs", + "Darling/PerformanceMonitor.Darling.Service/CollectorCostAccumulator.cs", + }) + { + /* FLATTENED first, and this is the whole reason the helper exists rather than a bare + DoesNotContain. Mutation-testing this pin caught it: restoring "a DURATION on the target" put + the phrase across a doc-comment line break, so the exact-substring form matched nothing and + reported GREEN on the very claim it was written to forbid. A pin that cannot fail is worse + than no pin, because it certifies the defect. Every phrase below is swept against prose whose + `///` continuations and whitespace runs have been collapsed, so wrapping cannot hide it. */ + var text = FlattenDocProse(ReadSource(path)); + + Assert.DoesNotContain("target-side cost", text, StringComparison.Ordinal); + Assert.DoesNotContain("target-side duration", text, StringComparison.Ordinal); + Assert.DoesNotContain("target-side query time", text, StringComparison.Ordinal); + Assert.DoesNotContain("DURATION on the target", text, StringComparison.Ordinal); + Assert.DoesNotContain("duration on the target", text, StringComparison.Ordinal); + + /* Positive control for the five negatives, per file: each one really does still discuss the + figure, so none of them is passing against a file that has stopped saying anything. */ + Assert.Contains("sql_ms", text, StringComparison.Ordinal); + + /* And a control on the FLATTENER, per file, because a helper that returned the empty string + would make every negative above pass. A wrapped phrase this fix deliberately kept must be + findable through it. */ + Assert.Contains("monitored servers", text, StringComparison.Ordinal); + } + + var log = ToolDescription(typeof(DarlingMcpDataTools), nameof(DarlingMcpDataTools.GetCollectionLog)); + Assert.Contains("sql_store_ms", log, StringComparison.Ordinal); + Assert.Contains("UPPER bound", log, StringComparison.Ordinal); + Assert.Contains("MONITORING STORE", log, StringComparison.Ordinal); + + /* And the web grid's column header, which named the monitored server in two words. */ + var page = ReadSource("Darling/PerformanceMonitor.Darling.Service/wwwroot/js/pages/server-tabs.js"); + Assert.DoesNotContain("label: \"On Server\"", page, StringComparison.Ordinal); + Assert.Contains("{ key: \"sql_store_ms\", label: \"Store (in SQL)\", format: \"ms\" },", page, StringComparison.Ordinal); + + /* Positive control: the sibling header this one sat beside is untouched, so the DoesNotContain above + is not passing because the grid moved somewhere this test cannot see. */ + Assert.Contains("label: \"On Store\"", page, StringComparison.Ordinal); + } + + /// + /// The decision NOT to re-base the column, pinned where reversing it would be silent. + /// + /// collect.collector_cost is V105's nine columns and no phase split, so a re-based + /// SqlMs could not be reconciled against the 90 days already in it — and the worker hands the + /// accumulator result.SqlMs unmodified, which is what makes the series internally consistent + /// across the deploy. Both halves are asserted: a future change that subtracts at the call site, or one + /// that adds a phase column here, reds this test and has to move the caveats on + /// get_collector_cost, CollectorCostAccumulator and SqlStoreMs with it. That is the + /// point — the trade is recorded, not forbidden. + /// + [Fact] + public void TheCostSeriesIsUnchanged_SoItsNinetyDaysStayComparableWithWhatFollows() + { + var v105 = PgMigrations.Scripts.Single(s => s.Version == 105).Sql; + + foreach (var column in new[] + { + "metric_time", "server_id", "database_name", "collector_name", + "run_count", "total_sql_ms", "max_sql_ms", "total_storage_ms", "total_rows", + }) + { + Assert.Contains(column, v105, StringComparison.Ordinal); + } + + /* No phase split in this series, which is the bound on what any fix could achieve here. */ + foreach (var absent in new[] { "probe_ms", "sql_open_ms", "sql_drain_ms", "watermark_ms", "sql_store_ms" }) + { + Assert.DoesNotContain(absent, v105, StringComparison.Ordinal); + } + + /* Positive control for those five negatives, through the identical containment form. */ + Assert.Contains("total_sql_ms", v105, StringComparison.Ordinal); + + /* And the blended figure is handed over unmodified. A subtraction here is the option-1 change, and it + is a decision rather than a tidy-up. */ + Assert.Contains( + "_collectorCost.Record(runtime.ServerId, collectorName, result.Rows, result.SqlMs, result.StorageMs);", + ReadSource("Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs"), StringComparison.Ordinal); + } + + /// + /// The driver's per-item budget doc used to say the budget was null for "every collector but + /// query_store", in two places. Four definitions declare one and two of those also enumerate, so + /// plan_correction reaches that parameter non-null as well — found while correcting the parameter + /// immediately above it. + /// + /// Derived from CollectorCatalog.All rather than restated, because a name in prose is a + /// frozen enumeration: it was right when written and went wrong the moment a second collector earned a + /// budget, with nothing to say so. The same argument CollectorCatalog.HasWallClockBudget's own doc + /// makes for existing at all. + /// + [Fact] + public void TheDriverNoLongerNamesOneCollectorAsTheOnlyBudgetedOne() + { + var budgeted = CollectorCatalog.All + .Where(d => d.PerItemWallClockBudget is not null) + .Select(d => d.Name) + .OrderBy(n => n, StringComparer.Ordinal) + .ToList(); + + /* More than one, which is the whole claim - asserted as a count derived from the catalog so it stays + true as the catalog grows, and named too so a definition losing its budget is visible. */ + Assert.True(budgeted.Count > 1, "The doc's premise was that exactly one collector declares a budget."); + Assert.Contains("query_store", budgeted); + Assert.Contains("plan_correction", budgeted); + + /* plan_correction is the one that makes the old wording false: it declares a budget AND enumerates, + so it reaches the driver's perItemBudget parameter. Derived by calling the real definition. */ + var planCorrection = CollectorCatalog.All.Single(d => d.Name == "plan_correction"); + Assert.NotNull(planCorrection.PerItemWallClockBudget); + + var driver = ReadSource("PerformanceMonitor.Collectors/EnumeratedCollectorDriver.cs"); + Assert.DoesNotContain("Null (every collector but query_store)", driver, StringComparison.Ordinal); + Assert.DoesNotContain("which is every collector but query_store", driver, StringComparison.Ordinal); + + /* Positive control for the two negatives: the parameter they document is still there under that + name, so the assertions are not passing on a file that no longer says anything. */ + Assert.Contains("", driver, StringComparison.Ordinal); + + /* THREE copies of the claim, not two - the third is at the runner's own call site, and it is the + one a reader of the enumerated branch actually meets. */ + var runner = ReadSource("Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs"); + Assert.DoesNotContain("Null for every collector but", runner, StringComparison.Ordinal); + + /* And no FOURTH copy, swept by counting the phrase against its QUOTED form. The correction has to be + able to name what it corrected, so a flat DoesNotContain fails on this very fix's own prose - the + trap V110's accumulation pin hit and documented. Every surviving occurrence must be inside a + `Not "..."` quotation; a new one asserted as fact breaks the equality. + + Stated rather than implied: this pair catches a REVERSION and a NEW copy, and does not catch + deleting the corrected paragraph outright. The catalog-derived assertions above are what make the + claim itself checkable; these two make its retraction stick. */ + foreach (var source in new[] { driver, runner }) + { + Assert.Equal( + CountOccurrences(source, "Not \"every collector but"), + CountOccurrences(source, "every collector but")); + } + + /* Positive control for that equality: the phrase really is present in both files in its quoted form, + so 0 == 0 cannot be what is passing. */ + Assert.True(CountOccurrences(driver, "every collector but") > 0); + Assert.True(CountOccurrences(runner, "every collector but") > 0); + } + + /// + /// Lite does NOT have the defect, and the pin is here so nobody "fixes" it into having one. + /// + /// Review read this PR and concluded Lite's query_store "has the identical store-probe + /// contamination" because Lite sums the same driverResult.SqlMs from the same shared driver. It + /// does not. The fetches are gated on CollectorContext.CapturePlanXml and + /// FetchQueryTextSeparately, and Lite sets neither — that is what makes Darling the plan-capturing + /// SKU — so no probe and no write-back ever runs there. What Lite DOES share is the watermark shape: its + /// query_store reaches the driver's perItemWatermark, which reads its local store inside the + /// slice. So Lite's description gains that precision and explicitly disclaims the probe half, and this + /// test asserts the disclaimer rather than the correction — a Lite description that CLAIMED store-probe + /// time would be asserting a cost that cannot be incurred, and would send someone building V110-equivalent + /// DuckDB columns that could only ever be NULL. + /// + [Fact] + public void LiteNeverRunsTheFetches_SoItsDescriptionDisclaimsTheProbeRatherThanInheritingTheCaveat() + { + /* The gates, from the shipped context: Lite sets neither, so the probe cannot run there. Asserted + against the Lite source rather than trusted from V110's prose. */ + var liteRunner = ReadSource("Lite/Services/RemoteCollectorService.DefinitionRunner.cs"); + Assert.DoesNotContain("CapturePlanXml = true", liteRunner, StringComparison.Ordinal); + Assert.DoesNotContain("FetchQueryTextSeparately = true", liteRunner, StringComparison.Ordinal); + + /* Positive control: that file really is Lite's enumerated runner, so the two negatives are not + passing against a file that has moved. */ + Assert.Contains("EnumeratedCollectorDriver.RunAsync(", liteRunner, StringComparison.Ordinal); + + /* And it really does reach the watermark delegate, which is the part that DOES carry over. */ + Assert.Contains("perItemWatermark:", liteRunner, StringComparison.Ordinal); + + /* Lite's description read as SOURCE rather than by reflection: Darling.Tests deliberately holds no + ProjectReference to Lite, and reading Lite .cs across the seam is the pattern #2839 established for + exactly this. Sliced to the one tool's attribute so a sibling tool's text cannot satisfy it. */ + var liteTools = ReadSource("Lite/Mcp/McpHealthTools.cs"); + var at = liteTools.IndexOf("Name = \"get_collection_log\"", StringComparison.Ordinal); + Assert.True(at > 0, "Could not locate Lite's get_collection_log tool."); + var lite = liteTools[at..liteTools.IndexOf(")]", at, StringComparison.Ordinal)]; + + Assert.Contains("watermark refresh", lite, StringComparison.Ordinal); + Assert.Contains("never enables the deferred", lite, StringComparison.Ordinal); + + /* The disclaimer, not the caveat: Lite must not advertise a store-probe share it cannot have, and + must not point at a sql_store_ms field its tool does not emit. */ + Assert.DoesNotContain("sql_store_ms", lite, StringComparison.Ordinal); + + /* Positive control for that negative: the slice really is a tool description carrying the subject, + so the assertion is not passing on an empty span. */ + Assert.Contains("sql_duration_ms", lite, StringComparison.Ordinal); + } + + /// + /// Collapses C# doc-comment continuations and whitespace runs so a phrase sweep sees PROSE rather than + /// lines. Without it a claim wrapped across two /// lines is invisible to an exact-substring + /// assertion — which is not hypothetical: it is the mutation that reported GREEN and forced this helper. + /// + private static string FlattenDocProse(string source) + { + var text = source.Replace("\r\n", "\n", StringComparison.Ordinal); + text = System.Text.RegularExpressions.Regex.Replace(text, @"\n\s*///?\s*", " "); + return System.Text.RegularExpressions.Regex.Replace(text, @"\s+", " "); + } + + private static int CountOccurrences(string haystack, string needle) + { + var count = 0; + for (var at = haystack.IndexOf(needle, StringComparison.Ordinal); at >= 0; + at = haystack.IndexOf(needle, at + needle.Length, StringComparison.Ordinal)) + { + count++; + } + + return count; + } + + /// The SHIPPED [Description] an MCP client receives, off the method rather than out of source. + private static string ToolDescription(Type toolType, string methodName) => + toolType.GetMethod(methodName, BindingFlags.Public | BindingFlags.Static)! + .GetCustomAttribute()!.Description; + + /// One collection_log row as the reader materializes it. + private static DarlingDataReader.CollectionLogEntry Row( + double sqlDurationMs, + double? planProbe = null, double? planTarget = null, double? planWrite = null, + double? textProbe = null, double? textTarget = null, double? textWrite = null) => + new( + CollectorName: "query_store", + CollectionTime: new DateTime(2026, 9, 9, 0, 0, 0, DateTimeKind.Utc), + DurationMs: sqlDurationMs, + SqlDurationMs: sqlDurationMs, + StoreDurationMs: 1_500, + RowsCollected: 11_614, + Status: "SUCCESS", + ErrorMessage: null, + PlanFetchProbeMs: planProbe, + PlanFetchTargetMs: planTarget, + PlanFetchWriteMs: planWrite, + TextFetchProbeMs: textProbe, + TextFetchTargetMs: textTarget, + TextFetchWriteMs: textWrite); + + /// Reads a repo source file by walking up from the test binary to the repo root. + private static string ReadSource(string relativePath) + { + var dir = AppContext.BaseDirectory; + for (var i = 0; i < 12 && dir is not null; i++) + { + var candidate = Path.Combine(dir, relativePath); + if (File.Exists(candidate)) + { + return File.ReadAllText(candidate); + } + + dir = Directory.GetParent(dir)?.FullName; + } + + throw new FileNotFoundException($"Could not locate {relativePath} from {AppContext.BaseDirectory}"); + } +} diff --git a/Darling/PerformanceMonitor.Darling.Service/CollectorCostAccumulator.cs b/Darling/PerformanceMonitor.Darling.Service/CollectorCostAccumulator.cs index 9cfe778b3..12a9f3a64 100644 --- a/Darling/PerformanceMonitor.Darling.Service/CollectorCostAccumulator.cs +++ b/Darling/PerformanceMonitor.Darling.Service/CollectorCostAccumulator.cs @@ -29,9 +29,19 @@ namespace PerformanceMonitor.Darling.Service; /// preserves the TAIL — a single 555s execution is how a collector sticks out on a target, and an hourly /// average would hide it. /// -/// sql_ms is a DURATION on the target (it includes waits), not pure CPU — a slow collector may be -/// latch-waiting rather than burning CPU. It still holds a connection/slot and competes, which is the -/// point of watching it. +/// sql_ms is a DURATION (it includes waits), not pure CPU — a slow collector may be latch-waiting +/// rather than burning CPU. It still holds a connection/slot and competes, which is the point of watching +/// it. +/// +/// "On the target" is not true of every collector, and the exception is the most expensive one +/// (#3192). CollectorRunResult.SqlMs is the driver's SQL slice, and on the ENUMERATED path that +/// slice wraps the per-item watermark refresh and the deferred plan/text fetches — all of which touch the +/// STORE. For query_store the store probe and write are the majority of it (107,334 of 124,972 ms on +/// one measured run; 55.4% of plan_fetch and 80.6% of text_fetch fleet-wide per V110). This +/// series cannot be corrected for it: it aggregates the blended figure in memory and flushes an hourly +/// total, so there is no phase split to subtract and no source table to re-derive from. That bound is why +/// the number is left alone and named instead — get_collector_cost carries the caveat and +/// get_collection_log's sql_store_ms carries the per-run attribution. /// public sealed class CollectorCostAccumulator { diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs index da5097612..531001642 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs @@ -42,6 +42,27 @@ namespace PerformanceMonitor.Darling.Service; /// default would let those sites stand in for the ONE success site that must pass the real list, which is /// the site whose silence #3161 was filed about. The compiler names every site instead of a grep. /// +/// +/// What lands in collection_log.sql_duration_ms: the driver's SQL slice for this run. +/// +/// Not a purely target-side figure, and on the heaviest collector mostly not one (#3192). On +/// the enumerated path this is the per-item stopwatch around the watermark refresh plus the whole +/// readItem closure, and for query_store that closure calls +/// DarlingCollectorRunner.FetchAndStorePlansAsync / +/// FetchAndStoreQueryTextAsync — each of which probes the STORE for +/// what content is already held and writes back what came off the target. One measured production run put +/// 107,334 ms of a 124,972 ms SqlMs in the store against 6,494 ms of plan-plus-text target time, and +/// the store probe is the largest single term in both fetches fleet-wide (55.4% / 80.6%, V110). +/// +/// Deliberately left blended rather than re-based, and the reason is downstream: this value is +/// also what sums into collect.collector_cost, a 90-day hourly +/// series that carries NO phase split and is built in memory rather than re-aggregated from +/// collection_log. Subtracting the store terms here would leave 90 days of rows meaning one thing and +/// every row after meaning another, with nothing in that series able to reconcile them — under a +/// Collector Cost Regression self-alert whose baseline window is 14 days. The attribution is published +/// instead of applied: derives the store +/// share from the V110 columns, which makes it retroactive to every row that has them. +/// /// /// The note the RUNNER authored for a run worth explaining on its collection_log row: the RDS ingest /// outcome, the whole-cycle budget, the probe-failure summary, the fan-out bookkeeping. Null (the default) @@ -2083,8 +2104,11 @@ line and a fetchless collector prints none. */ definition.Name, item, server.Config.DisplayName, ex.Message); }, cancellationToken, - /* #2150: the per-database wall-clock ceiling. Null for every collector but - query_store, so this argument leaves every other cycle untouched. */ + /* #2150: the per-database wall-clock ceiling, straight off the definition, so this + argument leaves a cycle whose collector declares none exactly as it was. + Not "every collector but query_store", which is what this said: four definitions + declare a budget and two of them also enumerate, so plan_correction arrives here + non-null too. */ perItemBudget: definition.PerItemWallClockBudget); rowsWritten = driverResult.Rows; diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs index 48324f557..35fa138f2 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs @@ -186,6 +186,21 @@ the daily TOTAL so a cheap-but-frequent collector still cannot trip on a per-run /// alone cannot tell that answer from a genuinely new one. Mirrors #2704's /// PoisonWaitDelta.CollectionTime fix for the identical shape of bug. private readonly ConcurrentDictionary _lastCostRegressionDataPoint = new(); + /// + /// #3192: the figure this condition fires on is collect.collector_cost.total_sql_ms, which is the + /// driver's SQL slice — and on the enumerated path that slice contains the per-item watermark refresh and + /// the deferred plan/text fetches, all of which touch the monitoring STORE. So a query_store + /// regression here can be the store getting slower rather than the target, and the alert used to say + /// flatly that it was "cost on the target". Appended rather than folded into the sentence above so the + /// text stays one substitution away from being re-worded, and stated on the alert itself because that is + /// where the reader is when the inference gets made. + /// + private const string CostIsNotAllTargetSide = + "NOTE: on collectors that fetch plan XML or statement text (query_store), part of this figure is the " + + "monitoring STORE's own probe and write rather than the monitored server - they run inside the same " + + "per-item stopwatch. get_collection_log's sql_store_ms attributes it per run; this series carries no " + + "phase split."; + private const double CostRegressionFactor = 2.0; private const long CostRegressionBaselineFloorMs = 1000; private static readonly TimeSpan CostRegressionBaselineWindow = TimeSpan.FromDays(14); @@ -697,8 +712,14 @@ await RecordResolutionAsync(new AlertResolution( /// FLEET-level (not per-server): the tool's OWN collectors regressing in cost ON the monitored servers /// (#2674) — the self-monitoring that makes a collector "sticking out" on a target page us instead of /// hiding in a log. Reads collect.collector_cost for per-(server, collector) pairs whose latest - /// day's target-side query time exceeds their own baseline (see the thresholds above), fires once per pair + /// day's query time exceeds their own baseline (see the thresholds above), fires once per pair /// on entry, re-fires on the cooldown while it stays regressed, and resolves the moment it drops back. + /// + /// "ON the monitored servers" is the series' intent and not always what it measures (#3192): the + /// figure rolls up the driver's SQL slice, which on the enumerated path contains the store's own + /// plan/text probe and write-back. So a query_store regression here can be the STORE getting + /// slower rather than the target, and the fired alert says so — see + /// , which exists because this doc and that text have to agree. /// Called once per cycle from the worker's hourly store-metrics tick, AFTER the flush that writes the /// latest hour. Testable directly with a recording deliverer + a controllable clock. /// @@ -759,10 +780,10 @@ await FireAsync( detail: $"The '{regression.CollectorName}' collector's OWN query time on {regression.ServerName} rose to " + $"{regression.LatestMsPerRun:N1} ms per run, {ratio:N1}x its {CostRegressionBaselineWindow.TotalDays:N0}-day " + $"baseline of {regression.BaselineMsPerRun:N1} ms per run ({regression.LatestRuns:N0} runs totalling " + - $"{regression.LatestMs:N0} ms so far today). This is the MONITORING TOOL's cost on the target, not the " + - $"server's own workload - each individual run is costing more than it used to. Measured PER RUN (#2846) so " + + $"{regression.LatestMs:N0} ms so far today). This is the MONITORING TOOL's own cost, not the " + + $"server's workload - each individual run is costing more than it used to. Measured PER RUN (#2846) so " + $"a cadence change cannot read as a cost change. get_collector_cost with " + - $"collector_name={regression.CollectorName} shows the trend.", + $"collector_name={regression.CollectorName} shows the trend. {CostIsNotAllTargetSide}", severity: AlertSeverityLevel.Warning, shortMessage: $"{regression.CollectorName} collection cost on {regression.ServerName} is {ratio:N1}x its per-run baseline", numericCurrentValue: regression.LatestMsPerRun, diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCollectorCostReader.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCollectorCostReader.cs index f77861799..92e28cc44 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCollectorCostReader.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCollectorCostReader.cs @@ -22,8 +22,16 @@ namespace PerformanceMonitor.Darling.Service.Mcp; /// /// Two reads: the ranked fleet summary over a window (total and per-run cost, and the TAIL — the /// worst single execution, which is how a collector "sticks out" on a target), and a per-collector daily -/// trend that both the panel charts and the self-alert's baseline consume. sql_ms is a DURATION on the -/// target, not pure CPU. +/// trend that both the panel charts and the self-alert's baseline consume. sql_ms is a DURATION, not pure +/// CPU. +/// +/// And not reliably a TARGET-side duration either (#3192), which is why the word is absent +/// above and from the members below. It rolls up CollectorRunResult.SqlMs, and on the enumerated path +/// that is the driver's per-item stopwatch around the watermark refresh and the whole readItem closure +/// — so for query_store the store's plan/text probe and write-back are inside it, measured at 107,334 +/// of 124,972 ms on one production run. This series carries no phase split and is flushed hourly from an +/// in-memory accumulator, so nothing here can subtract it; +/// get_collection_log's sql_store_ms is where the attribution lives. /// internal static class DarlingCollectorCostReader { @@ -65,7 +73,8 @@ public sealed record CollectorCostSummaryRow( long TotalRows, int ServerCount) { - /// Average target-side duration per run, over the window. Zero when nothing ran. + /// Average duration per run, over the window. Zero when nothing ran. NOT purely target-side + /// on the plan/text-fetching collectors — see this class's remarks (#3192). public long AvgSqlMs => RunCount > 0 ? TotalSqlMs / RunCount : 0; } @@ -120,7 +129,7 @@ public static async Task> GetTrendAsync( return rows; } - /// A collector whose most-recent day's target-side cost regressed against its own baseline + /// A collector whose most-recent day's cost regressed against its own baseline /// (#2674) — the self-alert's detection query. Per (server, collector): latest day's cost PER RUN vs the /// run-weighted cost per run of the prior days in the window, returned only when the baseline is /// meaningful (total >= floor, and at least 3 prior days so a new collector cannot trip it) and the diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingDataReader.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingDataReader.cs index 88a32fca2..b316c685a 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingDataReader.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingDataReader.cs @@ -125,6 +125,44 @@ phases run on separate stopwatches and tiny skew must not surface as a negative. SqlDurationMs is null || SqlOpenMs is null || SqlDrainMs is null ? null : Math.Max(0, SqlDurationMs.Value - SqlOpenMs.Value - SqlDrainMs.Value); + + /// + /// The milliseconds inside that were spent against the monitoring + /// STORE rather than the monitored target (#3192). NULL when this run performed no deferred fetch, + /// which is every collector but the plan/text-fetching ones and most runs of even those. + /// + /// Why a target-side column contains store time at all. On the ENUMERATED path the + /// driver's per-item stopwatch wraps the whole readItem closure + /// (EnumeratedCollectorDriver.RunAsync), and for query_store that closure calls + /// FetchAndStorePlansAsync / FetchAndStoreQueryTextAsync — each of which round-trips + /// the store to learn what content is already held and then writes back what came off the target. + /// Two of those three steps are Postgres, and all three are billed to sql_duration_ms. The + /// store probe is the largest single term in both: 55.4% of plan_fetch and 80.6% of + /// text_fetch measured over 38.2 h on 42 members (V110), and on one production run 107,334 ms + /// of a 124,972 ms "target-side" figure — 86% — against a plan-plus-text target time of 6,494 ms. + /// + /// Probe and write, not target. *FetchTargetMs is genuinely the monitored + /// server's work and belongs where it is; only the probe round trip and the write-back are ours. + /// + /// Derived, never stored — the and #2859 rule: a persisted copy + /// could drift from the parent it decomposes, and deriving it means it applies RETROACTIVELY to every + /// row written since V110 rather than only to rows written after this change. Nothing about + /// sql_duration_ms moves, so the 90-day collector_cost series and the rows already in + /// the store stay comparable with each other and with what follows. + /// + /// A FLOOR on the store share, not the whole of it, and the gap is named rather than + /// implied. The enumerated path's per-item watermark refresh is also inside the same stopwatch and + /// is also a store read — plus a store WRITE on the catch-up/adaptive path + /// (CollectorContext.PerItemWatermarkMs) — but that path never sets V108's measured flag, so + /// watermark_ms is NULL on precisely the rows this property is non-null on and the component is + /// recorded nowhere. So SqlDurationMs - SqlStoreMs is an UPPER bound on target-side time, not + /// the target-side time. + /// + public double? SqlStoreMs => + PlanFetchProbeMs is null && TextFetchProbeMs is null + ? null + : (PlanFetchProbeMs ?? 0) + (PlanFetchWriteMs ?? 0) + + (TextFetchProbeMs ?? 0) + (TextFetchWriteMs ?? 0); } /// One database file's latest I/O snapshot; avg latency is computed by the tool. diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpCollectorCostTools.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpCollectorCostTools.cs index 347e44f63..ee3edde7c 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpCollectorCostTools.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpCollectorCostTools.cs @@ -30,8 +30,27 @@ public sealed class DarlingMcpCollectorCostTools { public const int MaxDaysBack = CollectorCostAccumulator.RetentionDays; + /// + /// The one sentence that keeps this tool's headline number from being read as the monitored servers' + /// fault (#3192). Emitted on BOTH shapes — the ranked list and the single-collector trend — from one + /// constant rather than two copies, because the trend is the shape a regression investigation lands on + /// and it is the one that had no caveat at all. + /// + /// sql_ms comes from CollectorRunResult.SqlMs, which on the enumerated path is the driver's + /// per-item stopwatch around the whole readItem closure — and for query_store that closure + /// probes and writes the STORE. This series cannot be corrected for it: + /// sums the blended figure in memory and flushes an hourly total, so there is no phase split here to + /// subtract and no source table to re-aggregate from. Naming the caveat is the whole of what this + /// surface can honestly do; get_collection_log.sql_store_ms is where the attribution lives. + /// + internal const string StoreProbeCaveat = + "On query_store, part of sql_ms is the MONITORING STORE's own plan/text probe and write, not the " + + "monitored server: those fetches run inside the same per-item stopwatch, and the probe measured " + + "55.4% of plan_fetch and 80.6% of text_fetch on this fleet. This series carries no phase split, so " + + "read get_collection_log's sql_store_ms per run before concluding a target is slow."; + [McpServerTool(Name = "get_collector_cost"), Description( - "Gets the monitoring tool's OWN per-collector cost ON the monitored servers — which of THIS tool's collectors are the most expensive to run, so a hog shows on a dashboard instead of a log scrape. This is the tool measuring itself, NOT a monitored SQL Server. The service records an hourly aggregate per (server, collector): run count, total and average target-side query duration in ms (sql_ms is a DURATION that includes waits, not pure CPU), the WORST single execution in the window (max_sql_ms — the tail is how a collector sticks out on a target), store-write time, rows collected, and how many servers ran it. Returns the ranked fleet list, most expensive by total_sql_ms first. Pass collector_name to get that ONE collector's daily trend instead (summed cost and the day's worst execution), for spotting a regression against its own history.")] + "Gets the monitoring tool's OWN per-collector cost ON the monitored servers — which of THIS tool's collectors are the most expensive to run, so a hog shows on a dashboard instead of a log scrape. This is the tool measuring itself, NOT a monitored SQL Server. The service records an hourly aggregate per (server, collector): run count, total and average query duration in ms (sql_ms is a DURATION that includes waits, not pure CPU), the WORST single execution in the window (max_sql_ms — the tail is how a collector sticks out on a target), store-write time, rows collected, and how many servers ran it. Returns the ranked fleet list, most expensive by total_sql_ms first. Pass collector_name to get that ONE collector's daily trend instead (summed cost and the day's worst execution), for spotting a regression against its own history. CRITICAL — sql_ms is NOT purely target-side on the collectors that fetch plan XML or statement text (query_store). Those fetches run inside the driver's per-item SQL stopwatch and each one round-trips the MONITORING STORE to decide what content is already held before writing back what came off the target, so the store's probe and write land in this figure. On this fleet the store probe is the largest single term in both fetches — 55.4% of plan_fetch and 80.6% of text_fetch — and on one production run it was 107,334 ms of a 124,972 ms figure, 86%, against a plan-plus-text target time of 6,494 ms. This series carries NO phase split (it is an hourly total per server and collector, nothing more), so the attribution cannot be recovered here at all: use get_collection_log, whose sql_store_ms names the store share per run. Do NOT read a large total_sql_ms or max_sql_ms on query_store as evidence that the monitored servers are slow.")] public static async Task GetCollectorCost( NpgsqlDataSource postgres, [Description("Days of history to summarize. Default 7; max 90 (the series' own retention).")] int days_back = 7, @@ -61,7 +80,8 @@ public static async Task GetCollectorCost( { collector_name = collector_name.Trim(), days_back, - note = "sql_ms is target-side query DURATION (includes waits), not pure CPU. max_sql_ms is the day's worst single execution.", + note = "sql_ms is query DURATION (includes waits), not pure CPU. max_sql_ms is the day's worst single execution. " + + StoreProbeCaveat, trend = trend.Select(p => new { day = p.Day, @@ -85,7 +105,8 @@ public static async Task GetCollectorCost( return JsonSerializer.Serialize(new { days_back, - note = "The tool's OWN cost on the monitored servers. sql_ms is target-side query DURATION (includes waits), not pure CPU. max_sql_ms is the worst single execution in the window — the tail that makes a collector stick out on a target.", + note = "The tool's OWN cost on the monitored servers. sql_ms is query DURATION (includes waits), not pure CPU. max_sql_ms is the worst single execution in the window — the tail that makes a collector stick out on a target. " + + StoreProbeCaveat, collectors = top.Select(r => new { collector_name = r.CollectorName, diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpDataTools.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpDataTools.cs index 8e3814e63..8d8d797a7 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpDataTools.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpDataTools.cs @@ -1235,7 +1235,7 @@ private static string FreshnessStatus(DateTime? lastCollectionUtc, DateTime nowU .FromFreshness(ServerHealthClassifier.ClassifyFreshness(lastCollectionUtc, nowUtc)) .McpToken(); - [McpServerTool(Name = "get_collection_log"), Description("Gets the RAW per-run collection log for a server, newest first: one row per collector run with its total duration, the part spent querying the monitored server, the part spent writing to the store, rows collected, status and any error. get_collection_health rolls seven days of these into a per-collector verdict; this is the underlying runs, which is what you need when the rollup says healthy and collection still looks wrong, or when you want to see what a collector was doing during a specific incident window. Also carries the phase decomposition where the run recorded one, as nested blocks that are null when the run took a path that does not report them — and a row carries at most ONE family. Server-scoped collectors fill sql_phases (open_ms, drain_ms, other_ms which is derived, watermark_ms) and drain (rows_read, bytes_read, last_read_ms, target_session_id). Per-database collectors that perform a deferred plan or statement-text fetch instead fill plan_fetch and/or text_fetch, each carrying probe_ms, target_ms, write_ms, ids_attempted and probe_ids summed across that run's databases. sweep_peer_max_ms is flat and present on every row: it is the slowest peer collector in the same sweep, the denominator for asking whether a slow run was slow alone or the whole sweep was. A null block means the run took the other path, not that the phase was free — most runs perform no deferred fetch at all. Divide target_ms by ids_attempted for the per-id target cost, probe_ms by probe_ids for the per-reference probe cost.")] + [McpServerTool(Name = "get_collection_log"), Description("Gets the RAW per-run collection log for a server, newest first: one row per collector run with its total duration, the part spent querying the monitored server, the part spent writing to the store, rows collected, status and any error. get_collection_health rolls seven days of these into a per-collector verdict; this is the underlying runs, which is what you need when the rollup says healthy and collection still looks wrong, or when you want to see what a collector was doing during a specific incident window. Also carries the phase decomposition where the run recorded one, as nested blocks that are null when the run took a path that does not report them — and a row carries at most ONE family. Server-scoped collectors fill sql_phases (open_ms, drain_ms, other_ms which is derived, watermark_ms) and drain (rows_read, bytes_read, last_read_ms, target_session_id). Per-database collectors that perform a deferred plan or statement-text fetch instead fill plan_fetch and/or text_fetch, each carrying probe_ms, target_ms, write_ms, ids_attempted and probe_ids summed across that run's databases. sweep_peer_max_ms is flat and present on every row: it is the slowest peer collector in the same sweep, the denominator for asking whether a slow run was slow alone or the whole sweep was. A null block means the run took the other path, not that the phase was free — most runs perform no deferred fetch at all. Divide target_ms by ids_attempted for the per-id target cost, probe_ms by probe_ids for the per-reference probe cost. CRITICAL for reading sql_duration_ms on a fetching collector: it is NOT purely target-side there. The deferred fetches run inside the driver's per-item SQL stopwatch and each one round-trips the MONITORING STORE to decide what plan XML and statement text are already held before writing back what came off the target, so the store's probe and write are billed to the column documented as the monitored server's. The probe is the largest single term in both fetches on this fleet — 55.4% of plan_fetch and 80.6% of text_fetch — and on one production run it was 107,334 ms of a 124,972 ms sql_duration_ms, 86%, against a plan-plus-text target time of 6,494 ms. sql_store_ms is that store share, derived from the two fetch blocks (probe_ms + write_ms of each) and null when no fetch ran. It is a FLOOR, not the whole: the per-item watermark refresh is also a store read inside the same stopwatch, the enumerated path records no watermark_ms, and that component is stored nowhere — so sql_duration_ms minus sql_store_ms is an UPPER bound on target-side time rather than the target-side time. store_duration_ms is not where the probe went either: it is the binary COPY of the collected rows and nothing else. Do NOT conclude a monitored server is slow from a large sql_duration_ms on query_store without reading sql_store_ms beside it.")] public static async Task GetCollectionLog( NpgsqlDataSource postgres, [Description("Server name or display name.")] string? server_name = null, @@ -1303,9 +1303,34 @@ The split matters more than the total. A collector slow because the monitored server is slow needs work on that server; one slow because the store is slow needs work here. The total alone cannot tell those apart, and it is the question people actually ask of this log. + + #3192: and on the ENUMERATED path that split does not fall where these two columns + put it. sql_duration_ms is the driver's per-item stopwatch, which wraps the whole + readItem closure -- and for query_store that closure round-trips the STORE to decide + what plan XML and statement text are already held, then writes back what came off the + target. So the store's probe and write are billed to the target's column, and on this + fleet the probe is the largest single term in both fetches (55.4% of plan_fetch, 80.6% + of text_fetch; 107,334 of a 124,972 ms run). store_duration_ms is NOT where that time + went either -- it is the binary COPY of the collected rows and nothing else, which is + the measurement ServiceCommandDeadlines derives the COPY deadline from. + + So sql_store_ms names it instead, derived from the fetch blocks below rather than + stored (the SqlOtherMs / #2859 rule), which also makes it RETROACTIVE to every row + written since V110 instead of only to rows written after this change. Deliberately + NOT a correction applied to sql_duration_ms itself: that column feeds + collect.collector_cost, a 90-day hourly series that carries no phase split and is + written from an in-memory accumulator rather than re-aggregated from this table, so + the past could not be corrected to match and a re-based column would make the series + a step function across the deploy -- under a self-alert whose baseline window is 14 + days. The number stays; the attribution arrives beside it. */ sql_duration_ms = r.SqlDurationMs is null ? (double?)null : Math.Round(r.SqlDurationMs.Value, 0), store_duration_ms = r.StoreDurationMs is null ? (double?)null : Math.Round(r.StoreDurationMs.Value, 0), + /* Flat and nullable rather than inside a block, like sweep_peer_max_ms: it decomposes + sql_duration_ms (the sql_ prefix carries that, V108's convention) and belongs to neither + fetch half, being the sum of both halves' store terms. NULL means no deferred fetch ran, + so nothing is attributable -- never "the store share was zero". */ + sql_store_ms = r.SqlStoreMs is null ? (double?)null : Math.Round(r.SqlStoreMs.Value, 0), rows_collected = r.RowsCollected, status = r.Status, error_message = r.ErrorMessage, diff --git a/Darling/PerformanceMonitor.Darling.Service/wwwroot/js/pages/server-tabs.js b/Darling/PerformanceMonitor.Darling.Service/wwwroot/js/pages/server-tabs.js index d7653efde..068ccbf8a 100644 --- a/Darling/PerformanceMonitor.Darling.Service/wwwroot/js/pages/server-tabs.js +++ b/Darling/PerformanceMonitor.Darling.Service/wwwroot/js/pages/server-tabs.js @@ -2890,13 +2890,26 @@ const DEFAULT_TRACE_COLUMNS = [ /* #2484: the raw log's columns. The duration SPLIT is the reason this table earns its place beside the rollup -- total time cannot separate a collector that is slow because the monitored server is slow from - one that is slow because the store is, and that is the first question anyone asks of a slow collector. */ + one that is slow because the store is, and that is the first question anyone asks of a slow collector. + + #3192: this column was headed "On Server", and on the collectors that fetch plan XML or statement text + that header was false. The deferred fetches run inside the driver's per-item SQL stopwatch and each one + round-trips the STORE before writing back what came off the target, so a measured 107,334 ms of a + 124,972 ms query_store figure was the monitoring store -- 86% -- under a header naming the monitored + server. Headed "SQL" now, matching what the WPF viewer's grid has always called it - the HEADER only: that + grid has no "Store (in SQL)" breakout and cannot get one cheaply, because its row type and both backing + queries are verbatim copies of Lite's and Lite runs no deferred fetch. Its own comment says so. Here the + store share does get its own column beside the total. "Store (in SQL)" is blank on the ~98% of runs that perform no deferred + fetch, and blank there means "nothing to attribute", not "no store time": the per-item watermark refresh + is a store read inside the same stopwatch and is recorded nowhere, which is why that column is a floor + and "On Store" (the binary COPY of the collected rows) is not where the probe went either. */ const COLLECTION_LOG_COLUMNS = [ { key: "collection_time", label: "When", format: "time" }, { key: "collector", label: "Collector" }, { key: "status", label: "Status", statusSev: true }, { key: "duration_ms", label: "Total", format: "ms" }, - { key: "sql_duration_ms", label: "On Server", format: "ms" }, + { key: "sql_duration_ms", label: "SQL", format: "ms" }, + { key: "sql_store_ms", label: "Store (in SQL)", format: "ms" }, { key: "store_duration_ms", label: "On Store", format: "ms" }, { key: "rows_collected", label: "Rows", format: "int" }, { key: "error_message", label: "Error", wrap: true }, diff --git a/Darling/PerformanceMonitor.Darling.Viewer/CollectionLogWindow.xaml b/Darling/PerformanceMonitor.Darling.Viewer/CollectionLogWindow.xaml index ce9f04c3a..8a9f0ba24 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/CollectionLogWindow.xaml +++ b/Darling/PerformanceMonitor.Darling.Viewer/CollectionLogWindow.xaml @@ -83,6 +83,11 @@ + diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.xaml b/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.xaml index 6fa8b1406..816a95cb7 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.xaml +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.xaml @@ -3519,6 +3519,18 @@