難忘的OOM緝兇之旅

兇案現場：

公元20几几年的某一天，筆者正在公司清閒地啃着早餐，手機忽然傳來一個應用告警！！！打開一看: 應用老年代內存使用率超過95% 幾個大字赫然映入眼簾，嚇得筆者趕忙丟下了手中的肉包子，趕忙排查！

下圖是後面解決了問題後從應用監控中補拍的做案證據，明顯看到在一段時間內應用的老年代在頻繁進行着full gc，且內存高點一直在100%處徘徊。

緝兇過程：

咳咳，做爲一個成熟的java攻城獅，在面對着oom這種小毛賊時，筆者天然是保持着一臉淡定（其實心裏慌得一批，畢竟當時剛入職沒兩天，怎麼就接了這麼個鍋）。

當時第一反應是先諮詢了運維同事，發現監控平臺上並無集成內存分析的工具，須要自行dump分析。既然如此，那隻能硬着頭皮上了，筆者二話不說接入跳板機，登陸生產環境，一招 jps 找到當前java應用的進程pid，又一招 jmap -dump:format=b,file=filename pid , 內心想着等老子拿到dump文件，必定好好修理你個兇手。時間漫長地過去了 ~~~ 10分鐘，終於拿到了dump文件（此處省略各類與生產環境文件導出的鬥智鬥勇）。

筆者火燒眉毛拿出左右兩柄手術刀（java自帶的 visualvm 與一個比較有名的外部分析軟件 mat），準備對dump文件進行屍檢。畢竟第一次使刀，握着刀柄一時半會兒不知如何下手，真是丟我攻城獅的臉！折騰了半天，終於打開了 mat，載入了dump文件。（mac使用mat有時可能遇到啓動失敗的坑，此處不做贅述，請自行 度娘/google)

劃開屍體的第一刀，映入眼簾的是血淋淋的內臟佈局，以下圖：

火眼金睛的筆者一眼發現，我特麼這個腫瘤這麼大！！！1.9G的內存它佔據了1.7G，這究竟是哪裏來的腫瘤呢，筆者火燒眉毛地朝紅色箭頭指向的地方劃出第二刀！刀法以下，點擊mat的Reports項目的Leak Suspects，mat會自動爲咱們找出部分疑似致使oom的元兇對象。

咦！咱們看到了什麼，一個 logback.classic.AsyncAppender對象誒，它活活佔據了89.74%的內存！！！微接觸過logback這個日誌框架的小夥伴都應該知道AsyncAppender是logback框架的一個配置包裝對象，負責包裝設置日誌的一些配置。咱們不禁得開始懷疑，這具屍體的死因跟應用日誌有關！伴隨着懷疑，筆者又朝屍體深處劃出一刀。

拉到accumulate objects in dominator tree項，它爲咱們列出了這個asyncAppender對象的內存結構。果真如咱們所料，logback框架會使用一個隊列來緩存一個個loggingEvent對象，每一次調用日誌輸出都會被包裝成一個loggingEvent緩存起來。從上圖第1、二點咱們看到這個日誌緩存隊列佔據了十分巨大的內存，而且他的loggingEvent對象光一個就佔了23%左右的內存，個人天。上圖第三點的inspector觀察窗口能展現出這個對象的具體內容，因而咱們截取了前兩個佔比最大的loggingEvent對象的msg來看看這個日誌的內容究竟是啥？

通過一番仔細查驗，筆者基本肯定是 dubbo接口的生產者在返回結果時報出的傳輸內容長度超限問題，並且超出了兩個數量級之多。順藤摸瓜，咱們緊跟着從日誌內容着手，發現返回的結果 data 是一個數組，也就是在執行批量查詢的時候超限了。追溯到對應表的具體批量查詢，發現當有一個條件爲空時，批量查詢語句會跳過sql的in條件去走全表！！然而這個表一共有幾十萬的數據！！！（具體sql在此不表，就是條件篩選沒有生效致使）

結案：

區區oom果真沒能逃過筆者的法眼，案件最後定性緣由以下：因爲sql的設計錯誤致使批量查詢數據量巨大，超過了dubbo的傳輸限制，於是拋出異常並寫日誌。而日誌對象中包含了巨量的查詢返回對象具體信息，並丟進異步日誌隊列，日誌還沒來得及刷新到磁盤就已經撐爆了內存，oom發生告警！！ 後續優化的時候除了修改sql，優化了批量查詢的條件，同時還在logback配置上加入了日誌最大長度的限制，杜絕因日誌打印致使的oom再次發生。