一、背景

一个平静的下午，报警、Moji 群里接连传来并行 MOA 默认集群 /service/parallel 出现异常的提示信息，服务维护人员查看日志发现是发生了并行任务线程池被打满的问题。线程池满会导致新请求直接被拒绝，大量业务请求报错，极速版附近的人、基因、聊天室等多个业务进入降级状态... 而导致这一系列严重影响的问题原因，是大家最熟悉不过的 new JedisPool() 这一行代码。

Jedis 是 Java 访问 Redis 最常用的客户端组件

二、问题分析

从慢请求日志我们发现，单一请求阻塞线程的时间最长可达到 10 分钟以上。简单的 new JedisPool()为何会长时间阻塞线程？通过搭建测试服务、复现问题、抓取 jstack 分析后，我们发现 JedisPool 中向 JMX 注册对象的逻辑，在特定的场景会出现严重的锁竞争与阻塞问题。

包依赖说明

并行 MOA 工程 ->MOA（MOARedisClient） ->MCF（RedisDao） ->Jedis（JedisPool） ->commons-pool（BaseGenericObjectPool） ->JDK（JMX）

问题出现在并行 MOA 通过 MOARedisClient 访问下游服务新启动实例的过程中，此时需要通过 new JedisPool()创建与下游实例的连接池。

new JedisPool()中与 JMX 的交互

JedisPool 使用 commons-pool 来管理连接对象，commons-pool 创建对象池时会向 JMX 注册，以便于在运行时通过 JMX 接口获取对象池相关的监控数据。但向 JMX 注册的过程，包含以下逻辑

1. commons-pool 向 JMX 注册 BaseGenericObjectPool 对象，JMX 要求每个对象有不同的名字
2. commons-pool 生成不同名字的方式是：基于一个默认相同的名字，末尾添加一个自增 ID
3. 每次 new JedisPool()时 ID 从 1 开始尝试，发现名字重复后 ID 自增+1 后再次重试，直至发现一个未被占用的 ID、重试成功为止
4. 尝试某个名字是否被占用，会共用一把全局的锁，同一时刻只能有一个 JedisPool 对象对某一个名字 ID 验证是否重复

commons-pool 中遍历 ID 尝试注册 objName 的代码

JMX 中注册对象的代码，会获取一把全局的锁

问题产生的条件

1. 当前进程中已创建了大量的 JedisPool，有大量的自增 ID 已被占用（如 1~1w 已被占用）
2. 此时创建下一个 JedisPool，需要遍历 1w 次已有 ID 才能以 1w + 1 这个 ID 注册对象，这 1w 次尝试每次都需要加锁
3. 当有多个线程同时创建 JedisPool 时，每个线程都需要遍历所有 ID，并且遍历过程中每次加锁都会导致其他线程无法重试、只能等待
4. 假设 1 个线程遍历 1w 次需要 1 秒，100 个线程各遍历 1w 次、共计 100w 次尝试需要串行执行，并且 100 个线程是交替获得锁、交替重试，最终导致 100 个线程都需要 100 秒才能重试完

三、问题排查过程

问题产生

16:14 /service/phpmoa/v1_microvideo_index 执行常规的发布操作 16:16 /service/parallel 并行任务线程池被打满、开始通过扩容和隔离实例解决 16:26 服务逐步恢复

并行 MOA 使用了 MSC 线程池组件，从活跃线程数监控可以看到每个并行 MOA 实例线程池被打满到恢复的时间

被阻塞的线程是能够自动恢复的，并且恢复的时间并不统一。从日志中我们首先找到了阻塞线程的慢请求

execution finished after parallel timeout: /service/phpmoa/v1_microvideo_index,isRiskFeeds, startTime = 2020-11-30 16:26:02,428, server = 10.116.88.15:20000, routeTime = 2020-11-30 16:26:02,428, blacklistTime = 2020-11-30 16:26:02,428, executeTime = 2020-11-30 16:37:21,657, timeCost = 679229

复制代码

刚好是调用 /service/phpmoa/v1_microvideo_index 服务，但记录的执行时间最长可达到 10 分钟以上。慢日志中包含各个阶段的耗时，因此耗时的逻辑可以锁定在 blacklistTime 和 executeTime 之间，这里只对应一行通过 MOA 框架 MOARedisClient 调用下游服务的代码

初步分析

在 MOARedisClient.exeuteByServer()内部，仅有 2 个逻辑可能出现较长的耗时，一个是 RedisFactory.getRedisDao()，这里会与下游实例创建连接。另一个是 doInvoke()真正发起请求，由于后者的耗时会提交到 Hubble，并且未发现达到分钟级的耗时，因此问题的原因更可能出现在创建 RedisDao 的逻辑中。

排查瓶颈

由于 RedisFactory.getRedisDao()各个阶段的耗时缺少监控，并且服务出现异常期间没有及时通过 jstack 打印堆栈信息，问题排查到这一步仅靠分析很难继续进行。

问题复现

我们查找了 /service/phpmoa/v1_microvideo_index 的发布记录，发现这个服务每次发布的时候，/service/parallel 都会有短暂的 errorCount 波动，因此推断该问题是能够通过重启 /service/phpmoa/v1_microvideo_index 来复现的。

搭建测试服务

重启线上服务有可能再次导致服务异常、影响线上业务，所以我们先尝试在线上环境复制上下游项目、发布成不同的 ServiceUri，并增加一个测试接口，通过压测平台制造流量，搭建起和线上调用链路基本一致的测试环境。

增加监控

除了在 MOA 和 MCF 的代码中增加各阶段耗时的日志外，对于并行 MOA 出现线程池满拒绝请求、以及出现 10 秒以上慢请求的场景，均增加了自动打印 jstack 的机制。

获得排查依据

在适当调整模拟流量的压力后，重启测试的 /service/phpmoa/v1_microvideo_index 服务后，问题提复现了。这一次我们拿到了详细的耗时信息，以及线程池满后的 jstack 堆栈信息，才进一步分析到问题的根本原因。

四、问题验证

测试服务验证

1. 问题复现后的 jstack 堆栈，611 个线程停留在等待锁的步骤
2. 将 JMX 关闭后，对比其他未关闭的实例没有再复现该问题

与问题现象匹配

并行 MOA 的特征

1. 调用的下游服务极多、下游实例数极多，需要创建大量的 JedisPool
2. 下游重启过程中并行 MOA 需要创建大量新的 JedisPool，并且并行创建的线程数很多（最多 800 个）

问题发生过程

1. 下游服务发布后出问题（microvideo_index）、下游实例数多的服务发布问题严重（230 个）、发布速度快的服务问题严重（2 分钟）、多个服务同时发布的时候问题严重（microvideo_index 和 user_location 在同一时间段做发布）
2. 各个并行 MOA 实例能够自动恢复，但恢复的时间点差异较大（具体耗时取决于已有 ID 数量、并行创建 JedisPool 的线程数据量，各实例的情况可能不一致）
3. 异常期间并行 MOA 服务的 CPU 使用率大幅升高（在频繁获取锁）
4. 相同时刻其他并行 MOA 的集群未出问题（因为请求量低、并行创建 JedisPool 的线程少）

五、解决方案

问题影响范围

业务上使用 JedisPool 的场景，多通过 MCF 的 RedisDao 封装。RedisDao 主要用于两个场景

MomoStore

通过 MomoStore 访问 Redis 数据源、访问 OneStore 底层使用 RedisDao。由于 MomoStore 对于新实例的连接建立是在接收事件通知后单线程执行的，受并发创建 JedisPool 的影响较少。

MOARedisClient

由于与下游新实例创建连接的动作是在业务请求中完成的，所以使用 MOARedisClient 的场景受并发创建 JedisPool 影响的可能性较大。当服务与并行 MOA 具备类似的特征：下游服务多、实例多，并行执行的请求多，在下游服务发布时也容易出现相同的问题。使用 MOARedisClient 在某些场景下的执行时间超出设定的 timeout 时间，也与该问题有关。

修复方案

最简单有效的解决方案是关闭 JedisPool 的 JMX 配置，可以在 MCF 的代码中统一修改、通过升级 MCF 版本修复。对于已接入 Mesh 的服务，由于 MOARedisClient 实际与下游通信的地址是 127.0.0.1，所需建立的连接池很少，所以不会受该问题影响。后续我们会扫描所有使用 MOARedisClient、但尚未接入 Mesh 的服务，推动升级 MCF 版本消除这一隐患。

其他改进项

在 MSC 线程池中加入线程池满自动打印 jstack 的机制。