記錄一次句柄泄漏排查經歷(too many open files)

      今天元宵節,新年即將結束,年前由于每天在觀察服務器日志和維護,沒有出現過什么大問題。但是在過年放假期間,出現了日志過大的情況。平時每天產生1M的日志是正常的,但是年中有一天我查看服務器的時候,發現已經有42G日志了,線上功能也有些不正常,暗自心中一緊,迅速開啟了這次排查之旅。

      一、 備份服務器異常日志,恢復線上功能

      使用linux系統cp命令,將異常日志復制備份。

      cp [OPTION]... SOURCE... DIRECTORY
      

      重啟服務器進程,功能恢復正常。

      二、 查看日志,初步定位

      功能恢復以后,開始尋找異常原因。由于異常日志過大,下載很慢,于是再使用split命令分割日志文件,每塊大小1G。但是1個G還是很大,我再次對第一個小塊再次分割,每塊100M。

      split -b 100M mylog.txt
      

      最后再下載第一個100M文件進行查看。

      最后下載下來的日志顯示如下:

      java.net.SocketException: Too many open files
      at sun.nio.ch.Net.socket0(Native Method)
      at sun.nio.ch.Net.socket(Net.java:411)
      at sun.nio.ch.DatagramChannelImpl.<init>(DatagramChannelImpl.java:142)
      at sun.nio.ch.SelectorProviderImpl.openDatagramChannel(SelectorProviderImpl.java:46)
      at java.nio.channels.DatagramChannel.open(DatagramChannel.java:182)
      at lbms.plugins.mldht.kad.utils.AddressUtils.getDefaultRoute(AddressUtils.java:254)
      at lbms.plugins.mldht.kad.RPCServerManager.startNewServers(RPCServerManager.java:147)
      at lbms.plugins.mldht.kad.RPCServerManager.refresh(RPCServerManager.java:51)
      at lbms.plugins.mldht.kad.DHT.update(DHT.java:929)
      at lbms.plugins.mldht.kad.DHT.lambda$started$11(DHT.java:767)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
      at java.lang.Thread.run(Thread.java:748)
      
      java.net.SocketException: Too many open files
      at sun.nio.ch.Net.socket0(Native Method)
      at sun.nio.ch.Net.socket(Net.java:411)
      at sun.nio.ch.DatagramChannelImpl.<init>(DatagramChannelImpl.java:142)
      at sun.nio.ch.SelectorProviderImpl.openDatagramChannel(SelectorProviderImpl.java:46)
      at java.nio.channels.DatagramChannel.open(DatagramChannel.java:182)
      at lbms.plugins.mldht.kad.utils.AddressUtils.getDefaultRoute(AddressUtils.java:254)
      at lbms.plugins.mldht.kad.RPCServerManager.startNewServers(RPCServerManager.java:147)
      at lbms.plugins.mldht.kad.RPCServerManager.refresh(RPCServerManager.java:51)
      at lbms.plugins.mldht.kad.DHT.update(DHT.java:929)
      at lbms.plugins.mldht.kad.DHT.lambda$started$11(DHT.java:767)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
      at java.lang.Thread.run(Thread.java:748)
      ...
      

      如上所示,日志中不斷在循環寫入java.net.SocketException: Too many open files異常,并且一直未停止。于是到各大IT網站上搜索了相關問題,并嘗試了一些方案解決。

      大概的描述就是說:

      linux系統文件句柄不夠,已經被使用完了。

      按照網上的方案,使用ulimit -a查詢和永久修改了文件句柄配置文件,再次查詢數量設置為了65535.

      我想這下應該可以了。

      三、 猜想泄漏,印證猜想

      然而,事情并非如此。服務器繼續運行一周以后,再次出現了這個異常。

      于是重新思考了這個異常,可能是句柄泄漏造成的,并根據這個網址提供的思路進行排查。

      偵測程序句柄泄露的統計方法

      根據提示,在linux系統上編寫了監控進程句柄的后臺程序進行監控:

      其中下面的命令是查詢該進程當前占用的句柄數量。

       ls -l /proc/進程ID/fd |wc -l 
      

      設置每600秒做一次句柄占用統計,等待一天,并用excel表格做出了折現走勢圖:

      通過該折線圖,進一步印證了是句柄泄漏的原因。

      四、 定位泄漏位置,解決問題

      句柄泄漏肯定是程序引起的。句柄通常是指文件、socket或者其他,句柄泄漏肯定是java中的文件操作流或者socket未關閉導致的。于是再次反復檢查每一個設置文件操作的位置,發現并沒有未關閉的情況。

      將戰地轉移到本地IDE,使用windows任務進程管理器調試,反復測試每一個業務,并觀察句柄和線程使用情況。

      在反復測試每項業務的過程中,各項業務的線程和句柄占用在業務結束后都會釋放,只有一項業務,即使結束了,線程和句柄占用數也一直未釋放。因此,再次深入測試這項業務,并使用JVM棧命令查詢各個線程的使用情況:

      jstack -l 進程ID
      

      在這項業務結束后,我發現大量的線程依然處于RUNNABLE狀態,并且在執行接收socket數據包,如下:

      根據這些線程的提示,重新回到代碼上,最終發現是在項目的該業務邏輯分支過程中,runtime對象執行超時情況下,并未做關閉處理,導致了許多用戶在使用這項業務過程中,即使出現了超時,前端返回了提示,后端也并沒有進行關閉回收,一直處于運行狀態。

      五、 驗證泄漏解決

      在打好這個補丁后,重新發布線上觀察,并畫出折線圖:

      句柄占用穩定在600以內,本次句柄泄漏排查告一段落。

      六、 總結

      通過本次經歷,重新敬仰代碼。遇到問題也不可怕,深入研究,一點一點啃也能解決。

      但愿我的經歷能給遇到問題的人提供一些排查思路和參考。

      來源:https://www.icode9.com/content-4-870751.html

      免責聲明:本文僅代表文章作者的個人觀點,與本站無關。其原創性、真實性以及文中陳述文字和內容未經本站證實,對本文以及其中全部或者部分內容文字的真實性、完整性和原創性本站不作任何保證或承諾,請讀者僅作參考,并自行核實相關內容。

      http://image95.pinlue.com/image/25.jpg
      分享
      評論
      首頁
      和记