From b844d23fd441adfc0c27cb4f590cc185eb9f3fc0 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Fri, 4 Sep 2026 22:23:32 -0400 Subject: [PATCH] Take the default trace's archival-empty cutoff from the server's clock ft.StartTime is the monitored server's local wall clock, so the host-UTC bound the archival-empty branch supplied delivered 17 hours at UTC-7 and 34 at UTC+10 instead of 24 - a silent hole in trace history on one side, and on the other the parquet double-count that branch exists to prevent. The branch now binds NULL and the query's COALESCE derives the floor from SYSDATETIME(), matching JobHistoryCollector's GETDATE()-relative fallback, whose run_datetime is server-local for the same reason. The watermark branch needs no correction: the watermark IS a stored event_time. --- .../CollectorTimestampFrameTests.cs | 37 +++++++++++++++++ ...aultTraceEventsCollectorDefinitionTests.cs | 27 +++++++++--- .../DefaultTraceEventsCollector.cs | 41 +++++++++++++++---- 3 files changed, 92 insertions(+), 13 deletions(-) diff --git a/Darling/Darling.Tests/CollectorTimestampFrameTests.cs b/Darling/Darling.Tests/CollectorTimestampFrameTests.cs index 0f2ad999fc..8e00bbd2bd 100644 --- a/Darling/Darling.Tests/CollectorTimestampFrameTests.cs +++ b/Darling/Darling.Tests/CollectorTimestampFrameTests.cs @@ -87,6 +87,43 @@ public void CpuUtilization_KeepsSampleTimeInTheServersLocalClock() + "self-calibrates to zero - a regression visible on one app only."); } + /// + /// default_trace_events.event_time is the monitored server's LOCAL wall clock — the .trc files + /// store local time and ft.StartTime is shipped verbatim — so every bound this collector compares + /// against it has to come from the server's clock too. + /// + /// Only the archival-empty fallback was ever at risk, and it is the branch nobody exercises: the + /// steady-state bound is the watermark, which IS a previously-stored event_time and therefore + /// already server-local, and the true-first-run bound is a 1900 sentinel that no clock can misread. The + /// third branch fires only when the hot store has been emptied by retention/archival on a server that HAS + /// collected before, which is why a host-UTC bound there survived review: it is correct on a UTC server, + /// and every store anyone develops against is UTC. + /// + /// Pinned against the SOURCE rather than a rendered query because the point is the absence of the + /// alternative: this collector must carry a LOCAL clock and no UTC clock at all, which is the exact + /// inverse of . Both facts are per-TABLE. There is + /// no store-wide rule to appeal to, and no name-keyed one either — system_health.event_time is UTC + /// under the same column name, which is why StoreSqlClockDisciplineTests cannot judge either. + /// + [Fact] + public void DefaultTraceEvents_DerivesEveryCutoffFromTheServersClock() + { + var sql = QueryTextOf("DefaultTraceEventsCollector.cs"); + + Assert.True( + s_localClock.IsMatch(sql), + "DefaultTraceEventsCollector's archival-empty fallback must derive its cutoff from SYSDATETIME(). " + + "ft.StartTime is the server's LOCAL wall clock, so a host-supplied UTC bound delivers the wrong " + + "window by the server's offset: 17 hours at UTC-7 (a hole in trace history nothing refills) and " + + "34 at UTC+10 (re-ingesting events already in parquet, which v_default_trace_events UNIONs " + + "without dedup — the double-count the bound exists to prevent). Both are silent."); + + Assert.False( + s_utcClock.IsMatch(sql), + "DefaultTraceEventsCollector's query contains a UTC clock function; every bound it compares " + + "against the server-local ft.StartTime must be in the server's clock (see above)."); + } + /// /// The collector's query constants, with COMMENT spans removed and string literals kept — the inverse /// of CSharpSourceWalker.StripCommentsAndStrings, because the SQL under test IS a verbatim diff --git a/Lite.Tests/DefaultTraceEventsCollectorDefinitionTests.cs b/Lite.Tests/DefaultTraceEventsCollectorDefinitionTests.cs index 9f1cca59fd..acce3db614 100644 --- a/Lite.Tests/DefaultTraceEventsCollectorDefinitionTests.cs +++ b/Lite.Tests/DefaultTraceEventsCollectorDefinitionTests.cs @@ -83,7 +83,9 @@ public void BuildQuery_ReadsDefaultTraceViaFnTraceGettable_ServerSide() Assert.Contains("ELSE t.max_files", text, StringComparison.Ordinal); Assert.Contains("t.is_default = 1", text, StringComparison.Ordinal); Assert.Contains("t.status = 1", text, StringComparison.Ordinal); - Assert.Contains("ft.StartTime > @cutoff_time", text, StringComparison.Ordinal); + Assert.Contains( + "ft.StartTime > COALESCE(@cutoff_time, DATEADD(HOUR, -24, SYSDATETIME()))", + text, StringComparison.Ordinal); Assert.Contains("SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED", text, StringComparison.Ordinal); Assert.Contains("OPTION(RECOMPILE)", text, StringComparison.Ordinal); } @@ -179,12 +181,27 @@ public void BuildQuery_Watermark_AndFirstRunGuard_TrueFirstRunVsArchivalEmpty() /* Archival-emptied hot store (no watermark, but HAS succeeded before): a BOUNDED recent window (24 h), NEVER all-history — so we don't re-scan .trc events already in the parquet archive, which - v_default_trace_events (hot UNION parquet, no dedup) would double-count. The Dashboard's guard. */ + v_default_trace_events (hot UNION parquet, no dedup) would double-count. The Dashboard's guard. + + The bound is NOT bound from the host: @cutoff_time is NULL on this branch and the query's COALESCE + derives it from SYSDATETIME(), because ft.StartTime is the monitored server's local wall clock. A + host-UTC bound here delivers 17 hours at UTC-7 and 34 at UTC+10 instead of 24 — a silent hole in + trace history on one side and the very parquet double-count this branch exists to prevent on the + other. Asserting NULL is what makes that non-negotiable: any host clock reintroduced here has to + put a value back in this parameter. */ var archivalEmpty = DefaultTraceEventsCollector.Instance.BuildQuery( MakeContext(collectionTime: collectionTime, hasCollectedBefore: true)); - var boundedCutoff = (DateTime)archivalEmpty.Parameters.Single(p => p.Name == "@cutoff_time").Value!; - Assert.Equal(collectionTime.AddHours(-24), boundedCutoff); - Assert.NotEqual(new DateTime(1900, 1, 1, 0, 0, 0, DateTimeKind.Utc), boundedCutoff); + var boundedCutoff = archivalEmpty.Parameters.Single(p => p.Name == "@cutoff_time"); + Assert.Null(boundedCutoff.Value); + Assert.Equal(CollectorParameterType.DateTime2, boundedCutoff.Type); + Assert.Contains( + "COALESCE(@cutoff_time, DATEADD(HOUR, -24, SYSDATETIME()))", + archivalEmpty.Text, StringComparison.Ordinal); + + /* And the other two branches still bind a value, so the COALESCE never reaches the server clock for + them: the watermark is already server-local, and the first-run sentinel is far-past. */ + Assert.NotNull(withWatermark.Parameters.Single(p => p.Name == "@cutoff_time").Value); + Assert.NotNull(firstRun.Parameters.Single(p => p.Name == "@cutoff_time").Value); } [Fact] diff --git a/PerformanceMonitor.Collectors/DefaultTraceEventsCollector.cs b/PerformanceMonitor.Collectors/DefaultTraceEventsCollector.cs index 6aed42bb37..91ee0a6f8d 100644 --- a/PerformanceMonitor.Collectors/DefaultTraceEventsCollector.cs +++ b/PerformanceMonitor.Collectors/DefaultTraceEventsCollector.cs @@ -95,9 +95,31 @@ private DefaultTraceEventsCollector() /// smaller than any retention horizon, so on an archival-emptied (necessarily quiet) server it re-reads /// only genuinely-recent events — which by definition are not yet archived — and never re-scans parquet. /// Ports the Dashboard's collection_log-SUCCESS guard (install/29_collect_default_trace.sql lines 116-117). + /// + /// Computed server-side against SYSDATETIME(), not from the host's collection time. + /// ft.StartTime is the monitored server's LOCAL wall clock (the .trc files store local time), so a + /// host-supplied UTC bound is a different clock and the window it delivers is skewed by the server's + /// offset: at UTC-7 a 24-hour request reads only the last 17 hours, leaving a 7-hour hole in trace + /// history that nothing later refills, and at UTC+10 it reads 34 hours, re-ingesting events already aged + /// into parquet — the exact double-count this bound exists to prevent. Both are silent. The watermark + /// branch needs no such correction: the watermark IS a previously-stored event_time, already in + /// the server's clock. Same reasoning and same fix as 's + /// GETDATE()-relative fallback, whose run_datetime is server-local for the same reason. /// private const int ArchivalEmptyFallbackHours = 24; + /// + /// The archival-empty floor, in the monitored server's own clock. Sits behind a COALESCE so the + /// watermark and true-first-run branches keep binding @cutoff_time verbatim and only the archival + /// branch — which binds NULL — reaches the server clock. Non-sargable by construction and free anyway: + /// fn_trace_gettable materializes every file it is handed, so no predicate on + /// ft.StartTime pushes down (see the remarks at the top of this class). + /// + private static readonly string CutoffExpression = string.Format( + CultureInfo.InvariantCulture, + "COALESCE(@cutoff_time, DATEADD(HOUR, -{0}, SYSDATETIME()))", + ArchivalEmptyFallbackHours); + /// /// The key holding the trace file path this collector read on /// its previous cycle for this server (#1962) — the sibling of the event_time watermark for a @@ -229,7 +251,7 @@ JOIN sys.trace_events AS te ON ft.EventClass = te.trace_event_id WHERE t.is_default = 1 AND t.status = 1 -AND ft.StartTime > @cutoff_time +AND ft.StartTime > {1} AND ISNULL(ft.DatabaseID, 0) NOT IN (1, 3, 4) /*master, model, msdb*/ AND ISNULL(ft.DatabaseID, 0) < 32761 /*exclude contained AG system databases*/{0} AND @@ -307,17 +329,20 @@ NULL DatabaseName are KEPT rather than silently dropped by a bare `NOT IN`. Spli var (exclusionClause, exclusionParameters) = BuildNullSafeDatabaseExclusion(context.ExcludedDatabases); var exclusionSplice = exclusionClause.Length == 0 ? string.Empty : "\r\n" + exclusionClause; - var text = string.Format(CultureInfo.InvariantCulture, QueryTemplateFormat, exclusionSplice); + var text = string.Format(CultureInfo.InvariantCulture, QueryTemplateFormat, exclusionSplice, CutoffExpression); /* Cutoff selection (the Dashboard's first-run guard, ported): - - watermark present -> steady state, collect newer than it. - - watermark null, never succeeded -> TRUE first run, collect ALL on-disk .trc history. - - watermark null, HAS succeeded -> hot store emptied by retention/archival, use a BOUNDED - recent window so we never re-scan .trc events already in - the parquet archive (which the v_ view would double-count). */ + - watermark present -> steady state, collect newer than it. Already the server's own + clock: the watermark IS a stored event_time (ft.StartTime). + - watermark null, never succeeded -> TRUE first run, collect ALL on-disk .trc history. A far-past + sentinel, so which clock reads it cannot matter. + - watermark null, HAS succeeded -> hot store emptied by retention/archival. NULL here, and the + query's COALESCE supplies the bound from SYSDATETIME() — see + ArchivalEmptyFallbackHours for why the host's UTC clock cannot + express this window against a server-local ft.StartTime. */ var cutoffTime = context.Watermark ?? (context.HasCollectedBefore - ? context.CollectionTime.AddHours(-ArchivalEmptyFallbackHours) + ? (DateTime?)null : FirstRunCutoff); /* The path this collector read last cycle, or null when it has none — a first run, a host that