CPU 80%. Как найти проблемный запрос в ClickHouse?

CPU 80%, память на пределе, диск нагружен. Запросы тормозят. Расчёты не завершаются. Сервер на грани. Что же делать?

Расскажу как начинаю диагностику и как найти запрос, который создаёт нагрузку.

Шаг 1. Что висит прямо сейчас

Если нода прямо сейчас перегружена, начинаем с system.processes - она показывает запросы, выполняющиеся в данный момент:

SELECT
    elapsed,
    formatReadableSize(memory_usage) AS ram,
    formatReadableSize(read_bytes) AS read_size,
    read_rows,
    query
FROM system.processes
ORDER BY elapsed DESC;

Нашли запрос, который создаёт нагрузку - останавливаем:

KILL QUERY WHERE query_id = 'xxx';

KILL QUERY не ждёт завершения. Чтобы дождаться:

KILL QUERY WHERE query_id = 'xxx' SYNC;

Шаг 2. Анализ завершённых запросов

В ClickHouse есть системная таблица system.query_log. В нее записываются метрики каждого выполненного запроса. Все нужные данные там есть.

Замечание: данные попадают в query_log не мгновенно. Если нужно увидеть запросы, выполненные только что, выполните:

SYSTEM FLUSH LOGS;

Запрос, с которого я начинаю:

SELECT
    event_time,
    query_duration_ms / 1000 AS duration_sec,
    formatReadableSize(memory_usage) AS ram,
    formatReadableSize(read_bytes) AS read_size,
    read_rows,
    ProfileEvents['UserTimeMicroseconds'] / 1000000 AS user_cpu_sec,
    ProfileEvents['SystemTimeMicroseconds'] / 1000000 AS system_cpu_sec,
    round(user_cpu_sec + system_cpu_sec, 2) AS total_cpu_sec,
    substring(query, 1, 200) AS query_short
FROM system.query_log
WHERE event_date >= today()
  AND event_time >= now() - INTERVAL 1 HOUR
  AND type = 'QueryFinish'
  AND query NOT ILIKE '%system.query_log%'
ORDER BY duration_sec DESC
LIMIT 20;

Разберу ключевые части.

type = 'QueryFinish'

Каждый запрос создает несколько записей в логе: момент начала QueryStart, момент завершения QueryFinish или ExceptionWhileProcessing. Метрики потребления ресурсов есть только в финальной записи.

type = 'ExceptionWhileProcessing' - если нужны запросы, упавшие с ошибкой. Их тоже не стоит отсеивать, иногда они также бывают источником нагрузки.

query NOT ILIKE '%system.query_log%'

Чтобы не видеть логе наши же поисковые запросы, так удобнее.

ProfileEvents

ProfileEvents хранит полезные метрики запросов: сколько прочитано строк, байт, времени потрачено на CPU и т.д. Их можно достать для конкретного запроса по query_id:

SELECT
    ProfileEvents['UserTimeMicroseconds'] AS uCPU,
    ProfileEvents['SystemTimeMicroseconds'] AS sCPU,
    ProfileEvents['SelectedMarks'] AS marks_read,
    ProfileEvents['SelectedParts'] AS parts_read,
    ProfileEvents['MergedRows'] AS merged_rows
FROM system.query_log
WHERE query_id = 'xxx';

*TimeMicroseconds показывают процессорное время.

SelectedMarks и SelectedParts показывают сколько засечек и кусков данных ClickHouse прочитал. Если SelectedMarks близок к общему количеству засечек в таблице, ваш WHERE бесполезен для оптимизации чтения.

MergedRows полезен для движков ReplacingMergeTree или AggregatingMergeTree, где ClickHouse может тратить время на мержи при чтении. Большое значение сигнализирует, что стоит запустить OPTIMIZE TABLE.

ORDER BY duration_sec DESC

Сортируем по длительности выполнения запроса. Это грубый фильтр: если запрос висит на долго, он точно заслуживает внимания. Для разных типов ресурсов удобно менять ORDER BY:

Шаг 3. Метка источника нагрузки

Когда к ClickHouse обращаются несколько сервисов (дашборды, оркестраторы пайплайнов, ручные запросы аналитиков), в query_log тысячи записей, и непонятно, кто создаёт нагрузку.

Есть настройка log_comment. Она записывается в отдельную колонку query_log:

SET log_comment = 'sales_dashboard';
SELECT ...

Можно фильтровать по колонке, а не искать подстроку в тексте запроса:

SELECT ...
FROM system.query_log
WHERE log_comment = 'sales_dashboard'

Если менять настройки подключения нет возможности, работает и SQL-комментарий:

-- source:sales_dashboard
SELECT ...

SELECT ...
FROM system.query_log
WHERE query ILIKE '%source:sales_dashboard%'

Шаг 4. EXPLAIN indexes = 1

Запускаем EXPLAIN indexes = 1 перед текстом запроса. ClickHouse не выполнит сам запрос, а покажет план: сколько гранул и партиций будет прочитано и сколько пропущено благодаря индексам.

EXPLAIN indexes = 1
SELECT ... -- подозрительный запрос

Фильтрация по ключу сортировки. Granules: 10/1043 означает, что из 1043 гранул ClickHouse прочитает только 10. Условие попадает в ключ сортировки ORDER BY, и binary search эффективно сужает выборку до ~1% данных.

Если вы видите что-то вроде Granules: 95000/98400, значит фильтр не работает по ключу сортировки и ClickHouse делает почти full scan.

Иногда можно обойтись и без EXPLAIN, просто оценить в уме. Если в выборке N строк и они разбросаны по таблице, то в худшем случае каждая попадёт в свою гранулу. ClickHouse прочитает N × 8 192 строк с диска.

Допустим, нам нужно найти 500 строк в таблице на 100 млн. Это будет 4 млн строк чтения, нормально. А вот 50 000 разбросанных строк - это уже 409 млн, почти full scan.

Если N × 8 192 приближается к размеру таблицы, то индекс не спасает, нужно думать про таблицу и ключ сортировки.

Пример тяжёлого запроса

Рассмотрим пример. CPU на одной из нод стабильно держался выше 80%, хотя количество запросов не выросло. Запускаю наш запрос, сортирую по total_cpu_sec:

Первый кандидат найден. Один и тот же запрос выполняется в течении минуты и каждый раз читает 5.59 GiB. Смотрю полный текст:

SELECT
    user_id,
    uniqExact(event_id),
    sum(amount)
FROM events final
WHERE event_date > '2024-01-01'
GROUP BY user_id
ORDER BY sum(amount) DESC
LIMIT 100;

Прежде чем делать выводы, смотрю структуру таблицы:

SHOW CREATE TABLE events;

CREATE TABLE IF NOT EXISTS default.events
(
    event_date Date,
    event_id UUID,
    user_id UInt32,
    event_type String,
    amount Decimal(12, 2),
    status String,
    region String,
    device String,
    duration_ms UInt32
)
ENGINE = ReplacingMergeTree()
PARTITION BY toYYYYMM(event_date)
ORDER BY (event_id, user_id, event_date);

Теперь картина ясна. Что можно сделать?

1. Широкий фильтр по дате. Таблица партиционирована по дате c ключом сортировки (event_id, user_id, event_date). Запрос читает все данные за 2 года. Зачастую рассчитывать сразу такой объем данных нет необходимости - всегда можно сделать промежуточные агрегаты и работать уже с ними. С другой стороны, вполне возможно что пользователь забыл просто выставить фильтр.

2. uniqExact вместо uniq. Функция uniqExact используется для точного подрасчета и требует значительно больше ресурсов. Не всегда эта точность оправдана, для большинства расчетов достаточно функции uniq.

3. Добавить выражение PREWHERE. Работая с таблицами на движке *MergeTree иногда помогает использование выражения PREWHERE для снижения количества читаемых данных.

Про оптимизацию запросов на Clickhouse много отличных материалов. Здесь же сфокусируемся на главном. После исправлений сравниваем метрики до и после. Повторяем цикл пока система не придет в норму.

От разовой диагностики к аналитике запросов

Разовая диагностика решает конкретный инцидент. Но на system.query_log можно построить полноценную аналитику: агрегировать запросы, складывать в витрину, отслеживать изменения по дням, настроить алертинг на аномалии (резкий рост CPU, всплеск упавших запросов, увеличение времени выполнения) и устранять проблемы до того, как о них заговорят.

Например, суточная сводка по самым тяжёлым запросам:

SELECT
    toDate(event_time) AS day,
    normalized_query_hash,
    count() AS executions,
    round(avg(query_duration_ms) / 1000, 2) AS avg_sec,
    round(max(query_duration_ms) / 1000, 2) AS max_sec,
    formatReadableSize(sum(read_bytes)) AS total_read,
    formatReadableSize(max(memory_usage)) AS peak_ram,
    substring(any(query), 1, 150) AS example
FROM system.query_log
WHERE event_date >= today() - 7
  AND type = 'QueryFinish'
GROUP BY day, normalized_query_hash
ORDER BY day DESC, sum(query_duration_ms) DESC
LIMIT 30;

Чеклист

1. SYSTEM FLUSH LOGS

2. system.processes → что висит прямо сейчас

3. system.query_log → топ тяжёлых запросов за указанный период

4. EXPLAIN indexes = 1 на подозрительный запрос

5. WHERE попадает в ключ сортировки? Используется ли PREWHERE?

6. uniqExact, JOIN, широкий диапазон дат?

7. Исправить → сравнить метрики до/после

Большинство проблем с производительностью находятся за минуты, нужно лишь знать куда смотреть и что измерять. Все инструменты штатные: system.processes, system.query_log, EXPLAIN.

Буду рад вашим комментариям и дополнениям.