#kryo的Input读取字符串导致的FullGC问题
昨天某线上项目策划反馈有一个服卡顿，请求响应时间特别长，经过长时间排查发现起因是Kryo解码时读取字符串导致产生一个1.2G大小的char数组，撑爆了堆内存，现将排查过程和结果做一次总价，与大家分享，如果表述或者认知有误的地方，请谅解。

top

使用top命令查看当前进程使用cpu及其内存情况

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
top - 20:29:36 up 20 days,  6:22,  7 users,  load average: 1.30, 0.93, 0.94
Tasks: 247 total,   2 running, 245 sleeping,   0 stopped,   0 zombie
Cpu(s):  9.7%us,  7.9%sy,  0.0%ni, 82.1%id,  0.3%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  33014168k total, 32776124k used,   238044k free,   296344k buffers
Swap:        0k total,        0k used,        0k free, 19029888k cached
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
44778 root      20   0  9.8g 4.3g  16m S 100.8 13.5   1023:04 java
45397 root      20   0 9928m 3.5g  15m S 41.5 11.1 861:14.65 java   
 2950 root      20   0 1235m  14m 3148 S  4.0  0.0  28:00.31 falcon-agent
 3023 root       0 -20  126m  12m 5736 S  2.0  0.0  90:53.61 AliYunDun 
56487 root      20   0 15148 1344  896 R  2.0  0.0   0:00.01 top
    1 root      20   0 19232 1116  844 S  0.0  0.0   0:02.08 init
    2 root      20   0     0    0    0 S  0.0  0.0   0:00.00 kthreadd 
    3 root      RT   0     0    0    0 S  0.0  0.0   0:00.87 migration/0
    4 root      20   0     0    0    0 S  0.0  0.0   1:56.02 ksoftirqd/0

可以看出两个java程序使用cpu的比例相差一倍，本质上连个java进程应该是一样的，所以出判断44778java进程cpu使用异常。
而内存已经达到预设内存最大值。

jstat

使用jstat -gcutil 44778 1000 查看jvmgc情况

1
2
3
4
5
6
7
8
9
10
[root@zlzz_game_aliyun_0036 zlzz_ad_tanwan_s1067]# jstat -gcutil 44778 1500
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
 47.45   0.00 100.00  71.56  91.57  87.05   1949  323.409   970 4013.507 4336.917
 47.45   0.00 100.00  71.56  91.57  87.05   1949  323.409   970 4013.507 4336.917
  0.00   0.00  96.43  71.56  91.57  87.05   1949  323.409   970 4018.109 4341.518
  0.00   0.00  98.08  71.56  91.57  87.05   1949  323.409   970 4018.109 4341.518
  0.00   0.00  99.63  71.56  91.57  87.05   1949  323.409   970 4018.109 4341.518
  0.00  41.48 100.00  71.56  91.57  87.05   1950  323.724   971 4018.109 4341.833
  0.00  41.48 100.00  71.56  91.57  87.05   1950  323.724   971 4018.109 4341.833
  0.00  41.48 100.00  71.56  91.57  87.05   1950  323.724   971 4018.109 4341.833

这里非常明显可以看到YGC非常频繁，并且每一次YGC都伴随着一次FGC

到这里排查方向初步可以确定内存泄露

jvm gc日志

启动jvm时通过添加以下参数可以打印出jvmgc日志

1
-verbose:gc -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:../logs/sgc.log

日志内容节选

1
2
3
4
5
6
7
2019-07-31T18:20:11.343+0800: 115549.005: [GC (Allocation Failure) 2019-07-31T18:20:11.343+0800: 115549.005: [ParNew (promotion failed): 1258368K->1280669K(1415616K), 0.2792052 secs]2019-07-31T18:20:11.622+0800: 115549.284: [CMS: 1902520K->1902459K(2621440K), 4.7985543 secs] 3160883K->3062259K(4037056K), [Metaspace: 61116K->61116K(1107968K)], 5.0779956 secs] [Times: user=6.68 sys=0.00, real=5.08 secs] 
2019-07-31T18:20:21.075+0800: 115558.738: [GC (Allocation Failure) 2019-07-31T18:20:21.075+0800: 115558.738: [ParNew (promotion failed): 1258368K->1282096K(1415616K), 0.2835357 secs]2019-07-31T18:20:21.359+0800: 115559.021: [CMS: 1902466K->1902449K(2621440K), 4.9184284 secs] 3160827K->3062303K(4037056K), [Metaspace: 61116K->61116K(1107968K)], 5.2021565 secs] [Times: user=6.84 sys=0.00, real=5.20 secs] 
2019-07-31T18:20:30.946+0800: 115568.608: [GC (Allocation Failure) 2019-07-31T18:20:30.946+0800: 115568.608: [ParNew (promotion failed): 1258368K->1281630K(1415616K), 0.3006928 secs]2019-07-31T18:20:31.246+0800: 115568.909: [CMS: 1902457K->1902441K(2621440K), 4.8921319 secs] 3160817K->3062312K(4037056K), [Metaspace: 61117K->61117K(1107968K)], 5.1930185 secs] [Times: user=6.92 sys=0.00, real=5.19 secs] 
2019-07-31T18:20:37.771+0800: 115575.433: [GC (Allocation Failure) 2019-07-31T18:20:37.771+0800: 115575.433: [ParNew (promotion failed): 1258368K->1280899K(1415616K), 0.2869167 secs]2019-07-31T18:20:38.058+0800: 115575.720: [CMS: 1902455K->1902428K(2621440K), 4.9883430 secs] 3160809K->3062284K(4037056K), [Metaspace: 61124K->61124K(1107968K)], 5.2754469 secs] [Times: user=6.99 sys=0.00, real=5.28 secs] 
2019-07-31T18:20:47.878+0800: 115585.540: [GC (Allocation Failure) 2019-07-31T18:20:47.878+0800: 115585.540: [ParNew (promotion failed): 1258368K->1284016K(1415616K), 0.2894573 secs]2019-07-31T18:20:48.167+0800: 115585.830: [CMS: 1902435K->1902427K(2621440K), 4.4373591 secs] 3160796K->3062320K(4037056K), [Metaspace: 61132K->61132K(1107968K)], 4.7270053 secs] [Times: user=6.40 sys=0.00, real=4.73 secs] 
2019-07-31T18:20:52.609+0800: 115590.271: [GC (Allocation Failure) 2019-07-31T18:20:52.609+0800: 115590.271: [ParNew (promotion failed): 1162012K->1183594K(1415616K), 0.2559134 secs]2019-07-31T18:20:52.865+0800: 115590.527: [CMS: 1902434K->1902428K(2621440K), 4.8502115 secs] 3064440K->3062417K(4037056K), [Metaspace: 61139K->61139K(1107968K)], 5.1062855 secs] [Times: user=6.78 sys=0.00, real=5.10 secs] 
2019-07-31T18:20:57.715+0800: 115595.377: [Full GC (Allocation Failure) 2019-07-31T18:20:57.715+0800: 115595.377: [CMS: 1902428K->1902425K(2621440K), 4.3079877 secs] 3062417K->3062313K(4037056K), [Metaspace: 61139K->61139K(1107968K)], 4.3084721 secs] [Times: user=4.31 sys=0.00, real=4.31 secs]

可以看到gc原因是内存申请失败，但是gc过程中又发生了promotion failed

关于promotion failed的说明

1
2
3
发生promtion failed的原因是发生young gc的时候，eden区和survior区的from块里面存活的对象要复制到survior区的to块里面。
如果to块满了，那么yong gc的悲观策略将使还存活的对象移到old 区。
但是此时 old区也满了，对象放不进去，于是导致promtiom failed了

于是这里的疑问就是eden区为何会产生这么多内存需要回收，并且达到survivor都放不下？
该项目，线上已经开服超过150个，其他服从未出现过类似问题，说明整体内存使用是稳定的。

此时应该分析此进程内存情况了。

jmap + Eclipse Memory Analyzer

jmap

使用jmap dump当前jvm的堆

1
jmap -dump:format=b,file=47788.dump 44778

Eclipse Memory Analyzer
使用Eclipse Memory Analyzer打开dump文件，通过对象内存视图可以看到占用内存最大的是GameMap，这是正常的.
然后内存占用第二的居然是一个char数据，足有1.2G，此处存疑。
基于查看该char的gc路径，发现持有char的是KryoInput实例。

KryoInput

KryoInput读取字符串的时候，会通过一个char数组把待读数据保存下下来，然后转换成String

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
public String readString() {
	int available = require(1);
	int b = buffer[position++];
	if ((b & 0x80) == 0)
		return readAscii(); // ASCII.
	// Null, empty, or UTF8.
	int charCount = available >= 5 ? readUtf8Length(b) : readUtf8Length_slow(b);
	switch (charCount) {
	case 0:
		return null;
	case 1:
		return "";
	}
	charCount--;
	if (chars.length < charCount)
		chars = new char[charCount];
	readUtf8(charCount);
	return new String(chars, 0, charCount);
}

分析改代码片段，发现存在两个问题

  • 无条件相信字符串长度
  • 由于KryoInput是通过ThreadLocal来实现线程公用的，所以KryoInput是常驻内存，然而这里使用完char之后，并没有释放char数组

以上两个问题就导致最终线上服务器不断FullGC而性能极端下降，具体分析如下：

  • 客户端发送过的的字符串长度和字符串实际长度不一致，导致我们读取字符串的时候，创建了一个大小约为1.2G大小的char数组
  • 由于读取完毕后char数组没有释放，导致内存一直常驻
  • eden区一下多了一个1.2G内存的变量，当然可用空间被大大压缩，于是不停YGC
  • 然而1.2G的变量实在太大，survivor放不下，于是直接放入old区
  • 但是old区也放不下1.2G的对象，于是触发FullGc
  • 最最后，这些GC并不能腾出一个能放下1.2G对象的空间，所以往复循环，一直GC。。

解决方案

1、kryo读取字符串的时候需要对长度做判断，不能超过消息字节的最大长度
2、char数组使用需要释放（这个可能还需要讨论，释放后就不能复用char数组了，每次都要重建）