Tomcat 類加載機制觸發的 Too many open files 問題分析

cywhoyi 8年前發布 | 35K 次閱讀 Tomcat 應用服務器

作者簡介

宋順，攜程框架研發部技術專家。 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 就顯得太小了。

2 、 應用監控、報警

對應用的監控、報警還得繼續跟上。比如是否以后可以增加對應用的連接數指標進行監控，一旦超過一定的閾值，就報警。從而可以避免突然系統出現問題，陷于被動。

3、 中間件客戶端及早初始化

鑒于 Tomcat 的類加載機制，中間件客戶端應該在程序啟動的時候做好初始化動作，同時把所有的類都加載一遍，從而避免后續在運行過程中由于加載類而產生一些詭異的問題。

4、 遇到故障，不要慌張，保留現場

生產環境遇到故障，不要慌張，如果一時無法解決問題的話，可以通過重啟解決。不過應該至少保留一臺有問題的機器，從而為后面排查問題提供有利線索。