Netty堆外內存泄露排查與總結

<h2>導讀</h2> <p>Netty 是一個異步事件驅動的網絡通訊層框架，用於快速開發高可用高性能的服務端網絡框架與客戶端程序，它極大地簡化了 TCP 和 UDP 套接字服務器等網絡編程。</p> <p>Netty 底層基於 JDK 的 NIO，咱們爲何不直接基於 JDK 的 NIO 或者其餘NIO框架：</p> <ol> <li>使用 JDK 自帶的 NIO 須要瞭解太多的概念，編程複雜。</li> <li>Netty 底層 IO 模型隨意切換，而這一切只須要作微小的改動。</li> <li>Netty自帶的拆包解包，異常檢測等機制讓咱們從 NIO 的繁重細節中脫離出來，只需關心業務邏輯便可。</li> <li>Netty解決了JDK 的不少包括空輪訓在內的 Bug。</li> <li>Netty底層對線程，Selector 作了不少細小的優化，精心設計的 Reactor 線程作到很是高效的併發處理。</li> <li>自帶各類協議棧，讓咱們處理任何一種通用協議都幾乎不用親自動手。</li> <li>Netty社區活躍，遇到問題隨時郵件列表或者 issue。</li> <li>Netty已經歷各大RPC框架（Dubbo），消息中間件（RocketMQ），大數據通訊（Hadoop）框架的普遍的線上驗證，健壯性無比強大。</li> </ol> <h2>背景</h2> <p>最近在作一個基於 Websocket 的長連中間件，服務端使用實現了 Socket.IO 協議（基於WebSocket協議，提供長輪詢降級能力）的 <a href="https://github.com/mrniko/netty-socketio/" title="netty-socketio">netty-socketio</a> 框架，該框架爲 Netty 實現，鑑於本人對 Netty 比較熟，而且對比一樣實現了 Socket.IO 協議的其餘框架，Netty 的口碑都要更好一些，所以選擇這個框架做爲底層核心。</p> <p>誠然，任何開源框架都避免不了 Bug 的存在，咱們在使用這個開源框架時，就遇到一個堆外內存泄露的 Bug。美團的價值觀一直都是「追求卓越」，因此咱們就想挑戰一下，找到那隻臭蟲（Bug），而本文就是遇到的問題以及排查的過程。固然，想看結論的同窗能夠直接跳到最後，閱讀總結便可。</p> <h2>問題</h2> <p>某天早上，咱們忽然收到告警，Nginx 服務端出現大量5xx。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a06fc9a23e8b?w=1240&h=722&f=png&s=278951" alt="image.png" /></p> <p>咱們使用 Nginx 做爲服務端 WebSocket 的七層負載，5xx的爆發一般代表服務端不可用。因爲目前 Nginx 告警沒有細分具體哪臺機器不可用，接下來，咱們就到 <a href="https://tech.meituan.com/CAT_in_Depth_Java_Application_Monitoring.html">CAT</a>（美團點評統一監控平臺，目前已經開源）去檢查一下整個集羣的各項指標，就發現以下兩個異常:</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a07449da7c6c?w=1240&h=403&f=png&s=52496" alt="image.png" /></p> <p>某臺機器在同一時間點爆發 GC（垃圾回收），並且在同一時間，JVM 線程阻塞。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a07647235371?w=1240&h=438&f=png&s=49160" alt="image.png" /></p> <p>接下來，咱們就就開始了漫長的堆外內存泄露「排查之旅」。</p> <h2>排查過程</h2> <h3>階段1: 懷疑是log4j2</h3> <p>由於線程被大量阻塞，咱們首先想到的是定位哪些線程被阻塞，最後查出來是 Log4j2 狂打日誌致使 Netty 的 NIO 線程阻塞（因爲沒有及時保留現場，因此截圖缺失）。NIO 線程阻塞以後，因咱們的服務器沒法處理客戶端的請求，因此對Nginx來講就是5xx。</p> <p>接下來，咱們查看了 Log4j2 的配置文件。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a07904bcbf54?w=640&h=133&f=png&s=60210" alt="image.png" /></p> <p>咱們發現打印到控制檯的這個 appender 忘記註釋掉了，因此初步猜想：由於這個項目打印的日誌過多，而 Log4j2 打印到控制檯是同步阻塞打印的，因此就致使了這個問題。那麼接下來，咱們把線上全部機器的這行註釋掉，本覺得會「大功告成」，但沒想到僅僅過了幾天，5xx告警又來「敲門」。看來，這個問題並沒咱們最初想象的那麼簡單。</p> <h2>階段2：可疑日誌浮現</h2> <p>接下來，咱們只能硬着頭皮去查日誌，特別是故障發生點先後的日誌，因而又發現了一處可疑的地方：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a07bc9790965?w=1240&h=581&f=png&s=713215" alt="image.png" /></p> <p>能夠看到：在極短的時間內，狂打 <code>failed to allocate 64(bytes) of direct memory(...)</code>日誌（瞬間十幾個日誌文件，每一個日誌文件幾百M），日誌裏拋出一個 Netty 本身封裝的<code>OutOfDirectMemoryError</code>。說白了，就是堆外內存不夠用，Netty 一直在「喊冤」。</p> <p><strong>堆外內存泄露</strong>，聽到這個名詞就感到很沮喪。由於這個問題的排查就像 C 語言內存泄露同樣難以排查，首先能想到的就是，在 OOM 爆發以前，查看有無異常。而後查遍了 CAT 上與機器相關的全部指標，查遍了 OOM 日誌以前的全部日誌，均未發現任何異常！這個時候內心已經「萬馬奔騰」了......</p> <h3>階段3：定位OOM源</h3> <p>沒辦法，只能看着這堆討厭的 OOM 日誌發着呆，但願答案可以「蹦到」眼前，可是那只是妄想。束手無策之際，忽然一道光在眼前一閃而過，在 OOM 下方的幾行日誌變得耀眼起來（爲啥以前就沒想認真查看日誌？估計是被堆外內存泄露這幾個詞嚇怕了吧 ==！），這幾行字是 <code>....PlatformDepedeng.incrementMemory()...</code>。</p> <p>原來，堆外內存是否夠用，是 Netty 這邊本身統計的，那麼是否是能夠找到統計代碼，找到統計代碼以後咱們就能夠看到 Netty 裏面的對外內存統計邏輯了？因而，接下來翻翻代碼，找到這段邏輯，就在 <code>PlatformDepedent</code> 這個類裏面。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a07f01069501?w=1240&h=378&f=png&s=178952" alt="image.png" /></p> <p>這個地方，是一個對已使用堆外內存計數的操做，計數器爲 <code>DIRECT_MEMORY_COUNTER</code>，若是發現已使用內存大於堆外內存的上限（用戶自行指定），就拋出一個自定義 OOM Error，異常裏面的文本內容正是咱們在日誌裏面看到的。</p> <p>接下來，就驗證一下這個方法是不是在堆外內存分配的時候被調用。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a081c6be2179?w=1240&h=715&f=png&s=357914" alt="image.png" /></p> <p>果真，在 Netty 每次分配堆外內存以前，都會計數。想到這，思路就開始慢慢清晰，而心情也開始從「秋風瑟瑟」變成「春光明媚」。</p> <h3>階段4：反射進行堆外內存監控</h3> <p><a href="https://tech.meituan.com/CAT_in_Depth_Java_Application_Monitoring.html">CAT</a> 上關於堆外內存的監控沒有任何異常（應該是沒有統計準確，一直維持在 1M），而這邊咱們又確認堆外內存已快超過上限，而且已經知道 Netty 底層是使用的哪一個字段來統計。那麼接下來要作的第一件事情，就是反射拿到這個字段，而後咱們本身統計 Netty 使用堆外內存的狀況。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a084636ff096?w=1240&h=841&f=png&s=513475" alt="image.png" /></p> <p>堆外內存統計字段是 <code>DIRECT_MEMORY_COUNTER</code>，咱們能夠經過反射拿到這個字段，而後按期 Check 這個值，就能夠監控 Netty 堆外內存的增加狀況。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a086dcdd11a4?w=1240&h=694&f=png&s=287213" alt="image.png" /></p> <p>因而咱們經過反射拿到這個字段，而後每隔一秒打印，爲何要這樣作？</p> <p>由於，經過咱們前面的分析，在爆發大量 OOM 現象以前，沒有任何可疑的現象。那麼只有兩種狀況，一種是忽然某個瞬間分配了大量的堆外內存致使OOM；一種是堆外內存緩慢增加，到達某個點以後，最後一根稻草將機器壓垮。在這段代碼加上去以後，咱們打包上線。</p> <h3>階段5：究竟是緩慢增加仍是瞬間飆升？</h3> <p>代碼上線以後，初始內存爲 16384k（16M），這是由於線上咱們使用了池化堆外內存，默認一個 chunk 爲16M，這裏沒必要過於糾結。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a08949b919ca?w=1240&h=728&f=png&s=841877" alt="image.png" /></p> <p>可是沒過一會，內存就開始緩慢飆升，而且沒有釋放的跡象，二十幾分鍾以後，內存使用狀況以下：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a08c5d02310f?w=1240&h=997&f=png&s=1189490" alt="image.png" /></p> <p>走到這裏，咱們猜想多是前面提到的第二種狀況，也就是內存緩慢增加形成的 OOM，因爲內存實在增加太慢，因而調整機器負載權重爲其餘機器的兩倍，可是仍然是以數K級別在持續增加。那天恰好是週五，索性就過一個週末再開看。</p> <p>週末以後，咱們到公司第一時間就連上了跳板機，登陸線上機器，開始 tail -f 繼續查看日誌。在輸完命令以後，懷着期待的心情重重的敲下了回車鍵：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a08eb4dc1cf9?w=1240&h=696&f=png&s=857181" alt="image.png" /></p> <p>果真不出所料，內存一直在緩慢增加，一個週末的時間，堆外內存已經飆到快一個 G 了。這個時候，我居然想到了一句成語：「只要功夫深，鐵杵磨成針」。雖然堆外內存以幾個K的速度在緩慢增加，可是隻要一直持續下去，總有把內存打爆的時候（線上堆外內存上限設置的是2G）。</p> <p>此時，咱們開始自問自答環節：內存爲啥會緩慢增加，伴隨着什麼而增加？由於咱們的應用是面向用戶端的WebSocket，那麼，會不會是每一次有用戶進來，交互完以後離開，內存都會增加一些，而後不釋放呢？帶着這個疑問，咱們開始了線下模擬過程。</p> <h3>階段6：線下模擬</h3> <p>本地起好服務，把監控堆外內存的單位改成以B爲單位（由於本地流量較小，打算一次一個客戶端鏈接），另外，本地也使用非池化內存（內存數字較小，容易看出問題），在服務端啓動以後，控制檯打印信息以下</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a091a9e94051?w=1240&h=739&f=png&s=1021332" alt="image.png" /></p> <p>在沒有客戶端接入的時候，堆外內存一直是0，在乎料之中。接下來，懷着着無比激動的心情，打開瀏覽器，而後輸入網址，開始咱們的模擬之旅。</p> <p>咱們的模擬流程是：新建一個客戶端連接->斷開連接->再新建一個客戶端連接->再斷開連接。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0940cecb745?w=1240&h=697&f=png&s=883148" alt="image.png" /></p> <p>如上圖所示，一次 Connect 和 Disconnect 爲一次鏈接的創建與關閉，上圖綠色框框的日誌分別是兩次鏈接的生命週期。咱們能夠看到，內存每次都是在鏈接被關閉的的時候暴漲 256B，而後也不釋放。走到這裏，問題進一步縮小，確定是鏈接被關閉的時候，觸發了框架的一個Bug，並且這個Bug在觸發以前分配了 256B 的內存，隨着Bug被觸發，內存也沒有釋放。問題縮小以後，接下來開始「擼源碼」，捉蟲！</p> <h3>階段7：線下排查</h3> <p>接下來，咱們將本地服務重啓，開始完整的線下排查過程。同時將目光定位到 netty-socketio 這個框架的 Disconnect 事件（客戶端WebSocket鏈接關閉時會調用到這裏），基本上能夠肯定，在 Disconnect 事件先後申請的內存並無釋放。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a096805e8815?w=1240&h=681&f=png&s=563540" alt="image.png" /></p> <p>在使用 idea debug 時，要選擇只掛起當前線程，這樣咱們在單步跟蹤的時候，控制檯仍然能夠看到堆外內存統計線程在打印日誌。</p> <p>在客戶端鏈接上以後而後關閉，斷點進入到 <code>onDisconnect</code> 回調，咱們特地在此多停留了一會，發現控制檯內存並無飆升（7B這個內存暫時沒有去分析，只須要知道，客戶端鏈接斷開以後，咱們斷點hold住，內存還未開始漲）。接下來，神奇的一幕出現了，咱們將斷點放開，讓程序跑完：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a09976e3ad7e?w=1240&h=670&f=png&s=587857" alt="image.png" /></p> <p>Debug 鬆掉以後，內存立馬飆升了！！此時，咱們已經知道，這隻「臭蟲」飛不了多遠了。在 Debug 時，掛起的是當前線程，那麼確定是當前線程某個地方申請了堆外內存，而後沒有釋放，繼續「馬不停蹄「，深刻源碼。</p> <p>其實，每一次單步調試，咱們都會觀察控制檯的內存飆升的狀況。很快，咱們來到了這個地方：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a09c634dfb2a?w=1240&h=790&f=png&s=1148753" alt="image.png" /></p> <p>在這一行沒執行以前，控制檯的內存依然是 263B。而後，當執行完該行以後，馬上從 263B漲到519B（漲了256B）。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a09ef79e5f42?w=1240&h=721&f=png&s=604830" alt="image.png" /></p> <p>因而，Bug 範圍進一步縮小。咱們將本次程序跑完，釋而後客戶端再來一次鏈接，斷點打在 <code>client.send()</code> 這行，而後關閉客戶端鏈接，以後直接進入到這個方法，隨後的過程有點長，由於與 Netty 的時間傳播機制有關，這裏就省略了。最後，咱們跟蹤到了以下代碼，<code>handleWebsocket</code>：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0a1f6872ffe?w=1240&h=703&f=png&s=870817" alt="image.png" /></p> <p>在這個地方，咱們看到一處很是可疑的地方，在上圖的斷點上一行，調用 <code>encoder</code> 分配了一段內存，調用完以後，咱們的控制檯立馬就彪了 256B。因此，咱們懷疑確定是這裏申請的內存沒有釋放，它這裏接下來調用 <code>encoder.encodePacket()</code> 方法，猜測是把數據包的內容以二進制的方式寫到這段 256B的內存。接下來，咱們追蹤到這段 encode 代碼，單步執行以後，就定位到這行代碼：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0a4808351a5?w=1240&h=605&f=png&s=305508" alt="image.png" /></p> <p>這段代碼是把 packet 裏面一個字段的值轉換爲一個 char。然而，當咱們使用 idea 預執行的時候，卻拋出類一個憤怒的 NPE！！也就是說，框架申請到一段內存以後，在 encoder 的時候，本身 GG 了，還給本身挖了個NPE的深坑，最後致使內存沒法釋放（最外層有堆外內存釋放邏輯，如今沒法執行到了）。並且越攢越多，直到被「最後一根稻草」壓垮，堆外內存就這樣爆了。這裏的源碼，有興趣的讀者能夠本身去分析一下，限於篇幅緣由，這裏就再也不展開敘述了。</p> <h3>階段8：Bug解決</h3> <p>既然 Bug 已經找到，接下來就要解決問題了。這裏只須要解決這個NPE異常，就能夠 Fix 掉。咱們的目標就是，讓這個 <code>subType</code> 字段不爲空。因而咱們先經過 idea 的線程調用棧，定位到這個 packet 是在哪一個地方定義的：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0a7f30053f0?w=1240&h=1013&f=png&s=543975" alt="image.png" /></p> <p>咱們找到 idea 的 debugger 面板，眼睛盯着 packet 這個對象不放，而後上線移動光標，便光速定位到。原來，定義 packet 對象這個地方在咱們前面的代碼其實已經出現過，咱們查看了一下 <code>subType</code> 這個字段，果真是 null。接下來，解決 Bug 就很容易了。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0aa7edc1932?w=1240&h=621&f=png&s=389677" alt="image.png" /></p> <p>咱們給這個字段賦值便可，因爲這裏是鏈接關閉事件，因此咱們給他指定了一個名爲 DISCONNECT 的字段（能夠改天深刻去研究 Socket.IO 的協議），反正這個 Bug 是在鏈接關閉的時候觸發的，就粗暴一點了！</p> <p>解決這個 Bug 的過程是：將這個框架的源碼下載到本地，而後加上這一行，最後從新 Build一下，pom 裏改了一下名字，推送到咱們公司的倉庫。這樣，項目就能夠直接進行使用了。</p> <p>改完 Bug 以後，習慣性地去 GitHub上找到引起這段 Bug 的 Commit： <img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0ae1bc71925?w=1240&h=1022&f=png&s=308044" alt="image.png" /> 好奇的是，爲啥這位 <code>dzn</code> commiter 會寫出這麼一段如此明顯的 Bug，並且時間就在今年3月30號，項目啓動的前夕！</p> <h3>階段9：線下驗證</h3> <p>一切準備就緒以後，咱們就來進行本地驗證，在服務起來以後，咱們瘋狂地創建鏈接，瘋狂地斷開鏈接，並觀察堆外內存的狀況：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0b089672775?w=1240&h=597&f=png&s=749093" alt="image.png" /></p> <p>Bingo！無論咱們如何斷開鏈接，堆外內存不漲了。至此，Bug 基本 Fix，固然最後一步，咱們把代碼推到線上驗證。</p> <h3>階段10：線上驗證</h3> <p>此次線上驗證，咱們避免了比較土的打日誌方法，咱們把堆外內存的這個指標「噴射」到 CAT 上，而後再來觀察一段時間的堆外內存的狀況：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0b33512e9ea?w=1240&h=1067&f=png&s=118664" alt="image.png" /></p> <p>過完一段時間，堆外內存已經穩定不漲了。此刻，咱們的「捉蟲之旅」到此結束。最後，咱們還爲你們作一個小小的總結，但願對您有所幫助。</p> <h2>總結</h2> <ol> <li> <p>遇到堆外內存泄露不要怕，仔細耐心分析，總能找到思路，要多看日誌，多分析。</p> </li> <li> <p>若是使用了 Netty 堆外內存，那麼能夠自行監控堆外內存的使用狀況，不須要藉助第三方工具，咱們是使用的「反射」拿到的堆外內存的狀況。</p> </li> <li> <p>逐漸縮小範圍，直到 Bug 被找到。當咱們確認某個線程的執行帶來 Bug 時，可單步執行，可二分執行，定位到某行代碼以後，跟到這段代碼，而後繼續單步執行或者二分的方式來定位最終出 Bug 的代碼。這個方法屢試不爽，最後總能找到想要的 Bug。</p> </li> <li> <p>熟練掌握 idea 的調試，讓咱們的「捉蟲」速度快如閃電（「閃電俠」就是這麼來的）。這裏，最多見的調試方式是預執行表達式，以及經過線程調用棧，死盯某個對象，就可以掌握這個對象的定義、賦值之類。</p> </li> </ol> <p>最後，祝願你們都能找到本身的「心儀已久」 Bug！</p> <h1>做者簡介</h1> <p>閃電俠，2014年加入美團點評，主要負責美團點評移動端統一長連工做，歡迎同行進行技術交流。</p> <h1>招聘</h1> <p>目前咱們團隊負責美團點評長連基礎設施的建設，支持美團酒旅、外賣、到店、打車、金融等幾乎公司全部業務的快速發展。加入咱們，你能夠親身體驗到千萬級在線鏈接、日吞吐百億請求的場景，你會直面互聯網高併發、高可用的挑戰，有機會接觸到 Netty 在長連領域的各個場景。咱們誠邀有激情、有想法、有經驗、有能力的同窗，和咱們一塊兒並肩奮鬥！歡迎感興趣的同窗投遞簡歷至 chao.yu#dianping.com 諮詢。</p> <h1>參考文獻</h1> <ol> <li><a href="https://www.jianshu.com/p/a4e03835921a">Netty 是什麼</a></li> <li><a href="https://www.jianshu.com/p/c5068caab217">Netty 源碼分析之服務端啓動全解析</a></li> </ol> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0b82bef31f6?w=1875&h=835&f=png&s=142461" alt="" /></p>html

原文連接：https://my.oschina.net/meituantech/blog/2249206git