一次艱難的內(nèi)存泄露排查
-
現(xiàn)象
-
2019.4.26 22:00左右，通過(guò)jstat -gcutil pid 5000 ,發(fā)現(xiàn)fgc次數(shù)很多而且頻繁，此時(shí)老年代占比已經(jīng)大約70%左右，且已經(jīng)回收不了內(nèi)存，我們這邊設(shè)置的fgc閾值是老年代的70%。此時(shí)因?yàn)檫€有30%的老年空間，所以整體內(nèi)存相對(duì)還算穩(wěn)定，CPU也比較穩(wěn)定，但是有很大的潛在的風(fēng)險(xiǎn)，就是內(nèi)存一直上漲，不釋放。
[service@ZQ-SE-331-V05 ~]$ jstat -gcutil 1087 5000 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 55.09 88.41 72.10 92.64 85.22 9223 1169.442 435 168.866 1338.307 57.54 0.00 82.24 72.31 92.64 85.22 9224 1169.542 436 168.877 1338.418 0.00 63.75 5.33 72.50 92.64 85.22 9225 1169.642 436 168.877 1338.519 0.00 63.75 34.02 72.50 92.64 85.22 9225 1169.642 436 168.877 1338.519 0.00 63.75 59.26 72.50 92.64 85.22 9225 1169.642 436 168.877 1338.519 0.00 63.75 81.37 72.50 92.64 85.22 9225 1169.642 436 168.877 1338.519 55.60 0.00 11.75 72.71 92.64 85.22 9226 1169.742 436 168.877 1338.619 55.60 0.00 40.07 72.71 92.64 85.22 9226 1169.742 436 168.877 1338.619 55.60 0.00 67.86 72.70 92.64 85.22 9226 1169.742 437 169.541 1339.284 0.00 56.04 4.21 72.59 92.64 85.22 9227 1169.838 437 169.541 1339.379 0.00 56.04 30.01 71.73 92.64 85.22 9227 1169.838 438 169.649 1339.487 0.00 56.04 57.75 71.73 92.64 85.22 9227 1169.838 438 169.649 1339.487 0.00 56.04 79.01 71.73 92.64 85.22 9227 1169.838 438 169.649 1339.487 55.39 0.00 2.54 71.92 92.64 85.22 9228 1169.988 438 169.649 1339.638 55.39 0.00 24.70 71.92 92.64 85.22 9228 1169.988 438 169.649 1339.638 55.39 0.00 47.89 71.92 92.64 85.22 9228 1169.988 438 169.649 1339.638 55.39 0.00 82.01 71.89 92.64 85.22 9228 1169.988 439 170.207 1340.196 初步猜測(cè)是出現(xiàn)了內(nèi)存泄露
-
通過(guò)jmap -histo/-histo:live pid >> log 導(dǎo)出fgc前后的histo對(duì)比，發(fā)現(xiàn)了一個(gè)實(shí)例數(shù)很大的對(duì)象CarnivalOneDayInfo，達(dá)到了2kw級(jí)別，而且一直在增加
num #instances #bytes class name ---------------------------------------------- 1: 28906840 1387528320 java.util.HashMap 2: 38675870 1237627840 java.util.HashMap$Node 3: 18631826 745273040 xxx.CarnivalOneDayInfo num #instances #bytes class name ---------------------------------------------- 1: 31092889 1492458672 java.util.HashMap 2: 35749328 1143978496 java.util.HashMap$Node 3: 20355334 814213360 xxx.CarnivalOneDayInfo
-
-
排查
直接看CarnivalOneDayInfo(嘉年華)相關(guān)代碼，因?yàn)橹暗臏y(cè)試大概知道這個(gè)問(wèn)題，所以很快的定位到是在每分鐘的MinuteJob中檢查所有在線玩家的時(shí)間活動(dòng)的時(shí)候，相關(guān)邏輯會(huì)克隆一個(gè)CarnivalOneDayInfo。所以初步定位是CarnivalOneDayInfo不斷clone的問(wèn)題
后端y同學(xué)看了一下相關(guān)邏輯，本地把相關(guān)clone邏輯注釋后，再次本地觀察histo，發(fā)現(xiàn)該對(duì)象實(shí)例不在增加，再次確認(rèn)1的推論
-
但看了一下活動(dòng)相關(guān)代碼
所有活動(dòng)的檢查都是clone了一份，為什么只有嘉年華活動(dòng)泄露？
看相關(guān)代碼，發(fā)現(xiàn)clone出來(lái)的對(duì)象都是臨時(shí)對(duì)象，應(yīng)該會(huì)被fgc的，如何泄露呢？
-
所以直接開始操作第一步，準(zhǔn)備查CarnivalOneDayInfo是被誰(shuí)持有引用
查這個(gè)問(wèn)題的話，必須要把內(nèi)存堆快照dump出來(lái)，然后利用工具檢查，如mat
但是線上玩家很多，而且堆內(nèi)存很多，導(dǎo)出一次很花費(fèi)時(shí)間，會(huì)stw
-
所以直接連開發(fā)服務(wù)器，查了一下，一樣存在CarnivalOneDayInfo泄露的問(wèn)題，所以直接利用
jmap -dump:live,format=b,file=2388_heap.bin 2388，導(dǎo)出開發(fā)服務(wù)器java進(jìn)程的堆內(nèi)存快照
直接利用mat打開
-
對(duì)mat使用有經(jīng)驗(yàn)的話，操作步驟是直接
選擇dominator_tree
搜索CarnivalOneDayInfo
List Objects
選擇With incoming references，誰(shuí)持有了它的引用
-
直接發(fā)現(xiàn)是被
queue-executor-handler-5
java.lang.ThreadLocal$ThreadLocalMap @ 0x8104eec0
java.lang.ThreadLocal
Entry[64] @ 0x866710f0
java.lang.ThreadLocal
java.util.IdentityHashMap @ 0x86671628
java.lang.Object[]，通過(guò)查看這個(gè)屬性，可以看到其大量持有了CarnivalOneDayInfo和HashSet
從上面可以很確定的是，CarnivalOneDayInfo是直接被邏輯線程的threadlocal持有
-
艱難的分析之路
邏輯線程的threadlocal怎么會(huì)持有CarnivalOneDayInfo，從代碼和想法上感覺(jué)不可思議
-
我這邊的第一步是直接在ide中查所有ThreadLocal的引用，發(fā)現(xiàn)
logback
protobuf
業(yè)務(wù)自己的threadlocal
BeanUtils的threadlocal
排查后，簡(jiǎn)單測(cè)試了一下，和查了一下相關(guān)代碼，發(fā)現(xiàn)沒(méi)有什么思路和投訴。覺(jué)得beanutils和logback有點(diǎn)問(wèn)題，但是感覺(jué)和CarnivalOneDayInfo關(guān)系也不大
于是下面我的重點(diǎn)在于想從mat入手，看看能不能從中找出threadlocal的名字，但最終是被證明是徒勞的，只有引用地址
-
不過(guò)我們z同學(xué)從是debug的排查思路出發(fā)的
在ThreadLocal的set和setInitialValue打斷點(diǎn)
然后跑游戲，重點(diǎn)斷點(diǎn)在MinuteJob，向邏輯線程投遞消息檢查活動(dòng)狀態(tài)這塊
每次調(diào)用checkTimeActivity，都去觀察每個(gè)ThreadLocal
然后重點(diǎn)觀察是否出現(xiàn)IdentityHashMap，因?yàn)樯厦鎚at分析到了是這個(gè)map
終于定位到堆棧
-
堆棧
MinuJob -> 遍歷在線所有玩家，向邏輯線程投遞消息 -> ActivityManager#checkTimeActivity
遍歷所有個(gè)人活動(dòng) -> CarnivalActivityInfo#checkActivityState
CarnivalActivityInfo diff = playerInfo.clone() // 在這里clone了一份
checkIsSameState -> activityBaseInfo.getCarnivalDaysMap().equals(carnivalDaysMap) // 調(diào)用equals比較
去依次比較CarnivalDaysMap中每一個(gè)CarnivalOneDayInfo
調(diào)用CarnivalOneDayInfo -> BaseCarnivalOneDayInfo # equals
BeanUtils.isDirty
-
具體代碼
private static Set<String> getDirtyNamesByBean(AugmentedBean augmentedBean) { IdentityHashMap<AugmentedBean, Set<String>> dirtyNamesMap = dirtyNames.get(); if (dirtyNamesMap == null) { dirtyNamesMap = new IdentityHashMap<>(); dirtyNames.set(dirtyNamesMap); } return dirtyNamesMap.computeIfAbsent(augmentedBean, k -> Sets.newHashSet()); } public static boolean isDirty(AugmentedBean augmentedBean) { return getDirtyNamesByBean(augmentedBean).size() > 0; } -
從上面可以非常容易的看到
- 是這里創(chuàng)建了一個(gè)IdentityHashMap，然后set到了threadlocal中
- 和之前的分析如出一轍
至此完全定位問(wèn)題是，是BeanUtils的鍋
-
復(fù)盤和總結(jié)
- 其實(shí)在3的時(shí)候，非常懷疑過(guò)beanutils的問(wèn)題，但是沒(méi)有太仔細(xì)注意，現(xiàn)在一看，和上面的分析一模一樣
- 分析內(nèi)存泄露，思路
- 對(duì)比f(wàn)gc前后的histo，確認(rèn)那些對(duì)象實(shí)例數(shù)一直在增加，而且明顯偏大
- 分析代碼，如果直接定位問(wèn)題，最好
- 如果不能直接定位，需要確認(rèn)是誰(shuí)持有該對(duì)象引用，那么需要dump堆內(nèi)存快照
- 但是不能在線上dump，需要在開發(fā)服務(wù)器復(fù)現(xiàn)（內(nèi)存泄露通常比較容易復(fù)現(xiàn)），然后在開發(fā)服務(wù)器dump
- dump出來(lái)后，利用mat工具分析泄露，List Objects With incoming references，找到引用
- 下一步是需要確認(rèn)為什么這里會(huì)引用，可以分析代碼，解決問(wèn)題，最好
- 如果不能，那么可以使用debug的方式，在上一步引用相關(guān)對(duì)象的代碼出加斷點(diǎn)，確認(rèn)線程堆棧
- 也解釋了為什么只有嘉年華活動(dòng)有泄露，因?yàn)橹挥兴{(diào)用了beanutils生成的basexx的equals方法，其他都沒(méi)有調(diào)用
- beanutils是當(dāng)初clone對(duì)象的一個(gè)解決方案，用來(lái)回滾和diff，增量更新，后來(lái)該方案廢棄，因?yàn)闀?huì)隨著對(duì)象的復(fù)雜度提高而導(dǎo)致clone成本高，但是遺留了一大部分生成的代碼，而這次的bug也是因?yàn)檎{(diào)用了廢棄的生成代碼的方法。所以下一個(gè)版本一定將所有生成的廢棄代碼清理一遍
-
后續(xù)解決辦法
-
發(fā)現(xiàn)了beanutils的這個(gè)問(wèn)題后，那么很容易解決泄露問(wèn)題了。我寫了一個(gè)beanshell腳本，向邏輯線程投遞了消息，調(diào)用 BeanUtils.clean，清理所有threadlocals
import x.BeanUtils; import y.HandlerModule; for (int i = 1; i <= 16; i++) { HandlerModule.instance.addQueueTask(i, new Runnable() { public void run() { BeanUtils.clean(); } }); } -
在用jstat看了一下，CarnivalOneDayInfo經(jīng)過(guò)fgc后，從kw到了百萬(wàn)，老年代占用也從70到了30
$ jstat -gcutil 1087 5000 74.73 0.00 16.02 72.48 92.61 85.04 10156 1313.117 575 271.355 1584.472 74.73 0.00 34.71 72.48 92.61 85.04 10156 1313.117 575 271.355 1584.472 74.73 0.00 54.42 72.48 92.61 85.04 10156 1313.117 575 271.355 1584.472 74.73 0.00 73.29 72.48 92.61 85.04 10156 1313.117 575 271.355 1584.472 74.73 0.00 89.41 72.48 92.61 85.04 10156 1313.117 575 271.355 1584.472 0.00 71.54 9.25 72.74 92.64 85.06 10157 1313.303 576 272.188 1585.492 0.00 71.54 28.30 72.73 92.64 85.06 10157 1313.303 577 272.188 1585.492 0.00 71.54 55.85 72.73 92.64 85.06 10157 1313.303 577 272.463 1585.766 0.00 71.54 78.05 72.73 92.64 85.06 10157 1313.303 577 272.463 1585.766 69.21 0.00 1.70 70.98 92.64 85.06 10158 1313.438 578 273.320 1586.758 69.21 0.00 19.97 63.09 92.64 85.06 10158 1313.438 578 273.320 1586.758 69.21 0.00 39.82 53.33 92.64 85.06 10158 1313.438 578 273.320 1586.758 69.21 0.00 59.75 41.61 92.64 85.06 10158 1313.438 578 273.320 1586.758 69.21 0.00 75.12 31.79 92.64 85.06 10158 1313.438 578 273.320 1586.758 69.21 0.00 94.13 31.79 92.64 85.06 10158 1313.438 578 273.320 1586.758 0.00 86.02 15.60 32.07 92.64 85.06 10159 1313.761 578 273.320 1587.081 0.00 86.02 94.86 32.07 92.64 85.06 10159 1313.761 578 273.320 1587.081 [service@ZQ-SE-331-V05 config]$ jmap -histo 1087 | grep CarnivalOneDayInfo 10: 1408627 56345080 xxx.CarnivalOneDayInfo 另外后面的優(yōu)化方案是重構(gòu)活動(dòng)代碼，另外即使用equals，也不用之前beanutils生成的類的equals比較，避免beanutils threadlocals的泄露問(wèn)題
-
關(guān)于內(nèi)存問(wèn)題，在正式上線之前，一定要可根據(jù)同時(shí)在線人數(shù)，dau等準(zhǔn)確預(yù)估整體占用內(nèi)存，如一個(gè)player的實(shí)際的占用內(nèi)存，全局靜態(tài)數(shù)據(jù)如排行榜的實(shí)際占用內(nèi)存等。可以通過(guò)代碼和工具獲取。這樣能快速確認(rèn)是否是出現(xiàn)了內(nèi)存泄露還是真的比較占內(nèi)存。
