ClickHouse 慢查询日志剖析：system.query_log 中排查最耗 CPU 语句

周二早晨刚开完晨会运维工程师就在告警群里发了一张 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且尚未 FinishSELECT 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_time180/max_execution_time !-- 2. 最大扫描数据量保护单次查询超过 200 亿行直接阻断防止全表扫荡 -- max_rows_to_read20000000000/max_rows_to_read read_overflow_modethrow/read_overflow_mode !-- 3. 最大 CPU 核心线程限制限制单个查询最大并发线程数防止单挑全核 -- max_threads16/max_threads !-- 4. 开启慢查询自动异步采样持久化 -- log_queries1/log_queries log_queries_min_typeQueryFinish/log_queries_min_type !-- 仅针对执行超过 1 秒的查询记录详细日志节省系统表自身磁盘 I/O -- log_queries_min_query_duration_ms1000/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 片段推送至团队群让滥用资源的研发同学在第一时间收到整改提醒。