diff --git a/docs/QueryStorePerformanceDiagnostics.md b/docs/QueryStorePerformanceDiagnostics.md new file mode 100644 index 0000000000..de95bbb247 --- /dev/null +++ b/docs/QueryStorePerformanceDiagnostics.md @@ -0,0 +1,395 @@ +# Query Store Performance Diagnostics - Baseline Specification + +## Status + +Agreed baseline for implementation. This document defines an opt-in background worker that emits Azure SQL Query Store diagnostics from inside the FHIR server, the enablement model, the emitted log records, the disclosure boundary, and the repository ownership split. + +This specification **supersedes an earlier pull-based design** in which three stored procedures were called by an external caller. See [Rejected alternative](#rejected-alternative-caller-invoked-stored-procedures). + +## Problem + +FHIR Azure SQL performance investigations currently require privileged, manual access to Query Store plans, runtime metrics, wait statistics, and statistics metadata. Support engineers need a bounded way to: + +- identify expensive or regressed query plans; +- obtain an SSMS-viewable Showplan for a slow plan; +- compare runtime and wait metrics; and +- inspect statistics freshness, sampling, and cardinality metadata. + +Azure SQL diagnostic settings can already export `QueryStoreRuntimeStatistics`, `QueryStoreWaitStatistics`, and `AutomaticTuning` to Log Analytics. What that stream does **not** carry is the Query Store **query text** and the **Showplan XML**, which are the two artifacts an investigation actually needs in order to reason about a regression. This feature closes that gap. + +Related internal guidance: + +- `Health.wiki/Home/Olympus-Team/DRI/TSGs/SQL-Latency-Issues.md` +- `Health.wiki/Home/Olympus-Team/Knowledge-Base/Datastore/SQL-DB/SQL-Query-Store---help-with-analyzing-queries.md` +- `Health.wiki/Home/Olympus-Team/DRI/TSGs/SQL-Latency-Issues/SQL-Statistics-Overview.md` +- `Health.wiki/Home/Olympus-Team/Development/SQL-Performance-Automation.md` + +## Design + +A **watchdog** — the repository's existing leased background-worker pattern — periodically reads Query Store and statistics metadata and writes the results out as **structured log records**. It runs inside the FHIR server process on the server's **existing** SQL identity. + +```text +FHIR server instance (lease holder) + └── QueryStoreDiagnosticsWatchdog every PeriodSec, default 3600s + ├── sys.database_query_store_options state gate, always primary + ├── sys.query_store_* slow plans + query text + ├── sys.query_store_wait_stats best effort + ├── sys.stats / sys.dm_db_stats_properties + └── QueryPlanSanitizer (C#) strips parameter values + │ + └── ILogger structured log records + └── the host's existing log pipeline (PaaS -> Geneva / Log Analytics) +``` + +The critical property is that **nothing new connects inbound to the database**. The work is done by the service that already holds a connection, so the feature introduces no new authentication path, no new database principal, and no new grant. + +### Why a watchdog + +`WatchdogsBackgroundService` and `WatchdogLease` already provide what this feature needs, and each of these would otherwise have to be reinvented: + +- **Single-runner election.** `WatchdogLease` ensures exactly one instance in a multi-instance deployment performs the work, so an eight-instance service does not issue eight concurrent Query Store scans and emit eight copies of every diagnostics line. The lease is invisible runtime coordination rather than configuration: it holds nothing an operator sets, and it lives in `dbo.WatchdogLeases` behind `dbo.AcquireWatchdogLease`, shared with every other watchdog. +- **A managed background timer.** `FhirTimer` supplies the randomized start-up stagger that keeps replicas from collecting on the same second, and catches whatever a tick throws so that a failed collection costs one tick rather than the process. +- **A precedent for emitting SQL telemetry.** `GeoReplicationLagWatchdog` reads a SQL view on a timer and emits what it finds. This feature has the same shape, but emits **logs rather than metric notifications**; see [Why logs rather than metrics](#why-logs-rather-than-metrics). A single lag figure is metric-shaped, and query text and plan XML are not. + +**It derives from `Watchdog` like every other watchdog, and keeps configuration authoritative through the one hook the base class provides.** The base class inserts `{Name}.PeriodSec` and `{Name}.LeasePeriodSec` into `dbo.Parameters` on every start and then reads both back **over** the configured values, from a private, non-virtual initialization step. That read-back is not harmless: `dbo.Parameters` is declared `PRIMARY KEY CLUSTERED (Id) WITH (IGNORE_DUP_KEY = ON)`, so on a database that already holds those rows the seeding `INSERT` is a silent no-op — it neither inserts nor errors — and the stored value therefore wins over the environment variable. Verified directly against SQL Server: inserting `3600` and then `60` for the same `Id` reports *"Duplicate key was ignored. (0 rows affected)"* and leaves `3600` in place. + +The base class does expose one overridable step, `InitAdditionalParamsAsync`, which runs after that read-back and before the timer is constructed. This watchdog overrides it to `UPDATE` both rows to the configured values and re-assign the two properties, so configuration wins on every database and the rows stay an accurate mirror of the deployment's settings rather than a stale copy that silently contradicts them. An `UPDATE` is used rather than an `INSERT` precisely because `IGNORE_DUP_KEY` would make a re-`INSERT` a no-op. Deriving from the base class means the lease-holder gate, the capped randomized stagger, and the per-tick timing line come from shared code rather than being reproduced here, and no shared file is modified for this feature. + +### Enablement + +The feature is **off by default** and is gated by one switch, in configuration. + +| Gate | Location | Purpose | +| --- | --- | --- | +| `FhirServer:Watchdog:QueryStoreDiagnostics:Enabled` | Host configuration | When false the watchdog is never started by `WatchdogsBackgroundService`, and no Query Store read occurs. | + +**Every setting for this feature is set in configuration, and configuration always wins.** There is no row to seed or arm before the feature will run: no `IsEnabled` row, and nothing an operator has to write by hand. Turning the feature on, tuning it, and turning it off are configuration changes plus a restart, with no `UPDATE` against a live database required of anyone. + +The base class does keep `{Name}.PeriodSec` and `{Name}.LeasePeriodSec` in `dbo.Parameters`, and this watchdog reconciles both rows to the configured values during initialization, so a database can never hold a value that disagrees with the deployment's configuration. The rows are a readable mirror of what the service is running with, not an input to it — editing one changes nothing, because the next start overwrites it. + +The watchdog also re-reads `Enabled` at the start of every tick and returns without collecting when it is false. That check cannot be reached with the value false as the host is wired today: `WatchdogsBackgroundService` gates startup on the same configuration snapshot, and `IOptions` does not reload in place. It is kept because the watchdog is registered `AsSelf` and this is the only place the opt-out is enforced at the unit of work, so a future call site that executes a collection directly cannot bypass it. The cost is one boolean read per period. + +This feature causes three database rows to exist. Two are its `dbo.Parameters` rows, described above, which mirror configuration rather than drive it. The third is its **lease**, in `dbo.WatchdogLeases` through `dbo.AcquireWatchdogLease`. The lease is what stops every replica collecting and emitting the same diagnostics every period; it holds no configuration and is the same mechanism every other watchdog uses. That shared stored procedure does consult `dbo.Parameters` for the fleet-wide watchdog lease-holder include and exclude patterns, which is noted under [Configuration](#configuration): it is shared framework behaviour that this feature neither sets nor reads for itself. + +### Configuration + +`WatchdogConfiguration.QueryStoreDiagnostics`, bound from `FhirServer:Watchdog:QueryStoreDiagnostics`. Note that `Watchdog` is a sibling of `Operations` under `FhirServer`, not nested inside it: + +| Setting | Default | Meaning | +| --- | --- | --- | +| `Enabled` | `false` | The gate described above. | +| `PeriodSec` | `3600` | Interval between collections, and — clamped to `[60, 86400]` seconds — the Query Store lookback window each collection covers. A non-positive or non-finite value is rejected with a warning and the `3600` default is used, because `PeriodicTimer` would otherwise throw and fault every watchdog in the process. | +| `LeasePeriodSec` | `600` | How long the single-runner lease is held before it must be renewed. Long enough that a collection cannot outlive it, short enough that a dead replica's lease is picked up promptly. A non-positive or non-finite value is rejected with a warning and the `600` default is used. Most deployments should leave this alone; it is on the configuration surface because the base class stores it in `dbo.Parameters`, and every stored value must be settable from configuration. | +| `SlowQueryCount` | `10` | Number of slow plans to report per tick. | +| `MinDurationMilliseconds` | `1000` | Minimum weighted average duration for a plan to be reported. A negative value is treated as `0` — which makes every query qualify — and warns. | +| `IncludeQueryPlans` | `true` | Whether sanitized Showplan XML is emitted. | +| `IncludeStatisticsHealth` | `true` | Whether statistics metadata is emitted. | +| `StatisticsHealthCount` | `20` | Worst-ranked statistics rows **collected and reported** per tick; see [Why the count is capped](#why-the-count-is-capped). | +| `StatisticsHealthBatchSize` | `20` | How many of those rows are packed into each log line. This is **not** a second cap on what is collected: rows beyond the batch size are emitted on further lines, paginated. A non-positive value is reported with a warning and the `20` default is used, because a batch size cannot pack a row. Values above `64` are clamped, also with a warning; see [Batch size is capped](#batch-size-is-capped). | +| `RunStartDate` | `null` (unset) | Inclusive start of the optional run window. Ticks before it collect nothing. `null` means no lower bound. | +| `RunEndDate` | `null` (unset) | **Exclusive** end of the optional run window. Ticks at or after it collect nothing. `null` means no upper bound. | + +The lookback window is `PeriodSec` clamped to `[60, 86400]` seconds, so the collection window tracks the collection interval and a misconfigured value cannot request an unbounded scan. + +The watchdog warns on every tick where the clamp changed the value, naming the effective window and what the clamp costs, and pointing at `FhirServer:Watchdog:QueryStoreDiagnostics:PeriodSec` as the thing to change. The tick interval itself is **not** clamped, so whenever the clamp bites the interval and the window it covers are permanently decoupled: a period above the cap leaves the excess of every interval unexamined, and one below the floor makes consecutive collections overlap and re-report the same plans. + +**Every setting takes effect on restart, on every database.** All binding is through `IOptions` rather than `IOptionsMonitor`, so nothing reloads in place: editing configuration on a running host changes nothing until it restarts. `PeriodSec` and `LeasePeriodSec` are read once, at construction, because they are handed to the timer and the lease for the life of the process; the rest are read from configuration on each tick, which makes no observable difference while the values cannot change underneath. `PeriodSec` and `LeasePeriodSec` are stored in `dbo.Parameters` but never taken from it — initialization overwrites both rows with the configured values — so a deployment behaves identically against a database it created a minute ago and one it has been running against for a year. There is no first-run state for its settings to diverge from. + +One piece of pre-existing database state can still suppress collection, and it belongs to the shared lease rather than to this feature: `dbo.AcquireWatchdogLease` honours `WatchdogLeaseHolderIncludePattern` and `WatchdogLeaseHolderExcludePattern` rows in `dbo.Parameters`, plus the per-watchdog `...For` variants — where the name is `QueryStoreDiagnosticsWatchdog`. A worker excluded by such a row never becomes lease holder, so its ticks skip and nothing is collected. That applies identically to every watchdog in the process and is not something this feature sets, seeds, or reads itself, but it is the one thing to check on a long-lived database when the feature is enabled and silent. + +### Run window + +`RunStartDate` and `RunEndDate` bound the period during which collection happens. Both are `DateTimeOffset?` and both default to `null`; the feature behaves exactly as before when neither is set. A tick collects when: + +``` +(RunStartDate == null || now >= RunStartDate) && (RunEndDate == null || now < RunEndDate) +``` + +- **`RunStartDate` is inclusive, `RunEndDate` is exclusive.** The instant that equals the end is already outside the window, so adjacent windows tile without overlapping. +- **`null` means unbounded**, not "now": an unset start collects from the first tick, an unset end collects indefinitely. +- **A start that is not before the end is an empty window** — including a start exactly equal to the end — and nothing will ever be collected. That configuration is logged as a warning once at startup naming both values, because nothing downstream will ever complain about it. + +The window is evaluated inside the tick, after the configuration gate and after the lease-holder check, so a host that is outside its window still holds the lease and keeps ticking — it simply collects nothing and says so once, when the state changes. + +**Set the offset explicitly.** A value without one — `2026-03-01T00:00:00` — is bound in the **host's local timezone**, which is invisible in the configured text and is rarely what was intended. Use ISO-8601 with a `Z` suffix, `2026-03-01T00:00:00Z`. As an environment variable: + +``` +FhirServer__Watchdog__QueryStoreDiagnostics__RunStartDate=2026-03-01T00:00:00Z +FhirServer__Watchdog__QueryStoreDiagnostics__RunEndDate=2026-03-08T00:00:00Z +``` + +Whenever either bound is set, the watchdog logs the effective window **converted to UTC** once at startup — before the first tick, and not repeated per tick — so an operator who typed a local time without an offset sees the resolved instant immediately rather than waiting for a window that silently opens hours late — or, for a short window, never visibly opens at all. + +A **malformed** value is not silently ignored and does not silently disable the window: configuration binding throws `InvalidOperationException` naming the offending key. This matches every other typed setting in this section — `PeriodSec`, `SlowQueryCount` and `Enabled` all reject an unparseable value the same way — so a date bound introduces no failure mode the existing settings do not already have. An empty value binds as `null`, which is how a bound is removed rather than mistyped. + +**The watchdog keeps ticking after `RunEndDate`; it does not shut itself down.** Outside the window it evaluates one clock comparison and returns. Self-termination is not an option available to it: completing or faulting a watchdog task makes `WatchdogsBackgroundService` cancel the token that **every** watchdog shares, so an off-by-default diagnostics feature ending its own timer would take the transaction and cleanup watchdogs with it. An hourly comparison costs nothing by contrast. + +The window state is logged **only when it changes** — not open yet, open, closed — at information level. At the default hourly period a window that opens in a month would otherwise produce roughly 720 identical skip lines before collecting anything. The state a process starts in is always logged once, so the reason for silence is available immediately after a restart. + +**The window boundaries take effect without a restart, but the configured values do not.** These settings bind through `IOptions`, so the *values* are read once at process start and editing configuration afterwards has no effect until the host restarts — the same as every other setting in this feature. What changes without a restart is the *clock*: a window configured before the host started will open and close on schedule while the process keeps running, because each tick re-evaluates the fixed boundaries against the current time. Changing a boundary on a running host still requires a restart. + +## Emitted log records + +Everything this feature produces is a **structured log record**, written through the `ILogger` the host already configures. Nothing is emitted as a metric event, and there is no handler to bind: whatever a deployment already does with FHIR server logs, it does with these. + +All three payload lines are emitted at **information** level. The warnings this feature raises — misconfiguration, an unavailable Query Store, a failed wait read, a plan that would not sanitize — remain at **warning** level and are unaffected by how the payload is emitted. + +The payload shapes are `SlowQueryDiagnostics`, `QueryPlanDiagnostics`, and `StatisticsHealthDiagnostics`, in `Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/Models`. They are `internal` and live beside the watchdog because they are log payload shapes, not contracts another assembly binds to. + +### Why logs rather than metrics + +- **Cost and blast radius.** Metric events are charged on receipt. `docs/arch/adr-2605-metric-emission-rate-limiting.md` records a high-volume emission pattern throttling a *shared* metric account and degrading monitoring for both the FHIR and DICOM services, so volume on that pipeline is an availability concern as well as a bill. Logs are the cheap place to start, and moving a data point to a metric later is easy in a way that recovering a throttled account is not. +- **The payload is not metric-shaped.** `QueryText` is unbounded free text, `SanitizedQueryPlan` is an XML document, and `TopWaitCategory` is a high-cardinality string. Those are log fields. Carrying them as metric dimensions is a cardinality incident waiting to happen. +- **Nothing here is a rate.** These are periodic snapshots meant to be read and correlated by a responder during an investigation, not aggregated into a time series. + +### Slow query + +One line per slow plan per tick, beginning `QueryStoreDiagnosticsWatchdog slow query.`. + +Every field is its own **named** log property, so each lands as its own queryable column in Kusto or Log Analytics rather than inside a serialized blob: `QueryId`, `PlanId`, `ExecutionCount`, `TotalDurationMilliseconds`, `AverageDurationMilliseconds`, `MaxDurationMilliseconds`, `TotalCpuMilliseconds`, `AverageCpuMilliseconds`, `TotalLogicalReads`, `AverageLogicalReads`, `TotalWaitMilliseconds`, `AverageWaitMilliseconds`, `TopWaitCategory`, `WaitStatisticsStatus`, `QueryTextTruncated`, `QueryTextLength`, `IntervalStart`, `IntervalEnd`, `DiagnosticsTimestamp`, and `QueryText`. + +These lines are **not** batched. At the default `SlowQueryCount` of 10 a line per row is cheap, and column-level queryability is the whole reason to emit structured logs rather than JSON documents. `QueryText` is placed last so that everything an operator scans for is readable ahead of the one unbounded field on the line. + +`WaitStatisticsStatus` describes why the wait fields look the way they do: `Available` when wait statistics were read for the plan, `Unavailable` when the wait query succeeded but returned no row for it (wait capture off, or no waits accrued), and `Failed` when the wait query itself threw. Without it, "wait capture is switched off" and "the wait query has been failing for a month" are indistinguishable, because both leave the wait fields null. + +`QueryId` and `PlanId` are the join keys back into Query Store, and into the `QueryStoreRuntimeStatistics` stream already exported to Log Analytics, so a responder can correlate an emitted slow query with the existing diagnostic-settings telemetry. + +### Query plan + +One line per reported plan per tick when `IncludeQueryPlans` is set, beginning `QueryStoreDiagnosticsWatchdog query plan.`. Named properties: `QueryId`, `PlanId`, `SanitizationStatus`, `QueryPlanTruncated`, `OriginalQueryPlanLength`, `SanitizedQueryPlanLength`, `DiagnosticsTimestamp`, and `SanitizedQueryPlan`. + +These lines are **not** batched either, and for a different reason from the slow-query lines: the sanitized XML is capped at the field length rather than being small, so packing several plans into one record would risk producing a single oversized log record that the pipeline drops or truncates as a whole. + +A line is emitted for unsuccessful sanitization as well, with null XML and a status of `PlanXmlUnavailable`, `InvalidXml`, or `VerificationFailed`, so a sanitization failure is observable rather than silent. That failure is *also* logged as its own warning, so systematic sanitizer breakage does not look like "plans are simply unavailable" to someone who is not reading `SanitizationStatus`. + +### Statistics health + +Emitted in **batches**, beginning `QueryStoreDiagnosticsWatchdog statistics health.`. Each line carries `StatisticsHealthBatchSize` rows serialized as a compact JSON array in a single log property, `StatisticsHealthRows`, alongside the pagination properties described below. + +These rows are batched where the other two payloads are not because they are small, uniform, and contain no free text, so a batch of them has a predictable size. The cost of batching is that the rows arrive as a serialized blob rather than as queryable columns, which is affordable precisely because the fields are few, uniform, and cheap to re-parse; it would not be affordable for query text or plan XML. + +Each row carries schema, table, and statistics name, last-updated timestamp, rows, rows sampled, modification counter, modification percentage, the auto-created / user-created / from-index / filtered flags, and the collection timestamp. The timestamp is on the row rather than only on the line so that a row stays self-describing once it is lifted out of the batch it arrived in. + +When more rows are collected than fit in one batch, several lines are emitted and each one says where it sits in the set: + +| Property | Meaning | +| --- | --- | +| `StatisticsHealthPage` | The **1-based** page number of this line. | +| `StatisticsHealthPageCount` | How many lines the collection was emitted across. | +| `StatisticsHealthPageRowCount` | How many rows this line carries. | +| `StatisticsHealthRowCount` | How many rows were collected in total, across every page. | +| `StatisticsHealthRows` | The rows themselves, as a compact JSON array. | + +Carrying the totals on **every** line is what lets a reader distinguish a legitimately short final page from a set that was cut short by a host that died mid-collection: 18 rows on page 3 of 3 of a 58-row collection is complete, while pages 1 and 2 of 3 arriving alone is not. No line is emitted when nothing was collected — the per-tick summary already reports a count of zero, and an empty page would only make the pages harder to count. + +`DiagnosticsTimestamp` on the slow-query and query-plan lines, and `Timestamp` inside each statistics row, are the moment the watchdog collected the data. They are deliberately not named `Timestamp` at the log-property level, because that name collides with the ingestion timestamp log pipelines supply for every record. + +### Field size + +Query text and sanitized plan XML are capped at **32 KB** per field, matching the field limit of the downstream telemetry pipeline. Values exceeding the cap are truncated and flagged (`QueryTextTruncated`, `QueryPlanTruncated`). + +The pre-truncation length is reported alongside each flag so the loss is quantifiable rather than merely visible: `QueryTextLength` for query text, and `SanitizedQueryPlanLength` for plan XML. Plans additionally report `OriginalQueryPlanLength`, the raw length as read from Query Store — the two plan lengths differ by whatever sanitization removed, so reporting only the raw length would overstate how much truncation itself discarded. + +Truncation is applied **after** sanitization and verification, never before, so a truncated plan can never be a partially sanitized one. + +## Behaviour + +### Query Store state + +The watchdog reads `sys.database_query_store_options` and proceeds only when `actual_state_desc` is `READ_WRITE`. A row reporting any other state is logged as a warning naming that state together with the decoded `readonly_reason`, and the tick is skipped. When the view returns no row at all there is no state and no reason to report, so that case is logged as its own warning saying that Query Store is not configured on the database, and the tick is skipped. + +**The watchdog never issues `ALTER DATABASE`.** Turning Query Store on is a database-scoped configuration change with its own permission and blast-radius considerations, and it is on by default in Azure SQL Database. Enabling it stays an explicit operator action. + +### Slow-query aggregation + +Runtime statistics are aggregated across every Query Store interval overlapping the lookback window, restricted to `execution_type = 0` so that only regular completed executions contribute. Averages are weighted by `count_executions` before being combined across intervals, because Query Store stores per-interval averages and an unweighted mean across intervals of unequal execution counts is wrong. + +Query Store records durations and CPU in **microseconds**; the emitted contract is in milliseconds. + +Results are ordered by total duration descending and limited to `SlowQueryCount`, so the reported set is the aggregate-cost hot list rather than the worst single execution. + +### Self-exclusion + +The watchdog's own Query Store reads are excluded by filtering out query text referencing the Query Store catalog views. An earlier iteration attempted to tag the queries with a marker comment; SQL Server does **not** preserve those comments in `query_sql_text`, so text matching on the view names is the pragmatic mechanism. + +### Wait statistics + +Wait statistics are collected by a **separate, best-effort** query and merged in C#. A caught `SqlException` — the wait view being unavailable, a timeout, a deadlock, or a permission denial — is logged as a warning, leaves the wait fields null, and sets `WaitStatisticsStatus` to `Failed`. Runtime results are still emitted. + +`Failed` is reserved for that case: a wait read that actually broke. The ordinary outcomes of wait capture being turned off, or of no waits having accrued for a plan inside the window, are an empty result set rather than a failure — those plans carry `WaitStatisticsStatus` of `Unavailable`, with null wait fields and no warning logged. + +`SqlException` is caught broadly there on purpose, so that a transient wait-query failure cannot abort the tick and suppress the runtime statistics. The trade-off accepted is that timeouts, deadlocks, permission denials and missing views are not distinguished from one another at that point; the warning carries the exception, and the slow-query line carries the status. + +Wait capture is retained locally, rather than deferred entirely to the `QueryStoreWaitStatistics` Log Analytics stream, so that a single emitted slow-query line is self-contained: runtime statistics, waits, query text, and plan identity arrive together without a join against a second telemetry source. + +### Statistics health + +Statistics are read from `sys.stats` with an `OUTER APPLY` to `sys.dm_db_stats_properties`, so a statistics object remains visible even when its properties cannot be read. The scan is restricted to user tables and excludes temporal history tables. Rows are ordered by staleness — modification counter over row count — and limited to `StatisticsHealthCount`. + +Modification percentage is left null when the row count is null or zero rather than being reported as zero, so "no data" is distinguishable from "not stale". Percentages above 100 are preserved; they are a legitimate signal that a table has churned more than its cardinality. + +#### Why the count is capped + +`StatisticsHealthCount` is a cap on what is *reported*, not on what is examined: the ordering runs across every qualifying statistic and only the worst are emitted. It is also the only cap on the number of rows. `StatisticsHealthBatchSize` decides how many rows share a log line, not how many rows exist, so raising it never reports more and lowering it never reports less — the two settings are easy to confuse and do quite different things. + +The reason to cap is weaker than it was when each row was emitted as its own metric event, and it is worth being precise about what changed. Rows are now packed into batched log lines, so a row no longer costs a charged metric event and the per-row emission argument that `docs/arch/adr-2605-metric-emission-rate-limiting.md` supports no longer applies here in that form. What batching removes is **record count**, not bytes: 300 rows at a batch size of 20 is 15 log records instead of 300, but it is still 300 rows of ingested and retained data. + +That residual volume is what the cap is for now. The schema alone defines roughly a hundred index-backed statistics across its user tables, and SQL Server adds auto-created column statistics on top of that as queries run, so the full set on a busy database is comfortably several hundred — every collection, on every database, on every host that holds the lease, for as long as the feature is enabled. Log ingestion and retention are charged by volume, and a fleet multiplies the figure by database count, so reporting everything every hour is a real ongoing cost even though it is a much smaller one than it would have been on the metrics pipeline. The second cost is readability: several hundred rows an hour of mostly healthy statistics is a stream nobody reads, which defeats the purpose of collecting them. + +Capping is therefore still the right shape, and the ordering is what makes a small cap usable — the reported rows are the worst offenders rather than an arbitrary slice. Statistics with no readable row count sort last, so empty and unsampled tables do not consume the budget. + +One bias is worth knowing when reading the output. Ranking is by *ratio*, so a small table that churns heavily outranks a large one that has drifted less proportionally: ten rows with a hundred modifications scores 10.0, while a hundred-million-row table with twenty million modifications scores 0.2, even though the second is far more likely to distort a plan. A handful of small, busy tables can therefore fill the report while a consequential stale statistic on a large table sits below the cut. Raising `StatisticsHealthCount` widens the window, at the volume cost described above; on logs that is a defensible thing to do for the length of an investigation, which it was not when every extra row was a metric event. If large-table staleness is what is being chased, the ordering — not the cap — is the thing to revisit. + +#### Batch size is capped + +`StatisticsHealthBatchSize` is clamped to 64 rows per line, with a warning naming the configured value when the clamp bites. + +The reason is the same one that keeps plan XML out of a batch. Batching trades record count for record size, and a large enough batch recreates exactly the oversized record that batching plans was rejected for: a single line that a sink may truncate or reject, taking every row on it with it. A typical serialized statistics row is a little under 400 bytes, so 64 rows keeps a full page well inside the 32 KB budget the feature already applies to its other large fields. + +Clamping never drops rows. A batch size above the cap simply produces more pages, and the pagination properties still account for every row. Extra lines are the cheap thing here, which is the whole reason for preferring logs in the first place. + +### Failure containment + +`WatchdogsBackgroundService` cancels **every** watchdog if any one of them fails. A diagnostic feature must never be able to take down transaction or cleanup watchdogs, so the collection body contains its own failures: missing views and permission denials are logged and the tick returns rather than propagating. + +The missing-view handler spans the whole collection rather than each individual read, so the aborting read can be the last one, after slow queries and plans have already been emitted. Its warning is worded to hold in that case too: it reports that collection was aborted and that whatever had already been emitted was still logged, rather than claiming that nothing was collected. + +That containment covers **per-tick collection**, which is where all of this feature's own collection work happens: `FhirTimer` catches whatever a tick throws and keeps ticking, so a failed collection costs one tick. The lease renewal runs on the lease's own `FhirTimer` with the same per-tick catch. + +Deriving from `Watchdog` does add one step outside those catches: `ExecuteAsync` awaits `InitParamsAsync`, which seeds `dbo.Parameters` and then calls this feature's `InitAdditionalParamsAsync`, *before* and *outside* the per-tick catch — so a throw there faults the watchdog task and `WatchdogsBackgroundService` cancels the rest. That exposure is shared with every other watchdog, but this feature narrows its own contribution to it: the reconciling `UPDATE` is wrapped in a catch that logs a warning and continues, and the assignments that make configuration authoritative run outside that try. A diagnostics feature is not permitted to fail the transaction and cleanup watchdogs over a row it writes only so the table reads truthfully, and collection is unaffected when the update fails. + +What remains outside the catch is the period itself: `PeriodicTimer` throws on a non-positive or non-finite interval, and that throw would happen before the first tick. This is why the configured `PeriodSec` is validated at construction and replaced with the default rather than passed through, and why the run-window check skips a tick rather than ending the timer. + +### Reading the primary + +Every diagnostics read binds to the **primary**, not to a read-only replica, even though these are all read-only queries. + +Query Store state is primary-scoped: on a secondary the database is read-only, so `sys.database_query_store_options.actual_state_desc` reports `READ_ONLY`, the `READ_WRITE` state gate rejects it, and the tick returns having emitted nothing — silently, forever, with the feature enabled and no exception raised. Replica routing is also decided per call against a process-global counter, so a single tick could otherwise check state on the primary and read data from a secondary, harvesting plan identifiers on one server and looking them up on another. + +The cost is one collection per period against the primary — hourly by default — which is negligible next to the failure mode it removes. + +### Configuration that disables collection + +A non-positive `SlowQueryCount` or `StatisticsHealthCount` disables the corresponding section: the round-trip is skipped entirely rather than issued as a `TOP (0)` query whose empty result would be indistinguishable from a healthy one. Both cases are logged as a warning once per tick, and a section turned off deliberately through `IncludeQueryPlans` or `IncludeStatisticsHealth` is logged at information level. Misconfiguration is never fatal: a diagnostics feature must not fail the host. + +A completed tick logs one information-level line carrying the collection window and the counts of slow queries, plans and statistics rows emitted, **including zeros**, so that "the watchdog has been dead for three days" is distinguishable from "there were no slow queries". The plan count is the number of plans that actually carried sanitized XML, not the number of plan lines emitted, so it is deliberately lower than the slow-query count whenever Query Store held no plan for a query or sanitization rejected one. The statistics count is the number of **rows** collected, not the number of batch lines they were emitted across. + +## Sanitization + +Showplan sanitization is performed **in C#** by `QueryPlanSanitizer`, not in T-SQL. The previous design did this with 236 lines of XML DML inside a stored procedure; the C# implementation is materially more reliable and easier to test with a fixture corpus. + +The sanitizer: + +1. parses with an `XmlReader` configured with `DtdProcessing.Prohibit` and a null resolver, so a hostile or malformed plan cannot trigger entity resolution; +2. removes every `ParameterList` element and every `ParameterCompiledValue` and `ParameterRuntimeValue` attribute, matching on local name so that Showplan namespace differences between SQL versions cannot cause a miss; +3. re-serializes without formatting; +4. **verifies** structurally — by re-walking the parsed tree after removal and checking element and attribute local names, not by scanning the serialized text — that none of those three names survive, and returns `VerificationFailed` with null XML if any do; and +5. only then truncates to the field cap. + +Step 4 is defence in depth: the plan is never emitted on the strength of the removal logic alone. It is structural because Showplan embeds the original SQL in `StatementText`, so a text scan would drop — silently and permanently — any plan whose own query text happens to contain the literal string `ParameterList`. + +`QueryPlanSanitizationResult` is constructed only through static factories. The factories do not re-verify the document — the success factory trusts its caller for that — but they do constrain the result's shape: every failure factory forces the XML to null, so no failure status can be paired with a payload; the success factory refuses a null document; and the truncation flag is derived from the payload rather than supplied alongside it. + +### Disclosure boundary + +Query text, statement text, scalar expressions, non-parameter constants, object names, missing-index recommendations, warnings, memory grants, and optimizer statistics usage are permitted diagnostic output. + +This intentionally accepts that ad hoc or non-parameterized query text and plan constants may contain literal values. The protected content is parameter-value metadata in Showplan `ParameterList` elements, including compiled and runtime values. + +Statistics histogram values are never read, because `range_high_key` contains actual indexed-column values. + +## Security model + +The watchdog runs on the FHIR server's existing SQL connection and requires no additional database principal, role, or grant. Reading the Query Store catalog views requires `VIEW DATABASE STATE`, which the service identity already holds; where it does not, the permission denial is contained and logged rather than being fatal. + +Because this is an outbound emission from a process that is already trusted with the data, the previous design's audit requirements do not apply. There is no external caller to attribute, and the emitted log records are themselves the operational record. + +## Repository ownership + +### OSS `fhir-server` + +- the watchdog, its inline SQL, and the C# sanitizer; +- the configuration class and its defaults; +- the three log payload shapes and the structured lines they are emitted on; +- unit tests for sanitization and integration tests against a live SQL Server; and +- this specification. + +Nothing here is PaaS-specific, and no PaaS identity, storage account, or rollout mechanism is embedded in it. A self-hosted deployment can enable the feature and bind its own handler. + +### `fhir-paas` + +- routing the FHIR server log stream to Geneva or Log Analytics, and any parsing of the emitted lines built on top of it; +- setting the configuration gate per environment and ring; +- setting the collection settings, including the run window, for an investigation; +- retention, access control, and downstream handling of emitted query text and plans; and +- any responder-facing tooling built on top of the emitted stream. + +### Rollout + +1. Merge the OSS change. The feature ships disabled. +2. Confirm the FHIR server log stream is routed where the investigation needs it. There is no handler to bind. +3. Enable the configuration gate in a test ring and confirm emission volume and field sizes. +4. Enable it for the deployment under investigation through configuration — bounding it with `RunStartDate` and `RunEndDate` when the investigation is time-boxed — and restart that deployment for the change to take effect. + +Because there is **no schema change**, there is no migration ordering dependency and no package/schema-version synchronization step. This is the single largest operational simplification relative to the rejected design. Nothing has to be written to a database to turn the feature on, so there is also no per-database state to seed, clean up, or reconcile against configuration. + +## Simplifications and deferred work + +Recorded deliberately; each is a candidate for a follow-up. + +- **No schema version bump.** The SQL is inline in the watchdog rather than in versioned stored procedures. This removes a schema version, a 944-line migration diff, a database role, migration-sync risk, and the unresolved `dbo.LogEvent` audit-registration question. The cost is that the SQL is not independently hotfixable through a schema migration, and is reviewed as C# rather than as `.sql`. The SQL is kept in clearly formatted, commented `const` blocks to preserve readability. +- **Plans are re-emitted every tick.** There is no cross-tick deduplication by `plan_id`, so a persistently slow plan is emitted repeatedly. Accepted for v1; the duplication is bounded by `SlowQueryCount` and the tick interval, and suppression can be added once real emission volume is known. +- **Slow-query selection is total-duration only.** There is no configuration for selecting by CPU, reads, waits, or regression against a baseline. `MinDurationMilliseconds` and `SlowQueryCount` are the only tuning knobs. Richer selection is the expected first enhancement. +- **Truncation is a hard cut.** A plan exceeding 32 KB is truncated to invalid XML and flagged. It is not chunked, compressed, or externalized to blob storage. Compression would likely bring most large plans under the cap and is the obvious next step if truncation proves common. +- **No actual execution plans.** `sys.query_store_plan.query_plan` is the compile-time Showplan, equivalent to `SET SHOWPLAN_XML ON`. Actual-plan capture via `LAST_QUERY_PLAN_STATS` remains future work. +- **Plan-type and Parameter Sensitive Plan variant metadata are not read**, because those catalog fields are not stable across the supported Azure SQL fleet. +- **Statistics are reported at database level.** Incremental statistics are not expanded into partition-level rows. + +## Rejected alternative: caller-invoked stored procedures + +The original design exposed `dbo.GetQueryStoreSlowQueries`, `dbo.GetQueryStorePlanDiagnostics`, and `dbo.GetStatisticsHealth` behind a `FhirDiagnosticsReader` execute-only role, to be called by an external operational caller. + +It was rejected because it requires an **outside principal to connect to the FHIR database and execute procedures**, which is an entirely new inbound permission model for this service. That model would have to be provisioned, granted, audited, rotated, and defended in every environment, for a diagnostic feature. The watchdog design achieves the same investigative outcome using a trust relationship that already exists. + +Secondary benefits of the change: + +- plan sanitization moves from T-SQL to C#, where it is more reliable and far easier to test; +- the persistent SQL surface, the database role, and the schema version all disappear; and +- results are emitted into telemetry continuously rather than requiring someone to be connected and asking at the moment the problem is happening. + +## Testing requirements + +### Sanitization, unit tested + +1. Fixtures cover single- and multi-statement plans; compiled values; runtime values; multiple `ParameterList` elements; plans with no parameters; unusual or unknown namespaces; large and deeply nested plans; and malformed XML. +2. Fixtures contain PHI-shaped parameter values. +3. Serialized output contains no `ParameterList`, `ParameterCompiledValue`, or `ParameterRuntimeValue`. +4. Statement text, non-parameter constants, missing-index recommendations, and warnings survive unchanged. +5. Null, malformed, and verification-failing input yields the correct status and null XML. +6. Raw or partially sanitized XML is never returned. +7. Truncation sets the flag and reports the original length, and only ever occurs after successful verification. + +### Collection, integration tested against live SQL + +1. With Query Store enabled and a deliberately slow query executed, a slow-query line is emitted carrying a matching `QueryId`/`PlanId`. +2. A query-plan line is emitted for that plan with status `Sanitized`. +3. Statistics-health rows are emitted for user tables, batched and paginated, with page numbers and totals that account for every collected row. +4. The watchdog performs no work when the configuration gate is off. +5. Pre-existing `dbo.Parameters` rows holding stale values are reconciled to the configured values during initialization, so configuration wins on a database that already holds them. +6. A non-`READ_WRITE` Query Store state is handled without error and without emission. +7. Wait-statistic unavailability degrades to null wait fields while runtime results are still emitted, and `WaitStatisticsStatus` reports which of the three outcomes occurred. +8. The watchdog does not report its own Query Store queries. +9. Emitted content is asserted, not merely emission: the execution count matches the number of probe executions, and duration and CPU sit in a plausible millisecond range, which is what catches a regression in the weighted rollup or in the microsecond-to-millisecond conversion. + +## References + +- [Monitor performance by using Query Store](https://learn.microsoft.com/sql/relational-databases/performance/monitoring-performance-by-using-the-query-store) +- [How Query Store collects data](https://learn.microsoft.com/sql/relational-databases/performance/how-query-store-collects-data) +- [`sys.query_store_runtime_stats`](https://learn.microsoft.com/sql/relational-databases/system-catalog-views/sys-query-store-runtime-stats-transact-sql) +- [`sys.query_store_wait_stats`](https://learn.microsoft.com/sql/relational-databases/system-catalog-views/sys-query-store-wait-stats-transact-sql) +- [`sys.query_store_plan`](https://learn.microsoft.com/sql/relational-databases/system-catalog-views/sys-query-store-plan-transact-sql) +- [`sys.query_store_query`](https://learn.microsoft.com/sql/relational-databases/system-catalog-views/sys-query-store-query-transact-sql) +- [`sys.query_store_query_text`](https://learn.microsoft.com/sql/relational-databases/system-catalog-views/sys-query-store-query-text-transact-sql) +- [`sys.database_query_store_options`](https://learn.microsoft.com/sql/relational-databases/system-catalog-views/sys-database-query-store-options-transact-sql) +- [`sys.dm_db_stats_properties`](https://learn.microsoft.com/sql/relational-databases/system-dynamic-management-views/sys-dm-db-stats-properties-transact-sql) +- [Showplan XML schemas](https://schemas.microsoft.com/sqlserver/2004/07/showplan/) diff --git a/docs/arch/adr-2608-query-store-performance-diagnostics.md b/docs/arch/adr-2608-query-store-performance-diagnostics.md new file mode 100644 index 0000000000..313a345eba --- /dev/null +++ b/docs/arch/adr-2608-query-store-performance-diagnostics.md @@ -0,0 +1,85 @@ +# ADR-2608: Query Store Performance Diagnostics Collection + +Labels: [SQL](https://github.com/microsoft/fhir-server/labels/Area-SQL) + +**Status**: Proposed +**Date**: 2026-08-22 +**Feature**: Query Store performance diagnostics + +## Context + +Diagnosing a slow FHIR service today requires Azure SQL Query Store data: the slowest recent queries, their execution plans, wait statistics, and statistics health. Getting that data means connecting to the database, copying and pasting queries, and working by hand against a production system. That is slow and prone to errors. + +Direct database access can also expose PHI or PII by accident. The risk is not only the resource data itself. Query Store captures compiled and runtime parameter values inside query plans, so a plan copied out of the database can carry patient data with it even when nobody queried a resource table. + +We look to simplify database performance analysis and reduce the possible PHI / PII exposure as part of this ADR. + +## Options Considered + +1. **External caller executing diagnostics stored procedures** — grant an outside identity, such as the cloud SRE agent, a SQL role restricted to a fixed set of diagnostics stored procedures, and let it connect to the customer database directly. *(rejected: creates a new standing access path into the data plane)* +2. **PaaS Action layer brokering the same stored procedures** — keep the procedures, but invoke them through the existing PaaS Action broker so the agent never holds SQL credentials itself. *(rejected: moves the credential but does not remove the access path)* +3. **In-process background job that emits diagnostics** — the server collects on its own schedule using the identity it already holds, sanitizes plans in C#, and writes the results out as structured logs. *(chosen)* + +## Decision + +We chose option 3: a watchdog-style background job inside the FHIR server, off by default, enabled and tuned entirely through configuration. + +The deciding argument is that it introduces no new access path. The server is already authenticated to its own database and already runs scheduled background work there, so diagnostics collection is more work on a connection and an identity that both already exist. Options 1 and 2 each need a principal that can reach the data plane from outside. Option 2 is better than option 1, because the agent never holds a credential itself, but the existing action path has no database access today. Choosing it would still mean opening a path that is not there now. + +Three things follow from that choice, and each of them reinforced it. + +Data leaves by push, as structured log records on the logger the server already writes to, rather than by an inbound query into the data plane. The direction of trust stays the same as it is today. + +Plan sanitization moves from T-SQL into C#. There it is unit tested, it matches on element and attribute names rather than on a Showplan namespace that changes between SQL versions, and it fails closed by verifying its own output before anything is emitted. + +Enablement uses the existing configuration surface, so turning diagnostics on in an environment is an ordinary deployment change rather than a database operation. + +We also decided to emit the diagnostics as logs rather than as metric events. Three reasons, in order of weight. + +Metric events are charged when they are received, and the volume here is not small. `docs/arch/adr-2605-metric-emission-rate-limiting.md` records a high volume emission pattern that throttled a shared metric account and degraded monitoring for both the FHIR and DICOM services. That is an availability problem as well as a bill, and it is the kind of problem that is easier to avoid than to recover from. + +The data was never metric shaped. Query text is unbounded free text, a sanitized plan is an XML document, and the top wait category is a high cardinality string. Those belong in log fields. Putting them in metric dimensions invites a cardinality incident. Nothing collected here is a rate either. These are periodic snapshots that a responder reads during an investigation. + +Logs are also the cheap place to start. If a specific number later turns out to be worth alerting on, promoting it to a metric is a small change. Recovering a throttled metric account is not. + +The statistics health rows are the one payload that is batched. They are small, uniform, and free of free text, so several of them fit on one line as a JSON array without any risk of an oversized record. Each line carries its page number, the page count, and the total row count, so a reader can tell a short final page from a set that was cut short. The slow query and plan lines are not batched. Each field there is its own named log property, which is what keeps it queryable as a column, and plan XML is large enough that batching it would risk a single oversized record. + +We also decided that every setting is set in configuration, and that configuration always wins over `dbo.Parameters`. The first iteration followed the existing watchdog convention of keeping runtime values in that table. That meant an operator had to run an `UPDATE` to arm the feature, and the collection period was read back from the database over the top of the configured value. Both work against the goal: a feature whose purpose is to remove the need for database access should not require a write to the database to switch on, and configuration that is silently overridden by a stored row is not really configuration. + +That second problem is sharper than it first appears. `dbo.Parameters` is declared `WITH (IGNORE_DUP_KEY = ON)`, so the base class's seeding `INSERT` is a silent no-op on any database that already holds the row — it neither inserts nor errors — and the value stored on some earlier deployment then wins over the environment variable indefinitely. We reproduced this directly against SQL Server: seeding `3600` and then `60` for the same key reports *"Duplicate key was ignored. (0 rows affected)"* and leaves `3600` in place. A fresh database appears to honor configuration while an upgraded one quietly does not. + +An interim iteration avoided the whole mechanism by not deriving from `Watchdog` at all. We reverted that in favor of keeping the shared base class and using `InitAdditionalParamsAsync`, the one initialization step the base class does make overridable, to `UPDATE` both rows to the configured values and re-assign the properties before the timer is built. Configuration is authoritative on every database, the rows become a readable mirror of what the service is running with rather than an input to it, and no shared file is modified. The distributed lease that stops every replica collecting the same data was kept throughout. + +## Consequences + +### Benefits + +- No new principal, role, firewall exception, or credential to provision, rotate, or audit. Nothing outside the service gains data-plane access. +- Diagnostics are enabled and tuned per environment through normal configuration, including an optional run window, and are off by default. +- The PHI boundary is enforced in C#, is covered by unit tests, and fails closed rather than emitting an unverified plan. +- Collection is single-instance through the existing lease, so the emitted lines are not multiplied by replica count. +- The feature modifies no shared file. It derives from the same `Watchdog` base class as every other watchdog, so it inherits the shared timer, lease orchestration, and any future improvement to them. +- Emission costs a log record rather than a charged metric event, so enabling the feature does not add load to the metrics pipeline. + +### Adverse effects + +- Diagnostics cannot be pulled on demand. Data appears on the collection period, hourly by default, so an incident is served by data that was already being collected rather than by an engineer asking a question and getting an answer straight away. A run window has to be configured in advance. +- Settings bind through `IOptions`, so changing them on a running host requires a restart. +- Logs are not aggregated for you. Nothing here arrives as a pre-computed time series, so trend questions need a query over the emitted lines rather than a metric chart. +- This watchdog still writes two rows to `dbo.Parameters`, because the shared base class does so during initialization and we chose to keep that base class rather than fork it. The rows are reconciled to configuration on every start, so they cannot override it, but a reader who inspects the table between a configuration change and the next restart will see values that are briefly out of date. +- The reconciliation is one extra `UPDATE` per process start. It is wrapped in a catch that logs and continues, because it runs inside the base class's initialization, outside the per-tick catch, where an unhandled throw would fault this watchdog's task and cause `WatchdogsBackgroundService` to cancel every other watchdog with it. +- Collection depends on Query Store being enabled and in `READ_WRITE` state on the database. Otherwise the job reports why it cannot collect and does nothing. +- One piece of pre-existing database state can still suppress collection silently. `dbo.AcquireWatchdogLease` honors watchdog lease include and exclude patterns held in `dbo.Parameters`. A worker excluded by such a row never becomes lease holder, so the feature can be enabled and stay quiet. This applies to every watchdog in the process and is not something this feature sets or reads, but it is the first thing to check on a long-lived database. + +### Neutral effects + +- The emitted lines are ordinary log records. There is no handler to bind and this repository prescribes no sink. Whatever a deployment already does with FHIR server logs, it does with these. +- The statistics health rows arrive as a JSON array inside one log property rather than as separate columns. A reader has to parse them. That is the trade accepted for batching, and it is affordable because the fields are few and uniform. +- The lease continues to write to its own table. That is runtime coordination rather than configuration, and is not part of what this decision changed. + +## References + +- PR [#5723](https://github.com/microsoft/fhir-server/pull/5723) +- `docs/QueryStorePerformanceDiagnostics.md` — design and configuration reference +- `docs/arch/adr-2602-database-logging.md` — precedent for diagnostics gathered inside the service +- `docs/arch/adr-2605-metric-emission-rate-limiting.md` — the emission-rate incident behind the choice of logs over metrics diff --git a/src/Microsoft.Health.Fhir.Core/Configs/QueryStoreDiagnosticsConfiguration.cs b/src/Microsoft.Health.Fhir.Core/Configs/QueryStoreDiagnosticsConfiguration.cs new file mode 100644 index 0000000000..2cc9ecaea7 --- /dev/null +++ b/src/Microsoft.Health.Fhir.Core/Configs/QueryStoreDiagnosticsConfiguration.cs @@ -0,0 +1,87 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; + +namespace Microsoft.Health.Fhir.Core.Configs +{ + /// + /// Configuration settings for the Query Store diagnostics watchdog. + /// + public class QueryStoreDiagnosticsConfiguration + { + /// + /// Gets or sets a value indicating whether the Query Store diagnostics watchdog runs. This is the only + /// switch: the feature has no database-side enablement and writes no configuration to the database. + /// + public bool Enabled { get; set; } = false; + + /// + /// Gets or sets the interval, in seconds, between diagnostics collections. Also used, clamped to + /// [60, 86400], as the Query Store lookback window each collection covers. + /// + public double PeriodSec { get; set; } = 3600; + + /// + /// Gets or sets the lease renewal interval, in seconds, used to elect the single replica that collects each + /// period. Must be positive: it is handed to the lease timer, which rejects a non-positive value. The + /// watchdog base class writes this value into dbo.Parameters, so it is exposed here to keep the + /// stored row settable from an environment variable. + /// + public double LeasePeriodSec { get; set; } = 600; + + /// + /// Gets or sets the maximum number of slow query plans reported per collection. + /// + public int SlowQueryCount { get; set; } = 10; + + /// + /// Gets or sets the minimum weighted average plan duration, in milliseconds, to report. + /// + public int MinDurationMilliseconds { get; set; } = 1000; + + /// + /// Gets or sets a value indicating whether sanitized query plans are reported. + /// + public bool IncludeQueryPlans { get; set; } = true; + + /// + /// Gets or sets a value indicating whether table statistics health is reported. + /// + public bool IncludeStatisticsHealth { get; set; } = true; + + /// + /// Gets or sets the maximum number of table statistics rows reported per collection. + /// + public int StatisticsHealthCount { get; set; } = 20; + + /// + /// Gets or sets the number of table statistics rows packed into each emitted log line. This is not a cap on + /// what is collected — is — only on how many of the collected rows share + /// a line. Rows beyond the batch size are emitted on further lines, each carrying its page number and the + /// total page and row counts. A non-positive value is reported and the default is used, because a batch size + /// cannot pack a row. + /// + public int StatisticsHealthBatchSize { get; set; } = 20; + + /// + /// Gets or sets the inclusive start of the run window, before which no diagnostics are collected. + /// Null, the default, means there is no lower bound and collection can begin immediately. + /// A value without an explicit UTC offset is interpreted in the host's local timezone, which is rarely + /// what was intended and is not visible in the configured text, so an ISO-8601 value with a Z + /// suffix such as 2026-03-01T00:00:00Z is recommended. + /// + public DateTimeOffset? RunStartDate { get; set; } + + /// + /// Gets or sets the exclusive end of the run window, at and after which no diagnostics are collected. + /// Null, the default, means there is no upper bound and collection continues indefinitely. + /// A value without an explicit UTC offset is interpreted in the host's local timezone, which is rarely + /// what was intended and is not visible in the configured text, so an ISO-8601 value with a Z + /// suffix such as 2026-03-08T00:00:00Z is recommended. + /// + public DateTimeOffset? RunEndDate { get; set; } + } +} diff --git a/src/Microsoft.Health.Fhir.Core/Configs/WatchdogConfiguration.cs b/src/Microsoft.Health.Fhir.Core/Configs/WatchdogConfiguration.cs index 8581a1404e..928eaea12b 100644 --- a/src/Microsoft.Health.Fhir.Core/Configs/WatchdogConfiguration.cs +++ b/src/Microsoft.Health.Fhir.Core/Configs/WatchdogConfiguration.cs @@ -14,5 +14,10 @@ public class WatchdogConfiguration /// Gets the expired resource cleanup configuration. /// public ExpiredResourceConfiguration ExpiredResource { get; } = new ExpiredResourceConfiguration(); + + /// + /// Gets the Query Store diagnostics watchdog configuration. + /// + public QueryStoreDiagnosticsConfiguration QueryStoreDiagnostics { get; } = new QueryStoreDiagnosticsConfiguration(); } } diff --git a/src/Microsoft.Health.Fhir.Shared.Web/appsettings.json b/src/Microsoft.Health.Fhir.Shared.Web/appsettings.json index cf11c9886f..d196e9f626 100644 --- a/src/Microsoft.Health.Fhir.Shared.Web/appsettings.json +++ b/src/Microsoft.Health.Fhir.Shared.Web/appsettings.json @@ -160,6 +160,17 @@ "Watchdog": { "ExpiredResource": { "Enabled": false + }, + "QueryStoreDiagnostics": { + "Enabled": false, + "PeriodSec": 3600, + "LeasePeriodSec": 600, + "SlowQueryCount": 10, + "MinDurationMilliseconds": 1000, + "IncludeQueryPlans": true, + "IncludeStatisticsHealth": true, + "StatisticsHealthCount": 20, + "StatisticsHealthBatchSize": 20 } } }, diff --git a/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryPlanSanitizationResultTests.cs b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryPlanSanitizationResultTests.cs new file mode 100644 index 0000000000..70c64603ba --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryPlanSanitizationResultTests.cs @@ -0,0 +1,110 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; +using System.Linq; +using System.Reflection; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics.Models; +using Microsoft.Health.Fhir.Tests.Common; +using Microsoft.Health.Test.Utilities; +using Xunit; + +namespace Microsoft.Health.Fhir.SqlServer.UnitTests.Features.Watchdogs.QueryStoreDiagnostics +{ + [Trait(Traits.OwningTeam, OwningTeam.Fhir)] + [Trait(Traits.Category, Categories.Operations)] + public class QueryPlanSanitizationResultTests + { + [Fact] + public void GivenTheResultType_WhenInspected_ThenOnlyFactoriesCanCreateIt() + { + // Act + ConstructorInfo[] constructors = typeof(QueryPlanSanitizationResult) + .GetConstructors(BindingFlags.Instance | BindingFlags.Public | BindingFlags.NonPublic); + + // Assert + Assert.NotEmpty(constructors); + Assert.All(constructors, constructor => Assert.True(constructor.IsPrivate)); + } + + [Fact] + public void GivenSanitizedXmlWithinTheFieldCap_WhenCreated_ThenCarriesThePlanAndIsNotTruncated() + { + // Arrange + const string xml = ""; + + // Act + QueryPlanSanitizationResult result = QueryPlanSanitizationResult.Sanitized(xml, originalLength: 64, sanitizedLength: xml.Length); + + // Assert + Assert.Equal(QueryPlanSanitizer.SanitizedStatus, result.Status); + Assert.Equal(xml, result.Xml); + Assert.False(result.Truncated); + Assert.Equal(64, result.OriginalLength); + Assert.Equal(xml.Length, result.SanitizedLength); + } + + [Fact] + public void GivenSanitizedXmlShorterThanTheSanitizedLength_WhenCreated_ThenTruncationIsDerivedRatherThanDeclared() + { + // Arrange + const string xml = "(() => QueryPlanSanitizationResult.Sanitized(null, 10, 10)); + } + + [Fact] + public void GivenASanitizedLengthBelowThePayloadLength_WhenCreatingASanitizedResult_ThenTheIllegalCombinationIsRejected() + { + // Act + Assert + Assert.Throws(() => QueryPlanSanitizationResult.Sanitized("", 128, 1)); + } + + [Fact] + public void GivenNegativeLengths_WhenCreatingResults_ThenTheIllegalCombinationsAreRejected() + { + // Act + Assert + Assert.Throws(() => QueryPlanSanitizationResult.Sanitized("", -1, 15)); + Assert.Throws(() => QueryPlanSanitizationResult.InvalidXml(-1)); + Assert.Throws(() => QueryPlanSanitizationResult.VerificationFailed(-1, 0)); + Assert.Throws(() => QueryPlanSanitizationResult.VerificationFailed(0, -1)); + } + + [Fact] + public void GivenAnyFailureFactory_WhenCreated_ThenTheXmlIsAlwaysNullAndNeverTruncated() + { + // Act + QueryPlanSanitizationResult[] results = + { + QueryPlanSanitizationResult.PlanXmlUnavailable(), + QueryPlanSanitizationResult.InvalidXml(128), + QueryPlanSanitizationResult.VerificationFailed(128, 64), + }; + + // Assert + Assert.All(results, result => Assert.Null(result.Xml)); + Assert.All(results, result => Assert.False(result.Truncated)); + Assert.All(results, result => Assert.NotEqual(QueryPlanSanitizer.SanitizedStatus, result.Status)); + Assert.Equal( + new[] { QueryPlanSanitizer.PlanXmlUnavailableStatus, QueryPlanSanitizer.InvalidXmlStatus, QueryPlanSanitizer.VerificationFailedStatus }, + results.Select(result => result.Status)); + } + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryPlanSanitizerTests.cs b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryPlanSanitizerTests.cs new file mode 100644 index 0000000000..b4a3c65ef9 --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryPlanSanitizerTests.cs @@ -0,0 +1,265 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; +using System.Xml.Linq; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics.Models; +using Microsoft.Health.Fhir.Tests.Common; +using Microsoft.Health.Test.Utilities; +using Xunit; + +namespace Microsoft.Health.Fhir.SqlServer.UnitTests.Features.Watchdogs.QueryStoreDiagnostics +{ + [Trait(Traits.OwningTeam, OwningTeam.Fhir)] + [Trait(Traits.Category, Categories.Operations)] + public class QueryPlanSanitizerTests + { + [Fact] + public void GivenSingleStatementPlanWithPhiShapedParameterValues_WhenSanitized_ThenRemovesParametersAndPreservesDiagnosticContent() + { + // Arrange + const string patientName = "Mikael W"; + const string medicalRecordNumber = "MRN-12345"; + string queryPlan = $@" + + + + + + + + + + + + + + + + + + + + +"; + + // Act + QueryPlanSanitizationResult result = QueryPlanSanitizer.Sanitize(queryPlan, QueryStoreDiagnosticsWatchdog.MaxFieldLength); + + // Assert + Assert.Equal(QueryPlanSanitizer.SanitizedStatus, result.Status); + Assert.NotNull(result.Xml); + Assert.False(result.Truncated); + Assert.Equal(queryPlan.Length, result.OriginalLength); + AssertNoParameterMetadata(result.Xml); + Assert.DoesNotContain(patientName, result.Xml, StringComparison.Ordinal); + Assert.DoesNotContain(medicalRecordNumber, result.Xml, StringComparison.Ordinal); + Assert.Contains("SELECT * FROM dbo.Patient WHERE Status = 1", result.Xml, StringComparison.Ordinal); + Assert.Contains("ConstValue=\"(123)\"", result.Xml, StringComparison.Ordinal); + Assert.Contains("MissingIndexGroup", result.Xml, StringComparison.Ordinal); + Assert.Contains("Warnings", result.Xml, StringComparison.Ordinal); + } + + [Fact] + public void GivenMultiStatementPlanWithMultipleParameterLists_WhenSanitized_ThenRemovesEveryParameterListAndValueAttribute() + { + // Arrange + const string compiledValue = "Alice Smith"; + const string runtimeValue = "MRN-67890"; + string queryPlan = $@" + + + + + + + + + + + + + + + + +"; + + // Act + QueryPlanSanitizationResult result = QueryPlanSanitizer.Sanitize(queryPlan, QueryStoreDiagnosticsWatchdog.MaxFieldLength); + + // Assert + Assert.Equal(QueryPlanSanitizer.SanitizedStatus, result.Status); + Assert.NotNull(result.Xml); + AssertNoParameterMetadata(result.Xml); + Assert.DoesNotContain(compiledValue, result.Xml, StringComparison.Ordinal); + Assert.DoesNotContain(runtimeValue, result.Xml, StringComparison.Ordinal); + Assert.Contains("StatementText=\"SELECT 1\"", result.Xml, StringComparison.Ordinal); + Assert.Contains("StatementText=\"SELECT 2\"", result.Xml, StringComparison.Ordinal); + } + + [Fact] + public void GivenPlansWithUnknownAndNoShowplanNamespaces_WhenSanitized_ThenRemovesParameterMetadataByLocalName() + { + // Arrange + const string unknownNamespacePlan = @""; + const string noNamespacePlan = @""; + + // Act + QueryPlanSanitizationResult unknownNamespaceResult = QueryPlanSanitizer.Sanitize(unknownNamespacePlan, QueryStoreDiagnosticsWatchdog.MaxFieldLength); + QueryPlanSanitizationResult noNamespaceResult = QueryPlanSanitizer.Sanitize(noNamespacePlan, QueryStoreDiagnosticsWatchdog.MaxFieldLength); + + // Assert + Assert.Equal(QueryPlanSanitizer.SanitizedStatus, unknownNamespaceResult.Status); + Assert.Equal(QueryPlanSanitizer.SanitizedStatus, noNamespaceResult.Status); + Assert.NotNull(unknownNamespaceResult.Xml); + Assert.NotNull(noNamespaceResult.Xml); + AssertNoParameterMetadata(unknownNamespaceResult.Xml); + AssertNoParameterMetadata(noNamespaceResult.Xml); + Assert.Contains("SELECT 3", unknownNamespaceResult.Xml, StringComparison.Ordinal); + Assert.Contains("SELECT 4", noNamespaceResult.Xml, StringComparison.Ordinal); + Assert.DoesNotContain("Jane Doe", unknownNamespaceResult.Xml, StringComparison.Ordinal); + Assert.DoesNotContain("MRN-98765", unknownNamespaceResult.Xml, StringComparison.Ordinal); + Assert.DoesNotContain("John Doe", noNamespaceResult.Xml, StringComparison.Ordinal); + Assert.DoesNotContain("MRN-54321", noNamespaceResult.Xml, StringComparison.Ordinal); + } + + [Fact] + public void GivenPlanWithoutParameters_WhenSanitized_ThenPreservesThePlanInSubstance() + { + // Arrange + const string queryPlan = @""; + + // Act + QueryPlanSanitizationResult result = QueryPlanSanitizer.Sanitize(queryPlan, QueryStoreDiagnosticsWatchdog.MaxFieldLength); + + // Assert + Assert.Equal(QueryPlanSanitizer.SanitizedStatus, result.Status); + Assert.NotNull(result.Xml); + Assert.False(result.Truncated); + Assert.Equal(result.Xml.Length, result.SanitizedLength); + Assert.True(XNode.DeepEquals(XDocument.Parse(queryPlan), XDocument.Parse(result.Xml))); + } + + [Theory] + [InlineData(null)] + [InlineData("")] + public void GivenUnavailablePlanXml_WhenSanitized_ThenReturnsPlanXmlUnavailable(string queryPlan) + { + // Act + QueryPlanSanitizationResult result = QueryPlanSanitizer.Sanitize(queryPlan, QueryStoreDiagnosticsWatchdog.MaxFieldLength); + + // Assert + Assert.Equal(QueryPlanSanitizer.PlanXmlUnavailableStatus, result.Status); + Assert.Null(result.Xml); + Assert.False(result.Truncated); + Assert.Equal(0, result.OriginalLength); + Assert.Equal(0, result.SanitizedLength); + } + + [Fact] + public void GivenMalformedPlanXml_WhenSanitized_ThenReturnsInvalidXmlWithoutThrowing() + { + // Arrange + const string queryPlan = ""; + + // Act + QueryPlanSanitizationResult result = QueryPlanSanitizer.Sanitize(queryPlan, QueryStoreDiagnosticsWatchdog.MaxFieldLength); + + // Assert + Assert.Equal(QueryPlanSanitizer.InvalidXmlStatus, result.Status); + Assert.Null(result.Xml); + Assert.False(result.Truncated); + Assert.Equal(queryPlan.Length, result.OriginalLength); + Assert.Equal(0, result.SanitizedLength); + } + + [Fact] + public void GivenPlanXmlWithADtdEntityDeclaration_WhenSanitized_ThenTheDtdIsRefusedAndNoXmlIsReturned() + { + // Arrange + // Parsing is configured with DtdProcessing.Prohibit and no resolver, so a Showplan carrying a DTD is + // rejected outright rather than having its entities expanded. The assertion that matters as much as the + // status is that nothing comes back with it: this input never reaches removal or verification, so a + // payload here would be an unsanitized payload. + const string queryPlan = @"]>"; + + // Act + QueryPlanSanitizationResult result = QueryPlanSanitizer.Sanitize(queryPlan, QueryStoreDiagnosticsWatchdog.MaxFieldLength); + + // Assert + Assert.Equal(QueryPlanSanitizer.InvalidXmlStatus, result.Status); + Assert.Null(result.Xml); + Assert.False(result.Truncated); + Assert.Equal(queryPlan.Length, result.OriginalLength); + Assert.Equal(0, result.SanitizedLength); + } + + [Fact] + public void GivenSanitizedPlanExceedingFieldCap_WhenSanitized_ThenReturnsVerifiedTruncatedXml() + { + // Arrange + const int fieldCap = 512; + string queryPlan = $@""; + + // Act + QueryPlanSanitizationResult result = QueryPlanSanitizer.Sanitize(queryPlan, fieldCap); + + // Assert + Assert.Equal(QueryPlanSanitizer.SanitizedStatus, result.Status); + Assert.NotNull(result.Xml); + Assert.True(result.Truncated); + Assert.Equal(queryPlan.Length, result.OriginalLength); + Assert.Equal(fieldCap, result.Xml.Length); + Assert.True(result.SanitizedLength > fieldCap); + Assert.True(result.SanitizedLength <= result.OriginalLength); + AssertNoParameterMetadata(result.Xml); + } + + [Fact] + public void GivenPlanWhoseStatementTextContainsTheLiteralParameterList_WhenSanitized_ThenStillSanitizesSuccessfully() + { + // Arrange + // Showplan embeds the original SQL in StatementText. A serialized-text scan would treat this plan as + // unverifiable and drop it silently; structural verification must not. + const string queryPlan = @""; + + // Act + QueryPlanSanitizationResult result = QueryPlanSanitizer.Sanitize(queryPlan, QueryStoreDiagnosticsWatchdog.MaxFieldLength); + + // Assert + Assert.Equal(QueryPlanSanitizer.SanitizedStatus, result.Status); + Assert.NotNull(result.Xml); + Assert.False(result.Truncated); + Assert.Contains("FROM dbo.ParameterList", result.Xml, StringComparison.Ordinal); + } + + [Theory] + [InlineData(@"")] + [InlineData(@"")] + [InlineData(@"N'MRN-12345'")] + public void GivenSensitiveNameThatSurvivesRemoval_WhenSanitized_ThenFailsVerificationAndNeverReturnsXml(string queryPlan) + { + // Act + QueryPlanSanitizationResult result = QueryPlanSanitizer.Sanitize(queryPlan, QueryStoreDiagnosticsWatchdog.MaxFieldLength); + + // Assert + Assert.Equal(QueryPlanSanitizer.VerificationFailedStatus, result.Status); + Assert.Null(result.Xml); + Assert.False(result.Truncated); + Assert.Equal(queryPlan.Length, result.OriginalLength); + Assert.True(result.SanitizedLength > 0); + } + + private static void AssertNoParameterMetadata(string queryPlan) + { + Assert.DoesNotContain("ParameterList", queryPlan, StringComparison.OrdinalIgnoreCase); + Assert.DoesNotContain("ParameterCompiledValue", queryPlan, StringComparison.OrdinalIgnoreCase); + Assert.DoesNotContain("ParameterRuntimeValue", queryPlan, StringComparison.OrdinalIgnoreCase); + } + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsConfigurationPrecedenceTests.cs b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsConfigurationPrecedenceTests.cs new file mode 100644 index 0000000000..907947906b --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsConfigurationPrecedenceTests.cs @@ -0,0 +1,103 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; +using System.Linq; +using System.Reflection; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics; +using Microsoft.Health.Fhir.Tests.Common; +using Microsoft.Health.Test.Utilities; +using Xunit; + +namespace Microsoft.Health.Fhir.SqlServer.UnitTests.Features.Watchdogs.QueryStoreDiagnostics +{ + /// + /// Pins the invariant the feature is now required to have: configuration is authoritative over the two + /// dbo.Parameters rows the base class seeds for it. The base class seeds those + /// rows and then reads them back over the configured values, and dbo.Parameters carries + /// IGNORE_DUP_KEY = ON, so on a database that already holds the rows the seeding insert is a silent no-op + /// and a stale row would win over an environment variable. The only thing that stops that is the overridden + /// , which reconciles the rows back to configuration with an + /// UPDATE. Every way that override could be lost is silent — deleting it, or "fixing" the reconciliation + /// into an INSERT that IGNORE_DUP_KEY no-ops, compiles and passes every other unit test, because + /// the reconciliation is only ever exercised against a live database — so these reflection assertions are what + /// catch it. + /// + [Trait(Traits.OwningTeam, OwningTeam.Fhir)] + [Trait(Traits.Category, Categories.Operations)] + public class QueryStoreDiagnosticsConfigurationPrecedenceTests + { + [Fact] + public void GivenTheWatchdog_WhenItsTypeIsInspected_ThenItDerivesFromTheWatchdogBaseClass() + { + // Arrange, Act + Type baseType = typeof(QueryStoreDiagnosticsWatchdog).BaseType; + + // Assert + // Deriving from Watchdog is what supplies the timer and the single-replica lease, and with them the + // seeding of {Name}.PeriodSec and {Name}.LeasePeriodSec into dbo.Parameters. Accepting those rows is + // deliberate; keeping configuration authoritative over them is the job of the InitAdditionalParamsAsync + // override asserted below. + Assert.Equal(typeof(Watchdog), baseType); + } + + [Fact] + public void GivenTheWatchdog_WhenInitAdditionalParamsIsInspected_ThenItIsOverriddenOnTheWatchdog() + { + // Arrange, Act + MethodInfo initAdditionalParams = typeof(QueryStoreDiagnosticsWatchdog).GetMethod( + "InitAdditionalParamsAsync", + BindingFlags.NonPublic | BindingFlags.Instance); + + // Assert + // The base class's InitParamsAsync reads the stored period and lease period back over the configured + // values, then calls this hook and only afterwards builds the timer. Overriding it here is the ONLY + // place configuration is reasserted, so if the declaring type were the base class — the override + // deleted — the stale-row bug would return with no other test failing. + Assert.NotNull(initAdditionalParams); + Assert.Equal(typeof(QueryStoreDiagnosticsWatchdog), initAdditionalParams.DeclaringType); + } + + [Fact] + public void GivenTheReconciliationStatement_WhenInspected_ThenItUpdatesDboParametersAndDoesNotInsert() + { + // Arrange + // The exact statement the override issues, read from the type rather than duplicated, so this fails if the + // real reconciliation ever stops being an UPDATE against dbo.Parameters. + string reconciliationSql = QueryStoreDiagnosticsWatchdog.ReconcileParametersSql; + + // Act, Assert + Assert.Contains("dbo.Parameters", reconciliationSql, StringComparison.OrdinalIgnoreCase); + Assert.Contains("UPDATE", reconciliationSql, StringComparison.OrdinalIgnoreCase); + + // An INSERT here would be silently no-op'd by IGNORE_DUP_KEY on an existing database, leaving the stale + // row in place and reintroducing the bug the override exists to close. + Assert.DoesNotContain("INSERT", reconciliationSql, StringComparison.OrdinalIgnoreCase); + } + + [Fact] + public void GivenEveryConstStatementTheWatchdogCanIssue_WhenInspected_ThenNoneInsertsIntoDboParameters() + { + // Arrange + // Every statement this watchdog issues is a const string on the type, so taking all of its string + // literals is a superset of its SQL — the few non-SQL literals caught alongside them cost nothing. + string[] statements = typeof(QueryStoreDiagnosticsWatchdog) + .GetFields(BindingFlags.NonPublic | BindingFlags.Static | BindingFlags.Public) + .Where(field => field.IsLiteral && field.FieldType == typeof(string)) + .Select(field => (string)field.GetRawConstantValue()) + .ToArray(); + + // Act, Assert + // The single UPDATE the reconciliation issues is the whole of what this feature writes to dbo.Parameters; + // no statement inserts into it, which is what keeps IGNORE_DUP_KEY from ever silently ignoring a write + // this feature depended on taking effect. + Assert.NotEmpty(statements); + Assert.All( + statements, + statement => Assert.DoesNotContain("INSERT INTO dbo.Parameters", statement, StringComparison.OrdinalIgnoreCase)); + } + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsLeasePeriodTests.cs b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsLeasePeriodTests.cs new file mode 100644 index 0000000000..8b8f83044e --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsLeasePeriodTests.cs @@ -0,0 +1,120 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; +using System.Collections.Generic; +using System.Globalization; +using System.Linq; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Microsoft.Health.Fhir.Core.Configs; +using Microsoft.Health.Fhir.SqlServer.Features.Storage; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics; +using Microsoft.Health.Fhir.Tests.Common; +using Microsoft.Health.Test.Utilities; +using NSubstitute; +using Xunit; + +namespace Microsoft.Health.Fhir.SqlServer.UnitTests.Features.Watchdogs.QueryStoreDiagnostics +{ + /// + /// Covers the lease renewal interval. Like the collection period it is handed to a timer the base class owns, + /// which rejects a non-positive or non-finite value, and a fault there cancels the token every watchdog shares — + /// so a bad value in this off-by-default feature must degrade to the default rather than fail the host. It is + /// also one of the two values written into dbo.Parameters, which is why it is on the configuration + /// surface at all. + /// + [Trait(Traits.OwningTeam, OwningTeam.Fhir)] + [Trait(Traits.Category, Categories.Operations)] + public class QueryStoreDiagnosticsLeasePeriodTests + { + private const double DefaultLeasePeriodSec = 600; + + [Theory] + [InlineData(0d)] + [InlineData(-1d)] + [InlineData(-600d)] + [InlineData(double.NaN)] + [InlineData(double.PositiveInfinity)] + public void GivenAnUnusableConfiguredLeasePeriod_WhenConstructed_ThenTheDefaultIsUsedAndTheValueIsReported(double configuredLeasePeriodSec) + { + // Arrange + var logger = new CapturingLogger(); + + // Act + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, configuredLeasePeriodSec); + + // Assert + // The lease period must never reach PeriodicTimer in this state: it throws there, which faults this + // watchdog's task and causes WatchdogsBackgroundService to cancel the token every other watchdog shares. + Assert.Equal(DefaultLeasePeriodSec, watchdog.LeasePeriodSec); + + string warning = Assert.Single(logger.WarningMessages); + Assert.Contains(Format(configuredLeasePeriodSec), warning, StringComparison.Ordinal); + Assert.Contains(Format(DefaultLeasePeriodSec), warning, StringComparison.Ordinal); + Assert.Contains(QueryStoreDiagnosticsWatchdog.LeasePeriodSecConfigurationKey, warning, StringComparison.Ordinal); + } + + [Theory] + [InlineData(1d)] + [InlineData(300d)] + [InlineData(600d)] + [InlineData(3600d)] + public void GivenAUsableConfiguredLeasePeriod_WhenConstructed_ThenItIsUsedUnchangedAndNothingIsReported(double configuredLeasePeriodSec) + { + // Arrange + var logger = new CapturingLogger(); + + // Act + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, configuredLeasePeriodSec); + + // Assert + Assert.Equal(configuredLeasePeriodSec, watchdog.LeasePeriodSec); + Assert.Empty(logger.WarningMessages); + } + + private static QueryStoreDiagnosticsWatchdog CreateWatchdog(ILogger logger, double configuredLeasePeriodSec) + { + var configuration = new WatchdogConfiguration(); + configuration.QueryStoreDiagnostics.Enabled = true; + + // Left at its valid class default so that the only value under test is the lease period; a bad period + // would raise its own warning and defeat the Assert.Single checks above. + configuration.QueryStoreDiagnostics.LeasePeriodSec = configuredLeasePeriodSec; + + return new QueryStoreDiagnosticsWatchdog( + Substitute.For(), + logger, + Options.Create(configuration)); + } + + // The logging infrastructure formats message arguments with the invariant culture, so expected values are + // formatted the same way rather than with whatever culture the test host happens to run under. + private static string Format(double value) => value.ToString(CultureInfo.InvariantCulture); + + /// + /// Records what was logged, at what level, with the arguments already substituted, so a test can assert that + /// an operator is told the values they need rather than merely that some warning was raised. + /// + private sealed class CapturingLogger : ILogger + { + private readonly List<(LogLevel Level, string Message)> _entries = new List<(LogLevel Level, string Message)>(); + + internal IReadOnlyList WarningMessages => + _entries.Where(entry => entry.Level == LogLevel.Warning).Select(entry => entry.Message).ToList(); + + public IDisposable BeginScope(TState state) + where TState : notnull + => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + _entries.Add((logLevel, formatter(state, exception))); + } + } + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsPeriodTests.cs b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsPeriodTests.cs new file mode 100644 index 0000000000..6bcb5767b6 --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsPeriodTests.cs @@ -0,0 +1,180 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; +using System.Collections.Generic; +using System.Globalization; +using System.Linq; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Microsoft.Health.Fhir.Core.Configs; +using Microsoft.Health.Fhir.SqlServer.Features.Storage; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics.Models; +using Microsoft.Health.Fhir.Tests.Common; +using Microsoft.Health.Test.Utilities; +using NSubstitute; +using Xunit; + +namespace Microsoft.Health.Fhir.SqlServer.UnitTests.Features.Watchdogs.QueryStoreDiagnostics +{ + /// + /// Covers the collection period, which is the one setting whose misconfiguration reaches outside this feature: + /// it is handed to the timer this watchdog owns, and it is clamped independently when it is used as the Query + /// Store lookback window. Neither path is reachable from the integration tests, which call the collection + /// directly and never start the timer. + /// + [Trait(Traits.OwningTeam, OwningTeam.Fhir)] + [Trait(Traits.Category, Categories.Operations)] + public class QueryStoreDiagnosticsPeriodTests + { + private const double DefaultPeriodSec = 3600; + + [Theory] + [InlineData(0d)] + [InlineData(-1d)] + [InlineData(-3600d)] + [InlineData(double.NaN)] + [InlineData(double.PositiveInfinity)] + public void GivenAnUnusableConfiguredPeriod_WhenConstructed_ThenTheDefaultIsUsedAndTheValueIsReported(double configuredPeriodSec) + { + // Arrange + var logger = new CapturingLogger(); + + // Act + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, configuredPeriodSec); + + // Assert + // The period must never reach PeriodicTimer in this state: it throws there, which faults this watchdog's + // task and causes WatchdogsBackgroundService to cancel the token every other watchdog shares. + Assert.Equal(DefaultPeriodSec, watchdog.PeriodSec); + + string warning = Assert.Single(logger.WarningMessages); + Assert.Contains(Format(configuredPeriodSec), warning, StringComparison.Ordinal); + Assert.Contains(Format(DefaultPeriodSec), warning, StringComparison.Ordinal); + } + + [Theory] + [InlineData(1d)] + [InlineData(900d)] + [InlineData(86400d)] + public void GivenAUsableConfiguredPeriod_WhenConstructed_ThenItIsUsedUnchangedAndNothingIsReported(double configuredPeriodSec) + { + // Arrange + var logger = new CapturingLogger(); + + // Act + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, configuredPeriodSec); + + // Assert + Assert.Equal(configuredPeriodSec, watchdog.PeriodSec); + Assert.Empty(logger.WarningMessages); + } + + [Fact] + public void GivenAConfiguredPeriodAboveTheLookbackCap_WhenDerivingTheLookback_ThenTheUnexaminedWindowIsReported() + { + // Arrange + const double configuredPeriodSec = 604800; // one week + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, configuredPeriodSec); + + // Act + double lookbackPeriodSec = watchdog.GetLookbackPeriodSec(watchdog.PeriodSec); + + // Assert + Assert.Equal(86400d, lookbackPeriodSec); + + // The tick interval stays at the configured period, so the difference is a permanent coverage gap and the + // warning has to name it rather than leave it to be worked out from the clamp. + string warning = Assert.Single(logger.WarningMessages); + Assert.Contains(Format(configuredPeriodSec), warning, StringComparison.Ordinal); + Assert.Contains(Format(86400d), warning, StringComparison.Ordinal); + Assert.Contains(Format(configuredPeriodSec - 86400d), warning, StringComparison.Ordinal); + + // The remedy names the configuration key, because there is no longer a database row to update. + Assert.Contains(QueryStoreDiagnosticsWatchdog.PeriodSecConfigurationKey, warning, StringComparison.Ordinal); + } + + [Fact] + public void GivenAConfiguredPeriodBelowTheLookbackFloor_WhenDerivingTheLookback_ThenTheOverlapIsReported() + { + // Arrange + const double configuredPeriodSec = 30; + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, configuredPeriodSec); + + // Act + double lookbackPeriodSec = watchdog.GetLookbackPeriodSec(watchdog.PeriodSec); + + // Assert + Assert.Equal(60d, lookbackPeriodSec); + + string warning = Assert.Single(logger.WarningMessages); + Assert.Contains(Format(configuredPeriodSec), warning, StringComparison.Ordinal); + Assert.Contains(Format(60d), warning, StringComparison.Ordinal); + Assert.Contains("overlap", warning, StringComparison.OrdinalIgnoreCase); + Assert.Contains(QueryStoreDiagnosticsWatchdog.PeriodSecConfigurationKey, warning, StringComparison.Ordinal); + } + + [Theory] + [InlineData(60d)] + [InlineData(3600d)] + [InlineData(86400d)] + public void GivenAConfiguredPeriodWithinTheLookbackRange_WhenDerivingTheLookback_ThenItIsUsedUnchangedAndNothingIsReported(double configuredPeriodSec) + { + // Arrange + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, configuredPeriodSec); + + // Act + double lookbackPeriodSec = watchdog.GetLookbackPeriodSec(watchdog.PeriodSec); + + // Assert + Assert.Equal(configuredPeriodSec, lookbackPeriodSec); + Assert.Empty(logger.WarningMessages); + } + + private static QueryStoreDiagnosticsWatchdog CreateWatchdog(ILogger logger, double configuredPeriodSec) + { + var configuration = new WatchdogConfiguration(); + configuration.QueryStoreDiagnostics.Enabled = true; + configuration.QueryStoreDiagnostics.PeriodSec = configuredPeriodSec; + + return new QueryStoreDiagnosticsWatchdog( + Substitute.For(), + logger, + Options.Create(configuration)); + } + + // The logging infrastructure formats message arguments with the invariant culture, so expected values are + // formatted the same way rather than with whatever culture the test host happens to run under. + private static string Format(double value) => value.ToString(CultureInfo.InvariantCulture); + + /// + /// Records what was logged, at what level, with the arguments already substituted, so a test can assert that + /// an operator is told the values they need rather than merely that some warning was raised. + /// + private sealed class CapturingLogger : ILogger + { + private readonly List<(LogLevel Level, string Message)> _entries = new List<(LogLevel Level, string Message)>(); + + internal IReadOnlyList WarningMessages => + _entries.Where(entry => entry.Level == LogLevel.Warning).Select(entry => entry.Message).ToList(); + + public IDisposable BeginScope(TState state) + where TState : notnull + => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + _entries.Add((logLevel, formatter(state, exception))); + } + } + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsRunWindowTests.cs b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsRunWindowTests.cs new file mode 100644 index 0000000000..716dcb5539 --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsRunWindowTests.cs @@ -0,0 +1,319 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; +using System.Collections.Generic; +using System.Globalization; +using System.Linq; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Microsoft.Health.Fhir.Core.Configs; +using Microsoft.Health.Fhir.SqlServer.Features.Storage; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics.Models; +using Microsoft.Health.Fhir.Tests.Common; +using Microsoft.Health.Test.Utilities; +using NSubstitute; +using Xunit; + +namespace Microsoft.Health.Fhir.SqlServer.UnitTests.Features.Watchdogs.QueryStoreDiagnostics +{ + /// + /// Covers the optional run window, which decides whether a tick collects anything at all. Every boundary case is + /// a clock comparison the integration tests cannot reach — they invoke the collection directly, and the window is + /// evaluated above it — and the failure mode of getting one wrong is silence rather than an error, so the window + /// has to be pinned here or not at all. + /// + [Trait(Traits.OwningTeam, OwningTeam.Fhir)] + [Trait(Traits.Category, Categories.Operations)] + public class QueryStoreDiagnosticsRunWindowTests + { + private const string WindowStart = "2026-03-01T00:00:00Z"; + private const string WindowEnd = "2026-03-08T00:00:00Z"; + + [Theory] + [InlineData("0001-01-01T00:00:00Z")] + [InlineData("2026-03-01T00:00:00Z")] + [InlineData("9999-12-31T23:59:59Z")] + public void GivenNoConfiguredWindow_WhenCheckingAnyTime_ThenCollectionProceeds(string utcNow) + { + // Arrange + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger); + + // Act + bool isWithinRunWindow = watchdog.IsWithinRunWindow(Parse(utcNow)); + + // Assert + // Both bounds unset is the default configuration, so this is the shape the feature has for every + // deployment that never opts into a window. + Assert.True(isWithinRunWindow); + Assert.Empty(logger.WarningMessages); + } + + [Theory] + [InlineData("2026-02-28T23:59:59Z", false)] + [InlineData("2026-03-01T00:00:00Z", true)] // the start bound is inclusive + [InlineData("2026-03-01T00:00:01Z", true)] + [InlineData("9999-12-31T23:59:59Z", true)] + public void GivenOnlyAStartDate_WhenCheckingATime_ThenTheBoundIsInclusiveAndThereIsNoUpperLimit(string utcNow, bool expected) + { + // Arrange + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, runStartDate: Parse(WindowStart)); + + // Act + bool isWithinRunWindow = watchdog.IsWithinRunWindow(Parse(utcNow)); + + // Assert + Assert.Equal(expected, isWithinRunWindow); + } + + [Theory] + [InlineData("0001-01-01T00:00:00Z", true)] + [InlineData("2026-03-07T23:59:59Z", true)] + [InlineData("2026-03-08T00:00:00Z", false)] // the end bound is exclusive + [InlineData("2026-03-08T00:00:01Z", false)] + public void GivenOnlyAnEndDate_WhenCheckingATime_ThenTheBoundIsExclusiveAndThereIsNoLowerLimit(string utcNow, bool expected) + { + // Arrange + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, runEndDate: Parse(WindowEnd)); + + // Act + bool isWithinRunWindow = watchdog.IsWithinRunWindow(Parse(utcNow)); + + // Assert + Assert.Equal(expected, isWithinRunWindow); + } + + [Theory] + [InlineData("2026-02-28T23:59:59Z", false)] + [InlineData("2026-03-01T00:00:00Z", true)] + [InlineData("2026-03-04T12:00:00Z", true)] + [InlineData("2026-03-07T23:59:59Z", true)] + [InlineData("2026-03-08T00:00:00Z", false)] + [InlineData("2026-03-09T00:00:00Z", false)] + public void GivenBothDates_WhenCheckingATime_ThenOnlyTheHalfOpenIntervalCollects(string utcNow, bool expected) + { + // Arrange + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, Parse(WindowStart), Parse(WindowEnd)); + + // Act + bool isWithinRunWindow = watchdog.IsWithinRunWindow(Parse(utcNow)); + + // Assert + Assert.Equal(expected, isWithinRunWindow); + } + + [Theory] + [InlineData(WindowEnd, WindowEnd, "2026-02-28T23:59:59Z")] + [InlineData(WindowEnd, WindowEnd, "2026-03-08T00:00:00Z")] + [InlineData(WindowEnd, WindowEnd, "9999-12-31T23:59:59Z")] + [InlineData(WindowEnd, WindowStart, "2026-02-28T23:59:59Z")] + [InlineData(WindowEnd, WindowStart, "2026-03-04T12:00:00Z")] + [InlineData(WindowEnd, WindowStart, "2026-03-09T00:00:00Z")] + public void GivenAStartDateNotBeforeTheEndDate_WhenCheckingAnyTime_ThenCollectionNeverProceeds(string runStartDate, string runEndDate, string utcNow) + { + // Arrange + // Start equal to end is as empty as start after end, because the end bound is exclusive: there is no + // instant that is both at or after the start and strictly before the end. + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, Parse(runStartDate), Parse(runEndDate)); + + // Act + bool isWithinRunWindow = watchdog.IsWithinRunWindow(Parse(utcNow)); + + // Assert + Assert.False(isWithinRunWindow); + } + + [Fact] + public void GivenABoundWithANonUtcOffset_WhenCheckingATime_ThenItIsComparedAsTheInstantItDenotes() + { + // Arrange + // 05:00+05:00 is midnight UTC. A bound configured without an explicit offset is bound in the host's local + // timezone and arrives here exactly like this, so the comparison has to be on the instant rather than on + // the wall-clock reading, or such a window opens hours early or late. + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog( + logger, + runStartDate: new DateTimeOffset(2026, 3, 1, 5, 0, 0, TimeSpan.FromHours(5))); + + // Act + bool beforeTheInstant = watchdog.IsWithinRunWindow(Parse("2026-02-28T23:59:59Z")); + bool atTheInstant = watchdog.IsWithinRunWindow(Parse("2026-03-01T00:00:00Z")); + + // Assert + Assert.False(beforeTheInstant); + Assert.True(atTheInstant); + } + + [Fact] + public void GivenRepeatedTicksInTheSameState_WhenCheckingTheWindow_ThenOnlyTheTransitionsAreReported() + { + // Arrange + // At the default hourly period a window that opens in a month would otherwise log around 720 identical + // skip lines, which is what makes the skip unreadable rather than informative. + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, Parse(WindowStart), Parse(WindowEnd)); + + // Act + watchdog.IsWithinRunWindow(Parse("2026-02-27T00:00:00Z")); + watchdog.IsWithinRunWindow(Parse("2026-02-28T00:00:00Z")); + watchdog.IsWithinRunWindow(Parse("2026-03-02T00:00:00Z")); + watchdog.IsWithinRunWindow(Parse("2026-03-03T00:00:00Z")); + watchdog.IsWithinRunWindow(Parse("2026-03-09T00:00:00Z")); + watchdog.IsWithinRunWindow(Parse("2026-03-10T00:00:00Z")); + + // Assert + // Three transitions across six ticks: not open yet, open, closed. + Assert.Equal(3, logger.InformationMessages.Count); + Assert.Contains("has not opened yet", logger.InformationMessages[0], StringComparison.Ordinal); + Assert.Contains("within the configured run window", logger.InformationMessages[1], StringComparison.Ordinal); + Assert.Contains("closed", logger.InformationMessages[2], StringComparison.Ordinal); + + // The skip is the feature working as configured, so none of it is a warning. + Assert.Empty(logger.WarningMessages); + } + + [Fact] + public void GivenTheFirstObservedTick_WhenTheWindowIsAlreadyOpen_ThenTheStateIsStillReportedOnce() + { + // Arrange + // The initial state has to log, or a process that starts inside its window reports nothing about the + // window until the moment it closes. + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, Parse(WindowStart), Parse(WindowEnd)); + + // Act + watchdog.IsWithinRunWindow(Parse("2026-03-02T00:00:00Z")); + watchdog.IsWithinRunWindow(Parse("2026-03-03T00:00:00Z")); + + // Assert + string message = Assert.Single(logger.InformationMessages); + Assert.Contains(FormatUtc(Parse(WindowStart)), message, StringComparison.Ordinal); + Assert.Contains(FormatUtc(Parse(WindowEnd)), message, StringComparison.Ordinal); + } + + [Fact] + public void GivenAnEmptyWindow_WhenInitialized_ThenItIsReportedAsCollectingNothingEver() + { + // Arrange + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, Parse(WindowEnd), Parse(WindowStart)); + + // Act + watchdog.ReportConfiguredRunWindow(); + + // Assert + // Nothing downstream ever complains about this configuration — it simply never collects — so the warning + // has to name both values rather than say the window is invalid. + string warning = Assert.Single(logger.WarningMessages); + Assert.Contains(FormatUtc(Parse(WindowEnd)), warning, StringComparison.Ordinal); + Assert.Contains(FormatUtc(Parse(WindowStart)), warning, StringComparison.Ordinal); + } + + [Fact] + public void GivenAUsableWindow_WhenInitialized_ThenTheEffectiveWindowIsEchoedInUtcAndNothingIsWarned() + { + // Arrange + // A bound typed without an offset resolves against the host's timezone and looks identical in + // configuration either way, so the resolved UTC instants are echoed at startup where the mistake is still + // cheap to correct. + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog( + logger, + new DateTimeOffset(2026, 3, 1, 5, 0, 0, TimeSpan.FromHours(5)), + new DateTimeOffset(2026, 3, 7, 19, 0, 0, TimeSpan.FromHours(-5))); + + // Act + watchdog.ReportConfiguredRunWindow(); + + // Assert + string message = Assert.Single(logger.InformationMessages); + Assert.Contains(FormatUtc(Parse(WindowStart)), message, StringComparison.Ordinal); + Assert.Contains(FormatUtc(Parse(WindowEnd)), message, StringComparison.Ordinal); + Assert.Empty(logger.WarningMessages); + } + + [Fact] + public void GivenNoConfiguredWindow_WhenInitialized_ThenNothingIsReported() + { + // Arrange + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger); + + // Act + watchdog.ReportConfiguredRunWindow(); + + // Assert + // The default configuration has no window, and reporting an absent one on every host start would be noise. + Assert.Empty(logger.InformationMessages); + Assert.Empty(logger.WarningMessages); + } + + private static QueryStoreDiagnosticsWatchdog CreateWatchdog( + CapturingLogger logger, + DateTimeOffset? runStartDate = null, + DateTimeOffset? runEndDate = null) + { + var configuration = new WatchdogConfiguration(); + configuration.QueryStoreDiagnostics.Enabled = true; + configuration.QueryStoreDiagnostics.RunStartDate = runStartDate; + configuration.QueryStoreDiagnostics.RunEndDate = runEndDate; + + var watchdog = new QueryStoreDiagnosticsWatchdog( + Substitute.For(), + logger, + Options.Create(configuration)); + + // Constructing the watchdog constructs its WatchdogLease, which logs through this same logger, so + // construction is not silent. Dropping that here keeps every assertion below a statement about what the + // run window reported. + logger.Clear(); + + return watchdog; + } + + private static DateTimeOffset Parse(string value) => + DateTimeOffset.Parse(value, CultureInfo.InvariantCulture, DateTimeStyles.RoundtripKind); + + // The logging infrastructure formats message arguments with the invariant culture, so expected values are + // formatted the same way rather than with whatever culture the test host happens to run under. + private static string FormatUtc(DateTimeOffset value) => + value.ToUniversalTime().ToString(CultureInfo.InvariantCulture); + + /// + /// Records what was logged, at what level, with the arguments already substituted, so a test can assert that + /// an operator is told the values they need rather than merely that something was logged. + /// + private sealed class CapturingLogger : ILogger + { + private readonly List<(LogLevel Level, string Message)> _entries = new List<(LogLevel Level, string Message)>(); + + internal IReadOnlyList WarningMessages => + _entries.Where(entry => entry.Level == LogLevel.Warning).Select(entry => entry.Message).ToList(); + + internal IReadOnlyList InformationMessages => + _entries.Where(entry => entry.Level == LogLevel.Information).Select(entry => entry.Message).ToList(); + + public IDisposable BeginScope(TState state) + where TState : notnull + => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + _entries.Add((logLevel, formatter(state, exception))); + } + + internal void Clear() => _entries.Clear(); + } + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsStatisticsHealthBatchTests.cs b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsStatisticsHealthBatchTests.cs new file mode 100644 index 0000000000..9e7b98de83 --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsStatisticsHealthBatchTests.cs @@ -0,0 +1,273 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; +using System.Collections.Generic; +using System.Globalization; +using System.Linq; +using System.Text.Json; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Microsoft.Health.Fhir.Core.Configs; +using Microsoft.Health.Fhir.SqlServer.Features.Storage; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics.Models; +using Microsoft.Health.Fhir.Tests.Common; +using Microsoft.Health.Test.Utilities; +using NSubstitute; +using Xunit; + +namespace Microsoft.Health.Fhir.SqlServer.UnitTests.Features.Watchdogs.QueryStoreDiagnostics +{ + /// + /// Covers the statistics-health batching, which is the one place where what was collected and what reaches a log + /// line can differ. The pagination fields are the only way a reader can tell a short final page from a set that + /// was cut short, and an off-by-one in the page arithmetic silently drops or duplicates rows rather than failing, + /// so every boundary is pinned here. The integration test runs against whatever row count the live schema + /// happens to have and cannot pin any of them. + /// + [Trait(Traits.OwningTeam, OwningTeam.Fhir)] + [Trait(Traits.Category, Categories.Operations)] + public class QueryStoreDiagnosticsStatisticsHealthBatchTests + { + private const int DefaultBatchSize = 20; + + [Fact] + public void GivenExactlyOneFullBatch_WhenEmitting_ThenOneLineCarriesEveryRow() + { + // Arrange + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, batchSize: 5); + + // Act + watchdog.LogStatisticsHealthBatches(CreateRows(5)); + + // Assert + CapturingLogger.LogEntry entry = Assert.Single(logger.StatisticsHealthEntries); + Assert.Equal(LogLevel.Information, entry.Level); + Assert.Equal(1, entry.Properties["StatisticsHealthPage"]); + Assert.Equal(1, entry.Properties["StatisticsHealthPageCount"]); + Assert.Equal(5, entry.Properties["StatisticsHealthPageRowCount"]); + Assert.Equal(5, entry.Properties["StatisticsHealthRowCount"]); + + // A full batch must not spill into an empty second page, which is what a page count derived by dividing + // and then unconditionally adding one would produce. + AssertRowsAre(entry, 0, 5); + } + + [Fact] + public void GivenAPartialFinalPage_WhenEmitting_ThenTheLastLineReportsOnlyTheRowsItCarries() + { + // Arrange + // Twelve rows at a batch size of five is two full pages and a final page of two. + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, batchSize: 5); + + // Act + watchdog.LogStatisticsHealthBatches(CreateRows(12)); + + // Assert + Assert.Equal(3, logger.StatisticsHealthEntries.Count); + Assert.Equal(new[] { 1, 2, 3 }, logger.StatisticsHealthEntries.Select(entry => (int)entry.Properties["StatisticsHealthPage"])); + Assert.All(logger.StatisticsHealthEntries, entry => Assert.Equal(3, entry.Properties["StatisticsHealthPageCount"])); + + // The whole point of carrying the total: a final page of two out of twelve is complete, and a reader has + // to be able to say so without guessing from the batch size. + Assert.All(logger.StatisticsHealthEntries, entry => Assert.Equal(12, entry.Properties["StatisticsHealthRowCount"])); + Assert.Equal(new[] { 5, 5, 2 }, logger.StatisticsHealthEntries.Select(entry => (int)entry.Properties["StatisticsHealthPageRowCount"])); + + AssertRowsAre(logger.StatisticsHealthEntries[0], 0, 5); + AssertRowsAre(logger.StatisticsHealthEntries[1], 5, 5); + AssertRowsAre(logger.StatisticsHealthEntries[2], 10, 2); + } + + [Fact] + public void GivenMoreRowsThanOneBatch_WhenEmitting_ThenEveryRowIsEmittedExactlyOnceInOrder() + { + // Arrange + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, batchSize: 4); + + // Act + watchdog.LogStatisticsHealthBatches(CreateRows(9)); + + // Assert + Assert.Equal(3, logger.StatisticsHealthEntries.Count); + + // Paging is what makes the batch safe, so the union of the pages has to be the collected set exactly: + // neither a dropped row at a page boundary nor one emitted on two pages. + List emitted = logger.StatisticsHealthEntries + .SelectMany(entry => DeserializeRows(entry).Select(row => row.StatisticsName)) + .ToList(); + Assert.Equal(CreateRows(9).Select(row => row.StatisticsName).ToList(), emitted); + } + + [Fact] + public void GivenANonPositiveBatchSize_WhenEmitting_ThenTheDefaultIsUsedAndTheValueIsReported() + { + // Arrange + // Unlike the counts, a batch size of zero cannot mean "collect nothing": the rows have already been read + // by this point, so degrading to the default is the only option that does not throw away diagnostics. + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, batchSize: 0); + + // Act + watchdog.LogStatisticsHealthBatches(CreateRows(DefaultBatchSize + 1)); + + // Assert + Assert.Equal(2, logger.StatisticsHealthEntries.Count); + Assert.Equal(DefaultBatchSize, logger.StatisticsHealthEntries[0].Properties["StatisticsHealthPageRowCount"]); + Assert.Equal(1, logger.StatisticsHealthEntries[1].Properties["StatisticsHealthPageRowCount"]); + + string warning = Assert.Single(logger.WarningMessages); + Assert.Contains(Format(0), warning, StringComparison.Ordinal); + Assert.Contains(Format(DefaultBatchSize), warning, StringComparison.Ordinal); + } + + [Fact] + public void GivenABatchSizeAboveTheCap_WhenEmitting_ThenItIsClampedAndEveryRowIsStillEmitted() + { + // Arrange + // An unbounded batch would rebuild the single oversized record that is the reason plan XML is never + // batched, so the cap binds. Clamping must page the rows rather than drop the ones past the cap. + const int MaxBatchSize = 64; + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, batchSize: 5000); + + // Act + watchdog.LogStatisticsHealthBatches(CreateRows(MaxBatchSize + 3)); + + // Assert + Assert.Equal(2, logger.StatisticsHealthEntries.Count); + Assert.Equal(MaxBatchSize, logger.StatisticsHealthEntries[0].Properties["StatisticsHealthPageRowCount"]); + Assert.Equal(3, logger.StatisticsHealthEntries[1].Properties["StatisticsHealthPageRowCount"]); + Assert.Equal(MaxBatchSize + 3, logger.StatisticsHealthEntries[0].Properties["StatisticsHealthRowCount"]); + + AssertRowsAre(logger.StatisticsHealthEntries[0], firstRowIndex: 0, expectedRowCount: MaxBatchSize); + AssertRowsAre(logger.StatisticsHealthEntries[1], firstRowIndex: MaxBatchSize, expectedRowCount: 3); + + string warning = Assert.Single(logger.WarningMessages); + Assert.Contains(Format(5000), warning, StringComparison.Ordinal); + Assert.Contains(Format(MaxBatchSize), warning, StringComparison.Ordinal); + } + + [Fact] + public void GivenNoRows_WhenEmitting_ThenNoLineIsEmitted() + { + // Arrange + // The collection summary already reports a count of zero, so an empty page would add nothing except an + // extra page for a reader counting them. + var logger = new CapturingLogger(); + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(logger, batchSize: 5); + + // Act + watchdog.LogStatisticsHealthBatches(Array.Empty()); + + // Assert + Assert.Empty(logger.StatisticsHealthEntries); + Assert.Empty(logger.WarningMessages); + } + + private static void AssertRowsAre(CapturingLogger.LogEntry entry, int firstRowIndex, int expectedRowCount) + { + List rows = DeserializeRows(entry); + Assert.Equal(expectedRowCount, rows.Count); + for (int offset = 0; offset < expectedRowCount; offset++) + { + Assert.Equal(RowName(firstRowIndex + offset), rows[offset].StatisticsName); + } + } + + private static List DeserializeRows(CapturingLogger.LogEntry entry) + { + // Deserializing rather than string-matching, because the property is only useful downstream if it really + // is a JSON array of rows. + return JsonSerializer.Deserialize>((string)entry.Properties["StatisticsHealthRows"]); + } + + private static IReadOnlyList CreateRows(int count) + { + return Enumerable.Range(0, count) + .Select(index => new StatisticsHealthDiagnostics + { + SchemaName = "dbo", + TableName = "Resource", + StatisticsName = RowName(index), + Rows = index, + }) + .ToList(); + } + + private static string RowName(int index) => FormattableString.Invariant($"ST_{index}"); + + // The logging infrastructure formats message arguments with the invariant culture, so expected values are + // formatted the same way rather than with whatever culture the test host happens to run under. + private static string Format(int value) => value.ToString(CultureInfo.InvariantCulture); + + private static QueryStoreDiagnosticsWatchdog CreateWatchdog(ILogger logger, int batchSize) + { + var configuration = new WatchdogConfiguration(); + configuration.QueryStoreDiagnostics.Enabled = true; + configuration.QueryStoreDiagnostics.StatisticsHealthBatchSize = batchSize; + + return new QueryStoreDiagnosticsWatchdog( + Substitute.For(), + logger, + Options.Create(configuration)); + } + + /// + /// Records what was logged, at what level, keeping the named properties alongside the formatted message so a + /// test can assert on the values an emitted line carries rather than only on the text it renders to. + /// + private sealed class CapturingLogger : ILogger + { + private readonly List _entries = new List(); + + internal IReadOnlyList WarningMessages => + _entries.Where(entry => entry.Level == LogLevel.Warning).Select(entry => entry.Message).ToList(); + + internal IReadOnlyList StatisticsHealthEntries => + _entries.Where(entry => entry.Message.StartsWith("QueryStoreDiagnosticsWatchdog statistics health.", StringComparison.Ordinal)).ToList(); + + public IDisposable BeginScope(TState state) + where TState : notnull + => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + _entries.Add(new LogEntry(logLevel, formatter(state, exception), state as IReadOnlyList>)); + } + + internal sealed class LogEntry + { + internal LogEntry(LogLevel level, string message, IReadOnlyList> state) + { + Level = level; + Message = message; + + var properties = new Dictionary(StringComparer.Ordinal); + foreach (KeyValuePair property in state ?? Array.Empty>()) + { + // Assigned rather than added, because a template is free to repeat a placeholder and this + // capture must not throw on a line it merely passes through. + properties[property.Key] = property.Value; + } + + Properties = properties; + } + + internal LogLevel Level { get; } + + internal string Message { get; } + + internal IReadOnlyDictionary Properties { get; } + } + } + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsWaitStatisticsTests.cs b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsWaitStatisticsTests.cs new file mode 100644 index 0000000000..23220bc15b --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsWaitStatisticsTests.cs @@ -0,0 +1,181 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Data.SqlClient; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Microsoft.Health.Fhir.Core.Configs; +using Microsoft.Health.Fhir.SqlServer.Features.Storage; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics.Models; +using Microsoft.Health.Fhir.SqlServer.UnitTests.Features.Storage; +using Microsoft.Health.Fhir.Tests.Common; +using Microsoft.Health.Test.Utilities; +using NSubstitute; +using Xunit; + +namespace Microsoft.Health.Fhir.SqlServer.UnitTests.Features.Watchdogs.QueryStoreDiagnostics +{ + /// + /// Covers the branch that reports a broken wait collection. The integration test can only assert that the status + /// is not Failed, because it cannot make a live wait read fail, so without this the branch that exists + /// specifically to make that breakage visible would never be executed by the suite. + /// + [Trait(Traits.OwningTeam, OwningTeam.Fhir)] + [Trait(Traits.Category, Categories.Operations)] + public class QueryStoreDiagnosticsWaitStatisticsTests + { + private const int DeadlockErrorNumber = 1205; + + [Fact] + public async Task GivenAFailingWaitStatisticsRead_WhenCollecting_ThenSlowQueriesAreLoggedWithFailedWaitStatus() + { + // Arrange + var sqlRetryService = Substitute.For(); + var logger = new CapturingLogger(); + + var slowQuery = new QueryStoreDiagnosticsWatchdog.SlowQueryResult + { + QueryId = 11, + PlanId = 22, + ExecutionCount = 4, + TotalDurationMilliseconds = 400, + AverageDurationMilliseconds = 100, + MaxDurationMilliseconds = 150, + TotalCpuMilliseconds = 200, + AverageCpuMilliseconds = 50, + TotalLogicalReads = 80, + AverageLogicalReads = 20, + QueryText = "SELECT 1", + IntervalStart = DateTimeOffset.UtcNow.AddMinutes(-5), + IntervalEnd = DateTimeOffset.UtcNow, + }; + + sqlRetryService + .ExecuteReaderAsync( + Arg.Any(), + Arg.Any>(), + Arg.Any(), + Arg.Any(), + Arg.Any(), + Arg.Any()) + .Returns(new List { slowQuery }); + + sqlRetryService + .ExecuteReaderAsync( + Arg.Any(), + Arg.Any>(), + Arg.Any(), + Arg.Any(), + Arg.Any(), + Arg.Any()) + .Returns>( + _ => throw SqlExceptionFactory.GetSqlException(DeadlockErrorNumber, "Transaction was deadlocked on lock resources.")); + + QueryStoreDiagnosticsWatchdog watchdog = CreateWatchdog(sqlRetryService, logger); + + // Act + await watchdog.CollectDiagnosticsAsync(DateTimeOffset.UtcNow.AddHours(-1), DateTimeOffset.UtcNow, CancellationToken.None); + + // Assert + // The runtime statistics are the primary signal, so a broken wait read must not suppress them... + CapturingLogger.LogEntry entry = Assert.Single(logger.SlowQueryEntries); + Assert.Equal(LogLevel.Information, entry.Level); + Assert.Equal(slowQuery.QueryId, entry.Properties["QueryId"]); + Assert.Equal(slowQuery.PlanId, entry.Properties["PlanId"]); + Assert.Equal(slowQuery.TotalDurationMilliseconds, entry.Properties["TotalDurationMilliseconds"]); + + // ...and the breakage must be visible on the emitted line rather than looking like "this plan waited on + // nothing", which is what an Unavailable status would mean. These are asserted on the structured state + // rather than on the formatted message because a null renders as an empty string once formatted, which + // is indistinguishable from a value that was genuinely reported as empty. + Assert.Equal(QueryStoreDiagnosticsWatchdog.WaitStatisticsFailedStatus, entry.Properties["WaitStatisticsStatus"]); + Assert.Null(entry.Properties["TotalWaitMilliseconds"]); + Assert.Null(entry.Properties["AverageWaitMilliseconds"]); + Assert.Null(entry.Properties["TopWaitCategory"]); + + // The failure itself is still reported, so that a wait read broken for a month is not visible only to + // someone who thought to look at the status field. + Assert.Contains( + logger.WarningMessages, + message => message.Contains("wait statistics could not be read", StringComparison.Ordinal)); + } + + private static QueryStoreDiagnosticsWatchdog CreateWatchdog(ISqlRetryService sqlRetryService, ILogger logger) + { + var configuration = new WatchdogConfiguration(); + configuration.QueryStoreDiagnostics.Enabled = true; + configuration.QueryStoreDiagnostics.SlowQueryCount = 10; + configuration.QueryStoreDiagnostics.MinDurationMilliseconds = 1; + + // The plan and statistics sections are turned off so that the only reads this test has to stand up are + // the two it is about. + configuration.QueryStoreDiagnostics.IncludeQueryPlans = false; + configuration.QueryStoreDiagnostics.IncludeStatisticsHealth = false; + + return new QueryStoreDiagnosticsWatchdog( + sqlRetryService, + logger, + Options.Create(configuration)); + } + + /// + /// Records what was logged, at what level, keeping the named properties alongside the formatted message so a + /// test can assert on the values an emitted line carries rather than only on the text it renders to. + /// + private sealed class CapturingLogger : ILogger + { + private readonly List _entries = new List(); + + internal IReadOnlyList WarningMessages => + _entries.Where(entry => entry.Level == LogLevel.Warning).Select(entry => entry.Message).ToList(); + + internal IReadOnlyList SlowQueryEntries => + _entries.Where(entry => entry.Message.StartsWith("QueryStoreDiagnosticsWatchdog slow query.", StringComparison.Ordinal)).ToList(); + + public IDisposable BeginScope(TState state) + where TState : notnull + => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + _entries.Add(new LogEntry(logLevel, formatter(state, exception), state as IReadOnlyList>)); + } + + internal sealed class LogEntry + { + internal LogEntry(LogLevel level, string message, IReadOnlyList> state) + { + Level = level; + Message = message; + + var properties = new Dictionary(StringComparer.Ordinal); + foreach (KeyValuePair property in state ?? Array.Empty>()) + { + // Assigned rather than added, because a template is free to repeat a placeholder and this + // capture must not throw on a line it merely passes through. + properties[property.Key] = property.Value; + } + + Properties = properties; + } + + internal LogLevel Level { get; } + + internal string Message { get; } + + internal IReadOnlyDictionary Properties { get; } + } + } + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreReadonlyReasonTests.cs b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreReadonlyReasonTests.cs new file mode 100644 index 0000000000..e60ef685b5 --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer.UnitTests/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreReadonlyReasonTests.cs @@ -0,0 +1,102 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; +using System.Globalization; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics.Models; +using Microsoft.Health.Fhir.Tests.Common; +using Microsoft.Health.Test.Utilities; +using Xunit; + +namespace Microsoft.Health.Fhir.SqlServer.UnitTests.Features.Watchdogs.QueryStoreDiagnostics +{ + [Trait(Traits.OwningTeam, OwningTeam.Fhir)] + [Trait(Traits.Category, Categories.Operations)] + public class QueryStoreReadonlyReasonTests + { + [Theory] + [InlineData(1, "database is in read-only mode")] + [InlineData(2, "database is in single-user mode")] + [InlineData(4, "database is in emergency mode")] + [InlineData(8, "database is a secondary replica")] + [InlineData(65536, "Query Store has reached its size limit (MAX_STORAGE_SIZE_MB)")] + [InlineData(131072, "Query Store has reached the limit on the number of statements")] + public void GivenASingleDocumentedBit_WhenDescribed_ThenReturnsThatReason(int readonlyReason, string expected) + { + // Act + string description = QueryStoreDiagnosticsWatchdog.DescribeReadonlyReason(readonlyReason); + + // Assert + Assert.Equal(expected, description); + } + + [Fact] + public void GivenACombinedMask_WhenDescribed_ThenReturnsEveryReasonInBitOrder() + { + // Arrange + const int combinedMask = 8 | 65536 | 131072; + + // Act + string description = QueryStoreDiagnosticsWatchdog.DescribeReadonlyReason(combinedMask); + + // Assert + Assert.Equal( + "database is a secondary replica, Query Store has reached its size limit (MAX_STORAGE_SIZE_MB), Query Store has reached the limit on the number of statements", + description); + } + + [Fact] + public void GivenNoReason_WhenDescribed_ThenDistinguishesNotReportedFromNone() + { + // Act + string notReported = QueryStoreDiagnosticsWatchdog.DescribeReadonlyReason(null); + string none = QueryStoreDiagnosticsWatchdog.DescribeReadonlyReason(0); + + // Assert + Assert.Equal("not reported", notReported); + Assert.Equal("none", none); + } + + [Fact] + public void GivenAnUndocumentedBit_WhenDescribed_ThenReportsItAsUnrecognizedRatherThanEmpty() + { + // Act + string description = QueryStoreDiagnosticsWatchdog.DescribeReadonlyReason(1 << 20); + + // Assert + Assert.Equal("unrecognized reason", description); + } + + [Fact] + public void GivenTheSizeLimitBitCombinedWithAnUndocumentedBit_WhenDescribed_ThenStillNamesTheDocumentedReason() + { + // Act + string description = QueryStoreDiagnosticsWatchdog.DescribeReadonlyReason(65536 | (1 << 20)); + + // Assert + Assert.Contains("size limit", description, StringComparison.Ordinal); + } + + [Fact] + public void GivenADocumentedBitCombinedWithAnUndocumentedBit_WhenDescribed_ThenAlsoReportsTheUndocumentedBitAndTheRawValue() + { + // Arrange + const int undocumentedBit = 1 << 20; + const int mask = 65536 | undocumentedBit; + + // Act + string description = QueryStoreDiagnosticsWatchdog.DescribeReadonlyReason(mask); + + // Assert + // A state flag this code does not know about must not be swallowed just because a documented bit happened + // to be set alongside it: the raw value is what an operator takes to the SQL Server documentation. + Assert.Contains("Query Store has reached its size limit (MAX_STORAGE_SIZE_MB)", description, StringComparison.Ordinal); + Assert.Contains(undocumentedBit.ToString(CultureInfo.InvariantCulture), description, StringComparison.Ordinal); + Assert.Contains(mask.ToString(CultureInfo.InvariantCulture), description, StringComparison.Ordinal); + } + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer/AssemblyInfo.cs b/src/Microsoft.Health.Fhir.SqlServer/AssemblyInfo.cs index 7122f10988..7d6da185af 100644 --- a/src/Microsoft.Health.Fhir.SqlServer/AssemblyInfo.cs +++ b/src/Microsoft.Health.Fhir.SqlServer/AssemblyInfo.cs @@ -7,6 +7,10 @@ using System.Runtime.CompilerServices; [assembly: InternalsVisibleTo("Microsoft.Health.Fhir.SqlServer.UnitTests")] + +// Castle DynamicProxy backs NSubstitute; without this it cannot produce a substitute value for a generic type +// closed over an internal type, which is what mocking ISqlRetryService reads in the watchdogs requires. +[assembly: InternalsVisibleTo("DynamicProxyGenAssembly2")] [assembly: InternalsVisibleTo("Microsoft.Health.Fhir.Stu3.Tests.Integration")] [assembly: InternalsVisibleTo("Microsoft.Health.Fhir.R4.Tests.Integration")] [assembly: InternalsVisibleTo("Microsoft.Health.Fhir.R4B.Tests.Integration")] diff --git a/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/Models/QueryPlanDiagnostics.cs b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/Models/QueryPlanDiagnostics.cs new file mode 100644 index 0000000000..78220230fb --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/Models/QueryPlanDiagnostics.cs @@ -0,0 +1,61 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; + +namespace Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics.Models +{ + /// + /// A sanitized Query Store execution plan, as emitted on a single structured log line. This is a log payload + /// shape rather than a contract anything binds to, so it lives beside the only component that produces it and + /// is internal. + /// + internal sealed class QueryPlanDiagnostics + { + /// + /// Gets or sets the Query Store query identifier. + /// + public long QueryId { get; set; } + + /// + /// Gets or sets the Query Store plan identifier. + /// + public long PlanId { get; set; } + + /// + /// Gets or sets the sanitized query plan XML, limited to the diagnostics field-length cap. + /// + public string SanitizedQueryPlan { get; set; } + + /// + /// Gets or sets a value indicating whether was truncated. + /// + public bool QueryPlanTruncated { get; set; } + + /// + /// Gets or sets the character length of the raw query plan XML as read from Query Store. + /// + public int OriginalQueryPlanLength { get; set; } + + /// + /// Gets or sets the character length of the sanitized query plan XML before truncation. + /// Compare this against the field cap to see how much lost when + /// is set. Zero when sanitization did not produce a document. + /// + public int SanitizedQueryPlanLength { get; set; } + + /// + /// Gets or sets the outcome of query plan sanitization. + /// + public string SanitizationStatus { get; set; } + + /// + /// Gets or sets the timestamp when the diagnostics were collected. Emitted under a name of its own rather + /// than as Timestamp, because that name collides with the ingestion timestamp the log pipeline + /// supplies for every record. + /// + public DateTimeOffset Timestamp { get; set; } = DateTimeOffset.UtcNow; + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/Models/SlowQueryDiagnostics.cs b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/Models/SlowQueryDiagnostics.cs new file mode 100644 index 0000000000..5888d8b924 --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/Models/SlowQueryDiagnostics.cs @@ -0,0 +1,127 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; + +namespace Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics.Models +{ + /// + /// The aggregated Query Store diagnostics for one slow query plan, as emitted on a single structured log line. + /// This is a log payload shape rather than a contract anything binds to: it lives beside the only component that + /// produces it, and is internal because nothing outside this assembly consumes it. Each property becomes its own + /// named log property, so it stays queryable as a column downstream instead of being buried in a serialized blob. + /// + internal sealed class SlowQueryDiagnostics + { + /// + /// Gets or sets the Query Store query identifier. + /// + public long QueryId { get; set; } + + /// + /// Gets or sets the Query Store plan identifier. + /// + public long PlanId { get; set; } + + /// + /// Gets or sets the number of regular completed executions in the reporting interval. + /// + public long ExecutionCount { get; set; } + + /// + /// Gets or sets the total execution duration, in milliseconds. + /// + public double TotalDurationMilliseconds { get; set; } + + /// + /// Gets or sets the weighted average execution duration, in milliseconds. + /// + public double AverageDurationMilliseconds { get; set; } + + /// + /// Gets or sets the maximum execution duration, in milliseconds. + /// + public double MaxDurationMilliseconds { get; set; } + + /// + /// Gets or sets the total CPU time, in milliseconds. + /// + public double TotalCpuMilliseconds { get; set; } + + /// + /// Gets or sets the weighted average CPU time, in milliseconds. + /// + public double AverageCpuMilliseconds { get; set; } + + /// + /// Gets or sets the total logical reads. + /// + public double TotalLogicalReads { get; set; } + + /// + /// Gets or sets the weighted average logical reads. + /// + public double AverageLogicalReads { get; set; } + + /// + /// Gets or sets the total observed wait time, in milliseconds, when Query Store wait statistics are available. + /// + public double? TotalWaitMilliseconds { get; set; } + + /// + /// Gets or sets the average observed wait time per execution, in milliseconds, when Query Store wait statistics are available. + /// + public double? AverageWaitMilliseconds { get; set; } + + /// + /// Gets or sets the wait category with the greatest observed wait time. This can be null even when + /// is Available, because Query Store itself reports no category + /// for some waits; Available means a wait row was read for the plan, not that it named a category. + /// + public string TopWaitCategory { get; set; } + + /// + /// Gets or sets the outcome of wait-statistics collection, so that absent wait fields are self-describing: + /// Available when wait statistics were read for this plan, Unavailable when the wait query + /// succeeded but returned no row for this plan (typically wait capture is off, or the plan accrued no waits), + /// and Failed when the wait query itself threw. Failed means the wait fields are missing because + /// collection is broken, not because there was nothing to report. + /// + public string WaitStatisticsStatus { get; set; } + + /// + /// Gets or sets the query text, limited to the diagnostics field-length cap. + /// + public string QueryText { get; set; } + + /// + /// Gets or sets a value indicating whether was truncated. + /// + public bool QueryTextTruncated { get; set; } + + /// + /// Gets or sets the character length of the query text before truncation, so the amount lost is + /// visible when is set. + /// + public int QueryTextLength { get; set; } + + /// + /// Gets or sets the start of the Query Store reporting interval. + /// + public DateTimeOffset IntervalStart { get; set; } + + /// + /// Gets or sets the end of the Query Store reporting interval. + /// + public DateTimeOffset IntervalEnd { get; set; } + + /// + /// Gets or sets the timestamp when the diagnostics were collected. Emitted under a name of its own rather + /// than as Timestamp, because that name collides with the ingestion timestamp the log pipeline + /// supplies for every record. + /// + public DateTimeOffset Timestamp { get; set; } = DateTimeOffset.UtcNow; + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/Models/StatisticsHealthDiagnostics.cs b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/Models/StatisticsHealthDiagnostics.cs new file mode 100644 index 0000000000..627670ce27 --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/Models/StatisticsHealthDiagnostics.cs @@ -0,0 +1,85 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; + +namespace Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics.Models +{ + /// + /// Table statistics health for one statistics object. Unlike the slow-query and query-plan payloads, instances of + /// this type are serialized to JSON and carried several to a log line: the rows are small, uniform, and contain no + /// free text, so a batch of them has a predictable size and nothing is lost by giving up per-field columns. + /// Properties are public because only serializes public members; + /// the type itself is internal because nothing outside this assembly consumes it. + /// + internal sealed class StatisticsHealthDiagnostics + { + /// + /// Gets or sets the schema that owns the table. + /// + public string SchemaName { get; set; } + + /// + /// Gets or sets the table name. + /// + public string TableName { get; set; } + + /// + /// Gets or sets the statistics object name. + /// + public string StatisticsName { get; set; } + + /// + /// Gets or sets the timestamp when the statistics were last updated. + /// + public DateTimeOffset? LastUpdated { get; set; } + + /// + /// Gets or sets the number of rows represented by the statistics. + /// + public long? Rows { get; set; } + + /// + /// Gets or sets the number of rows sampled to build the statistics. + /// + public long? RowsSampled { get; set; } + + /// + /// Gets or sets the number of modifications since the statistics were last updated. + /// + public long? ModificationCounter { get; set; } + + /// + /// Gets or sets the percentage of represented rows modified since the statistics were last updated. + /// + public double? ModificationPercent { get; set; } + + /// + /// Gets or sets a value indicating whether SQL Server automatically created the statistics. + /// + public bool IsAutoCreated { get; set; } + + /// + /// Gets or sets a value indicating whether a user created the statistics. + /// + public bool IsUserCreated { get; set; } + + /// + /// Gets or sets a value indicating whether the statistics are associated with an index. + /// + public bool IsFromIndex { get; set; } + + /// + /// Gets or sets a value indicating whether the statistics use a filter. + /// + public bool HasFilter { get; set; } + + /// + /// Gets or sets the timestamp when the diagnostics were collected. Carried on the row rather than only on the + /// log line so that a row stays self-describing once it is lifted out of the batch it was emitted in. + /// + public DateTimeOffset Timestamp { get; set; } = DateTimeOffset.UtcNow; + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/QueryPlanSanitizationResult.cs b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/QueryPlanSanitizationResult.cs new file mode 100644 index 0000000000..2656b06caa --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/QueryPlanSanitizationResult.cs @@ -0,0 +1,117 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using EnsureThat; + +namespace Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics +{ + /// + /// Outcome of Showplan sanitization. + /// + /// + /// The constructor is private and instances are produced only through the factory methods below, because the + /// payload can embed literal parameter values taken from patient data. The factories do not themselves verify + /// the document — trusts its caller for that — but they do guarantee the shape of the + /// result: every failure factory forces to null, so no failure status can be paired with a + /// payload, the success factory refuses a null document, and is derived from the + /// payload rather than supplied alongside it, so it cannot contradict what it describes. + /// + internal sealed class QueryPlanSanitizationResult + { + private QueryPlanSanitizationResult(string status, string xml, int originalLength, int sanitizedLength) + { + Status = status; + Xml = xml; + OriginalLength = originalLength; + SanitizedLength = sanitizedLength; + + // Derived here rather than supplied by each factory, so the invariant "truncated exactly when the payload + // is shorter than the document it came from" has one implementation instead of four opportunities to + // contradict it. A failure result carries no payload and is therefore never truncated. + Truncated = xml != null && sanitizedLength > xml.Length; + } + + /// + /// Gets the sanitization outcome, one of the status constants on . + /// + internal string Status { get; } + + /// + /// Gets the sanitized and verified Showplan XML, or null when sanitization did not succeed. + /// + internal string Xml { get; } + + /// + /// Gets a value indicating whether was truncated to the field cap. + /// + internal bool Truncated { get; } + + /// + /// Gets the length of the raw Showplan XML as read from Query Store. + /// + internal int OriginalLength { get; } + + /// + /// Gets the length of the sanitized Showplan XML before truncation, or zero when sanitization did not produce a document. + /// This is the value to compare against the field cap when is set. + /// + internal int SanitizedLength { get; } + + /// + /// Creates a successful result. The XML is required to be non-null and already verified free of parameter data. + /// + /// The sanitized, verified and field-capped Showplan XML. + /// The length of the raw Showplan XML as read from Query Store. + /// The length of the sanitized Showplan XML before truncation. + /// A result carrying the sanitized document. + internal static QueryPlanSanitizationResult Sanitized(string xml, int originalLength, int sanitizedLength) + { + EnsureArg.IsNotNull(xml, nameof(xml)); + EnsureArg.IsGte(originalLength, 0, nameof(originalLength)); + EnsureArg.IsGte(sanitizedLength, xml.Length, nameof(sanitizedLength)); + + return new QueryPlanSanitizationResult( + QueryPlanSanitizer.SanitizedStatus, + xml, + originalLength, + sanitizedLength); + } + + /// + /// Creates a result for a plan that Query Store did not supply any Showplan XML for. + /// + /// A result with null XML. + internal static QueryPlanSanitizationResult PlanXmlUnavailable() + { + return new QueryPlanSanitizationResult(QueryPlanSanitizer.PlanXmlUnavailableStatus, null, 0, 0); + } + + /// + /// Creates a result for Showplan XML that could not be parsed. + /// + /// The length of the raw Showplan XML as read from Query Store. + /// A result with null XML. + internal static QueryPlanSanitizationResult InvalidXml(int originalLength) + { + EnsureArg.IsGte(originalLength, 0, nameof(originalLength)); + + return new QueryPlanSanitizationResult(QueryPlanSanitizer.InvalidXmlStatus, null, originalLength, 0); + } + + /// + /// Creates a result for Showplan XML in which parameter data survived removal. The document is discarded. + /// + /// The length of the raw Showplan XML as read from Query Store. + /// The length of the discarded document, retained so the loss is quantifiable. + /// A result with null XML. + internal static QueryPlanSanitizationResult VerificationFailed(int originalLength, int sanitizedLength) + { + EnsureArg.IsGte(originalLength, 0, nameof(originalLength)); + EnsureArg.IsGte(sanitizedLength, 0, nameof(sanitizedLength)); + + return new QueryPlanSanitizationResult(QueryPlanSanitizer.VerificationFailedStatus, null, originalLength, sanitizedLength); + } + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/QueryPlanSanitizer.cs b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/QueryPlanSanitizer.cs new file mode 100644 index 0000000000..fa819b99d4 --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/QueryPlanSanitizer.cs @@ -0,0 +1,118 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; +using System.IO; +using System.Linq; +using System.Xml; +using System.Xml.Linq; + +namespace Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics +{ + /// + /// Removes Showplan parameter metadata, which can carry literal values taken from patient data, and verifies + /// that none of it survived before the plan is allowed out of the process. + /// + internal static class QueryPlanSanitizer + { + internal const string SanitizedStatus = "Sanitized"; + internal const string PlanXmlUnavailableStatus = "PlanXmlUnavailable"; + internal const string InvalidXmlStatus = "InvalidXml"; + internal const string VerificationFailedStatus = "VerificationFailed"; + + /// + /// Removes parameter metadata from a Showplan document, verifies the removal, and caps the result. + /// + /// The raw Showplan XML as read from Query Store. + /// The maximum length of the returned XML. + /// The sanitization outcome. The XML is null unless removal was verified to have succeeded. + internal static QueryPlanSanitizationResult Sanitize(string queryPlanXml, int maxLength) + { + if (string.IsNullOrEmpty(queryPlanXml)) + { + return QueryPlanSanitizationResult.PlanXmlUnavailable(); + } + + try + { + var settings = new XmlReaderSettings + { + DtdProcessing = DtdProcessing.Prohibit, + XmlResolver = null, + }; + + XDocument document; + using (var stringReader = new StringReader(queryPlanXml)) + using (var xmlReader = XmlReader.Create(stringReader, settings)) + { + document = XDocument.Load(xmlReader, LoadOptions.PreserveWhitespace); + } + + // A document with no root element is handled here and only here, because it is the one condition that + // would otherwise both skip removal (there is nothing to descend from) and satisfy verification + // (nothing sensitive is found in an empty tree), and so would emit the document verbatim. XDocument.Load + // rejects a rootless document today, which makes this unreachable; a PHI boundary must nevertheless + // have no condition under which sanitization is skipped and verification reports success. + if (document.Root == null) + { + return QueryPlanSanitizationResult.VerificationFailed(queryPlanXml.Length, 0); + } + + var elements = document.Root.DescendantsAndSelf() + .Where(element => string.Equals(element.Name.LocalName, "ParameterList", StringComparison.OrdinalIgnoreCase)) + .ToList(); + elements.Remove(); + + var attributes = document.Root.DescendantsAndSelf() + .Attributes() + .Where(attribute => + string.Equals(attribute.Name.LocalName, "ParameterCompiledValue", StringComparison.OrdinalIgnoreCase) || + string.Equals(attribute.Name.LocalName, "ParameterRuntimeValue", StringComparison.OrdinalIgnoreCase)) + .ToList(); + attributes.Remove(); + + var sanitizedXml = document.ToString(SaveOptions.DisableFormatting); + var sanitizedLength = sanitizedXml.Length; + + // Verification re-inspects the tree after removal and fails closed. It is deliberately structural: + // Showplan embeds the original SQL in StatementText, so a text scan would drop any plan whose own + // query text happens to contain the literal string "ParameterList". + if (ContainsSensitiveParameterData(document)) + { + return QueryPlanSanitizationResult.VerificationFailed(queryPlanXml.Length, sanitizedLength); + } + + maxLength = Math.Max(0, maxLength); + if (sanitizedXml.Length > maxLength) + { + sanitizedXml = sanitizedXml.Substring(0, maxLength); + } + + return QueryPlanSanitizationResult.Sanitized(sanitizedXml, queryPlanXml.Length, sanitizedLength); + } + catch (XmlException) + { + return QueryPlanSanitizationResult.InvalidXml(queryPlanXml.Length); + } + } + + private static bool ContainsSensitiveParameterData(XDocument document) + { + // Matching is by local name and namespace-agnostic, exactly as the removal above, so a Showplan namespace + // change between SQL versions cannot let parameter data pass verification. The root is known non-null: + // Sanitize fails a rootless document closed before reaching removal. + return document.Root.DescendantsAndSelf().Any(element => + IsSensitiveName(element.Name.LocalName) || + element.Attributes().Any(attribute => IsSensitiveName(attribute.Name.LocalName))); + } + + private static bool IsSensitiveName(string localName) + { + return string.Equals(localName, "ParameterList", StringComparison.OrdinalIgnoreCase) || + string.Equals(localName, "ParameterCompiledValue", StringComparison.OrdinalIgnoreCase) || + string.Equals(localName, "ParameterRuntimeValue", StringComparison.OrdinalIgnoreCase); + } + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsWatchdog.cs b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsWatchdog.cs new file mode 100644 index 0000000000..eb40ee4c82 --- /dev/null +++ b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/QueryStoreDiagnostics/QueryStoreDiagnosticsWatchdog.cs @@ -0,0 +1,1203 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; +using System.Collections.Generic; +using System.Data; +using System.Linq; +using System.Text.Json; +using System.Threading; +using System.Threading.Tasks; +using EnsureThat; +using Microsoft.Data.SqlClient; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Microsoft.Health.Fhir.Core.Configs; +using Microsoft.Health.Fhir.SqlServer.Features.Storage; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics.Models; + +namespace Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics +{ + /// + /// Collects Azure SQL Query Store and statistics diagnostics on a timer and emits them as structured log lines. + /// Logs rather than metric events: the payload is not metric-shaped — query text and plan XML are unbounded + /// free text and wait categories are high cardinality — and metric events are charged on receipt, which + /// docs/arch/adr-2605-metric-emission-rate-limiting.md records as having throttled a shared metric + /// account. Derives from for its timer and its single-replica lease, and so accepts + /// the two dbo.Parameters rows the base class seeds for its period and lease period. Configuration stays + /// authoritative over those rows: the base class re-reads them over the configured values during + /// initialization, and is overridden to reconcile them back to + /// configuration before the timer starts, so an environment variable always wins over a stale stored row. + /// + internal sealed class QueryStoreDiagnosticsWatchdog : Watchdog + { + internal const int MaxFieldLength = 32 * 1024; + + /// + /// The configuration key that sets the collection period, named in the warnings that report the period + /// being unusable or clamped so the remedy does not have to be looked up. + /// + internal const string PeriodSecConfigurationKey = "FhirServer:Watchdog:QueryStoreDiagnostics:PeriodSec"; + + /// + /// The configuration key that sets the lease renewal interval, named in the warning that reports the lease + /// period being unusable so the remedy does not have to be looked up. + /// + internal const string LeasePeriodSecConfigurationKey = "FhirServer:Watchdog:QueryStoreDiagnostics:LeasePeriodSec"; + + /// + /// The statement that reconciles the two dbo.Parameters rows the base class seeds — the period and the + /// lease period — back to the configured values. An UPDATE rather than an INSERT on purpose: + /// the base class's seeding INSERT already guarantees the rows exist, and dbo.Parameters carries + /// IGNORE_DUP_KEY = ON, so a re-INSERT of an existing row is silently ignored and would leave a + /// stale value overriding configuration. Exposed as internal so a unit test can pin that shape without a + /// database, because the reconciliation is otherwise only exercised against a live one. + /// + internal const string ReconcileParametersSql = @" +UPDATE dbo.Parameters SET Number = @PeriodSec WHERE Id = @PeriodSecId +UPDATE dbo.Parameters SET Number = @LeasePeriodSec WHERE Id = @LeasePeriodSecId"; + + /// Wait statistics were read for the plan. + internal const string WaitStatisticsAvailableStatus = "Available"; + + /// The wait query succeeded but returned no row for the plan. + internal const string WaitStatisticsUnavailableStatus = "Unavailable"; + + /// The wait query itself failed, so wait fields are missing because collection is broken. + internal const string WaitStatisticsFailedStatus = "Failed"; + + /// The collection interval used when configuration does not supply a usable one. + private const double DefaultPeriodSec = 3600; + + /// The lease renewal interval used when configuration does not supply a usable one. + private const double DefaultLeasePeriodSec = 600; + + /// + /// The statistics-health batch size used when configuration does not supply a usable one. Mirrors the class + /// default on . + /// + private const int DefaultStatisticsHealthBatchSize = 20; + + /// + /// The largest number of statistics rows packed into one log line. Batching exists to reduce record count, + /// but an unbounded batch would recreate the single oversized record that is the reason plan XML is not + /// batched at all. A typical serialized row is a little under 400 bytes, so this keeps a full page well + /// inside the budget the feature already applies to its other large fields. + /// Rows above the cap are not dropped; they move to the next page. + /// + private const int MaxStatisticsHealthBatchSize = 64; + + /// The shortest lookback window a collection is allowed to use. + private const double MinLookbackPeriodSec = 60; + + /// The longest lookback window a collection is allowed to use. + private const double MaxLookbackPeriodSec = 86400; + + private const string QueryStoreStateSql = @" +-- readonly_reason is a bitmask, and it is int here while neighbouring Query Store columns (query_id, plan_id, +-- count_executions, rows, rows_sampled, modification_counter) are bigint. That inconsistency is the trap: reading +-- this column with GetInt64 throws InvalidCastException at runtime, which no compiler or unit test will catch. +SELECT actual_state_desc, readonly_reason +FROM sys.database_query_store_options;"; + + private const string SlowQueriesSql = @" +-- Query Store duration and CPU values are recorded in MICROSECONDS while the emitted contract is in MILLISECONDS, +-- which is what every /1000.0 below is for. Query Store also stores PER-INTERVAL averages, so combining intervals +-- requires weighting each interval average by its count_executions first; an unweighted mean across intervals with +-- unequal execution counts is mathematically wrong. +;WITH PlanRuntimeStatistics AS +( + SELECT + runtimeStatistics.plan_id, + SUM(runtimeStatistics.count_executions) AS execution_count, + SUM(CONVERT(float, runtimeStatistics.avg_duration) * runtimeStatistics.count_executions) AS total_duration_microseconds, + MAX(CONVERT(float, runtimeStatistics.max_duration)) AS max_duration_microseconds, + SUM(CONVERT(float, runtimeStatistics.avg_cpu_time) * runtimeStatistics.count_executions) AS total_cpu_microseconds, + SUM(CONVERT(float, runtimeStatistics.avg_logical_io_reads) * runtimeStatistics.count_executions) AS total_logical_reads, + MIN(runtimeStatisticsInterval.start_time) AS interval_start, + MAX(runtimeStatisticsInterval.end_time) AS interval_end + FROM sys.query_store_runtime_stats AS runtimeStatistics + INNER JOIN sys.query_store_runtime_stats_interval AS runtimeStatisticsInterval + ON runtimeStatistics.runtime_stats_interval_id = runtimeStatisticsInterval.runtime_stats_interval_id + WHERE runtimeStatisticsInterval.end_time >= @StartTime + AND runtimeStatistics.execution_type = 0 -- regular completed executions only + GROUP BY runtimeStatistics.plan_id +) +SELECT TOP (@Top) + queryStoreQuery.query_id, + queryStorePlan.plan_id, + runtimeRollup.execution_count, + runtimeRollup.total_duration_microseconds / 1000.0 AS total_duration_milliseconds, + runtimeRollup.total_duration_microseconds / runtimeRollup.execution_count / 1000.0 AS average_duration_milliseconds, + runtimeRollup.max_duration_microseconds / 1000.0 AS max_duration_milliseconds, + runtimeRollup.total_cpu_microseconds / 1000.0 AS total_cpu_milliseconds, + runtimeRollup.total_cpu_microseconds / runtimeRollup.execution_count / 1000.0 AS average_cpu_milliseconds, + runtimeRollup.total_logical_reads, + runtimeRollup.total_logical_reads / runtimeRollup.execution_count AS average_logical_reads, + queryText.query_sql_text, + runtimeRollup.interval_start, + runtimeRollup.interval_end +-- 'statistics' is a RESERVED T-SQL keyword and cannot be used as a table alias, which is why the rollup CTE is +-- aliased runtimeRollup rather than statistics. +FROM PlanRuntimeStatistics AS runtimeRollup +INNER JOIN sys.query_store_plan AS queryStorePlan + ON runtimeRollup.plan_id = queryStorePlan.plan_id +INNER JOIN sys.query_store_query AS queryStoreQuery + ON queryStorePlan.query_id = queryStoreQuery.query_id +INNER JOIN sys.query_store_query_text AS queryText + ON queryStoreQuery.query_text_id = queryText.query_text_id +WHERE runtimeRollup.execution_count > 0 + AND runtimeRollup.total_duration_microseconds / runtimeRollup.execution_count / 1000.0 >= @MinDurationMilliseconds + -- Query Store does NOT preserve comments in query_sql_text, so a marker comment cannot be used to identify a + -- statement. The watchdog therefore excludes its own statements by catalog name, and the integration tests + -- identify their probe query by a GUID-derived result-column alias, which Query Store does preserve. + -- The explicit case-insensitive collation also keeps the comparison correct on case-sensitive databases. + AND queryText.query_sql_text COLLATE Latin1_General_CI_AS NOT LIKE N'%query_store%' + AND queryText.query_sql_text COLLATE Latin1_General_CI_AS NOT LIKE N'%dm_db_stats_properties%' +ORDER BY + runtimeRollup.total_duration_microseconds DESC, + queryStoreQuery.query_id, + queryStorePlan.plan_id;"; + + private const string WaitStatisticsSql = @" +-- Wait statistics are collected independently so unavailable wait capture does not suppress the slow-query lines. +;WITH WaitsByCategory AS +( + SELECT + waitStatistics.plan_id, + waitStatistics.wait_category_desc, + SUM(CONVERT(float, waitStatistics.total_query_wait_time_ms)) AS total_wait_milliseconds + FROM sys.query_store_wait_stats AS waitStatistics + INNER JOIN sys.query_store_runtime_stats_interval AS runtimeStatisticsInterval + ON waitStatistics.runtime_stats_interval_id = runtimeStatisticsInterval.runtime_stats_interval_id + WHERE runtimeStatisticsInterval.end_time >= @StartTime + AND waitStatistics.execution_type = 0 -- regular completed executions only + AND waitStatistics.plan_id IN + ( + SELECT CONVERT(bigint, [value]) + FROM STRING_SPLIT(@PlanIds, ',') + ) + GROUP BY waitStatistics.plan_id, waitStatistics.wait_category_desc +), +RankedWaits AS +( + SELECT + plan_id, + SUM(total_wait_milliseconds) OVER (PARTITION BY plan_id) AS total_wait_milliseconds, + wait_category_desc, + ROW_NUMBER() OVER + ( + PARTITION BY plan_id + ORDER BY total_wait_milliseconds DESC, wait_category_desc + ) AS wait_category_rank + FROM WaitsByCategory +) +SELECT plan_id, total_wait_milliseconds, wait_category_desc +FROM RankedWaits +WHERE wait_category_rank = 1;"; + + private const string QueryPlansSql = @" +SELECT plan_id, query_plan +FROM sys.query_store_plan +WHERE plan_id IN +( + SELECT CONVERT(bigint, [value]) + FROM STRING_SPLIT(@PlanIds, ',') +);"; + + private const string StatisticsHealthSql = @" +SELECT TOP (@Top) + SCHEMA_NAME(queryObject.schema_id) AS schema_name, + queryObject.name AS table_name, + statisticsObject.name AS statistics_name, + TODATETIMEOFFSET(statisticsProperties.last_updated, '+00:00') AS last_updated, + statisticsProperties.rows, + statisticsProperties.rows_sampled, + statisticsProperties.modification_counter, + CASE + WHEN statisticsProperties.rows IS NULL OR statisticsProperties.rows = 0 THEN NULL + ELSE CONVERT(float, statisticsProperties.modification_counter) * 100.0 / statisticsProperties.rows + END AS modification_percent, + statisticsObject.auto_created, + statisticsObject.user_created, + CONVERT(bit, CASE WHEN queryIndex.index_id IS NULL THEN 0 ELSE 1 END) AS is_from_index, + statisticsObject.has_filter +-- 'statistics' is a RESERVED T-SQL keyword and cannot be used as a table alias, which is why sys.stats is +-- aliased statisticsObject rather than statistics. +FROM sys.stats AS statisticsObject +INNER JOIN sys.objects AS queryObject + ON statisticsObject.object_id = queryObject.object_id +INNER JOIN sys.tables AS queryTable + ON queryObject.object_id = queryTable.object_id +LEFT JOIN sys.indexes AS queryIndex + ON statisticsObject.object_id = queryIndex.object_id + AND statisticsObject.stats_id = queryIndex.index_id +OUTER APPLY sys.dm_db_stats_properties(statisticsObject.object_id, statisticsObject.stats_id) AS statisticsProperties +WHERE queryObject.is_ms_shipped = 0 + AND queryObject.type = 'U' + AND queryTable.temporal_type <> 1 -- exclude temporal history tables +ORDER BY + CASE + WHEN statisticsProperties.rows IS NULL OR statisticsProperties.rows = 0 THEN NULL + ELSE CONVERT(float, statisticsProperties.modification_counter) / statisticsProperties.rows + END DESC, + statisticsProperties.modification_counter DESC, + SCHEMA_NAME(queryObject.schema_id), + queryObject.name, + statisticsObject.name;"; + + private readonly QueryStoreDiagnosticsConfiguration _configuration; + private readonly ILogger _logger; + private readonly ISqlRetryService _sqlRetryService; + + // The validated collection interval and lease renewal interval, resolved from configuration once at + // construction. Held separately from the PeriodSec and LeasePeriodSec properties because the base class + // overwrites those properties with the values it reads back out of dbo.Parameters during initialization; + // InitAdditionalParamsAsync reconciles the table and the properties back to these fields so configuration + // stays authoritative. + private readonly double _effectivePeriodSec; + private readonly double _effectiveLeasePeriodSec; + + // The run-window state observed on the previous tick, used to log only when the state changes. Null until the + // first observation, so that the state a process starts in is always reported once and an operator never has + // to infer "the window has not opened yet" from the absence of collection logs. Ticks of a given watchdog + // instance are sequential — FhirTimer awaits each RunWorkAsync before the next tick — so this needs no + // synchronization. + private RunWindowState? _lastRunWindowState; + + public QueryStoreDiagnosticsWatchdog( + ISqlRetryService sqlRetryService, + ILogger logger, + IOptions watchdogConfiguration) + : base(sqlRetryService, logger) + { + _sqlRetryService = EnsureArg.IsNotNull(sqlRetryService, nameof(sqlRetryService)); + _logger = EnsureArg.IsNotNull(logger, nameof(logger)); + _configuration = EnsureArg.IsNotNull(watchdogConfiguration?.Value, nameof(watchdogConfiguration)).QueryStoreDiagnostics; + + // PeriodSec reaches PeriodicTimer through the base class timer (Watchdog.ExecuteAsync -> + // FhirTimer.ExecuteAsync -> new PeriodicTimer(TimeSpan.FromSeconds(PeriodSec))), which rejects a + // non-positive period. That rejection is not contained: it faults this watchdog's task, and + // WatchdogsBackgroundService cancels the token shared by every watchdog as soon as one of their tasks + // completes — so a single mistyped value in an off-by-default diagnostics feature would still take the + // transaction and cleanup watchdogs down with it. A diagnostics feature degrades instead of failing the + // host: keep the class default and name the rejected value. Non-finite values are rejected on the same + // grounds, because TimeSpan.FromSeconds rejects them for the same reason and with the same blast radius. + if (_configuration.PeriodSec > 0 && double.IsFinite(_configuration.PeriodSec)) + { + _effectivePeriodSec = _configuration.PeriodSec; + } + else + { + _effectivePeriodSec = DefaultPeriodSec; + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: configured PeriodSec is {ConfiguredPeriodSec}, which is not a usable collection interval. Falling back to {FallbackPeriodSec} seconds. Configure a positive value in '{PeriodSecConfigurationKey}' to change the interval.", + _configuration.PeriodSec, + DefaultPeriodSec, + PeriodSecConfigurationKey); + } + + // The lease renewal interval reaches PeriodicTimer through the base class the same way the period does, + // and a non-positive or non-finite value faults the watchdog with the same shared-token blast radius, so + // it is validated identically and falls back to the class default rather than failing the host. + if (_configuration.LeasePeriodSec > 0 && double.IsFinite(_configuration.LeasePeriodSec)) + { + _effectiveLeasePeriodSec = _configuration.LeasePeriodSec; + } + else + { + _effectiveLeasePeriodSec = DefaultLeasePeriodSec; + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: configured LeasePeriodSec is {ConfiguredLeasePeriodSec}, which is not a usable lease renewal interval. Falling back to {FallbackLeasePeriodSec} seconds. Configure a positive value in '{LeasePeriodSecConfigurationKey}' to change the interval.", + _configuration.LeasePeriodSec, + DefaultLeasePeriodSec, + LeasePeriodSecConfigurationKey); + } + + // Assigned here as well as in InitAdditionalParamsAsync so a unit test that never calls ExecuteAsync — + // and so never runs base initialization — still observes the configured values on these properties. + PeriodSec = _effectivePeriodSec; + LeasePeriodSec = _effectiveLeasePeriodSec; + } + + /// + /// Where the current time sits relative to the configured run window. Tracked between ticks so that the + /// skip is reported when it starts and stops rather than on every tick: at the default hourly period, a + /// window that opens in a month would otherwise produce around 720 identical lines before collecting anything. + /// + private enum RunWindowState + { + /// The window has a start and the current time has not reached it yet. + BeforeWindow, + + /// The current time is inside the window, so collection proceeds. + InWindow, + + /// The window has an end and the current time has reached or passed it. + AfterWindow, + } + + /// + /// Gets or sets the interval, in seconds, between collections. Overrides the base class property so the base + /// timer uses it; set from configuration at construction and reconciled back to configuration in + /// after the base class reads it out of dbo.Parameters. + /// + public override double PeriodSec { get; internal set; } + + /// + /// Gets or sets the lease renewal interval, in seconds. Overrides the base class property so the base lease + /// uses it; set from configuration at construction and reconciled back to configuration in + /// after the base class reads it out of dbo.Parameters. + /// + public override double LeasePeriodSec { get; internal set; } + + /// + /// Gets or sets a value indicating whether the lease may be handed to another replica to balance watchdogs + /// across a deployment. Matches what every other watchdog asks for. + /// + public override bool AllowRebalance { get; internal set; } = true; + + /// + /// Exposes RunWorkAsync for unit testing purposes. + /// + /// The cancellation token. + /// A task representing the asynchronous operation. + internal Task RunWorkForTestingAsync(CancellationToken cancellationToken) => RunWorkAsync(cancellationToken); + + /// + /// Reconciles the two dbo.Parameters rows the base class seeds — the period and the lease period — back + /// to configuration, and reports the configured run window. Runs after the base class has seeded those rows + /// and read them back over the configured values, and before the base class starts the timer, so the values + /// the timer and the lease run at are the configured ones. + /// + /// This override is the mechanism that keeps configuration authoritative. dbo.Parameters has + /// PRIMARY KEY CLUSTERED (Id) WITH (IGNORE_DUP_KEY = ON), so on a database that already holds these + /// rows the base class's seeding INSERT is a silent no-op — it neither inserts nor errors — and the + /// base class then reads the stale stored value back over the configured one. Without this override an + /// environment variable would be silently overridden by whatever was first stored. The UPDATE forces + /// the stored rows to the configured values, so the table stays an accurate mirror of configuration rather + /// than a misleading stale copy, and the properties are then re-assigned to undo the base class's read-back. + /// An UPDATE is used rather than an INSERT precisely because IGNORE_DUP_KEY would make a + /// re-INSERT a no-op; the base class's seeding INSERT already guarantees the rows exist by the + /// time this hook runs. + /// + /// + /// A failure of the reconciling UPDATE is reported and swallowed. This hook runs inside the base + /// class's initialization, before and outside the per-tick catch, so a throw here would fault this + /// watchdog's task and cause WatchdogsBackgroundService to cancel every other watchdog with it. The + /// property assignments that make configuration authoritative are therefore performed outside the try, so + /// that the functional guarantee does not depend on the cosmetic one. + /// + /// + /// A task representing the asynchronous operation. + protected override async Task InitAdditionalParamsAsync() + { + try + { + await using var cmd = new SqlCommand(ReconcileParametersSql); + cmd.Parameters.AddWithValue("@PeriodSecId", PeriodSecId); + cmd.Parameters.AddWithValue("@PeriodSec", _effectivePeriodSec); + cmd.Parameters.AddWithValue("@LeasePeriodSecId", LeasePeriodSecId); + cmd.Parameters.AddWithValue("@LeasePeriodSec", _effectiveLeasePeriodSec); + await cmd.ExecuteNonQueryAsync(_sqlRetryService, _logger, CancellationToken.None, "InitAdditionalParamsAsync failed."); + } + catch (Exception exception) + { + // Reported and swallowed rather than propagated, and deliberately so. This runs inside + // Watchdog.ExecuteAsync's initialization, which is before and outside FhirTimer's per-tick catch, + // so a throw here faults this watchdog's task — and WatchdogsBackgroundService cancels the token + // shared by EVERY watchdog as soon as one task completes. Letting an off-by-default diagnostics + // feature fail the transaction and cleanup watchdogs over a cosmetic row update is the wrong trade. + // Nothing about the collection depends on the update succeeding: the rows are a mirror of + // configuration, not an input to it, and the assignments below make configuration authoritative in + // this process whether or not the mirror was written. The cost of failure is a stale pair of rows + // that disagree with the running configuration, which is what this warning names. + _logger.LogWarning( + exception, + "{WatchdogName}: could not reconcile the {PeriodSecId} and {LeasePeriodSecId} rows in dbo.Parameters to the configured values. Collection is unaffected and continues to run at the configured period, but those rows may now disagree with configuration and should not be read as the values in use.", + Name, + PeriodSecId, + LeasePeriodSecId); + } + + // Undo the base class's read-back of the (now reconciled) stored values, so the properties match + // configuration exactly even if the UPDATE and a concurrent write were to race. + PeriodSec = _effectivePeriodSec; + LeasePeriodSec = _effectiveLeasePeriodSec; + + // Reported once per process rather than once per tick, and from here — after seeding, before the timer + // starts — because that is where the base class initialization lifecycle now provides a single hook. A + // mistyped window collects nothing and raises nothing, which is indistinguishable from a window that has + // simply not opened yet, so it has to be stated at startup; repeating it hourly for the weeks until the + // window was meant to open would bury it. + ReportConfiguredRunWindow(); + } + + /// + /// Reports the configured run window at startup: a window that can never open as a warning, and any + /// configured window as its effective UTC bounds. Exposed as internal only for unit testing. + /// + internal void ReportConfiguredRunWindow() + { + DateTimeOffset? runStartDate = _configuration.RunStartDate; + DateTimeOffset? runEndDate = _configuration.RunEndDate; + + if (runStartDate.HasValue && runEndDate.HasValue && runStartDate.Value >= runEndDate.Value) + { + // The end bound is exclusive, so a start equal to the end is as empty as a start after it, and neither + // is reachable by any clock value. Nothing downstream will ever complain, so this is the only place + // the mistake can surface. + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: the configured run window is empty because RunStartDate {RunStartDate} is not before RunEndDate {RunEndDate}, so no diagnostics will ever be collected. Set RunStartDate earlier than RunEndDate, or clear one of them.", + runStartDate.Value, + runEndDate.Value); + } + + if (runStartDate.HasValue || runEndDate.HasValue) + { + // Echoed in UTC on purpose: a value configured without an explicit offset is bound in the host's local + // timezone, and the configured text looks identical either way. Resolving it to a UTC instant here + // lets an operator who meant UTC catch the mistake immediately, rather than discovering it when the + // window silently opens hours late or, for a short window, not visibly at all. + _logger.LogInformation( + "QueryStoreDiagnosticsWatchdog: diagnostics collection is limited to a run window. In UTC it starts at {RunStartDateUtc} inclusive and ends at {RunEndDateUtc} exclusive, where an unset bound is unbounded. Current UTC time is {UtcNow}.", + runStartDate?.ToUniversalTime(), + runEndDate?.ToUniversalTime(), + DateTimeOffset.UtcNow); + } + } + + /// + /// Clamps the configured collection period into the supported lookback range, reporting what the clamp costs + /// when it changes the value. Takes the period as a parameter rather than reading + /// directly so that both clamp directions are reachable from a unit test. + /// Exposed as internal only for unit testing. + /// + /// The collection period this instance is running at. + /// The lookback window, in seconds, to use for this collection. + internal double GetLookbackPeriodSec(double configuredPeriodSec) + { + var lookbackPeriodSec = Math.Clamp(configuredPeriodSec, MinLookbackPeriodSec, MaxLookbackPeriodSec); + + // The tick interval is the configured period unclamped, so whenever the clamp bites the interval and the + // window it covers decouple permanently and silently — every tick after the first inherits the same gap + // or the same overlap. + if (lookbackPeriodSec < configuredPeriodSec) + { + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: the configured PeriodSec of {ConfiguredPeriodSec} seconds exceeds the maximum lookback window, so every collection looks back only {LookbackPeriodSec} seconds and {UnexaminedPeriodSec} seconds of each interval are never examined. Set '{PeriodSecConfigurationKey}' to at most {MaxLookbackPeriodSec} seconds.", + configuredPeriodSec, + lookbackPeriodSec, + configuredPeriodSec - lookbackPeriodSec, + PeriodSecConfigurationKey, + MaxLookbackPeriodSec); + } + else if (lookbackPeriodSec > configuredPeriodSec) + { + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: the configured PeriodSec of {ConfiguredPeriodSec} seconds is below the minimum lookback window, so every collection looks back {LookbackPeriodSec} seconds and consecutive collections overlap and re-report the same plans. Set '{PeriodSecConfigurationKey}' to at least {MinLookbackPeriodSec} seconds.", + configuredPeriodSec, + lookbackPeriodSec, + PeriodSecConfigurationKey, + MinLookbackPeriodSec); + } + + return lookbackPeriodSec; + } + + /// + /// Determines whether the supplied instant falls inside the configured run window, reporting the state only + /// when it changes. The instant is a parameter rather than read from the clock inside, for the same reason + /// takes the stored period as one: it is the only way to reach + /// every branch from a unit test without introducing a mockable clock abstraction for a single comparison. + /// Exposed as internal only for unit testing. + /// + /// The current time, supplied by the caller. + /// True when collection should proceed; false when the window has not opened or has closed. + internal bool IsWithinRunWindow(DateTimeOffset utcNow) + { + DateTimeOffset? runStartDate = _configuration.RunStartDate; + DateTimeOffset? runEndDate = _configuration.RunEndDate; + + // DateTimeOffset comparisons are made on the underlying UTC instant, so a bound configured with any offset + // — including one implied by the host's local timezone — compares correctly against a UTC clock reading + // without converting anything first. + RunWindowState state; + if (runStartDate.HasValue && utcNow < runStartDate.Value) + { + state = RunWindowState.BeforeWindow; + } + else if (runEndDate.HasValue && utcNow >= runEndDate.Value) + { + // The end bound is exclusive, so the instant that equals it is already outside. That also makes + // adjacent windows tile without overlapping. + state = RunWindowState.AfterWindow; + } + else + { + state = RunWindowState.InWindow; + } + + if (_lastRunWindowState != state) + { + _lastRunWindowState = state; + LogRunWindowState(state, runStartDate, runEndDate, utcNow); + } + + return state == RunWindowState.InWindow; + } + + /// + /// Emits the one line that explains why collection is or is not happening, on the tick where the run-window + /// state changed. + /// + /// The state that has just been entered. + /// The configured start bound, or null when unbounded. + /// The configured end bound, or null when unbounded. + /// The instant the state was observed at. + private void LogRunWindowState(RunWindowState state, DateTimeOffset? runStartDate, DateTimeOffset? runEndDate, DateTimeOffset utcNow) + { + // Information rather than warning throughout: a closed window is the feature working as configured, not a + // misconfiguration. Bounds are echoed in UTC so they can be compared against the current time at a glance + // without mentally applying whatever offset they were configured with. + switch (state) + { + case RunWindowState.BeforeWindow: + _logger.LogInformation( + "QueryStoreDiagnosticsWatchdog: the configured run window has not opened yet, so collection is skipped. It opens at {RunStartDateUtc} and the current UTC time is {UtcNow}.", + runStartDate?.ToUniversalTime(), + utcNow); + break; + + case RunWindowState.AfterWindow: + // Says explicitly that ticking continues, because the obvious reading of "the window has closed" + // is that the watchdog stopped, and someone would otherwise go looking for a process that died. + _logger.LogInformation( + "QueryStoreDiagnosticsWatchdog: the configured run window closed at {RunEndDateUtc} and the current UTC time is {UtcNow}, so collection is skipped. The watchdog keeps ticking and will collect again if the window is widened and the host restarted.", + runEndDate?.ToUniversalTime(), + utcNow); + break; + + default: + _logger.LogInformation( + "QueryStoreDiagnosticsWatchdog: collection is within the configured run window, which starts at {RunStartDateUtc} inclusive and ends at {RunEndDateUtc} exclusive in UTC, where an unset bound is unbounded. The current UTC time is {UtcNow}.", + runStartDate?.ToUniversalTime(), + runEndDate?.ToUniversalTime(), + utcNow); + break; + } + } + + protected override async Task RunWorkAsync(CancellationToken cancellationToken) + { + try + { + if (!_configuration.Enabled) + { + // Unreachable in the host as it stands: WatchdogsBackgroundService reads the same configuration + // snapshot and never starts this watchdog when the feature is off, and IOptions does not + // reload in place. It is kept because the watchdog is registered AsSelf and this is the only + // place the opt-out is enforced at the unit of work — any future call site that executes a + // collection directly would otherwise read Query Store on a deployment that opted out. One bool + // read per period is not a cost worth trading that away for. + _logger.LogInformation("QueryStoreDiagnosticsWatchdog is disabled by configuration. Exiting..."); + return; + } + + // One clock reading serves both the window decision and the collection window, so a tick that is + // admitted cannot then collect for an instant on the other side of its own boundary. + var collectionTime = DateTimeOffset.UtcNow; + if (!IsWithinRunWindow(collectionTime)) + { + // Deliberately a skipped tick rather than a shutdown, even once the end date has passed. Stopping + // would mean faulting or completing this watchdog's task, and WatchdogsBackgroundService cancels + // the token shared by EVERY watchdog as soon as one task completes — so self-terminating an + // off-by-default diagnostics feature would take the transaction and cleanup watchdogs down with + // it. PeriodSec and timer faults propagate the same way for the same reason. A clock comparison + // once an hour costs nothing; the alternative costs the host. + return; + } + + var lookbackPeriodSec = GetLookbackPeriodSec(PeriodSec); + var startTime = collectionTime.AddSeconds(-lookbackPeriodSec); + var queryStoreState = await GetQueryStoreStateAsync(cancellationToken); + if (queryStoreState == null) + { + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: sys.database_query_store_options returned no row, so Query Store is not configured on this database. Skipping collection."); + return; + } + + if (!string.Equals(queryStoreState.ActualState, "READ_WRITE", StringComparison.OrdinalIgnoreCase)) + { + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: Query Store is unavailable for diagnostics. State={QueryStoreState}, ReadonlyReason={ReadonlyReason}, ReadonlyReasonDescription={ReadonlyReasonDescription}", + queryStoreState.ActualState, + queryStoreState.ReadonlyReason, + DescribeReadonlyReason(queryStoreState.ReadonlyReason)); + return; + } + + await CollectDiagnosticsAsync(startTime, collectionTime, cancellationToken); + } + catch (SqlException ex) when (ex.Number == 208) + { + // This filter covers the whole method body rather than each read, which loses the ability to name the + // failing statement. That is the accepted trade-off: the watchdog only runs when an operator enabled + // it in configuration, so "the views you asked me to read do not exist" is always operator-actionable + // and permanent, and per-read catches would be more churn than value. + // Because the filter spans every read, the missing view can be the last one, after slow queries and + // plans have already been emitted; the message is therefore deliberately worded to be true of a + // partial tick as well as of one that emitted nothing. + _logger.LogWarning(ex, "QueryStoreDiagnosticsWatchdog: collection was aborted because a required Query Store or statistics view is unavailable. Any diagnostics already emitted during this collection were still logged."); + } + catch (SqlException ex) when (ex.Number == 229 || ex.Number == 262) + { + _logger.LogWarning(ex, "QueryStoreDiagnosticsWatchdog: SQL permissions do not allow diagnostics collection."); + } + } + + /// + /// Runs the collection itself, once the configuration, run-window and Query Store state gates have all + /// passed. Separated from so that the reads and the log lines they produce + /// are reachable from unit tests, and so that exception handling stays in one place in the caller. + /// + /// The start of the collection window. + /// The end of the collection window. + /// The cancellation token. + /// A task representing the asynchronous operation. + internal async Task CollectDiagnosticsAsync(DateTimeOffset startTime, DateTimeOffset collectionTime, CancellationToken cancellationToken) + { + IReadOnlyList slowQueries = Array.Empty(); + var waitStatisticsFailed = false; + if (_configuration.SlowQueryCount <= 0) + { + // Skipping the round-trip rather than running it with TOP (0) keeps this degenerate configuration + // reading the same way as the StatisticsHealthCount one below. + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: SlowQueryCount is {SlowQueryCount}, which disables slow-query collection. Configure a positive value to collect slow queries.", + _configuration.SlowQueryCount); + } + else + { + slowQueries = await GetSlowQueriesAsync(startTime, cancellationToken); + var waitStatistics = await GetWaitStatisticsAsync(startTime, slowQueries, cancellationToken); + waitStatisticsFailed = waitStatistics.Failed; + + foreach (var slowQuery in slowQueries) + { + waitStatistics.Waits.TryGetValue(slowQuery.PlanId, out var wait); + var queryText = slowQuery.QueryText; + var queryTextTruncated = queryText.Length > MaxFieldLength; + LogSlowQuery( + new SlowQueryDiagnostics + { + QueryId = slowQuery.QueryId, + PlanId = slowQuery.PlanId, + ExecutionCount = slowQuery.ExecutionCount, + TotalDurationMilliseconds = slowQuery.TotalDurationMilliseconds, + AverageDurationMilliseconds = slowQuery.AverageDurationMilliseconds, + MaxDurationMilliseconds = slowQuery.MaxDurationMilliseconds, + TotalCpuMilliseconds = slowQuery.TotalCpuMilliseconds, + AverageCpuMilliseconds = slowQuery.AverageCpuMilliseconds, + TotalLogicalReads = slowQuery.TotalLogicalReads, + AverageLogicalReads = slowQuery.AverageLogicalReads, + TotalWaitMilliseconds = wait?.TotalWaitMilliseconds, + AverageWaitMilliseconds = wait == null ? null : wait.TotalWaitMilliseconds / slowQuery.ExecutionCount, + TopWaitCategory = wait?.TopWaitCategory, + WaitStatisticsStatus = GetWaitStatisticsStatus(waitStatistics.Failed, wait), + QueryText = queryTextTruncated ? queryText.Substring(0, MaxFieldLength) : queryText, + QueryTextTruncated = queryTextTruncated, + QueryTextLength = queryText.Length, + IntervalStart = slowQuery.IntervalStart, + IntervalEnd = slowQuery.IntervalEnd, + }); + } + } + + var queryPlanCount = 0; + if (!_configuration.IncludeQueryPlans) + { + _logger.LogInformation("QueryStoreDiagnosticsWatchdog: query plan collection is turned off by configuration (IncludeQueryPlans)."); + } + else if (slowQueries.Count > 0) + { + queryPlanCount = await EmitQueryPlansAsync(slowQueries, cancellationToken); + } + + var statisticsHealthCount = 0; + if (!_configuration.IncludeStatisticsHealth) + { + _logger.LogInformation("QueryStoreDiagnosticsWatchdog: statistics health collection is turned off by configuration (IncludeStatisticsHealth)."); + } + else if (_configuration.StatisticsHealthCount <= 0) + { + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: StatisticsHealthCount is {StatisticsHealthCount}, which disables statistics health collection. Configure a positive value to collect statistics health.", + _configuration.StatisticsHealthCount); + } + else + { + statisticsHealthCount = await EmitStatisticsHealthAsync(cancellationToken); + } + + // A completed tick logs unconditionally, including zero counts: without this, "the watchdog has been + // dead for three days" and "there were no slow queries" are indistinguishable downstream. QueryPlans + // counts the plans that actually carried sanitized XML, so it is deliberately lower than SlowQueries + // whenever Query Store had no plan for a query or sanitization rejected one. + _logger.LogInformation( + "QueryStoreDiagnosticsWatchdog completed a collection. WindowStart={WindowStart}, WindowEnd={WindowEnd}, SlowQueries={SlowQueryCount}, QueryPlans={QueryPlanCount}, StatisticsHealth={StatisticsHealthCount}, WaitStatisticsFailed={WaitStatisticsFailed}", + startTime, + collectionTime, + slowQueries.Count, + queryPlanCount, + statisticsHealthCount, + waitStatisticsFailed); + } + + private async Task GetQueryStoreStateAsync(CancellationToken cancellationToken) + { + await using var command = new SqlCommand(QueryStoreStateSql); + + // Every diagnostics read binds to the primary: isReadOnly would route to a read-only secondary when + // SupportsSqlReplicas is on, and Query Store state is primary-scoped, so a secondary reports READ_ONLY + // and the state gate below would silently disable collection forever. Replica routing is also decided + // per call, so the state check and the data reads could otherwise land on different servers and produce + // torn results. The cost is negligible: one collection per period, hourly by default. + var states = await _sqlRetryService.ExecuteReaderAsync( + command, + reader => new QueryStoreState( + reader.IsDBNull(0) ? null : reader.GetString(0), + reader.IsDBNull(1) ? (int?)null : reader.GetInt32(1)), + _logger, + "Failed to read Query Store state", + cancellationToken); + + return states.Count == 0 ? null : states[0]; + } + + private async Task> GetSlowQueriesAsync(DateTimeOffset startTime, CancellationToken cancellationToken) + { + await using var command = new SqlCommand(SlowQueriesSql); + var minDurationMilliseconds = Math.Max(0, _configuration.MinDurationMilliseconds); + if (_configuration.MinDurationMilliseconds < 0) + { + // Clamping to zero inverts the operator's intent — every query in the window becomes "slow" — so it + // is reported rather than absorbed, as its sibling thresholds already are. + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: MinDurationMilliseconds is {ConfiguredMinDurationMilliseconds}, which is negative and is being treated as {EffectiveMinDurationMilliseconds}, so every query in the collection window qualifies as slow. Configure a non-negative value.", + _configuration.MinDurationMilliseconds, + minDurationMilliseconds); + } + + command.Parameters.Add("@StartTime", SqlDbType.DateTimeOffset).Value = startTime; + command.Parameters.Add("@Top", SqlDbType.Int).Value = Math.Max(0, _configuration.SlowQueryCount); + command.Parameters.Add("@MinDurationMilliseconds", SqlDbType.Int).Value = minDurationMilliseconds; + + return await _sqlRetryService.ExecuteReaderAsync( + command, + reader => new SlowQueryResult + { + QueryId = reader.GetInt64(0), + PlanId = reader.GetInt64(1), + ExecutionCount = reader.GetInt64(2), + TotalDurationMilliseconds = reader.GetDouble(3), + AverageDurationMilliseconds = reader.GetDouble(4), + MaxDurationMilliseconds = reader.GetDouble(5), + TotalCpuMilliseconds = reader.GetDouble(6), + AverageCpuMilliseconds = reader.GetDouble(7), + TotalLogicalReads = reader.GetDouble(8), + AverageLogicalReads = reader.GetDouble(9), + QueryText = reader.IsDBNull(10) ? string.Empty : reader.GetString(10), + IntervalStart = reader.GetDateTimeOffset(11), + IntervalEnd = reader.GetDateTimeOffset(12), + }, + _logger, + "Failed to read Query Store slow queries", + cancellationToken); + } + + private async Task<(Dictionary Waits, bool Failed)> GetWaitStatisticsAsync( + DateTimeOffset startTime, + IReadOnlyList slowQueries, + CancellationToken cancellationToken) + { + if (slowQueries.Count == 0) + { + return (new Dictionary(), false); + } + + try + { + await using var command = new SqlCommand(WaitStatisticsSql); + command.Parameters.Add("@StartTime", SqlDbType.DateTimeOffset).Value = startTime; + command.Parameters.Add("@PlanIds", SqlDbType.NVarChar, -1).Value = string.Join(',', slowQueries.Select(query => query.PlanId)); + + var waits = await _sqlRetryService.ExecuteReaderAsync( + command, + reader => new WaitStatistics( + reader.GetInt64(0), + reader.GetDouble(1), + reader.IsDBNull(2) ? null : reader.GetString(2)), + _logger, + "Failed to read Query Store wait statistics", + cancellationToken); + + return (waits.ToDictionary(wait => wait.PlanId), false); + } + catch (SqlException ex) + { + // SqlException is caught broadly on purpose: a transient wait-query failure must never abort the tick + // and suppress the runtime statistics, which are the primary signal. The cost of that breadth is + // that timeouts, deadlocks, permission denials and missing views all look alike here, so the failure + // is logged as a warning and surfaced on every slow-query line as WaitStatisticsStatus = Failed. + _logger.LogWarning(ex, "QueryStoreDiagnosticsWatchdog: Query Store wait statistics could not be read for this collection. Wait fields will be empty."); + return (new Dictionary(), true); + } + } + + private async Task EmitQueryPlansAsync(IReadOnlyList slowQueries, CancellationToken cancellationToken) + { + await using var command = new SqlCommand(QueryPlansSql); + command.Parameters.Add("@PlanIds", SqlDbType.NVarChar, -1).Value = string.Join(',', slowQueries.Select(query => query.PlanId)); + + var plans = await _sqlRetryService.ExecuteReaderAsync( + command, + reader => (PlanId: reader.GetInt64(0), QueryPlanXml: reader.IsDBNull(1) ? null : reader.GetString(1)), + _logger, + "Failed to read Query Store plans", + cancellationToken); + + // Keyed by plan id and holding the plan XML itself: a plan with no row and a plan whose row carries NULL + // XML both yield null here, which is exactly what the sanitizer reports as PlanXmlUnavailable. + var plansById = plans.ToDictionary(plan => plan.PlanId, plan => plan.QueryPlanXml); + var emittedPlanCount = 0; + + foreach (var slowQuery in slowQueries) + { + plansById.TryGetValue(slowQuery.PlanId, out var queryPlan); + var sanitizedPlan = QueryPlanSanitizer.Sanitize(queryPlan, MaxFieldLength); + if (!string.Equals(sanitizedPlan.Status, QueryPlanSanitizer.SanitizedStatus, StringComparison.Ordinal)) + { + // Without this, systematic sanitizer breakage looks exactly like "plans are simply unavailable" + // unless whoever is reading the plan lines happens to look at SanitizationStatus. + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: query plan was not emitted because sanitization did not succeed. PlanId={PlanId}, SanitizationStatus={SanitizationStatus}", + slowQuery.PlanId, + sanitizedPlan.Status); + } + + LogQueryPlan( + new QueryPlanDiagnostics + { + QueryId = slowQuery.QueryId, + PlanId = slowQuery.PlanId, + SanitizedQueryPlan = sanitizedPlan.Xml, + QueryPlanTruncated = sanitizedPlan.Truncated, + OriginalQueryPlanLength = sanitizedPlan.OriginalLength, + SanitizedQueryPlanLength = sanitizedPlan.SanitizedLength, + SanitizationStatus = sanitizedPlan.Status, + }); + + // A line is emitted for every slow query, including the ones with no usable plan, but only the ones + // that carried XML are counted: a count that always equalled the slow-query count would tell an + // operator nothing about whether plans are actually arriving. + if (sanitizedPlan.Xml != null) + { + emittedPlanCount++; + } + } + + return emittedPlanCount; + } + + private async Task EmitStatisticsHealthAsync(CancellationToken cancellationToken) + { + await using var command = new SqlCommand(StatisticsHealthSql); + command.Parameters.Add("@Top", SqlDbType.Int).Value = _configuration.StatisticsHealthCount; + + // The reader projects straight into the emitted payload shape: an intermediate DTO here would be a + // property-for-property copy of it and nothing else. + var statisticsHealth = await _sqlRetryService.ExecuteReaderAsync( + command, + reader => new StatisticsHealthDiagnostics + { + SchemaName = reader.GetString(0), + TableName = reader.GetString(1), + StatisticsName = reader.GetString(2), + LastUpdated = reader.IsDBNull(3) ? (DateTimeOffset?)null : reader.GetDateTimeOffset(3), + Rows = reader.IsDBNull(4) ? (long?)null : reader.GetInt64(4), + RowsSampled = reader.IsDBNull(5) ? (long?)null : reader.GetInt64(5), + ModificationCounter = reader.IsDBNull(6) ? (long?)null : reader.GetInt64(6), + ModificationPercent = reader.IsDBNull(7) ? (double?)null : reader.GetDouble(7), + IsAutoCreated = reader.GetBoolean(8), + IsUserCreated = reader.GetBoolean(9), + IsFromIndex = reader.GetBoolean(10), + HasFilter = reader.GetBoolean(11), + }, + _logger, + "Failed to read statistics health", + cancellationToken); + + LogStatisticsHealthBatches(statisticsHealth); + + return statisticsHealth.Count; + } + + /// + /// Emits the collected statistics rows as JSON batches, one log line per page. Batched where the slow-query + /// and plan payloads are not because these rows are small, uniform and free of free text, so a batch has a + /// predictable size; a batch of plan XML could not make that promise and would risk one oversized record. + /// The cost of batching is that the rows are a serialized blob rather than queryable columns, which is + /// affordable here precisely because the fields are uniform and cheap to re-parse. Exposed as internal only + /// for unit testing. + /// + /// The collected rows, already capped at StatisticsHealthCount. + internal void LogStatisticsHealthBatches(IReadOnlyList statisticsHealth) + { + if (statisticsHealth.Count == 0) + { + // No line at all rather than an empty page: the collection summary already reports a count of zero, + // and a page carrying nothing would only make the emitted pages harder to count. + return; + } + + var batchSize = _configuration.StatisticsHealthBatchSize; + if (batchSize <= 0) + { + // Unlike the counts, this one cannot degrade to collecting nothing — the rows have already been read + // and dropping them would lose diagnostics an operator asked for — so it falls back to the default + // and names the rejected value, the way an unusable PeriodSec does. + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: StatisticsHealthBatchSize is {ConfiguredStatisticsHealthBatchSize}, which cannot pack a row. Falling back to {FallbackStatisticsHealthBatchSize} rows per log line. Configure a positive value to change the batch size.", + batchSize, + DefaultStatisticsHealthBatchSize); + batchSize = DefaultStatisticsHealthBatchSize; + } + else if (batchSize > MaxStatisticsHealthBatchSize) + { + // Clamped rather than honoured, because the failure this prevents is not a smaller page but a single + // record large enough for a sink to truncate or reject, which would lose the rows entirely. Paging + // costs extra lines, and lines are the cheap thing here. + _logger.LogWarning( + "QueryStoreDiagnosticsWatchdog: StatisticsHealthBatchSize is {ConfiguredStatisticsHealthBatchSize}, which risks a log record too large for the sink to accept. Using {MaxStatisticsHealthBatchSize} rows per log line instead. All rows are still emitted, across more pages.", + batchSize, + MaxStatisticsHealthBatchSize); + batchSize = MaxStatisticsHealthBatchSize; + } + + var pageCount = ((statisticsHealth.Count - 1) / batchSize) + 1; + for (var page = 0; page < pageCount; page++) + { + var pageRows = statisticsHealth.Skip(page * batchSize).Take(batchSize).ToList(); + + // Page number, page count and total row count travel on every line so that a reader can tell a + // partial last page from a set that was cut short by a host that died mid-collection. + _logger.LogInformation( + "QueryStoreDiagnosticsWatchdog statistics health. StatisticsHealthPage={StatisticsHealthPage}, StatisticsHealthPageCount={StatisticsHealthPageCount}, StatisticsHealthPageRowCount={StatisticsHealthPageRowCount}, StatisticsHealthRowCount={StatisticsHealthRowCount}, StatisticsHealthRows={StatisticsHealthRows}", + page + 1, + pageCount, + pageRows.Count, + statisticsHealth.Count, + JsonSerializer.Serialize(pageRows)); + } + } + + /// + /// Emits one slow query as a single structured line. Every field is its own named property rather than a + /// serialized document, so each one lands as a queryable column downstream; at the default of ten rows a + /// tick, a line per row costs nothing worth batching for. + /// + /// The diagnostics to emit. + private void LogSlowQuery(SlowQueryDiagnostics slowQuery) + { + // QueryText is last because it is the one unbounded field on the line, so everything an operator scans + // for is still readable ahead of it. DiagnosticsTimestamp rather than Timestamp, because that name + // collides with the ingestion timestamp the log pipeline supplies for every record. + _logger.LogInformation( + "QueryStoreDiagnosticsWatchdog slow query. QueryId={QueryId}, PlanId={PlanId}, ExecutionCount={ExecutionCount}, TotalDurationMilliseconds={TotalDurationMilliseconds}, AverageDurationMilliseconds={AverageDurationMilliseconds}, MaxDurationMilliseconds={MaxDurationMilliseconds}, TotalCpuMilliseconds={TotalCpuMilliseconds}, AverageCpuMilliseconds={AverageCpuMilliseconds}, TotalLogicalReads={TotalLogicalReads}, AverageLogicalReads={AverageLogicalReads}, TotalWaitMilliseconds={TotalWaitMilliseconds}, AverageWaitMilliseconds={AverageWaitMilliseconds}, TopWaitCategory={TopWaitCategory}, WaitStatisticsStatus={WaitStatisticsStatus}, QueryTextTruncated={QueryTextTruncated}, QueryTextLength={QueryTextLength}, IntervalStart={IntervalStart}, IntervalEnd={IntervalEnd}, DiagnosticsTimestamp={DiagnosticsTimestamp}, QueryText={QueryText}", + slowQuery.QueryId, + slowQuery.PlanId, + slowQuery.ExecutionCount, + slowQuery.TotalDurationMilliseconds, + slowQuery.AverageDurationMilliseconds, + slowQuery.MaxDurationMilliseconds, + slowQuery.TotalCpuMilliseconds, + slowQuery.AverageCpuMilliseconds, + slowQuery.TotalLogicalReads, + slowQuery.AverageLogicalReads, + slowQuery.TotalWaitMilliseconds, + slowQuery.AverageWaitMilliseconds, + slowQuery.TopWaitCategory, + slowQuery.WaitStatisticsStatus, + slowQuery.QueryTextTruncated, + slowQuery.QueryTextLength, + slowQuery.IntervalStart, + slowQuery.IntervalEnd, + slowQuery.Timestamp, + slowQuery.QueryText); + } + + /// + /// Emits one query plan as a single structured line. Not batched with its neighbours: the sanitized XML is + /// capped at the field length rather than being small, so packing several into one record would risk a + /// single oversized log row. + /// + /// The diagnostics to emit. + private void LogQueryPlan(QueryPlanDiagnostics queryPlan) + { + _logger.LogInformation( + "QueryStoreDiagnosticsWatchdog query plan. QueryId={QueryId}, PlanId={PlanId}, SanitizationStatus={SanitizationStatus}, QueryPlanTruncated={QueryPlanTruncated}, OriginalQueryPlanLength={OriginalQueryPlanLength}, SanitizedQueryPlanLength={SanitizedQueryPlanLength}, DiagnosticsTimestamp={DiagnosticsTimestamp}, SanitizedQueryPlan={SanitizedQueryPlan}", + queryPlan.QueryId, + queryPlan.PlanId, + queryPlan.SanitizationStatus, + queryPlan.QueryPlanTruncated, + queryPlan.OriginalQueryPlanLength, + queryPlan.SanitizedQueryPlanLength, + queryPlan.Timestamp, + queryPlan.SanitizedQueryPlan); + } + + /// + /// Decodes the sys.database_query_store_options.readonly_reason bitmask into a readable reason list, + /// so an operator sees the cause rather than an integer to look up. Exposed as internal only for unit testing. + /// + /// The bitmask value, or null when no value was reported. + /// A comma-separated description of the set bits. + internal static string DescribeReadonlyReason(int? readonlyReason) + { + // Every bit this method knows how to name. An unrecognized bit is reported rather than dropped, so a + // state flag introduced by a newer SQL Server reaches the operator instead of vanishing behind whichever + // documented bits happened to be set alongside it. + const int knownReasonMask = 1 | 2 | 4 | 8 | 65536 | 131072; + + if (readonlyReason == null) + { + return "not reported"; + } + + if (readonlyReason.Value == 0) + { + return "none"; + } + + var reasons = new List(); + if ((readonlyReason.Value & 1) != 0) + { + reasons.Add("database is in read-only mode"); + } + + if ((readonlyReason.Value & 2) != 0) + { + reasons.Add("database is in single-user mode"); + } + + if ((readonlyReason.Value & 4) != 0) + { + reasons.Add("database is in emergency mode"); + } + + if ((readonlyReason.Value & 8) != 0) + { + reasons.Add("database is a secondary replica"); + } + + if ((readonlyReason.Value & 65536) != 0) + { + reasons.Add("Query Store has reached its size limit (MAX_STORAGE_SIZE_MB)"); + } + + if ((readonlyReason.Value & 131072) != 0) + { + reasons.Add("Query Store has reached the limit on the number of statements"); + } + + if (reasons.Count == 0) + { + return "unrecognized reason"; + } + + var unrecognizedBits = readonlyReason.Value & ~knownReasonMask; + if (unrecognizedBits != 0) + { + reasons.Add(FormattableString.Invariant($"unrecognized reason bits {unrecognizedBits} (readonly_reason = {readonlyReason.Value})")); + } + + return string.Join(", ", reasons); + } + + private static string GetWaitStatisticsStatus(bool waitStatisticsFailed, WaitStatistics wait) + { + if (waitStatisticsFailed) + { + return WaitStatisticsFailedStatus; + } + + return wait == null ? WaitStatisticsUnavailableStatus : WaitStatisticsAvailableStatus; + } + + internal sealed class SlowQueryResult + { + internal long QueryId { get; set; } + + internal long PlanId { get; set; } + + internal long ExecutionCount { get; set; } + + internal double TotalDurationMilliseconds { get; set; } + + internal double AverageDurationMilliseconds { get; set; } + + internal double MaxDurationMilliseconds { get; set; } + + internal double TotalCpuMilliseconds { get; set; } + + internal double AverageCpuMilliseconds { get; set; } + + internal double TotalLogicalReads { get; set; } + + internal double AverageLogicalReads { get; set; } + + internal string QueryText { get; set; } + + internal DateTimeOffset IntervalStart { get; set; } + + internal DateTimeOffset IntervalEnd { get; set; } + } + + private sealed class QueryStoreState + { + // Trap: sys.database_query_store_options.readonly_reason is int, NOT bigint, even though the neighbouring + // Query Store columns this watchdog reads (query_id, plan_id, SUM(count_executions), rows, rows_sampled, + // modification_counter) genuinely are bigint. Reading it with GetInt64 compiles and only fails at runtime + // with InvalidCastException, so it must be read with GetInt32 and held as int. + internal QueryStoreState(string actualState, int? readonlyReason) + { + ActualState = actualState; + ReadonlyReason = readonlyReason; + } + + internal string ActualState { get; } + + internal int? ReadonlyReason { get; } + } + + internal sealed class WaitStatistics + { + internal WaitStatistics(long planId, double totalWaitMilliseconds, string topWaitCategory) + { + PlanId = planId; + TotalWaitMilliseconds = totalWaitMilliseconds; + TopWaitCategory = topWaitCategory; + } + + internal long PlanId { get; } + + internal double TotalWaitMilliseconds { get; } + + internal string TopWaitCategory { get; } + } + } +} diff --git a/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/WatchdogsBackgroundService.cs b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/WatchdogsBackgroundService.cs index 867c30cdb9..178a30d3fc 100644 --- a/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/WatchdogsBackgroundService.cs +++ b/src/Microsoft.Health.Fhir.SqlServer/Features/Watchdogs/WatchdogsBackgroundService.cs @@ -17,6 +17,7 @@ using Microsoft.Health.Fhir.Core.Features.Operations; using Microsoft.Health.Fhir.Core.Messages.Search; using Microsoft.Health.Fhir.Core.Messages.Storage; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics; namespace Microsoft.Health.Fhir.SqlServer.Features.Watchdogs { @@ -29,6 +30,7 @@ internal class WatchdogsBackgroundService : BackgroundService, INotificationHand private readonly InvisibleHistoryCleanupWatchdog _invisibleHistoryCleanupWatchdog; private readonly ExpiredResourceCleanupWatchdog _expiredResourceCleanupWatchdog; private readonly GeoReplicationLagWatchdog _geoReplicationLagWatchdog; + private readonly QueryStoreDiagnosticsWatchdog _queryStoreDiagnosticsWatchdog; private readonly JobMonitorWatchdog _jobMonitorWatchdog; private readonly CoreFeatureConfiguration _coreFeatureConfiguration; private readonly WatchdogConfiguration _watchdogConfiguration; @@ -40,6 +42,7 @@ public WatchdogsBackgroundService( InvisibleHistoryCleanupWatchdog invisibleHistoryCleanupWatchdog, ExpiredResourceCleanupWatchdog expiredResourceCleanupWatchdog, GeoReplicationLagWatchdog geoReplicationLagWatchdog, + QueryStoreDiagnosticsWatchdog queryStoreDiagnosticsWatchdog, JobMonitorWatchdog jobMonitorWatchdog, IOptions coreFeatureConfiguration, IOptions watchdogConfiguration) @@ -50,6 +53,7 @@ public WatchdogsBackgroundService( _invisibleHistoryCleanupWatchdog = EnsureArg.IsNotNull(invisibleHistoryCleanupWatchdog, nameof(invisibleHistoryCleanupWatchdog)); _expiredResourceCleanupWatchdog = EnsureArg.IsNotNull(expiredResourceCleanupWatchdog, nameof(expiredResourceCleanupWatchdog)); _geoReplicationLagWatchdog = geoReplicationLagWatchdog; // Can be null when feature is disabled + _queryStoreDiagnosticsWatchdog = EnsureArg.IsNotNull(queryStoreDiagnosticsWatchdog, nameof(queryStoreDiagnosticsWatchdog)); _jobMonitorWatchdog = EnsureArg.IsNotNull(jobMonitorWatchdog, nameof(jobMonitorWatchdog)); _coreFeatureConfiguration = EnsureArg.IsNotNull(coreFeatureConfiguration?.Value, nameof(coreFeatureConfiguration)); _watchdogConfiguration = EnsureArg.IsNotNull(watchdogConfiguration?.Value, nameof(watchdogConfiguration)); @@ -90,6 +94,11 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) tasks.Add(_expiredResourceCleanupWatchdog.ExecuteAsync(continuationTokenSource.Token)); } + if (_watchdogConfiguration.QueryStoreDiagnostics.Enabled) + { + tasks.Add(_queryStoreDiagnosticsWatchdog.ExecuteAsync(continuationTokenSource.Token)); + } + await Task.WhenAny(tasks); if (!stoppingToken.IsCancellationRequested) diff --git a/src/Microsoft.Health.Fhir.SqlServer/Registration/FhirServerBuilderSqlServerRegistrationExtensions.cs b/src/Microsoft.Health.Fhir.SqlServer/Registration/FhirServerBuilderSqlServerRegistrationExtensions.cs index 12fe9334b3..17c3bc5ebf 100644 --- a/src/Microsoft.Health.Fhir.SqlServer/Registration/FhirServerBuilderSqlServerRegistrationExtensions.cs +++ b/src/Microsoft.Health.Fhir.SqlServer/Registration/FhirServerBuilderSqlServerRegistrationExtensions.cs @@ -37,6 +37,7 @@ using Microsoft.Health.Fhir.SqlServer.Features.Storage; using Microsoft.Health.Fhir.SqlServer.Features.Storage.Registry; using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics; using Microsoft.Health.Fhir.SqlServer.Registration; using Microsoft.Health.JobManagement; using Microsoft.Health.SqlServer.Api.Registration; @@ -209,6 +210,7 @@ public static IFhirServerBuilder AddSqlServer(this IFhirServerBuilder fhirServer services.Add().Singleton().AsSelf(); services.Add().Singleton().AsSelf(); services.Add().Singleton().AsSelf(); + services.Add().Singleton().AsSelf(); services.Add().Singleton().AsSelf(); services.Add().Scoped().AsSelf(); services.AddFactory>(); diff --git a/test/Microsoft.Health.Fhir.Shared.Tests.Integration/Microsoft.Health.Fhir.Shared.Tests.Integration.projitems b/test/Microsoft.Health.Fhir.Shared.Tests.Integration/Microsoft.Health.Fhir.Shared.Tests.Integration.projitems index 368f7a10da..f743ed567f 100644 --- a/test/Microsoft.Health.Fhir.Shared.Tests.Integration/Microsoft.Health.Fhir.Shared.Tests.Integration.projitems +++ b/test/Microsoft.Health.Fhir.Shared.Tests.Integration/Microsoft.Health.Fhir.Shared.Tests.Integration.projitems @@ -28,6 +28,7 @@ + diff --git a/test/Microsoft.Health.Fhir.Shared.Tests.Integration/Persistence/QueryStoreDiagnosticsWatchdogTests.cs b/test/Microsoft.Health.Fhir.Shared.Tests.Integration/Persistence/QueryStoreDiagnosticsWatchdogTests.cs new file mode 100644 index 0000000000..a8e08e15ab --- /dev/null +++ b/test/Microsoft.Health.Fhir.Shared.Tests.Integration/Persistence/QueryStoreDiagnosticsWatchdogTests.cs @@ -0,0 +1,674 @@ +// ------------------------------------------------------------------------------------------------- +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. +// ------------------------------------------------------------------------------------------------- + +using System; +using System.Collections.Generic; +using System.Data; +using System.Diagnostics; +using System.Linq; +using System.Text.Json; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Data.SqlClient; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Microsoft.Health.Fhir.Core.Configs; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics; +using Microsoft.Health.Fhir.SqlServer.Features.Watchdogs.QueryStoreDiagnostics.Models; +using Microsoft.Health.Fhir.Tests.Common; +using Microsoft.Health.Fhir.Tests.Common.FixtureParameters; +using Microsoft.Health.Test.Utilities; +using Xunit; + +namespace Microsoft.Health.Fhir.Tests.Integration.Persistence +{ + [FhirStorageTestsFixtureArgumentSets(DataStore.SqlServer)] + [Trait(Traits.OwningTeam, OwningTeam.Fhir)] + [Trait(Traits.Category, Categories.DataSourceValidation)] + public class QueryStoreDiagnosticsWatchdogTests : IClassFixture + { + private const int QueryExecutionCount = 2; + private const int QueryStorePollAttempts = 15; + + // The probe table's row count at the point its statistics are updated, and the number of rows inserted + // afterwards. They are deliberately different from each other and from any other value asserted below, so a + // reordering of the positionally read statistics columns cannot go unnoticed. + private const int ProbeTableRowCount = 200; + private const int ProbeTableModificationCount = 5; + + // Wall-clock timing on the client is coarser than Query Store's own measurement, and the first execution pays + // for compilation, so the upper bound gets a fixed allowance on top of the measured elapsed time. + private const double ProbeTimingToleranceMilliseconds = 5000; + + private static readonly TimeSpan QueryStorePollInterval = TimeSpan.FromSeconds(1); + private readonly SqlServerFhirStorageTestsFixture _fixture; + + public QueryStoreDiagnosticsWatchdogTests(SqlServerFhirStorageTestsFixture fixture) + { + _fixture = fixture; + } + + [Fact] + public async Task GivenEnabledWatchdogAndCapturedProbe_WhenRun_ThenLogsSlowQuerySanitizedPlanAndStatisticsHealth() + { + // Arrange + var logger = new CapturingLogger(); + var watchdog = CreateWatchdog(logger, enabled: true); + string tableName = $"DiagProbe_{Guid.NewGuid():N}"; + + // Query Store does not preserve comments in query_sql_text, so the probe cannot be tagged with a marker + // comment. A GUID-derived result-column alias is preserved and makes the probe query self-identifying. + string queryAlias = $"probe_{Guid.NewGuid():N}"; + + await using SqlConnection connection = await _fixture.SqlConnectionBuilder.GetSqlConnectionAsync(cancellationToken: CancellationToken.None); + await connection.OpenAsync(CancellationToken.None); + + try + { + await EnableAndVerifyQueryStoreAsync(connection, CancellationToken.None); + await CreateProbeTableAsync(connection, tableName, CancellationToken.None); + double probeElapsedMilliseconds = await ExecuteProbeQueryAsync(connection, tableName, queryAlias, CancellationToken.None); + await WaitForQueryStoreCaptureAsync(connection, queryAlias, CancellationToken.None); + await PrepareStatisticsProbeAsync(connection, tableName, CancellationToken.None); + + // Act + await watchdog.RunWorkForTestingAsync(CancellationToken.None); + + // Assert + // The probe query is grouped by plan_id, and a recompile between executions would produce a second + // plan and therefore a second log line. That is a legitimate outcome, so the assertions are on the + // whole matching set: what must hold is that the executions add up. + List probeSlowQueries = logger.SlowQueries + .Where(slowQuery => slowQuery.QueryText.Contains(queryAlias, StringComparison.Ordinal)) + .ToList(); + Assert.NotEmpty(probeSlowQueries); + + // The probe runs a fixed number of times under a GUID alias, so the rollup across Query Store + // intervals and plans must sum to exactly that count. + Assert.Equal((long)QueryExecutionCount, probeSlowQueries.Sum(slowQuery => slowQuery.ExecutionCount)); + + // Query Store records microseconds and the contract is milliseconds. The probe runs at MAXDOP 1 and + // is timed on the client, so the reported totals must sit inside the wall clock plus a tolerance. A + // missing /1000.0 would inflate these by three orders of magnitude and break the upper bound; a + // doubly applied one would sink them below MinDurationMilliseconds and the query would never appear. + double durationUpperBoundMilliseconds = probeElapsedMilliseconds + ProbeTimingToleranceMilliseconds; + foreach (SlowQueryDiagnostics slowQuery in probeSlowQueries) + { + Assert.True(slowQuery.QueryId > 0); + Assert.True(slowQuery.PlanId > 0); + Assert.True(slowQuery.QueryTextLength > 0); + Assert.True(slowQuery.ExecutionCount > 0); + + Assert.InRange(slowQuery.TotalDurationMilliseconds, 1, durationUpperBoundMilliseconds); + Assert.InRange(slowQuery.AverageDurationMilliseconds, 1, durationUpperBoundMilliseconds); + Assert.InRange(slowQuery.MaxDurationMilliseconds, 1, durationUpperBoundMilliseconds); + + // The probe is a three-way cross join at MAXDOP 1, so its CPU is provably non-trivial: a lower + // bound of zero would let a regression that zeroed CPU entirely pass. + Assert.InRange(slowQuery.TotalCpuMilliseconds, 1, durationUpperBoundMilliseconds); + Assert.InRange(slowQuery.AverageCpuMilliseconds, 1, durationUpperBoundMilliseconds); + + // Query Store stores per-interval averages, so the emitted average must be the count-weighted + // one rather than an unweighted mean across intervals. + Assert.Equal(slowQuery.TotalDurationMilliseconds / slowQuery.ExecutionCount, slowQuery.AverageDurationMilliseconds, 3); + Assert.Equal(slowQuery.TotalCpuMilliseconds / slowQuery.ExecutionCount, slowQuery.AverageCpuMilliseconds, 3); + Assert.True(slowQuery.TotalLogicalReads > 0); + + // Wait collection is best-effort and its failure is swallowed so that the runtime statistics + // are still emitted. A status other than Failed is therefore the only proof that the wait SQL + // executed. + Assert.Contains( + slowQuery.WaitStatisticsStatus, + new[] { QueryStoreDiagnosticsWatchdog.WaitStatisticsAvailableStatus, QueryStoreDiagnosticsWatchdog.WaitStatisticsUnavailableStatus }); + if (string.Equals(slowQuery.WaitStatisticsStatus, QueryStoreDiagnosticsWatchdog.WaitStatisticsAvailableStatus, StringComparison.Ordinal)) + { + Assert.NotNull(slowQuery.TotalWaitMilliseconds); + Assert.NotNull(slowQuery.AverageWaitMilliseconds); + Assert.False(string.IsNullOrEmpty(slowQuery.TopWaitCategory)); + } + else + { + Assert.Null(slowQuery.TotalWaitMilliseconds); + } + + QueryPlanDiagnostics queryPlan = Assert.Single( + logger.QueryPlans, + plan => plan.QueryId == slowQuery.QueryId && plan.PlanId == slowQuery.PlanId); + Assert.Equal(QueryPlanSanitizer.SanitizedStatus, queryPlan.SanitizationStatus); + Assert.NotNull(queryPlan.SanitizedQueryPlan); + } + + AssertStatisticsHealthOrdinals(logger, tableName); + + foreach (SlowQueryDiagnostics slowQuery in logger.SlowQueries) + { + Assert.DoesNotContain("query_store", slowQuery.QueryText, StringComparison.OrdinalIgnoreCase); + Assert.DoesNotContain("dm_db_stats_properties", slowQuery.QueryText, StringComparison.OrdinalIgnoreCase); + } + } + finally + { + await DropProbeTableAsync(connection, tableName, CancellationToken.None); + } + } + + [Fact] + public async Task GivenConfigurationGateDisabled_WhenRun_ThenNothingIsEmitted() + { + // Arrange + var logger = new CapturingLogger(); + var watchdog = CreateWatchdog(logger, enabled: false); + + // Act + await watchdog.RunWorkForTestingAsync(CancellationToken.None); + + // Assert + Assert.Empty(logger.SlowQueries); + Assert.Empty(logger.QueryPlans); + Assert.Empty(logger.StatisticsHealthPages); + + // Asserted alongside the absence of diagnostics, because a tick that collected nothing for some other + // reason — Query Store unavailable, say — would satisfy the assertions above just as well. + Assert.Contains( + logger.Messages, + message => message.Contains("QueryStoreDiagnosticsWatchdog is disabled by configuration", StringComparison.Ordinal)); + } + + [Fact] + public async Task GivenExistingStaleParameterRows_WhenTheWatchdogInitialises_ThenTheRowsAreReconciledToConfiguration() + { + // Arrange + // The feature now derives from Watchdog, so it accepts the two dbo.Parameters rows the base class + // seeds for its period and lease period. The owner's condition is that those rows stay settable from + // configuration, which only a live database can demonstrate: dbo.Parameters carries IGNORE_DUP_KEY, so + // the base class's seeding INSERT is a silent no-op when the rows already exist and the base class then + // reads the stored value back over the configured one. Without the InitAdditionalParamsAsync override the + // stale row below would win; with it, configuration wins. + const double configuredPeriodSec = 1; + const double configuredLeasePeriodSec = 123; + const double staleValue = 999999; + + var logger = new CapturingLogger(); + + // A one-second period keeps the randomized start-up delay inside the test's own budget. Base + // initialization runs to completion under CancellationToken.None before the timer starts, so the rows are + // reconciled regardless of when the token below trips. + var watchdog = CreateWatchdog(logger, enabled: true, periodSec: configuredPeriodSec, leasePeriodSec: configuredLeasePeriodSec); + + await using SqlConnection connection = await _fixture.SqlConnectionBuilder.GetSqlConnectionAsync(cancellationToken: CancellationToken.None); + await connection.OpenAsync(CancellationToken.None); + + // Start from a known state, then plant stale rows so the assertion proves reconciliation rather than a + // first-time seed. These are exactly the rows a database that ran an earlier configuration would hold. + await DeleteWatchdogParametersAsync(connection, CancellationToken.None); + await SeedWatchdogParameterAsync(connection, "QueryStoreDiagnosticsWatchdog.PeriodSec", staleValue, CancellationToken.None); + await SeedWatchdogParameterAsync(connection, "QueryStoreDiagnosticsWatchdog.LeasePeriodSec", staleValue, CancellationToken.None); + + using var cancellationTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(5)); + + // Act + try + { + await watchdog.ExecuteAsync(cancellationTokenSource.Token); + } + catch (OperationCanceledException) + { + // Expected whenever the token trips while a randomized start-up delay or a tick is pending, which is + // the usual case. Cancelling between ticks instead returns normally, so neither outcome is asserted on. + } + + // Assert + // Both rows exist and hold the configured values, not the stale ones — the UPDATE in the override forced + // the table to mirror configuration. Number is SQL float (IEEE-754 double), so exact equality is correct + // here and no epsilon tolerance is warranted. + Assert.Equal(2, await CountWatchdogParametersAsync(connection, CancellationToken.None)); + Assert.Equal(configuredPeriodSec, await ReadWatchdogParameterAsync(connection, "QueryStoreDiagnosticsWatchdog.PeriodSec", CancellationToken.None)); + Assert.Equal(configuredLeasePeriodSec, await ReadWatchdogParameterAsync(connection, "QueryStoreDiagnosticsWatchdog.LeasePeriodSec", CancellationToken.None)); + } + + private static void AssertStatisticsHealthOrdinals(CapturingLogger logger, string probeTableName) + { + // Every column of the statistics-health read is taken positionally from a hand-written SELECT list that + // no compiler checks, so two same-typed columns could be reordered and every value would silently swap. + // The probe table is set up so that its statistics carry values that differ from one another, which pins + // those ordinals: a swap would have to preserve every one of these values to go unnoticed. + List statisticsHealth = logger.StatisticsHealth; + Assert.NotEmpty(statisticsHealth); + + AssertStatisticsHealthPagination(logger, statisticsHealth.Count); + + StatisticsHealthDiagnostics probeIndexStatistics = Assert.Single( + statisticsHealth, + row => + string.Equals(row.SchemaName, "dbo", StringComparison.Ordinal) + && string.Equals(row.TableName, probeTableName, StringComparison.Ordinal) + && string.Equals(row.StatisticsName, $"PK_{probeTableName}", StringComparison.Ordinal)); + + // The probe table holds ProbeTableRowCount rows at the point its statistics were updated with a full + // scan, and exactly ProbeTableModificationCount rows were added afterwards, so every numeric column has + // a known and distinct value rather than a coincidentally equal one. + Assert.NotNull(probeIndexStatistics.LastUpdated); + Assert.NotNull(probeIndexStatistics.Rows); + Assert.NotNull(probeIndexStatistics.RowsSampled); + Assert.NotNull(probeIndexStatistics.ModificationCounter); + Assert.Equal((long)ProbeTableRowCount, probeIndexStatistics.Rows.Value); + Assert.Equal((long)ProbeTableRowCount, probeIndexStatistics.RowsSampled.Value); + Assert.Equal((long)ProbeTableModificationCount, probeIndexStatistics.ModificationCounter.Value); + Assert.NotNull(probeIndexStatistics.ModificationPercent); + Assert.Equal(ProbeTableModificationCount * 100.0 / ProbeTableRowCount, probeIndexStatistics.ModificationPercent.Value, 6); + + // Statistics backed by an index report is_from_index, and nothing else. + Assert.True(probeIndexStatistics.IsFromIndex); + Assert.False(probeIndexStatistics.IsAutoCreated); + Assert.False(probeIndexStatistics.IsUserCreated); + Assert.False(probeIndexStatistics.HasFilter); + + // A standalone CREATE STATISTICS object reports user_created, and nothing else, which separates that + // flag from the three bit columns adjacent to it. + StatisticsHealthDiagnostics probeUserStatistics = Assert.Single( + statisticsHealth, + row => + string.Equals(row.SchemaName, "dbo", StringComparison.Ordinal) + && string.Equals(row.TableName, probeTableName, StringComparison.Ordinal) + && string.Equals(row.StatisticsName, $"ST_{probeTableName}", StringComparison.Ordinal)); + Assert.True(probeUserStatistics.IsUserCreated); + Assert.False(probeUserStatistics.IsFromIndex); + Assert.False(probeUserStatistics.IsAutoCreated); + Assert.False(probeUserStatistics.HasFilter); + + // A real FHIR table is asserted on as well, so that the scan is not merely finding the table this test + // created. This index is filtered, which is what separates has_filter from is_from_index. + StatisticsHealthDiagnostics filteredIndexStatistics = Assert.Single( + statisticsHealth, + row => + string.Equals(row.SchemaName, "dbo", StringComparison.Ordinal) + && string.Equals(row.TableName, "Resource", StringComparison.Ordinal) + && string.Equals(row.StatisticsName, "IX_Resource_ResourceTypeId_ResourceId", StringComparison.Ordinal)); + Assert.True(filteredIndexStatistics.HasFilter); + Assert.True(filteredIndexStatistics.IsFromIndex); + Assert.False(filteredIndexStatistics.IsAutoCreated); + Assert.False(filteredIndexStatistics.IsUserCreated); + } + + private static void AssertStatisticsHealthPagination(CapturingLogger logger, int expectedRowCount) + { + // The schema carries far more statistics objects than one batch holds, so a live collection exercises + // pagination rather than only the single-page case the unit tests pin. What is asserted here is that the + // pages an operator would read describe the set they actually cover. + IReadOnlyList pages = logger.StatisticsHealthPages; + Assert.NotEmpty(pages); + Assert.Equal(Enumerable.Range(1, pages.Count).ToList(), pages.Select(page => page.PageNumber).ToList()); + Assert.All(pages, page => Assert.Equal(pages.Count, page.PageCount)); + Assert.All(pages, page => Assert.Equal(expectedRowCount, page.RowCount)); + Assert.Equal(expectedRowCount, pages.Sum(page => page.Rows.Count)); + } + + private QueryStoreDiagnosticsWatchdog CreateWatchdog(ILogger logger, bool enabled, double periodSec = 300, double leasePeriodSec = 600) + { + var configuration = new WatchdogConfiguration(); + configuration.QueryStoreDiagnostics.Enabled = enabled; + configuration.QueryStoreDiagnostics.PeriodSec = periodSec; + configuration.QueryStoreDiagnostics.LeasePeriodSec = leasePeriodSec; + configuration.QueryStoreDiagnostics.SlowQueryCount = 100; + configuration.QueryStoreDiagnostics.MinDurationMilliseconds = 1; + configuration.QueryStoreDiagnostics.IncludeQueryPlans = true; + configuration.QueryStoreDiagnostics.IncludeStatisticsHealth = true; + + // High enough to cover every statistics object in the FHIR schema, so that the assertions on named + // statistics do not depend on where the staleness ordering happens to place them. + configuration.QueryStoreDiagnostics.StatisticsHealthCount = 5000; + + // Left at the default so that a live collection, which reads far more statistics objects than one batch + // holds, exercises the pagination rather than packing everything onto a single line. + configuration.QueryStoreDiagnostics.StatisticsHealthBatchSize = new QueryStoreDiagnosticsConfiguration().StatisticsHealthBatchSize; + + return new QueryStoreDiagnosticsWatchdog( + _fixture.SqlRetryService, + logger, + Options.Create(configuration)); + } + + private static async Task EnableAndVerifyQueryStoreAsync(SqlConnection connection, CancellationToken cancellationToken) + { + string initialState = await GetQueryStoreStateAsync(connection, cancellationToken); + if (!string.Equals(initialState, "READ_WRITE", StringComparison.OrdinalIgnoreCase)) + { + await ExecuteNonQueryAsync(connection, "ALTER DATABASE CURRENT SET QUERY_STORE = ON;", cancellationToken); + } + + await ExecuteNonQueryAsync( + connection, + "ALTER DATABASE CURRENT SET QUERY_STORE (OPERATION_MODE = READ_WRITE, QUERY_CAPTURE_MODE = ALL, WAIT_STATS_CAPTURE_MODE = ON);", + cancellationToken); + + Assert.Equal("READ_WRITE", await GetQueryStoreStateAsync(connection, cancellationToken), ignoreCase: true); + } + + private static async Task GetQueryStoreStateAsync(SqlConnection connection, CancellationToken cancellationToken) + { + await using SqlCommand command = connection.CreateCommand(); + command.CommandText = "SELECT actual_state_desc FROM sys.database_query_store_options;"; + return (string)await command.ExecuteScalarAsync(cancellationToken); + } + + private static async Task DeleteWatchdogParametersAsync(SqlConnection connection, CancellationToken cancellationToken) + { + await using SqlCommand command = connection.CreateCommand(); + command.CommandText = "DELETE FROM dbo.Parameters WHERE Id LIKE 'QueryStoreDiagnosticsWatchdog%';"; + await command.ExecuteNonQueryAsync(cancellationToken); + } + + private static async Task CountWatchdogParametersAsync(SqlConnection connection, CancellationToken cancellationToken) + { + // Matched by prefix rather than by the two names the watchdog seeds, so a row this feature has no + // business creating is caught whatever it is called. + await using SqlCommand command = connection.CreateCommand(); + command.CommandText = "SELECT COUNT(*) FROM dbo.Parameters WHERE Id LIKE 'QueryStoreDiagnosticsWatchdog%';"; + return Convert.ToInt32(await command.ExecuteScalarAsync(cancellationToken)); + } + + private static async Task SeedWatchdogParameterAsync(SqlConnection connection, string id, double number, CancellationToken cancellationToken) + { + await using SqlCommand command = connection.CreateCommand(); + command.CommandText = "INSERT INTO dbo.Parameters (Id, Number) VALUES (@Id, @Number);"; + command.Parameters.AddWithValue("@Id", id); + command.Parameters.AddWithValue("@Number", number); + await command.ExecuteNonQueryAsync(cancellationToken); + } + + private static async Task ReadWatchdogParameterAsync(SqlConnection connection, string id, CancellationToken cancellationToken) + { + // Number is SQL float, which reads back as a .NET double, so the value is returned unboxed as one and + // compared for exact equality by the caller — no epsilon, because float equality is exactly what the + // reconciliation guarantees. + await using SqlCommand command = connection.CreateCommand(); + command.CommandText = "SELECT Number FROM dbo.Parameters WHERE Id = @Id;"; + command.Parameters.AddWithValue("@Id", id); + return (double)await command.ExecuteScalarAsync(cancellationToken); + } + + private static async Task CreateProbeTableAsync(SqlConnection connection, string tableName, CancellationToken cancellationToken) + { + // The primary key is named explicitly so that the statistics object it backs has a predictable name to + // assert on; an unnamed constraint would get a generated one. + await ExecuteNonQueryAsync( + connection, + $"CREATE TABLE dbo.[{tableName}] (Id int NOT NULL CONSTRAINT [PK_{tableName}] PRIMARY KEY); INSERT INTO dbo.[{tableName}] (Id) SELECT TOP ({ProbeTableRowCount}) ROW_NUMBER() OVER (ORDER BY (SELECT NULL)) FROM sys.all_objects;", + cancellationToken); + } + + private static async Task PrepareStatisticsProbeAsync(SqlConnection connection, string tableName, CancellationToken cancellationToken) + { + // A full-scan update fixes rows and rows_sampled at the current row count and sets last_updated; the + // rows inserted afterwards then fix modification_counter at a different, known value. Without this the + // table's statistics have never been updated and dm_db_stats_properties reports nulls throughout, which + // asserts nothing about which column was read. + string commandText = $@" +UPDATE STATISTICS dbo.[{tableName}] WITH FULLSCAN; +CREATE STATISTICS [ST_{tableName}] ON dbo.[{tableName}] (Id) WITH FULLSCAN; +INSERT INTO dbo.[{tableName}] (Id) SELECT TOP ({ProbeTableModificationCount}) {ProbeTableRowCount} + ROW_NUMBER() OVER (ORDER BY (SELECT NULL)) FROM sys.all_objects;"; + + await ExecuteNonQueryAsync(connection, commandText, cancellationToken); + } + + private static async Task DropProbeTableAsync(SqlConnection connection, string tableName, CancellationToken cancellationToken) + { + await ExecuteNonQueryAsync(connection, $"DROP TABLE IF EXISTS dbo.[{tableName}];", cancellationToken); + } + + private static async Task ExecuteProbeQueryAsync(SqlConnection connection, string tableName, string queryAlias, CancellationToken cancellationToken) + { + // MAXDOP 1 keeps CPU time comparable with elapsed time, so the millisecond assertions have a meaningful + // upper bound rather than one inflated by an unknown degree of parallelism. + var stopwatch = Stopwatch.StartNew(); + for (int execution = 0; execution < QueryExecutionCount; execution++) + { + await using SqlCommand command = connection.CreateCommand(); + command.CommandText = $"SELECT SUM(CONVERT(bigint, firstProbe.Id) * secondProbe.Id * thirdProbe.Id) AS [{queryAlias}] FROM dbo.[{tableName}] AS firstProbe CROSS JOIN dbo.[{tableName}] AS secondProbe CROSS JOIN dbo.[{tableName}] AS thirdProbe OPTION (MAXDOP 1);"; + object result = await command.ExecuteScalarAsync(cancellationToken); + Assert.NotNull(result); + } + + stopwatch.Stop(); + return stopwatch.Elapsed.TotalMilliseconds; + } + + private static async Task WaitForQueryStoreCaptureAsync(SqlConnection connection, string queryAlias, CancellationToken cancellationToken) + { + for (int attempt = 0; attempt < QueryStorePollAttempts; attempt++) + { + await ExecuteNonQueryAsync(connection, "EXEC sys.sp_query_store_flush_db;", cancellationToken); + + await using SqlCommand command = connection.CreateCommand(); + + // Wait for every execution to be persisted, not merely the first, so the execution-count assertion + // cannot race the flush. + command.CommandText = @" +SELECT ISNULL(SUM(runtimeStats.count_executions), 0) +FROM sys.query_store_runtime_stats AS runtimeStats +INNER JOIN sys.query_store_plan AS queryPlan + ON runtimeStats.plan_id = queryPlan.plan_id +INNER JOIN sys.query_store_query AS queryStoreQuery + ON queryPlan.query_id = queryStoreQuery.query_id +INNER JOIN sys.query_store_query_text AS queryText + ON queryStoreQuery.query_text_id = queryText.query_text_id +WHERE queryText.query_sql_text LIKE @QueryTextPattern + AND runtimeStats.execution_type = 0;"; + command.Parameters.Add("@QueryTextPattern", SqlDbType.NVarChar, 256).Value = $"%{queryAlias}%"; + + long capturedExecutionCount = Convert.ToInt64(await command.ExecuteScalarAsync(cancellationToken)); + if (capturedExecutionCount >= QueryExecutionCount) + { + return; + } + + await Task.Delay(QueryStorePollInterval, cancellationToken); + } + + Assert.Fail("Query Store did not persist regular runtime statistics for every execution of the GUID-alias probe query after the supported flush and polling window."); + } + + private static async Task ExecuteNonQueryAsync(SqlConnection connection, string commandText, CancellationToken cancellationToken) + { + await using SqlCommand command = connection.CreateCommand(); + command.CommandText = commandText; + await command.ExecuteNonQueryAsync(cancellationToken); + } + + /// + /// Reassembles the emitted diagnostics from what the watchdog logged. The named properties of each line are + /// read back into the payload type they were taken from, and the statistics batches are deserialized from + /// the JSON they are carried in, so the assertions are statements about what a reader of these logs would + /// actually be able to recover. + /// + private sealed class CapturingLogger : ILogger + { + private const string SlowQueryPrefix = "QueryStoreDiagnosticsWatchdog slow query."; + private const string QueryPlanPrefix = "QueryStoreDiagnosticsWatchdog query plan."; + private const string StatisticsHealthPrefix = "QueryStoreDiagnosticsWatchdog statistics health."; + + // The lease and the timer log from their own tasks while a collection is running, so the capture has to + // tolerate concurrent writers even though the collection itself is sequential. + private readonly object _syncRoot = new object(); + private readonly List _messages = new List(); + private readonly List _slowQueries = new List(); + private readonly List _queryPlans = new List(); + private readonly List _statisticsHealthPages = new List(); + + internal IReadOnlyList Messages + { + get + { + lock (_syncRoot) + { + return _messages.ToList(); + } + } + } + + internal IReadOnlyList SlowQueries + { + get + { + lock (_syncRoot) + { + return _slowQueries.ToList(); + } + } + } + + internal IReadOnlyList QueryPlans + { + get + { + lock (_syncRoot) + { + return _queryPlans.ToList(); + } + } + } + + internal IReadOnlyList StatisticsHealthPages + { + get + { + lock (_syncRoot) + { + return _statisticsHealthPages.ToList(); + } + } + } + + internal List StatisticsHealth => + StatisticsHealthPages.SelectMany(page => page.Rows).ToList(); + + public IDisposable BeginScope(TState state) + where TState : notnull + => NoOpDisposable.Instance; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + string message = formatter(state, exception); + IReadOnlyDictionary properties = ToProperties(state as IReadOnlyList>); + + lock (_syncRoot) + { + _messages.Add(message); + + if (message.StartsWith(SlowQueryPrefix, StringComparison.Ordinal)) + { + _slowQueries.Add(ToSlowQuery(properties)); + } + else if (message.StartsWith(QueryPlanPrefix, StringComparison.Ordinal)) + { + _queryPlans.Add(ToQueryPlan(properties)); + } + else if (message.StartsWith(StatisticsHealthPrefix, StringComparison.Ordinal)) + { + _statisticsHealthPages.Add(ToStatisticsHealthPage(properties)); + } + } + } + + private static IReadOnlyDictionary ToProperties(IReadOnlyList> state) + { + var properties = new Dictionary(StringComparer.Ordinal); + foreach (KeyValuePair property in state ?? Array.Empty>()) + { + // Assigned rather than added, because a template is free to repeat a placeholder and this + // capture must not throw on a line it merely passes through. + properties[property.Key] = property.Value; + } + + return properties; + } + + private static SlowQueryDiagnostics ToSlowQuery(IReadOnlyDictionary properties) => + new SlowQueryDiagnostics + { + QueryId = (long)properties["QueryId"], + PlanId = (long)properties["PlanId"], + ExecutionCount = (long)properties["ExecutionCount"], + TotalDurationMilliseconds = (double)properties["TotalDurationMilliseconds"], + AverageDurationMilliseconds = (double)properties["AverageDurationMilliseconds"], + MaxDurationMilliseconds = (double)properties["MaxDurationMilliseconds"], + TotalCpuMilliseconds = (double)properties["TotalCpuMilliseconds"], + AverageCpuMilliseconds = (double)properties["AverageCpuMilliseconds"], + TotalLogicalReads = (double)properties["TotalLogicalReads"], + AverageLogicalReads = (double)properties["AverageLogicalReads"], + TotalWaitMilliseconds = (double?)properties["TotalWaitMilliseconds"], + AverageWaitMilliseconds = (double?)properties["AverageWaitMilliseconds"], + TopWaitCategory = (string)properties["TopWaitCategory"], + WaitStatisticsStatus = (string)properties["WaitStatisticsStatus"], + QueryText = (string)properties["QueryText"], + QueryTextTruncated = (bool)properties["QueryTextTruncated"], + QueryTextLength = (int)properties["QueryTextLength"], + IntervalStart = (DateTimeOffset)properties["IntervalStart"], + IntervalEnd = (DateTimeOffset)properties["IntervalEnd"], + Timestamp = (DateTimeOffset)properties["DiagnosticsTimestamp"], + }; + + private static QueryPlanDiagnostics ToQueryPlan(IReadOnlyDictionary properties) => + new QueryPlanDiagnostics + { + QueryId = (long)properties["QueryId"], + PlanId = (long)properties["PlanId"], + SanitizedQueryPlan = (string)properties["SanitizedQueryPlan"], + QueryPlanTruncated = (bool)properties["QueryPlanTruncated"], + OriginalQueryPlanLength = (int)properties["OriginalQueryPlanLength"], + SanitizedQueryPlanLength = (int)properties["SanitizedQueryPlanLength"], + SanitizationStatus = (string)properties["SanitizationStatus"], + Timestamp = (DateTimeOffset)properties["DiagnosticsTimestamp"], + }; + + private static StatisticsHealthPage ToStatisticsHealthPage(IReadOnlyDictionary properties) => + new StatisticsHealthPage( + (int)properties["StatisticsHealthPage"], + (int)properties["StatisticsHealthPageCount"], + (int)properties["StatisticsHealthRowCount"], + JsonSerializer.Deserialize>((string)properties["StatisticsHealthRows"])); + + internal sealed class StatisticsHealthPage + { + internal StatisticsHealthPage(int pageNumber, int pageCount, int rowCount, List rows) + { + PageNumber = pageNumber; + PageCount = pageCount; + RowCount = rowCount; + Rows = rows; + } + + /// Gets the 1-based page number this line carried. + internal int PageNumber { get; } + + /// Gets the number of pages the collection was emitted across. + internal int PageCount { get; } + + /// Gets the total number of rows collected, across every page. + internal int RowCount { get; } + + /// Gets the rows carried on this page, deserialized from the batch property. + internal List Rows { get; } + } + + /// + /// A scope that does nothing on dispose. The base class's InitParamsAsync opens a timed logging scope + /// through BeginTimedScope, whose ActionTimer dereferences the value BeginScope returns when it is + /// disposed; a real logger returns a non-null scope, so this test double must too. + /// + private sealed class NoOpDisposable : IDisposable + { + internal static readonly NoOpDisposable Instance = new NoOpDisposable(); + + public void Dispose() + { + } + } + } + } +}