system.query_log：一条查询到底耗在哪里

做的事：真实跑一条查询，从query_log拿完整画像

代码SELECT sum(v) FROM demo.threadtest WHERE k > 100 GROUP BY k%10; SYSTEM FLUSH LOGS; SELECT query_duration_ms, read_rows, read_bytes, result_rows, memory_usage, ProfileEvents['SelectedParts'], ProfileEvents['SelectedMarks'], ProfileEvents['FileOpen'] FROM system.query_log WHERE type='QueryFinish' ...;

验证：一行记录，真实拼出这条查询完整的耗时画像

实测 · 本机执行输出

query_duration_ms: 11     ← 真实总耗时
read_rows:         2000000  ← 真实读了200万行(全表，因为k>100几乎不裁剪任何数据)
read_bytes:        32000000 ← 真实32MB(k+v两个UInt64列，200万行×16字节)
result_rows:       10       ← 真实最终只返回10行(按k%10分组)
memory_usage:      382149   ← 真实约373KB内存
SelectedParts:     2         ← 真实命中了2个part
SelectedMarks:     245       ← 真实245个mark(对应200万行/8192≈244)
FileOpen:          8         ← 真实打开了8次文件

这一行记录真实把"这条查询做了什么"量化成了一组具体的数字：读了多少、算出多少、花了多少内存、碰了多少个物理文件——不需要猜测或者定性地说"读得挺多"，每一个数字都真实可以拿来跟其他查询、或者同一条查询的历史执行做对比。

真实的用法：这些数字连起来，就是排查性能问题的完整线索链

本文这条查询的read_rows=2000000而result_rows=10，两者相差20万倍——这组对比真实提示了一个排查方向：如果这条查询真实需要频繁反复执行，本系列前面《Projection》一篇验证过的"给非排序键的过滤列加一份额外排序副本"，或者用GROUP BY结果预先算好存成一张小表(本系列《物化视图》一篇)，都能真实把read_rows这个数字压下来，而不需要每次都真实扫描全部200万行。memory_usage这个数字，本系列《GROUP BY内存爆炸》一篇验证过它真实跟分组基数(不是行数)强相关，本文这次分组数很少(10个)，382KB完全在预期之内，如果同样200万行、分组数变成200万(每行一个分组)，这个数字会真实暴涨到接近1GB。SelectedParts和SelectedMarks这两个数字，真实是本系列前面《分区裁剪》《Data Skipping Index》验证过的"裁剪效果"最终落地到这一条具体查询上的真实体现——如果预期WHERE条件应该裁掉大部分分片/分区，但这两个数字看起来跟全表规模差不多，那就说明索引/分区设计真实没有在这条查询上生效，值得进一步用EXPLAIN indexes=1(本系列上一篇验证过)去确认具体是哪一层索引没起作用。system.query_log真实的价值，不在于单独看某一个数字，而在于把这些数字放在一起，跟"这条查询本来应该是什么样子"的预期做对比，差距越大，就越值得深入排查。

分步演示：从单一耗时数字到完整的排查线索链

每一步都是本文上面用真实system.query_log跑出来的原始结果。

一行query_log记录，真实拼出完整的耗时画像

这一步新读取的指标

本文用到的工具

本机 ClickHouse 26.9.4（单节点），真实的 system.query_log 与 ProfileEvents

下一篇 · CLICKHOUSE 内部原理 86

system.parts：如何判断 Part 是否过多