QA 同学反映登录不上服务器
查看 log, 发现玩家登录的时候抛出了一个 java.lang.OutOfMemoryError,大概出错代码是序列化一个 PlayerMirror 镜像数据保存到 Redis 的时候,但是在 JSON.toJSONString 的时候出现了错误。即序列化的时候需要扩容 expandCapacity,但是内存不足。
又看了一下日志,有好几个 OutOfMemoryError, 都是类似于用 fastjson 序列化 PlayerMirror 报的错误,还看了一下 server 目录,发现了几个. hprof,即 OOM 时自动生成的 dump 文件,说明确实发生了堆内存溢出,因为启动参数增加了’-XX:+HeapDumpOnOutOfMemoryError’:,错误日志如下:
at java.lang.OutOfMemoryError.<init>()V (OutOfMemoryError.java:48)
at com.alibaba.fastjson.serializer.SerializeWriter.expandCapacity(I)V (SerializeWriter.java:249)
dump 文件如下:
-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 命令
使用了 jvm 命令(jstat 和 jmap)初步排查一下问题:
-
jstat 看到老年代基本已经满了
-
jmap 看到排名前两位的分别是 Object[] 和 char[]
num #instances #bytes class name
----------------------------------------------
1: 146219 741203672 [Ljava.lang.Object;
2: 2842356 639498168 [C
这种的结果,就能说明是有一个 Object[] 占了很大的空间,导致 OOM,正常的 jmap -histo 结果前两位应该是 char[] 和 byte[],而且占用空间远大于其他对象。
排查问题 3–MAT
因为有 hprof,所以只需要用专业的内存分析工具 mat 即可,mat->Open Heap Dump, 打开 dump 文件后直接出来一个 Getting Started Wizard->Leak Suspects Report,即内存泄露的报告, 选择 finish:
两个怀疑的问题:
-
其中有一个 JSONArray 的实例就占用了大约 700M 内存
-
另外一个是线程的 local Variables 占用了 500M 内存
MAT 截图如下,两个怀疑点:
点开问题 1 详情,发现这个 JSONArray 是配置类 PersonalityStrengthenConfig#cost 字段,仔细看一下这个 JSONArray#list#elementData 的数组长度是可怕的 183842095:
点开问题 2 详情,第一张图可以看到,fastjson 内部的 SerializeWriter 中 buf#char[] 长度竟然是可怕的 262012306,而第二张图的堆栈信息可以看到是在序列化 PersonalityStrengthenConfig 抛出的内存溢出:
image
结合两个问题, 比较能容易的想到答案:
PersonalityStrengthenConfig 中的 cost 字段 (JSONArray) 占用了大量的内存,而玩家下线或者上线的时候要序列化一部分数据到 redis, 其中就包括这个 PersonalityStrengthenConfig,所以也要序列化这个超级大的 cost, 而序列化要申请空间,所以就内存溢出了。
分析问题 1-- 观察数据
为什么数据配置类 PersonalityStrengthenConfig 会被序列化呢?因为玩家下线的时候需要序列化一个玩家镜像数据到 redis:
Player->Hero->HeroPersonality->getConfig(PersonalityStrengthenConfig)
HeroPersonality 有一个 getConfig 方法,而做序列化时这个同学忘记加 SerializerFeature.IgnoreNonFieldGetter 这个参数,所以导致这个不需要保存到 Redis 的 config 对象被序列化进去了。
修改完毕代码后, 所有的问题都没有了。需要确认一下: PersonalityStrengthenConfig#cost 这个 JsonArray 为什么占这么大空间,能看一下里面都是什么。在 mat 中怀疑的第一个怀疑报告中点击 PersonalityStrengthenConfig@0x8140c468 对象, 左侧 Inspector 页面有一个 Attributes, 找到 cost 右键 ->List Objects->with outgoing references,从下图可以看到,这个 JSONAray 内部除了第一个元素是一个正常的 JSONObject 外,其他的全部为 null。当然你可以从第二个怀疑报告中将 SerializeWriter 中的 buf#char[] 数据拷贝出来 -> 单击 ->Copy->Save Value to File. 当然这个文件几百 M(且只有一行),非常大,普通的文本编辑器根本看不出来(UE 可以,Notepad++ 基本上不行), 而这个数据也是当序列化到了 config#cost 字段时, 只有一个正常的数据,其他后面全部为 null。
所以数据问题确认完毕: cost 字段里面除了一个正常的 JSONObject 外,剩余的全部是 null:
分析问题 2-- 山重水复疑无路
尝试在本地重现这个问题,比想象要难一些。在我反复写本地测试代码重现的时候,出现了一道曙光(坚持就是胜利),我写了一个反序列化 HeroPersonality 的例子,先用 HeroPersonality 序列化为一堆字符串,然后尝试在这堆字符串加入一些额外信息,然后再反序列化,不经意的发现,当进行一次 HeroPersonality 的反序列化后再将原来的 HeroPersonality 再次序列化输出时惊奇的发现序列化后的 cost 字段多了一个 null,然后我就将反序列化代码放在循环里然后再次输出,发现 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 < 10; i++) {
String str1 = "{...}";
JSON.parseObject(str1, HeroPersonality.class);
}
System.out.println("dcs.config2:" + config.cost);
System.out.println("dcs.config2:" + config.attr_num);
结果输出:
这个结果让我惊喜,让我非常的肯定,cost 中的大量 null 就是这样产生的, 而且我最早就怀疑 HeroPersonality 中有一些非序列化的 get 方法有一些问题; 而同样的 attr_num 也是 JSONArray 类型,就没有任何问题。问题初步锁定在 HeroPersonality 中的一个 get 方法。
分析问题 3-- 源代码跟踪
需要源代码 debug,为什么在不断的调用反序列化的时候,cost 被加入了大量的 null,下面这个是 HeroPersonality 的两个 get 方法,可以看到其中的 getNextTrainCost 调用了 getConfig 字段 cost 字段, 下面从源代码 debug 的角度看一下为什么会每次反序列化都多了很多 null。
首先 getNextTrainCost 这个 getter 中的 nextTrainCost 被当成了一个 field,因为其返回值是一个 JSONArray, 其本身是可以作为 setter 用到的,其反序列化,用 json 中 “nextTrainCost” 相关反序列化,该字符串是 [{“[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-hja6Mr2Y-1652276408224)(https://mmbiz.qpic.cn/mmbiz_svg/1gvL9ficRs1HvicqCeX28m7Ganto5dXmIqhFFRgHSVLEscFZdKvhyuQ5vs05Qtcico140b6zriay1hawQ0hR6SS1sOpfFaadyZRL/640?wx_fmt=svg)].config.cost[0]”} 即使用了 fastjson 的循环引用, 这个反序列化出来为 [null] (因为本身 config 压根就不属于 field, 只是一个 get 方法而已),然后调用 setter(本身就是一个 setter), 得到 cost, 然后将这个 [null] add 到 cost 上。然后每反序列化一次都向 cost 中加入一个 [null], 进而使 cost 越来越大 (JSONArray# 底层数组还会自动 expand):
public JSONArray getNextTrainCost() {
return ((PersonalityStrengthenConfig) getConfig()).cost;
}
@Override
public DataConfigItem getConfig() {
return DataConfigService.getSettingById(PersonalityStrengthenConfig.class,
personalityLevel);
}
反序列化 nextTrainCost:
// FieldDeserializer#setValue 其中method就是getNextTrainCost() 即获取方法的返回值然后加了一个null
Collection collection = (Collection) method.invoke(object);
if (collection != null) {
collection.addAll((Collection) value);
}
分析问题 4-- 问题初步总结
第一个问题出在了 HeroPersonality 中的 getNextTrainCost 方法引用了 getConfig 中的 cost,导致在反序列化的时候每次会将 json#nextTrainCost 中反序列化出来的 JSONArray#add 到 cost 上 (相当于调用了 setter 方法)。注意即使 json#nextTrainCost 不是循环引用 (fastjson 可关闭), 即值就是引用的 config#cost 值, 则每次反序列化一样也会将反序列化出来的 JSONArray#add 到 cost,只不过这次不会是 null 而已。
第二个问题是最开始提到的我们正常序列化的时候就要带上 IgnoreNonFieldGetter 这个参数,不要将非 field 的 get 方法给序列化上去。加上参数后,序列化后的 json 就没有 nextTrainCost 了, 那么也就不会有反序列化的问题了,因为压根就扫描不到,当然 HeroPersonality 这个 getNextTrainCost 也比较奇葩,用了引用的方式,其实完全没有必要,可以考虑干掉。
为什么 cost 会那么大?
刚才我们已经基本肯定是因为错误模式下的反序列化会导致 cost 字段会越来越大,那么也不至于上亿次吧?这个我大概查了一下代码,很大几率是好友推荐模块和相关模块,相关代码需要较频繁的对于离线镜像反序列化,或者存在类似心跳业务处理。解决办法很简单,就是一定要记住 fastjson 序列化的时候要加上 IgnoreNonFieldGetter 就可以了。
作者:landon30
链接:https://www.jianshu.com/p/876d443c2162
来源:简书