📚 课程目录第4章慢查询日志的开启与解读

4、慢查询日志的开启与解读：MySQL慢查询日志配置、Go侧自定义慢日志、日志字段含义解析

慢查询日志是定位数据库性能瓶颈的第一道防线。在搜索查询边界场景中，Go 服务与 MySQL 之间的交互延迟往往隐藏在大量正常查询中，只有通过精确的慢查询捕获与解读，才能快速锁定异常 SQL。本章从 MySQL 原生配置、Go 侧自定义日志、日志字段深度解析三个维度展开。

4.1 MySQL 慢查询日志配置

MySQL 慢查询日志记录执行时间超过 long_query_time 阈值的 SQL 语句。以下为生产环境推荐配置参数及说明：

参数名	推荐值	说明
`slow_query_log`	`ON`	开启慢查询日志
`slow_query_log_file`	`/var/log/mysql/slow.log`	日志文件路径，确保 MySQL 用户有写权限
`long_query_time`	`1` (秒)	超过此阈值的查询被记录；搜索业务建议设为 1 秒
`log_queries_not_using_indexes`	`ON`	记录未使用索引的查询，即使未超过阈值
`log_slow_admin_statements`	`ON`	记录慢管理语句（ALTER、ANALYZE 等）
`min_examined_row_limit`	`1000`	仅记录扫描行数超过此值的查询，过滤小表全表扫描

配置生效方式： 使用 SET GLOBAL 动态调整，或写入 my.cnf 永久生效。动态调整示例：SET GLOBAL long_query_time = 1;。注意：long_query_time 的单位为秒，支持小数（如 0.5 表示 500 毫秒）。

4.2 Go 侧自定义慢日志

MySQL 原生慢查询日志只能记录数据库端的执行时间，无法感知 Go 应用侧的网络延迟、连接池等待、ORM 开销。因此，在 Go 服务中实现自定义慢日志是必要的补充。

4.2.1 基于数据库驱动中间件的实现

使用 database/sql 包的 DB.SetConnMaxLifetime 和 DB.SetMaxOpenConns 控制连接池，同时通过包装 driver.Conn 或使用开源中间件（如 sqlmw）拦截 SQL 执行，记录耗时。

// 自定义慢查询拦截器示例
type slowQueryInterceptor struct {
    slowThreshold time.Duration
    logger        *log.Logger
}

func (s *slowQueryInterceptor) Query(ctx context.Context, query string, args []interface{}, conn driver.Conn) (driver.Rows, error) {
    start := time.Now()
    rows, err := conn.QueryContext(ctx, query, args)
    elapsed := time.Since(start)
    if elapsed > s.slowThreshold {
        s.logger.Printf("[SLOW_QUERY] duration=%v query=%s args=%v", elapsed, query, args)
    }
    return rows, err
}

4.2.2 日志字段设计

Go 侧自定义慢日志应包含以下关键字段，便于与 MySQL 慢日志关联分析：

字段	类型	说明
`timestamp`	RFC3339	请求开始时间
`duration_ms`	int	总耗时（毫秒）
`sql`	string	执行的 SQL 语句（可脱敏）
`args`	[]interface{}	绑定参数
`rows_affected`	int64	影响行数（仅 DML）
`conn_id`	uint64	MySQL 连接 ID，用于关联服务端日志
`trace_id`	string	分布式追踪 ID，用于全链路关联

注意： Go 侧慢日志与 MySQL 慢日志的时间差可能由网络延迟、连接池等待、ORM 映射耗时导致。当两者同时出现时，优先分析 MySQL 侧的执行计划；若仅 Go 侧慢而 MySQL 侧正常，则排查网络、连接池或应用代码。

4.3 日志字段含义解析

以下为一条典型的 MySQL 慢查询日志记录，逐字段解析：

# Time: 2025-03-21T10:15:30.123456+08:00
# User@Host: search_user[search_user] @  [10.0.1.100]  Id: 12345
# Query_time: 2.345678  Lock_time: 0.000123  Rows_sent: 50  Rows_examined: 50000
# Thread_id: 67890  Schema: search_db  Last_errno: 0  Killed: 0
SET timestamp=1742537730;
SELECT /*+ BKA(t1) */ t1.id, t2.title
FROM search_doc t1
LEFT JOIN search_tag t2 ON t1.tag_id = t2.id
WHERE t1.status = 1 AND t2.type = 'hot'
ORDER BY t1.score DESC
LIMIT 50;

字段	值示例	含义与排查方向
`Time`	2025-03-21T10:15:30.123456+08:00	语句开始执行的时间点，精确到微秒
`User@Host`	search_user @ [10.0.1.100]	执行用户与客户端 IP，用于定位来源应用
`Id`	12345	MySQL 连接线程 ID，与 `SHOW PROCESSLIST` 对应
`Query_time`	2.345678	SQL 执行总耗时（秒），核心指标
`Lock_time`	0.000123	表锁或行锁等待时间，过高表示锁竞争严重
`Rows_sent`	50	返回给客户端的行数，与 `LIMIT` 一致
`Rows_examined`	50000	扫描行数，远大于 `Rows_sent` 说明索引效率低
`Thread_id`	67890	内部线程标识，用于关联 `INNODB_TRX` 等系统表
`Schema`	search_db	当前数据库名
`Last_errno`	0	错误码，非 0 表示执行出错
`Killed`	0	是否被 `KILL` 命令终止

关键比值： Rows_examined / Rows_sent 称为“扫描-返回比”。当该比值超过 100 时，通常意味着缺少合适的索引或查询条件无法有效过滤数据。上例中比值为 1000（50000/50），属于严重低效查询，需优先优化。

4.4 慢查询日志处理流程

以下 SVG 图展示了从 MySQL 慢日志生成到 Go 侧自定义日志聚合的完整处理链路：

4.5 日志解读实战要点

Query_time 与 Lock_time 的关系： 若 Lock_time 占 Query_time 比例超过 30%，优先排查锁竞争（行锁、间隙锁、MDL 锁）。
Rows_examined 突增： 通常由索引失效、隐式类型转换、LIKE '%keyword%' 导致。使用 EXPLAIN 确认 type 是否为 ALL 或 INDEX。
Go 侧慢日志中的 duration_ms 远大于 MySQL 侧 Query_time： 检查连接池配置（MaxOpenConns 是否过小导致排队）、网络延迟（ping 值）、ORM 的 N+1 查询问题。
日志轮转与清理： MySQL 侧使用 logrotate 或 mysqladmin flush-logs；Go 侧使用 lumberjack 等库实现按大小/时间轮转，避免磁盘写满。

最佳实践： 在搜索业务中，建议将 long_query_time 设置为 1 秒，同时开启 log_queries_not_using_indexes。Go 侧自定义慢日志阈值建议设为 500 毫秒，以捕获应用层额外开销。两个日志通过 trace_id 关联后，可快速定位是 SQL 本身慢还是应用层慢。