收到了数据库挂了的告警。可数据库从来没挂过

早上打开 Slack,四条 CRITICAL 告警堆在那儿。

504 AppHttpException: The request timed out.
  POST /customer/practice/attempts

PrismaClientKnownRequestError
  Transaction already closed

500 DriverAdapterError: canceling statement due to statement timeout
  GET /admin/dashboard/stats

DATABASE 서비스 다운
  "error": "Database health check (retry) timeout after 2000ms"

最后一行最吓人,因为它的意思是数据库死了。四条摆在一个屏幕里,一个故事自然就浮现出来:数据库吃力了,于是查询积压,于是请求超时,最后连健康检查也挂了。挺像那么回事。

所以我先打开了数据库指标。这个故事在第一屏就塌了。

数据库这 21 小时一直很闲

我把包含故障时刻在内的 21 小时区间的 RDS 指标按 5 分钟粒度拉了出来。252 个数据点。

指标	最小	最大
CPU	4.6%	19.7%
连接数	53	73
CPU 积分余额	576	576
读延迟	0s	0.01s
写延迟	0.01s	0.08s

CPU 从没超过 20%,积分余额的最小值和最大值一模一样,意思是一点都没消耗。写延迟最高 80 毫秒。RDS Proxy 我也看了:连接借用延迟最高 26 毫秒,后端连接最多 36 个。没有任何一个数字能解释得了那些 8 秒、10 秒的查询。

数据库没死。它甚至都不忙。

一个请求要横跨大西洋二十五次

那 8 秒的查询是从哪儿来的?看结构就有答案了。

我们的服务跑在两个区域:us-east 和 eu-west。primary DB 只有 us-east 一个,eu-west 应用的读取由本地副本承接,但写入全都要跨过大西洋,经由 RDS Proxy 打到 us-east 的 primary。

问题出在写入的次数上。我顺着代码把一个保存练习记录的请求(POST /customer/practice/attempts)数了一遍:资产 upsert 1 次、预聚合读取 3 次、学习尝试事务 4 次、runner 的重新查询 1 次、进度更新 2 到 3 次、连续打卡事务约 6 次、统计事务 2 次、复习状态更新 2 到 3 次。分散在三块独立的交互式事务里,大约二十五次。

日志里的数字和这个一模一样。

06:03:17  request_done  POST /customer/practice/attempts
          status=201  duration_ms=11695  query_count=25

25 个查询,11.7 秒。而且这个请求根本没失败。它硬撑了 11.7 秒,最后还返回了 201。

这里有件事我得老实交代。这一次往返到底要花几毫秒,我没有测。代码里有一处注释把区域间 RTT 写成 220 毫秒,另一处注释写的是每句 80 到 100 毫秒。我没去确认这两个哪个才对,就在 issue 正文里写下了“25 x 220ms = 5.5 秒”这个算式。现在回头看,那不是测量,是引用。准确的说法是:往返次数我数了(25 次),每次往返的代价我没测。不过结论并不因此动摇。跨大西洋往返二十五次,代价是按秒累积的。

在欧洲的早高峰(06:00 到 06:10 UTC),超过 3 秒的 primary 写入密集出现了 57 次。LearningAttempt.create 8,989ms、UserActiveDate.upsert 9,070ms、LearningAttempt.findUnique 10,561ms。请求彼此挤压,往返延迟就一层层堆了上去。

其中两条告警,就是从这个缝隙里冒出来的。

告警 1 和 2:5 秒的事务扛不住 9.3 秒

连续打卡的更新代码长这样。

// streak.service.ts:254
const changed = await this.prisma.primary.$transaction(async (tx) => {
  // ... 六条跨区域的查询 ...
});

没有 options 对象。于是套用了 Prisma 默认的交互式事务超时,5,000 毫秒。平时没问题。只要不跨区域。

Transaction API error: A query cannot be executed on an expired transaction.
The timeout for this transaction was 5000 ms,
however 9326 ms passed since the start of the transaction.

9,326 毫秒。然后它变成 P2028,请求在网关那儿变成 504。

这段代码在我们整个代码库里是唯一没设防的。其他事务路径都要穿过 withTxRetry 工具,而那个工具会把超时提到 8 秒,并把 P2028 纳入重试范围。只有连续打卡的更新留在那把伞外面,还在用 5 秒的默认值。

告警 4:健康检查走过了它自己在监视的那个瓶颈

最吓人的那条“DATABASE 服务宕机”,其实是最离谱的。

健康检查的代码写得挺好。它以 2 秒超时发出 SELECT 1,失败就歇 500 毫秒再试一次,再失败才打 CRITICAL 告警。为了不和应用的 Prisma 连接池混在一起,它还单独配了专用连接池(最多 2 个)。设计意图是:哪怕应用连接池耗尽,健康检查也还活着。

可这个探针抵达数据库的路径并没有被隔离。

// health.service.ts:139
// 如果设置了 DIRECT_DATABASE_URL 就用它,否则回退到 DATABASE_URL

DIRECT_DATABASE_URL 没有配置。于是走了回退,而 DATABASE_URL 指向的正是应用写入正挤在上面的那个 RDS Proxy。也就是说,eu-west 的健康探针发出的 SELECT 1,得跨过大西洋、穿过此刻正堵着的那个代理、跑到 us-east 的 primary 再回来。而且要在 2 秒之内。

代码其实知道这件事。回退发生时,它会留下这样一条警告。

DIRECT_DATABASE_URL is not set; DB health checks will use DATABASE_URL
and may still share proxy bottlenecks.

日志里这行原封不动地躺着。只是没人读过而已。

决定性的证据是,两个区域在同一时刻一起失败了。12:02:17,us-east 任务的健康检查超时。12:02:18,eu-west 任务也超时。如果是地域性问题,应该只有一边死。两边一起死,说明原因出在两边共用的东西上,也就是那条代理路径。

后面的事就顺理成章了。健康检查两次都失败,/public/health 返回 503,编排器认为这个任务有问题,把它替换掉。4 分钟后新任务起来了。新任务一启动,就又撞上了同样的健康检查超时。毕竟换个任务并不能让大西洋变窄。

“DATABASE 服务宕机”不是故障的症状。它是监视装置走了一趟被监视对象那条拥堵的路,然后回来报告说自己很吃力。

后台 500 是另一码事

到这里,人很容易想把四条告警归成一件事。我一开始也想这么收尾。但后台 500 的根因不一样。

GET /admin/dashboard/stats 在取热门单词时会按最近 7 天过滤。可这个过滤条件落到的表(category_attempt)没有自己的日期列。日期只在被 join 的 learning_attempt 那边。所以 Postgres 没办法先按日期把 category_attempt 裁掉,只能把整段历史全扫一遍。索引铺得再好,也没法让这个过滤条件变得有选择性。

slow_query path=/admin/dashboard/stats
           label=CategoryAttempt.groupBy dur=8009ms

statement_timeout 是 8,000 毫秒。而它跑了 8,009 毫秒。差 9 毫秒,死了。这是一次和区域毫无关系、只要表长大了迟早会爆的全表扫描。

四条告警里三条同根,一条不是。四条同屏出现,不等于原因只有一个。

被否掉的一个假设

有一个挺像样的嫌疑人。06:00 突发流量之前会跑的 device-cleanup 定时任务,引发了锁竞争。时间点对得上,听着相当有说服力。

我把两个区域 05:30 到 06:15 的日志翻了一遍。和这个定时任务相关的日志一条都没有。再去看那些慢下来的 Device.updateMany 走的是哪条路径,发现它不是定时任务的批量更新,而是 /v2/public/auth/refresh,也就是普通用户的令牌刷新请求。假设被实测否掉了。时间点重合是相关性,而日志里没有是事实。

我们把往返折叠了

处方分两条路。一条是忍受症状:把超时提到 8 秒、把连接池调大、加上重试。另一条是消灭成本本身:减少往返次数。

我们两条都做了。给连续打卡事务套上 withTxRetry 是块创可贴,但是块必要的创可贴。真正的处方是把往返折叠起来。

工具其实早就造好了。6 月 27 日的一次迁移里有一个叫 create_practice_attempt_v1 的服务端函数。它把会话加锁、查询、插入、会话元数据更新、预聚合读取全折进一个 SQL 函数里,一次往返就搞定。连幂等性都有(用同一个 client attempt id 调两次,第二次会返回已有的行,并返回 inserted=false)。

可打开这个函数的功能开关 PRACTICE_ATTEMPT_SINGLE_RT_ENABLED 默认值是 false,在生产环境里是关着的。

我们没有去砍区域,也没有去做 active-active。我们做的,是把一个早就造好的开关打开。

金丝雀:到底看什么来判定

我们只在 eu-west 打开了这个开关。us-east 作为对照组保持关闭。task definition 从 786 升到 787,滚动发布。

判定指标选哪个,才是这个故事的核心。延迟是个陷阱。挑流量清闲的时段发布,什么都不改 p95 也会变好。实际上延迟确实变好了,p50 从 2,784ms 降到了 2 千 ms 以下。但这个证据很弱。

我看的是每请求查询数。

部署前  n=85   avg query_count = 22.0
部署后  n=49   avg query_count = 15.3

查询数是与负载无关的 per-request 指标。不管流量多还是少,一个请求会发出多少条查询,是由代码路径决定的。从 22 降到 15.3,少了约 7 个。而这 7 个,和我们折进那个函数的查询清单(会话加锁 + 查询 + 插入 + 会话元数据 + 预聚合读取)的条数精确对得上。代码路径确实变了,证据是这个数字。不是延迟。

发布后的样本是 15 分钟内的 49 条。在那个窗口里 5xx 和 P2028 都是 0 件,但我并没有把同一天、同样长度的“发布前”错误数并排量出来。这个开关只折叠了 attempt 的保存。连续打卡的事务照样在跨区域。那天那个窗口里 P2028 是 0 件,意思是运气不错,不是证明。

发布是成功了,可开关差点消失

我们开金丝雀的方式是有代价的。787 是在控制台里手动注册的 task definition。下一次正式发布一跑,CD 流水线就会用不带这个开关的 task definition 覆盖掉它。这不致命(被覆盖了会回到安全的 OFF)。只是这个改进会悄无声息地消失。

所以得把它提升到 terraform 里,而这里冒出了第二个陷阱。terraform 工作流在 develop push 时只 apply staging,production 只在 main push 时才 apply。可 staging 里压根就没有 eu-west 这个区域。也就是说,把一个包含生产 eu-west 变更的 PR 合进 develop,什么都不会发生。base 必须改成 main。

还有第三个陷阱。直接合进 main,develop 就会落后;要是不做回合并,下一次发布就会把这个变更 revert 掉。得另外再开一个 back-merge PR。

“terraform apply 成功了”和“已经在生产环境生效了”,是两句不同的话。

剩下的

收到“数据库宕机”的告警,第一个该打开的是数据库指标。告警的名字是发这条告警的代码起的,不是原因起的。我们的健康检查连和应用隔离的专用连接池都准备好了,可通往数据库的那条路是同一条,于是还是和应用一起被堵住了。隔离不能只分资源,还得分路径。

把超时从 5 秒提到 8 秒,那一天的告警是会停。可请求依然要横跨大西洋二十五次。流量只要再涨一点,8 秒也不够用。到底是忍受症状还是消灭成本,最好事先就想清楚。如果成本的本质是“次数 x 距离”,那要减的就是次数。

延迟会被负载牵着走,per-request 指标不会。上线一个性能修复、看到 p95 变好就放心之前,得先看看一个请求实际干的活是不是真的变少了。这个数字,不管你是凌晨发布还是中午发布,都是一样的。

我数了往返次数,而每次往返的延迟是从代码注释里拿来的。那两处注释说的还是两个不同的值。这次结论没被它改变,算是走运,但下一次结论有可能就被改变了。没测过的数字,就写清楚是没测过的。