1 前言

項目運行過程中，我們一定都遇到過OOM的問題，大家也一定在想，OOM的問題能夠有多特殊？我來簡單舉例，我們在排查問題中遇到的奇葩問題：

• 排查過程中，明明發(fā)現(xiàn)了占用了大量內(nèi)存的實例對象，為什么在項目里面會找不到相關(guān)代碼呢？
• 百度都不靈了，竟然也找不到這個類的任何信息？
• SpringBoot的啟動在本地和服務(wù)器中的啟動竟然還有這種差別？
• SpringBoot的腳本引擎初始化竟然也會導(dǎo)致OOM？

讓我們帶著這一系列的問題來看本次的文章。

2 問題背景

俠客匯作為二手回收商圈的第一款社交領(lǐng)域的APP，社交相關(guān)信息主要分布在找同行、做生意、同行圈和推薦四個頁面。在同行圈推薦過程中需要完整的將用戶相關(guān)信息和用戶發(fā)布的帖子信息進(jìn)行展示，這些展示數(shù)據(jù)是我們實時請求的，需要實時進(jìn)行計算，所以我們采用多線程異步執(zhí)行來提升性能。在我們緊鑼密鼓的研發(fā)過程中，測試同學(xué)發(fā)現(xiàn)，服務(wù)總是莫名其妙的掛掉，之后就發(fā)生了如下對話：

測試同學(xué)：XXX，你快幫忙看一下，同行圈的列表刷一會就沒數(shù)據(jù)了，你的服務(wù)動不動就掛掉，怎么回事啊。

研發(fā)同學(xué)：是不是測試環(huán)境有問題啊，訪問的數(shù)據(jù)太多了？畢竟我們這個是實時計算的，多個線程在跑任務(wù)，不行加個內(nèi)存試一下？

隨后，我們的測試環(huán)境內(nèi)存從4G調(diào)整到了8G，果然好了一點，但是好景不長，沒有多久，又開始重復(fù)出現(xiàn)了當(dāng)前問題。

測試同學(xué)：加了內(nèi)存，還不行啊，你快看看吧，這個影響測試進(jìn)度了。

研發(fā)同學(xué)：行，我看看具體怎能回事。

接下來看我們的特殊OOM問題的排查流程。

3 問題定位

服務(wù)部署過程中沒有任何的報錯信息，而且，在服務(wù)的運行過程中也沒有明顯的報錯信息，而是在運行一段時間之后出現(xiàn)了這種錯誤。那么，大概率是內(nèi)存的問題，先按照OOM的常規(guī)排查思路，按部就班的來。

3.1 內(nèi)存基本情況分析

老規(guī)矩，jps抓一下業(yè)務(wù)服務(wù)進(jìn)程的進(jìn)程號。

圖片

因為業(yè)務(wù)場景是在項目運行一段時間后才出現(xiàn)的，必要是要一定的數(shù)據(jù)累計才行。我們需要借用工具壓測一波， 通過apifox，20個并發(fā)壓一波，同時借助jmap、jstat看一下內(nèi)存和垃圾回收情況（GC）。

首先看一下我們的內(nèi)存情況，執(zhí)行命令：jmap -heap 44

圖片

對上述圖片的內(nèi)容進(jìn)行分析。

首先，F(xiàn)rom Space 的使用率達(dá)到了驚人的百分之百，這就意味著from Space 中的內(nèi)存已被完全占用，沒有可用空間來分配新的對象。這可能導(dǎo)致應(yīng)用程序在嘗試分配新對象時遇到內(nèi)存不足的問題。同時Java 虛擬機(jī)會觸發(fā)一次GC來釋放內(nèi)存。這通常會導(dǎo)致暫停應(yīng)用程序的執(zhí)行，影響應(yīng)用程序的響應(yīng)時間。

其次，Concurrent Mark-Sweep generation的使用率也達(dá)到了80%，對于長時間運行的應(yīng)用程序，這可能意味著對象的存活率較高，可能會導(dǎo)致頻繁的垃圾回收。如果頻繁發(fā)生這種情況，可能會導(dǎo)致性能下降，因為每次 GC 都需要暫停應(yīng)用程序，而且如果在垃圾回收后，F(xiàn)rom Space仍然無法找到足夠的空間來分配新對象，應(yīng)用程序可能會拋出OutOfMemoryError，導(dǎo)致程序崩潰或無法正常運行，這就和我們的當(dāng)前業(yè)務(wù)場景很相似了。

根據(jù)以上的結(jié)論，我們再來看一下GC的情況，執(zhí)行命令：jstat -gcutil 6556 1000 100

圖片

果不其然，GC展示的情況和我們上面分析的內(nèi)容基本一致。內(nèi)存占用，尤其是老年代內(nèi)存占用很高，流量打進(jìn)來后，ygc次數(shù)快速上升，緊著ygc伴隨的是fgc。

再次對當(dāng)前圖片的參數(shù)進(jìn)行分析,內(nèi)存不夠用通常就是以下幾種情況：

• 內(nèi)存泄漏，應(yīng)用程序占用的內(nèi)存未能被釋放，導(dǎo)致可用內(nèi)存逐漸減少。但是內(nèi)存泄漏是一個長期的過程，而且從Eden區(qū)和old區(qū)的使用率可以看出，gc過程會伴隨比較徹底的內(nèi)存回收，無明顯的堆內(nèi)存泄漏特征。
• 參數(shù)設(shè)置不合理，在測試環(huán)境，沒有大量用戶，不需要太大的參數(shù)，再說，我們已經(jīng)調(diào)整了內(nèi)存參數(shù)了，看來并沒有徹底解決問題。
• 頻繁創(chuàng)建對象，垃圾回收器來不及回收導(dǎo)致了OOM。

根據(jù)我們以上的結(jié)論，排除1和2兩種場景，重點排查第三種情況這個問題。

3.2 一次失敗的日志內(nèi)存占用消除

在以上的分析中，我們已經(jīng)推論，是堆內(nèi)存被不合理的使用了，那就看一下堆內(nèi)存中實例創(chuàng)建的情況。

執(zhí)行命令：jmap -histo 3688 | more

圖片

在以上的堆內(nèi)存的實例對象中，我們發(fā)現(xiàn)了一個可疑項，為什么有這么多日志事件呢？我們知道，通常來講，為保證系統(tǒng)性能，日志是異步刷盤的。難道是日志的緩沖隊列太大，導(dǎo)致OOM了？我們先排除一下可疑的選項。

但修改日志全局打印配置，比如控制日志級別，貌似比想象的要麻煩。通過多方嘗試，最后找到了這個虛擬機(jī)入?yún)?，統(tǒng)一控制異步日志的事件隊列：-DAsyncLoggerConfig.RingBufferSize=128。

我們將相關(guān)的參數(shù)添加之后，重新進(jìn)行壓測，再次查看堆內(nèi)存的實例信息。

圖片

發(fā)現(xiàn)logger事件隊列在視線里消失了，但是OOM的情況依然存在，說明我們只是排除了干擾項， 并沒有實際的解決問題

3.3 一個奇怪的類：StringSequence？

繼續(xù)排查，等等，好像發(fā)現(xiàn)了一個奇怪的東西，這StringSequence是什么東西？

圖片

既然存在的可疑選項，我們就繼續(xù)排查，先去項目代碼里面看一下，這個類到底是做什么用的。讓人崩潰的事情發(fā)生了，搜遍了整個項目，沒有搜到這個類的任何信息。即使動用搜索引擎，也沒有找到相關(guān)說明。

不過，看上去，是一個Springboot的內(nèi)置的東西。我們知道，Springboot會將所有的資源統(tǒng)一打包成一個fatjar，保證一個jar包就能啟動整個服務(wù)，以實現(xiàn)微服務(wù)化。我們解壓一下項目的jar包，按圖索驥一下。

圖片

果然，這個StringSequence是springboot內(nèi)置的東西。這種不是常用的類，居然有這么多實例，就非常值得懷疑，可以重點排查。

但是，項目源碼里沒有，那本地debug也排查不了它啊，那要不dump內(nèi)存，分析一下？但服務(wù)器上的dump文件比較大，下載比較麻煩。

圖片

我們只能另辟蹊徑，在本地啟動，然后dump文件分析。這樣操作更靈活，也省得去服務(wù)器上下載dump文件了。

3.4 StringSequence消失了？

idea里修改啟動入?yún)ⅲ缓箝_始讓整個項目run起來，希望揭開廬山真面目。

圖片

可是，這個奇怪的StringSequnce居然又消失了？

…… 不對，有問題。剛才都說了，SpringBoot是用單一的fatjar包去啟動的，那會不會是IDEA測試和服務(wù)器上的項目啟動方式有區(qū)別呢？我們可以看一下idea的啟動相關(guān)信息?？截恑dea控制臺啟動信息第一行就是了。

圖片

果然，idea和SpringBoot的原生啟動方式是不一樣的！idea是classpath+原生的main方法啟動Springboot的。而通常，Springboot是一個fatjar啟動。

圖片

圖片

如果是這樣，那么想復(fù)現(xiàn)pod環(huán)境的問題，我們也改成jar包方式啟動，再試一下。

去項目target目錄找到打包的boot jar包，然后把classpath和idea的agent虛擬機(jī)入?yún)⑷サ?，重新啟動?/p>

圖片

啟動成功、那個熟悉又陌生的StringSequence又回來了。

圖片

dump heap內(nèi)存，然后就可以揭開這個奇怪的StringSequence的廬山真面目了。

3.5 誰在使用腳本引擎？

開始dump內(nèi)存，執(zhí)行命令：jmap -dump:live,format=b,file=dump.hprof 21896。

圖片

我們主要分析內(nèi)存中類及對應(yīng)的實例信息，決定用jhat命令，分析dump文件。

執(zhí)行命令：jhat -J-Xmx4g dump.hprof ，加載堆轉(zhuǎn)儲文件。它將分析文件并啟動一個 HTTP 服務(wù)器，允許你通過瀏覽器訪問分析結(jié)果。

接下來，我們一步步尋找那個奇怪的StringSequence。

1）查詢虛擬機(jī)所有類對應(yīng)實例的統(tǒng)計信息,在當(dāng)前的class頁面可以看到很多信息，但是我們關(guān)注的是實例化對象的內(nèi)存使用，所以，我們需要關(guān)心的是show instance counts for all class這個視圖，看圖片可以知道，這個視圖有兩個

• Including: 這個統(tǒng)計信息包含了所有類的實例，包括被 GC 標(biāo)記為可達(dá)的（即仍然在使用中的對象）和不可達(dá)的（即可能已被回收但在堆轉(zhuǎn)儲中仍然存在的對象）。這個視圖可以幫助你了解整個堆中存在的所有對象。
• Excluding: 這個統(tǒng)計信息則只包括當(dāng)前仍然在使用的實例，即被 GC 標(biāo)記為可達(dá)的對象。這個視圖更關(guān)注于應(yīng)用程序當(dāng)前活躍的內(nèi)存使用情況。

我們的問題是內(nèi)存被大量占用，所以，我們直接關(guān)注excluding這個視圖。

圖片

2）查詢StringSequence類下邊的所有實例列表

圖片

我們發(fā)現(xiàn)，當(dāng)前視圖的展示數(shù)量和控制臺的顯示數(shù)據(jù)差異比較大，懷疑是應(yīng)該和dump那一時刻的垃圾回收行為有關(guān)，帶著疑問，繼續(xù)排查。

3）查詢實例的字段值等詳細(xì)信息

圖片

就是這里了，實例有個字段叫source，然后這個字段值是"file:/C:/Users/Administrator/IdeaProjects/hero_search/service/target/hero_search.jar!/BOOT-INF/lib/transport-netty4-client-7.6.2.jar!/META-INF/services/javax.script.ScriptEngineFactory "。

類看起來很陌生，不太像是我們常用的。不過javax.script.ScriptEngineFactory應(yīng)該是一個線索。我們嘗試搜一下。

圖片

圖片

看上去是一個腳本引擎，支持動態(tài)性的。那到底是誰在使用呢？還是沒有明確的調(diào)用點。

內(nèi)存分析只能解決數(shù)據(jù)是什么的問題，但不能解決方法鏈路問題。那么如何更方便的解決調(diào)用鏈路的問題呢？而且還得考慮到StringSequence是Springboot內(nèi)置的，不在項目源碼，不能用idea debug。所以，接下來只能通過其他的工具進(jìn)行排查具體的調(diào)用鏈路問題。

3.6 終顯廬山真面目

讓我們定位一下到底是誰在初始化StringSequence。

關(guān)于arthas使用，可以參考arthas官網(wǎng)（https://arthas.aliyun.com/doc/），接入、使用都很簡單，功能強(qiáng)大。

接下來組裝一下命令：

1）由于我們要定位方法的調(diào)用鏈路，所以用stack命令。

2）由于我們要跟蹤構(gòu)造器，所以對應(yīng)的是init方法。

3）由于請求過多會導(dǎo)致控制臺打印亂序，可以限制一下命令的觸發(fā)條件。

從StringSequence的構(gòu)造函數(shù)可以看出，其第一個入?yún)⒁欢ㄊ巧衔奶岬降膕ource字段。

圖片

綜上，我們最終定位StringSequence初始化鏈路的arthas命令為：

stack org.springframework.boot.loader.jar.StringSequence'params[0].contains("hero_search.jar!/BOOT-INF/lib/transport-netty4-client-7.6.2.jar!/META-INF/services/javax.script.ScriptEngineFactory")'

圖片

元兇現(xiàn)身了。一個腳本引擎的頻繁初始化代碼。和剛才的腳本引擎使用的猜測也對上了

圖片

圖片

兩層for循環(huán)調(diào)evaluate，然后evaluate里面重復(fù)初始化腳本引擎，那內(nèi)存肯定不夠用，必須改掉。

經(jīng)查詢，腳本引擎線程安全，可以并發(fā)情況下全局復(fù)用。所以，去掉每次初始化的成本，改造成一個全局可復(fù)用的引擎，再看看效果。

圖片

果然，那個奇怪的StringSequence消失了。內(nèi)存也不會頻繁的OOM了。

圖片

謎底揭開，問題終于被徹底解決?。?！

4 深度分析

問題定位只是直接目標(biāo)，但疑問仍在：為什么一個引擎會占用這么多資源呢？這里可以繼續(xù)分析一下，以獲得更多的認(rèn)知。

4.1 內(nèi)存占用風(fēng)險之：SPI加載ScriptEngineFactory

圖片

我們從調(diào)用?？梢钥闯?，腳本引擎初始化需要ScriptEngineFactory，而ScriptEngineFactory加載用到了java的SPI機(jī)制。SPI機(jī)制的實現(xiàn)原理是遍歷classpath下的所有jar包的META-INF/services目錄，獲取匹配的接口實現(xiàn)類。而這個過程依賴的是classloader的加載資源的能力。

SpringBoot為了將業(yè)務(wù)jar包封裝在其fatJar里，替換系統(tǒng)類加載器為LaunchedURLClassLoader,而LaunchedURLClassLoader加載資源過程會遍歷所有的業(yè)務(wù)jar包，并且每一個jar包的遍歷過程中，會實例化一個StringSequence。這個也就解釋了StringSequence內(nèi)容為啥都是類似 "file:/C:/Users/Administrator/IdeaProjects/hero_search/service/target/hero_search.jar!/BOOT-INF/lib/transport-netty4-client-7.6.2.jar!/META-INF/services/javax.script.ScriptEngineFactory" 的字符串。因為需要遍歷每個jar包嘗試獲取匹配的資源。

也解釋了為啥會有這么多StringSequence的實例，因為項目引用jar包比較多，需要遍歷279個path。

圖片

同時，部分解釋了，為啥引擎實例化耗費資源：SPI的遍歷jar包的機(jī)制是原因之一。

4.2 內(nèi)存占用風(fēng)險之：腳本引擎的資源消耗

我們剛才分析了腳本引擎初始化過程中，SPI的資源消耗。那腳本引擎本身資源消耗如何呢。因為從代碼上看，ScriptEngine也會重復(fù)初始化，其實例的內(nèi)存占用影響同樣很關(guān)鍵。

我們可以借用arthas 的vmtool 分析一下腳本引擎的內(nèi)存占用情況。

獲取javax.script.ScriptEngine的一個實例，打印其成員變量,對應(yīng)arthas命令為：

vmtool --action getInstances --className javax.script.ScriptEngine --express 'instances[0]'

圖片

可以看到，項目實例化的腳本引擎為NashornScriptEngine。其初始化需要很多配置，成本很高。

以gobal成員變量為例，我們可以簡單看一下其字段數(shù)量：

vmtool --action getInstances --className javax.script.ScriptEngine --express 'instances[0].global.getClass().getDeclaredFields().length'

圖片

可以看到，一個global實例有126個成員變量，就這數(shù)量也足夠恐怖了。

4.3 內(nèi)存占用風(fēng)險之：類加載

對于動態(tài)腳本，java的實現(xiàn)方案一般是通過動態(tài)類去支持，那重復(fù)創(chuàng)建腳本引擎會有什么影響呢？

答案是：每個引擎都有腳本生成動態(tài)類的緩存，重復(fù)初始化，會使緩存失效，導(dǎo)致重復(fù)地生成動態(tài)類，給GC造成很大壓力。

代碼路徑：jdk.nashorn.internal.runtime.Context#compile

圖片

我們可以打開類加載監(jiān)控,復(fù)現(xiàn)一下類加載、卸載的場景(vm新增啟動入?yún)ⅲ?verbose:class)

如下圖，從控制臺日志中，捕獲到了18w次動態(tài)腳本引發(fā)的類加載事件。

圖片

我們知道，類卸載的條件非?？量?，所以這里面會存在內(nèi)存泄漏嗎？

答案是不會。因為引擎對于腳本的動態(tài)類加載，自定義了一個類加載器。這樣，當(dāng)引擎及腳本不再使用，類加載器也會被回收，從而動態(tài)加載的類也會被卸載。（前提是服務(wù)器有充裕的資源去回收）

代碼路徑：jdk.nashorn.internal.runtime.Context#compile

圖片

如下圖，從控制臺日志中，捕獲到了15w次和動態(tài)腳本相關(guān)的類卸載事件。

圖片

綜上，重復(fù)創(chuàng)建ScprintEngine（實現(xiàn)類為NashornScriptEngine）的成本非常高，使用中一定要謹(jǐn)慎。

5 總結(jié)

整體排查問題的過程，其實也是對我們自身知識儲備以及處理問題經(jīng)驗的一個考量。

首先要大膽的設(shè)想和懷疑，排除掉一些干擾項，例如，我們第一次排除的日志內(nèi)存占用，對StringSequence實例出現(xiàn)產(chǎn)生的懷疑。

其次，要綜合考量虛擬機(jī)提供的參數(shù)，我們根據(jù)內(nèi)存的使用率判斷出GC的大概情況，又根據(jù)多次GC時新生代和老年代的參數(shù)變化，排除了內(nèi)存泄漏的可能，最終判斷出是對象頻繁創(chuàng)建，GC來不及回收導(dǎo)致的OOM。

再次，問題是否真的解決，還是要通過驗證來判斷，在我們修復(fù)完成之后，發(fā)現(xiàn)我們懷疑的干擾項沒有再次出現(xiàn)，而且相關(guān)的OOM問題，也沒有再次出現(xiàn)，說明問題徹底的被解決。

最終，是我們真正獲得成長的部分，問題的產(chǎn)生一定是有原因的，這個原因背后的邏輯需要我們及時復(fù)盤，在本次問題中，從腳本引擎的初始化，我們想到了SPI的加載腳本的過程，想到了腳本的資源消耗，想到了類加載的過程，以往，一些概念性的東西，在此刻，與我們的實踐過程完美的結(jié)合。