分析Tomcat 类加载机制触发的 Too many open files 问题

作者：简简单单 2016-11-18

宋顺，携程框架研发部技术专家。 2016年初加入携程，主要负责中间件产品的相关研发工作。毕业于复旦大学软件工程系，曾就职于大众点评，担任后台系统技术负责人。

说起 Too many open files 这个报错，想必大家一定不陌生。在 Linux 系统下，如果程序打开文件句柄数（包括网络连接、本地文件等）超出系统设置，就会抛出这个错误。

不过最近发现 Tomcat 的类加载机制在某些情况下也会触发这个问题。今天就来分享下问题的排查过程、问题产生的原因以及后续优化的一些措施。

在正式分享之前，先简单介绍下背景。

Apollo配置中心是携程框架研发部（笔者供职部门）推出的配置管理平台，提供了配置中心化管理、配置修改后实时推送等功能。

有一个 Java Web 应用接入了 Apollo 配置中心，所以用户在配置中心修改完配置后，配置中心就会实时地把最新的配置推送给该应用。

一、故障现象

某天，开发在生产环境照常通过配置中心修改了应用配置后，发现应用开始大量报错。

查看日志，发现原来是 redis 无法获取到连接了，所以导致接口大量报错。

Caused by: redis.clients.jedis.exceptions.JedisConnectionException: Could not get a resource from the pool
         at redis.clients.util.Pool.getResource(Pool.java:50)
         at redis.clients.jedis.JedisPool.getResource(JedisPool.java:99)
         at credis.java.client.entity.RedisServer.getJedisClient(RedisServer.java:219)
         at credis.java.client.util.ServerHelper.execute(ServerHelper.java:34)
         ... 40 more
Caused by: redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketException: Too many open files
         at redis.clients.jedis.Connection.connect(Connection.java:164)
         at redis.clients.jedis.BinaryClient.connect(BinaryClient.java:82)
         at redis.clients.jedis.BinaryJedis.connect(BinaryJedis.java:1641)
         at redis.clients.jedis.JedisFactory.makeObject(JedisFactory.java:85)
         at org.apache.commons.pool2.impl.GenericObjectPool.create(GenericObjectPool.java:868)
         at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:435)
         at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
         at redis.clients.util.Pool.getResource(Pool.java:48)
         ... 43 more
Caused by: java.net.SocketException: Too many open files
         at java.net.Socket.createImpl(Socket.java:447)
         at java.net.Socket.getImpl(Socket.java:510)
         at java.net.Socket.setReuseAddress(Socket.java:1396)
         at redis.clients.jedis.Connection.connect(Connection.java:148)
         ... 50 more
由于该应用是基础服务，有很多上层应用依赖它，所以导致了一系列连锁反应。情急之下，只能把所有机器上的 Tomcat 都重启了一遍，故障恢复。

二、初步分析

由于故障发生的时间和配置中心修改配置十分吻合，所以后来立马联系我们来一起帮忙排查问题（配置中心是我们维护的）。不过我们得到通知时，故障已经恢复，应用也已经重启，所以没了现场。只好依赖于日志和 CAT（实时应用监控平台）来尝试找到一些线索。

从 CAT 监控上看，该应用集群共 20 台机器，不过在配置客户端获取到最新配置，准备通知应用该次配置的变化详情时，只有 5 台通知成功， 15 台通知失败。

其中 15 台通知失败机器的 JVM 似乎有些问题，报了无法加载类的错误（ NoClassDefFoundError ），错误信息被 catch 住并记录到了 CAT 。

5 台成功的信息如下：

15 台失败的如下：

报错详情如下：

java.lang.NoClassDefFoundError: com/ctrip/framework/apollo/model/ConfigChange
    ...
Caused by: java.lang.ClassNotFoundException: com.ctrip.framework.apollo.model.ConfigChange
    at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1718)
    at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1569)
    ... 16 more
配置客户端在配置更新后，会计算配置的变化并通知到应用。配置的变化会通过 ConfigChange 对象存储。

由于是该应用启动后第一次配置变化，所以 ConfigChange 类是第一次使用到，基于 JVM 的懒加载机制，这时会触发一次类加载过程。

这里就有一个疑问来了，为啥 JVM 会无法加载类？这个类 com.ctrip.framework.apollo.model.ConfigChange 和配置客户端其它的类是打在同一个 jar 包里的，不应该出现 NoClassDefFoundError 的情况。

而且，碰巧的是，后续 redis 报无法连接错误的也正是这 15 台报了 NoClassDefFoundError 的机器。

联想到前面的报错 Too many open files ，会不会也是由于文件句柄数不够，所以导致 JVM 无法从文件系统读取 jar 包，从而导致 NoClassDefFoundError ？

三、故障原因

关于该应用出现的问题，种种迹象表明那个时段应该是进程句柄数不够引起的，例如无法从本地加载文件，无法建立 redis 连接，无法发起网络请求等等。

前一阵我们的一个应用也出现了这个问题，当时发现老机器的 Max Open Files 设置是 65536 ，但是一批新机器上的 Max OpenFiles 都被误设置为 4096 了。

虽然后来运维帮忙统一修复了这个设置问题，但是需要重启才会生效。所以目前生产环境还有相当一部分机器的 Max Open Files 是 4096 。

所以，我们登陆到其中一台出问题的机器上去查看是否存在这个问题。但是出问题的应用已经重启，无法获取到应用当时的情况。不过好在该机器上还部署了另外的应用， pid 为 16112 。通过查看 /proc/16112/limits 文件，发现里面的 Max Open Files 是 4096 。

所以有理由相信应用出问题的时候，它的 Max Open Files 也是 4096 ，一旦当时的句柄数达到 4096 的话，就会导致后续所有的 IO 都出现问题。

所以故障原因算是找到了，是由于 Max Open Files 的设置太小，一旦进程打开的文件句柄数达到 4096 ，后续的所有请求（文件 IO ，网络 IO ）都会失败。

由于该应用依赖了 redis ，所以一旦一段时间内无法连接 redis ，就会导致请求大量超时，造成请求堆积，进入恶性循环。（好在 SOA 框架有熔断和限流机制，所以问题影响只持续了几分钟）

四、疑团重重

故障原因算是找到了，各方似乎对这个答案还算满意。不过还是有一个疑问一直在心头萦绕，为啥故障发生时间这么凑巧，就发生在用户通过配置中心发布配置后？

为啥在配置发布前，系统打开的文件句柄还小于 4096 ，在配置发布后就超过了？

难道配置客户端在配置发布后会大量打开文件句柄？

4.1、代码分析

通过对配置客户端的代码分析，在配置中心推送配置后，客户端做了以下几件事情：

1. 之前断开的 http long polling 会重新连接

2. 会有一个异步 task 去服务器获取最新配置

3. 获取到最新配置后会写入本地文件

4. 写入本地文件成功后，会计算 diff 并通知到应用

从上面的步骤可以看出，第 1 步会重新建立之前断开的连接，所以不算新增，第 2 步和第 3 步会短暂的各新增一个文件句柄（一次网络请求和一次本地 IO ），不过执行完后都会释放掉。

4.2、尝试重现

代码看了几遍也没看出问题，于是尝试重现问题，所以在本地起了一个 demo 应用（命令行程序，非 web ），尝试操作配置发布来重现，同时通过 bash 脚本实时记录打开文件信息，以便后续分析。

for i in {1..1000}
do
lsof -p 91742 > /tmp/20161101/$i.log
sleep 0.01
done
然而本地多次测试后都没有发现文件句柄数增加的情况，虽然洗清了配置客户端的嫌疑，但是问题的答案却似乎依然在风中飘着，该如何解释观测到的种种现象呢？

五、柳暗花明

尝试自己重现问题无果后，只剩下最后一招了 - 通过应用的程序直接重现问题。

为了不影响应用，我把应用的 war 包连同使用的 Tomcat 在测试环境又独立部署了一份。不想竟然很快就发现了导致问题的原因。

原来 Tomcat 对 webapp 有一套自己的 WebappClassLoader ，它在启动的过程中会打开应用依赖的 jar 包来加载 class 信息，但是过一段时间就会把打开的 jar 包全部关闭从而释放资源。

然而如果后面需要加载某个新的 class 的时候，会把之前所有的 jar 包全部重新打开一遍，然后再从中找到对应的 jar 来加载。加载完后过一段时间会再一次全部释放掉。

所以应用依赖的 jar 包越多，同时打开的文件句柄数也会越多。

同时，我们在 Tomcat 的源码中也找到了上述的逻辑。

之前的重现实验最大的问题就是没有完全复现应用出问题时的场景，如果当时就直接测试了 Tomcat ，问题原因就能更早的发现。

5.1、重现环境分析

5.1.1 Tomcat 刚启动完

刚启动完，进程打开的句柄数是 443 。

lsof -p 31188 | wc -l
5.1.2 Tomcat 启动完过了几分钟左右

启动完过了几分钟后，再次查看，发现只剩 192 个了。仔细比较了一下其中的差异，发现 WEB-INF/lib 下的 jar 包句柄全释放了。

lsof -p 31188 | wc -l
lsof -p 31188 | grep "WEB-INF/lib" | wc -l
5.1.3 配置发布后 2 秒左右

然后通过配置中心做了一次配置发布，再次查看，发现一下子又涨到 422 了。其中的差异恰好就是 WEB-INF/lib 下的 jar 包句柄数。从下面的命令可以看到， WEB-INF/lib 下的 jar 包文件句柄数有 228 个之多。

lsof -p 31188 | wc -l
lsof -p 31188 | grep "WEB-INF/lib" | wc -l
5.1.4 配置发布 30 秒后

过了约 30 秒后， WEB-INF/lib 下的 jar 包句柄又全部释放了。

lsof -p 31188 | wc -l
lsof -p 31188 | grep "WEB-INF/lib" | wc -l
5.2 TomcatWebappClassLoader 逻辑

通过查看 Tomcat(7.0.72 版本 ) 的逻辑，也印证了我们的实验结果。

5.2.1 加载类逻辑

Tomcat 在加载 class 时，会首先打开所有的 jar 文件，然后遍历找到对应的 jar 去加载：

5.2.2 关闭 jar 文件逻辑

同时会有一个后台线程定期执行文件的关闭动作来释放资源：

5.3故障场景分析

对于应用出现故障的场景，由于是应用启动后第一次配置变化，所以会使用到一个之前没有引用过的 class: com.ctrip.framework.apollo.model.ConfigChange ，进而会触发 Tomcat 类加载，并最终打开所有依赖的 jar 包，从而导致在很短的时间内进程句柄数升高。（对该应用而言，之前测试下来的数字是 228 ）。

虽然现在无从知晓该应用在出问题前总的文件句柄数，但是从 CAT 监控可以看到光 TCP 连接数 (Established 和 TimeWait 之和 ) 就在 3200+ 了，再加上一些 jdk 加载的类库（这部分 Tomcat 不会释放）和本地文件等，应该离 4096 的上限相差不多了。所以这时候如果 Tomcat 再一下子打开本地 228 个文件，自然就很容易导致 Too manyopen files 的问题了。

六、总结

6.1 问题产生原因

所以，分析到这里，整件事情的脉络就清晰了：

1. 应用的 Max Open Files 限制设置成了 4096

2. 应用自身的文件句柄数较高，已经接近了 4096

3. 用户在配置中心操作了一次配置发布，由于 Tomcat 的类加载机制，会导致瞬间打开本地 200 多个文件，从而迅速达到 4096 上限

4. Jedis 在运行过程中需要和 Redis 重新建立连接，然而由于文件句柄数已经超出上限，所以连接失败

5. 应用对外的服务由于无法连接 Redis ，导致请求超时，客户端请求堆积，陷入恶性循环

6.2 后续优化措施

通过这次问题排查，我们不仅对 Too many open files 这一问题有了更深的认识，对平时不太关心的 Tomcat 类加载机制也有了一定了解，同时也简单总结下未来可以优化的地方：

1、操作系统配置

从这次的例子可以看出，我们不仅要关心应用内部，对系统的一些设置也需要保持一定的关注。如这次的 Max Open Files 配置，对于普通应用，如果流量不大的话，使用 4096 估计也 OK 。但是对于对外提供服务的应用， 4096 就显得太小了。