firebolt: time queries on the same boundary as the other entries - #1620
Conversation
The three Firebolt entries recorded the response's own
`.statistics.elapsed`. That value stops well before Firebolt has finished
answering: the engine writes the result rows in one chunk of the chunked
HTTP response and then emits the trailing `"statistics"` object of the same
response tens of milliseconds later, carrying an `elapsed` captured before
that gap. A curl trace of Q41 at 192 threads:
+0.000 upload completely sent off
+0.051 <= Recv data, 553 bytes "query"/"meta"/"data"
+0.113 <= Recv data, 298 bytes "rows", "statistics": {"elapsed": 0.031}
+0.113 <= Recv data, 5 bytes terminating chunk
The gap tracks the engine's thread count - about 2 ms at 8 threads, 15 ms
at 96, 55 ms at 192 - so it barely shows on c6a.4xlarge and dominates the
cheap queries on the metal machines.
`clickhouse-client --time`, which the reference entry uses, prints the
server's elapsed_ns from the final Progress packet, and TCPHandler sends
that packet after the last result block has been written. So it ends where
Firebolt's number ought to end too; this is not about charging Firebolt for
teardown that other engines also hide.
Measure from "request sent" to "last response byte" instead, which is the
same boundary: `%{time_total} - %{time_pretransfer}` leaves DNS and TCP
setup out, exactly as the ClickHouse figure does. This is not a client-side
guess - Firebolt's own
information_schema.engine_query_history.duration_us agrees with it to
within 1.2% mean absolute error across all 43 queries, while
`.statistics.elapsed` is up to 3.6x lower:
Q1 @192 threads elapsed 0.0237 duration_us 0.0784 measured 0.0792
Q19 @192 threads elapsed 0.0195 duration_us 0.0693 measured 0.0702
Q33 @192 threads elapsed 0.4726 duration_us 0.5182 measured 0.5192
Per-query geometric mean of the correction is 1.05x at 16 threads and 1.78x
at 192, so the existing c6a.4xlarge results are close to unaffected and the
c6a.metal / c7a.metal-48xl / c8g.metal-48xl ones need re-running.
`.statistics.elapsed` is still parsed, but only as a guard against a
truncated response that happens to parse as JSON.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
GitHub Actions
Error
…ge, c6a.metal, c6a.xlarge, c7a.metal-48xl, c8g.4xlarge, c8g.metal-48xl)
|
Results for Logs:
|
1 participant
All three Firebolt entries record the response's own
.statistics.elapsed. That value stops well before Firebolt has finished answering the request.What the number leaves out
Firebolt writes the result rows in one chunk of its chunked HTTP response, then emits the trailing
"statistics"object of the same response tens of milliseconds later — and theelapsedinside that late chunk was captured before the gap.curl --trace-timeon Q41 with 192 threads:The gap tracks the engine's thread count — roughly 2 ms at 8 threads, 15 ms at 96, 55 ms at 192 — so it is invisible on
c6a.4xlargeand dominates the cheap queries on the metal machines.Why this is an alignment fix, not a penalty
clickhouse-client --timeprints the server'selapsed_nsfrom the final Progress packet (ProgressIndication::getElapsedNanoseconds()prefers the server value; the client stopwatch is only a fallback for old servers), andTCPHandler::processOrdinaryQuerysends that packet aftersendData(state, {}), i.e. after the last result block is on the socket. Verified: the same query is 0.024–0.028 s withFORMAT Nulland 0.207–0.276 s withFORMAT TSVto the client, so serialization and send are inside the number.So the reference entry's clock stops at "last result byte written". Firebolt's 60 ms happens before its last result byte is written. Including it makes the two identical; it is not charging Firebolt for teardown that other engines also hide.
The replacement
%{time_total} - %{time_pretransfer}: same boundary, with DNS/TCP setup excluded exactly as the ClickHouse figure excludes it.This is not a client-side guess. Firebolt's own
information_schema.engine_query_history.duration_usagrees with it to within 1.2% mean absolute error over all 43 queries, while.statistics.elapsedis up to 3.6x lower:.statistics.elapsedduration_use2e_duration_usThe engine agreeing with the wire also rules out a Nagle / delayed-ACK artifact.
.statistics.elapsedis still parsed, but only as a guard against a truncated response that happens to parse as JSON. Error paths were re-tested against a live container: query error → exit 1 with the server's message, connection refused → exit 1 with a clear message, success → timing as the last stderr line (matches the driver's^[0-9]+(\.[0-9]+)?$extraction).Effect on the existing results
Per-query geometric mean of the correction is 1.05x at 16 threads and 1.78x at 192, measured on a 96-core box with
max_threadsforced to each value — an estimate for the real machines, but the publishedelapsedfloor onc7a/c8galready sits in the 192-thread regime.So
c6a.4xlargeis close to unaffected and thec6a.metal/c7a.metal-48xl/c8g.metal-48xlresults need re-running. Note that the default PR benchmark only coversc6a.4xlarge, where this change is nearly a no-op — amachine:all(or at leastmachine:c7a.metal-48xl/machine:c8g.metal-48xl) label is needed to see or replace the affected numbers.Independent of #1619, which fixes the broken
EventDateconstants in the two Parquet entries; different files, no conflict.🤖 Generated with Claude Code