Check query cancellation inside the row loop of formatQuery and friends - #113055
Check query cancellation inside the row loop of formatQuery and friends#113055groeneai wants to merge 19 commits into
Conversation
formatQuery, formatQueryOrNull, formatQuerySingleLine, formatQuerySingleLineOrNull, formatQueryFromJSON, parseQueryToJSON and fuzzQuery parse one row at a time inside a single pipeline task. Query cancellation is only polled between pipeline tasks: PipelineExecutor::cancel sets flags and cannot interrupt a task already running inside executeImpl. A whole block therefore ran to completion, so max_execution_time and KILL QUERY were silently ignored. Measured on a debug build with 200000 rows of moderate SQL text and max_execution_time = 1: the query stopped after 23 s instead of 1 s, and a KILL QUERY took 21 s to take effect. The server-side AST fuzzer pins max_block_size to 65409 and installs a 30 s cancel deadline, both per task, so one block outlives both; that is the Stress test (arm_msan) hung check where the stuck query reported is_cancelled = 1 next to elapsed = 1247 s. Obtain a QueryStatus via getProcessListElementSafe (some callers have no process-list entry, where the check stays a no-op) and call checkTimeLimit at the top of each per-row loop. This follows FunctionBaseXXConversion, which was fixed for the same bug class. checkTimeLimit throws for KILL QUERY and the throw overflow mode and returns false for break; a scalar has no meaningful partial result, so break is a hard stop here too. In formatQuery the check sits outside the existing try/catch: for ErrorHandling::Null that handler turns any exception into a NULL and continues, which would convert cancellation into wrong results instead of an error. The overhead is one clock_gettime plus a comparison per row, against a full SQL parse. Three runs of the 200000-row query without a time limit: 70.2/70.6/70.2 s before, 69.1/69.3/70.5 s after. The new test asserts the elapsed time rather than the error, because an unpatched server also raises TIMEOUT_EXCEEDED, just tens of seconds late.
…ting Review round 1 follow-up to the per-row cancellation poll. highlightQuery and tokenizeQuery are carriers of the same defect. Both register through FunctionQueryTokenization, whose row loop never polled cancellation, and highlightQuery runs a full ParserQuery parse per row. They are more exposed than the functions already covered: no setting gates them, and they build Tokens with max_query_size = 0, so per-row input length is unbounded. One poll in the shared loop covers both. The five copies of the check are replaced by one helper in FunctionHelpers, which needs no new include in the high-fan-out header because QueryStatusPtr is forward declared there. The test asserted elapsed time but could pass on an unpatched server: the runner randomizes max_block_size over 8000..100000, and a small block lets the uninterruptible unit finish under the threshold. Every timed query now pins max_block_size and max_threads per query, measured at 2995 ms unpinned versus 70909 ms pinned on the same unpatched binary. The oracle also counts the rows it found, so a marker that stopped matching can no longer make countIf() = 0 trivially true over an empty set, and it pins max_execution_time = 0 for its own query_log scan, which the session-wide limit would otherwise apply to. Two of the polls were unreachable from the old cases: fuzzQuery opts out of the default constant handling, so its ColumnConst loop needs a genuinely constant argument, and formatQueryFromJSON was masked by the inner parseQueryToJSON raising first. Both now have their own case. KILL QUERY is part of the contract and had no regression guard, so it gets a companion test. It refuses to pass blind: a KILL matching nothing returns immediately and would otherwise satisfy a latency bound without killing anything, so the test asserts the query reached system.processes and that KILL reported exactly one killed query.
The readiness loop waited for the query to appear in system.processes, but ProcessList publishes the entry before the pipeline executor is attached, and QueryStatus::addPipelineExecutor calls throwProperExceptionIfNeeded as its first statement. A KILL landing in that window therefore aborts the query at executor-attach time regardless of the per-row cancellation checks this branch adds, so KILL ... SYNC returned in milliseconds and the test printed "killed promptly" on an unpatched server. Both existing guards were satisfied: the query was visible, and KILL did report exactly one row. Wait for max(elapsed) > 1 instead, which is the predicate the merged sibling test 04648_geohashes_in_box_cancellation.sh uses for the same reason. max(elapsed) over an empty set is 0, so one expression covers both the absent and the merely pending case. The deadline goes from 30 s to 60 s because readiness now additionally waits about a second of execution. Measured on an unpatched binary: killing with no readiness wait at all ends the query in 2 to 4 ms with code 394 and reports "killed promptly", while the new predicate still reports the full 68 s.
An unconditional poll per row is not free. QueryStatus::checkTimeLimit calls throwProperExceptionIfNeeded, whose body opens with an unconditional lock_guard on cancel_mutex, so each poll is a clock read plus a mutex acquire/release, about 31 ns. That is invisible next to a full SQL parse but not next to tokenizeQuery, which is lexer-only and shares the row loop: 480M rows of an empty string went from 3.27 s to 19.43 s, a 5.95x regression. So accumulate the bytes each row parses and poll on crossing a 64 KiB stride, the way geohashesInBox, arrayFold and Base58 already throttle theirs. That brings the same measurement to 3.66 s, 1.12x, against run-to-run noise under 2%. One stride is about 50 ms of parsing in a debug build, three orders of magnitude below the granularity max_execution_time is expressed in, and a row larger than the stride still polls every row. Each row counts as at least one byte so a block of empty strings polls rather than never polling. The earlier claim that this poll takes no lock, and that base58 polls per item, were both wrong; base58 polls every 1<<20 work units. timeout_overflow_mode = 'break' gets its own test case. There checkTimeLimit returns false instead of throwing and this fix turns that into a hard stop, a user-visible change the throw-mode cases cannot exercise, and one CI cannot stumble on since timeout_overflow_mode is not randomized. The query succeeds in both directions, emitting no row, so latency is the only discriminator: 69783 ms before, 1045 ms after. Because a successful query is logged as QueryFinish rather than ExceptionWhileProcessing, it carries its own marker and the counting query now filters type != 'QueryStart', matching 04648's duration check. The liveness arm, which is what would catch a check that fires when it should not, needed rebuilding for the same reason the stride exists: a single short query never crosses the stride, so those calls no longer reach the poll at all. Verified against a binary with the check made to throw unconditionally, where every one of the old single-row calls passed. It now runs one block per polled row loop, covering all seven entry points, and every line reddens individually under that mutation.
…tride The throttled cancellation check accumulates the bytes each row parses and polls on crossing a 64 KiB stride, so the bytes it is given have to be proportional to the work the row actually does. In the two-argument form of formatQueryFromJSON they were not. Only the JSON was counted, while each row additionally tokenizes the whole original query, and may reparse the merged text, in formatWithOriginalWhitespaceChecked. The smallest valid AST serializes to 339 bytes of JSON, so a stride admitted 193 rows, each lexing an original bounded only by max_query_size. Measured on a 1.2 MB original with max_query_size raised to 2000000: 4386-4676 ms against a 1 s limit before this change, 1017-1022 ms after, both on freshly started servers with the binaries differing only in this accounting. Counting the second argument's bytes as well restores the proportionality the helper documents. The other six call sites were audited and are already proportional: formatQuery and the ColumnString loop of fuzzQuery charge the row's own length against a parse of that text, parseQueryToJSON charges sql.size() against a parse plus AST-to-JSON conversion, the ColumnConst loop of fuzzQuery charges data.size() against a clone, fuzz and format of that same AST, and QueryTokenizationImpl charges query.size() against its lex or parse. Also drop five verbatim copies of a comment about callers that have no process-list entry. That is a property of getProcessListElementSafe and of the shared helper, which states it once at its declaration, not of any individual call site.
The existing timed cases all run at default settings, and at the default max_query_size the second argument is capped at 262144 bytes. That bounds how far the old accounting can overshoot to about 1.7 seconds, which does not cross the threshold case 7 asserts, so a case folded in there could not distinguish the two accountings. Measured at the default cap the overshoot saturates at roughly 1.7 seconds no matter how many rows the block holds, because what overshoots is one stride's worth of work rather than the whole block. The new case therefore raises max_query_size and carries its own latency bound instead of joining case 7's marker, which leaves the ten existing cases and their count untouched. Its marker deliberately spells no other case's marker, since the comment is part of the logged query text and would otherwise inflate that case's count. Measured against a one second limit, with only the binary differing: 3964 to 4079 ms when only the JSON is counted, 1005 to 1017 ms once both arguments are, so the 3000 ms bound sits clear of both. Deleting just the second argument's term from the byte sum puts it back to 4038 to 4730 ms, so the assertion rests on that term. At test level the suite fails on the old accounting with only the new assertion flipping, and passes with the fix.
The case asserted wall-clock milliseconds against a 3000 ms bound. Measured over fifty runs at -j 1 on the same tree, it failed seven times, for two reasons that no choice of threshold fixes. The arms overlap once the server is not fresh. The bound was set from a fresh-server measurement of 1.08 to 1.13 s with the fix; on a loaded server the same query takes 3979 to 5272 ms, median 4184 over forty-two samples, which runs through the bound and into the unpatched range of 4385 to 4675 ms. A wider bound is then vacuous and a narrower one is flaky. The query also sometimes succeeds outright. The test runner injects its own max_block_size, and a small one splits the two hundred rows across blocks so the one second limit is never reached and nothing is raised. The query log then shows QueryFinish at 8 ms and 15 ms, and the oracle's count() = 1 matches no row at any threshold. Pinning max_block_size in the query does not help, because the runner's value decides the split. Folding the case into case 7's marker instead was measured at twenty-nine failures in fifty. The accounting this case was meant to cover keeps its evidence: the fresh-server A/B of 4675, 4385 and 4445 ms before against 1021, 1018 and 1017 ms after, and the mutation arm where deleting only the second argument's term from the byte sum restores the pre-fix latency. It also keeps a liveness line in case 9. What is removed is only an oracle that reddens on healthy servers, which is worse than absent coverage because it teaches readers to ignore the file. The file already makes that argument for tokenizeQuery, which likewise gets no case of its own rather than one whose oracle cannot redden. This reverts commit 8ec6367. The source change that counts both arguments toward the stride is not touched.
The two-argument form takes its own branch through the row loop, and after the latency case was dropped no arm anywhere would have reddened if the check threw unconditionally on that path: case 9 only exercised the one-argument form. Both arguments are small, so the line crosses the stride by row count rather than by row size. At the 339-byte floor for the smallest valid AST, a hundred thousand rows cross the 64 KiB stride about five hundred times, so the poll is genuinely reached and the assertion is not vacuous. Verified the way the other case 9 lines were: under a binary whose check throws unconditionally, this line fails on its own.
Each declaration keeps a contract block, matching the sibling precedents in geohashesInBox, arrayFold and FunctionBaseXXConversion, but the motivation and the measurements move out. The measurements are not lost: the 31 ns poll cost, the 5.95x tokenizeQuery regression and the ~50 ms per stride are all already recorded in the commit that introduced the throttle. Comments only. The token stream is unchanged.
Internal second-model review: adjudication log (click to expand)Pre-publication review by an independent model (engine: codex; 6 passes, 14 findings), plus my own
Severity: ❌ blocker / ⚠ major / 💡 nit. DISAGREE verdicts carry recorded evidence and are Session id: cron:clickhouse-review-slot-48:20260803-014900 |
Pre-PR validation gate (click to expand)
Each of the polls was verified to be load-bearing by deleting it in source, rebuilding, and confirming the corresponding case reddens: with the tokenization poll removed the Performance, since it is the natural question here: each poll is one |
|
cc @nihalzp @yariks5s, could you review this? The query-parsing functions parse one row at a time inside a single pipeline task, and |
PedroTadim
added
the
can be tested
|
Workflow [PR], commit [10ba525] Summary: ❌
AI ReviewSummaryThis PR does fix the retained- Findings
Final VerdictRequest changes. Either the remaining uninterruptible work needs to be fixed, or the PR scope, changelog claim, and regression coverage need to be narrowed to the cases this implementation actually makes cancellable. LLVM Coverage Report
Changed lines: Changed C/C++ lines covered: 51/53 (96.23%) · Uncovered code |
clickhouse-gh
Bot
added
the
pr-bugfix
![clickhouse-gh[bot]](https://avatars.githubusercontent.com/in/928874?s=60&v=4){kind=small}
The cancellation poll added by this pull request read a QueryStatus captured in the function constructor. An IFunction is not query-lifetime: it is kept in a cached FunctionBase inside ExpressionActions, and table metadata retains those actions. ALTER rebuilds the partition key from its own query context (AlterCommands::apply) and StorageMergeTree::alter commits that object, while MergeTreePartition::adjustPartitionKey hands the same object to later inserts unless the key contains modulo. A later insert therefore polled the ALTER's stopwatch, which keeps running after the ALTER finishes, and failed on that long-finished query's max_execution_time. Measured on a table partitioned by cityHash64(formatQuery(q)): after an ALTER ... SETTINGS max_execution_time = 1 and a short wait, an insert of 3000 rows failed with TIMEOUT_EXCEEDED reporting "elapsed 6063.799 ms, maximum: 1000 ms" although it set no limit of its own. The same insert succeeds on master and after this change. The mirror image also mattered: a function built without a process-list entry kept an empty QueryStatus for every later query, so the poll stayed a no-op in exactly the case the fix targets. Resolve the status per executeImpl call from CurrentThread instead, which costs one thread-local read per block rather than per row and so keeps the throttling behaviour unchanged.
| { | ||
| std::string_view query = col_query.getDataAt(i); | ||
|
|
||
| checkQueryCancellationThrottled(query_status, name, query.size(), bytes_since_check); |
There was a problem hiding this comment.
checkQueryCancellationThrottled here only runs once before the whole Impl::processRow. That still leaves both carriers behind this shared loop able to spend arbitrarily long on a single row without observing cancellation: highlightQuery tokenizes/parses the entire row after this one check (highlightQuery.cpp:43-64, note the unbounded Tokens(..., 0, ...)), and tokenizeQuery lexes the whole row in its own loop (tokenizeQuery.cpp:33-44). So max_execution_time / KILL QUERY are still ignored for a one-row large input, and the new test never exercises that shape because it only uses many-row blocks. This needs either a cancellation hook inside that tokenization/parsing work, or a row-size bound that makes one processRow cheap enough.
There was a problem hiding this comment.
Both halves of this are correct, and I confirmed each in source and by measurement before answering. The residual is real but it is pre-existing, not introduced here, so I am not folding it into this PR.
(a) is true for highlightQuery, and false for the other five carriers. The discriminator is max_query_size. One row of 2.2 MB under max_execution_time = 1:
| carrier | result | why |
|---|---|---|
formatQuery, parseQueryToJSON, fuzzQuery, formatQueryFromJSON |
Code: 62 Max query size exceeded |
bounded before parsing, 262144 by default |
highlightQuery |
Code: 159 ... elapsed 1486 ms |
Tokens(begin, end, /* max_query_size = */ 0, ...), highlightQuery.cpp:43, no bound |
tokenizeQuery |
finished inside the limit | lexer only, 11 MB in 0.91 s |
The overshoot is linear and unbounded, with a control that isolates it to the function: building the same strings and taking length of them finishes under the limit at both 200000 and 800000 repeats, while feeding them to highlightQuery gives elapsed 2047.773 ms and elapsed 10195.074 ms against a 1000 ms limit. So one row can spend ten times its limit inside one processRow.
tokenizeQuery is not a carrier in practice, for the reason the test file already records at line 41: its cost is dominated by the token array it builds, so it exhausts memory before it overshoots a time limit.
(b) is true. Every case uses many-row blocks, so no shipped case covers the one-row shape.
Why it is out of scope here. git diff <merge-base>..HEAD -- src/Functions/highlightQuery.cpp src/Functions/tokenizeQuery.cpp is empty, and max_query_size = 0 at highlightQuery.cpp:43 predates this branch. This PR only adds the poll to the shared row loop in QueryTokenizationImpl.h; the missing bound inside processRow is a second, narrower defect that the poll cannot reach by construction. Closing it means either threading cancellation into ParserQuery::parse and Tokens, which is new plumbing across src/Parsers (it currently contains no reference to QueryStatus, checkTimeLimit or CurrentThread), or bounding highlightQuery's Tokens by max_query_size, which changes behaviour for inputs above 262144 bytes that succeed today. Either is a separate change with its own owner decision, and this PR is already at +313 over six review rounds.
Unrelated to your comment, the same push fixes a problem this head did have: the test exceeded the flaky check's per-test bound on four sanitizers. The cause was self-parallelism rather than per-run cost (ci/jobs/functional_tests.py:509 runs nproc - 1 workers, each with its own queue), so I cut the two compute-bound arms. Summed statement time goes from 46560 ms to 16104 ms, and under the real runner at -j 4 the .sql goes from 41.9-56.9 s to 19.8-26.4 s. The stride is charged in raw bytes, so padding rows to 39 bytes keeps the same twelve stride crossings at a fifth of the rows; cutting the row count alone would have weakened the arm to 2.4 crossings. Re-proven non-vacuous both ways: under a mutation making the poll throw unconditionally all seven liveness lines still fail, and under a mutation restoring the constructor capture in formatQuery.cpp alone the retained-expression case still fails with its own signature (elapsed 4449 ms against the ALTER's 3000 ms).
The flaky check ran 04691 concurrently in nproc-1 workers, each with its own queue (ci/jobs/functional_tests.py:509, tests/clickhouse-test:5269), and the test exceeded both the 180 s per-test bound and the runner's 600 s cap on amd_debug, amd_msan, amd_tsan and amd_asan_ubsan. Standalone it took 21 s, so the carrier is that self-parallelism rather than the per-run cost, and the two compute-bound arms had the headroom to give. The stride the cancellation poll is throttled on is charged in raw bytes, so padding each row to 39 bytes buys the same 12 stride crossings with a fifth of the rows; cutting the row count alone would have dropped case 9 to 2.4 crossings and weakened the arm. Case 10 only needs one crossing plus the retained partition-key expression, and 200 padded rows over four partitions reach that without materialising 3000 partitions. Its ALTER also carried a 1 s limit, which was seen timing out the ALTER itself on a loaded server. The limit only has to be finite and to have elapsed before the insert, so it is now 3 s with a 4 s settle. Summed statement time drops from 46560 ms to 16104 ms, and under an 8-way contention repro the worst copy goes from 51771 ms to 21743 ms. Every assertion is unchanged; only the row count in the reference moves. Non-vacuousness was re-proven rather than assumed: under a mutation that makes the poll throw unconditionally, all seven case-9 lines still fail at the reduced fixture, and under a mutation restoring the constructor capture in formatQuery.cpp alone, case 10 still fails with the defect's own signature (elapsed 4449 ms against the ALTER's 3000 ms) while case 9 stays green.
The flaky check runs nproc-1 copies of a test against one server, so `query_duration_ms` for these statements carries scheduling delay that has nothing to do with the code under test. The 15 s wall-clock budget in case 7 was therefore violated on loaded sanitizer hosts: 13 failures across amd_debug and amd_asan_ubsan, every one of them the single line `all bounded 1` -> `0` with the other twelve reference lines matching. No threshold fixes this. A budget wide enough for a host running the test 17x slower would have to exceed the 21-90 s pre-fix cost that the assertion exists to detect, which disarms it. The property under test is how much work a cancelled query does, which is CPU time, and `query_log.ProfileEvents` already records it. Measured over the same ten statements on the same fixtures: an unpatched server reports 70878-75814 ms of user+system CPU (8 statements over the bound), a patched one 1034 ms (0 over), so the new oracle discriminates exactly as the old one did. Unlike wall clock it does not absorb starvation: taking the server from 384 available CPUs down to 1 under 24-way contention moved wall from 1047 to 1765 ms while CPU stayed within 1016-1050 ms. Headroom on the patched build is 8.6x (209 statements over a 20-way run, CPU max 1738 ms), and one 64 KiB stride of parsing, the most a poll can overshoot by, costs under 2.4 s even on an ASAN build. Proven non-vacuous by rebuilding with the poll removed from `formatQuery.cpp`: the new oracle reddens with the defect's own signature.
|
Pushed The failure was 13 runs across What the test actually wants to assert is how much work a cancelled query does, which is CPU time, and
So the new bound discriminates exactly as the old one did. Unlike wall clock it does not absorb starvation: taking the server from 384 available CPUs down to 1 under 24-way contention moved wall from 1047 to 1765 ms while CPU stayed within 1016-1050 ms. Headroom on this branch is 8.6x, measured over 209 statements in a 20-way run (CPU max 1738 ms), and one 64 KiB stride of parsing, the most a poll can overshoot by, costs under 2.4 s even on an ASAN build. I checked the oracle is not vacuous by rebuilding with the poll deleted from Validation on the shipped tree: 40/40 with One note on the earlier diagnosis: round 2 read this as cost ( Session id: cron:clickhouse-maint-slot-17:20260803-232300 |
The flaky check runs nproc-1 copies of a changed test against one server, and every copy of this test was crossing the runner's 180 s per-run cap on the two slowest builds: 7 of 21 runs on amd_debug and 8 of 15 on amd_asan_ubsan, all with "Test runs too long (> 180s)". amd_msan and amd_tsan passed only by margin, at 121-166 s against the same cap. The ten timed statements are limit-bound, not fixture-bound: each one parses until max_execution_time elapses and is then cancelled, so it costs the limit and nothing else. Ten statements at a 1 s limit therefore cost 10 s of the test's ~16 s, and lowering the limit cuts that proportionally without touching a single fixture or assertion. Measured on one binary: 300 ms leaves each statement at 300-617 ms of CPU, against case 7's 15 s bound. Case 10's ALTER limit and its settle only have to be finite and elapsed, so they come down the same way. A/B on the same binary at 12-way self-parallelism: 18.4-19.6 s before, 8.8 s after, 24 of 24 runs passing. Discrimination is unchanged - with the poll deleted from formatQuery, 5 of the 10 statements still burn 72-74 s of CPU and case 7 still reports "all bounded 0".
|
The flaky check was failing this test on the runner's 180 s per-run cap, not on an assertion: 7 of 21 runs on The ten timed statements are limit-bound rather than fixture-bound. Each one parses until A/B at 12-way self-parallelism against the same binary, only the
Discrimination is unchanged. With the poll deleted from |
The flaky check's 180s per-test cap was still being straddled (5 FAIL / 4 OK across 173-206s on amd_asan_ubsan). Rounds so far tuned the timed cancellation cases, but those are not where the time goes. The job's own query_log shows the liveness arm is 15.7s of the run's 19.6s of CPU, and one statement of it, fuzzQuery over 20000 rows, averages 99s of wall clock alone. The arm exists to prove the new poll does not fire when it should not, so each call has to cross the poll's 64 KiB stride at least once. The stride is charged in bytes, but the parse it guards costs per row, so the row count was buying stride crossings at the worst possible rate: 20000 rows of 39 bytes cross the stride 11 times, and so do 100 rows of 7809 bytes, for a 22x lower CPU cost (914ms -> 41ms measured per arm, settings held fixed). The padding is a string literal rather than the previous trailing comment because a comment is not part of the AST. parseQueryToJSON emits the same 339 bytes however long the comment is, so padding a comment would leave the two formatQueryFromJSON calls, whose rows are that JSON, never crossing the stride and their halves of the arm vacuous. Every assertion, fixture, marker and the CPU-time oracle are unchanged. Verified by deleting the poll from formatQuery's row loop and rebuilding: the reduced test still reddens with the defect's own signature, 5 of the 10 marked statements burning 68-70s of CPU against the 15s bound, while the liveness arm stays at 32ms. Shipped arm leaves 32x headroom on that bound.
|
The 180s flaky-check cap was still being straddled on The time is not in the timed cancellation cases. Per run they cost 3.1s of CPU. The liveness arm (case 9) costs 15.7s of the run's 19.6s, and one statement of it, That arm only has to prove the poll does not fire when it should not, which means each call must cross the poll's 64 KiB stride at least once. The stride is charged in bytes, but the parse it guards costs per row, so the row count was buying crossings at the worst possible rate. 20000 rows of 39 bytes cross the stride 11 times; so do 100 rows of 7809 bytes, measured at 22x less CPU (914ms -> 41ms per arm, settings held fixed). The padding sits in a string literal rather than the previous trailing comment because a comment is not part of the AST: Every assertion, fixture, marker and the CPU-time oracle are unchanged. Non-vacuousness, by rebuilding rather than by argument: with the poll deleted from A/B on one binary with only the |
CI finish ledger — 71110b0Every failure below has an owner: a fixing PR (mine or external), or a full-effort fix task whose
Session id: cron:our-pr-ci-monitor:20260804-210000 |
|
The two remaining failures on The runner's minimization is misleading here. Its diagnosis block reports
What actually happens. From The same shape holds for the other three in that database (17.0 s, 19.4 s, 17.1 s). On each of them Reproduced locally on this exact binary (server confirmed serving build id
and five repeats at 200000 gave 318, 319, 320, 323, 1421 ms, so the overshoot is nondeterministic and reaches about 4.7x the limit on an idle machine. It scales with the limit (0.3 s gives 313-1765 ms, 1 s gives 1029-1269 ms, 3 s gives 3010-3042 ms), which means it is a fraction of a block rather than a fixed cost. The arithmetic agrees: rows are 39 bytes, so one 64 KiB stride is about 1680 rows, and at the measured 0.349 ms per row a single stride costs about 587 ms here, already twice the limit before any sanitizer slowdown. So I also checked and ruled out the obvious alternative, that
|
max_execution_time is charged from query start, so it also has to cover parsing, analysis, planning, plan optimization and pipeline construction. On the amd_msan build that prelude is about 60x more expensive than on a debug build: 246-276 ms of the 300 ms budget the test was setting, and up to 1.63 s for the constant-argument fuzzQuery case, whose constant folding costs ~2.5x the others even locally. The consequence was not a late failure but a silent one. In 16 of the 19 runs recorded in the failing job's query_log artifact, every timed query exhausted its limit before the pipeline read a single row, so the row loop those queries exist to exercise never ran, and countIf(cpu > 15 s) = 0 was satisfied by queries that had formatted nothing. The two populations are disjoint: runs that reached the loop spent 118-157 ms in the prelude, runs that did not spent 246 ms or more. Loop entry was a per-run property, all eight applicable statements or none. So raise the limit to 3 s, which clears the worst observed prelude while staying far below the ~70 s an unpolled block costs, and add countIf(read_rows = 0) = 0 so that a query which never reached the loop fails the assertion instead of passing it. Forcing the vacuous shape locally, the old oracle returns 1 and the new one returns 0; on ten healthy statements the new one still returns 1. Ten statements now run to a 3 s limit rather than a 300 ms one, so the test costs about 30 s of CPU instead of 3 s, hence the long tag. The 180 s runner cap applies only in flaky-check mode and only to untagged tests, and --no-long is passed by Fast test, which this test already skips, and by the LLVM coverage job. Verified by disabling the poll at all seven call sites (stride set to SIZE_MAX, build id cf3d7a3e75 -> 000f2650da, confirmed serving): the .sql test hits the runner's 600 s timeout and the kill companion reports "KILL took 69s, expected under 15s". Reverting restored build id cf3d7a3e75 exactly and 14 of 14 runs pass with randomization on.
The tag was not needed and was not free. It exempts a test from the 180 s per-run limit that only applies in flaky-check mode, but it also cuts the flaky check's repetitions to int(test_runs * long_test_runs_ratio), and that ratio defaults to 0.1, so a 50-run check would have run this timing sensitive test 5 times. The limit does not need the exemption. The ten timed statements are limit-bound rather than throughput-bound, so their cost is about ten times the 3 s limit no matter how loaded the host is: measured at 31.8-32.2 s per run both standalone and under ten-way self-contention, against the 180 s limit. A single sanitizer pass adds about 25 s of marked CPU over the old 300 ms limit, which leaves the same margin there.
Root cause of the two
|
Build profile diff (arm_release)No arm_release build profile data for commit 10ba525 - the build was skipped, reused from cache, or predates profile upload. |
Dropping it in 5431af7 was wrong. That commit argued the tag was not needed because the ten timed statements are limit-bound, measured at 31.8-32.2 s per run. The measurement was right and the inference was not: it was taken on a debug build on an idle machine, and it missed that one of the functions under test serializes against concurrent copies of the test itself. The flaky check then failed five of five runs of this test with "Test runs too long (> 180s)" at 180.7-188.6 s. Its own query_log shows where the time goes. Per run, the two fuzzQuery statements cost 100-120 s of the 165-181 s total while every other statement together costs 56-76 s. Those two have a wall median of 58070 ms against the 3 s limit but burn only 2321 ms of CPU, and their thread time is 95% blocked rather than runnable. Every other timed statement sits at about 5 s wall for 1 s of CPU. The reason is that getGlobalASTFuzzer hands out a lock on one process-global mutex and fuzzQuery takes it once per row, so copies of this test running in different workers fully serialize. Wall time scales linearly with the number of overlapping copies, about 5 s per copy, and the flaky check overlaps a median of ten of them. A thread parked on that mutex runs no code, so the cancellation check cannot observe the wait, and the overshoot is one poll stride of lock waits with no CPU attached to it. Even with no other copy running the statement took 12.4 s against the 3 s limit. No test-side tuning removes this. The overshoot is one 64 KiB stride of input, and parse cost is proportional to input bytes, so it is invariant to how wide the rows are: sweeping the row width by 16x moves the overshoot between 5 and 20 ms. It is likewise invariant to the row count, since a timed statement stops one stride past its limit however many rows follow. The limit itself cannot go back down either, because 05dc83b raised it to 3 s precisely so that it outlives query planning on a sanitizer build, without which the row loop is never reached and the whole test passes vacuously. That leaves the tag, and the coverage objection to it does not survive arithmetic. Without it the test is run 50 times and every run exceeds the cap, so it yields no usable runs at all. With it the flaky check runs it int(50 * 0.1) = 5 times and those runs pass. Five real runs beat fifty failures. The only job that skips long tests outright is the non-per-test LLVM coverage one. Padding the argument so the stride is crossed sooner was tried and rejected. Padding with a string literal puts the padding in the result column: peak memory went to 3.1 GB for the constant shape and 5.1 GB for the other one, against a 10 GB server shared by eight concurrent copies under a sanitizer. Padding with a comment costs nothing but buys nothing either, about 70 ms, because it does not touch the serial cost. The test is otherwise unchanged, and it still detects the bug it was written for: run against a pristine pre-fix server, both it and its kill companion fail on the runner's 600 s timeout.
Restored the
|
| { | ||
| /// Every row fuzzes and re-formats the same parsed query, so each one costs the same | ||
| /// as parsing that text once. | ||
| checkQueryCancellationThrottled(query_status, name, data.size(), bytes_since_check); |
There was a problem hiding this comment.
data.size() is not a safe proxy for the work hidden behind each iteration. After this poll, the loop can still spend arbitrarily long in ast->clone() and, more importantly, waiting for getGlobalASTFuzzer()'s process-global mutex before it touches QueryStatus again. With short inputs the 64 KiB stride admits about 1600 rows between polls, so concurrent fuzzQuery calls can still sit far past max_execution_time / KILL QUERY on this path. Since the PR advertises fuzzQuery as fixed, this needs a cancellation point around the mutex acquisition (or a much tighter fuzzQuery-specific throttle), not just the row-entry poll.
There was a problem hiding this comment.
The mechanism you name is real and is already characterised in this PR's history, but I measured
both of the claims that would justify a code change here and they do not hold.
data.size() as a proxy. I compared per-row cost against the siblings that use the same
stride, on byte-identical input, with read_rows asserted at 2000 on every arm: formatQuery
346.5 us/row, highlightQuery 348.0, fuzzQuery 448.5. So clone plus fuzzMain plus the lock
add about 30% on top of a parse, and the same 64 KiB stride buys fuzzQuery 1.3x the latency it
buys formatQuery, not orders more.
One correction worth stating, because my first attempt at that comparison was wrong in a way that
supported your reading: formatQuery has useDefaultImplementationForConstants() == true, so a
constant argument is folded and its row loop never runs, while fuzzQuery returns false and is
non-deterministic, so its loop does run on a constant. Comparing the two on a constant argument
measures "loop ran" against "loop never ran" and reports a 88x difference that is an artefact. Both
arms above use materialize().
Latency. Debug build, Build ID cf3d7a3e75, max_execution_time = 3, max_threads = 1,
read_rows from query_log used as the control on every arm so that a query which exhausts its
limit during planning cannot pass as a bounded one:
| shape | read_rows | elapsed | overshoot |
|---|---|---|---|
| 498-byte argument | 200000 | 3015.6 ms | +16 ms |
| 8-byte argument | 2000000 | 3001.1 ms | +1 ms |
Concurrency does not change the picture on this path. Ten concurrent copies of the constant-argument
form finish in 3.096 to 3.177 s of client wall time, which includes connect and teardown; twelve
copies of the short form report 3000.4 to 3167.4 ms of server elapsed. KILL QUERY ... SYNC on the
short form with no time limit returns in 0.18 s. Against a pre-fix binary that has none of
these polls, the same short form overshoots by 1500 ms, so the arms do detect a bad number.
The stride on the shape this test uses is 131 rows, not about 1600; 65536/498. The 1600 figure needs
an argument of roughly 40 bytes, and at 448.5 us/row that is still well under a second.
Where you are right. There is one shape that does sit far past the limit, and it is the mutex:
on amd_asan_ubsan under the flaky check's eight-way self-concurrency, the two fuzzQuery
statements showed a wall median of 58070 ms against the 3 s limit while burning 2321 ms of CPU, with
thread time 95% blocked rather than runnable. That is why the test carries the long tag, and it is
disclosed in the PR.
A cancellation point around the acquisition does not bound it, though. A thread parked in
unique_lock executes nothing, so a check placed either side of the acquisition cannot run during
the wait. Bounding it means try_lock with a timeout on a process-global mutex that server-side AST
fuzzing also takes, which is a larger change than this PR's contract on a function gated behind
allow_fuzz_query_functions, default off and experimental. I would rather not fold it in here.
…budget Two distinct failures of this PR's own tests on `Stateless tests (amd_msan, WasmEdge, parallel, 2/2)`. WasmEdge is not implicated: the other three WasmEdge shards, the msan flaky check and both msan sequential shards are green. The CPU overshoot. Seven of the ten timed statements burned 28-38 s of CPU against their 3 s limit, and the `break`-mode case ran 29.7-38.2 s with `result_rows = 0`, which means the poll did stop it, one stride late. The poll is throttled on accumulated input bytes while a row's parse cost is set by how many AST nodes it has, so the worst wait is 64 KiB divided by the row size, times the per-row cost. The rows were 40 `OR` clauses in 458 bytes, the worst possible ratio: 143 rows per stride. Deriving the per-row cost two independent ways, from the `break`-mode stop times and from the liveness arm measured in the same job, gives 204-264 ms per row there, so one stride cost 29 s. Comment bytes count toward the stride but produce no AST, so a 2000-character trailing comment buys five times the stride budget for no extra parse work, and the row counts are halved to hold peak memory where it was. Locally, in `break` mode where only the poll can stop the query, the overshoot above a 3 s limit falls from 7-46 ms to 1-4 ms, and peak memory is 515 MiB against 518 MiB before. The `ALTER`. The statement that aborted the script is `ALTER TABLE t_04691_retained ADD COLUMN extra UInt8 DEFAULT 0 SETTINGS max_execution_time = 1`, whose seven rows in the job's `query_log` are three `ExceptionBeforeStart` at 1352-1899 ms and two `QueryFinish` at 970-1070 ms. `ExceptionBeforeStart` with `throwIfKilled` beneath `executeQuery.cpp:2012` means the deadline expired during interpretation, before a pipeline existed, so no poll can reach it. That budget straddles the cost distribution on this build: the same statement takes 4 ms locally. Its own comment already records that the limit "only has to be finite and elapse, not tight", so it is raised to 30 s. Verified in both directions against a mutation build that sets the stride to `SIZE_MAX`, disabling the poll at all seven call sites. Unpolled, one block of the new fixture costs 34.4 s of CPU, so the assertion still has more than twice the margin it needs over its 15 s threshold; the `.sql` test fails and the companion reports `KILL took 34s, expected under 15s`. With the poll both pass, five runs with randomization on. The 15 s bound, the `read_rows` conjunct and the `long` tag are unchanged.
CI finish ledger — 8b39f7fEvery failure below has an owner: a fixing PR (ours or external), or a full-effort fix task
Both
|
| { | ||
| static constexpr size_t bytes_between_cancellation_checks = 65536; | ||
|
|
||
| bytes_since_check += bytes ? bytes : 1; |
There was a problem hiding this comment.
bytes is not a safe proxy for the work in these callers. formatQuery, parseQueryToJSON, highlightQuery, and fuzzQuery all do parser / AST work whose cost depends much more on syntactic density than on raw input size, and the latest 04691 change is already padding each row with a 2 KB comment purely so this 64 KiB gate trips sooner. That means the production bug is still there for the unpadded shape that actually failed CI: short rows with many AST nodes can still run far past max_execution_time / KILL QUERY before the next poll. This needs a work proxy tied to parsing cost, or unconditional per-row checks in the parse-heavy loops with the throttle kept only for the genuinely cheap carrier.
There was a problem hiding this comment.
Measured, and the density premise does not hold. Thanks for pushing on it: the earlier answer in the fuzzQuery thread bounded the ratio between callers on one input shape, which does not bound the worst case across syntactic densities, so this was the right question to ask.
The throttle charges input bytes and the stride is fixed at 64 KiB, so unpolled work per stride is (65536 / row_bytes) * cost(row_bytes). That is constant if and only if parse cost is proportional to bytes at fixed density, and bounded if and only if cost per byte is bounded across densities. Both hold.
Cost per byte is flat in row size. Dense identifier list (SELECT a,a,...,a), formatQuery over materialized rows, one debug binary, read_rows confirming the loop ran to completion:
| row bytes | us/row | us/byte | stride at 64 KiB |
|---|---|---|---|
| 226 | 425 | 1.88 | 123 ms |
| 886 | 1678 | 1.89 | 124 ms |
| 3526 | 6888 | 1.95 | 128 ms |
| 14086 | 27633 | 1.96 | 129 ms |
| 28166 | 55433 | 1.97 | 129 ms |
A 125x change in row size moves cost per byte by 5 percent, so the stride cost does not grow with row size.
Cost per byte is bounded across densities. Twenty-two shapes at a fixed ~450 bytes, the size that failed CI: nested function calls, CASE chains, IN lists, array and tuple literals, CAST chains, INTERVAL chains, lambda chains, subquery nesting, UNION chains, WITH chains, qualified columns, IS NOT NULL chains. The worst is a bare identifier list at 2.03 us/byte, against 0.76 for the 40-OR shape this test uses, so the spread is 2.7x, not orders of magnitude. The floor is 0.09 us/byte.
End to end that is 5 ms, not tens of seconds. timeout_overflow_mode = 'break' under a 3 s limit, where only this poll can stop the query, result_rows = 0 confirming it did, 3 repetitions each, overshoot above the limit:
| shape | unpadded, worst density | this test's 40-OR shape |
|---|---|---|
| fixed | +109 / +2 / +114 ms | +28 / +20 / +5 ms |
| pre-fix, same shapes | +164195 / +164405 / +165120 ms | +66580 / +65762 / +65569 ms |
The pre-fix column is the control that the arms can show a bad number: same queries, same host, only the binary differing. Worst-density overshoot is 3.8 percent of the limit fixed and 5500 percent unfixed.
So the unpadded shape is not unbounded, and the 2 KB comment in 04691 is not there to make the gate trip at all. It is there to keep one unpolled block expensive enough that the test's CPU bound still detects a regression while the polled wait stays short, which are two different quantities: a comment adds stride budget without adding AST nodes.
On the alternative: unconditional per-row checks were measured at 5.95x slower for tokenizeQuery against 1.12x for the throttled form, which is why the throttle exists. A parse-cost proxy would need the node count before parsing, which is not available at the call site. Given a bounded 2.7x density spread and a measured 114 ms worst case, neither is worth its cost.
The case exists to fail when the cancellation poll reads a QueryStatus captured when the function was built rather than the executing query's. It stopped doing that when its ALTER budget was raised from 1 second to 30 to stop the ALTER timing itself out on a slow host: a stale timer only fails the later insert once the builder query's own max_execution_time has elapsed, and the case waits 1.2 seconds before an insert that finishes well inside 30. Measured against a build that captures the status in the constructor, the case passed 3 of 3 while that same build still reproduced the original bug on a 1 second budget, reporting "elapsed 3009.757 ms, maximum: 1000 ms" for an insert that sets no limit. Shorten the budget below the wait and give the ALTER break overflow mode. On expiry CancellationChecker::cancelTask calls checkTimeLimit instead of cancelQuery(CancelReason::TIMEOUT), so is_killed is never set and the ALTER completes whatever its budget, while the stopwatch a stale status would read keeps running. Verified directly: a statement that outlives a 1 second budget records QueryFinish with exception code 0 under break and ExceptionWhileProcessing with code 159 under throw. That removes the failure mode the 30 second budget was working around, which had aborted the script with TIMEOUT_EXCEEDED on the amd_msan WasmEdge shard where the ALTER itself measured 1352 to 1899 ms against its 1000 ms budget. The constructor-capture build now fails the test inside t_04691_retained with "elapsed time limit reached in function formatQuery", and the shipped build passes 20 of 20 randomized runs.
CI finish ledger — 10ba525Every failure below has an owner: a fixing PR (ours or external), or a full-effort fix task
CI is otherwise finished on this head: 175 check-runs, 0 incomplete, Neither failure is caused by this PR, whose diff is confined to On the first line: my own #107957 previously carried this signature and was closed earlier today as Session id: cron:our-pr-ci-monitor:20260806-020000 |
2 participants
Changelog category (leave one):
Changelog entry (a user-readable short description of the changes that goes into CHANGELOG.md):
Fixed
max_execution_timeandKILL QUERYbeing ignored byformatQuery,formatQueryOrNull,formatQuerySingleLine,formatQuerySingleLineOrNull,formatQueryFromJSON,parseQueryToJSON,fuzzQuery,highlightQueryandtokenizeQuery. These functions parse one row at a time inside a single pipeline task, and cancellation was only checked between tasks, so a query ran far past its limit.Description
Requested in #107125 (comment). Report: https://s3.amazonaws.com/clickhouse-test-reports/json.html?PR=107125&sha=c2d8b026702b6eed289c8a6d56d6532d2a7d4105&name_0=PR&name_1=Stress%20test%20%28arm_msan%29
What breaks.
PipelineExecutor::cancelonly sets flags, so cancellation is observed between pipeline tasks. These functions parse per row in oneexecuteImpland never obtained aQueryStatus, making a block one uninterruptible unit. On a debug build, 200000 rows of moderate SQL withmax_execution_time = 1stopped after 70 s instead of 1 s. The AST fuzzer reaches this at scale with a 30 s deadline per task.The change. Call
checkTimeLimitinside each per-row loop, followingFunctionBaseXXConversion, fixed for the same bug class. TheQueryStatusis resolved perexecuteImplcall fromCurrentThreadrather than stored on the function: anIFunctionis retained in table metadata,ALTERrebuilds the partition key from its own query context, and later inserts reuse that object, so a stored status failed them on the ALTER's expired limit. InformatQuerythe check sits outside the existingtry/catch: forErrorHandling::Nullthat handler turns any exception into a NULL, so checking inside would give wrong results.Performance. A poll costs a
clock_gettimeplus acancel_mutexacquisition, so it is throttled on 64 KiB of accumulated input, asgeohashesInBoxandarrayFolddo. Worst case istokenizeQueryover short inputs: unthrottled polling was 5.95x slower, the shipped throttle 1.12x.Validation. New tests
04691_format_query_respects_time_limitand its_killcompanion assert elapsed time, not the error code: an unpatched server also raisesTIMEOUT_EXCEEDED, just tens of seconds late.timeout_overflow_mode = 'break', wherecheckTimeLimitreturns false instead of throwing, gets its own case. Both fail unpatched and pass fixed with only the binary differing, the timed case reporting 71142 ms against a 1 s limit before and 1016 ms after. A case for the retained-metadata path above fails the same way on a stored status. Fifty randomized runs at-j 1: 100/100.