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 图

问题定位流程:从告警到根因 告警触发 网关日志分析 慢查询日志采集 活跃连接数监控 关联分析 定位慢 SQL 模板 根因确认:索引缺失

4.4 定位过程中的关键决策点

  1. 10:23:17 ~ 10:23:30(告警确认期): 值班工程师同时收到网关延迟和数据库连接数告警,初步判断为数据库侧问题,而非网关自身故障。
  2. 10:23:35 ~ 10:23:50(日志拉取期): 从 RDS 慢查询日志平台拉取最近 5 分钟慢查询,发现大量相同模板的 SQL,执行时间均超过 30 秒。
  3. 10:24:00 ~ 10:24:15(关联分析期): 将慢查询 SQL 与网关日志中的请求路径关联,确认该 SQL 对应 /api/v1/permission/check 接口的权限查询逻辑。
  4. 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