Query Performance Monitoring

Without query observability, a ClickHouse cluster degrades silently: a mis-keyed dashboard starts full-scanning a billion rows, a runaway aggregation quietly climbs toward the memory ceiling, and nobody knows until latency graphs turn red or the OOM killer pages the on-call engineer. system.query_log is the ground truth that closes that gap — every executed statement leaves a row recording its duration, rows read, bytes scanned, peak memory, and a full ProfileEvents map of low-level counters. This page is the working reference for turning that raw log into a latency SLA you can defend: how the schema is shaped, how flushing and retention work, how to compute percentiles and rank the heaviest query shapes, and how to wire the whole thing into alerts so slow queries surface before a human does.

Query performance monitoring is owned by whoever runs the ClickHouse cluster — a platform or DevOps team — because it spans every tenant and workload. The signal it produces feeds three consumers: capacity planning (are we running out of CPU or memory headroom), regression detection (did a deploy make the p99 worse), and incident triage (which query is saturating I/O right now). Everything downstream depends on the query log being enabled, flushed promptly, and retained long enough to compare today against last week. This reference sits inside the broader monitoring, observability, and operations practice and pairs with the merge- and replication-health signals that live alongside it.

How a query becomes a monitored signal

A query is not logged the instant it starts. ClickHouse writes log rows into an in-memory buffer and flushes them to the system.query_log MergeTree table on a timer (or when you call SYSTEM FLUSH LOGS). From there, aggregation queries or a materialized view roll the raw rows into percentiles and top-N tables that a dashboard reads and an alert rule evaluates.

Two facts about this topology govern everything that follows. First, the log is asynchronous: the row for a query that finished two seconds ago may still be sitting in the in-memory buffer, so any near-real-time diagnostic must call SYSTEM FLUSH LOGS first or accept a lag of up to flush_interval_milliseconds. Second, the log is itself a MergeTree table on the same node — it consumes disk, generates parts, and must be partitioned and TTL-expired like any other table, or it will grow until it competes with the workload it is supposed to observe.

Core DDL / configuration reference

system.query_log is created automatically from the <query_log> block in the server configuration. You do not run CREATE TABLE for it; you shape it in XML (or a YAML override) and ClickHouse provisions the table on start. The block below is a production-oriented configuration with inline commentary.

<!-- /etc/clickhouse-server/config.d/query_log.xml -->
<clickhouse>
    <query_log>
        <database>system</database>
        <table>query_log</table>
        <!-- Daily partitions keep each part bounded and make TTL drops cheap. -->
        <partition_by>toYYYYMMDD(event_date)</partition_by>
        <!-- Retain 30 days on the node; ship older data out if you need history. -->
        <ttl>event_date + INTERVAL 30 DAY DELETE</ttl>
        <!-- Order the log for the queries you actually run against it. -->
        <order_by>(event_date, event_time, query_duration_ms)</order_by>
        <!-- Buffer flush cadence. 7500 ms is the default; lower it for fresher data. -->
        <flush_interval_milliseconds>7500</flush_interval_milliseconds>
        <!-- Cap rows held in memory between flushes so a burst cannot bloat RAM. -->
        <max_size_rows>1048576</max_size_rows>
        <reserved_size_rows>8192</reserved_size_rows>
    </query_log>
</clickhouse>

The relevant columns of the resulting table — inspect the live schema with DESCRIBE system.query_log — are worth internalizing because every diagnostic below selects from them:

-- The columns that carry the performance signal.
SELECT name, type
FROM system.columns
WHERE database = 'system' AND table = 'query_log'
  AND name IN (
    'type', 'event_time', 'query_duration_ms', 'read_rows', 'read_bytes',
    'written_rows', 'result_rows', 'memory_usage', 'query', 'query_kind',
    'normalized_query_hash', 'exception_code', 'ProfileEvents', 'user'
  )
ORDER BY name;

The type column is the single most important filter. Each query produces at least two rows: a QueryStart row when it begins and a QueryFinish row when it succeeds — or ExceptionBeforeStart / ExceptionWhileProcessing if it fails. Almost every performance query filters type = 'QueryFinish', because only the finish row carries the final query_duration_ms, read_rows, and memory_usage. Counting without that filter double-counts every statement.

ProfileEvents is a Map(String, UInt64) of low-level counters accumulated during execution — hundreds of them, addressed by name. The high-value keys for performance work are SelectedMarks and SelectedRanges (how much of the sparse index survived pruning), OSCPUVirtualTimeMicroseconds (real CPU burned), RealTimeMicroseconds, ReadBufferFromFileDescriptorReadBytes (physical disk read), and MemoryTrackerPeakUsage. You extract a single counter with map subscript:

-- Pull one ProfileEvents counter out of the map for finished SELECTs.
SELECT
    query_duration_ms,
    read_rows,
    ProfileEvents['SelectedMarks']      AS selected_marks,
    ProfileEvents['SelectedRanges']     AS selected_ranges,
    ProfileEvents['OSCPUVirtualTimeMicroseconds'] AS cpu_us
FROM system.query_log
WHERE type = 'QueryFinish'
  AND query_kind = 'Select'
  AND event_time > now() - INTERVAL 15 MINUTE
ORDER BY query_duration_ms DESC
LIMIT 20;

Step-by-step implementation

1. Confirm the log is enabled and flushing

A server with query_log disabled — or one where a session set log_queries = 0 — is blind. Verify both the server default and the effective session value, then force a flush so the freshest rows are visible.

SELECT name, value FROM system.settings
WHERE name IN ('log_queries', 'log_query_threads', 'log_queries_min_query_duration_ms');

SYSTEM FLUSH LOGS;   -- drain the in-memory buffer to the table now

Confirm the table exists and holds recent rows:

SELECT max(event_time) AS newest, count() AS rows_last_hour
FROM system.query_log
WHERE event_time > now() - INTERVAL 1 HOUR;

newest should be within flush_interval_milliseconds of now. If the table is empty, log_queries is off; enable it in users.xml or the default profile.

2. Establish the latency baseline with percentiles

Averages hide the tail that actually pages people. Compute a full quantile spread per minute so you can see p50 drift apart from p99 — the signature of a few pathological queries dragging the tail.

SELECT
    toStartOfMinute(event_time)               AS minute,
    count()                                   AS queries,
    round(quantile(0.50)(query_duration_ms))  AS p50_ms,
    round(quantile(0.90)(query_duration_ms))  AS p90_ms,
    round(quantile(0.99)(query_duration_ms))  AS p99_ms,
    round(max(query_duration_ms))             AS max_ms
FROM system.query_log
WHERE type = 'QueryFinish'
  AND query_kind = 'Select'
  AND event_time > now() - INTERVAL 3 HOUR
GROUP BY minute
ORDER BY minute DESC;

A healthy read workload shows p50 and p99 within roughly one order of magnitude of each other. When p99 detaches and climbs while p50 stays flat, a specific query shape has regressed — step 3 finds it.

3. Rank the heaviest query shapes

Ranking individual queries is noisy because literals differ. normalized_query_hash collapses statements that are identical except for constants into one shape, so you can aggregate cost per shape rather than per literal.

SELECT
    normalized_query_hash                       AS shape,
    any(normalizeQuery(query))                  AS example,
    count()                                     AS runs,
    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_read,
    formatReadableSize(max(memory_usage))       AS peak_mem
FROM system.query_log
WHERE type = 'QueryFinish'
  AND query_kind = 'Select'
  AND event_time > now() - INTERVAL 6 HOUR
GROUP BY shape
ORDER BY sum(query_duration_ms) DESC   -- rank by total time burned, not per-run cost
LIMIT 15;

Ranking by sum(query_duration_ms) surfaces the shapes that cost the most cluster time in aggregate — a cheap query run a million times often outranks a slow one run twice. Re-rank by sum(read_rows) to find I/O hogs and by max(memory_usage) to find the shapes that flirt with the memory ceiling.

4. Explain the worst offender

Once a shape is identified, EXPLAIN indexes = 1 shows whether the sparse primary index is pruning granules or the query is full-scanning — the difference between a millisecond and a minute.

EXPLAIN indexes = 1
SELECT event_type, count()
FROM analytics.events_raw
WHERE event_type = 'checkout'
  AND event_timestamp >= now() - INTERVAL 1 DAY
GROUP BY event_type;

ReadFromMergeTree (analytics.events_raw)
Indexes:
  PrimaryKey
    Keys: event_type, event_timestamp
    Condition: and((event_type in ['checkout','checkout']), (event_timestamp in [...]))
    Parts: 1/90
    Granules: 812/122070

Granules: 812/122070 means the query read under 1% of the table — the sort key is doing its job. When EXPLAIN reports Granules: 122070/122070, the filter is not aligned with the leading ORDER BY columns and the query is scanning everything; the fix lives at CREATE TABLE time in the MergeTree engine deep dive, not in the monitoring layer.

5. Persist a compact metrics rollup

Reading raw query_log on every dashboard refresh re-scans millions of rows. Roll the signal into a small AggregatingMergeTree fed by a materialized view so dashboards read pre-aggregated state. The full retention and dashboard build is covered in building query log retention and dashboards; the minimal target table is:

CREATE TABLE analytics.query_metrics_5m
(
    bucket        DateTime,
    query_kind    LowCardinality(String),
    user          LowCardinality(String),
    runs          UInt64,
    duration_state AggregateFunction(quantile(0.99), UInt64),
    read_rows_sum  UInt64,
    peak_mem       UInt64
)
ENGINE = AggregatingMergeTree
PARTITION BY toYYYYMMDD(bucket)
ORDER BY (bucket, query_kind, user);

Verify the rollup keeps pace after wiring the view by comparing a raw p99 against the aggregated one for the same window — they should match within rounding.

Integration touchpoints

Query monitoring does not stand alone; its signal is only actionable next to the ingestion and storage state that produces it.

• Upstream ingestion pressure. Insert queries land in the same query_log (query_kind = 'Insert'). A spike in insert query_duration_ms or a climb in written_rows per insert often precedes the small-part churn diagnosed in part and merge health monitoring — watch both signals together so you catch a struggling write path before it manifests as TOO_MANY_PARTS.
• Storage layout is the root cause of most slow reads. A query that suddenly reads ten times more rows almost always lost granule pruning because its filter drifted off the sort key; the mechanics of why belong to the MergeTree engine deep dive, and the monitoring layer’s job is to catch the regression, not redesign the table.
• Memory ceilings. memory_usage in the log is a per-query figure; when it approaches the max_memory_usage budget set in threshold tuning and performance limits, the query is one bad batch away from MEMORY_LIMIT_EXCEEDED. Alert on the ratio, not the raw number, so the threshold travels with the setting.
• The observability practice. These query signals are one of three focus areas in the wider monitoring, observability, and operations practice, sitting alongside merge health and replication availability; a mature runbook correlates all three when triaging an incident.

Tuning parameters

The most common misconfiguration is leaving the query_log table with no TTL. On a busy cluster it accumulates tens of gigabytes of parts that background merges must maintain, stealing merge threads from the production tables — the log becomes a load source instead of an observer. Set a TTL sized to how far back your dashboards actually look (14–30 days is typical) and ship anything longer to a separate history table, as the retention guide describes.

Troubleshooting

The most recent queries are missing from the log. You ran a diagnostic and your own query — or one that finished a second ago — is not there. The row is still in the in-memory buffer.

-- Force the buffer to disk, then re-query.
SYSTEM FLUSH LOGS;
SELECT event_time, query_duration_ms, substr(query, 1, 60) AS q
FROM system.query_log
WHERE type = 'QueryFinish' AND event_time > now() - INTERVAL 1 MINUTE
ORDER BY event_time DESC LIMIT 10;

Fix: always SYSTEM FLUSH LOGS before near-real-time analysis, or lower flush_interval_milliseconds for the whole node if freshness matters more than log-table part count.

Counts and sums are exactly doubled. A query that forgot the type filter aggregates both the QueryStart and QueryFinish rows for every statement.

SELECT type, count() FROM system.query_log
WHERE event_time > now() - INTERVAL 10 MINUTE
GROUP BY type;

Fix: filter type = 'QueryFinish' for successful-query metrics. Only QueryFinish rows carry final query_duration_ms and read_rows; the start rows have them zeroed.

The query_log table itself is a top disk consumer. Left unbounded, it can rival the tables it observes.

SELECT formatReadableSize(sum(bytes_on_disk)) AS size, count() AS parts
FROM system.parts
WHERE database = 'system' AND table = 'query_log' AND active;

Fix: add the <ttl> shown in the configuration block, then reclaim space immediately with ALTER TABLE system.query_log MODIFY TTL event_date + INTERVAL 30 DAY; followed by OPTIMIZE TABLE system.query_log FINAL off-peak.

Percentiles look wrong because failed queries are included. Timeouts and MEMORY_LIMIT_EXCEEDED failures log an ExceptionWhileProcessing row whose query_duration_ms is the time until failure — mixing them into a success SLA skews the tail.

SELECT exception_code, count(), round(avg(query_duration_ms)) AS avg_ms
FROM system.query_log
WHERE type != 'QueryFinish' AND event_time > now() - INTERVAL 1 HOUR
  AND query_kind = 'Select'
GROUP BY exception_code ORDER BY count() DESC;

Fix: separate success and failure SLAs. Compute latency percentiles over type = 'QueryFinish' only, and track type = 'ExceptionWhileProcessing' as an independent error-rate signal.

A short query runs millions of times and dominates the workload. Per-run cost looks trivial, but aggregate time is enormous — invisible if you rank by average duration.

SELECT normalizeQuery(query) AS shape, count() AS runs,
       round(sum(query_duration_ms) / 1000) AS total_seconds
FROM system.query_log
WHERE type = 'QueryFinish' AND event_time > now() - INTERVAL 1 HOUR
GROUP BY shape ORDER BY total_seconds DESC LIMIT 10;

Fix: rank by sum(query_duration_ms), cache or pre-aggregate the offending shape, or push the caller onto a materialized rollup instead of hitting the raw table on every request.

Related

• Detecting slow queries with system.query_log — the step-by-step drill-down from symptom to offending query shape.
• Building query log retention and dashboards — TTL, a materialized-view rollup, and Grafana panels.
• Part & merge health monitoring — the ingestion-side signal that pairs with insert-query latency.
• MergeTree engine deep dive — why granule pruning, not the monitoring layer, fixes most slow reads.
• Threshold tuning & performance limits — the memory and execution ceilings your alerts should track.

Up: Monitoring, Observability & Operations