`SlowQueryMonitor` cannot see the queries it exists to report. Found while tryin…g to diagnose #7127, where the reporter set `--long-database-query-threshold` to one minute, watched a query run for five, and got no warning.
This does not fix #7127. See "About #7127" at the end for what I measured there.
## The problem
The monitor itself is fine. It is a periodic sweep that reports queries **still running** (`SlowQueryMonitor.cs`, the timer and `CheckSlowQueries`), so a query that never finishes is exactly what it is built to catch.
But registration only happens inside the extension methods in `Database/ExtensionMethods.cs`, and none of their `ExecuteReaderAsync` overloads takes a lone `CancellationToken`. So a call written as
```csharp
await cmd.ExecuteReaderAsync(token)
```
binds to `SqliteCommand`'s **own** method and is never registered. `ExecuteNonQueryAsync` and `ExecuteScalarAsync` have the same problem via `DbCommand`. **122 call sites** were in that shape: 80 readers, 36 non-queries, 6 scalars.
`WriteFilesetAsync` — where #7127 hangs — is one of them, which is why no threshold could ever have produced a warning there.
**Adding an overload that matches the bare shape would not help**, because an applicable instance method always wins over an extension method. There is a proof of that in the file already: the four-argument `ExecuteScalarAsync` calls `self.ExecuteScalarAsync(cancellationToken)`, which would be an unbounded recursion if the extension were picked. It is not, so the instance method wins — and the single-argument `ExecuteScalarAsync` extension was therefore unreachable dead code. Removed.
So the call has to name the overload it wants.
## Shape
Four commits, so the guard can be dropped on its own.
1. **Write down why the command's own methods must not be called** — remove the unreachable extension, put the recursion proof in the class docs, and record that the two `...PerformanceSensitiveAsync` methods skip the monitor *deliberately* (their callers are the per-block loops in the backup, where registering every statement would put a lock and a dictionary insert in the innermost loop). That bypass read like an oversight; now it says otherwise.
2. **Run the database queries through the monitored overload** — 122 sites, every hunk the same one-token edit inserting `writeLog: false`.
3. **The tests.**
4. **The guard.**
`writeLog: false` is behaviour-neutral: the overload forwards with a null command text and null values, both null-guarded, so the command text, parameters and transaction are untouched and the return type is unchanged. With `writeLog` false no profiling record is written and the printable command text is never built. The only difference is the registration. `writeLog: true` would have added two log records and a regex pass at all 122 sites.
The four non-queries that took no token at all now pass `default`, which is the token they already used.
## Tests
- **positive** — a query that runs longer than the threshold, executed through the monitored overload, produces the warning and the warning carries the sql
- **negative control** — the same query through the command's own method produces nothing. This is the executable proof of the shadowing rule, and it stays green even if someone later adds an extension matching the bare shape
Reverting the positive test's call to the bare shape makes **only that test** fail, so it tests what it claims to.
Three things about the setup are easy to get wrong and are commented in the code: the log scope has to be established *before* the monitor starts, because the scope lives in an `AsyncLocal` and the monitor reports from a `Timer` callback that captures the execution context when it is created (`Controller` does it in this order for the same reason); anything under a second is read as a request to disable monitoring, so the test asserts the monitor actually started; and the sink is a `ConcurrentQueue` because the timer thread writes while the test reads.
## The guard
`Microsoft.CodeAnalysis.BannedApiAnalyzers`, scoped to `Duplicati.Library.Main`, with `RS0030` set to error for that project in `.editorconfig`. Nothing in the language prevents the bare shape from returning by copy-paste, and a test that scans source text would be evadable by a local variable or a line break.
Worth noting: the analyzer flagged **exactly the seven calls inside `ExtensionMethods.cs`** — the layer that has to make them — and nothing else. That is an independent check, by the compiler rather than by my grep, that commit 2 missed nothing. That file disables the rule once with the reason rather than seven times.
**This is the first analyzer package in the repository**, so it is a separate commit. If you would rather not take it, drop commit 4; the rest stands on its own. The limitation is that it only covers `Library.Main` — the other callers of these methods are not monitored by design.
## Known limitation, not fixed here
On the monitored path the `QueryScope` is disposed when the reader is returned, so time spent in the caller's `ReadAsync` loop is still unmonitored. Only `ExecuteReaderEnumerableAsync` keeps the scope alive across the loop. It does not matter for #7127, where the time is spent in the first `sqlite3_step`, and fixing it properly means either returning a reader that owns the scope or moving callers to `ExecuteReaderEnumerableAsync` — both larger changes.
Also worth saying: the default threshold is 30 minutes, so reproduction instructions for a hang need `--long-database-query-threshold=10s` to get useful output quickly.
## Testing
- `--filter "Category=SQLite"`: 4 passed (2 existing, 2 new)
- reverting the positive test's call to the bare shape: 1 failed, 3 passed — the expected one
- `dotnet build Duplicati.slnx`: 0 errors
- `RS0030` violations outside `ExtensionMethods.cs`: 0
## About #7127
I could not reproduce it, and the hypothesis I went in with is refuted. Recording it here so the next person does not repeat the work.
The theory was that `PRAGMA optimize` (which runs at the end of every operation and is the only writer of `sqlite_stat1` in the tree) leaves statistics describing a nearly empty database after a small first backup, and that the second backup then plans `LIST_FOLDERS_AND_SYMLINKS` badly. To test it I built one database at the reporter's largest size — 1,111 folders / 11,110 files, the case reported as taking over an hour — and swapped the statistics underneath it, so the data was identical and only the statistics changed:
| statistics | FOLDERS_AND_SYMLINKS (1,111 rows) | FILESETS (11,110 rows) | `SCAN` steps |
| --- | --- | --- | --- |
| from the large backup | 0.054 s | 0.443 s | 0 |
| none at all | 0.048 s | 0.357 s | 0 |
| from the small backup | 0.065 s | 0.396 s | 0 |
Both queries in `WriteFilesetAsync` finish in well under a second in every configuration, and no plan contains a single `SCAN`. Also confirmed while there: `ENABLE_STAT4` is absent from this build of SQLite, so only `sqlite_stat1` exists.
I then ran the same scenario on all three CI operating systems, with this branch's monitored overloads and `--long-database-query-threshold=1s`:
| runner | small first backup | 11,110 files / 1,111 folders | third backup, unchanged | queries over 1 s |
| --- | --- | --- | --- | --- |
| windows-latest | 0.1 s | **15.2 s** | 3.7 s | **none** |
| macos-latest | 0.1 s | **16.9 s** | 2.3 s | **none** |
| ubuntu-latest | 0.1 s | **10.7 s** | 5.2 s | **none** |
The case reported as taking over an hour finishes in ten to seventeen seconds on every platform, and **not one query anywhere exceeded a single second**. The CI runners were faster than my own machine (81–130 s for the same backup), so machine speed does not explain it either.
What differs between my setup and the reporter's, as far as I know: my test files are at most 1 KiB with a 10 KiB blocksize, so `BlocklistHash` is empty on every run — though that only matters for the file query, and only for blocksets over ~3 MiB, so the reporter's small-file tree would have had none either; and I ran through the test fixture rather than a real install on Windows 10.
So #7127 stays open, and I have stopped guessing at it. **That is the argument for this PR.** Nobody outside the reporter's machine can reproduce it, and on that machine the one tool that would say which query is at fault has never been able to see it. With this PR in, `--long-database-query-threshold=10s` gives the query text and a running elapsed figure every ten seconds — the attribution that is currently impossible to obtain.
