深入 Play 34:故障诊断,从外部症状追到线程、提交与资源终态
健康检查返回 200,并不说明服务没有线程饥饿;请求返回 504,并不说明订单没有提交;流的终止回调已经执行,也不说明应用持有的文件句柄已经释放。这三个故障需要查询不同的证据,HTTP 状态码无法独自回答它们。
独立实验包包含 A、B、C 三个可选故障 profile。每个包先保留缺陷,再用相同请求序列运行对应修复。累计示例工程不引入这些缺陷。实验的入口是现象记录:请求耗时、线程栈、独立 SQL、文件描述符和下一次资源申请。
匿名故障包和诊断边界
应用固定为 Play 3.0.6、Scala 2.13.15、sbt 1.10.7、Corretto 21.0.11。数据库场景使用 HikariCP 5.0.1、PostgreSQL JDBC 42.7.5 和 PostgreSQL 17.6。所有请求都发给实际 stage 生产进程,监听地址为 loopback。
源码和驱动位于 examples/play-electives/diagnosis。A/B/C 是给故障包的中性编号,阅读练习可以先看观察结果,再展开源码。自动回归驱动知道预期断言,因此这里的“盲测”是隐藏根因的诊断练习,不是声称由不知情的人完成了一次独立双盲研究。
classify_observations.py 只读取已捕获的 HTTP、线程和资源观察,不读取 Java 源码或启动 profile。它根据观测字段形成定位结论,再与源代码中的具体分支核对。自动分类也只能覆盖这个预先定义的小故障集合,不能作为通用线上诊断器。
| 包 | 首先观察到的症状 | 要保留的反证 |
|---|---|---|
| A | 两个慢请求期间,health 仍为200但延迟上升 | health 本身没有调用数据库 |
| B | 相同订单键连续两次504,最后出现两行 | 第一次504后的独立查询当时还是0行 |
| C | 两次读取后断开,第三次订阅503 | 两条流的终止回调都已执行 |
三个包都只有有限请求数和等待上限。没有持续压测,也没有把整台机器的线程、文件或容器作为清理对象。每个进程只关闭自己建立的执行器、数据库池和文件租约。
先确定是哪一种“没有完成”
flowchart TD
S["HTTP异常或延迟"] --> A{"无业务依赖的health也慢?"}
A -->|是| T["抓实际线程栈与线程名"]
T --> Q["检查共享dispatcher是否执行阻塞代码"]
A -->|否| B{"HTTP失败后业务是否变化?"}
B -->|是| D["独立连接查询提交与幂等键"]
B -->|否| C{"断开后下一次申请是否失败?"}
C -->|是| R["同时检查终止回调、FD、文件和permit"]
C -->|否| X["继续缩小parser、依赖与协议范围"]
这个树中的问题来自可执行检查。health 的实现只构造一个小 JSON,业务线程仍在运行时也应能及时到达控制器。订单终态由另一个 psql 进程读取。资源是否释放由文件系统、lsof 和信号量余量交叉判断。
单独增加日志常会遗漏观测时间。请求失败前的一次 SQL 查询不能证明失败后的终态;应用退出后的句柄归零不能证明每次取消都正确释放。驱动因此把“收到响应”“工作线程空闲”“流终止计数增加”和“下一次申请”分别记录。
包 A:已经完成的 Future 包住了阻塞调用
故障分支在 Action 线程上先执行 sleep(),再调用 CompletableFuture.completedFuture 包装返回值。Java 必须先求实参的值,方法名里的 completedFuture 不会把实参计算移到其他线程。
实验将 Pekko default-dispatcher 的并行度固定为 2,同时发出两个等待 2 秒的请求。随后执行 jcmd <pid> Thread.print -l,保存实际线程名和调用栈,再发送 health 请求。源码中的睡眠只是一个可控阻塞替身,目的是让等待阶段足够稳定,便于采集线程栈。
故障进程的两条睡眠栈都属于 default-dispatcher。health 返回 200,但耗时约 1609.8 ms。修复进程把同一个 sleep() 提交到两个线程、16个队列位置的独立 ThreadPoolExecutor;相同负载下,睡眠栈属于 diagnosis-business,health 约 20.1 ms。
两个工作请求在修复前后仍各自等待约 2 秒。修复没有加快业务操作,而是让不依赖它的请求获得调度机会。单看业务请求耗时会错过这个变化。
Play 3.0.6 的 JavaAsync 文档明确区分异步 Result 和阻塞工作所需的执行上下文。实际修复点是 hold() 中从“同步调用后包装”变为“提交到指定执行器”,并在生命周期停止钩子中等待该执行器退出。增加默认线程数可能暂时推迟饥饿,但不会证明共享线程上的阻塞代码已经移走。
这个小型负例只发出两个任务,没有覆盖独立队列耗尽后的所有异常映射。生产端点还需要明确容量拒绝响应、排队预算和上游重试策略;第33篇的有界队列实验单独覆盖了这些问题。
包 B:第一次超时后重试,两个事务都提交了
B 的每次请求在独立业务线程中打开事务,执行 pg_sleep(1.5),随后插入一行订单并提交。HTTP 结果的外层时钟为150 ms,计时任务只是完成 Result,不取消 Statement,也不终止事务。
故障表有自增主键,但业务 key 没有唯一约束。第一次请求得到504后,独立连接查询仍为0行;相同key立即重试,也得到504。等待两个工作线程空闲后再查,数据库已有2行。
sequenceDiagram
participant C as 客户端
participant P as Play与预算时钟
participant W as 两个业务线程
participant D as PostgreSQL
C->>P: 相同key第一次请求
P->>W: 事务1
P-->>C: 504
C->>D: 独立查询
D-->>C: 0行
C->>P: 相同key重试
P->>W: 事务2
P-->>C: 504
W->>D: 两次INSERT
D-->>C: 无唯一约束时最终2行
Note over D: 唯一key与ON CONFLICT后最终1行
修复表给 key 加 UNIQUE,并使用 INSERT ... ON CONFLICT(key) DO NOTHING。相同请求序列仍然得到两次504,最终行数变为1。这里修复的是重复副作用,没有把“及时响应”或“取消事务”混入验收条件。PostgreSQL 17 的 INSERT 文档定义了唯一约束冲突时 DO NOTHING 的行为。
这个模型故意没有 payload、租户和金额,只证明业务key防重复的最小机制。真实订单服务需要检查“同key不同payload”,需要定义幂等键的租户作用域,也需要在重试时返回已存在的业务结果;第33篇和结课服务包含更完整的契约。
初次运行使用400 ms的数据库等待,独立psql的启动与连接开销超过了剩余观测窗口,早期查询已经看到提交。失败记录保留在原始证据中,最终实验把受控等待延长为1.5秒,再完整重跑六个场景。观测必须实际落在两个事件之间,不能因为命令按顺序写出,就假定它们之间有足够时间。
包 C:流终止了,应用租约没有释放
C 每次订阅先申请一个permit,再创建临时文件并打开FileChannel,将它们登记成一个应用租约。总许可数为2。响应以chunked方式周期性发送合成数据;这个临时文件代表导出任务持有的旁路资源,不是Pekko的FileIO stage自身管理的文件。
客户端直接建立TCP连接,读取响应头和至少8 KiB响应数据后关闭socket。实际收到的字节还可能包含分块编码开销和额外块,日志保留原始读数,不能把它当成文件字节进度。
缺陷分支在 watchTermination 的完成回调里只增加计数,没有关闭租约。两次断开后,终止计数为2,FileChannel仍有2个打开,磁盘上仍有2个临时文件,lsof也能看到这两个路径。剩余许可为0,第三次订阅得到503。
这组证据排除了“服务器还不知道连接断开”的假设。已经观察到的终止信号没有触发应用自己的释放逻辑。仅有一个完成回调,无法证明回调里的动作完整。
修复分支调用 release(id):先从ConcurrentHashMap移除租约,只有取到租约的调用者负责关闭文件、删除临时路径,并在finally中归还permit。终止回调和停止钩子重复触发时,第二个调用者取不到同一租约,避免双重归还。
相同TCP取消序列后,租约数、打开通道数和临时文件数均为0,许可恢复为2,第三次订阅得到200。验收不是“close方法调用过”,而是下一次同等资源申请成功,且系统资源的读回值相符。
Pekko 1.0.3 的 watchTermination 提供代表流终止的完成值。成功结束和取消不能仅凭“完成了”区分;这里因为客户端主动断开且流持续产生数据,驱动能把终止现象与明确的取消动作关联。它仍然不证明对端完整消费了某个文件。
释放一次的完整小例子
下面的 Java 21 程序建立真实临时文件和通道,并并发调用两次close。程序只证明租约实现的重复释放保护;真实网络取消的证据仍来自C包。
1 | |
这个例子先取得许可,再创建文件和通道;初始化失败时删除已创建路径并归还许可。关闭或删除本身失败的注入仍未运行,不能从正常取消结果推导出磁盘故障也已处理。C包的实际stream方法也为初始化失败设置了关闭、删除和permit归还分支。
同负载回归与退出
可下载诊断工程与完整证据,用SHA256SUMS校验。共享工程位于 examples/play-electives/diagnosis,接入后重新生成 stage 并核对 2 个自有 class 的 jar 字节,真实运行 6 个场景、26 条断言;线程转储、SQL、文件描述符、TCP 及退出记录在 examples/play-electives/evidence/diagnosis/integration。隔离结果保留在同级 isolated,两次运行分别记账。
最终运行包含6个生产进程和26条断言,分别覆盖三个缺陷版本及三个修复版本。A检查具体线程栈与health时延,B检查两次HTTP超时与独立SQL行数,C检查TCP取消、打开文件与下一次许可申请。三种结果不能合成一个“接口测试通过”来代替。
每个进程在场景结束后收到SIGTERM,停止钩子等待业务线程退出、关闭预算时钟、回收剩余租约并关闭数据库池。故障C的残留租约先由受控reap端点回收,再退出,避免实验结束后留下故意制造的资源。关闭日志中worker与clock均关闭,permits为2,leases为0;B的数据库会话还通过独立查询确认归零。
reap 是实验救援入口,不是生产修复。若只有应用停止时才回收文件,服务运行数天期间仍会积累泄漏。取消修复需要在每次流终止时生效,回归必须在应用继续运行时重新申请资源。
完整命令见工程README。核心运行方式是:
1 | |
原始证据在 examples/play-electives/evidence/diagnosis/isolated。线程栈与lsof属于实际进程快照,SQL来自独立连接,控制器class与stage jar另有字节核对。当前没有JUnit用例;编译成功只证明包能生成,26条运行断言才证明这些具体场景。
两个诊断练习
保留A的请求负载,分别改为CPU忙循环和等待外部HTTP。先写出预期线程状态,再捕获线程栈、CPU读数和health延迟。两个请求都慢,不意味着根因都是Thread.sleep;线程状态与栈顶方法应该能区分等待和计算。
在C的资源释放路径加入可控的删除失败,要求保留未删除路径和错误原因,并验证其他租约仍能释放。下一次申请成功不能单独证明文件已经消失;把“容量恢复”和“磁盘清理完成”拆成两条验收,再决定失败重试应由哪个生命周期负责。
上一节:33 相同约束下的Web栈。下一节:35 可验证的订单与订阅服务。
