Skip to content

perf(telemetry): don't let slow or rate-limited telemetry delay interpreter exit - #1028

Open
vuanhphung wants to merge 2 commits into
mainfrom
perf/close-path
Open

vuanhphung wants to merge 2 commits into
mainfrom
perf/close-path

Conversation

@vuanhphung

@vuanhphung vuanhphung commented Nov 12, 2026 •

Copy link
Copy Markdown
Collaborator

What type of PR is this?

  • Other (performance)

Description

connection.close() doesn't wait for telemetry: the final flush is submitted to the telemetry ThreadPoolExecutor, which is then shut down with wait=False, and the comment says that is "to allow process to exit immediately". Since Python 3.9, though, concurrent.futures joins every executor worker at interpreter exit. So a script that closes its connection and ends still waits for the final /telemetry-ext POST, including its retries. On the pecotesting warehouse /telemetry-ext intermittently returns 429 with Retry-After: 1. The telemetry HTTP client sleeps max(Retry-After, delay_max=10 s) per retry for up to 5 retries, so the process stayed alive 10–51 s after close(). A hung endpoint could hold it for the 900 s request timeout.

Telemetry sends now run on a small executor whose workers are daemon threads. An atexit hook waits up to TelemetryClientFactory.EXIT_FLUSH_TIMEOUT_SECONDS (3 s) for sends that are still in flight, including those of an executor already shut down by the last close(). In the normal case the final flush completes in ~120 ms, well inside the bound, and is delivered exactly as before. Only a send still pending after 3 s (a slow endpoint, or a 429 retry sleep) is dropped instead of blocking exit. Nothing else changes: close() latency, retries during normal operation, the circuit breaker, and the flush thread. With #868 (cap retry sleeps at delay_max instead of using it as a floor), a Retry-After: 1 retry would also fit inside the bound.

Interpreter exit lag (time from the end of the script to process exit after conn.close()), main → this PR:

Case main this PR
Live pecotesting, /telemetry-ext 200 (median; 12 vs 9 runs) 188 ms 184 ms
Live pecotesting, runs where /telemetry-ext returned 429 (3 vs 6 runs) 10.2 s, 10.2 s, 51.0 s 3.07 s (max)
Mock, 429 Retry-After: 1 (median, n=5) 50.3 s 3.07 s
Mock, 503 without Retry-After (median, n=5) 50.3 s 3.07 s
Mock, telemetry responds in 8 s (median, n=5) 8.07 s 3.07 s
Mock, telemetry 200 in 40 ms (median, n=7) 106 ms 107 ms

Over 15 interleaved live rounds, exit lag p95 went from 10.2 s to 3.07 s and max from 51.0 s to 3.07 s. The trade-off is in the 429 runs: main eventually delivered that batch (after 10–51 s), and this PR drops it at the 3 s bound. Every run that got a 200 delivered its telemetry on both. conn.close() itself is unchanged (~43 ms on a 40 ms-RTT mock, ~80 ms live). With 200 connections closing concurrently, close p50/p99 is 121/250 ms on main vs 126/247 ms here (noise), and the mock server received all 400 telemetry events on both.

How is this tested?

  • Unit tests
  • E2E Tests
  • Manually

New unit tests cover the executor (bounded daemon workers, result/exception propagation, shutdown draining queued work, wait_until_idle), the bounded exit wait across a shut-down executor, a subprocess test in which a quick send is delivered at exit and a stuck one doesn't block it (on main that subprocess hangs until it is killed), and a fork test showing that a child doesn't inherit the parent's in-flight sends. The full unit suite passes. test_telemetry_e2e.py, test_concurrent_telemetry.py and the close/cancel tests in test_driver.py pass against a live warehouse. Mock numbers come from a local Thrift-over-HTTP server with 40 ms RTT; live numbers come from interleaved single-connection runs against pecotesting.

Related Tickets & Documents

N/A

This pull request and its description were written by Isaac.

The final telemetry flush on close is submitted to a ThreadPoolExecutor,
whose workers are joined at interpreter exit. When /telemetry-ext is slow
or returns 429 (retried with 10 s sleeps), the process could not exit
until the retries finished: 10-50 s on a rate-limited endpoint, up to the
900 s request timeout on a hung one.

Run telemetry sends on daemon worker threads instead, and at exit wait at
most EXIT_FLUSH_TIMEOUT_SECONDS (3 s) for in-flight sends, so the normal
final flush is still delivered before the process exits.

Signed-off-by: Vu Anh Phung <vu.phung@databricks.com>
Co-authored-by: Isaac <no-reply@databricks.com>

@peco-review-bot peco-review-bot Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Verdict: 1 Low

Looks good, with one low-severity edge case. A forked child can be left with a stale in-flight count, so its interpreter exit always waits the full 3 s. The daemon-executor design, the bounded atexit wait across executors that were already shut down, and the subprocess regression test all look correct for the main use case.

Sends in flight in the parent at fork time stayed counted in the child, so
a child that sent its own telemetry always waited the full exit bound.
Reset each executor's queue, workers, count and lock after fork (the parent
still sends the work it queued), and start a worker before queueing so the
count only covers work some worker will run.

Signed-off-by: Vu Anh Phung <vu.phung@databricks.com>
Co-authored-by: Isaac <no-reply@databricks.com>

@peco-review-bot peco-review-bot Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

✅ No issues identified by the review bot.

This branch was previously deployed

1 inactive deployment
azure-prod — 26efb872 Deployed Nov 12, 2026 by peco-review-bot[bot] via followup #1834
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant