HTTP 成功、SQL 成功与订单存在可以不一致

一次真实 HTTP 请求返回 200,Actuator 的请求指标记录 SUCCESS,SQL 日志包含成功执行的 INSERT,独立数据库会话却查不到订单。这个结果不需要网络故障:请求代码最后显式 rollback,同时正常返回字符串,所有表面现象都符合各自的语义。

观测的难点是不同记录只覆盖不同边界。请求指标覆盖 HTTP 处理,SQL 完成覆盖语句执行,事务终态决定写入是否保留。要解释订单为何不存在,需要将这些记录关联到同一操作,而不能从某一条“成功”推断整体业务结果。

本篇在一个合成请求内注入数据库休眠、连接池等待和线程池拒绝,另开一次独立启动失败场景。运行基线为 JDK 21、Boot 3.5.6、Framework 6.2.11、Tomcat 10.1.46、Micrometer 1.15.4、HikariCP 6.3.3、pgJDBC 42.7.7、真实 PostgreSQL 18.0。HTTP 使用本机随机端口,数据库只操作专用 spring_ch40_orders 表中的合成行。

实验故障均为主动构造,不是生产事故回放或性能容量评测。300 毫秒查询与等待用于区分可见事件,不提供任何吞吐量结论。

请求、观测、数据库等待与业务终态的关联图

启动失败要保留失败发生的阶段

Chapter40.Broken 声明的工厂方法主动抛出 IllegalStateException("synthetic-boot-failure-40")。启动监听器记录一次 ApplicationFailedEvent,外层断言捕获 Bean 创建异常,并确认消息包含 broken。

异常链保留三个层次:启动失败的通知、容器指出的 Bean 名称、工厂方法抛出的具体原因。它们不应被压成一条“SpringApplication 启动失败”。最外层只说明启动没有完成,最内层才解释这个实验中的故障原因。

Boot 的 SpringApplication.run 在 refresh 前准备环境和上下文,在 refresh 后调用 runner,两个阶段的异常都可进入失败处理。因此 ApplicationFailedEvent 本身不提供唯一故障阶段,仍需结合栈、Bean 定义来源和时间线。固定启动实现

成功启动的 HTTP 应用启用容量为 2048 的 BufferingApplicationStartup。实际时间线包含 spring.beans.instantiate 步骤。它有助于缩小启动耗时的位置,但某个 Bean 创建耗时长,也可能包含其依赖创建或外部连接等待,不能仅凭步骤名称就判定该类算法慢。缓冲容量还限制可保留事件数量,本实验只断言相关步骤存在,不把事件总数当成跨机器恒定值。

请求标识如何连接不同线程的事件

HTTP 入口是 /evidence,每次实验只发一个业务请求,操作标识固定为 synthetic-40。事件包含标识、System.nanoTime()、线程名与阶段信息。SQL 注释保留同一标识,数据库连接取得 pg_backend_pid(),后续服务器观测使用这个 PID。

这种固定标识适合单请求可复现实验,不适合作为生产请求 ID。生产中的并发操作需要唯一标识、生命周期和传播协议;仅在线程本地保存字符串,任务切换后不会自动传播。本实验跨线程传入同一个明确的 id,并没有验证 tracing bridge 的自动上下文传播。

nanoTime 用于同一 JVM 内的耗时差值,不是 UTC 时间戳,不能直接与另一台机器的日志相减。服务器等待记录的时间来自观察方收到结果的时刻,因此表示“在这个采样窗口观察到等待”,不是数据库内部事件精确开始时间。

因果还需要对象身份。数据库 backend PID 将 SQL 与服务器会话连接起来,连接池的 active/waiting 计数描述本池状态,线程池的 active/queue 计数描述本执行器状态。只把所有消息写到一个文件,不会自动建立这些归属关系。

慢 SQL 要从服务器侧验证

请求先取得唯一池连接,关闭 autocommit,写入一行订单。工作线程随后在同一连接上执行:

1
select pg_sleep(0.3) /* synthetic-40 */;

HTTP 线程使用独立 DriverManager 连接查询 pg_stat_activity,按 backend PID 过滤,观察 wait_event_type=Timeout、wait_event=PgSleep 以及带合成注释的 SQL。查询线程完成后,Future 返回,才继续下一项故障注入。请求线程与查询线程没有同时操作同一个 JDBC 连接。

一次实际运行的关键片段如下,PID 和纳秒值在重跑时会变化:

1
2
3
4
connection.acquired backend=72457 active=1
sql.start backend=72457 sql=select pg_sleep(0.3) /* synthetic-40 */
server.wait backend=72457 type=Timeout event=PgSleep
sql.end backend=72457

这组证据说明该会话确实在 PostgreSQL 的休眠等待中,而非应用只在客户端 sleep。它仍然不是慢查询优化案例:pg_sleep 没有索引选择、锁冲突或执行计划退化。真实 SQL 变慢时,应按相同关联方式继续检查锁、I/O、计划和返回行数,而不是把所有等待都归为数据库 CPU 不足。

观察连接必须独立于待诊断池。若从已经耗尽的同一个连接池取诊断连接,采样可能先被资源等待阻塞,造成“数据库没有活动”的错误印象。独立观察也有连接成本;本实验显式关闭该会话,不假设监控操作没有资源消耗。

连接池等待发生在 SQL 之前

本池最大连接数为 1,当前请求继续持有该连接。第二个工作线程尝试 getConnection(),因此没有机会发送 SQL。HTTP 线程观测 waiting=1,随后等待者在配置的 300 毫秒 connectionTimeout 附近抛出 SQLTransientConnectionException。

1
2
3
pool.wait active=1 waiting=1
pool.timeout SQLTransientConnectionException
pool.wait.duration.ns=307850583

这条时间记录对应一次运行,不是“超时保证恰好 307 毫秒”。断言依据是等待者进入池等待、最终得到规定异常和任务结束;调度、日志与方法调用会影响测量差值。

数据库慢查询与池等待可以有因果关系,但本实验把两阶段顺序拆开:慢 SQL 已经结束,持有连接的事务仍未结束,第二个取连接动作照样等待。这能排除“池等待一定意味着某条 SQL 仍在执行”的错误判断。应用在事务内进行其他工作,同样可能长时间占用连接。

增大池上限会改变这个反例,但未必提高整体容量。后端数据库可并行处理能力、每请求连接需求与持有时间仍然约束系统。这里没有负载压测数据,不能从“单次等待消失”得出扩容方案在生产中有效。

线程池拒绝要同时检查队列与任务终态

执行器设置为一个工作线程、容量为一的有界队列。第一个任务通过 latch 保持运行,第二个任务占据队列,第三次 execute 触发 RejectedExecutionException。日志记录 active=1、queued=1,将拒绝与当时容量状态关联起来。

拒绝本身也是边界事件:第三个任务没有开始,不能记录成“任务运行失败”。调用方必须决定如何改变业务结果。本实验捕获它作为预期负例,随后释放第一个任务、排空第二个任务、shutdown 并等待终止。它没有把拒绝异常吞掉后声称通知已经发出。

这里使用直接的 ThreadPoolExecutor 来控制队列状态,拒绝语义与 JDK 执行器一致。它不证明任意 @Async 代理、事件广播器或调度器都配置了相同队列;那些入口仍需核查实际注入的执行器、拒绝处理器和异步异常传播方式。

验收同时检查结束后连接等待者为零、执行器终止、队列中的任务完成。只看到一次 rejection 日志,无法排除两个已经接受的任务在异常路径中永久阻塞。

Observation 是生命周期协议,不是业务提交证据

HTTP 应用通过 Boot Actuator 自动配置提供 ObservationRegistry。业务入口建立 lab.order Observation,并使用专用 OrderContext 子类匹配自定义 ObservationHandler。Handler 在开始和结束时记录事件,最终断言结束回调恰好执行一次。

Handler 的 supportsContext 依据上下文类型,不依赖一个尚未完成设置的名称字段。Micrometer 在构造观测对象时就会筛选 Handler;若假设此时 getName() 一定非空,观测代码自身就可能导致请求失败。专用上下文还使业务 Handler 与框架提供的 HTTP 观测分开。Observation 组件协议

业务标签使用低基数字段 operation=synthetic,合成请求 ID 放在日志中。将每个订单号都放进指标 tag 会不断增加时间序列数量。日志关联字段与聚合指标维度承担不同职责,不应把前者全部复制给后者。

本实验没有安装 tracing bridge、导出器或收集器,所以没有声称生成了可跨服务查询的 trace。实际观察到的是 Observation 生命周期、自定义事件和 Actuator 请求指标。需要分布式追踪时,还必须验证跨进程上下文、采样、导出及接收端记录,不能从 Registry Bean 存在推导那些行为已经发生。

四种成功对应四个可验证的边界

请求结束前显式 rollback,HTTP 返回 synthetic-40:rolled-back。随后读取 /actuator/metrics/http.server.requests,指标包含 COUNT=1、status=200、outcome=SUCCESS。这是已经完成的 HTTP 观测,且采样发生在第二个指标请求自身完成之前。

独立数据库连接再查询专用主键,结果为零。这个读回验证写入没有保留;Observation 的 error=null 表示业务回调没有向外抛异常,不等于事务一定 commit。系统若把“HTTP 成功”当作“订单创建成功”,错误发生在业务协议映射层,指标无需伪造就会产生误导。

观察 实际覆盖的边界 不能单独证明
SQL 执行结束 语句完成 事务提交
Observation 正常停止 被观测操作返回 订单持久化
HTTP 200 / SUCCESS 请求响应状态 下游业务终态
独立会话 count=0 此时已提交数据不可见 所有外部副作用均不存在

最后关闭 ApplicationContext,断言 Hikari 已关闭,并再次连接随机 HTTP 端口得到 I/O 失败。请求返回后 active connection 为零、池关闭和端口关闭,分别覆盖请求级与应用级资源终态。数据库服务器由整套实验共享,不属于本篇启动的资源,因此保留运行。

复现与修改练习

先按实验工程 db/README.md 启动 PostgreSQL,默认地址为 127.0.0.1:55432,数据库与用户均为 spring_lab,使用合成数据。随后在实验根目录执行:

1
sh boot-lab/run.sh 40

原始证据在 evidence/40/local-20261002/run.txt 和退出码文件中。启动失败堆栈属于预期场景,后面的业务请求应完成,末行出现 CHAPTER 40 PASS。该场景会产生真实监听端口与数据库访问,容器内或受限环境必须提供相应权限,不能用静态编译结果代替运行证据。

修改练习:只把 rollback 改成 commit,预测哪些日志与指标保持相同,哪个业务断言会失败。HTTP 仍可返回 200,Observation 仍可正常停止,但独立会话 count 应从零变为一。再把池容量改为 2,预期 waiting=1 的故障注入断言不再成立;这提示实验输入改变后必须调整场景定义,不能简单删除失败断言继续宣称池耗尽被验证。

前置阅读:深入 Spring 38:Boot 自动配置的输入、退让与属性绑定 与 深入 Spring 19:编程式事务、连接绑定与提交结果。

参考资料