数据库

查询剖析与 trace_log 诊断

系统讲解 ClickHouse 查询剖析与链路追踪：system.query_log 关键列解读、ProfileEvents 计数、Query Profiler 采样与火焰图、trace_log 开启与表结构、trace_id/span_id 端到端串联、与 OpenTelemetry/Jaeger 集成、内存与执行细节下钻，以及一套可复用的慢查询定位流程。

Leeting Yan 2026-10-07 6 分钟阅读 2926 字

1. 查询性能诊断的数据源

定位 ClickHouse 慢查询，靠的不是感觉，而是三类自带的可观测数据：system.query_log 提供每次查询的终态统计，ProfileEvents 提供执行过程中的计数器明细，trace_log 则把一次查询拆成带时间戳的调用栈与 span。三者从粗到细，构成完整的诊断链路。

理解它们的分工很重要：

数据源	粒度	回答的问题	开销
`system.query_log`	每次查询一行	哪条查询慢、慢在哪个阶段	低（默认开启）
`ProfileEvents`	每次查询一组计数器	慢在哪类操作（IO/CPU/内存）	低
`system.trace_log`	每个采样帧一行	具体哪段代码/函数耗时	中（需开启）

先用 query_log 找到「嫌疑查询」，再用 ProfileEvents 判断「瓶颈类型」，最后用 trace_log 下钻到「具体代码路径」。跳过前两步直接上火焰图，往往会被噪声淹没。

1.1 system.query_log 的关键列

query_log 默认按 query_start_time 分区，保留最近若干天的记录。最值得关注的列：

列	含义
`query_duration_ms`	查询总耗时（毫秒）
`read_rows` / `read_bytes`	实际读取的行数/字节数
`memory_usage`	峰值内存占用
`result_rows` / `result_bytes`	返回结果规模
`ProfileEvents`	计数器映射（Map 类型）
`type`	QueryStart / QueryFinish / ExceptionWhileProcessing
`exception_code`	出错时的错误码
`query_kind`	Select / Insert / 其它

注意：query_log 里同一次查询会有 QueryStart 与 QueryFinish 两行，统计耗时要过滤 type = 'QueryFinish'。

query_log 的采样与保留由 config.d 中的 <query_log> 段控制。生产环境常见配置是保留 30 天、flush_interval_milliseconds 设为 1000。若发现日志表膨胀过快，可启用 log_queries_probability 做概率采样，但排查慢查询时建议保持全量——被采样掉的往往正是需要复现的那些。

此外，query_log 只记录终态：一条查询是否成功、耗时多少、读了多少行。它不告诉你「时间花在哪个算子」。这正是需要 ProfileEvents 与 trace_log 的原因。

1.2 ProfileEvents 与执行细节

ProfileEvents 是 ClickHouse 内部的计数器字典，每个查询执行完会把相关计数写入 query_log.ProfileEvents。几个高频指标：

SELECT
    query_duration_ms,
    ProfileEvents['RealTimeMicroseconds']   AS real_us,
    ProfileEvents['UserTimeMicroseconds']   AS user_us,
    ProfileEvents['OSIOWaitMicroseconds']   AS iowait_us,
    ProfileEvents['SelectedRows']           AS selected,
    ProfileEvents['SelectedBytes']          AS selected_bytes,
    ProfileEvents['MemoryAllocatorPurge']   AS purge
FROM system.query_log
WHERE type = 'QueryFinish'
ORDER BY query_duration_ms DESC
LIMIT 10;

关键判断逻辑：

UserTimeMicroseconds 接近 query_duration_ms → CPU 密集，考虑向量化、编码、聚合方式；
OSIOWaitMicroseconds 占比高 → IO 密集，考虑分区裁剪、跳过索引、冷热分层；
SelectedRows 远大于 result_rows → 过滤效率低，检查主键前缀与 WHERE 条件。

这套判断与 /clickhouse-query-optimizer/ 里讲的执行引擎模型是配套的：知道瓶颈类型，才知道该改哪里。

1.3 trace_log 与 OpenTelemetry

system.trace_log 记录采样到的调用栈（stack trace）与 span。它有两种记录模式：

trace_type = 'CPU'：基于 CPU 时间采样，用于火焰图定位 CPU 热点；
trace_type = 'Real'：基于真实时间采样，能捕捉 IO 等待；
trace_type = 'Memory'：内存分配采样。

当配置了 OpenTelemetry 集成后，trace_log 还会写入 trace_id、span_id、operation_name 等列，使 ClickHouse 的内部 span 能与上游服务（应用、网关）的 trace 串联。

2. 开启 trace_log

trace_log 默认关闭（有采样开销），需在配置文件中开启：

<!-- /etc/clickhouse-server/config.d/trace_log.xml -->
<clickhouse>
    <trace_log>
        <database>system</database>
        <table>trace_log</table>
        <engine>ENGINE = MergeTree
            PARTITION BY toYYYYMM(timestamp)
            ORDER BY (event_time, trace_type, query_id)
            TTL event_time + INTERVAL 7 DAY
        </engine>
        <flush_interval_milliseconds>7500</flush_interval_milliseconds>
    </trace_log>
    <query_profiler_real_time_period_ns>1000000000</query_profiler_real_time_period_ns>
    <query_profiler_cpu_time_period_ns>1000000000</query_profiler_cpu_time_period_ns>
</clickhouse>

两个 query_profiler_*_period_ns 控制采样周期，单位纳秒。1000000000 表示每秒采样一次。周期越小精度越高、开销越大；生产环境建议 1 秒（real）、1 秒（cpu），压测时可临时调到 1 毫秒。

表结构要点：

DESCRIBE system.trace_log;

主要列包括 event_time、trace_type、query_id、thread_number、trace（栈帧地址数组）、size（采样权重）、trace_id、span_id、operation_name。trace 是一组指针地址，需要用 addressToLine 或 addressToSymbol 还原成函数名。

3. 从 query_log 定位慢查询

3.1 找出最慢的一批查询

SELECT
    query_id,
    query_duration_ms,
    formatReadableSize(read_bytes)  AS read,
    formatReadableSize(memory_usage) AS mem,
    read_rows,
    result_rows,
    substring(query, 1, 120) AS q
FROM system.query_log
WHERE type = 'QueryFinish'
  AND event_time >= now() - INTERVAL 1 HOUR
  AND query_kind = 'Select'
ORDER BY query_duration_ms DESC
LIMIT 20;

3.2 按查询指纹聚合

同一条 SQL 带不同参数会生成不同 query_id，但 normalized_query_hash 相同。按指纹聚合才能看出「哪类查询整体最耗资源」：

SELECT
    normalized_query_hash,
    count()                        AS calls,
    sum(query_duration_ms)         AS total_ms,
    avg(query_duration_ms)         AS avg_ms,
    sum(read_rows)                 AS total_rows,
    any(substring(query, 1, 100))  AS sample
FROM system.query_log
WHERE type = 'QueryFinish'
  AND event_time >= now() - INTERVAL 1 DAY
GROUP BY normalized_query_hash
ORDER BY total_ms DESC
LIMIT 20;

优化优先级应看 total_ms（总耗时）而非单次最慢：一条平均 2 秒、每天跑 1 万次的查询，比一条偶发 60 秒的查询更值得先修。

3.3 找出扫描放大

SELECT
    query_id,
    read_rows,
    result_rows,
    round(read_rows / greatest(result_rows, 1)) AS amplification,
    substring(query, 1, 100) AS q
FROM system.query_log
WHERE type = 'QueryFinish'
  AND read_rows > 10000000
ORDER BY amplification DESC
LIMIT 20;

放大倍数过高，说明过滤没有生效——这是 /clickhouse-query-pruning-indexes/ 要解决的问题。

4. 查询剖析：Query Profiler 与火焰图

4.1 基于 trace_log 生成火焰图

拿到 query_id 后，可以用内置函数把栈帧还原并聚合：

SELECT
    addressToLine(trace[1]) AS top_frame,
    count() AS samples
FROM system.trace_log
WHERE trace_type = 'CPU'
  AND query_id = 'a1b2c3d4-...'
GROUP BY top_frame
ORDER BY samples DESC
LIMIT 30;

要生成完整火焰图，官方推荐用 clickhouse-flamegraph 脚本，或直接导出成 flamegraph.pl 能吃的格式：

clickhouse-flamegraph --query-id 'a1b2c3d4-...' --host localhost \
    > flame.html

火焰图从上到下是调用栈、横轴宽度代表采样占比。最宽的顶层帧就是热点：常见的有 MergeTreeReader（IO）、Aggregator（聚合）、Join（连接）、CompressionCodec（解压）。

4.2 区分 CPU 与 Real 采样

同一查询同时看两种采样能快速判断瓶颈：

SELECT
    trace_type,
    count() AS samples
FROM system.trace_log
WHERE query_id = 'a1b2c3d4-...'
GROUP BY trace_type;

若 CPU 采样密集而 Real 稀疏 → 纯计算；若 Real 采样远多于 CPU → 大量时间花在等待（IO、锁、网络）。这与 ProfileEvents 的判断互相印证。

4.3 慢查询的实时观察

调试进行中的长查询，可以用 system.processes 看当前状态：

SELECT
    query_id,
    elapsed,
    read_rows,
    formatReadableSize(memory_usage) AS mem,
    substring(query, 1, 80) AS q
FROM system.processes
ORDER BY elapsed DESC;

5. 端到端链路追踪

5.1 trace_id 与 span_id

开启 OpenTelemetry 集成后，客户端可以传入 traceparent（W3C Trace Context）头，ClickHouse 会把它解析为 trace_id/span_id 并写入 query_log 与 trace_log。这样一次请求就能跨越应用层、ClickHouse 层：

SELECT
    trace_id,
    query_id,
    query_duration_ms,
    substring(query, 1, 80) AS q
FROM system.query_log
WHERE trace_id != ''
  AND event_time >= now() - INTERVAL 10 MINUTE
ORDER BY query_duration_ms DESC
LIMIT 20;

5.2 与 OTel Collector 集成

ClickHouse 可以把自己的 span 导出到 OpenTelemetry Collector：

<opentelemetry_span_log>
    <engine>
        ENGINE = MergeTree
        ORDER BY (trace_id, span_id)
        TTL finish_date + INTERVAL 3 DAY
    </engine>
</opentelemetry_span_log>

导出后即可在 Jaeger / Tempo 里看到 ClickHouse 内部的子 span（如 QueryPipeline、ReadFromMergeTree），与应用侧的 trace 拼成完整链路。这套「指标 + 日志 + 链路」的组合，正是 /clickhouse-observability-logs-metrics/ 讨论的自建可观测性后端的延伸——只是这次被观测的对象是 ClickHouse 自己。更通用的三大支柱方法论可参考可观测性三大支柱。

6. 内存与执行细节下钻

除了 CPU/IO，内存问题也需要剖析。system.query_log 的 memory_usage 是峰值，但看不到分配路径。打开内存采样：

SELECT
    addressToLine(trace[1]) AS frame,
    sum(size)               AS bytes
FROM system.trace_log
WHERE trace_type = 'Memory'
  AND query_id = 'a1b2c3d4-...'
GROUP BY frame
ORDER BY bytes DESC
LIMIT 20;

对于「为什么会 spill 到磁盘」这类问题，把 ProfileEvents['MaxMemoryUsage'] 与查询的 max_memory_usage 设置对比，就能判断是配额不足还是真的吃内存。内存管理与落盘机制在 /clickhouse-memory-management-spill/ 有完整拆解。

另外几个值得监控的 ProfileEvents：

事件	含义	异常信号
`SelectedParts`	扫描的 part 数	远大于分区数 → 分区裁剪失效
`SelectedMarks`	读取的 granule 数	与 read_rows 比例异常 → 索引粒度问题
`CompressedReadBufferBlocks`	解压块数	高 → 压缩编码选择不佳
`MergedRows` / `MergedUncompressedBytes`	合并工作量	高 → 写入放大大

7. 一套可复用的定位流程

把上面的工具串成固定动作，能显著缩短排查时间：

发现：按 normalized_query_hash 聚合 query_log，找 total_ms 最高的查询；
分类：读该查询的 ProfileEvents，判断是 CPU、IO 还是内存瓶颈；
定位：对典型 query_id 拉 trace_log 生成火焰图，找到最宽的顶层帧；
验证：改 SQL / 加索引 / 调参数后，用相同 query_id 指纹复查耗时；
回归：把这条查询加入基线测试集，防止后续改动回退。

-- 步骤 4 的复查：对比修改前后
SELECT
    toStartOfHour(event_time) AS h,
    count()                   AS calls,
    round(avg(query_duration_ms)) AS avg_ms,
    round(quantile(0.95)(query_duration_ms)) AS p95_ms
FROM system.query_log
WHERE type = 'QueryFinish'
  AND normalized_query_hash = 1234567890
GROUP BY h
ORDER BY h;

小结

ClickHouse 自带的三层诊断数据源各有分工：query_log 找嫌疑、ProfileEvents 分类、trace_log 下钻。把 query_profiler_*_period_ns 调到合理值并开启 trace_log，配合 trace_id 串联应用侧链路，就能把「这条查询为什么慢」从一个模糊问题变成一个可量化、可回归的工程流程。核心原则是先聚合后下钻、先分类后优化，避免一上来就被火焰图的海量帧淹没。

继续阅读

探索更多技术文章

浏览归档，发现更多关于系统设计、工具链和工程实践的内容。

全部文章返回首页