分析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的類加載機制，中間件客戶端應該在程序啓動的時候作好初始化動做，同時把全部的類都加載一遍，從而避免後續在運行過程當中因爲加載類而產生一些詭異的問題。

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

　　生產環境遇到故障，不要慌張，若是一時沒法解決問題的話，能夠經過重啓解決。不過應該至少保留一臺有問題的機器，從而爲後面排查問題提供有利線索。

　　須要更多編程資訊能夠到時間財富網。