现象
最近接手了一个同事的项目,某一天接口的响应耗时突然增加了很多,由几十ms 增加到了几十秒。
首先查看机器上的日志,有调用第三方接口超时,查询数据库超时。立马查看第三方接口监控和数据库监控,一切正常。可能由于 GC 停顿造成统计的超时,这个时候我们通过 jstat -gcutil pid 查看 gc 情况。数据如下:
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 0.00 3.88 12.86 76.39 45.62 211 8.574 892 626.192 634.767
0.00 0.00 4.10 12.86 76.39 45.62 211 8.574 893 626.192 634.767
0.00 0.00 0.00 12.88 76.39 45.62 211 8.574 894 626.915 635.489
0.00 0.00 0.11 12.88 76.39 45.62 211 8.574 896 627.678 636.253
0.00 0.00 0.00 12.87 76.39 45.62 211 8.574 897 628.926 637.500
0.00 0.00 0.00 12.87 76.39 45.62 211 8.574 899 630.381 638.956
0.00 0.00 1.92 12.87 76.39 45.62 211 8.574 901 631.155 639.729
0.00 0.00 0.00 12.87 76.39 45.62 211 8.574 902 632.379 640.954
0.00 0.00 2.14 12.87 76.39 45.62 211 8.574 903 633.094 641.668
0.00 0.00 0.00 12.88 76.39 45.62 211 8.574 904 633.859 642.433
复制代码
这里我们可以看到年轻代(E) 使用率很小,老年代(O)使用率 12% 也不多,M(Metaspace) 使用率 76.39% 也没占满,Yong GC 没有变化,Full GC 一直在进行,每次耗时800多ms。结合前面 E、O 和 M 使用率都没有变化,说明内存一直回收不掉。
JVM 内存大小相关配置如下:
-Xms3g -Xmx3g -Xmn1g -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m
复制代码
接下来我们看下 GC 日志:
2020-08-13T23:11:00.352+0800: 214929.371: [GC (CMS Initial Mark) 276144K(3040896K), 0.0405942 secs]
2020-08-13T23:11:00.886+0800: 214929.905: [Full GC (Metadata GC Threshold) 290482K->275966K(3040896K), 0.7939954 secs]
2020-08-13T23:11:01.693+0800: 214930.712: [Full GC (Last ditch collection) 275966K->275964K(3040896K), 0.8086755 secs]
2020-08-13T23:11:02.520+0800: 214931.539: [Full GC (Metadata GC Threshold) 295199K->273816K(3040896K), 0.8332017 secs]
2020-08-13T23:11:03.366+0800: 214932.385: [Full GC (Last ditch collection) 273816K->273799K(3040896K), 0.7748226 secs]
复制代码
GC 日志中有 Metadata GC Threshold ,结合前面 Metaspace 使用率最高我们猜测可能是 Metaspace 溢出了,然后我们在日志中 grep OutOfMemory 关键字,有如下报错:
java.lang.OutOfMemoryError: Metaspace
复制代码
至此可以确认是 Metaspace 出问题了,但是为什么 jstat 输出的使用率只有 76.39% 呢?大家如果经常使用 jstat 看一下正常的程序就会很