3. 慢查询日志格式解析：时间戳、用户、主机、查询耗时、锁等待时间、返回行数、扫描行数等字段含义
慢查询日志（Slow Query Log）是 MySQL 提供的核心诊断工具，记录了执行时间超过预设阈值（long_query_time）的 SQL 语句。在搜索服务压测场景中，尾延迟波动往往由少数“慢查询”引发，因此准确解析日志每一字段是定位根因的第一步。
以下以 MySQL 8.0 默认慢查询日志格式为例，逐字段拆解其含义与压测关联。
3.1 日志行结构总览
一条完整的慢查询日志记录由头信息行与SQL 语句行组成。头信息行包含执行上下文与耗时指标，SQL 行记录具体查询文本。
典型日志片段（已脱敏）：
# Time: 2025-03-21T14:23:45.123456Z
# User@Host: search_user[search_app] @ [10.0.1.105] Id: 98765
# Query_time: 2.345678 Lock_time: 0.001234 Rows_sent: 50 Rows_examined: 120000
# Thread_id: 98765 Schema: search_db Last_errno: 0 Killed: 0
SET timestamp=1742567025;
SELECT /*+ NO_ICP */ item_id, title, price FROM items WHERE MATCH(title) AGAINST('蓝牙耳机') ORDER BY score DESC LIMIT 50;3.2 字段含义详解
| 字段名 | 日志示例 | 含义 | 压测关联 |
|---|---|---|---|
| Time | 2025-03-21T14:23:45.123456Z |
语句执行结束的 UTC 时间戳，精确到微秒 | 用于对齐压测时间线，判断慢查询是否集中在高负载时段 |
| User@Host | search_user[search_app] @ [10.0.1.105] |
连接用户、应用名与客户端 IP | 区分流量来源，识别是搜索服务节点还是后台任务触发的慢查询 |
| Query_time | 2.345678 |
查询实际执行耗时（秒），不含网络往返 | 尾延迟核心指标：超过 1s 的查询直接贡献 P99 延迟 |
| Lock_time | 0.001234 |
表锁或行锁等待时间（秒） | 高锁等待暗示并发冲突，可能因热点行更新或 DDL 阻塞 |
| Rows_sent | 50 |
实际返回给客户端的行数 | 搜索分页场景下通常较小，若异常增大需检查分页逻辑 |
| Rows_examined | 120000 |
服务器扫描的行数（含存储引擎层） | 扫描行数远大于返回行数 → 索引缺失或查询计划低效 |
| Thread_id | 98765 |
执行该查询的 MySQL 线程 ID | 关联 SHOW PROCESSLIST 或 performance_schema 做深度追踪 |
| Schema | search_db |
查询所在的数据库名 | 多租户场景下区分业务线 |
| SET timestamp | 1742567025 |
Unix 时间戳，用于 pt-query-digest 等工具重放 |
压测回放时保证时间顺序正确 |
3.3 关键字段的压测诊断价值
- Query_time vs Lock_time：若
Lock_time占比超过 30%，优先排查锁竞争；否则优先排查索引与扫描行数。 - Rows_examined / Rows_sent 比值：比值 > 1000 时，通常意味着全表扫描或索引选择性差，是尾延迟的主要成因。
- Time 字段的微秒精度：可精确判断慢查询是否集中在压测波峰后的 100ms 窗口内，辅助定位“雪崩”效应。
实战建议：在压测脚本中同时采集
SHOW GLOBAL STATUS LIKE 'Slow_queries'，与慢查询日志条目数交叉验证，避免日志轮转导致漏记。
3.4 慢查询日志字段关系图
下图展示了一条慢查询记录中各字段如何协同反映查询性能瓶颈：
3.5 字段解析常见陷阱
注意以下易混淆点：
- Query_time 不包含网络传输时间：客户端感知的延迟 = Query_time + 网络 RTT + 应用层处理时间。压测中若客户端延迟远大于 Query_time，需排查网络或连接池。
- Lock_time 仅统计 MySQL 层锁等待：不包含存储引擎内部锁（如 InnoDB 行锁）。行锁等待时间需从
INNODB_TRX或performance_schema获取。 - Rows_examined 可能被存储引擎缓存影响：InnoDB buffer pool 命中时，实际物理 IO 可能远小于扫描行数，但扫描行数仍反映索引选择效率。
- SET timestamp 与 Time 字段可能不一致：Time 是语句结束时间，SET timestamp 是语句开始时间。长查询两者差异可达 Query_time 值。
3.6 字段提取与格式化示例
使用 pt-query-digest 或自建脚本解析时，建议按以下结构提取字段：
# 使用 awk 提取关键字段（适用于 MySQL 8.0 默认格式）
awk '/^# Time:/ { time=$3 " " $4 }
/^# User@Host:/ { user=$3; host=$5 }
/^# Query_time:/ { qtime=$3; ltime=$5; rsent=$7; rexam=$9 }
/^SELECT|^INSERT|^UPDATE|^DELETE/ {
print time, user, host, qtime, ltime, rsent, rexam, $0
}' slow-query.log
字段映射到压测指标：
Query_time→ 服务端处理延迟（server_latency）Rows_examined / Rows_sent→ 索引效率比（efficiency_ratio）Lock_time→ 锁竞争系数（lock_contention）Time→ 压测时间轴对齐（timestamp_aligned）