Investigating a rising ClickHouse error rate
A method for turning 'errors are going up' into a short list of culprit queries, using only system.query_log: signal versus noise, new versus old query shapes, and victims versus causes.
A dashboard shows the number of failed queries on a ClickHouse cluster climbing day after day. Total query volume is flat. Nobody has changed the server. What now?
This is the method that works for that situation, written up from a real investigation and rebuilt on synthetic data so every query below can be run on your laptop. The error in question was MEMORY_LIMIT_EXCEEDED (code 241), but nothing here is specific to it. The only data source is system.query_log.
The short version of the story: a single new query shape, issued many times, was using hundreds of megabytes per run. It failed often itself and pushed everything running next to it toward the server memory limit. Once the application stopped issuing it, the error rate fell back to its old level. The interesting part is how you get from “errors are up” to that sentence.
The five questions
- Is the increase real, or is it noise and a growing denominator?
- Which error is it, and which limit was hit?
- Is the damage concentrated in a few query shapes?
- Are those shapes new, or did something old change?
- Who is the cause, and who is just a victim?
Setup: a stand-in for query_log
system.query_log does not exist in clickhouse local, so the examples use a table query_log_demo with the same column names. It holds 14 days of synthetic traffic: eight regular query shapes, plus one heavy shape that appears on day 6, grows, and disappears on day 13. The full script is at the end of the article. To run any query below on a real server, replace query_log_demo with system.query_log.
Two things to know about the real table:
- By default it logs two rows per query: a
QueryStartrow and aQueryFinishorException*row. Counting everything double-counts. Every query below filters outQueryStart. - It is per node. On a cluster, read it through
clusterAllReplicas('my_cluster', system.query_log), and remember that aGLOBAL INsubquery is needed if you filter one distributed read with the result of another.
1. Is it real?
Count errors per day, next to the number of finished queries, and compute the rate. Add the memory the failed queries held when they died: it tells you how much work was thrown away.
SELECT
event_date,
countIf(exception_code = 241) AS oom_errors,
count() AS finished,
round(oom_errors / finished * 100, 2) AS oom_pct,
round(sumIf(memory_usage, exception_code = 241) / 1e9, 1) AS gb_at_failure
FROM query_log_demo
WHERE type != 'QueryStart'
GROUP BY event_date
ORDER BY event_date; ┌─event_date─┬─oom_errors─┬─finished─┬─oom_pct─┬─gb_at_failure─┐
1. │ 2025-01-01 │ 2 │ 2000 │ 0.1 │ 0.2 │
2. │ 2025-01-02 │ 1 │ 2000 │ 0.05 │ 0.1 │
3. │ 2025-01-03 │ 0 │ 2000 │ 0 │ 0 │
4. │ 2025-01-04 │ 3 │ 2000 │ 0.15 │ 0.3 │
5. │ 2025-01-05 │ 0 │ 2000 │ 0 │ 0 │
6. │ 2025-01-06 │ 22 │ 2000 │ 1.1 │ 14.7 │
7. │ 2025-01-07 │ 36 │ 2000 │ 1.8 │ 26 │
8. │ 2025-01-08 │ 92 │ 2000 │ 4.6 │ 74.5 │
9. │ 2025-01-09 │ 107 │ 2000 │ 5.35 │ 85.5 │
10. │ 2025-01-10 │ 167 │ 2000 │ 8.35 │ 131.4 │
11. │ 2025-01-11 │ 224 │ 2000 │ 11.2 │ 182.8 │
12. │ 2025-01-12 │ 318 │ 2000 │ 15.9 │ 252.8 │
13. │ 2025-01-13 │ 1 │ 2000 │ 0.05 │ 0.2 │
14. │ 2025-01-14 │ 3 │ 2000 │ 0.15 │ 0.3 │
└────────────┴────────────┴──────────┴─────────┴───────────────┘Volume is flat, so a rising rate is not a denominator effect. When volume is not flat, the rate column is the one to trust.
Separating signal from noise
A healthy cluster always has a few failures: a client that disconnects, an occasional big query. The question is whether today’s rate is outside what that background produces. Compute a baseline from a quiet period and express each day as a number of standard deviations from it:
WITH daily AS
(
SELECT event_date,
countIf(exception_code = 241) / count() AS err_rate
FROM query_log_demo
WHERE type != 'QueryStart'
GROUP BY event_date
),
baseline AS
(
SELECT avg(err_rate) AS mu, stddevPop(err_rate) AS sigma
FROM daily WHERE event_date < '2025-01-06'
)
SELECT event_date, round(err_rate * 100, 2) AS err_pct,
round((err_rate - mu) / sigma, 1) AS z,
z > 3 AS alert
FROM daily, baseline
ORDER BY event_date; ┌─event_date─┬─err_pct─┬─────z─┬─alert─┐
1. │ 2025-01-01 │ 0.1 │ 0.7 │ 0 │
2. │ 2025-01-02 │ 0.05 │ -0.2 │ 0 │
3. │ 2025-01-03 │ 0 │ -1 │ 0 │
4. │ 2025-01-04 │ 0.15 │ 1.5 │ 0 │
5. │ 2025-01-05 │ 0 │ -1 │ 0 │
6. │ 2025-01-06 │ 1.1 │ 17.8 │ 1 │
7. │ 2025-01-07 │ 1.8 │ 29.8 │ 1 │
8. │ 2025-01-08 │ 4.6 │ 77.9 │ 1 │
9. │ 2025-01-09 │ 5.35 │ 90.7 │ 1 │
10. │ 2025-01-10 │ 8.35 │ 142.2 │ 1 │
11. │ 2025-01-11 │ 11.2 │ 191 │ 1 │
12. │ 2025-01-12 │ 15.9 │ 271.7 │ 1 │
13. │ 2025-01-13 │ 0.05 │ -0.2 │ 0 │
14. │ 2025-01-14 │ 0.15 │ 1.5 │ 0 │
└────────────┴─────────┴───────┴───────┘The z-scores here are absurd because the synthetic baseline is tiny and tidy; on real data they are smaller, and a threshold of 3 is a starting point rather than a law. What matters is the shape: the background wobbles between roughly -1 and +1.5, and the incident is not within sight of it. Choose the baseline window carefully. If it already contains part of the problem, the deviation shrinks and you under-react.
2. Which error, which limit?
First check that you are chasing the right error. Compare every non-zero code across the period before, during and after:
SELECT
exception_code,
errorCodeToName(exception_code) AS name,
countIf(event_date < '2025-01-06') AS before,
countIf(event_date >= '2025-01-06' AND event_date < '2025-01-13') AS during,
countIf(event_date >= '2025-01-13') AS after
FROM query_log_demo
WHERE exception_code != 0
GROUP BY exception_code
ORDER BY during DESC; ┌─exception_code─┬─name──────────────────┬─before─┬─during─┬─after─┐
1. │ 241 │ MEMORY_LIMIT_EXCEEDED │ 6 │ 966 │ 4 │
└────────────────┴───────────────────────┴────────┴────────┴───────┘On a real system this table has several rows, and the one that moves is your target. Code 241 has two faces, and the message text tells them apart. “Memory limit (for query) exceeded” means one query went past its own max_memory_usage. “Memory limit (total) exceeded” means the server as a whole hit its ceiling, and the query that happened to ask for the next allocation was the one that died:
SELECT
event_date,
countIf(exception LIKE '%Memory limit (for query)%') AS per_query_limit,
countIf(exception LIKE '%Memory limit (total)%') AS server_limit
FROM query_log_demo
WHERE exception_code = 241
GROUP BY event_date
ORDER BY event_date
LIMIT 3 OFFSET 5; ┌─event_date─┬─per_query_limit─┬─server_limit─┐
1. │ 2025-01-08 │ 56 │ 36 │
2. │ 2025-01-09 │ 60 │ 47 │
3. │ 2025-01-10 │ 103 │ 64 │
└────────────┴─────────────────┴──────────────┘Both kinds rise together. That already hints at the answer: some queries exceed their own limit, and the rest die because those queries are eating the headroom.
3. Is it concentrated?
normalized_query_hash is the same for queries that differ only in their literals, so it identifies a query shape. Group the failures by it:
SELECT
normalized_query_hash,
countIf(exception_code = 241) AS oom_errors,
count() AS runs,
round(oom_errors / runs * 100, 1) AS oom_pct,
min(event_date) AS first_seen,
max(event_date) AS last_seen,
round(avg(memory_usage) / 1e6) AS avg_mb
FROM query_log_demo
WHERE type != 'QueryStart'
GROUP BY normalized_query_hash
HAVING oom_errors > 0
ORDER BY oom_errors DESC
LIMIT 5; ┌─normalized_query_hash─┬─oom_errors─┬─runs─┬─oom_pct─┬─first_seen─┬──last_seen─┬─avg_mb─┐
1. │ 1698585397640420898 │ 949 │ 2037 │ 46.6 │ 2025-01-06 │ 2025-01-12 │ 806 │
2. │ 11874517917000456137 │ 11 │ 3257 │ 0.3 │ 2025-01-01 │ 2025-01-14 │ 150 │
3. │ 13022058269516533352 │ 4 │ 3233 │ 0.1 │ 2025-01-01 │ 2025-01-14 │ 45 │
4. │ 2327842345198709636 │ 3 │ 3210 │ 0.1 │ 2025-01-01 │ 2025-01-14 │ 45 │
5. │ 13481578172604398871 │ 3 │ 3254 │ 0.1 │ 2025-01-01 │ 2025-01-14 │ 45 │
└───────────────────────┴────────────┴──────┴─────────┴────────────┴────────────┴────────┘One shape accounts for almost all failures, fails nearly half the time, and averages several times the memory of its neighbours. It also has a first_seen and last_seen that do not span the whole period, which is the next clue. In a real investigation also group by user or initial_user and query_kind: knowing which application or service owns the query is most of the fix.
To get the text of a shape, fetch one example: SELECT any(query) FROM system.query_log WHERE normalized_query_hash = <hash>.
4. New, old, or changed?
There are three ways a shape can become a problem, and the query log separates them:
- It is new. Its first appearance coincides with the start of the trend.
- It got more frequent or heavier. Same hash, more runs per day, or higher average memory.
- It is old and unchanged, but the data grew. Same hash, same frequency, memory creeping up.
Compare a period before the incident with the period during it, per hash:
SELECT
normalized_query_hash,
countIf(period = 'before' AND exception_code = 241) AS err_before,
countIf(period = 'during' AND exception_code = 241) AS err_during,
countIf(period = 'before') AS runs_before,
countIf(period = 'during') AS runs_during
FROM
(
SELECT *, if(event_date < '2025-01-06', 'before', 'during') AS period
FROM query_log_demo
WHERE type != 'QueryStart' AND event_date < '2025-01-13'
)
GROUP BY normalized_query_hash
ORDER BY err_during DESC
LIMIT 3; ┌─normalized_query_hash─┬─err_before─┬─err_during─┬─runs_before─┬─runs_during─┐
1. │ 1698585397640420898 │ 0 │ 949 │ 0 │ 2037 │
2. │ 11874517917000456137 │ 3 │ 6 │ 1229 │ 1509 │
3. │ 15906855584294885080 │ 0 │ 3 │ 1262 │ 1522 │
└───────────────────────┴────────────┴────────────┴─────────────┴─────────────┘Zero runs before, thousands during: a new shape. Everything else grew only in proportion to its own traffic.
The same idea works for “when did this shape first run?” over the whole log. Note that query_log has a retention period, so “first seen” really means “first seen within retention”:
SELECT normalized_query_hash, min(event_date) AS first_seen, count() AS runs
FROM query_log_demo
GROUP BY normalized_query_hash
HAVING first_seen >= '2025-01-03'
ORDER BY first_seen; ┌─normalized_query_hash─┬─first_seen─┬─runs─┐
1. │ 1698585397640420898 │ 2025-01-06 │ 2037 │
└───────────────────────┴────────────┴──────┘Did it stop?
The error rate came back down, and the question is whether the cause went away or the problem merely moved. List the offending shapes of the incident window that no longer appear at all afterwards. EXCEPT expresses this directly:
SELECT normalized_query_hash
FROM query_log_demo
WHERE type != 'QueryStart' AND exception_code = 241 AND event_date BETWEEN '2025-01-06' AND '2025-01-12'
GROUP BY normalized_query_hash
EXCEPT
SELECT normalized_query_hash
FROM query_log_demo
WHERE event_date >= '2025-01-13'; ┌─normalized_query_hash─┐
1. │ 1698585397640420898 │
└───────────────────────┘The culprit disappeared from the traffic at the same moment the errors did. That is strong, but still circumstantial evidence; the confirming step is a person: whoever owns that application confirms they removed or changed the query. When errors stop without the query stopping, look at server-side changes instead (settings, memory limits, a background merge or mutation that was running).
5. Cause or victim?
The failing query is not necessarily the one that used the memory. With a server-wide limit, whichever query asks for the next allocation when the server is full is the one that gets the exception. So look at the neighbourhood of the failures: all queries that were running at a given moment, with their memory.
WITH toDateTime('2025-01-10 12:00:00') AS t
SELECT
normalized_query_hash,
count() AS concurrent_queries,
round(sum(memory_usage) / 1e6) AS peak_mb_sum
FROM query_log_demo
WHERE type != 'QueryStart'
AND event_date = toDate(t)
AND query_start_time <= t + 3600 AND event_time >= t
GROUP BY normalized_query_hash
ORDER BY peak_mb_sum DESC
LIMIT 3; ┌─normalized_query_hash─┬─concurrent_queries─┬─peak_mb_sum─┐
1. │ 1698585397640420898 │ 13 │ 10381 │
2. │ 11874517917000456137 │ 9 │ 1361 │
3. │ 13022058269516533352 │ 14 │ 707 │
└───────────────────────┴────────────────────┴─────────────┘The condition query_start_time <= end AND event_time >= start selects every query whose lifetime overlaps the window. Use a narrow window (seconds, or even the exact event_time_microseconds of one failure) when you have a specific failure to explain, and a wider one to see the pattern. Two caveats: memory_usage is each query’s peak, and peaks of different queries do not necessarily coincide, so the sum is an upper bound. And rows are written when a query ends, so very long queries only show up once they finish or fail.
In the original investigation this was the decisive step. At the instant of one failure, dozens of queries were running, and most used only kilobytes to a few megabytes. Ten of them, all with the same hash, were holding hundreds of megabytes each. The failures were many, but the cause was one.
What the causes turned out to be
In general terms, in this kind of incident:
- A newly deployed query shape (a new dashboard, a new endpoint, a changed ORM query) that reads or aggregates far more than anything before it. The hash did not exist until the trend started.
- Concurrency of that shape. One such query fits in memory; thirteen at once do not. The failure rate depends on how many overlap, which is why it grew over days as usage grew, and why it was bursty within a day.
- Victims. Small, well-behaved queries failing with the server-wide limit because the heavy ones had taken the headroom.
The fix was on the application side: stop issuing the query, or make it cheaper.
Making it harder to repeat
- Give the application’s user a settings profile with
max_memory_usage, and where it fitsmax_memory_usage_for_userandmax_concurrent_queries_for_user. A heavy query then fails alone, with a message that names the per-query limit, instead of taking its neighbours down. - Track error rate as a rate, with a baseline, instead of a raw count. The trend-tracking tutorial on this site shows how to keep a per-minute rollup of
query_logand compare it with the previous week. - Watch the number of new query shapes per day. A brand-new shape with a large memory footprint is the earliest signal this method finds.
Appendix: the demo table
This script creates query_log_demo and fills it. Save it as setup.sql, then run clickhouse local --path ./demo --multiquery < setup.sql. The --path option keeps the table, so the queries above can be run afterwards with clickhouse local --path ./demo --query "...".
CREATE TABLE query_log_demo
(
type Enum8('QueryStart' = 1, 'QueryFinish' = 2, 'ExceptionBeforeStart' = 3, 'ExceptionWhileProcessing' = 4),
event_date Date,
event_time DateTime,
query_start_time DateTime,
normalized_query_hash UInt64,
exception_code Int32,
exception String,
memory_usage UInt64,
query_duration_ms UInt64,
read_rows UInt64,
read_bytes UInt64,
query_kind LowCardinality(String),
user String
) ENGINE = MergeTree ORDER BY event_time;
INSERT INTO query_log_demo
WITH
toDateTime('2025-01-01 00:00:00') AS t0,
n AS i,
intDiv(i, 2000) AS day, -- 14 days, 2000 queries per day
cityHash64(i, 1) % 1000 / 1000 AS r1,
cityHash64(i, 2) % 1000 / 1000 AS r2,
-- shapes 1..8 are the regular workload; shape 9 is the newcomer (days 6 to 12)
if(day >= 5 AND day < 12 AND r1 < 0.05 + 0.03 * (day - 5), 9, 1 + cityHash64(i, 3) % 8) AS shape,
cityHash64('shape', shape) AS hash,
-- regular queries use 10-80 MB, shape 4 is a bit heavier, shape 9 is a memory hog
multiIf(shape = 9, 600000000 + cityHash64(i, 4) % 400000000,
shape = 4, 100000000 + cityHash64(i, 4) % 100000000,
10000000 + cityHash64(i, 4) % 70000000) AS mem,
-- probability that the query dies with MEMORY_LIMIT_EXCEEDED
multiIf(shape = 9, 0.15 + 0.08 * (day - 5), shape = 4, 0.004, 0.0005) AS p_fail,
r2 < p_fail AS failed
SELECT
if(failed, 'ExceptionWhileProcessing', 'QueryFinish'),
toDate(t0 + toIntervalSecond(i * 43 % 86400) + toIntervalDay(day)),
t0 + toIntervalSecond(i * 43 % 86400) + toIntervalDay(day),
t0 + toIntervalSecond(i * 43 % 86400) + toIntervalDay(day) - toIntervalSecond(1),
hash,
if(failed, 241, 0),
multiIf(NOT failed, '',
shape = 9 AND cityHash64(i, 9) % 10 < 6, 'Code: 241. DB::Exception: Memory limit (for query) exceeded',
'Code: 241. DB::Exception: Memory limit (total) exceeded'),
mem,
if(shape = 9, 4000, 50 + cityHash64(i, 5) % 400),
1000 + cityHash64(i, 6) % 100000,
100000 + cityHash64(i, 7) % 10000000,
'Select',
['dashboard', 'api', 'etl'][1 + cityHash64(i, 8) % 3]
FROM (SELECT number AS n FROM numbers(2000 * 14));Docs: system.query_log, system.errors, settings profiles and memory limits.
Discussion
Comments live in GitHub Discussions. Sign in with GitHub to join in.