Detecting Slow Queries with system.query_log

A user reports that “the dashboard is slow,” a latency alert fires, or a node’s CPU pins at 100% — and you have minutes to find the one query out of millions that is responsible. system.query_log holds the answer, but only if you interrogate it in the right order: filter to finished queries, rank by the dimension that matches the symptom, collapse literals into query shapes, then read the low-level counters that separate a genuinely expensive query from one that is merely frequent. This is the exact drill-down, from a raw symptom to the offending statement and the reason it is slow.

Prerequisites

system.query_log enabled on the node (log_queries = 1 in the active profile)
SELECT privilege on system.query_log for your investigating role
The parent query performance monitoring reference for the schema and column semantics
A recent window of traffic in the log — at least the incident timeframe, not yet expired by TTL
Optional: clickhouse-client for SYSTEM FLUSH LOGS and EXPLAIN, since these are DDL/utility statements

The triage order

Slow-query detection is a funnel, not a single query. Each stage narrows the search: force a flush so the incident’s rows are on disk, rank finished queries by the resource the symptom points at, group the survivors into shapes, and finally explain the worst shape to learn why it is slow.

Step 1 — Flush the buffer and scope the window

The row for the query you are chasing may still be in the in-memory buffer. Drain it first, then confirm the log holds the incident window.

sql

SYSTEM FLUSH LOGS;

SELECT min(event_time) AS oldest, max(event_time) AS newest, count() AS rows
FROM system.query_log
WHERE event_time > now() - INTERVAL 2 HOUR;

Expected: newest within a few seconds of now and a row count consistent with your traffic. If the window you need has already aged past the log’s TTL, stop here — the evidence is gone, and lengthening retention is a task for building query log retention and dashboards.

Step 2 — Rank finished queries by the symptom

Always filter type = 'QueryFinish'; only the finish row carries the final measurements, and including QueryStart doubles every count. Which column you sort by depends on the symptom.

Latency symptom — sort by query_duration_ms:

sql

SELECT
    event_time,
    query_duration_ms                    AS ms,
    formatReadableQuantity(read_rows)    AS rows_read,
    formatReadableSize(memory_usage)     AS mem,
    user,
    substr(normalizeQuery(query), 1, 80) AS shape
FROM system.query_log
WHERE type = 'QueryFinish'
  AND query_kind = 'Select'
  AND event_time > now() - INTERVAL 1 HOUR
ORDER BY query_duration_ms DESC
LIMIT 20;

I/O symptom (disk saturated) — sort by read_rows / read_bytes:

sql

SELECT event_time, formatReadableQuantity(read_rows) AS rows_read,
       formatReadableSize(read_bytes) AS bytes_read, query_duration_ms AS ms,
       substr(normalizeQuery(query), 1, 80) AS shape
FROM system.query_log
WHERE type = 'QueryFinish' AND event_time > now() - INTERVAL 1 HOUR
ORDER BY read_rows DESC LIMIT 20;

Memory symptom (OOM risk) — sort by memory_usage:

sql

SELECT event_time, formatReadableSize(memory_usage) AS peak_mem,
       query_duration_ms AS ms, user,
       substr(normalizeQuery(query), 1, 80) AS shape
FROM system.query_log
WHERE type = 'QueryFinish' AND event_time > now() - INTERVAL 1 HOUR
ORDER BY memory_usage DESC LIMIT 20;

Expected output: the top rows are your suspects. A query reading a row count close to the table’s full cardinality is a full scan; one with memory_usage near the max_memory_usage budget is a failed-or-nearly-failed aggregation.

Step 3 — Group literals into query shapes

Individual rows are noisy because the same statement appears with different constants. normalized_query_hash gives every structurally-identical statement the same 64-bit hash, so you can aggregate cost per shape and see which pattern — not which one-off — is expensive.

sql

SELECT
    normalized_query_hash                    AS shape_hash,
    any(normalizeQuery(query))               AS example,
    count()                                  AS runs,
    round(sum(query_duration_ms) / 1000, 1)  AS total_seconds,
    round(avg(query_duration_ms))            AS avg_ms,
    round(quantile(0.99)(query_duration_ms)) AS p99_ms,
    formatReadableQuantity(sum(read_rows))   AS total_rows
FROM system.query_log
WHERE type = 'QueryFinish'
  AND query_kind = 'Select'
  AND event_time > now() - INTERVAL 3 HOUR
GROUP BY shape_hash
ORDER BY total_seconds DESC
LIMIT 15;

Sorting by total_seconds (the sum of durations) is what distinguishes a shape that is slow once from a shape that is cheap but runs thousands of times — the latter can dominate cluster time while never appearing in a per-query top-20. This is the single most useful query for capacity work: the top three shapes usually account for most of the load.

Step 4 — Read ProfileEvents to classify the cost

query_duration_ms tells you a query is slow; ProfileEvents tells you why. The map carries hundreds of counters — pull the ones that separate a full scan from a CPU-bound aggregation from a disk-bound read.

sql

SELECT
    query_duration_ms                                       AS ms,
    read_rows,
    ProfileEvents['SelectedMarks']                          AS marks_read,
    ProfileEvents['SelectedParts']                          AS parts_read,
    ProfileEvents['OSCPUVirtualTimeMicroseconds']           AS cpu_us,
    ProfileEvents['ReadBufferFromFileDescriptorReadBytes']  AS disk_read_bytes,
    ProfileEvents['NetworkReceiveBytes']                    AS net_bytes
FROM system.query_log
WHERE type = 'QueryFinish'
  AND normalized_query_hash = 12345678901234567890   -- from Step 3
  AND event_time > now() - INTERVAL 3 HOUR
ORDER BY query_duration_ms DESC
LIMIT 10;

A high marks_read relative to the table’s total marks means the sparse index barely pruned — a scan problem. High cpu_us with modest read_rows means a heavy expression or aggregation — a compute problem. High disk_read_bytes with low CPU means cold data and an I/O-bound query. Each points at a different fix.

Step 5 — Isolate full-scan queries directly

Full scans are the most common cause of a sudden slowdown, and you can flag them without staring at rankings: compare read_rows against the table’s approximate size. A ratio near 1 means the query read almost the whole table.

sql

SELECT
    tables[1]                              AS scanned_table,
    substr(normalizeQuery(query), 1, 90)   AS shape,
    formatReadableQuantity(read_rows)      AS rows_read,
    query_duration_ms                      AS ms,
    ProfileEvents['SelectedMarks']         AS marks
FROM system.query_log
WHERE type = 'QueryFinish'
  AND query_kind = 'Select'
  AND length(tables) = 1
  AND read_rows > 50000000            -- tune to a fraction of your largest table
  AND event_time > now() - INTERVAL 1 HOUR
ORDER BY read_rows DESC
LIMIT 20;

Confirm the suspicion by explaining the shape — EXPLAIN indexes = 1 shows the granule count actually read versus available:

sql

EXPLAIN indexes = 1
SELECT count() FROM analytics.events_raw WHERE user_id = 42;

If the plan reports Granules: 122070/122070, the filter (user_id, a trailing sort-key column) cannot use the primary index, and the query scans every granule. The remedy — realigning the WHERE with the leading ORDER BY columns or adding a skipping index — is a storage decision covered in the MergeTree engine deep dive.

Step 6 — Set a logging threshold to cut noise

Once the acute incident is resolved, keep the log focused on statements worth investigating by dropping trivial sub-threshold queries. log_queries_min_query_duration_ms logs only queries slower than the given wall-clock time.

sql

-- Session scope for a targeted investigation:
SET log_queries_min_query_duration_ms = 200;

To apply it durably, set it in the profile rather than per session:

xml

<!-- /etc/clickhouse-server/users.d/log_thresholds.xml -->
<clickhouse>
    <profiles>
        <default>
            <log_queries>1</log_queries>
            <log_queries_min_query_duration_ms>200</log_queries_min_query_duration_ms>
        </default>
    </profiles>
</clickhouse>

Use this deliberately: a threshold that is too high hides a flood of fast-but-frequent queries whose aggregate cost is large — exactly the shapes Step 3 surfaces. Keep it low (or zero) on clusters where you care about total time burned, not just per-query latency.

Verification

Confirm your investigation is reading only successful queries and that the threshold is in effect:

sql

SYSTEM FLUSH LOGS;

SELECT
    type,
    count()                          AS rows,
    round(min(query_duration_ms))    AS min_ms,
    round(quantile(0.99)(query_duration_ms)) AS p99_ms
FROM system.query_log
WHERE query_kind = 'Select'
  AND event_time > now() - INTERVAL 15 MINUTE
GROUP BY type
ORDER BY rows DESC;

You should see a QueryFinish bucket whose min_ms sits at or above your configured log_queries_min_query_duration_ms, and separate ExceptionWhileProcessing rows for any failures — never mixed into the success set.

Gotchas & edge cases

QueryStart rows have zeroed measurements. A QueryStart row exists the moment a query begins, but its query_duration_ms, read_rows, and memory_usage are 0 — they are only known at finish. Ranking without type = 'QueryFinish' buries real offenders under a pile of zero-cost start rows.
Failed queries carry misleading durations. An ExceptionWhileProcessing row’s query_duration_ms is the time until the query failed (often a timeout at exactly max_execution_time), and its read_rows is partial. Including these in a latency percentile inflates the tail with events that never returned a result.
normalized_query_hash ignores literals but not structure. Two queries that differ only in a WHERE constant share a hash; two that differ in column order or an added GROUP BY do not. A schema or query-builder change silently creates a new shape, so a regression can look like a brand-new hash appearing rather than an existing one slowing down.
read_rows counts rows read, not rows returned. A query returning ten rows after scanning a billion has read_rows near a billion and result_rows of ten. Judge scan cost by read_rows; judge result size by result_rows. Confusing them makes an efficient point lookup and a catastrophic full scan look identical.
The log lags by flush_interval_milliseconds. Without SYSTEM FLUSH LOGS, the most recent 7.5 seconds (the default) of queries are invisible. During a fast-moving incident that window is exactly where your offender lives.

Query performance monitoring — the parent reference for the log schema, percentiles, and alerting.
Building query log retention and dashboards — keep enough history for these queries to reach the incident window.
MergeTree engine deep dive — why a filter off the sort key turns into a full scan.

Up: Query Performance Monitoring