Case study

Idle CPUs, 60-second queries: a global lock in ClickHouse 23.8

How a dashboard widget that needed two numbers took a ClickHouse cluster down for 48 minutes, and why the fix was a cheaper query rather than more hardware.

6 min read · Markdown

TL;DR

The symptom

A customer-facing dashboard had a widget showing two counters: items ready to be handed over, in total and today. Over a year earlier the counters had been added to an existing report function, so the widget called the full report with a page size of one and read the counters from the result. On PostgreSQL this cost about 10 ms per call, and nobody noticed.

In the morning the widget was switched to a ClickHouse cluster: two replicas, 80 cores each. Within a minute:

The widget was rolled back after 48 minutes. Idle CPU with everything timing out is the signature of a lock, not of load.

The mechanism

In ClickHouse 23.8, the shared part of the query Context is protected by a single global mutex. A query takes it when it creates a context for a subquery, reads settings, and so on. A simple query takes it a handful of times. A view with dozens of subqueries takes it thousands of times. With the old query analyzer, each scalar subquery in a global WITH is recomputed at every nesting level where it is used.

Below the mutex's ceiling, waiting is close to zero. Above it, every query on the node stands in one line, regardless of free CPU. On these nodes the ceiling was about 56–59K acquisitions per second.

Measuring it

ClickHouse counts lock acquisitions and lock wait per query. This query finds the most expensive query shapes:

SELECT
    normalized_query_hash,
    count() AS calls,
    round(avg(query_duration_ms)) AS avg_ms,
    round(avg(ProfileEvents['ContextLock'])) AS locks_per_call,
    round(avg(ProfileEvents['ContextLockWaitMicroseconds']) / 1000) AS lock_wait_ms,
    round(avg(ProfileEvents['OSCPUVirtualTimeMicroseconds']) / 1000) AS cpu_ms
FROM system.query_log
WHERE type = 'QueryFinish' AND event_time > now() - INTERVAL 1 HOUR
GROUP BY normalized_query_hash
ORDER BY sum(ProfileEvents['ContextLock']) DESC
LIMIT 20;

If lock wait is close to the query duration while CPU time is small, you are looking at this problem.

For the node as a whole, system.metric_log gives acquisitions per second and the average number of threads waiting on the lock. During the incident there were about 545 waiting threads for 500 running queries:

SELECT
    toStartOfMinute(event_time) AS minute,
    round(sum(ProfileEvent_ContextLock) / 60) AS locks_per_second,
    round(sum(ProfileEvent_ContextLockWaitMicroseconds) / 60e6, 1) AS avg_waiting_threads
FROM system.metric_log
WHERE event_time > now() - INTERVAL 3 HOUR
GROUP BY minute
ORDER BY minute;

System tables are per node, so run both on every replica.

What queries cost

Query Context lock acquisitions per call
SELECT 1 6–19
count() with FINAL over 26 parts, one parameter ~230
The report view with a page size of one (29 subqueries, 388 scalar-subquery cache misses, ~0.9 s CPU) 6,849
A pending change to the same report, as first written 44,000–67,000
The same change after rework 4,000–5,200

At about one request per second, the change in the last two rows would have consumed three quarters of the lock on its own. The rework made it more than ten times cheaper.

One formula

When the lock is saturated:

latency ≈ concurrent queries × lock acquisitions per query ÷ ceiling

500 × 6,849 ÷ 58,000 ≈ 59 seconds. The observed median was 60.

The same numbers give capacity: 58,000 ÷ 6,849 ≈ 8.5 calls per second per node. The widget sent about 43 per second across two nodes, two and a half times the ceiling.

The formula also shows why raising max_concurrent_queries would not help: throughput stays the same, and latency grows with concurrency (1,000 slots ≈ 120 seconds), while more threads and memory are held.

Versions: the fix exists, just not in 23.8

The upstream fix, "Context lock contention fix" (ClickHouse#55121), was merged in October 2023 and backported to 23.9. The cherry-pick to 23.8 (#55236) was closed without merging. 23.8 is an LTS release.

I reproduced the incident on a 16-core Docker stand: synthetic data with the same 26-part layout, 300 concurrent callers.

Setup Throughput Median latency Notes
23.8, original view 4.0 QPS 68 s 72 s of lock wait per query
24.3, old analyzer 6.0 QPS 42 s lock wait 9 ms: the lock is gone, the query is now CPU-bound (2.3 s per call)
25.3, new analyzer 25 QPS 9.9 s scalar subqueries computed once (388 → 10 cache misses), 0.53 s CPU per call
23.8, rewritten view 22 QPS — same version, no upgrade
any version, dedicated count() 40–64 QPS — 0.2–0.3 s CPU per call

24.3 removes the lock. With the new analyzer the original view failed, so we ran it with the old one. Only 25.3 with the new analyzer also stops recomputing scalar subqueries. On 80-core production nodes the absolute numbers are higher, but the ratios hold. Under load, CPU per query was 2–2.5 times the single-run figure.

What fixed it

  1. A counter is not a report. The widget came back the same day on a direct count() query: about 230 acquisitions per call instead of 6,849. It served up to ~50 requests per second with a median of 45–53 ms and no errors. A dedicated counter view was then load-tested at 400 requests per second per cluster without errors.
  2. Fewer subqueries in the report itself. Move counters into the final SELECT, avoid scalar subqueries in a global WITH, use IN instead of building arrays, compute related counters in one pass. The rewritten view returned byte-identical results and was 3.5–5 times cheaper on the same version.
  3. Limits per consumer. max_concurrent_queries_for_user and max_execution_time stop one consumer from taking all 500 slots and starving everyone else.
  4. An upgrade with a measured case. 24.3 or later for the lock, 25.3 or later with the new analyzer for repeated scalar subqueries.

Takeaways


All writing · A similar problem? contact@ivanblinov.com