4. 问题发现过程:从告警触发到问题定位的完整时间线
本次慢查询故障并非由单一指标触发,而是由应用层告警与数据库层告警共同构成的多级告警链。以下按时间线还原从告警触发到根因定位的完整过程,并附关键日志与监控截图描述。
4.1 告警触发时间线
| 时间点 (UTC+8) | 告警来源 | 告警内容 | 严重级别 |
|---|---|---|---|
| 2024-03-15 10:23:17 | Prometheus + Alertmanager | 网关 P99 延迟 > 500ms (当前值 2.3s) | P1 严重 |
| 2024-03-15 10:23:22 | RDS 性能监控 | 数据库活跃连接数突增至 1200+ (基线 200) | P1 严重 |
| 2024-03-15 10:23:30 | 慢查询日志采集器 | 检测到单条 SQL 执行耗时 > 30s (共 47 条) | P1 严重 |
| 2024-03-15 10:24:05 | 网关错误率监控 | 5xx 错误率从 0.1% 上升至 8.7% | P2 警告 |
关键观察: 数据库活跃连接数告警比网关延迟告警仅晚 5 秒,说明数据库瓶颈是延迟飙升的直接原因,而非网络或网关自身问题。
4.2 关键日志与监控截图描述
4.2.1 网关访问日志(10:23:15 ~ 10:23:20)
2024-03-15 10:23:15.123 [INFO] request_id=req_abc123 method=POST path=/api/v1/permission/check
status=200 latency=2.1s user_id=u_10001
2024-03-15 10:23:15.456 [INFO] request_id=req_abc124 method=POST path=/api/v1/permission/check
status=200 latency=2.3s user_id=u_10002
2024-03-15 10:23:16.001 [INFO] request_id=req_abc125 method=POST path=/api/v1/permission/check
status=200 latency=2.5s user_id=u_10003
2024-03-15 10:23:16.789 [WARN] request_id=req_abc126 method=POST path=/api/v1/permission/check
status=503 latency=30.1s user_id=u_10004 // 超时断开
2024-03-15 10:23:17.234 [ERROR] request_id=req_abc127 method=POST path=/api/v1/permission/check
status=500 latency=0.0s error="context deadline exceeded"
日志特征: 正常请求延迟从 2.1s 持续攀升至 2.5s,随后出现 503 和 500 错误,且错误请求的 latency 为 0.0s 或 30.1s,表明网关与数据库之间的连接池已耗尽,请求在等待连接时超时。
4.2.2 数据库慢查询日志(10:23:10 ~ 10:23:30)
# Time: 2024-03-15T10:23:10.123456Z
# User@Host: auth_gateway[auth_gateway] @ [10.0.1.100]
# Query_time: 31.234567 Lock_time: 0.000123 Rows_sent: 1 Rows_examined: 2456789
SET timestamp=1710483790;
SELECT r.role_id, r.role_name, p.permission_code
FROM role r
JOIN role_permission rp ON r.role_id = rp.role_id
JOIN permission p ON rp.permission_id = p.permission_id
WHERE r.user_id = ?
AND r.status = 'active'
AND p.resource_type = 'api'
AND p.resource_path LIKE '/api/v1/%';
# Time: 2024-03-15T10:23:12.456789Z
# User@Host: auth_gateway[auth_gateway] @ [10.0.1.101]
# Query_time: 32.567890 Lock_time: 0.000234 Rows_sent: 1 Rows_examined: 3123456
-- 相同的 SQL 模板,不同的 user_id 参数
慢查询特征:
- 单条 SQL 执行时间超过 30 秒,扫描行数高达 200 万 ~ 300 万行。
- 同一 SQL 模板在短时间内被大量并发执行,形成“慢查询风暴”。
- 查询涉及三表 JOIN(
role、role_permission、permission),且使用了LIKE模糊匹配,索引失效。
4.2.3 数据库活跃连接数监控截图描述
监控面板显示:
- 基线: 活跃连接数稳定在 180 ~ 220 之间。
- 10:23:17: 活跃连接数从 200 直线拉升,在 10 秒内突破 1000。
- 10:23:30: 达到峰值 1287,接近连接池上限(1500)。
- 10:24:00: 连接数开始回落,但仍在 800 以上持续了约 3 分钟。
诊断提示: 活跃连接数飙升与慢查询日志时间高度吻合,说明慢查询导致连接持有时间延长,进而引发连接池耗尽,最终导致网关请求排队超时。
4.3 问题定位流程 SVG 图
4.4 定位过程中的关键决策点
- 10:23:17 ~ 10:23:30(告警确认期): 值班工程师同时收到网关延迟和数据库连接数告警,初步判断为数据库侧问题,而非网关自身故障。
- 10:23:35 ~ 10:23:50(日志拉取期): 从 RDS 慢查询日志平台拉取最近 5 分钟慢查询,发现大量相同模板的 SQL,执行时间均超过 30 秒。
- 10:24:00 ~ 10:24:15(关联分析期): 将慢查询 SQL 与网关日志中的请求路径关联,确认该 SQL 对应
/api/v1/permission/check接口的权限查询逻辑。 - 10:24:20 ~ 10:24:30(根因锁定期): 使用
EXPLAIN分析慢 SQL 执行计划,发现role_permission表缺少联合索引,导致全表扫描。
复盘教训: 从告警触发到根因锁定耗时约 1 分 13 秒,整体响应速度尚可。但若能在告警规则中增加“慢查询数量突增”的聚合告警,可将定位时间缩短至 30 秒以内。
4.5 监控数据对比表
| 指标 | 故障前(基线) | 故障中(峰值) | 故障后(恢复) |
|---|---|---|---|
| 网关 P99 延迟 | 120ms | 2.3s | 130ms |
| 数据库活跃连接数 | 200 | 1287 | 180 |
| 慢查询数量(每分钟) | 0 ~ 2 | 47 | 0 |
| 网关 5xx 错误率 | 0.1% | 8.7% | 0.05% |
| 单次权限查询平均耗时 | 45ms | 31.2s | 38ms |