Repository navigation
perf: skip latency timing nothing records; build rows in fewer calls (stacked on #1059) - #1062
vuanhphung wants to merge 4 commits into
Conversation
log_latency timed every decorated call (execute, execute_async, metadata calls) and then dropped the result when telemetry was off and DEBUG logging was disabled, which is always the case on kernel connections. It now checks first and calls the method directly. Row factories built each row through Row.__call__, _create_row, Row.__new__ and Row.__setattr__; they now build the tuple and set __fields__ directly, producing the same object. Single-thread benchmark of one-row kernel queries with the kernel faked: 17.2 -> 16.2 us of Python per query; a 5-column row factory call drops from 402 to 288 ns. Signed-off-by: Vu Anh Phung <[email protected]> Co-authored-by: Isaac <[email protected]>
GitHub Actions
Error
GitHub Actions
Inactive
![peco-review-bot[bot]](https://avatars.githubusercontent.com/in/3801177?s=60&v=4){kind=small}
There was a problem hiding this comment.
Verdict: 1 Low
Looks good. I found 1 low-severity issue: a unit test asserts a timing-dependent log message and could fail intermittently on CI. Both production changes behave the same as before. The early return in log_latency gives the same telemetry and debug-log results, because ResultSetDownloadHandler has no connection and so was never exported anyway. Building rows through tuple.__new__ plus a direct write to __dict__ gives the same object that Row.__new__ and Row.__setattr__ produced. Nit: the log_latency docstring ("measures the execution time…") and the leftover "Fast check" comment don't mention that nothing is timed when telemetry and DEBUG logging are both off.
Match "execute completed in <n>ms" instead of 0ms, so a slow CI runner can't fail it, and say in the log_latency docstring and comment that nothing is timed when telemetry and DEBUG logging are both off. Signed-off-by: Vu Anh Phung <[email protected]> Co-authored-by: Isaac <[email protected]>
GitHub Actions
Inactive
GitHub Actions
Inactive
GitHub Actions
Error
GitHub Actions
Error
There was a problem hiding this comment.
Verdict: 1 Nit
Looks good: I found no correctness issues. The early return in log_latency keeps the previous behaviour whenever telemetry or DEBUG logging is on. ResultSetDownloadHandler has no connection, so it never exported before this change either. The inlined Row construction produces the same object Row.__setattr__ would have built, and the new tests cover the changed branches.
Other findings
- ⚪ Nit —
log_latencynow readsconnection.telemetry_enabledbefore the wrapped call rather than after it. That is equivalent today becauseConnection.telemetry_enabledis only set inConnection.__init__(client.py:474). A short note in the wrapper comment that the flag is read once, before the call, would keep a future change that toggles it mid-call from quietly diverging.
…call Signed-off-by: Vu Anh Phung <[email protected]> Co-authored-by: Isaac <[email protected]>
GitHub Actions
Inactive
GitHub Actions
Inactive
GitHub Actions
Error
There was a problem hiding this comment.
Verdict: 1 Low
Looks good. Both changes keep the existing behaviour: the latency wrapper still exports when telemetry is on (including on exceptions), and the inlined Row construction produces the same object as Row.__new__ + __setattr__ did. One low finding: the fast-path test can't fail if the optimization regresses.
Patch the module's clock and assert monotonic() is not called with telemetry and DEBUG logging off (or without a connection), and is called when either is on. The fake clock also makes the logged and exported latency exact. Signed-off-by: Vu Anh Phung <[email protected]> Co-authored-by: Isaac <[email protected]>
GitHub Actions
Inactive
GitHub Actions
Inactive
GitHub Actions
Error
GitHub Actions
Inactive
What type of PR is this?
Stacked on #1059 (base
perf/rd-py-overhead-3); review only the top commit.Description
Two pieces of per-call Python work that run on every query, on every backend.
log_latency(onexecute(),execute_async()and the metadata calls) timed each call and then threw the timing away when the connection's Python telemetry was off and DEBUG logging was disabled. That is always the case on kernel connections, which export telemetry from the kernel. The wrapper now checks both first and calls the method directly when nothing would record the latency. With telemetry on, or DEBUG enabled, it behaves as before, including exporting on exceptions.Each fetched row was built through
Row.__call__,_create_row,Row.__new__andRow.__setattr__.Row.__call__and_create_rownow build the tuple and set__fields__directly, so each row takes fewer Python calls. The resulting object is the same: aRowwhose__dict__holds__fields__. Pickling,repr,asDict, attribute and key access, and the too-many-values error are unchanged.How is this tested?
New unit tests cover the decorator (no timing, export or log line when telemetry and DEBUG are off, a debug line when DEBUG is on, export with telemetry on even when the call raises, objects without a connection) and
Row(factory rows, fewer values, too many values, read-only,_create_row, pickle round trip).test_row.pyalso passes against the base of this stack. The decorator tests patch the clock and check that nothing is timed on the fast path, so two of them fail against the base. The full unit suite passes (-m "not realkernel", andtest_session.py -m realkernel); mypy and black (22.3.0 and 26.3.1) are clean.Single-thread benchmark: a real
use_kernelconnection with the kernel session faked, so only Python runs. Each query is a fresh cursor,execute("SELECT 1"),fetchall()and close. 6 interleaved rounds, medians:Rowfactory call, 5 columnsRows matter most on larger results.
ResultSet._convert_arrow_table(the Thrift/SEA row path) on a 100,000 x 5 table, 3 interleaved rounds, best of 7:_disable_pandas=TruepathOn one-row queries the saving does not show in QPS. A one-process client running
SELECT 1on 800 threads is limited by GIL hand-offs: each query releases the GIL 7 times, 6 of them in pyarrow's C-data-interface imports. That makes 1 µs of GIL-held Python worth about 0.7% QPS. Measured with the full set of open kernel-path PRs (#1059, #1052, #1050, #1051, #1053) and the matching kernel build, 3 interleaved rounds each:SELECT 1All within run-to-run noise. The client ran on 8 cores.
#1061 (with databricks/databricks-sql-kernel#467) cuts the hand-offs to one per query, which makes the GIL-held Python matter more. On top of it (same PR set plus #1061, the kernel PRs plus #467), Rust mock, 30 ms server time, 7 client cores, 20 s, 3 interleaved rounds:
SELECT 1, one processLive on the same stack (staging X-Large, 1,600 sessions, 60 s, 8 client cores), the results are within noise: base 6503 / 6489 avg QPS vs 6984 / 6669 / 6222. A third base round hit a cold warehouse and is left out. The client is CPU-bound at that load.
Related Tickets & Documents
Stacked on #1059.
This pull request and its description were written by Isaac.