周二早晨刚开完晨会,运维工程师就在告警群里发了一张 CPU 监控曲线截图:ClickHouse 集群的 3 号计算节点从今天凌晨 4 点开始,CPU 使用率笔直拉平在 99.8%,整整持续了四个小时!节点温度报警灯疯狂闪烁,前台业务发起的即席点查全部排队超时,整个节点仿佛掉进了一个无尽的死循环计算旋涡。
业务线的研发第一反应是甩锅:“是不是底层的 MergeTree 正在执行后台大合成分区(Heavy Merge)?或者是系统定时任务在刷物化视图?”
我连上终端,敲下一行命令打开 ClickHouse 原生内置的系统慢查询全景神表——system.query_log。在这张记录了每一个查询从语法解析、管道调度、内存分配到各个线程物理 CPU 消耗细节的宝藏表里,底层真实的执行真相在三秒钟内无所遁形:一条由某自动化爬虫系统发起的全表不带分区下推、且对数千万未压缩字符串执行深度模糊正则匹配(like '%...%')的“流氓 SQL”,一口气霸占了该节点整整 32 个物理线程,单条查询累积空转消耗了超过 460 万毫秒的纯 CPU 时间!
在分布式 OLAP 引擎的运维与架构调优中,脱离system.query_log去排查慢查询,如同蒙着双眼在雷区散步。掌握从数百万条系统事件日志中精准揪出“CPU 吞噬兽”的高阶剖析技术,是每一位数仓专家守护集群平稳运行的看家本领。
一、 走进底层神表:system.query_log 的运作机制与核心字段
很多工程师只知道 ClickHouse 有日志,但不知道这些日志是如何产生的。在 ClickHouse 内部,每一次查询的生命周期都会触发状态变更事件,并异步批量写入物理系统表system.query_log(其底层由普通 MergeTree 引擎驱动)。
想要精准锁定 CPU 杀手,必须吃透以下八个最硬核的核心度量字段:
+-------------------------------------------------------------+ | system.query_log 核心物理诊断字段矩阵 | +-------------------------------------------------------------+ | 1. ProfileEvents['OSCPUVirtualTimeMicroseconds'] (核心杀招) | | -> 操作系统层级度量的微秒级真实用户态 CPU 耗时 | | 2. query_duration_ms: 查询从发起到结束的物理自然流逝时钟 (毫秒) | | 3. ProfileEvents['RealTimeMicroseconds']: 真实流逝微秒 | | 4. read_rows / read_bytes: 物理从磁盘/缓存中扫描的数据行与字节| | 5. memory_usage: 查询峰值瞬间所吞噬的物理 RAM 字节数 | | 6. type: 查询状态 (QueryFinish 正常完成, ExceptionWhile... 报错)| | 7. exception_code: 异常退出错误码 (如超内存、超时) | | 8. initial_query_id / query_id: 全局链路追踪分布式唯一定位符 | +-------------------------------------------------------------+为什么不能只看query_duration_ms(执行时间)?
一条查询耗时 10 秒,可能只是因为网络传输慢,或者在等待全局锁,CPU 实际上一直在睡觉(I/O 阻塞或线程挂起);而另一条查询虽然只跑了 3 秒,但它瞬间调用了 64 个 CPU 核心跑满运算,其实际消耗的 CPU 算力是前者的数十倍!因此,排查 CPU 瓶颈必须以 CPU 核心真实消耗时间(CPU Time)为唯一黄金判定标准。
二、 生产级实战诊断:精准定位最耗 CPU 语句的四大黄金 SQL
以下是我们线上排查性能事故时,直接在 ClickHouse 终端粘贴运行的诊断利器:
1. 抓捕今日累积消耗 CPU 时间 Top-5 的“头号恶魔”
SELECT user, query_id, toStartOfMinute(event_time) AS minute_window, query_duration_ms / 1000 AS duration_sec, -- 提取用户态与系统态累积 CPU 耗时 (折算为秒) round(ProfileEvents['OSCPUVirtualTimeMicroseconds'] / 1000000, 2) AS user_cpu_sec, round(ProfileEvents['OSCPUSystemTimeMicroseconds'] / 1000000, 2) AS sys_cpu_sec, formatReadableSize(memory_usage) AS peak_mem, formatReadableSize(read_bytes) AS scanned_disk, read_rows, -- 提取规范化后的 SQL 前 200 字符 normalizeQuery(query) AS normalized_sql FROM system.query_log WHERE event_date = today() AND type = 'QueryFinish' ORDER BY user_cpu_sec DESC LIMIT 5;2. 计算“CPU 虚耗比”:揪出那些产出极低却极耗算力的低效垃圾查询
有些查询扫了数十亿行,算了大半天,最后只向客户端吐出了 10 行数据,且没有命中任何聚合索引:
SELECT query_id, user, query_duration_ms, read_rows, result_rows, -- 计算每一万行扫描消耗的 CPU 微秒数 (CPU 密度指标) round(ProfileEvents['OSCPUVirtualTimeMicroseconds'] / nullIf(read_rows, 0) * 10000, 2) AS cpu_per_10k_rows, query FROM system.query_log WHERE event_date = today() AND type = 'QueryFinish' AND read_rows > 1000000 ORDER BY cpu_per_10k_rows DESC LIMIT 10;3. 实时追踪:当前正在集群中疯狂燃烧 CPU 的活跃长查询
如果问题正在发生,必须立刻抓出当前的正在运行态(type = 'QueryStart'且尚未 Finish):
SELECT query_id, user, elapsed, formatReadableSize(memory_usage) AS current_mem, formatReadableSize(read_bytes) AS current_read, query FROM system.processes WHERE is_cancelled = 0 ORDER BY elapsed DESC LIMIT 5;找到对应的query_id后,若判定为失控查询,可直接执行强制击杀:
KILL QUERY WHERE query_id = 'xxxx-yyyy-zzzz';三、 深度剖析:从 ProfileEvents 诊断 CPU 暴涨的四大底层根因
当我们定位到了具体的慢 SQL 后,拆开其ProfileEvents字典,往往能一针见血发现 CPU 耗尽的具体原因:
+-------------------------------------------------------------+ | ProfileEvents 指标异常模式与对应病灶 | +-------------------------------------------------------------+ | 1. RegexpCreated / RegexpExecuted 极高 | | -> 病灶: 在 WHERE 或 SELECT 中滥用复杂未编译正则表达式 | | 2. FileOpen / ReadBufferFromFileDescriptorReadBytes 极高 | | -> 病灶: 碎片化小文件过多,频繁解压缩小数据块吃满 CPU | | 3. HashTableAdd / HashTableResize 极高 | | -> 病灶: GROUP BY 超高基数字段,哈希表反复扩容与哈希冲突 | | 4. SelectedMarksPk / MarksLoader 极高 | | -> 病灶: 索引基准失效,执行器对数百万个主键 Mark 进行暴力扫描| +-------------------------------------------------------------+例如,当发现一条查询中RegexpExecuted高达数千万次时,证明开发人员在对未分词的日志列使用了全量文本正则搜索。在 ClickHouse 中,这完全是在逼迫 CPU 跑密集的标量指令集。此时将其优化为原生支持的multiSearchAny或基于ngrambf_v1跳数索引的字符串匹配,CPU 消耗能瞬间削减 95%!
四、 生产集群防护与配置闭环
为了不让这类消耗万秒 CPU 的失控查询在生产环境中再次演化为灾难,我们必须在用户配置(users.xml)中构筑起三道硬核熔断阈值:
<clickhouse> <profiles> <default> <!-- 1. 物理执行时间熔断:单条即席查询最多允许运行 180 秒,超时直接自动掐死 --> <max_execution_time>180</max_execution_time> <!-- 2. 最大扫描数据量保护:单次查询超过 200 亿行直接阻断,防止全表扫荡 --> <max_rows_to_read>20000000000</max_rows_to_read> <read_overflow_mode>throw</read_overflow_mode> <!-- 3. 最大 CPU 核心线程限制:限制单个查询最大并发线程数,防止单挑全核 --> <max_threads>16</max_threads> <!-- 4. 开启慢查询自动异步采样持久化 --> <log_queries>1</log_queries> <log_queries_min_type>QueryFinish</log_queries_min_type> <!-- 仅针对执行超过 1 秒的查询记录详细日志,节省系统表自身磁盘 I/O --> <log_queries_min_query_duration_ms>1000</log_queries_min_query_duration_ms> </default> </profiles> </clickhouse>五、 架构师实战经验总结
system.query_log自身也需要清理生命周期:默认情况下该表会永久沉淀在磁盘上,高并发场景下一天就能产生几十 GB 日志。必须在config.xml中配置该表的 TTL(例如TTL event_date + INTERVAL 14 DAY),防止系统日志反噬把磁盘填满。- 善用
normalizeQuery进行模板化聚合:如果上千次慢查询来自同一个报表(仅仅是参数不同),通过normalizeQuery(query)可以把具体的日期和 ID 替换为通配符,进而使用GROUP BY normalizeQuery(query)找出是哪个业务模板在整天蚕食集群算力。 - 将 CPU 监控与钉钉/飞书告警自动打通:在调度巡检中心写一个定时任务,每隔 10 分钟检索一次
system.query_log中单次 CPU 消耗超过 300 秒的查询,自动将负责人的工号与 SQL 片段推送至团队群,让滥用资源的研发同学在第一时间收到整改提醒。