У каждой из трёх систем есть свой аналог pg_stat_statements и EXPLAIN, но называются они иначе и считают другое. ClickHouse пишет каждый запрос в system.query_log вместе с ProfileEvents, Redis держит SLOWLOG последних медленных команд, MongoDB пишет в system.profile и умеет explain("executionStats"). Метод тот же, что для PostgreSQL в разборе медленного запроса: найти запрос, найти метрику «сколько работы», объяснить расхождение, исправить и снять те же цифры. Сводка запросов по queryid описана в статье про pg_stat_statements, гранулы и ORDER BY ClickHouse — в статье про первичный ключ MergeTree, а почему эти движки хранят данные иначе, чем PostgreSQL, — в статье про колоночное и документное моделирование.
Три цепочки: симптом, инструмент, метрика, причина, исправление
Стенд
Три контейнера без сети, по одному на систему; в каждой измерен один запрос. Версии дали select version() (25.3.14.14), INFO server (8.10.3) и db.version() (8.3.13).
docker run -d --name dba-clickhouse-redis-mongo-diagnostics-ch --memory 1500m clickhouse/clickhouse-server:25.3
docker run -d --name dba-clickhouse-redis-mongo-diagnostics-redis --memory 512m redis:8
docker run -d --name dba-clickhouse-redis-mongo-diagnostics-mongo --memory 1g mongo:8ClickHouse: запрос читает все гранулы
Таблица events с ключом (tenant, ts), 10 млн строк. Запрос ищет события одного пользователя, а user_id в ключе нет.
CREATE TABLE events (tenant UInt16, ts DateTime, user_id UInt32, url_id UInt16, bytes UInt32)
ENGINE = MergeTree ORDER BY (tenant, ts);
INSERT INTO events
SELECT number % 50, toDateTime('2026-10-01 00:00:00') + intDiv(number, 50),
rand32(1) % 2000000, rand32(2) % 1000, rand32(3) % 100000
FROM numbers(10000000);
OPTIMIZE TABLE events FINAL;
SELECT count(), sum(bytes) FROM events WHERE user_id = 123456 SETTINGS log_comment = 'before';
SYSTEM FLUSH LOGS;
SELECT query_duration_ms, read_rows, read_bytes,
ProfileEvents['SelectedParts'] AS parts, ProfileEvents['SelectedMarks'] AS marks,
ProfileEvents['SelectedMarksTotal'] AS marks_total, memory_usage
FROM system.query_log WHERE type = 'QueryFinish' AND log_comment = 'before'
ORDER BY event_time_microseconds DESC LIMIT 1 FORMAT Vertical;вывод
query_duration_ms: 3
read_rows: 10000000 -- 10.00 million
read_bytes: 40139136 -- 40.14 million
parts: 1
marks: 1221
marks_total: 1221
memory_usage: 138432Запрос вернул 9 строк, а read_rows равен числу строк таблицы: выбраны все 1 221 засечка из 1 221. Счётчики объявлены так:
M(SelectedMarks, "Number of marks (index granules) selected to read from a MergeTree table.", ValueType::Number) \
M(SelectedMarksTotal, "Number of total marks (index granules) before selecting which ones to read from a MergeTree table.", ValueType::Number) \ProfileEvents.cpp, строки 230–231 тега v25.3.14.14-lts. Отношение SelectedMarks к SelectedMarksTotal — доля индекса, которую запрос не смог отбросить; единица означает полный скан. Причину показывает EXPLAIN indexes = 1: Condition: true и Granules: 1221/1221: первичный ключ условие по user_id не использует. Индекс minmax по user_id не помог: значения случайны, в каждой грануле есть и малые, и большие, и EXPLAIN показал Granules: 1221/1221 у user_mm. bloom_filter проверяет принадлежность значения, а не диапазон:
ALTER TABLE events ADD INDEX user_bf user_id TYPE bloom_filter(0.01) GRANULARITY 1;
ALTER TABLE events MATERIALIZE INDEX user_bf SETTINGS mutations_sync = 2;
EXPLAIN indexes = 1 SELECT count(), sum(bytes) FROM events WHERE user_id = 123456;вывод
Skip
Name: user_bf
Description: bloom_filter GRANULARITY 1
Parts: 1/1
Granules: 15/1221query_log после индекса: read_rows 122 880 вместо 10 000 000, read_bytes 630 656 вместо 40 139 136, marks 15 вместо 1 221. Время при этом не упало: 20 запусков с use_skip_indexes = 0 дали в среднем 3,4 мс (максимум 5), 20 запусков с индексом — 5,8 мс (максимум 8). На 10 млн строк в кэше проверка 1 221 фильтра стоит дороже, чем чтение 40 МБ из памяти; на диске это не измерялось. Индекс занял 11,95 MiB рядом со 133,76 MiB таблицы. Проекция или другой ORDER BY переписывают данные, здесь не мерились. system.asynchronous_metrics (MemoryResident, Uptime) отвечает на вопрос «здоров ли сервер», system.text_log с фильтром level IN ('Warning', 'Error') — «что он сам о себе пишет».
Redis: одна команда держит остальные
Команды Redis выполняет основной поток, и пока идёт долгая команда, остальные ждут. Стенд: миллион ключей sess:N, множество online:users на 500 000 членов, хеш cart:big на 300 000 полей и список feed:u1 на 200 000 элементов.
r() { docker exec -i dba-clickhouse-redis-mongo-diagnostics-redis redis-cli "$@"; }
docker exec -i dba-clickhouse-redis-mongo-diagnostics-redis sh -c '
seq 1 1000000 | sed "s/.*/SET sess:& x/" | redis-cli --pipe
seq 1 500000 | sed "s/^/SADD online:users u/" | redis-cli --pipe
seq 1 300000 | sed "s/^/HSET cart:big f/;s/$/ 1/" | redis-cli --pipe
seq 1 200000 | sed "s/^/RPUSH feed:u1 item/" | redis-cli --pipe'
r CONFIG SET latency-monitor-threshold 10
r CONFIG RESETSTAT; r SLOWLOG RESET
r SMEMBERS online:users >/dev/null; r HGETALL cart:big >/dev/null; r KEYS '*' >/dev/null
r LRANGE feed:u1 0 -1 >/dev/null; r GET sess:7 >/dev/nullПорог slowlog-log-slower-than по умолчанию 10 000 мкс, slowlog-max-len — 128. Запись делает slowlogPushEntryIfNeeded после выполнения команды:
int slowlogPushEntryIfNeeded(client *c, robj **argv, int argc, long long duration) {
if (server.slowlog_log_slower_than < 0 || server.slowlog_max_len == 0) return 0;
if (duration >= server.slowlog_log_slower_than) {
listAddNodeHead(server.slowlog,
slowlogCreateEntry(c,argv,argc,duration));
/* Remove old entries if needed. */
while (listLength(server.slowlog) > server.slowlog_max_len)
listDelNode(server.slowlog,listLast(server.slowlog));
return 1;
}
return 0;
}slowlog.c, строки 105–117 тега 8.10.3. SLOWLOG LEN вернул 3; самая медленная запись:
вывод
1) 1) (integer) 4
2) (integer) 1793150336
3) (integer) 102721
4) 1) "KEYS"
2) "*"
5) "127.0.0.1:43546"
6) ""
7) (integer) 2Третье поле — микросекунды: KEYS * по миллиону ключей занял 102 721 мкс. Две другие записи — SMEMBERS online:users (26 498 мкс) и HGETALL cart:big (16 261 мкс). LRANGE feed:u1 0 -1 в журнал не попал, но INFO commandstats его показывает: 4 587 мкс на вызов (GET sess:7 — 2 мкс).
LATENCY DOCTOR с включённым latency-monitor-threshold собирает те же события: command: 2 latency spikes (average 64ms, mean deviation 38ms, period 5.50 sec). Worst all time event 102ms.
Виновные ключи находит redis-cli --bigkeys (по числу элементов) и --memkeys (по байтам): online:users — 500 000 членов и 18 680 438 байт, cart:big — 300 000 полей и 15 180 434 байта, feed:u1 — 200 000 элементов и 2 302 176 байт. MEMORY USAGE online:users дал те же 18 680 438 байт, MEMORY USAGE sess:7 — 32. Причина: KEYS обходит весь словарь за один вызов, а SMEMBERS и HGETALL отдают 500 000 и 300 000 элементов за один вызов. Замена — курсорные команды с COUNT:
r CONFIG RESETSTAT
docker exec -i dba-clickhouse-redis-mongo-diagnostics-redis sh -c 'redis-cli --scan --count 1000 --pattern "sess:9*" | wc -l
scan() { c=0; while :; do c=$(redis-cli "$1" "$2" $c COUNT 1000 | head -1); [ "$c" = 0 ] && break; done; }
scan SSCAN online:users; scan HSCAN cart:big'
r INFO commandstats | grep scanвывод
111111
cmdstat_scan:calls=1000,usec=173291,usec_per_call=173.29,rejected_calls=0,failed_calls=0
cmdstat_sscan:calls=500,usec=104448,usec_per_call=208.90,rejected_calls=0,failed_calls=0
cmdstat_hscan:calls=300,usec=75099,usec_per_call=250.33,rejected_calls=0,failed_calls=0Было: одна блокировка на 102 721 мкс (KEYS) и 26 498 мкс (SMEMBERS). Стало: вызовы по 173–250 мкс, SLOWLOG LEN по-прежнему 3. Суммарно работа не уменьшилась (104 448 мкс на 500 вызовов SSCAN против 26 498 мкс на один SMEMBERS), но между вызовами сервер обслуживает других клиентов. Как Redis делится на реплики и слоты, описано в статье про репликацию, Sentinel и Cluster.
MongoDB: запрос без индекса
Коллекция shop.orders на миллион документов, запрос ищет последние оплаченные заказы клиента. Профилировщик уровня 1 пишет в system.profile операции дольше slowms.
const st = ["new", "paid", "shipped", "cancelled"]; let b = [];
for (let i = 0; i < 1000000; i++) {
b.push({ customerId: i % 50000, status: st[i % 4], createdAt: new Date(1760000000000 + i * 1000), amount: (i % 1000) / 10 });
if (b.length == 10000) { db.orders.insertMany(b, { ordered: false }); b = []; }
}
db.setProfilingLevel(1, { slowms: 50 });
const q = () => db.orders.find({ customerId: 777, status: "paid" }).sort({ createdAt: -1 }).limit(10);
q().toArray();
db.system.profile.find({ ns: "shop.orders" }, { _id: 0, millis: 1, docsExamined: 1, keysExamined: 1, nreturned: 1, planSummary: 1, hasSortStage: 1 }).sort({ ts: -1 }).limit(1).toArray();вывод
[
{
keysExamined: 0,
docsExamined: 1000000,
hasSortStage: true,
nreturned: 10,
millis: 125,
planSummary: 'COLLSCAN'
}
]Запрос в 125 мс попал в журнал при пороге 50 мс. Миллион просмотренных документов ради десяти возвращённых и COLLSCAN в planSummary — готовый диагноз. Строку planSummary собирает getPlanSummary из листьев дерева исполнения:
for (const auto* stage : stages) {
if (stage->getChildren().empty()) {
tassert(3420006, "Unexpected MultiPlanStage", STAGE_MULTI_PLAN != stage->stageType());
// This is a leaf node. Add to the plan summary string accordingly. Unless
// this is the first leaf we've seen, add a delimiting string first.
if (seenLeaf) {
sb << ", ";
} else {
seenLeaf = true;
}
addStageSummaryStr(stage, sb);
}
}
return sb.str();plan_explainer_impl.cpp, строки 825–839 тега r8.3.13. q().explain("executionStats").executionStats дал nReturned: 10, executionTimeMillis: 131, totalKeysExamined: 0, totalDocsExamined: 1000000. Индекс строится по правилу ESR: сначала поля с равенством, затем поле сортировки, затем диапазоны; диапазона в запросе нет, поэтому здесь E, E, S.
db.orders.createIndex({ customerId: 1, status: 1, createdAt: -1 })Те же четыре поля explain после индекса: nReturned: 10, executionTimeMillis: 0, totalKeysExamined: 10, totalDocsExamined: 10. Профилировщик с slowms: 0 (пишет и быстрые запросы) показал keysExamined: 10, docsExamined: 10, millis: 0, planSummary: 'IXSCAN { customerId: 1, status: 1, createdAt: -1 }'.
Лишние индексы находит $indexStats. После добавления { amount: 1 } и двух запросов:
db.orders.createIndex({ amount: 1 })
db.orders.aggregate([{ $indexStats: {} }, { $project: { _id: 0, name: 1, ops: "$accesses.ops" } }])Вывод: _id_ — ops: 0, customerId_1_status_1_createdAt_-1 — ops: 2, amount_1 — ops: 0. Ноль обращений у amount_1: такой индекс замедляет запись и ничего не даёт чтению. Запрос, который идёт прямо сейчас, показывает db.currentOp(): при $where с sleep(4000) в соседней сессии и фильтре { active: true, ns: /shop/ } через две секунды вернулось op: 'query', ns: 'shop.orders', secs_running: 2, planSummary: 'COLLSCAN'. Как устроены узлы MongoDB, описано в статье про replica set и шардирование.
Что из этого следует
- Метрика «сколько работы» у каждой системы своя: доля прочитанных засечек в ClickHouse, микросекунды на вызов в Redis, отношение
docsExaminedкnreturnedв MongoDB. Время запроса её не заменяет: в ClickHouse после индекса оно выросло с 3,4 до 5,8 мс при чтении примерно в 81 раз меньше строк. - Журналы режут по порогу:
LRANGEна 4 587 мкс не попал вSLOWLOG, а запросы MongoDB быстрееslowmsне попадают вsystem.profile.
Чек-лист
- ClickHouse: после
SYSTEM FLUSH LOGSсравниSelectedMarksиSelectedMarksTotalвsystem.query_log; значения у единицы означают, что фильтр не по префиксуORDER BY.EXPLAIN indexes = 1до и после. - Redis: включи
latency-monitor-threshold, выбериslowlog-log-slower-thanпод свой SLA и читайSLOWLOG GETвместе сINFO commandstats;--bigkeysи--memkeysнаходят большие ключи заранее. - MongoDB: включи профилировщик с
slowms, сверяйdocsExaminedсnreturned, индекс строй по ESR и проверяйexplain("executionStats"); неиспользуемые индексы ищи через$indexStats. - После исправления снимай те же метрики, что и до него, и записывай обе цифры.
- Убери стенд:
docker rm -f -v dba-clickhouse-redis-mongo-diagnostics-ch dba-clickhouse-redis-mongo-diagnostics-redis dba-clickhouse-redis-mongo-diagnostics-mongo. Без-vтом с данными остаётся на диске.