淺析JVM內(nèi)存大對(duì)象監(jiān)控和優(yōu)化實(shí)踐的過(guò)程

服務(wù)器內(nèi)存問(wèn)題是影響應(yīng)用程序性能和穩(wěn)定性的重要因素之一，需要及時(shí)排查和優(yōu)化。本文介紹了某核心服務(wù)內(nèi)存問(wèn)題排查與解決過(guò)程。首先在JVM與大對(duì)象優(yōu)化上進(jìn)行了有效的實(shí)踐，其次在故障轉(zhuǎn)移與大對(duì)象監(jiān)控上提出了可靠的落地方案。最后，總結(jié)了內(nèi)存優(yōu)化需要考慮的其他問(wèn)題。

一、問(wèn)題描述

音樂(lè)業(yè)務(wù)中，core服務(wù)主要提供歌曲、歌手等元數(shù)據(jù)與用戶資產(chǎn)查詢。隨著元數(shù)據(jù)與用戶資產(chǎn)查詢量的增長(zhǎng)，一些JVM內(nèi)存問(wèn)題也逐漸顯露，例如GC頻繁、耗時(shí)長(zhǎng)，在高峰期RPC調(diào)用超時(shí)等問(wèn)題，導(dǎo)致業(yè)務(wù)核心功能受損。

圖1 業(yè)務(wù)異常數(shù)量變化

二、分析與解決

通過(guò)對(duì)日志，機(jī)器CPU、內(nèi)存等監(jiān)控?cái)?shù)據(jù)分析發(fā)現(xiàn)：

YGC平均每分鐘次數(shù)12次，峰值為24次，平均每次的耗時(shí)在327毫秒。FGC平均每10分鐘0.08次，峰值1次，平均耗時(shí)30秒?？梢钥吹紾C問(wèn)題較為突出。

在問(wèn)題期間，機(jī)器的CPU并沒(méi)有明顯的變化，但是堆內(nèi)存出現(xiàn)較大異常。圖2，黃色圓圈處，內(nèi)存使用急速上升，F(xiàn)GC變的頻繁，釋放的內(nèi)存越來(lái)越少。

圖2 老年代內(nèi)存使用異常

因此，我們認(rèn)為業(yè)務(wù)功能異常是機(jī)器的內(nèi)存問(wèn)題導(dǎo)致的，需要對(duì)服務(wù)的內(nèi)存做一次專(zhuān)項(xiàng)優(yōu)化。

步驟1 JVM優(yōu)化

以下是默認(rèn)的JVM參數(shù)：

-Xms4096M-Xmx4096M-Xmn1024M-XX:MetaspaceSize=256M-Djava.security.egd=file:/dev/./urandom-XX:+HeapDumpOnOutOfMemoryError-XX:HeapDumpPath=/data/{runuser}/logs/other

如果不指定垃圾收集器，那么JDK 8默認(rèn)采用的是Parallel Scavenge（新生代） +Parallel Old（老年代），這種組合在多核CPU上充分利用多線程并行的優(yōu)勢(shì)，提高垃圾回收的效率和吞吐量。但是，由于采用多線程并行方式，會(huì)造成一定的停頓時(shí)間，不適合對(duì)響應(yīng)時(shí)間要求較高的應(yīng)用程序。然而，core這類(lèi)的服務(wù)特點(diǎn)是對(duì)象數(shù)量多，生命周期短。在系統(tǒng)特點(diǎn)上，吞吐量較低，要求時(shí)延低。因此，默認(rèn)的JVM參數(shù)并不適合core服務(wù)。

根據(jù)業(yè)務(wù)的特點(diǎn)和多次對(duì)照實(shí)驗(yàn)，選擇了如下參數(shù)進(jìn)行JVM優(yōu)化（4核8G的機(jī)器）。該參數(shù)將young區(qū)設(shè)為原來(lái)的1.5倍，減少了進(jìn)入老年代的對(duì)象數(shù)量。將垃圾回收器換成ParNew+CMS，可以減少YGC的次數(shù)，降低停頓時(shí)間。此外還開(kāi)啟了CMSScavengeBeforeRemark，在CMS的重新標(biāo)記階段進(jìn)行一次YGC，以減少重新標(biāo)記的時(shí)間。

-Xms4096M-Xmx4096M-Xmn1536M-XX:MetaspaceSize=256M-XX:+UseConcMarkSweepGC-XX:+CMSScavengeBeforeRemark-Djava.security.egd=file:/dev/./urandom-XX:+HeapDumpOnOutOfMemoryError-XX:HeapDumpPath=/data/{runuser}/logs/other

圖3 JVM優(yōu)化前后的堆內(nèi)存對(duì)比

優(yōu)化后效果如圖3，堆內(nèi)存的使用明顯降低，但是Dubbo超時(shí)仍然存在。

我們推斷，在業(yè)務(wù)高峰期，該節(jié)點(diǎn)出現(xiàn)了大對(duì)象晉升到了老年代，導(dǎo)致內(nèi)存使用迅速上升，并且大對(duì)象沒(méi)有被及時(shí)回收。那如何找到這個(gè)大對(duì)象及其產(chǎn)生的原因呢？為了降低問(wèn)題排查期間業(yè)務(wù)的損失，提出了臨時(shí)的故障轉(zhuǎn)移策略，盡量降低異常數(shù)量。

步驟2 故障轉(zhuǎn)移策略

在api服務(wù)調(diào)用core服務(wù)出現(xiàn)異常時(shí)，將出現(xiàn)異常的機(jī)器ip上報(bào)給監(jiān)控平臺(tái)。然后利用監(jiān)控平臺(tái)的統(tǒng)計(jì)與告警能力，配置相應(yīng)的告警規(guī)則與回調(diào)函數(shù)。當(dāng)異常觸發(fā)告警，通過(guò)配置的回調(diào)函數(shù)將告警ip傳遞給api服務(wù)，此時(shí)api服務(wù)可以將core服務(wù)下的該ip對(duì)應(yīng)的機(jī)器視為“故障”，進(jìn)而通過(guò)自定義的故障轉(zhuǎn)移策略（實(shí)現(xiàn)Dubbo的AbstractLoadBalance抽象類(lèi)，并且配置在項(xiàng)目），自動(dòng)將該ip從提供者集群中剔除，從而達(dá)到不去調(diào)用問(wèn)題機(jī)器。圖 4 是整個(gè)措施的流程。在該措施上線前，每當(dāng)有機(jī)器內(nèi)存告警時(shí)，將會(huì)人工重啟該機(jī)器。

圖4 故障轉(zhuǎn)移策略

步驟3 大對(duì)象優(yōu)化

大對(duì)象占用了較多的內(nèi)存，導(dǎo)致內(nèi)存空間無(wú)法被有效利用，甚至造成OOM（Out Of Memory）異常。在優(yōu)化過(guò)程中，先是查看了異常期間的線程信息，然后對(duì)堆內(nèi)存進(jìn)行了分析，最終確定了大對(duì)象身份以及產(chǎn)生的接口。

（1） Dump Stack 查看線程

從監(jiān)控平臺(tái)上Dump Stack文件，發(fā)現(xiàn)一定數(shù)量的如下線程調(diào)用。

Thread 5612: (state = IN_JAVA)
 - org.apache.dubbo.remoting.exchange.codec.ExchangeCodec.encodeResponse(org.apache.dubbo.remoting.Channel, org.apache.dubbo.remoting.buffer.ChannelBuffer, org.apache.dubbo.remoting.exchange.Response) @bci=11, line=282 (Compiled frame; information may be imprecise)
 - org.apache.dubbo.remoting.exchange.codec.ExchangeCodec.encode(org.apache.dubbo.remoting.Channel, org.apache.dubbo.remoting.buffer.ChannelBuffer, java.lang.Object) @bci=34, line=73 (Compiled frame)
 - org.apache.dubbo.rpc.protocol.dubbo.DubboCountCodec.encode(org.apache.dubbo.remoting.Channel, org.apache.dubbo.remoting.buffer.ChannelBuffer, java.lang.Object) @bci=7, line=40 (Compiled frame)
 - org.apache.dubbo.remoting.transport.netty4.NettyCodecAdapter$InternalEncoder.encode(io.netty.channel.ChannelHandlerContext, java.lang.Object, io.netty.buffer.ByteBuf) @bci=51, line=69 (Compiled frame)
 - io.netty.handler.codec.MessageToByteEncoder.write(io.netty.channel.ChannelHandlerContext, java.lang.Object, io.netty.channel.ChannelPromise) @bci=33, line=107 (Compiled frame)
 - io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(java.lang.Object, io.netty.channel.ChannelPromise) @bci=10, line=717 (Compiled frame)
 - io.netty.channel.AbstractChannelHandlerContext.invokeWrite(java.lang.Object, io.netty.channel.ChannelPromise) @bci=10, line=709 (Compiled frame)
...

state = IN_JAVA 表示Java虛擬機(jī)正在執(zhí)行Java程序。從線程調(diào)用信息可以看到，Dubbo正在調(diào)用Netty，將輸出寫(xiě)入到緩沖區(qū)。此時(shí)的響應(yīng)可能是一個(gè)大對(duì)象，因而在對(duì)響應(yīng)進(jìn)行編碼、寫(xiě)緩沖區(qū)時(shí)，需要耗費(fèi)較長(zhǎng)的時(shí)間，導(dǎo)致抓取到的此類(lèi)線程較多。另外耗時(shí)長(zhǎng)，也即是大對(duì)象存活時(shí)間長(zhǎng)，導(dǎo)致full gc 釋放的內(nèi)存越來(lái)越小，空閑的堆內(nèi)存變小，這又會(huì)加劇full gc 次數(shù)。

這一系列的連鎖反應(yīng)與圖2相吻合，那么接下來(lái)的任務(wù)就是找到這個(gè)大對(duì)象。

（2）Dump Heap 查看內(nèi)存

對(duì)core服務(wù)的堆內(nèi)存進(jìn)行了多次查看，其中比較有代表性的一次快照的大對(duì)象列表如下，

圖5 core服務(wù)的堆內(nèi)存快照

整個(gè)Netty的taskQueue有258MB。并且從圖中綠色方框處可以發(fā)現(xiàn)，單個(gè)的Response竟達(dá)到了9M，紅色方框處，顯示了調(diào)用方的服務(wù)名以及URI。

進(jìn)一步排查，發(fā)現(xiàn)該接口會(huì)通過(guò)core服務(wù)查詢大量信息，至此基本排查清楚了大對(duì)象的身份以及產(chǎn)生原因。

（3）優(yōu)化結(jié)果

在對(duì)接口進(jìn)行優(yōu)化后，整個(gè)core服務(wù)也出現(xiàn)了非常明顯的改進(jìn)。YGC全天總次數(shù)降低了76.5%，高峰期累計(jì)耗時(shí)降低了75.5%。FGC三天才會(huì)發(fā)生一次，并且高峰期累計(jì)耗時(shí)降低了90.1%。

圖6大對(duì)象優(yōu)化后的core服務(wù)GC情況

盡管優(yōu)化后，因內(nèi)部異常導(dǎo)致獲取核心業(yè)務(wù)失敗的異常請(qǐng)求數(shù)顯著減少，但是依然存在。為了找到最后這一點(diǎn)異常產(chǎn)生的原因，我們打算對(duì)core服務(wù)內(nèi)存中的對(duì)象大小進(jìn)行監(jiān)控。

圖7系統(tǒng)內(nèi)部異常導(dǎo)致核心業(yè)務(wù)失敗的異常請(qǐng)求數(shù)

步驟4 無(wú)侵入式內(nèi)存對(duì)象監(jiān)控

Debug Dubbo 源碼的過(guò)程中，發(fā)現(xiàn)在網(wǎng)絡(luò)層，Dubbo通過(guò)encodeResponse方法對(duì)響應(yīng)進(jìn)行編碼并寫(xiě)入緩沖區(qū)，通過(guò)checkPayload方法去檢查響應(yīng)的大小，當(dāng)超過(guò)payload時(shí)，會(huì)拋出ExceedPayloadLimitException異常。在外層對(duì)異常進(jìn)行了捕獲，重置buffer位置，而且如果是ExceedPayloadLimitException異常，重新發(fā)送一個(gè)空響應(yīng)，這里需要注意，空響應(yīng)沒(méi)有原始的響應(yīng)結(jié)果信息，源碼如下。

//org.apache.dubbo.remoting.exchange.codec.ExchangeCodec#encodeResponse
protected void encodeResponse(Channel channel, ChannelBuffer buffer, Response res) throws IOException {
    //...省略部分代碼
    try {
 
        //1、檢查響應(yīng)大小是否超過(guò) payload，如果超過(guò)，則拋出ExceedPayloadLimitException異常
        checkPayload(channel, len);
 
 
    } catch (Throwable t) {
         
        //2、重置buffer
        buffer.writerIndex(savedWriteIndex);
 
        //3、捕獲異常后，生成一個(gè)新的空響應(yīng)
        Response r = new Response(res.getId(), res.getVersion());
        r.setStatus(Response.BAD_RESPONSE);
         
        //4、ExceedPayloadLimitException異常，將生成的空響應(yīng)重新發(fā)送一遍
        if (t instanceof ExceedPayloadLimitException) {
            r.setErrorMessage(t.getMessage());
            channel.send(r);
            return;
        }
         
    }
}
 
//org.apache.dubbo.remoting.transport.AbstractCodec#checkPayload
protected static void checkPayload(Channel channel, long size) throws IOException {
    int payload = getPayload(channel);
    boolean overPayload = isOverPayload(payload, size);
    if (overPayload) {
        ExceedPayloadLimitException e = new ExceedPayloadLimitException("Data length too large: " + size + ", max payload: " + payload + ", channel: " + channel);
        logger.error(e);
        throw e;
    }
}

受此啟發(fā)，自定義了編解碼類(lèi)（實(shí)現(xiàn)org.apache.dubbo.remoting.Codec2接口，并且配置在項(xiàng)目），去監(jiān)控超出閾值的對(duì)象，并打印請(qǐng)求的詳細(xì)信息，方便排查問(wèn)題。在具體實(shí)現(xiàn)中，如果特意去計(jì)算每個(gè)對(duì)象的大小，那么勢(shì)必是對(duì)服務(wù)性能造成影響。經(jīng)過(guò)分析，采取了和checkPayload一樣的方式，根據(jù)編碼前后buffer的writerIndex位置去判斷有沒(méi)有超過(guò)設(shè)定的閾值。代碼如下。

/**
 * 自定義dubbo編碼類(lèi)
 **/
public class MusicDubboCountCodec implements Codec2 {
 
    /**
     * 異常響應(yīng)池：緩存超過(guò)payload大小的responseId
     */
    private static Cache EXCEED_PAYLOAD_LIMIT_CACHE = Caffeine.newBuilder()
        // 緩存總條數(shù)
        .maximumSize(100)
        // 過(guò)期時(shí)間
        .expireAfterWrite(300, TimeUnit.SECONDS)
        // 將value設(shè)置為軟引用，在OOM前直接淘汰
        .softValues()
        .build();
 
 
    @Override
    public void encode(Channel channel, ChannelBuffer buffer, Object message) throws IOException {
        //1、記錄數(shù)據(jù)編碼前的buffer位置
        int writeBefore = null == buffer ? 0 : buffer.writerIndex();
 
        //2、調(diào)用原始的編碼方法
        dubboCountCodec.encode(channel, buffer, message);
 
        //3、檢查&記錄超過(guò)payload的信息
        checkOverPayload(message);
 
        //4、計(jì)算對(duì)象長(zhǎng)度
        int writeAfter = null == buffer ? 0 : buffer.writerIndex();    
        int length = writeAfter - writeBefore;
 
        //5、超過(guò)告警閾值，進(jìn)行日志打印處理
        warningLengthTooLong(length, message);
    }
 
    //校驗(yàn)response是否超過(guò)payload，超過(guò)了，緩存id
    private void checkOverPayload(Object message){
        if(!(message instanceof Response)){
            return;
        }
        Response response = (Response) message;
 
        //3.1、新的發(fā)送過(guò)程：通過(guò)狀態(tài)碼BAD_RESPONSE與錯(cuò)誤信息識(shí)別出空響應(yīng)，并記錄響應(yīng)id
        if(Response.BAD_RESPONSE == response.getStatus() && StrUtil.contains(response.getErrorMessage(), OVER_PAYLOAD_ERROR_MESSAGE)){          
            EXCEED_PAYLOAD_LIMIT_CACHE.put(response.getId(), response.getErrorMessage());
            return;
        }
 
        //3.2、原先的發(fā)送過(guò)程：通過(guò)異常池識(shí)別出超過(guò)payload的響應(yīng)，打印有用的信息
        if(Response.OK == response.getStatus() &&  EXCEED_PAYLOAD_LIMIT_CACHE.getIfPresent(response.getId()) != null){      
            String responseMessage = getResponseMessage(response);
            log.warn("dubbo序列化對(duì)象大小超過(guò)payload,errorMsg is {},response is {}", EXCEED_PAYLOAD_LIMIT_CACHE.getIfPresent(response.getId()),responseMessage);
        }
    }
     
}

在上文中提到，當(dāng)捕獲到超過(guò)payload的異常時(shí)，會(huì)重新生成空響應(yīng)，導(dǎo)致失去了原始的響應(yīng)結(jié)果，此時(shí)再去打印日志，是無(wú)法獲取到調(diào)用方法和入?yún)⒌?，但是encodeResponse方法步驟4中，重新發(fā)送這個(gè)Response，給了我們機(jī)會(huì)去獲取到想要的信息，因?yàn)橹匦掳l(fā)送意味著會(huì)再去走一遍自定義的編碼類(lèi)。

假設(shè)有一個(gè)超出payload的請(qǐng)求，執(zhí)行到自定編碼類(lèi)encode方法的步驟2（Dubbo源碼中的編碼方法），在這里會(huì)調(diào)用encodeResponse方法重置buffer，發(fā)送新的空響應(yīng)。

（1）當(dāng)這個(gè)新的空響應(yīng)再次進(jìn)入自定義encode方法，執(zhí)行 checkOverPayload方法的步驟3.1時(shí)，就會(huì)記錄異常響應(yīng)的id到本地緩存。由于在encodeResponse中buffer被重置，無(wú)法計(jì)算對(duì)象的大小，所以步驟4、5不會(huì)起到實(shí)際作用，就此結(jié)束新的發(fā)送過(guò)程。

（2）原先的發(fā)送過(guò)程回到步驟2 繼續(xù)執(zhí)行，到了步驟3.2 時(shí)，發(fā)現(xiàn)本地緩存的異常池中有當(dāng)前的響應(yīng)id，這時(shí)就可以打印調(diào)用信息了。

綜上，對(duì)于大小在告警閾值和payload之間的對(duì)象，由于響應(yīng)信息成功寫(xiě)入了buffer，可以直接進(jìn)行大小判斷，并且打印響應(yīng)中的關(guān)鍵信息；對(duì)于超過(guò)payload的對(duì)象，在重新發(fā)送中記錄異常響應(yīng)id到本地，在原始發(fā)送過(guò)程中訪問(wèn)異常id池識(shí)別是否是異常響應(yīng)，進(jìn)行關(guān)鍵信息打印。

在監(jiān)控措施上線后，通過(guò)日志很快速的發(fā)現(xiàn)了一部分產(chǎn)生大對(duì)象的接口，當(dāng)前也正在根據(jù)接口特點(diǎn)做針對(duì)性優(yōu)化。

三、總結(jié)

在對(duì)服務(wù)JVM內(nèi)存進(jìn)行調(diào)優(yōu)時(shí)，要充分利用日志、監(jiān)控工具、堆棧信息等，分析與定位問(wèn)題。盡量降低問(wèn)題排查期間的業(yè)務(wù)損失，引入對(duì)象監(jiān)控手段也不能影響現(xiàn)有業(yè)務(wù)。除此之外，還可以在定時(shí)任務(wù)、代碼重構(gòu)、緩存等方面進(jìn)行優(yōu)化。優(yōu)化服務(wù)內(nèi)存不僅僅是JVM調(diào)參，而是一個(gè)全方面的持續(xù)過(guò)程。

審核編輯：劉清