FastJson那些年犯下的'血案'...
點(diǎn)擊上方[全棧開發(fā)者社區(qū)]→右上角[...]→[設(shè)為星標(biāo)?]
現(xiàn)象
QA同學(xué)反映登錄不上服務(wù)器
排查問題1–日志級(jí)別
查看log,發(fā)現(xiàn)玩家登錄的時(shí)候拋出了一個(gè)java.lang.OutOfMemoryError 大概代碼是向Redis序列化一個(gè)PlayerMirror鏡像數(shù)據(jù),但是在JSON.toJSONString的時(shí)候出現(xiàn)了錯(cuò)誤.比較清晰，即序列化的時(shí)候expandCapacity,內(nèi)存不足。 又看了一下日志，有好幾個(gè)OutOfMemoryError,都是類似于用fastjson序列化PlayerMirror報(bào)的錯(cuò)誤 又仔細(xì)看了一下server目錄，發(fā)現(xiàn)了幾個(gè).hprof,說明確實(shí)發(fā)生了堆內(nèi)存溢出，因?yàn)閱?dòng)參數(shù)增加了’-XX:+HeapDumpOnOutOfMemoryError’
?at?java.lang.OutOfMemoryError.()V?(OutOfMemoryError.java:48)
??at?com.alibaba.fastjson.serializer.SerializeW
riter.expandCapacity(I)V?(SerializeWriter.java:249)
-rw-------??1?xx?xx?2043416350?Nov?24?11:37?java_pid8068.hprof
-rw-------??1?xx?xx?2028797313?Nov?24?11:17?java_pid4671.hprof
-rw-------??1?xx?xx?1477222612?Nov?23?23:25?java_pid31563.hprof
排查問題2–JVM命令級(jí)別
使用了jvm命令初步排查一下問題 jstat -gcutil pid jstat -gc pid jmap -histo pid jmap -heap pid jstat看到老年代基本已經(jīng)滿了 jmap看到排名前兩位的分別是Object[]和char[]
?num?????#instances?????????#bytes??class?name
----------------------------------------------
???1:????????146219??????741203672??[Ljava.lang.Object;
???2:???????2842356??????639498168??[C
排查問題3–專業(yè)工具級(jí)別
因?yàn)榱薶prof,所以只需要用專業(yè)的內(nèi)存分析工具mat即可 mat#Open Heap Dump,載入后直接出來一個(gè)Getting Started Wizard#Leak Suspects Report,即內(nèi)存泄露的報(bào)告,選擇finish 兩個(gè)懷疑的問題:
其中有一個(gè)JSONArray的實(shí)例就占用了大約700M內(nèi)存 另外一個(gè)是線程的local Variables占用了500M內(nèi)存
點(diǎn)開問題1詳情，發(fā)現(xiàn)這個(gè)JSONArray是配置類PersonalityStrengthenConfig#cost字段，仔細(xì)看一下這個(gè)JSONArray#list#elementData的數(shù)組長度是可怕的183842095。
點(diǎn)開問題2詳情，第一張圖可以看到，fastjson內(nèi)部的SerializeWriter中中buf#char[]長度竟然是可怕的262012306，而第二種圖的堆棧信息可以看到是在序列化PersonalityStrengthenConfig拋出的內(nèi)存溢出。
結(jié)合兩個(gè)問題，比較能容易的想到答案，PersonalityStrengthenConfig中的cost字段(JSONArray)占用了大量的內(nèi)存，而玩家下線或者上線的時(shí)候要序列化一部分?jǐn)?shù)據(jù)到redis,其中就包括這個(gè)PersonalityStrengthenConfig，所以也要序列化這個(gè)超級(jí)大的cost，而序列化要申請空間，所以就內(nèi)存溢出了。
分析問題1–觀察數(shù)據(jù)
為什么數(shù)據(jù)配置類PersonalityStrengthenConfig會(huì)被序列化呢，因?yàn)橥婕蚁戮€的時(shí)候需要序列化一個(gè)玩家鏡像數(shù)據(jù)到redis Player->Hero->HeroPersonality->getConfig(PersonalityStrengthenConfig) HeroPersonality有一個(gè)get方法,而做序列化的這個(gè)同學(xué)忘記加了SerializerFeature.IgnoreNonFieldGetter這個(gè)參數(shù)，所以導(dǎo)致getConfig中的這個(gè)config對(duì)象被序列化進(jìn)去了，修改完畢代碼后，所有的問題都沒有了。
需要確認(rèn)一下:PersonalityStrengthenConfig#cost這個(gè)JsonArray為什么占這么大空間，能看一下里面都是什么？
在mat中懷疑的第一個(gè)懷疑報(bào)告中點(diǎn)擊PersonalityStrengthenConfig@0x8140c468對(duì)象,左側(cè)Inspector頁面有一個(gè)Attributes,找到cost右鍵->List Objects->with outgoing references
從下圖可以看到，這個(gè)JSONAray內(nèi)部出了第一個(gè)元素是一個(gè)正常的JSONObject外，其他的全部為null，當(dāng)然你可以從第二個(gè)懷疑報(bào)告中將SerializeWriter中的buf#char[]數(shù)據(jù)拷貝出來->單擊->Copy->Save Value to File.當(dāng)然這個(gè)文件幾百M(fèi)(且只有一行)，非常大，普通的文本編輯器根本看不出來(我在linux上使用了tail，然后不斷的ctrl+c 最終看到了數(shù)據(jù)的開頭),而這個(gè)數(shù)據(jù)也是當(dāng)序列化到了config#cost字段時(shí),只有一個(gè)正常的數(shù)據(jù)，其他后面全部為null，所以數(shù)據(jù)問題確認(rèn)完畢:cost字段里面除了一個(gè)正常的JSONObject外，剩余的全部是null。
分析問題2–嘗試重現(xiàn)
最初的解決方法很簡單 嘗試通過代碼方式能否復(fù)現(xiàn)
即new一個(gè)HeroPersonality,其內(nèi)部有一個(gè)getConfig,使用沒有加IgnoreNonFieldGetter的方式序列化,看是否會(huì)造成大內(nèi)存的占用 很遺憾，未能復(fù)現(xiàn)
?HeroPersonality?hp?=?new?HeroPersonality();
?hp.setPersonalityLevel(1);
?String?str?=?JSON.toJSONString(hp);
然后嘗試還原數(shù)值表最近的幾個(gè)版本，看看是否有問題，這個(gè)就是懷疑策劃配置表有問題 導(dǎo)致這個(gè)cost字段在某些特殊情況下會(huì)如可能在加載的時(shí)候就變的很大，不過很遺憾未能復(fù)現(xiàn)。
分析源代碼 確認(rèn)是否可能啟動(dòng)加載配置表后這個(gè)cost字段就很大
debug DataConfigService 發(fā)現(xiàn)的第一個(gè)問題是這個(gè)類混用了json-lib和fastjson(這個(gè)框架已更新，我們項(xiàng)目一直未更新)，這里懷疑是否是json-lib有bug，發(fā)現(xiàn)反序列化的過程是JSONLexer#掃描如大括號(hào),逗號(hào),方括號(hào)。先找到了配置表的的第一個(gè)JSONObject,然后加到cost數(shù)組(注意此時(shí)JSONArray#list的底層數(shù)組長度已經(jīng)被expand到了長度10) 然后遇到RBRACKET,就結(jié)束掃描了。
看到這里就有一個(gè)想法 是否是有可能遇到了特殊字符,如fastjson中的循環(huán)引用 進(jìn)而猜測到是否是策劃配置的時(shí)候配置了公式？而且我也各種嘗試在json的cost字段加各種特殊字符，很遺憾，經(jīng)過驗(yàn)證 未能復(fù)現(xiàn)。
嘗試仔細(xì)看了一下堆快照，將PersonalityStrengthenConfig的10個(gè)對(duì)象內(nèi)部數(shù)據(jù)都看了一下，和svn的策劃表對(duì)比了一下，確認(rèn)了是某個(gè)版本的數(shù)據(jù)。而這個(gè)版本的數(shù)據(jù)在本地測試是沒有任何問題的，排除策劃配置數(shù)據(jù)問題。
分析問題3–山重水復(fù)疑無路
在我寫本地測試代碼重現(xiàn)的時(shí)候，我寫了一個(gè)反序列化HeroPersonality的例子，先用HeroPersonality序列化為一堆字符串,然后嘗試在這堆字符串加入一些額外信息,然后再反序列化，不經(jīng)意的發(fā)現(xiàn)當(dāng)進(jìn)行一次HeroPersonality的反序列化后 再將原來的HeroPersonality再次序列化輸出時(shí)驚奇的發(fā)現(xiàn)序列化后的cost字段多了一個(gè)null，然后我就將反序列化代碼放在循環(huán)里 然后再次輸出 發(fā)現(xiàn)cost字段被加了很多null。
偽測試代碼
PersonalityStrengthenConfig?config?=?DataConfigService.
getSettingById(PersonalityStrengthenConfig.class,?1);
System.out.println("dcs.config1:"?+?config.cost);
System.out.println("dcs.config1:"?+?config.attr_num);
for?(int?i?=?0;?i?????String?str1?=?"{...}";
????JSON.parseObject(str1,?HeroPersonality.class);
}
System.out.println("dcs.config2:"?+?config.cost);
System.out.println("dcs.config2:"?+?config.attr_num);
結(jié)果輸出：
這個(gè)結(jié)果讓我驚喜，讓我非常的肯定，cost中的大量null就是這樣產(chǎn)生的,而且我最早就懷疑HeroPersonality中有一些非序列化的get方法有一些問題;而同樣的attr_num也是JSONArray類型，就沒有任何問題.問題初步鎖定在HeroPersonality中的一個(gè)get方法.
分析問題4–源代碼跟蹤
需要源代碼debug，為什么在不斷的調(diào)用反序列化的時(shí)候，cost被加入了大量的null，下面這個(gè)是HeroPersonality的兩個(gè)get方法，可以看到其中的getNextTrainCost調(diào)用了getConfig字段cost字段,下面從源代碼debug的角度看一下為什么會(huì)每次反序列化都多了很多null。首先getNextTrainCost這個(gè)getter中的nextTrainCost被當(dāng)成了一個(gè)field，因?yàn)槠浞祷刂凳且粋€(gè)JSONArray,其本身是可以作為setter用到的。其反序列化，用json中"nextTrainCost"相關(guān)反序列化
該字符串是[{".config.cost[0]"} 即使用了fastjson的循環(huán)引用,這個(gè)反序列化出來為[null] (因?yàn)楸旧韈onfig壓根就不屬于field,只是一個(gè)get方法而已)
然后調(diào)用setter(本身就是一個(gè)setter),得到cost,然后將這個(gè)[null] add到cost上
然后每反序列化一次都向cost中加入一個(gè)[null],進(jìn)而使cost越來越大(JSONArray#底層數(shù)組還會(huì)自動(dòng)expand)
public?JSONArray?getNextTrainCost()?{
????return?((PersonalityStrengthenConfig)?getConfig()).cost;
}
@Override
public?DataConfigItem?getConfig()?{
????return?DataConfigService.getSettingById(PersonalityStrengthenConfig.class,
????????????personalityLevel);
}
反序列化nextTrainCost
//?FieldDeserializer#setValue?其中method就是getNextTrainCost()?即獲取方法的返回值然后加了一個(gè)null
Collection?collection?=?(Collection)?method.invoke(object);
if?(collection?!=?null)?{
??????collection.addAll((Collection)?value);
}
分析問題5–問題初步總結(jié)
第一個(gè)問題出在了HeroPersonality中的getNextTrainCost方法引用了getConfig中的cost，導(dǎo)致在反序列化的時(shí)候每次會(huì)將json#nextTrainCost中反序列化出來的JSONArray#add到cost上(相當(dāng)于調(diào)用了setter方法)
注意即使json#nextTrainCost不是循環(huán)引用(fastjson可關(guān)閉),即值就是引用的config#cost值,則每次反序列化一樣也會(huì)將反序列化出來的JSONArray#add到cost，只不過這次不會(huì)是null而已，第二個(gè)問題是最開始提到的我們正常序列化的時(shí)候就要帶上IgnoreNonFieldGetter這個(gè)參數(shù)，不要將非field的get方法給序列化上去，加上參數(shù)后，序列化后的json就沒有nextTrainCost了,那么也就不會(huì)有反序列化的問題了，因?yàn)閴焊蛼呙璨坏剑?dāng)然HeroPersonality這個(gè)getNextTrainCost也比較奇葩，用了引用的方式，其實(shí)完全沒有必要，可以考慮干掉。
解決問題1–為什么cost會(huì)那么大
剛才我們已經(jīng)基本肯定是因?yàn)殄e(cuò)誤模式下的反序列化會(huì)導(dǎo)致cost字段會(huì)越來越大，那么也不至于上億次吧?這個(gè)我大概查了一下代碼，很大幾率是好友推薦模塊和相關(guān)模塊。相關(guān)代碼需要較頻繁的對(duì)于離線鏡像反序列化或者存在類似心跳業(yè)務(wù)處理
解決辦法
很簡單，就是一定要記住fastjson序列化的時(shí)候要加上IgnoreNonFieldGetter就可以了。
擴(kuò)展
mat還有很多強(qiáng)大的使用功能：
Hisogram: list Number of instances per class Dominator: TreeList the biggest objects and what they keep alive Top Consumers: Print the most expensive objects grouped by class and by package List Objects…
此外還可以查看線程、Class Loader Explorer等
作者：landon30
來源：https://club.perfma.com/article/1656271
覺得本文對(duì)你有幫助？請分享給更多人
關(guān)注「全棧開發(fā)者社區(qū)」加星標(biāo)，提升全棧技能
本公眾號(hào)會(huì)不定期給大家發(fā)福利，包括送書、學(xué)習(xí)資源等，敬請期待吧！
如果感覺推送內(nèi)容不錯(cuò)，不妨右下角點(diǎn)個(gè)在看轉(zhuǎn)發(fā)朋友圈或收藏，感謝支持。
好文章，留言、點(diǎn)贊、在看和分享一條龍吧??