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 NOT has(tables, 'system.query_log')
ORDER BY duration_sec DESC
LIMIT 20;

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

type = 'QueryFinish'

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

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

AND NOT has(tables, ‘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:

Симптом

ORDER BY

Тормозят запросы

duration_sec DESC

CPU на пределе

total_cpu_sec DESC

RAM на пределе

memory_usage DESC

Диск перегружен, высокая утилизация

read_bytes DESC

Будьте осторожны: system.query_log - обычная таблица MergeTree, и она может быть большой. Запрос с широким диапазоном времени и без фильтров сам по себе может создать нагрузку. Начинайте с узкого окна now() - INTERVAL 1 HOUR и расширяйте его при необходимости. Используйте LIMIT и избегайте SELECT *.

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

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

Штатные колонки

В system.query_log есть колонки user, initial_user, client_hostname, initial_address. С их помощью можно отделить запросы аналитиков от сервисных и понять, с какого хоста идёт нагрузка:

SELECT
    user,
    client_hostname,
    count() AS queries,
    round(sum(query_duration_ms) / 1000, 1) AS total_sec,
    formatReadableSize(sum(read_bytes)) AS total_read
FROM system.query_log
WHERE event_date >= today()
  AND type = 'QueryFinish'
GROUP BY user, client_hostname
ORDER BY total_sec DESC
LIMIT 10;

Этого хватит, если у каждого сервиса свой пользователь. Но часто оркестратор (Airflow, Dagster, ...) подключается под одним аккаунтом на все DAG-и. Мы имеем в логе тысячи записей от одного user без возможности понять, какой процесс создаёт проблему.

Метки-комментарии

Встройте log_comment в сервисные клиенты. Указывайте имя шага/отчёта/DAG-а - всё, что поможет идентифицировать процесс:

client.execute(
    query,
    settings={'log_comment': 'dag:report/step:aggregate_daily'}
)

Значение попадает в колонку log_comment в query_log. Теперь можно группировать по процессам:

SELECT
    log_comment,
    count() AS queries,
    round(sum(query_duration_ms) / 1000, 1) AS total_sec,
    formatReadableSize(sum(read_bytes)) AS total_read
FROM system.query_log
WHERE event_date >= today()
  AND type = 'QueryFinish'
  AND user = 'airflow'
GROUP BY log_comment
ORDER BY total_sec DESC
LIMIT 20;

Вместо тысячи запросов от оркестратора вы видите: нагрузку создаёт DAG report на шаге aggregate_daily.

Так же для поиска интересующего вас запроса:

SELECT ...
FROM system.query_log
WHERE ...
  AND log_comment = 'dag:report/step:aggregate_daily'

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

-- source:sales_dashboard
SELECT ...
SELECT ...
FROM system.query_log
WHERE ...
  AND 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 для снижения количества читаемых данных.

  4. Ключ сортировки. В текущей структуре на первом месте стоит уникальное значение event_id. Это означает, что остальные колонки ключа user_id, event_date фактически не участвуют в фильтрации. Стоит задуматься, оптимальна ли структура хранения? Например, ORDER BY (event_date, user_id, event_id) позволи ли бы ClickHouse эффективно пропускать данные при фильтрации по дате и пользователю.

Про оптимизацию запросов на 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.

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