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

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

　　Too many open files意思是打开文件太多了那么碰到Tomcat类加载机制触发的Too many open files问题要如何来处理，咱们这边一块儿来看看细节吧。

　　提及Too many open files这个报错，想必你们必定不陌生。在Linux系统下，若是程序打开文件句柄数（包括网络链接、本地文件等）超出系统设置，就会抛出这个错误。

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

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

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

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

　　1、故障现象

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

　　查看日志，发现原来是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都重启了一遍，故障恢复。

　　2、初步分析

　　因为故障发生的时间和配置中心修改配置十分吻合，因此后来立马联系咱们来一块儿帮忙排查问题（配置中心是咱们维护的）。不过咱们获得通知时，故障已经恢复，应用也已经重启，因此没了现场。只好依赖于日志和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？

　　3、故障缘由

　　关于该应用出现的问题，种种迹象代表那个时段应该是进程句柄数不够引发的，例如没法从本地加载文件，没法创建 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 框架有熔断和限流机制，因此问题影响只持续了几分钟）

　　4、疑团重重

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

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

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

　　4.一、代码分析

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

　　1.以前断开的 http long polling 会从新链接

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

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

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

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

　　4.二、尝试重现

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

　　for i in {11000}

　　do

　　lsof -p 91742 > /tmp/20161101/$i.log

　　sleep 0.01

　　done

　　然而本地屡次测试后都没有发现文件句柄数增长的状况，虽然洗清了配置客户端的嫌疑，可是问题的答案却彷佛依然在风中飘着，该如何解释观测到的种种现象呢？

　　5、柳暗花明

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

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

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

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

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

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

　　以前的重现实验最大的问题就是没有彻底复现应用出问题时的场景，若是当时就直接测试了Tomcat，问题缘由就能更早的发现。

　　5.一、重现环境分析

　　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、总结

　　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类加载机制也有了必定了解，同时也简单总结下将来能够优化的地方：

　　一、 操做系统配置

　　从此次的例子能够看出，咱们不只要关心应用内部，对系统的一些设置也须要保持必定的关注。如此次的Max Open Files配置，对于普通应用，若是流量不大的话，使用4096估计也OK。可是对于对外提供服务的应用，4096就显得过小了。

　　2 、 应用监控、报警

　　对应用的监控、报警还得继续跟上。好比是否之后能够增长对应用的链接数指标进行监控，一旦超过必定的阈值，就报警。从而能够避免忽然系统出现问题，陷于被动。

　　三、 中间件客户端及早初始化

　　鉴于Tomcat的类加载机制，中间件客户端应该在程序启动的时候作好初始化动做，同时把全部的类都加载一遍，从而避免后续在运行过程当中因为加载类而产生一些诡异的问题。

　　四、 遇到故障，不要慌张，保留现场

　　生产环境遇到故障，不要慌张，若是一时没法解决问题的话，能够经过重启解决。不过应该至少保留一台有问题的机器，从而为后面排查问题提供有利线索。

　　须要更多编程资讯能够到时间财富网。