夜莺 Nightingale 告警时间比实际晚 30 分钟：自定义 5xx exporter 时间窗只跟不追的根因排查

夜莺 Nightingale 告警时间比实际晚 30 分钟：自定义 5xx exporter 时间窗"只跟不追"的根因排查

以下涉及的域名、主机名、IP、token 等均已替换为占位值，照搬到你自己的环境时换成实际值即可。

先把结论摆前面：告警通知里的"告警时间"不一定是事故发生时间。 当告警链路里有一个按时间窗顺序处理的自定义 exporter，而它"只跟不追"时，告警可以稳定地比真实事故晚几十分钟。这次排查里，一条 20:32 的 5xx 告警，对应的真实事故发生在 20:02——整整差了半小时，差点把排查方向带偏。

下面是完整的定位过程，包括我中途一个被数据直接推翻的错误假设。

一、现象：告警时刻，访问日志却是干净的

收到一条告警：

【最近两分钟】核心接口出现5xx
告警时间: 2026-06-01 20:32:29
告警域名：www.example.com
告警URI/值：/api/biz/download：1
触发时值: 1

第一反应是去访问日志里看 20:30–20:32 这条接口的实际状态码。日志在阿里云 SLS，直接按分钟查这个域名+接口的 5xx：

aliyun sls get-logs-v2 \
  --region <REGION> --project <NGINX_PROJECT> --logstore log \
  --from <ts> --to <ts> \
  --query 'host:www.example.com and request_uri:"/api/biz/download" and status >= 500'
# count: 0

20:30–20:33 这个窗口里，这条接口 72 个请求全部 200，一条 5xx 都没有。告警说有，日志说没有——矛盾就此开始。

二、顺藤摸瓜：真实事故在 20:02，不是 20:32

把时间放宽，按分钟统计这个域名当天所有 5xx：

20:02:00  502 x2031
20:03:00  502 x442
20:04 起   0（恢复）

真实事故是一次后端 upstream 瞬时抖动：20:02–20:03 两分钟内全站约 2473 个 502，之后秒级自愈。那条 /api/biz/download 的 5xx 就落在 20:03 这一分钟里。

关键观察来了：当天还有一起同型告警，真实事故在 18:45、告警在 19:15。把两起摆一起：

真实事故（访问日志） 告警时间 偏移
18:45–18:46 19:14–19:15 +29 min
20:02–20:03 20:31–20:32 +29 min

两起独立事件都精确偏 +29 分钟。随机的网络抖动或积压不会这么整齐——这是一个固定滞后，意味着告警链路里某个环节稳定地慢了半小时。

三、走错的岔路：一个被数据推翻的假设

先看告警是怎么产生的。这条规则在夜莺（Nightingale）里，PromQL 是：

max_over_time(nginx_5xx_uri_count{host=~"www.example.com"}[2m]) > 0

nginx_5xx_uri_count 是个自定义指标，由一个名为 nginx_5xx_reporter 的 Python 脚本算出来、推到 Pushgateway，再被 Prometheus 抓走。脚本的数据源不是 SLS，而是另一套日志后端 OpenObserve。

我当时的假设是：OpenObserve 摄入延迟。这个流里没有 nginx 自带的时间字段（没采 time_iso8601），如果 OpenObserve 用"摄入时间"当 _timestamp，那么一次 502 突发把日志管道顶出积压、晚 29 分钟才摄入，_timestamp 就会被打成 20:31，reporter 那时才查到——看起来能自圆其说。

然后我去 OpenObserve 里直接查那批 5xx 的 _timestamp 分布，假设当场被打脸：

5xx rows: 2
   2026-06-01T12:02:00 5xx x 2031     # = 20:02 CST
   2026-06-01T12:03:00 5xx x 442      # = 20:03 CST

OpenObserve 里这批 5xx 的 _timestamp 就是 20:02–20:03，和 SLS 完全一致——根本没有摄入延迟。 再实测一条最新日志，lag_vs_now = 0.0 分钟，管道是准实时的。

这一步的教训：别让一个能自圆其说的假设替代验证。 那段"管道积压"的解释逻辑通顺、却是错的，唯一能否掉它的就是去查真实数据。假设作废，延迟不在日志侧，那只能在 reporter → Prometheus → 告警 这一段。

四、根因：时间窗"只跟不追"

去读 reporter 的运行日志，一行就看见了问题。它每轮处理时打印当前查询的时间窗：

21:45:39  开始批量查询，时间窗口 ... (13:17:00 - 13:18:00 UTC)
21:46:39  开始批量查询，时间窗口 ... (13:18:00 - 13:19:00 UTC)
21:47:39  开始批量查询，时间窗口 ... (13:19:00 - 13:20:00 UTC)
...
21:50:39  开始批量查询，时间窗口 ... (13:22:00 - 13:23:00 UTC)
now = 21:51:29 CST

左边是墙上时间，括号里是它此刻正在查询的数据窗口。21:50:39 在查 13:22 UTC（即 21:22 CST）——落后真实时间约 28.5 分钟。而且每过 60 秒，窗口只往前推进 60 秒（13:17 → 13:18 → 13:19），差距纹丝不动。

再回到事发当晚那几行，把因果钉死：

2026-06-01 20:31:35  开始批量查询，时间窗口 ... (12:03:00 - 12:04:00 UTC)
2026-06-01 20:31:37  WARNING - 检测到 www.example.com /api/biz/download 有 1 条 5xx 错误

墙上时间 20:31:35 才查到数据窗口 12:03 UTC（20:03 CST），20:31:37 打出那条 download 的 5xx ——也就是说，告警内容里那条 5xx，脚本是在 20:31 才"发现" 20:03 的数据，随后 Prometheus 抓到、夜莺在 20:32:29 发出。半小时的来源，就是这两个时间的差。

为什么会"只跟不追"？看两段源码就够了。取下一个时间窗的逻辑：

def get_next_time_range():
    latest_start, latest_end = get_time_range()          # 当前最新可查窗口 (now - delay)
    window_us = QUERY_WINDOW_SECONDS * 1_000_000          # = 60s
    if LAST_QUERY_END_TIME is None:                       # 首次启动
        LAST_QUERY_END_TIME = latest_start               #   → 对齐到近实时
        return latest_start, latest_end
    next_start = LAST_QUERY_END_TIME                      # 否则：从水位线往后
    next_end = next_start + window_us                     #   只 +1 个 60s 窗口
    if next_end > latest_end:
        return None, None
    return next_start, next_end

驱动它的周期循环：

while True:
    started_at = time.time()
    task_func()                                  # 内部只调用一次 get_next_time_range
    elapsed = time.time() - started_at
    sleep_time = max(1, interval_seconds - elapsed)   # interval = 60
    time.sleep(sleep_time)

把两段合起来，行为就确定了：

  1. 处理速率上限 = 真实速率。每轮（约 60 秒）只消费一个 60 秒的数据窗口。它最好也只能"刚好跟住"，天生没有"追赶"能力。
  2. 慢一次就永久掉队。这个脚本跨区查询（控制机查另一机房的 OpenObserve）、要扫几十个 host × 十几个 URI，某些轮耗时 > 60 秒。这时 sleep_time = 1，下轮立刻开始，但仍只前进一个窗口 → 这一轮用了 >60s 墙上时间却只推进了 60s 数据，净掉队 (elapsed − 60) 秒。日积月累，攒成 29 分钟。
  3. 快的时候不补。即使某轮很快，它也不会多处理几个窗口去追 → 差距只增不减，单调累积。

对照之下，这个脚本里另一条"近 N 个请求占比"的路径就不掉队：它用 now − delay 直接锚定当前时刻，每次都查最近一段，不依赖水位线。问题只出在这条用 watermark 顺序推进的窗口计数路径上。

一句话：这条路径只会"跟"，不会"追"；一旦因慢查询掉队，就永久滞后。

五、延迟是哪天攒起来的：一次网络抖动，然后永不恢复

既然 reporter 每轮都打印"正在处理的时间窗"，那把整段日志拉出来，用 墙上时间 − 窗口时间 就能还原出每一刻的滞后量。把它按天聚合，曲线很说明问题：

日期        滞后区间(分钟)
05-06        0.0 ..  0.0
05-07        0.0 ..  1.8
05-08        1.8 ..  3.1
 ...         （每天约 +1.3，期间被几次重启压回 1~8）
05-27        6.7 ..  8.0
05-28        8.0 .. 22.5   ← 单日从 8 跳到 22.5
05-29       22.5 .. 23.8
05-30       23.8 .. 25.1
05-31       25.1 .. 26.4
06-01        0.5 .. 27.7   ← 涨到 27.7，重启后清零
06-02        0.6 ..  1.4

两层信息：

  • 结构性慢漂移一直存在。从上线起，滞后每天稳定 +1.3 分钟左右——正是"只跟不追 + 每轮平均略超 60s"的累积。它被几次重启反复压回 1~8 分钟，所以一直没人察觉。
  • 失控的大延迟有明确起点：05-28。这天滞后单日从 8 分钟跳到 22.5 分钟，远超 +1.3/天的正常漂移。

放大 05-28，跳变集中在 13:30–14:10 这约 40 分钟：

13:30   8.8
13:40  11.4
13:50  14.8
14:01  17.3
14:11  21.3   ← 40 分钟内从 8.8 顶到 ~22，之后稳定不动

同一段时间，日志里同时出现处理停顿和网络报错，互相印证：

停顿 206s  13:57:51 -> 14:01:17   lag 14.8 -> 17.3
停顿 146s  14:05:59 -> 14:08:25   lag 19.0 -> 20.4
 ...（13:32–14:08 共 5 次 2~3 分钟停顿）

[FAIL] PushGateway 上报失败 <host>: <urlopen error timed out>          ← 占多数
recent-N 查询失败 <host>: ('Connection aborted.', RemoteDisconnected(...))
[FAIL] PushGateway 上报失败 <host>: [Errno 104] Connection reset by peer

报错全部挤在 13 时（28 条）和 14 时（23 条），其余时段为 0。上报端（Pushgateway）和查询端同时超时/被重置，指向的是网络层抖动，不是某个单一服务变慢。

因果链就此闭合：

  1. 05-28 13:30–14:10 一段网络抖动 → 每次 urlopen timed out 把那一轮卡住几秒到几十秒 → 每轮远超 60 秒。
  2. 窗口计数循环这 40 分钟掉队约 13 分钟（8.8 → 22）。
  3. 网络恢复、报错消失，但"只跟不追" + 进程一直没重启 → 这 22 分钟永久留下。
  4. 叠加每天 +1.3 分钟的结构漂移，到 06-01 涨成 ~28 分钟——就是那条"晚半小时"告警的由来。

这才是最该记住的一点：在"只跟不追"的设计下，一次几十分钟的网络抖动会留下永久滞后，而且因为没有滞后自监控，没人会发现。要不是一条告警时间对不上，这 28 分钟的盲区会一直躺着。

六、修复：先止血，再根治

止血（治标）：重启服务。水位线 LAST_QUERY_END_TIME 是内存变量、没持久化，重启后会重新对齐到近实时。日志里能直接看到水位线被重置：

重启前: 22:01:40  查询窗口 13:33 UTC   ← 还落后约 28 分钟
Active since 22:02:30（新进程）
重启后: 22:02:31  查询窗口 14:01 UTC   ← 窗口一步跳到近实时
        22:03:31  查询窗口 14:02 UTC
now = 22:04:00 CST

滞后从 ~28.5 分钟降到 ~1 分钟（设计内的 delay + window）。但这只是止血——代码不改，慢查询会让它重新累积。

根治（治本），三选一，推荐第一个：

  1. 加追赶循环：每轮把积压窗口一次性处理到追平，而不是只走一个。加个上限防止长宕机后猛打数据源。
def batch_process_hosts():
    processed = 0
    while processed < MAX_CATCHUP_WINDOWS:
        start, end = get_next_time_range()
        if start is None:
            break                       # 已追平到最新
        process_one_window(start, end)
        mark_time_range_processed(end)
        processed += 1

为什么加个循环就能"追上"？ 关键在一个容易忽略的事实：处理一个 60 秒窗口，实际只花几秒钟，远比窗口本身代表的 1 分钟快。 拿"保安回看监控录像"打个比方：

  • 看 1 分钟录像，实际只花 ~3 秒。
  • 老规矩（现在的代码）：看完就休息，凑满 60 秒再看下一段——看 3:00（3秒）→ 睡 57 秒 → 看 3:01（3秒）→ 睡 57 秒 → …。结果每过 60 秒真实时间，只往前看了 1 分钟录像，跟直播刚好打平。落后 20 分钟，就永远落后 20 分钟——那 57 秒的休息，把"看得快"的本事浪费了。
  • 新规矩（追赶循环）：落后时不休息，看完一段立刻看下一段。因为 3 秒能看 1 分钟，1 分钟真实时间能看完约 20 段录像。落后在看 3:00、直播已到 3:20，连着快看一分钟就追到了 3:20，追上直播后才恢复正常节奏（看一分钟、睡到下一分钟）。

一句话：看录像比录像本身快得多，平时这个"快"被休息浪费了；落后时不休息，就用这个"快"把落下的补回来。 老规矩"看完必睡"所以快也没用；新规矩"没追上就别睡"，于是几十秒就追平。代码上就是把"取一格 + 处理"那一步，用一个带上限的循环包起来。

  1. 锚定当前时刻：窗口计数也改成每轮查最新窗口（丢掉水位线），像占比路径一样永远实时。代价是某轮被跳过会有计数空洞——但对"现在有没有 5xx"的告警，新鲜度比完整性重要。

  2. 滞后封顶：当 latest_end − LAST_QUERY_END_TIME > 阈值 时，直接把水位线快进到近端并打 WARNING，防止永久滞后。

配套（建议都做）：

  • 降低每轮开销：把 exporter 部署到贴近数据源的地方消掉跨区 RTT；或把"几十 host × 十几 URI"的循环查询改成一条 GROUP BY host, uri 的聚合查询。
  • 加滞后自监控：导出 processing_lag = now − LAST_QUERY_END_TIME，超过 5 分钟就告警。这次就是它默默掉队、没有任何信号，才让一条延迟告警把人带偏。

七、复盘：这次真正的收获

技术根因是一个时间窗 bug，但更值得记的是排查方法上的两条：

  • 告警时间不等于事故时间。只要链路里有按窗口/批次处理的中间件，"告警时间"就只是"被处理到的时刻"。判断真实事故时间，要用实时可信的那条数据（这里是 SLS 访问日志的 time_iso8601），而不是告警自带的时间戳。
  • 固定偏移是强线索。两起事故都精确 +29 分钟，直接排除了"随机抖动/积压"，把方向锁到"某个环节恒定滞后"。遇到可疑的等量偏移，先怀疑固定机制，别归因于偶然。
  • 能自圆其说的假设也要验证。我那个"OpenObserve 摄入延迟"的假设逻辑通顺，却被一条 _timestamp 查询当场否掉。假设的价值在于被验证或被推翻，不在于听起来合理。

快速参考

排查"告警时间和实际对不上"的通用步骤：

  1. 用实时可信的日志（如 SLS 访问日志）确定真实事故时刻，不要信告警自带时间。
  2. 对比多起同型告警的偏移量；偏移恒定 → 怀疑固定滞后的中间环节。
  3. 顺链路逐段查：告警规则 → 指标来源 exporter → exporter 数据源。每段都用数据验证，别用假设代替。
  4. exporter 类问题，直接看它运行日志里"正在处理的时间窗 vs 当前时间"的差。

时间窗顺序处理的设计铁律：

  • 顺序消费时间窗的任务，必须有追赶能力（每轮处理到追平），否则只会"跟"不会"追"，一次掉队永久滞后。
  • 或者干脆锚定 now，每轮查最新窗口，不留水位线。
  • 一定要导出 processing lag 指标并告警；watermark 滞后是静默故障，不监控就没人知道。
  • 水位线放内存 = 重启即清零，可作应急止血，但不是修复。

常用命令：

# 看 exporter 当前处理到哪个时间窗 vs 现在
grep -aE '开始批量查询' /tmp/xxx_reporter.log | tail -3 ; date

# 重启止血（内存水位线重置到近实时）
systemctl restart xxx_reporter.service
posted @ 2026-06-03 15:07  Hello_worlds  阅读(4)  评论(0)    收藏  举报