Tomcat 类加载机制触发的 Too many open files 问题分析
cywhoyi
8年前
<h2>作者简介</h2> <p>宋顺，携程框架研发部技术专家。 2016年初加入携程，主要负责中间件产品的相关研发工作。 毕业于复旦大学软件工程系， 曾就职于大众点评，担任后台系统技术负责人。</p> <p>说起 Too many open files 这个报错，想必大家一定不陌生。在 Linux 系统下，如果程序打开文件句柄数（包括网络连接、本地文件等）超出系统设置，就会抛出这个错误。</p> <p>不过最近发现 Tomcat 的类加载机制在某些情况下也会触发这个问题。今天就来分享下问题的排查过程、问题产生的原因以及后续优化的一些措施。</p> <p>在正式分享之前，先简单介绍下背景。</p> <p>Apollo配置中心是携程框架研发部（笔者供职部门）推出的配置管理平台，提供了配置中心化管理、配置修改后实时推送等功能。</p> <p>有一个 Java Web 应用接入了 Apollo 配置中心，所以用户在配置中心修改完配置后，配置中心就会实时地把最新的配置推送给该应用。</p> <h2><strong>一、故障现象</strong></h2> <p>某天，开发在生产环境照常通过配置中心修改了应用配置后，发现应用开始大量报错。</p> <p>查看日志，发现原来是 redis 无法获取到连接了，所以导致接口大量报错。</p> <pre> <code class="language-groovy">Caused by: redis.clients.jedis.exceptions.JedisConnectionException: Could not get a resource from the pool</code></pre> <pre> <code class="language-groovy"> at redis.clients.util.Pool.getResource(Pool.java:50)</code></pre> <pre> <code class="language-groovy"> at redis.clients.jedis.JedisPool.getResource(JedisPool.java:99)</code></pre> <pre> <code class="language-groovy"> at credis.java.client.entity.RedisServer.getJedisClient(RedisServer.java:219)</code></pre> <pre> <code class="language-groovy"> at credis.java.client.util.ServerHelper.execute(ServerHelper.java:34)</code></pre> <pre> <code class="language-groovy"> ... 40 more</code></pre> <pre> <code class="language-groovy">Caused by: redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketException: Too many open files</code></pre> <pre> <code class="language-groovy"> at redis.clients.jedis.Connection.connect(Connection.java:164)</code></pre> <pre> <code class="language-groovy"> at redis.clients.jedis.BinaryClient.connect(BinaryClient.java:82)</code></pre> <pre> <code class="language-groovy"> at redis.clients.jedis.BinaryJedis.connect(BinaryJedis.java:1641)</code></pre> <pre> <code class="language-groovy"> at redis.clients.jedis.JedisFactory.makeObject(JedisFactory.java:85)</code></pre> <pre> <code class="language-groovy"> at org.apache.commons.pool2.impl.GenericObjectPool.create(GenericObjectPool.java:868)</code></pre> <pre> <code class="language-groovy"> at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:435)</code></pre> <pre> <code class="language-groovy"> at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)</code></pre> <pre> <code class="language-groovy"> at redis.clients.util.Pool.getResource(Pool.java:48)</code></pre> <pre> <code class="language-groovy"> ... 43 more</code></pre> <pre> <code class="language-groovy">Caused by: java.net.SocketException: Too many open files</code></pre> <pre> <code class="language-groovy"> at java.net.Socket.createImpl(Socket.java:447)</code></pre> <pre> <code class="language-groovy"> at java.net.Socket.getImpl(Socket.java:510)</code></pre> <pre> <code class="language-groovy"> at java.net.Socket.setReuseAddress(Socket.java:1396)</code></pre> <pre> <code class="language-groovy"> at redis.clients.jedis.Connection.connect(Connection.java:148)</code></pre> <pre> <code class="language-groovy"> ... 50 more</code></pre> <p>由于该应用是基础服务，有很多上层应用依赖它，所以导致了一系列连锁反应。情急之下，只能把所有机器上的 Tomcat 都重启了一遍，故障恢复。</p> <h2>二、初步分析</h2> <p>由于故障发生的时间和配置中心修改配置十分吻合，所以后来立马联系我们来一起帮忙排查问题（配置中心是我们维护的）。不过我们得到通知时，故障已经恢复，应用也已经重启，所以没了现场。只好依赖于日志和 CAT（实时应用监控平台）来尝试找到一些线索。</p> <p>从 CAT 监控上看，该应用集群共 20 台机器，不过在配置客户端获取到最新配置，准备通知应用该次配置的变化详情时，只有 5 台通知成功， 15 台通知失败。</p> <p>其中 15 台通知失败机器的 JVM 似乎有些问题，报了无法加载类的错误（ NoClassDefFoundError ），错误信息被 catch 住并记录到了 CAT 。</p> <p>5 <strong> 台成功的信息如下： </strong></p> <p><img src="https://simg.open-open.com/show/12fa1a6d0b235e10988128410913c22d.jpg"></p> <p>15 <strong> 台失败的如下： </strong></p> <p><img src="https://simg.open-open.com/show/67258b9f7a007742702b482acf2a0e8f.jpg"></p> <p>报错详情如下：</p> <pre> <code class="language-groovy">java.lang.NoClassDefFoundError: com/ctrip/framework/apollo/model/ConfigChange</code></pre> <pre> <code class="language-groovy"> ...</code></pre> <pre> <code class="language-groovy">Caused by: java.lang.ClassNotFoundException: com.ctrip.framework.apollo.model.ConfigChange</code></pre> <pre> <code class="language-groovy"> at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1718)</code></pre> <pre> <code class="language-groovy"> at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1569)</code></pre> <pre> <code class="language-groovy"> ... 16 more</code></pre> <p>配置客户端在配置更新后，会计算配置的变化并通知到应用。配置的变化会通过 ConfigChange 对象存储。</p> <p>由于是该应用启动后第一次配置变化，所以 ConfigChange 类是第一次使用到，基于 JVM 的懒加载机制，这时会触发一次类加载过程。</p> <p>这里就有一个疑问来了，为啥 JVM 会无法加载类？这个类 com.ctrip.framework.apollo.model.ConfigChange 和配置客户端其它的类是打在同一个 jar 包里的，不应该出现 NoClassDefFoundError 的情况。</p> <p>而且，碰巧的是，后续 redis 报无法连接错误的也正是这 15 台报了 NoClassDefFoundError 的机器。</p> <p>联想到前面的报错 Too many open files ， 会不会也是由于文件句柄数不够，所以导致 JVM 无法从文件系统读取 jar 包，从而导致 NoClassDefFoundError ？</p> <h2>三、故障原因</h2> <p>关于该应用出现的问题，种种迹象表明那个时段应该是进程句柄数不够引起的，例如无法从本地加载文件，无法建立 redis 连接，无法发起网络请求等等。</p> <p>前一阵我们的一个应用也出现了这个问题，当时发现老机器的 Max Open Files 设置是 65536 ，但是一批新机器上的 Max OpenFiles 都被误设置为 4096 了。</p> <p>虽然后来运维帮忙统一修复了这个设置问题，但是需要重启才会生效。所以目前生产环境还有相当一部分机器的 Max Open Files 是 4096 。</p> <p>所以，我们登陆到其中一台出问题的机器上去查看是否存在这个问题。但是出问题的应用已经重启，无法获取到应用当时的情况。不过好在该机器上还部署了另外的应用， pid 为 16112 。通过查看 /proc/16112/limits 文件，发现里面的 Max Open Files 是 4096 。</p> <p><img src="https://simg.open-open.com/show/e25427194bd047bc4ebef00baa1602f5.jpg"></p> <p>所以有理由相信应用出问题的时候，它的 Max Open Files 也是 4096 ，一旦当时的句柄数达到 4096 的话，就会导致后续所有的 IO 都出现问题。</p> <p>所以故障原因算是找到了，是由于 Max Open Files 的设置太小，一旦进程打开的文件句柄数达到 4096 ，后续的所有请求（文件 IO ，网络 IO ）都会失败。</p> <p>由于该应用依赖了 redis ，所以一旦一段时间内无法连接 redis ，就会导致请求大量超时，造成请求堆积，进入恶性循环。（好在 SOA 框架有熔断和限流机制，所以问题影响只持续了几分钟）</p> <h2>四、疑团重重</h2> <p>故障原因算是找到了，各方似乎对这个答案还算满意。不过还是有一个疑问一直在心头萦绕，为啥故障发生时间这么凑巧，就发生在用户通过配置中心发布配置后？</p> <p>为啥在配置发布前，系统打开的文件句柄还小于 4096 ，在配置发布后就超过了？</p> <p>难道配置客户端在配置发布后会大量打开文件句柄？</p> <h3>4.1、代码分析</h3> <p>通过对配置客户端的代码分析，在配置中心推送配置后，客户端做了以下几件事情：</p> <p>1. 之前断开的 http long polling 会重新连接</p> <p>2. 会有一个异步 task 去服务器获取最新配置</p> <p>3. 获取到最新配置后会写入本地文件</p> <p>4. 写入本地文件成功后，会计算 diff 并通知到应用</p> <p>从上面的步骤可以看出，第 1 步会重新建立之前断开的连接，所以不算新增，第 2 步和第 3 步会短暂的各新增一个文件句柄（一次网络请求和一次本地 IO ），不过执行完后都会释放掉。</p> <h3>4.2、尝试重现</h3> <p>代码看了几遍也没看出问题，于是尝试重现问题，所以在本地起了一个 demo 应用（命令行程序，非 web ），尝试操作配置发布来重现，同时通过 bash 脚本实时记录打开文件信息，以便后续分析。</p> <pre> <code class="language-groovy">for i in {1..1000}</code></pre> <pre> <code class="language-groovy">do</code></pre> <pre> <code class="language-groovy"> lsof -p 91742 > /tmp/20161101/$i.log</code></pre> <pre> <code class="language-groovy"> sleep 0.01</code></pre> <pre> <code class="language-groovy">done</code></pre> <p>然而本地多次测试后都没有发现文件句柄数增加的情况，虽然洗清了配置客户端的嫌疑，但是问题的答案却似乎依然在风中飘着，该如何解释观测到的种种现象呢？</p> <h2>五、柳暗花明</h2> <p>尝试自己重现问题无果后，只剩下最后一招了 - 通过应用的程序直接重现问题。</p> <p>为了不影响应用，我把应用的 war 包连同使用的 Tomcat 在测试环境又独立部署了一份。不想竟然很快就发现了导致问题的原因。</p> <p>原来 Tomcat 对 webapp 有一套自己的 WebappClassLoader ，它在启动的过程中会打开应用依赖的 jar 包来加载 class 信息，但是过一段时间就会把打开的 jar 包全部关闭从而释放资源。</p> <p>然而如果后面需要加载某个新的 class 的时候，会把之前所有的 jar 包全部重新打开一遍，然后再从中找到对应的 jar 来加载。加载完后过一段时间会再一次全部释放掉。</p> <p>所以应用依赖的 <strong> jar </strong> <strong> 包越多，同时打开的文件句柄数也会越多。 </strong></p> <p>同时，我们在 Tomcat 的源码中也找到了上述的逻辑。</p> <p>之前的重现实验最大的问题就是没有完全复现应用出问题时的场景，如果当时就直接测试了 Tomcat ，问题原因就能更早的发现。</p> <h3>5.1、重现环境分析</h3> <p>5.1.1 Tomcat 刚启动完</p> <p>刚启动完，进程打开的句柄数是 443 。</p> <pre> <code class="language-groovy">lsof -p 31188 | wc -l</code></pre> <p>5.1.2 Tomcat 启动完过了几分钟左右</p> <p>启动完过了几分钟后，再次查看，发现只剩 192 个了。仔细比较了一下其中的差异，发现 WEB-INF/lib 下的 jar 包句柄全释放了。</p> <pre> <code class="language-groovy">lsof -p 31188 | wc -l</code></pre> <pre> <code class="language-groovy">lsof -p 31188 | grep "WEB-INF/lib" | wc -l</code></pre> <p>5.1.3 配置发布后 2 秒左右</p> <p>然后通过配置中心做了一次配置发布，再次查看，发现一下子又涨到 422 了。其中的差异恰好就是 WEB-INF/lib 下的 jar 包句柄数。从下面的命令可以看到， WEB-INF/lib 下的 jar 包文件句柄数有 228 个之多。</p> <pre> <code class="language-groovy">lsof -p 31188 | wc -l</code></pre> <pre> <code class="language-groovy">lsof -p 31188 | grep "WEB-INF/lib" | wc -l</code></pre> <p>5.1.4 配置发布 30 秒后</p> <p>过了约 30 秒后， WEB-INF/lib 下的 jar 包句柄又全部释放了。</p> <pre> <code class="language-groovy">lsof -p 31188 | wc -l</code></pre> <pre> <code class="language-groovy">lsof -p 31188 | grep "WEB-INF/lib" | wc -l</code></pre> <h3>5.2 TomcatWebappClassLoader 逻辑</h3> <p>通过查看 Tomcat(7.0.72 版本 ) 的逻辑，也印证了我们的实验结果。</p> <p>5.2.1 加载类逻辑</p> <p>Tomcat 在加载 class 时，会首先打开所有的 jar 文件，然后遍历找到对应的 jar 去加载：</p> <p><img src="https://simg.open-open.com/show/1962fe0632a1eb6a4460aff7dd3b0ab1.jpg"><br> <img src="https://simg.open-open.com/show/6dbdf080a493ac998e8c7229058ef2d5.jpg"></p> <p>5.2.2 关闭 jar 文件逻辑</p> <p>同时会有一个后台线程定期执行文件的关闭动作来释放资源：</p> <p><img src="https://simg.open-open.com/show/6acd5c9ec98f36089c4be2f3832f1e76.jpg"> <img src="https://simg.open-open.com/show/3e1788ad731d87f772f194f48cc95554.jpg"></p> <h3>5.3故障场景分析</h3> <p>对于应用出现故障的场景，由于是应用启动后第一次配置变化，所以会使用到一个之前没有引用过的 class: com.ctrip.framework.apollo.model.ConfigChange ， 进而会触发 Tomcat 类加载，并最终打开所有依赖的 jar 包 ， 从而导致在很短的时间内进程句柄数升高。 （ 对该应用而言，之前测试下来的数字是 228 ）。</p> <p>虽然现在无从知晓该应用在出问题前总的文件句柄数，但是从 CAT 监控可以看到光 TCP 连接数 (Established 和 TimeWait 之和 ) 就在 3200+ 了，再加上一些 jdk 加载的类库（这部分 Tomcat 不会释放）和本地文件等，应该离 4096 的上限相差不多了。所以这时候如果 Tomcat 再一下子打开本地 228 个文件，自然就很容易导致 Too manyopen files 的问题了。</p> <p><img src="https://simg.open-open.com/show/a92590874110896d5d182c02ee108968.jpg"></p> <h2>六、总结</h2> <h3>6.1 问题产生原因</h3> <p>所以，分析到这里，整件事情的脉络就清晰了：</p> <p>1. 应用的 Max Open Files 限制设置成了 4096</p> <p>2. 应用自身的文件句柄数较高，已经接近了 4096</p> <p>3. 用户在配置中心操作了一次配置发布，由于 Tomcat 的类加载机制，会导致瞬间打开本地 200 多个文件，从而迅速达到 4096 上限</p> <p>4. Jedis 在运行过程中需要和 Redis 重新建立连接，然而由于文件句柄数已经超出上限，所以连接失败</p> <p>5. 应用对外的服务由于无法连接 Redis ，导致请求超时，客户端请求堆积，陷入恶性循环</p> <h3>6.2 后续优化措施</h3> <p>通过这次问题排查，我们不仅对 Too many open files 这一问题有了更深的认识，对平时不太关心的 Tomcat 类加载机制也有了一定了解，同时也简单总结下未来可以优化的地方：</p> <p>1、 <strong> 操作系统配置 </strong></p> <p>从这次的例子可以看出，我们不仅要关心应用内部，对系统的一些设置也需要保持一定的关注。如这次的 Max Open Files 配置，对于普通应用，如果流量不大的话，使用 4096 估计也 OK 。但是对于对外提供服务的应用， 4096 就显得太小了。</p> <p>2 、 <strong> 应用监控、报警 </strong></p> <p>对应用的监控、报警还得继续跟上。比如是否以后可以增加对应用的连接数指标进行监控，一旦超过一定的阈值，就报警。从而可以避免突然系统出现问题，陷于被动。</p> <p>3、 <strong> 中间件客户端及早初始化 </strong></p> <p>鉴于 Tomcat 的类加载机制，中间件客户端应该在程序启动的时候做好初始化动作，同时把所有的类都加载一遍，从而避免后续在运行过程中由于加载类而产生一些诡异的问题。</p> <p>4、 <strong> 遇到故障，不要慌张，保留现场 </strong></p> <p>生产环境遇到故障，不要慌张，如果一时无法解决问题的话，可以通过重启解决。不过应该至少保留一台有问题的机器，从而为后面排查问题提供有利线索。</p> <p>延伸阅读：</p> <ul> <li> <p><a href="http://mp.weixin.qq.com/s?__biz=MjM5MDI3MjA5MQ==&mid=2697265573&idx=2&sn=3a560b14da608cea5bdff193e9d7cbdf&chksm=8376fe91b4017787c46fc854dd9a96e6ece6b2e14c00d1aded4b741cbeac0ca29884fe1cabc7&scene=21#wechat_redirect" rel="nofollow,noindex">携程是如何做React Native优化的</a></p> </li> <li> <p><a href="http://mp.weixin.qq.com/s?__biz=MjM5MDI3MjA5MQ==&mid=2697265573&idx=3&sn=b70e0c43dfb1932b6bde045ace8560ba&chksm=8376fe91b40177877629977475a964ec99c0908c2fd4b752596f7aa68ce7a757b1b7b2f2bed9&scene=21#wechat_redirect" rel="nofollow,noindex">那些携程火车票业务在RN时间中踩过的坑</a></p> </li> <li> <p><a href="http://mp.weixin.qq.com/s?__biz=MjM5MDI3MjA5MQ==&mid=2697265512&idx=1&sn=792a50de432093914c80e0e0d15d1cdf&chksm=8376fe5cb401774a6e84fa7da2671ac940861fced42e665a48023444f95888c49f6eebe3fe49&scene=21#wechat_redirect" rel="nofollow,noindex">常见的用户密码加密方式以及破解方法</a></p> </li> <li> <p><a href="http://mp.weixin.qq.com/s?__biz=MjM5MDI3MjA5MQ==&mid=2697265512&idx=2&sn=afc88b133d02163603c28be1efd6d40a&chksm=8376fe5cb401774a84b774a901786fa70403be6190480dd6dcae9ad41f75d2faedd913c5ca17&scene=21#wechat_redirect" rel="nofollow,noindex">携程移动端架构演进与优化之路</a></p> </li> <li> <p><a href="http://mp.weixin.qq.com/s?__biz=MjM5MDI3MjA5MQ==&mid=2697265470&idx=1&sn=b338666305963526ff5168398ebfa95f&chksm=8376fe0ab401771cbd1a7870f5adcf31c4f0d5a4d320272c73270c61c3e16c9056aad31ba764&scene=21#wechat_redirect" rel="nofollow,noindex">携程风险防御体系的变革之路</a></p> </li> </ul> <p> </p> <p>来自：https://mp.weixin.qq.com/s?__biz=MjM5MDI3MjA5MQ==&mid=2697265591&idx=1&sn=48cd5869b3b1bbcfa9e22b77016e355d&chksm=8376fe83b401779588f1837371c0d85307a1e998f357292fa3a8ce89be402060c2fdbe53bc66&mpshare=1&scene=1&srcid=1116dkVjjBr8oiYOV50NzmaN&pass_ticket=yspAN6RM6Q8Nr8dYVuHCMJUh2qfzU0bLTwiqNv0QgVY=</p> <p> </p>