1 前言

項(xiàng)目運(yùn)行過(guò)程中，我們一定都遇到過(guò)OOM的問(wèn)題，大家也一定在想，OOM的問(wèn)題能夠有多特殊？我來(lái)簡(jiǎn)單舉例，我們?cè)谂挪閱?wèn)題中遇到的奇葩問(wèn)題：

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

讓我們帶著這一系列的問(wèn)題來(lái)看本次的文章。

2 問(wèn)題背景

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

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

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

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

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

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

接下來(lái)看我們的特殊OOM問(wèn)題的排查流程。

3 問(wèn)題定位

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

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

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

圖片

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

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

圖片

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

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

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

根據(jù)以上的結(jié)論，我們?cè)賮?lái)看一下GC的情況，執(zhí)行命令：jstat -gcutil 6556 1000 100

圖片

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

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

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

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

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

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

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

圖片

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

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

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

圖片

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

3.3 一個(gè)奇怪的類：StringSequence？

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

圖片

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

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

圖片

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

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

圖片

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

3.4 StringSequence消失了？

idea里修改啟動(dòng)入?yún)ⅲ缓箝_(kāi)始讓整個(gè)項(xiàng)目run起來(lái)，希望揭開(kāi)廬山真面目。

圖片

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

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

圖片

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

圖片

圖片

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

去項(xiàng)目target目錄找到打包的boot jar包，然后把classpath和idea的agent虛擬機(jī)入?yún)⑷サ?，重新啟?dòng)。

圖片

啟動(dòng)成功、那個(gè)熟悉又陌生的StringSequence又回來(lái)了。

圖片

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

3.5 誰(shuí)在使用腳本引擎？

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

圖片

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

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

接下來(lái)，我們一步步尋找那個(gè)奇怪的StringSequence。

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

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

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

圖片

2）查詢StringSequence類下邊的所有實(shí)例列表

圖片

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

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

圖片

就是這里了，實(shí)例有個(gè)字段叫source，然后這個(gè)字段值是"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 "。

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

圖片

圖片

看上去是一個(gè)腳本引擎，支持動(dòng)態(tài)性的。那到底是誰(shuí)在使用呢？還是沒(méi)有明確的調(diào)用點(diǎn)。

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

3.6 終顯廬山真面目

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

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

接下來(lái)組裝一下命令：

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

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

3）由于請(qǐng)求過(guò)多會(huì)導(dǎo)致控制臺(tái)打印亂序，可以限制一下命令的觸發(fā)條件。

從StringSequence的構(gòu)造函數(shù)可以看出，其第一個(gè)入?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)身了。一個(gè)腳本引擎的頻繁初始化代碼。和剛才的腳本引擎使用的猜測(cè)也對(duì)上了

圖片

圖片

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

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

圖片

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

圖片

謎底揭開(kāi)，問(wèn)題終于被徹底解決！?。?/strong>

4 深度分析

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

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

圖片

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

SpringBoot為了將業(yè)務(wù)jar包封裝在其fatJar里，替換系統(tǒng)類加載器為L(zhǎng)aunchedURLClassLoader,而LaunchedURLClassLoader加載資源過(guò)程會(huì)遍歷所有的業(yè)務(wù)jar包，并且每一個(gè)jar包的遍歷過(guò)程中，會(huì)實(shí)例化一個(gè)StringSequence。這個(gè)也就解釋了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" 的字符串。因?yàn)樾枰闅v每個(gè)jar包嘗試獲取匹配的資源。

也解釋了為啥會(huì)有這么多StringSequence的實(shí)例，因?yàn)轫?xiàng)目引用jar包比較多，需要遍歷279個(gè)path。

圖片

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

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

我們剛才分析了腳本引擎初始化過(guò)程中，SPI的資源消耗。那腳本引擎本身資源消耗如何呢。因?yàn)閺拇a上看，ScriptEngine也會(huì)重復(fù)初始化，其實(shí)例的內(nèi)存占用影響同樣很關(guān)鍵。

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

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

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

圖片

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

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

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

圖片

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

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

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

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

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

圖片

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

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

圖片

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

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

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

圖片

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

圖片

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

5 總結(jié)

整體排查問(wèn)題的過(guò)程，其實(shí)也是對(duì)我們自身知識(shí)儲(chǔ)備以及處理問(wèn)題經(jīng)驗(yàn)的一個(gè)考量。

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

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

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

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