解决因主库故障迁移导致的核心服务不可用问题

1. 背景

8月30日，下午 15:50 左右，因阿里云 RDS 宿主机故障，我们部署在此宿主机上的一个核心订单库（mysql.order_sharding ）因探活失败发生 HA 切换。随后，交易主链路上依赖该库的若干应用陆续出现了服务不可用问题，并又一次经历了漫长的恢复过程。之所以说是 “又一次”，是因为在过去这半年时间里，类似的问题已经不是第一次发生。 根据 NOC  提供的本次事件时间线。

显然，超过3分钟的恢复时间，无疑在强烈的警告我们 —— 肯定在某个环节搞砸了。而同一问题重复出现，也让我们深感不安，或许下一次就要酿成大祸。为了弄清楚问题的根源，避免再次栽跟头，组织成立了一个特别调查小组，而我也奉命和交易的同学一起，将问题查个水落石出。

2. 整理信息

盲干肯定是不行的，得先确定排查的方向和重点。既然已经不是第一次发生这样的问题了，我决定先从当前已有的线索着手。截止目前，掌握的关键信息有：

1. HA 结束后，订单相关应用 CPU 负载飙高，且历次问题都具有类似特征（典型的是 bme-trade-order-svc ，由于这个应用比较底层，被众多上游应用依赖，且靠近出问题的数据库，后续的排查将重点围绕该应用展开）；
2. 结合此前历次故障，交易同学推测导致服务不可用的原因是：数据库故障期间，用户重试，创建了大量工作线程（Tomcat Thread）。数据库故障恢复后，为了调度数量庞大的工作线程，导致 CPU 负载持续飙高。最终 CPU 过载，无法继续处理请求，导致整个应用不可用。

在我看来，第一条信息是一种 “观测事实”，事实本身暂时还没有太多可推敲的地方。而交易同学的推测，乍一听，似乎是说得通的。但稍微分析一下，我觉得其中的一些因果关系过于想当然了。

2.1 重试一定会创建大量工作线程吗？

—— 这要看情况。

但也许比较反直觉的是，这种情况其实并不多见。以常态化全链路压测为例，即便是请求量达到日常流量峰值的1.5倍时，工作线程的数量通常也不会有明显增长。

这里我选取了最能反映压测流量变化的应用之一，以其线程监控指标（单机）为参考，如图1。从图中可见，在压测期间，工作线程数（Available Threads/tomcat_threads_current_threads）虽有略微上升，但其峰值仅为38，远低于我们设置的最大工作线程数（Max Threads/tomcat_threads_config_max_threads）200。我们知道，重试本质上等价于增加了流量，而图1的案例说明，简单的增加流量并不会造成工作线程数量的显著增长。

图1：压测状态下线程池波动（单机）

这主要是得益于线程池中工作线程的有效复用，如果一定要让工作线程数量飙升，就要破坏线程复用。最有可能的情况是，工作线程长时间在某个高频操作上陷入等待 。我将在后文中接着来讨论。

2.2 线程多一定会导致 CPU 负载高，甚至过载吗？

—— 至少在当前这个问题的上下文中，我认为不太可能。

首先，我们刚刚讨论过，想要在使用线程池的前提下产生大量的工作线程，则必须要让已经创建的线程长时间等待，阻止线程的复用。然而，通常处于等待状态的线程会释放其占用的 CPU 资源，因此 CPU 负载可能保持稳定甚至有所降低。其次，线程数量并不能无限扩增，最终会达到线程池最大工作线程数，而经过确认，bme-trade-order-svc配置的最大线程数也是200，这个值几乎被视为此类应用的最佳实践。所以对于在数据库故障恢复后调度这200个线程的 CPU 开销来说，算力配额应该绰绰有余，不太可能发生过载。

结合前面的分析，现在让我来整理一下。基于已知的2个事实，我将排查的思路，拆解为表中的6个问题。

接下来我将尝试寻找线索，逐个解答这六个问题，看能否揭示故障根因。

Let's get started!

3. 寻找线索，各个击破

3.1 线程数飙升是因为等待吗？

—— 是的。

其实这个问题回答起来并不是太困难。不过在开始之前，有必要先来复习一下 Java 线程的6种状态。

其中有3种状态表示 “等待”，分别是BLOCKED、WAITING和TIMED_WAITING。如图2：

• WAITING和 TIMED_WAITING状态表达的是线程 主动让出  CPU 时间片，等另一个线程完成某个操作后通知自己 ，再继续执行后续的逻辑。 TIMED_WAITING仅仅是比 WAITING多指定了一个超时时间；
• 而 BLOCKED 状态则是竞争监视器锁失败，被锁 “阻挡”， 被迫等待；
  ‍
  

图2：Java Thread Lifecycle

让我们带着这些知识，再来翻阅 bme-trade-order-svc 应用的监控。如图3，通过 Tomcat 线程池监控曲线可以看到，工作线程确实出现了飙升，发生在 15:51:00 - 15:52:30，并且大致呈现出一种 “三段式” 增长趋势。

图3：Tomcat 线程池监控

而我也很快通过 JVM 线程状态监控曲线发现了时间和趋势都与之对应的线程状态波动的证据，如图4。可以看到 也是在 15:51:00 - 15:52:30 期间，TIMED_WAITING状态的线程数呈现明显的 “三段式” 增长。

图4：JVM 线程数量（分状态）监控

这说明我之前的推论是正确的。因为某种原因，线程池中原本复用良好的工作线程纷纷主动让出 CPU，进入到TIMED_WAITING等待状态，无法再被复用。线程池只能补充新的线程来处理新的请求，可是新补充的线程也很快进入到TIMED_WAITING状态，线程池只能继续补充新线程。就这样，陷入恶性循环，最终导致线程数量飙升。

3.2 线程在等什么？

—— 等数据库连接。

对于这个问题，在实际排查的过程中，几乎可以立刻做出下意识的判断，也很容易从监控上找到证据。我们使用 HikariCP 管理数据库连接，HikariCP 有着完善的连接池指标埋点，其中部分指标的监控信息如图5。但要解释清楚细节，就没那么容易了。让我们先从理解图5中的指标开始。

图5：HikariCP 链接池监控

图中共有3条曲线，我将它们的含义归纳在了下方的表格里。

显然首先会关注的就是 “Pending Connections/等待连接” 指标。这个指标名起的不太好，实际上表示的是当前排队获取连接的线程数，它反映的正是线程在等待 —— 因为获取不到连接而进入了TIMED_WAITING状态。

可能有一部分本文的读者会误认为是获取到连接后，和数据库的 I/O 阻塞，导致了线程进入 TIMED_WAITING状态，但并非如此。事实上，Java 线程遇到同步 I/O 阻塞时，仍然是 RUNNABLE状态。如果你对此不是很有概念，我们可以设计一对简单的 Client - Server 实验程序来验证这一点。

import java.io.IOException;
import java.io.InputStream;
import java.io.OutputStream;
import java.net.ServerSocket;
import java.net.Socket;

public class Server {
    public static void main(String[] args) throws InterruptedException, IOException {
        try (ServerSocket server = new ServerSocket(39707)) {
            System.out.println("[Start] waiting for connection...");
            for(;;) {
                try (Socket connection = server.accept()) {
                    System.out.println("Connected: " + connection.getRemoteSocketAddress());
                    InputStream in = connection.getInputStream();
                    OutputStream out = connection.getOutputStream();
                    
                    byte[] buffer = new byte[1024];
                    int len = in.read(buffer);
                    System.out.println("Recv: " + new String(buffer, 0, len));

                    // We sleep 60 seconds to simulate an I/O wait
                    Thread.sleep(60 * 1000);

                    out.write("pong".getBytes());
                }
            }
        }
    }
}

import java.io.IOException;
import java.io.InputStream;
import java.io.OutputStream;
import java.net.Socket;

public class Client {
    public static void main(String[] args) throws IOException {
        try (Socket client = new Socket("localhost", 39707)) {
            InputStream in = client.getInputStream();
            OutputStream out = client.getOutputStream();

            out.write("ping".getBytes());

            byte[] buffer = new byte[1024];

            // I/O wait on read()
            int len = in.read(buffer);
            System.out.print("Recv: " + new String(buffer, 0, len));
        }
    }
}

代码执行后，Client 首先会向 Server 发送 "ping"，随后阻塞在 Line 17 的read()方法上。而 Server 在接收到并打印出 Client 发送的字符串后，会在 Line 22 行执行 Thread.sleep(60 * 1000)休眠60秒，来模拟服务端在处理繁重的业务逻辑，未及时给出响应。 

此时我们通过jstack查看Client的 "main" thread 堆栈信息，可以看到它处于RUNNABLE状态，如图6。

图6：线程 I/O 阻塞时的堆栈信息

那么获取 HikariCP 连接又为何能够让线程进入TIMED_WAITING状态的呢？答案就藏在源码中，如图7、图8。

首先来看图7，图中的 getConnection(final long hardTimeout)方法，是获取数据库连接的入口方法，位于 com.zaxxer.hikari.pool.HikariPool 类中，其中最重要的是 Line 9，从 connectionBag（com.zaxxer.hikari.util.ConcurrentBag 的实例） 中借出（borrow）一个连接（PoolEntry）。要么借出成功，要么等待timeout毫秒后超时，返回一个空值null。

图7：HikariCP 连接池获取连接入口方法

而borrow方法的实现中，唯一可能导致线程进入TIMED_WAITING状态的代码就是图8中 Line 32 的handoffQueue.poll(timeout, NANOSECONDS)。此处poll 方法的第一个参数timeout，就是getConnection方法的入参hardTimeout。经确认，bme-trade-order-svc并没有配置这个超时时间，timeout 使用的是默认值：30s。

另外，这里的handoffQueue实际上就是java.util.concurrent.SynchronousQueue，最常见的用法就是作为 handoff queue 协同（sync up）两个线程的执行过程。

对于SynchronousQueue，官方文档 专门有一段这样的描述：

图8：HikariCP 连接池 ConnectionBag 的 borrow 方法

3.2.1 扩展知识：HikariCP 并发工具包 ConcurrentBag

如果不熟悉 HikariCP 的ConcurrentBag并发设计，borrow方法的源码可能会比较难理解。尽管本文不是专门介绍 HikariCP 的文章，但我还是打算花一些篇幅展开讨论一下 HikariCP 获取连接的过程。如图9，

• 工作线程会首先尝试从 threadList中获取连接， threadList是一个 ThreadLocal 对象，可以理解为每个线程都缓存了一部分连接。对应的代码为 图8中的 Line 3 ~ 12；
• 如果未能从 threadList中获取到可用连接，则继续尝试从 sharedList中获取连接。 shareList是一个 CopyOnWriteArrayList，跨线程共享。对应代码为 Line 14 ~ 25；
• 如果仍然未能获取到可用连接，线程将在 handoffQueue的 poll方法上等待，直到其他线程归还连接（ poll方法将返回释放的连接）或超时（ poll方法将返回 null）。对应代码为 Line 29 ~ 38；
  
  图9：线程获取 HikariCP 连接的过程

实际上，一段简短的borrow方法，整合了很多设计上的玄机，包括：

• Lock-Free Design；
• ThreadLocal-Caching；
• Queue-Stealing；
• Direct hand-off optimizations；

以下分别做介绍。

3.2.1.1 Lock-Free Design

让我先从图9中的sharedList讲起，这是一个CopyOnWriteArrayList，它在 HikariCP 中，扮演的就是 “连接池” 的角色。通常在一些其他的连接池设计中，取出连接时会将连接从池中删除，等连接用完后再添加回连接池中，在并发场景下，删除和添加这两个动作都需要加锁。HikariCP 的精妙之处就在于，用 “借+还” 的设计，规避了对sharedList的频繁更新。连接在被线程借出（borrow）的时候是不会从池中删除的，而是通过 CAS 修改连接的状态为 “使用中（STATE_IN_USE）”。反之，当线程归还（requite）连接的时候，也不需要将连接添加回池中，只需要将状态修改为 “空闲（STATE_NOT_IN_USE）”。这是典型的 Lock-Free 设计。

3.2.1.2 ThreadLocal-Caching

从图9还可以看到，每个线程都有一个独立的threadList用来缓存该线程使用过的连接，对于为什么引入 ThreadLocal-Caching，官方并没有做过多的解释，以下是我自己的理解：

对比下 borrow 方法中遍历 threadList 和 sharedList 的实现方式，也能看到一些细节，如图10、图11。

• 图10中，遍历 threadList 是按下标，从 list.size() - 1，即 List 的末尾元素开始，从后往前倒序遍历的；

• 而图11中遍历 sharedList 时，则直接使用了语法糖从前往后按照正常顺序遍历；

图10

图11

这是因为threadList中越靠后的元素越是最近刚加入到缓存中的连接，其被别的线程借用的可能性越小，这种遍历的策略完全符合 “亲密假说”。而sharedList中的连接能否被借用的概率与其在 List 中的位置并无关系，因此用正常的遍历方式即可。同时可以看到，图10中直接通过list.remove(i)将遍历到的连接从 List 中删除，这么做首先是因为ThreadLocal 的线程独占特性，不用担心锁竞争。其次，当遍历到的连接 “可以借出（STATE_NOT_IN_USE）” 时，该连接被返回，使用完后归还时再次被加到 List 末尾，仍然是当前线程最 “亲密” 的连接，而如果连接 “不可借出（STATE_IN_USE）”，则确保了 “不再亲密” 的连接从缓存中删除。

3.2.1.3 Queue-Stealing

图12：Queue-Stealing 思想实验示意图

现在参考图12，让我们通过一个思想实验来理解一下 Queue-Stealing 设计：

值得一提的是，在图8中，Line 19 有一段注释，尽管也提到了 stolen 关键词，但和 Queue-Stealing 并不是一回事：

让我们结合代码上下文，来理解一下相关代码的真正意图：

• Line 15：执行到这里说明线程未能从 threadList中获得可用连接，需要等待别的线程归还连接。因此HikariCP 的  waiters（ waiting）计数器  +1；
• Line 27：先看 27 行。代码执行到这里，说明线程遍历完整个 sharedList，也没能获取到可用连接（否则 Line 23 就已经返回了）。换句话说，连接池中的连接已经耗尽。在没有达到连接池配置的 “最大连接数上限” 的前提下， listener.addBagItem(waiting) 会通过一个独立的线程，创建 waiting个新连接，并添加到连接池中，对连接池进行扩容；
• Line 19-22：此时回头看 19 ~ 22 行，发现这只是启动连接池扩容的一种特殊情况。假设  sharedList中仅剩 1个可用连接，而 Thread #1 和 Thread #2 同时（waiters/waiting = 2）在遍历  sharedList，最终 Thread #1 获得了连接。如果没有 Line 19-22 的代码， borrow 方法将直接返回，没有进行任何的连接池扩容；

3.2.1.4 Direct hand-off optimizations

从borrow方法中可以看到，如果线程遍历完 sharedList 后依然没有获得可用连接，就会在handoffQueue.poll(timeout, NANOSECONDS)方法上等待。当其他线程归还连接时，也会首先尝试通过 handoffQueue直接将连接传递给等待的线程，相关代码在requite方法中，如图13。

图13：HikariCP 归还连接

一个题外话，当通过 handoffQueue 投递连接失败时，HikariCP 进行了两种不同的处理：parkNanos(MICROSECONDS.toNanos(10)) 和yield()。前者很好理解，相当于主动休眠 10 ms，但应该如何理解 yield() 呢？

Java Thread 对yield方法有一段如下的注释：

很显然，尽管都是 “主动让出” 算力资源，但它和 parkNanos 的区别在于，yield 将决定权交给了调度器（scheduler），调度器可能会让当前线程运行继续执行。相比于强制休眠，线程切换的开销、调度效率更高，可用连接的投递延迟（latency）可能更低。

3.3 是因为工作线程飙升导致 CPU 负载高吗？

—— 不是的。

在 2.2 节我已经给出了 “否定” 的推测，主要是基于两个推论：

1. 飙升的线程大都也处于等待状态，会主动释放 CPU 资源；
2. 调度 200个工作线程对于应用的算力配额来说不是难事儿；

要证明推论正不正确也很简单，只需要把 “活跃线程数监控曲线” 和 “CPU 利用率监控曲线” 放在一起做个对比，答案就显而易见了，如图14。

• 15:51 - 15:52 之间（粉色阴影区域）活跃线程数飙升，在 15:52 左右达到顶点。上文已经分析过，这主要是因为工作线程无法获得可用的数据库连接，在 handoffQueue 的 poll方法上等待，导致线程池复用机制失效。同时段内 CPU 利用率呈现下降趋势，在 15:52 左右几乎跌零 。这说明第一个推论是正确的；
• 15:52 - 15:53 之间（黄色阴影区域）活跃线程数开始下降，同时 CPU 利用率小幅度上升，但仍然处在 40%左右的安全水位。说明调度完积压的 2K+工作线程，并没有给 CPU 带来无法接受的负载 。因此，第二个推论也是正确的；

图14：活跃线程数 VS CPU 利用率

至此，足以得出结论：工作线程飙升并没有导致 CPU 负载高。

但从图14中也看到，又过了一分多钟后，大约从 15:54:30 开始（灰色阴影区域），的确出现了 CPU 负载飙升的问题，部分 Pod 节点的峰值甚至超过了200%。

3.4 CPU 负载飙高的原因是什么？

—— 应用重启。

既然和工作线程的飙升无关，CPU 负载飙高的原因又是什么呢？这时我把注意力放在了 CPU 负载飙升之前 15:53 - 15:54:30，即图14中靛蓝色阴影区域。可以看到，在 CPU 负载飙高前的这段时间里，活跃线程数是跌零 的。 

俗话说，事出反常必有妖。看到 “活跃线程跌零”，你会想到哪些可能的原因呢？闪过我脑中的有：

事实上，我首先向交易同学确认了该应用在故障时间段内是否进行了重启 ，原因是根据以往经验，应用重启后由于代码预热、流量负载均衡等原因，的确可能导致 CPU 飙升，甚至触发长时间限流，使得应用不可用，这和我们的问题模型、曲线特征都很相似。但得到的答复却是否定的 ，于是只能转而去排查是否为第一种原因。

查看了多个上游应用后，我终于发现了一丝端倪，如图15。图中上半部分是 bme-trade-order-svc 接收到的请求的 QPS 埋点曲线 ，下半部分则是它的其中一个上游应用发起调用的 QPS 埋点曲线 。

图15：客户端流量 VS 服务端流量

对比图中粉色阴影区域，可以看到，在服务端跌零的这段时间，客户端的请求实际并没有跌零。于是我推测，可能是客户端的请求根本没有到达服务端。通过进一步搜索客户端日志，确认了这一点。如图16，可以看到上游应用调用 bme-trade-order-svc 的时候，抛出了 Connection Refused 异常。

图16：上游 Connection Refused 异常

然而 bme-trade-order-svc 的调用方式和标准的 SOA 调用方式有所区别，并不是 “服务发现 + 软负载” 的方案，而是基于域名的方案，调用链路如图17，由专门的 SLB 来完成域名解析（trade-xxxhll.cn:80，见图16）、负载均衡和流量代理。是否是 SLB 服务异常、或者执行了某些流量管制策略，导致了客户端 Connection Refused 呢？

图17：调用 bme-trade-order-svc 应用的流量路径

因为 SLB 由 CI 团队闭环管理，我只能求助于当日值班的运维同学协助排查。经过细致的分析，最终我们确认 SLB 在故障期间一切正常。正当要走入死胡同之际，运维同学在排查节点历史事件的时候，偶然发现 bme-trade-order-svc 的一些 Pod 在故障期间发生了重启！这显然和交易同学同步的信息不同，但却让人喜出望外。

图18：Pod 重启事件

部分节点的重启事件如图18。经过分析，15:52:30 开始就有一部分节点发生了重启，而更多节点的重启发生在 15:53:30 前后，由于重启过程中的节点不可用，这就导致了前面的 Connection Refused 异常，也导致了图15中 15:53:30 - 15:55:00 时段内的流量曲线跌零。

重启完成后，未预热的应用突然接入大量上游重试流量，CPU 负载也随之飙升，触发了严重的 CPU 限流，如图19。

图19：服务端 Pod CPU 限流

那么，服务不可用是因为 CPU 负载飙高吗？

3.5 服务不可用的原因是什么？

—— 3个阶段，3种原因：线程等待、应用重启、CPU 限流。

看完上文的分析就知道，对于这个问题，我们不能提供一个统一的答案，而是需要分为三个阶段，每个阶段中导致 bme-trade-order-svc 不可用的 “主要原因” 都有所不同。为了让这个问题更容易理解，我们引用 RT 与 Error 指标的对比图，如图20，来解释一个具体的上游应用例子。

• 图20的上半部分，显示的是 Consumer RT 指标，它反映了上游应用调用  bme-trade-order-svc所需的响应时间；
• 图20的下半部分，展示的是 Consumer Request Error 指标，它反映了上游应用在调用  bme-trade-order-svc 时产生的错误数量；

图20

结合图20的指标特征，我总结出了如下的表格。

当然，实际情况中，导致系统不可用的诸多影响因素，无法准确的按照表格所示的时间段进行分割，往往存在着一些交叉区域。这也是我选择聚焦于各个阶段的主要影响因素的理由。

4. 我们能恢复的更快吗

答案显而易见。至少有下面几个改进方向：

• 能不能不让线程傻等？获取不到连接时 Fail faster？ —— 合理调整超时时间的设定；
• 线程发生等待时，能否不那么轻易的重启？ —— 改良 “探活” 设计；
• 就算发生重启，应用重启后能否更快响应请求（少限流）？ —— 提升 Java 应用在启动完成初期的性能表现；

4.1 合理调整超时时间设定

如何正确设置超时时间，是个庞大且复杂的话题。在正式讨论之前，先要区分和超时有关的三个概念。

考虑下方的伪代码，相信熟悉 Java 的同学不会陌生：

@Component
public class UserService {
    @Resource
    private UserRepository repository;
    
    @Transactional(timeout = 3)  //org.springframework.transaction.annotation.Transactional
    public void updateUserInfo(UserEntity entity) {
        repository.updateProfile(entity);
        repository.updateAccount(entity);
        repository.updateExtra(entity);
    }
}

• Line 3-4：注入 DAO bean，是一个 UserRepository 类实例。 UserRepository  暴露了三个方法  updateProfile 、 updateAccount  和  updateExtra ；
  
• Line 6：开启事务，事务超时时间设为 3s；
• Line 7-11： UserService对外暴露的唯一公共方法 updateUserInfo，内部通过调用 UserRepository的三个方法，对用户信息进行更新；

假设使用的 ORM 框架为 Mybatis，并存在如下方表格所示的关系。

<update id="updateProfile" parameterType="xxx.xxx.UserEntity">
update tb_user_profile
<set>
    <if test="userName != null and userName != ''">
        username = #{userName}
    </if>
</set>
</update>

<update id="updateAccount" parameterType="xxx.xxx.UserEntity">
update tb_user_account
<set>
    <if test="token != null and token != ''">
        token = #{token}
    </if>
</set>
</update>

<update id="updateExtra" parameterType="xxx.xxx.UserEntity">
update tb_user_extra_data
<set>
    <if test="address != null and address != ''">
        address = #{address}
    </if>
</set>
</update>

代码（3）

那么，代码的执行过程，可参考图21（从左往右来解读）：

图21

其中和超时设置有关的地方共有5处，图中已经分别用 ①②③④⑤ 序号标注。

4.1.1 与 “连接池管理” 有关的超时：获取连接超时（HikariCP connectionTimeout）

对应图21中标号为 ① 处的超时，这个超时时间很容易引起混淆。它代表的含义是 “从连接池中获取到连接的最长等待时间”。注意这个时间和数据库读写超时是无关的，它发生在实际发送 SQL 之前。因此，当我们得到一条和数据库操作相关的异常信息时，一定要注意区分到底是获取连接超时，还是读写数据库超时。 

例如，主要影响本次故障恢复时长的因素之一，就是获取连接的超时时间太长，排查过程中，我们也得到了如图22的异常日志（30s），但很多同学都误认为是读写数据库超时，对问题根因的判断也因此跑偏了。

回看图7的代码，getConnection方法的 Line 26，当获取连接超时，会调用createTimeoutException方法，抛出超时异常。方法实现如图23，而日志中的异常信息就是由 Line 11 代码输出的。

图23：createTimeoutException 实现

那么，获取连接的超时时间应该设置为多少呢？结合目前的最佳实践，建议设置为1s。实际上，上文已经分析过，获取连接的操作从设计上就是 “低延迟（Low-latency）” 的。在理想情况下，连接总是被提前创建好放入池中，线程高效借出、使用、归还连接，实现最大化的复用。当线程在获取连接上等待时间过长时，说明连接的复用出现了严重的问题 ，此时应该去解决这个问题 ，而不是调大超时时间。

4.1.2 与 “数据库操作” 有关的超时

在具体介绍 事务超时（Transaction Timeout）、 语句超时（Statement Timeout） 和 JDBC 驱动超时（JDBC Driver Timeout） 之前，让我通过一种相比图21更加清晰的方式，帮助大家从宏观上认识一下这三个超时时间生效的具体位置，如图24。

图24：不同超时时间生效的位置

记住了吗？那么，就让我从承上启下的 Statement Timeout 开始说起。

4.1.2.1 语句超时（Statement Timeout）

对应图21中标号为 ② 处的超时。顾名思义，就是对语句（Statement）运行时长的限制。语句超时是通过 java.sql.Statement.setQueryTimeout(int timeout) 这个 JDBC API 进行设置的，但在整合了 ORM 框架（e.g. Mybatis）的项目中，则通常是通过框架进行配置，例如下方的 XML 配置代码。

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE configuration
        PUBLIC "-//mybatis.org//DTD Config 3.0//EN"
        "http://mybatis.org/dtd/mybatis-3-config.dtd">
<configuration>
    <settings>
        <setting name="defaultStatementTimeout" value="3000"/>
    </settings>
</configuration>

也许会有一部分读者对 Statement Timeout 和 JDBC Driver Timeout（Socket Timeout） 感到困惑，搞不清二者区别。在接下来的 4.1.4 节，我将更细致的介绍 JDBC Driver Timeout（Socket Timeout），现在只需要知道这个超时时间是通过 JDBC 配置，但却是由操作系统的 Socket 层执行和生效的，本质上是控制 “网络通信（通过网络读写数据）” 的超时时间。而 Statement Timeout 则是通过 JDBC API 定义 ，由 JDBC Driver 执行和生效的，参见图24。

具体来说，在 JDBC Driver 执行 Statement 时，会创建一个新的线程，并向该线程注册 “超时任务”（参见图7中 New Thread 节点串联的链路）。当超时发生时，该线程会获取一个新的连接，通过该连接向数据库发送取消执行指令（KILL QUERY ），取消执行中的 Statement。

因此 Statement Timeout 的设计初衷，是作为一种 “主动控制\ SQL\ 执行时间” 的机制，可以说它建立在 Socket 之上，但和网络超时无关。

4.1.2.2 事务超时（Transaction Timeout）

对应图21中标号为③处的超时。事务超时，通常是 Spring 等应用框架提供的超时机制，用来对多条语句（Statement）的执行总时间进行限制。 

但需要注意的是，事务执行时间通常并不完全等价于语句执行时间之和。考虑上文的示例代码，事实上，updateUserInfo 方法通常不会如此简单，而是会在数据库操作的代码之间穿插着更多复杂的业务代码，执行这些业务代码也会有时间开销，而且在执行过程中还有可能遇到 GC Pause 等影响，如图25。

图25：事务耗时分析

因此，事务执行时间大致上满足以下公式：

在设置事务超时时间时，也要综合考虑除 Statement 自身执行耗时以外的其他因素的影响。

事务超时的意义在于，提供了一种机制来为 “规模风险” 兜底。例如，如果处理 1 条语句需要 0.1 秒，处理几条语句不成问题，但处理 200 条语句则需要 20 秒。这时事务超时就派上用处了。

考虑如下伪代码：

@Transactional(timeout = ?)
public Long createOrder(OrderDTO orderDTO) {
    Long orderId = repository.insert(buildMajorOrder(orderDTO));  // tb_major_order，主单
    
    List<SubOrderEntity> subOrderEntityList = buildSubOrders(orderDTO);
    for (SubOrderEntity subOrderEntity : subOrderEntityList) {
        repository.insert(subOrderEntity);    // tb_sub_order，子单
    }

    repository.insert(buildExtraEntity(orderDTO));  // tb_order_extra
    
    List<OrderEventEntity> orderEventEntityList = buildOrderEvents(orderDTO);
    for (OrderEventEntity orderEventEntity : orderEventEntityList) {
        repository.insert(orderEventEntity);  // tb_order_event，订单事件
    }
    
    return orderId;
}

在实际开发中，有时我们会遇到类似的场景：

• 需要一次读写多张表：例如示例代码就需要写  tb_major_order、 tb_sub_order、 tb_order_extra、 tb_order_event 四张表；
• 语句的执行数量是可变的（不确定的）：例如示例代码中写子单（Line 7） 和 写订单事件（Line 14），具体要执行多少次  INSERT Statement 是可变的；

特别是遇到 “语句执行数量可变” 这种场景时，设置合理的事务超时时间尤为重要。

4.1.2.3 JDBC 驱动超时（JDBC Driver Timeout）

对应图21中标号为④处的超时。JDBC 驱动程序的超时时间实质上是应用于驱动程序底层 Socket 的，是真正的 “网络通信层面” 的超时设定，参考图24。

如果数据库突然停止服务或发生网络错误（比如设备故障），这个超时时间就显得至关重要。由于在当前TCP/IP的设计架构下，Socket 无法检测到网络错误，这就导致应用程序无法感知到与数据库的连接已经断开。如果没有设置 Socket 超时，应用程序可能会在一个失效的连接（dead Connection）上无限期地等待数据库返回。

Socket 超时有以下两个配置选项：

需要注意的是，Socket 超时时间必须大于 Statement 超时时间。如果 Socket 超时时间小于 Statement 超时时间，则 Socket 超时将首先被执行，而 Statement 超时将不会被执行，变得毫无意义。

4.1.3 操作系统底层机制：OS Low-level Timeout

最后简单提一下 OS Level Timeout，对应图21中标号为⑤处的超时。

这是操作系统底层对连接的管理机制，即使没有设置 Socket 的读写超时，当连接失效后，操作系统最终也能够通过 TCP Keepalive 等机制将无效连接清除。但通常我们无需关注如此底层的具体配置。

让我们在本节结尾讨论一下，在发生故障时，工作线程和连接池可能会存在的一些 “工况”，以及超时时间如何起作用，还有它们之间的互相转换和影响，如图26～图29。

1. 进行中的数据库读写（参见图26）：在故障发生前，连接已经被成功借出并正在执行数据库的读写操作，在超时发生前，这些使用中的连接将无法被其他线程复用。此外，由于 Socket 读写超时时间（socketTimeout = 6000ms）比 Statement 超时时间（Mybatis defaultStatementTimeout = 3000ms）长，Statement 超时通常会先被触发。如前文所述，一旦 Statement 超时被触发，JDBC 驱动会尝试获得一个新的连接，并通过这个新的连接向数据库发送KILL QUERY指令来取消正在执行的 Statement。而这将加速整个状态向图27所描述的工况演变；

2. 连接借出成功但探活失败（参见图27）：当连接从 ConcurrentBag 中借出后，HikariCP 会根据 “探活窗口” 对它进行探活 ，具体的实现在com.zaxxer.hikari.pool#isConnectionAlive方法中 ，在这里不做展开。然而，探活过程也需要与数据库交互，很明显，故障发生时探活会失败，连接将被关闭。而对于不在 “探活窗口” 的连接，它将被连接池返回用于执行数据库操作，又会重复图26中的工况；

3. 连接借出失败（参见图28）：经过一段时间图26、图27中描述的两种工况的循环，连接池中的连接最终会被耗尽，连接池中再无连接可供借用，此时工作线程只能等待，直到超时（HikariCP connectionTimeout = 30s）；

4. 补充新连接失败（参见图29）；而另一边，HikariCP 的 addConnectionExecutor 一直在尝试着向连接池中补充连接，但由于数据库不可用，总是建连超时（connectTimeout = 1500ms），无法有效补充连接到连接池中。这使得图28描述的工况将持续很长时间；

图 26‍

图 27

图 28‍‍

图 29

这里没有提到 Transaction 超时，是因为尽管 bme-trade-order-svc 的代码中使用了 @Transactional 注解，但并没有指定指定事务超时时间。

最后，必须要理解的是，不同类型的超时时间应对的工况也不同。例如，对于本文讨论的例子来说，bme-trade-order-svc 的 Statement 超时 和 JDBC驱动超时（Socket 超时，即 socketTimeout + connectTimeout）设定都是合理的。但它们只能应对图26、图27和图29中所描述的工况，却无法应对图28的工况

4.2 改良 “探活” 设计

当前我们的 k8s 默认使用 SpringBoot 的健康检查端口（Endpoint），即actuator/health，作为容器的存活探针 。它基于 HTTP 协议，使得处理探活请求的线程和处理业务请求的线程共享 Tomcat 线程池。当线程池中的线程因为等待可用数据库连接而耗尽时，探活也必然失败，从而导致应用重启。

那么，此时容器应该被重启吗？这就不得不讨论两个概念：“存活（Liveness）” 和 “就绪（Readiness）”，k8s 也对应的提供了两种不同的探针 “存活探针（Liveness Probe）” 和 “就绪探针（Readiness Probe）”。

官方对于这两种探针的使用场景有如下的解释 。

总结来说，所谓 “存活”，在官方定义中的准确表达为 “container is running”，这个表述基本等价于 “process is running”。而 “就绪” 则表示 “ready to respond to requests”， 重点是 “respond”，容器要对请求作出响应。显然本文讨论的问题是由于超时配置错误导致线程资源耗尽，进而导致无法作出响应（respond），需要暂停接收请求（stop serviing traffic），而非重启。但由于使用了 actuator/health作为存活探针，容器总是很快被判定为探活失败，先触发了重启，根本等不到就绪探针发挥作用。

因此，最为直截了当的改进方案就是使用更加轻量的存活探针。例如，使用 “命令（exec）探针” 来替换 “httpGet 探针” 。正如前面所说，“container is running” 基本可以等价于 “process is running”，容器中 Java 进程的 PID 又是固定的，命令探针的配置就十分简单了，以下为示例。

livenessProbe:
  exec:
    command:
    - bash
    - -c
    - "kill -0 [PID] > /dev/null 2>&1"
  initialDelaySeconds: 5
  periodSeconds: 5

通常使用 kill -0 [PID] 这个命令来检查某个进程是否还在运行。其中，[PID] 将替换为真实的进程 id，kill -0 并不会终止进程，而是检查指定的进程 id（pid）是否存在，以及当前用户是否有权限给这个进程发送信号，该命令的执行结果会有如下几种情况。

因为本来就是 k8s 管理的容器我们无需担心权限问题。同时也无需关注输出信息，k8s 只会根据命令返回值是否为0来判断容器是否存活，因此通过重定向> /dev/null 2>&1 忽略了命令的输出。

4.3 提升 Java 应用在启动完成初期的性能表现

首先，一个值得讨论的话题是，在 Java 应用启动的初始阶段，会出现哪些具体的性能问题？已知的问题，大致可以划分为两类，归纳在下方表格中。

可见，除冷资源转热外 ，提升启动初期性能表现的关键就在于如何对 Java 代码进行预热（Warm up）？

很遗憾，我无法提供太多基于亲身实践的经验，但以下是我的一些思路。

1. 使用 CRaC（Coordinated Restore at Checkpoint） ：这是 OpenJDK 下的一个开源项目，其核心思路和平时我们使用 Time Machine 对 Mac 电脑备份，然后在未来的某个时间点基于该备份进行系统恢复十分类似。即在任意时刻创建检查点（Checkpoint）对运行中的 Java 应用实例 dump 出一份镜像（JVM image），当应用需要重启（或在另一个环境、另一个时间新建）时，可直接从该镜像恢复，从而无需重新加载类以及对热点代码进行 JIT 编译优化；

2. 自定义预热代码并加入到启动过程：例如可以针对热点方法执行模拟调用，从而在接入正式流量前，提前将热点链路中依赖的类加载完成，同时尽可能完成一部分 JIT 优化 。但模拟调用的代码必须尽可能的覆盖所有逻辑，这就类似于追求单元测试的覆盖率；

3. 缓慢释放真实流量，使用真实流量预热：类似于第 2 个方案，不同的是通过控制真实流量的路由策略，来达到预热的目的。例如，先释放 1 个请求、10 个请求、50 个请求，...，1% 流量，10% 流量...，控制真实流量的策略，还可以分接口、综合考量冷资源转热等等；

方案 2 对于一部分应用可能有显著的效果。以我们的 “超时中心（bme-timeout-svc）” 为例，该应用主要是提供 “延迟任务调度” 能力，客户端通过registerTask接口将延迟任务注册到超时中心。而registerTask 的核心逻辑就是进行一些标准的参数检查和转换后写库，并根据期望执行时间决定是否立即发送到执行队列（基于 RabbitMQ）。因此很容易通过批量构造 Fake Task 的方式发起模拟调用，并覆盖所有核心的代码分支。但对于其他的一些业务逻辑十分复杂的应用，想要通过模拟调用来实现有效的预热，则会非常困难。因此，对于这些应用而言，方案 3 或许是更好的选择。

‍无论是方案 2 还是方案 3,本质上都是通过 “延迟提供服务” 的方式来交换 “提供服务时的性能”。有时候我们需要在两个方案之间做出权衡。对于本文所讨论的问题，通过延迟提供服务来提高正式流量接入时的性能可能是更好的选择。过快的接入正式流量很容易将未预热、性能较差的应用再次打挂，陷入到频繁的无效重启中。事实上，在本次故障中，bme-trade-order-svc 的多个容器，都重启了不止一次。

至于 CRaC，似乎是一个更加完美的方案：在平稳运行时 dump 一份 Checkpoint 镜像，并在故障发生时基于镜像重启。这样既不需要延迟提供服务来对代码进行预热，又能保证运行的性能。难点在于，如何定义哪些是需要打包到镜像中的 “CRaC Resource”，以及如何处理一些无法 dump 的资源（通常是一些 “有状态” 的对象，例如打开的 Socket）。因此，实际落地该方案的过程中，势必要解决很多未知的问题。

5. 结语

这是本系列的继任篇章，先前的一篇可参考：深度解析：大对象分配引发的GC问题案例研究 。如今，能深入、全面解读复杂问题的技术文章越来越稀缺，一部分文章主打纯粹的知识讲解，而另一部分则倾向于给出 “一针见血” 的问题解决方案。于是我想尝试着打破这种局面，在一个真实的问题背景下，介绍思路、讲解知识、讨论解法，三管齐下。尽管篇幅很长，但我觉得这样的技术文章会更有趣，读完之后的收获也会更多。

最后，希望大家一键三... 哦，错了。愿大家：Take care of your apps, don't let them crash!

脚注

[2] NOC：即 “全局应急响应故障处理中心（Network Operations Center）”。负责第一时间识别线上风险，根据风险及影响程度判断上报的事件类型，对事件进行应急响应处理，并跟进事件的应急处理过程直至事件关闭；

[3] 类似于 “资源id”，我们还会为每一个应用指定一个标识符，这种标识符被称为 “应用id（app_id）”，例如这里的 bme-trade-order-svc；

[4] 工作线程也可能因为处理耗时的计算任务长时间处于繁忙状态，导致无法复用，也可能造成工作线程数量增长，并伴随 CPU 负载升高。但这并不符合 bme-trade-order-svc 的特征，它是一个典型的**“I/O 密集型”**应用；

[5] 主动调用 wait()/wait(n), sleep(n),join(n), park(blocker)/parkNanos(blocker, n) 等方法；

[6] 调用 notify()/notifyAll() 方法；

[7] 参考：https://docs.oracle.com/javase/8/docs/api/java/util/concurrent/SynchronousQueue.html；

[8] 注意这里 “跌底” 只是为了描述方便，不同 Pod 上的应用获取连接失败的情况不可能完全相同，因此每个 Pod 节点的 CPU 利用率都会趋向于0%，但存在一些偏差；

[9] 实际上，后来我意识到，积压的工作线程快速下降，可能也和 Pod 重启、上游服务主动熔断 Incoming 流量下降等因素有关；

[10] 同 脚注 ，但由于活跃线程数是所有 Pod 上的应用活跃线程数的总和，因此它只有一条曲线；

[11] 由于不属于该应用的支持团队，我没有在发布平台上查看和操作该应用的相关权限，只能进行间接的确认；

[12] 沟通出现了偏差，交易同学把我的问题理解成了 “是否进行过人肉重启”，事实上确实没有，但发布平台探活失败后进行了自动重启。在这里绕了很大的弯路；

[13] 这是服务端的埋点，即 bme-trade-order-svc 应用自己上报给 Prometheus 的打点；

[14] 这是客户端应用的埋点，只要发起了调用就会上报，不受 bme-trade-order-svc 是否正确处理请求的影响；

[15] 例如本文讨论的问题，就属于连接池复用问题；

[16] 可能得问题有 Slow SQL、Pool Size 设置的不合理 等等；

[17] 尽管在有些项目中通过 ORM 框架配置，但最终还是通过调用 java.sql.Statement.setQueryTimeout(int timeout)生效，只是这个调用过程由 ORM 框架隐式执行了；

[18] 参考：https://dev.mysql.com/doc/refman/5.7/en/kill.html；

[19] 探活窗口：HikariCP 并不会每次从 ConcurrentBag 中借出连接后都进行探活，而是判断elapsedMillis(poolEntry.lastAccessed, now) > aliveBypassWindowMs 后，才进行探活；

[20] 这里还会涉及到 HikariCP 的另一个超时概念 validationTimeout，这个超时只用来进行连接有效性检查，bme-trade-order-svc 并没有自定义该超时时间，因此使用的是默认值 5000ms；

[21] 事实上，就绪探针使用的也是actuator/health这个端口；

[22] 参考：https://kubernetes.io/docs/concepts/workloads/pods/pod-lifecycle/#types-of-probe；

[23] 关于探针的类型可参考：https://kubernetes.io/docs/concepts/workloads/pods/pod-lifecycle/#probe-check-methods；

[24] 资源转热很多时候是业务设计上应该讨论的主题，并且需要 case by case 的结合业务场景进行分析；

[25] 参考 OpenJDK Wiki：https://wiki.openjdk.org/display/crac。可通过 https://github.com/CRaC/docs 和 https://docs.azul.com/core/crac/crac-introduction 了解更多；

[26] 只有当模拟调用的次数足够多的情况下，才有可能真正触发 JIT 优化；