作者簡介

宋順，攜程框架研發部技術專家。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的原始碼中也找到了上述WebappClassLoader的邏輯。

之前的重現實驗最大的問題就是沒有完全復現應用出問題時的場景，如果當時就直接測試了Tomcat，問題原因就能更早的發現。

5.1、重現環境分析

5.1.1 Tomcat剛啟動完

剛啟動完，程序開啟的控制代碼數是443。

lsof -p 31188 | wc -l

443

5.1.2 Tomcat啟動完過了幾分鐘左右

啟動完過了幾分鐘後，再次檢視，發現只剩192個了。仔細比較了一下其中的差異，發現WEB-INF/lib下的jar包控制代碼全釋放了。

lsof -p 31188 | wc -l

192

lsof -p 31188 | grep "WEB-INF/lib" | wc -l

0

5.1.3 配置釋出後2秒左右

然後通過配置中心做了一次配置釋出，再次檢視，發現一下子又漲到422了。其中的差異恰好就是WEB-INF/lib下的jar包控制代碼數。從下面的命令可以看到，WEB-INF/lib下的jar包檔案控制代碼數有228個之多。

lsof -p 31188 | wc -l

422

lsof -p 31188 | grep "WEB-INF/lib" | wc -l

228

5.1.4 配置釋出30秒後

過了約30秒後，WEB-INF/lib下的jar包控制代碼又全部釋放了。

lsof -p 31188 | wc -l

194

lsof -p 31188 | grep "WEB-INF/lib" | wc -l

0

5.2 TomcatWebappClassLoader邏輯

通過檢視Tomcat(7.0.72版本)的WebappClassLoader邏輯，也印證了我們的實驗結果。

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、遇到故障，不要慌張，保留現場

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