Skip to content

CI: stateless tests time out due to network latency between our runners and the S3 test-data bucket #2227

Description

@CarlosFelipeOR

Type of problem

CI infrastructure — not a product bug, and not slow machines.

Summary

Stateless tests that read test.hits get killed by the 600s per-test timeout on our CI.
The same tests, on the same build type, never come close to that limit upstream.

240 timeout deaths in 90 days, concentrated in three builds:

build timeout deaths runs
amd_debug 181 104,932
arm_binary 44 67,596
amd_binary 15 2,522

Sanitizer and coverage builds are essentially unaffected (amd_msan, amd_ubsan,
arm_asan_ubsan, both coverage builds: 0).

Root cause

test.hits is not on local disk. tests/docker_scripts/create.sql:142-144 puts it on a
cache disk wrapping a web disk pointing at S3 in us-east-1:

SETTINGS
    table_disk = 1,
    disk = disk(type = cache, path = 'filesystem_caches/stateful/', max_size = '4G',
    disk = disk(type = web, endpoint = 'https://clickhouse-datasets-web.s3.us-east-1.amazonaws.com/...'));

That 4 GB cache layer exists precisely so the remote reads are paid once. But
tests/clickhouse-test randomizes the setting that disables it, 50/50:

"enable_filesystem_cache": lambda: random.randint(0, 1),

When the coin lands on 0, every column read becomes an HTTP request to us-east-1. Our
runners pay ~207ms just to open each connection to that bucket (measured below); upstream's
test durations show they do not.

Both files are byte-identical to upstream. Same code, same dataset, same randomization —
the only variable is where the runner sits.

Evidence

1. Controlled experiment — the setting isolated

Same table, same query, warm cache present, alternating only enable_filesystem_cache.
Identical result hash in every run:

test query cache=1 cache=0 ratio
00071_merge_tree_optimize_aio (6 columns) 1.25s / 1.22s 60.0s / 53.6s 46x
00154_avro (131 columns) 0.86s / 0.82s 28.1s / 26.4s 33x
03595_extract_url_parameters (1 column) 0.82s / 0.81s 3.04s / 2.82s 3.6x

The multiplier scales with how many files the query opens, not how much data it reads.

2. The cost is connection setup, not bandwidth

Measured against the bucket endpoint:

new connection:      connect 140ms -> TLS 285ms -> first byte 445ms
20 requests reusing a single connection:  0.159s total  =  8ms each

55x, and ~300ms of the 445ms is pure TCP+TLS handshake. RTT is ~137ms.

Connections are barely reused. ProfileEvents from one query with the cache off:

ReadWriteBufferFromHTTPRequestsSent:  280
ReadWriteBufferFromHTTPBytes:         13,265,792
DiskConnectionsCreated:               139
DiskConnectionsReused:                141

139 handshakes for 280 requests. On CI runners the same counters give ~207ms per
connection
(35.9s across 173 connections).

With the cache on: 306 cache hits, 9.9 MB from local disk, 4.6ms, zero HTTP.

3. Our machines are not slower — upstream comparison

Same build (amd_debug, parallel), 90 days:

test upstream p50 upstream max our p50 our max
00071_merge_tree_optimize_aio 3.08s 56.4s 2.00s 810.3s
03595_extract_url_parameters 2.67s 26.9s 2.24s 860.9s
00088_global_in_one_shard_and_rows_before_limit 0.7s 13.9s 0.7s 582.4s
00174_distinct_in_order 1.3s 25.3s 1.5s 553.0s

Our median matches or beats upstream's. CPU is fine — one failing query used 1.7s of CPU
across 395s of wall clock, 99.6% blocked on I/O. What differs is the tail: upstream's
worst case across ~27,000 runs each is 14–56s; ours reaches 810–860s.

Second failure mode, not fixed by the timeout

The same latency also trips ClickHouse's own execution-speed guard. From
tests/config/users.d/limits.yaml:

timeout_before_checking_execution_speed: 300
max_estimated_execution_time: 900

After 300s the server estimates total runtime; if the estimate exceeds 900s it aborts the
query with TOO_SLOW (error 160) — well before any test timeout. Three stateful tests
failed this way in a single recent run, at 317s, 391s and 480s.

The file's own comment says these limits are set high "so it will not limit anything". On our
infra they do.

What we did — workaround only

PR #2223 raises the per-test timeout from 600s to 1200s for amd_debug, arm_binary and
amd_binary, following the precedent already in the file for amd_tsan.

This is a workaround. It converts failures into slow runs — a test that would have failed
now burns up to 10+ minutes of CI — and it does nothing for the TOO_SLOW failures above.

What a real fix would look like

Ordered by how much of the problem they remove:

  1. Serve the test datasets from close to the runners — an S3 mirror in the runners' region,
    Hetzner object storage, or a caching HTTP proxy in the runner network. This removes both
    failure modes.
  2. Pre-warm filesystem_caches/stateful/ in the runner image, so the first read never
    goes over the network.
  3. Stop randomizing enable_filesystem_cache for stateful tests — removes the trigger
    but diverges from upstream's clickhouse-test. There is precedent in the same file:
    the azure job already sets --no-random-settings for exactly this kind of reason.

Option 1 is the only one that also fixes the TOO_SLOW failures and any future test that
reads remote data.

Open question for infra

DiskConnectionsReset: 145 (of 261 requests) appears on CI runners but not on a
developer machine running the same query. Connection reuse is poor in both, but something
is actively dropping connections in the CI network. Worth checking for a proxy, NAT or
firewall idle-timeout on the runner network — if that is fixed, the per-request cost drops
by the ~300ms handshake even without moving the data.

Metadata

Metadata

Assignees

Labels

antalyabugSomething isn't workingcicdImprovements and fixes to the CICD process

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions