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

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 实验程序来验证这一点。