併發環境下HashMap引起的full gc排查

阿新 • • 發佈：2018-12-22

現象

最近上線一個需求，完成需求的過程對程式碼進行了一次重構。應用釋出後半個小時左右，發現一個機器報警，load過高。登陸機器看CPU使用情況，發現load已經正常，看下CPU使用情況，發現有一個核跑滿，其他CPU使用率很低。大概一個小時後，其他機器陸續報警，發現同樣的問題，緊急回滾應用。

應用執行在16G記憶體的虛機上，整個JVM11G記憶體，其中新生代3G，CMS gc，JDK7。

第一反應是JVM可能在進行full gc，因為只有一個執行緒跑滿，其他執行緒被JVM暫停了。先去應用日誌看下應用執行情況，果然日誌已經沒有任何輸出。jstat -gcutil檢視JVM記憶體使用情況，發現Old區使用已經100%。

摘掉服務

考慮到full gc導致RT變得超長，去ateye摘掉應用註冊的HSF服務，但是操作失敗，整個JVM已經沒有響應。

保留現場

jmap -F -dump:format=b,file=atw.bin `jid`

把整個堆dump到本地，dump失敗，JVM已經僵死。

jmap -histo  `jid` > histo.log

保留histo記憶體快照成功;)

jstack `jid` > stack.log

JVM執行緒資訊儲存成功:)

現場儲存完畢，重啟應用。

初步分析

首先看下JVM執行緒棧資訊，看看下是否有應用執行緒阻賽，一般情況下，如果大量執行緒阻賽，每個執行緒都持有一定量的記憶體，很可能導致記憶體吃緊，而這些阻塞的執行緒又沒有處理完請求，佔用的heap空間不能被minor gc回收掉，導致產生full gc，

cat stack.log | grep atw | sort | uniq -c | sort -nr | head -10

結果如下(重新排版過)：

 177    at ...service.impl...searchInterProduct(AtwSearchServiceImpl.java:505)
 104    at ...service.impl..searchOneWay(AtwSearchServiceImpl.java:260)
  80    at ...service.impl.executor...execute(OneWayCommonAgentSearchExecutor.java:419 
)
  70    at ...service.impl.executor...handleFlights(AbstractSearchExecutor.java:689)
  47    at ...service.impl...searchOneWay(AtwSearchServiceImpl.java:257)
  31    at ...service.impl.executor...getFlightInfoAndStock(AbstractSearchExecutor.java:1073)
  30    at ...service.impl.executor...getFlightInfoAndStock(AbstractSearchExecutor.java:1087)
  22    at ...util.stlog.FarePolicyCounter.addFail(FarePolicyCounter.java:249)
  20    at ...service.impl.executor...execute(OneWayCommonAgentSearchExecutor.java:424)
  20    at ...service.impl.executor...getAllFares(AbstractSearchExecutor.java:892)

HSF執行緒開了200個，應用相關的正在執行的執行緒最多的是com.taobao.trip.atw.service.impl.AtwSearchServiceImpl.searchInterProduct(AtwSearchServiceImpl.java:505)，一共177個，小於HSF執行緒數，屬於正常，其他執行緒數量也在正常範圍內。執行緒的鎖和其他資訊也未發現異常。

接下來看下histo.log:

num     #instances         #bytes  class name
----------------------------------------------
  1:        204258     4368429800  [B
  2:       6812683      926524888  com.taobao.trip.atw.domain.AtwInterFareDO
  3:      22639343      724458976  java.util.HashMap$Entry
  4:      22304135      538457776  [S
  5:      21614962      518759088  java.lang.Long
  6:      13867918      443773376  com.taobao.trip.atw.util.LongReferenceConcurrentHashMap$HashEntry
  7:       6812439      326997072  com.taobao.trip.atw.domain.AtwInterFareSegmentDO
  8:        421442      211696296  [J
  9:        557827      199825568  [Ljava.util.HashMap$Entry;
 10:       6812439      163498536  [Lcom.taobao.trip.atw.domain.AtwInterFareSegmentDO;

發現最大的記憶體物件是byte陣列，204258個例項大約佔用4G堆空間(整個堆11G)，平均每個20k。

初步猜測可能本次上線程式碼還有new byte[]的地方，即檢視程式碼，發現本次新增功能沒有這樣的程式碼。而且整個應用的程式碼也無可疑地方產生了byte陣列。

繼續分析可能是依賴的二方或者三方jar包引起，重新申請分支，提釋出單，檢視釋出包變化：

通過對比發現，本次釋出涉及jar包變更很小，而且無三方包變更，只有內部包發生變化。對變化的包進行分析沒有找到new byte[]地方。

繼續分析histo.log，找到一臺線上正常機器，生成histo，用故障機器資料減去正常值，得到差值如下(top 10)：

class	instances	bytes
[B	47404	4275481936
java.util.HashMap$Entry	19442009	622144288
java.lang.Long	19711584	473078016
[Ljava.util.HashMap$Entry;	239216	164734560
com.taobao.at.dal.common.dataobject.AtwMessage	359668	20141408
java.util.HashMap	215770	10356960
java.util.concurrent.LinkedBlockingQueue$Node	421036	10104864
com.taobao.trip.atw.metaq.service.common.LocalMessageReactor$1	359769	8634456
com.alibaba.rocketmq.common.message.MessageExt	65151	6775704

除了byte[] 外，java.util.HashMap$Entry比正常機器多2kw，檢視程式碼也沒有明顯證據能解釋HashMap和byte[]同時增大的場景。

至此，分析思路阻塞，需要找到新的線索。

通過GC日誌找到新線索

通過上面的分析，已經找到現象：應用出現了full gc，而且伴隨大量byte[]和java.util.HashMap$Entry不能回收。

然而，full gc最直接的產物gc.log還沒有被挖掘。根據full gc時間點，發現新線索(重新排版過):)

==WARNNING==  allocating large array--thread_id[0x00007f71211b0800]--thread_name[owc--425027705]--array_size[2132509912 bytes]--array_length[2132509891 elememts]
prio=10 tid=0x00007f71211b0800 nid=0x3f43e runnable
    at com.alibaba.dubbo.common.io.Bytes.copyOf(Bytes.java:59)
    at com.alibaba.dubbo.common.io...write(UnsafeByteArrayOutputStream.java:64)
    at com.taobao.hsf.com.caucho.hessian.io...flushBuffer(Hessian2Output.java:1553)
    at com.taobao.hsf.com.caucho.hessian.io...printString(Hessian2Output.java:1466)
    at com.taobao.hsf.com.caucho.hessian.io...writeString(Hessian2Output.java:987)
    at com.taobao.hsf.com.caucho.hessian.io...writeObject(BasicSerializer.java:149)
    at com.taobao.hsf.com.caucho.hessian.io...writeObject(Hessian2Output.java:421)
    at com.taobao.hsf.com.caucho.hessian.io...writeObject(MapSerializer.java:99)
    at com.taobao.hsf.com.caucho.hessian.io...writeObject(Hessian2Output.java:421)
    at com.taobao.hsf.com.caucho.hessian.io...serialize(UnsafeSerializer.java:293)
    at com.taobao.hsf.com.caucho.hessian.io...writeInstance(UnsafeSerializer.java:212)
    at com.taobao.hsf.com.caucho.hessian.io...writeObject(UnsafeSerializer.java:171)
    at com.taobao.hsf.com.caucho.hessian.io.H..writeObject(Hessian2Output.java:421)
    at com.taobao.hsf.remoting.serialize...encode(Hessian2Encoder.java:23)
    at com.taobao.hsf.remoting.server.output...writeHSFResponse(RpcOutput.java:47)
    at com.taobao.hsf.remoting.provider...handleRequest(ProviderProcessor.java:202)
    at com.taobao.hsf.remoting.server...handleRequest(RPCServerHandler.java:47)
    at com.taobao.hsf.remoting.server..r.handleRequest(RPCServerHandler.java:25)
    ...

阿里定製的JVM增加了許多自己的新特性，其中一個就是在full gc不能回收的情況下，會把當前分配最大記憶體的執行緒資訊和分配的記憶體資訊打印出來！

==WARNNING== allocating large array–thread_id[0x00007f71211b0800]–thread_name[owc–425027705]–array_size[2132509912 bytes]–array_length[2132509891 elememts]

執行緒owc--425027705，這是一個應用自己處理HSF請求的執行緒，它在分配一個巨大的資料組！通過gc日誌的堆疊資訊發現當前這個執行緒正在處理byte[]的拷貝：

at com.alibaba.dubbo.common.io.Bytes.copyOf(Bytes.java:59)

這個拷貝過程一般是，應用處理好HSF請求後，把處理結果序列化成byte[]，然後通過網路傳輸到呼叫機器上。

至此找到了byte[]產生的原因，還有java.util.HashMap$Entry未解決。

根據執行緒名字owc--425027705去JVM的執行緒日誌查詢資訊，發現owc--425027705是處理請求的主執行緒，下面有四個子執行緒都在處理這樣的堆疊：

"owc--425027705-344" daemon prio=10 tid=0x00007f710278f800 nid=0x3f414 runnable [0x0000000051906000]
   java.lang.Thread.State: RUNNABLE
    at java.util.HashMap.getEntry(HashMap.java:469)
    at java.util.HashMap.get(HashMap.java:421)
    at com.taobao.trip.atw.result.impl.DefaultPriceMergerOW.processHeightQuality(DefaultPriceMergerOW.java:327)
    at com.taobao.trip.atw.result.impl.DefaultPriceMergerOW.extendedProductProcess(DefaultPriceMergerOW.java:179)
    at com.taobao.trip.atw.result.impl.DefaultPriceMergerOW.mergeOneWay(DefaultPriceMergerOW.java:137)
    at com.taobao.trip.atw.result.PriceMergerProxy.mergeOneWay(PriceMergerProxy.java:184)
    ...

子執行緒都在從HashMap中get資料！由於之前遇到過HashMap多執行緒操作導致成環形資料結構，繼而get操作成死迴圈的教訓，這裡斷定是HashMap問題！

HashMap多執行緒下成死迴圈原因

簡短的說，多執行緒下對HashMap的put操作，會導致內部的Entry連結串列形成環形資料結構。
首先，put操作會檢查容量是否充足，如果不足，會resize內部陣列。

void addEntry(int hash, K key, V value, int bucketIndex) {
    if ((size >= threshold) && (null != table[bucketIndex])) {
        resize(2 * table.length);
        hash = (null != key) ? hash(key) : 0;
        bucketIndex = indexFor(hash, table.length);
    }

    createEntry(hash, key, value, bucketIndex);
}

問題就在於resize內部會遍歷Entry的連結串列：

void addEntry(int hash, K key, V value, int bucketIndex) {
    if ((size >= threshold) && (null != table[bucketIndex])) {
        resize(2 * table.length);
        hash = (null != key) ? hash(key) : 0;
        bucketIndex = indexFor(hash, table.length);
    }

    createEntry(hash, key, value, bucketIndex);
}

這樣的程式碼在多執行緒情況下，會出現環。

對於成環的Map，get遍歷Entry連結串列時會導致死迴圈：

final Entry<K,V> getEntry(Object key) {
    if (size == 0) {
        return null;
    }

    int hash = (key == null) ? 0 : hash(key);
    for (Entry<K,V> e = table[indexFor(hash, table.length)];
         e != null;
         e = e.next) {
        Object k;
        if (e.hash == hash &&
            ((k = e.key) == key || (key != null && key.equals(k))))
            return e;
    }
    return null;
}

為什麼會出現多個執行緒同時操作一個HashMap？

處理邏輯

主執行緒收到請求後，會分配4個子執行緒去計算結果，然後由主執行緒去完成對結果的合併。如果子執行緒處理失敗或者超時，那麼這個子執行緒的結果會被丟棄，不會被合併。

從日誌上看，4個子執行緒的處理都已經超時，但是由於HashMap併發操作造成死迴圈，4個子執行緒仍然在執行，主執行緒丟棄了子執行緒的結果，那數量量應該非常小才對，為何會產生如此大的byte[]？

追根溯源，從主執行緒分配任務找到了端倪。4個子執行緒處理計算的結果物件都是從主執行緒拷貝過來的：

BeanUtils.copyProperties(main, rsp);

這次修改在結果物件上增加了一個HashMap：

    private Map<Long,Map<ItemGroupType,ItemDO>> agentItemGroup;
    
    public Map<Long, Map<ItemGroupType, ItemDO>> getAgentItemGroup() {
        if (agentItemGroup == null) {
            agentItemGroup = new HashMap<Long, Map<ItemGroupType, ItemDO>>();
        }
        return agentItemGroup;
    }

    public void setAgentItemGroup(Map<Long, Map<ItemGroupType, ItemDO>> agentItemGroup) {
        this.agentItemGroup = agentItemGroup;
    }

agentItemGroup的get方法會判斷是否null，如果是的話，會生成一個新的map。

在org.springframework.beans.BeanUtils#copyProperties(java.lang.Object, java.lang.Object)方法中，物件屬性的賦值會呼叫get/set方法，(參考：org.springframework.beans.BeanUtils#copyProperties(java.lang.Object, java.lang.Object, java.lang.Class, java.lang.String[]))這樣就導致4個子執行緒用的map跟主執行緒是同一個map，而且就運算元執行緒的結果被放棄了，主執行緒的map已經被搞壞。

com.taobao.hsf.com.caucho.hessian.io.MapSerializer.writeObject(MapSerializer.java:99)

HSF在對Map的序列化時候，對遍歷Map，進行序列化：

    public void writeObject(Object obj, AbstractHessianOutput out) throws IOException {
        if(!out.addRef(obj)) {
            Map map = (Map)obj;
            Class cl = obj.getClass();
            if(!cl.equals(HashMap.class) && this._isSendJavaType && obj instanceof Serializable) {
                out.writeMapBegin(obj.getClass().getName());
            } else {
                out.writeMapBegin((String)null);
            }

            Iterator iter = map.entrySet().iterator();

            while(iter.hasNext()) {
                Entry entry = (Entry)iter.next();
                out.writeObject(entry.getKey());
                out.writeObject(entry.getValue());
            }

            out.writeMapEnd();
        }
    }

由於主執行緒的map已經成環形資料結構，遍歷的迭代器會死迴圈執行。

至此，full gc現象全部排查完畢，解決方案，一行程式碼到搞定：

BeanUtils.copyProperties(main, rsp);
rsp.setAgentItemGroup(new HashMap<Long, Map<ItemGroupType, ItemDO>>());

總結

併發環境下被HashMap坑不止一次，很多時候，寫程式碼沒有考慮併發場景，熟知寫的程式碼已經是在併發環境運行了。這樣就釀成大錯，其實後來想想，HashMap也可以做一下改進，get中如果迴圈超過size次了，丟擲個異常，也不會導致死迴圈和full gc了

併發環境下HashMap引起的full gc排查

現象

摘掉服務

保留現場

初步分析

通過GC日誌找到新線索

HashMap多執行緒下成死迴圈原因

處理邏輯

總結

併發環境下HashMap引起的full gc排查

圖文高併發環境下HashMap的問題

高併發環境下，HashMap可能出現的致命問題。注意：是在jdk8以下版本

Java併發環境下的佇列（Queue）概述

高併發場景系列(一) 利用redis實現分散式事務鎖,解決高併發環境下減庫存

高併發環境下執行緒安全的單例模式（最全最經典）

資料庫之高併發環境下的規則

Java多執行緒:解決高併發環境下資料插入重複問題

利用redis實現分散式事務鎖,解決高併發環境下減庫存

高併發環境下生成訂單唯一流水號方法:SnowFlake

併發環境下，先操作資料庫還是先操作快取？

ThreadLocalRandom ---- Random在大併發環境下的替代者

【高併發】高併發環境下詭異的加鎖問題（你加的鎖未必安全）

【高併發】在高併發環境下該如何構建應用級快取？

【高併發】高併發環境下如何防止Tomcat記憶體溢位？看完我懂了！！

【高併發】高併發環境下構建快取服務需要注意哪些問題？我和阿里P9聊了很久！

k8s環境下由predis初始化連線緩慢引起的一次問題排查

(轉載)一次生產系統 Full GC 問題分析與排查總結

HashMap多執行緒環境下的死迴圈問題解釋

併發下HashMap為什麼不是執行緒安全的？

併發環境下HashMap引起的full gc排查

現象

摘掉服務

保留現場

初步分析

通過GC日誌找到新線索

HashMap多執行緒下成死迴圈原因

處理邏輯

總結

相關推薦