记一次线上OOM排查及调优过程

通过异常邮件，发现线上定时任务服务产生了OOM： java.lang.OutOfMemoryError: Java heap space

发现异常后，先重启线上服务，然后把未执行的定时任务恢复。

查看gc信息，发现项目启动没多久，平均200秒一次FullGC
 

> jstat -gcutil 6
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00  25.85  66.86  16.12  94.99  92.71    932   11.408    34   24.540   35.947
  
> jcmd 6 VM.uptime
6:
6877.407 s

查看内存信息，发现年轻代只有230m，而且占用非常高
 

> jcmd 6 GC.heap_info
6:
 def new generation   total 235968K, used 170108K [0x00000000d0000000, 0x00000000e0000000, 0x00000000e0000000)
  eden space 209792K,  77% used [0x00000000d0000000, 0x00000000d9f83a68, 0x00000000dcce0000)
  from space 26176K,  25% used [0x00000000de670000, 0x00000000ded0b668, 0x00000000e0000000)
  to   space 26176K,   0% used [0x00000000dcce0000, 0x00000000dcce0000, 0x00000000de670000)
 tenured generation   total 524288K, used 84496K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000)
   the space 524288K,  16% used [0x00000000e0000000, 0x00000000e5284118, 0x00000000e5284200, 0x0000000100000000)
 Metaspace       used 126246K, capacity 132522K, committed 132904K, reserved 1167360K
  class space    used 14759K, capacity 15854K, committed 15920K, reserved 1048576K

查看VM参数，发现MaxHeapSize只有805306368byte/1024/1024=768M
很明显，堆内存设置小了

jcmd 6 VM.flags
6:
-XX:CICompilerCount=2 -XX:InitialHeapSize=50331648 -XX:MaxHeapSize=805306368 -XX:MaxNewSize=268435456 -XX:MinHeapDeltaBytes=196608 -XX:NewSize=16777216 -XX:OldSize=33554432 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops

在预发布环境进行调参
调整启动参数，增加堆内存到2G，增加GC日志，设置OOM时导出堆内存

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=... -XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -verbose:gc -Xloggc:... -Xms2G -Xmx2G

项目启动后，查看内存信息, 年轻代614M，应该够用

> jcmd 6 GC.run
6:
Command executed successfully
> jcmd 6 GC.heap_info
6:
 def new generation   total 629120K, used 13644K [0x0000000080000000, 0x00000000aaaa0000, 0x00000000aaaa0000)
  eden space 559232K,   2% used [0x0000000080000000, 0x0000000080d530d0, 0x00000000a2220000)
  from space 69888K,   0% used [0x00000000a6660000, 0x00000000a6660000, 0x00000000aaaa0000)
  to   space 69888K,   0% used [0x00000000a2220000, 0x00000000a2220000, 0x00000000a6660000)
 tenured generation   total 1398144K, used 49997K [0x00000000aaaa0000, 0x0000000100000000, 0x0000000100000000)
   the space 1398144K,   3% used [0x00000000aaaa0000, 0x00000000adb737e0, 0x00000000adb73800, 0x0000000100000000)
 Metaspace       used 86540K, capacity 90342K, committed 90496K, reserved 1128448K
  class space    used 10635K, capacity 11343K, committed 11392K, reserved 1048576K

项目启动后，查看gc信息，发现有4次FullGC，除去上面手动触发的FullGC，推测项目启动过程中发生了3次FullGC，很奇怪

> jstat -gcutil 6
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00   0.00  13.14   3.58  95.62  93.36      5    0.142     4    0.563    0.705

查看GC日志, 3次FullGC发生的时间2022-03-28T16:50:11，2022-03-28T16:50:15，2022-03-28T16:50:22，而且每次都是Metadata空间不足引发的

fgrep Full gc.log
2022-03-28T16:50:11.280+0800: 3.307: [Full GC (Metadata GC Threshold) 2022-03-28T16:50:11.280+0800: 3.307: [Tenured: 0K->8152K(1398144K), 0.0883040 secs] 536878K->8152K(2027264K), [Metaspace: 20515K->20515K(1069056K)], 0.0883757 secs] [Times: user=0.09 sys=0.00, real=0.09 secs]
2022-03-28T16:50:15.447+0800: 7.474: [Full GC (Metadata GC Threshold) 2022-03-28T16:50:15.447+0800: 7.474: [Tenured: 8152K->16623K(1398144K), 0.0895848 secs] 291984K->16623K(2027264K), [Metaspace: 34153K->34153K(1081344K)], 0.0896720 secs] [Times: user=0.09 sys=0.00, real=0.08 secs]
2022-03-28T16:50:22.017+0800: 14.044: [Full GC (Metadata GC Threshold) 2022-03-28T16:50:22.017+0800: 14.044: [Tenured: 16623K->33960K(1398144K), 0.1533989 secs] 510804K->33960K(2027264K), [Metaspace: 56634K->56634K(1101824K)], 0.1534892 secs] [Times: user=0.15 sys=0.01, real=0.15 secs]
2022-03-28T16:53:18.692+0800: 190.719: [Full GC (System.gc()) 2022-03-28T16:53:18.692+0800: 190.719: [Tenured: 33960K->49997K(1398144K), 0.2315362 secs] 477467K->49997K(2027264K), [Metaspace: 86536K->86536K(1128448K)], 0.2316727 secs] [Times: user=0.21 sys=0.00, real=0.23 secs]

查看日志，发现3次FullGC的时间在项目启动过程中发生的，符合上述推断

2022-03-28 16:50:11.575  INFO SpringBootBanner Line:62 [||||] -  :: Spring Boot ::        (v2.2.5.RELEASE)
.
.
.
2022-03-28 16:50:29.669  INFO Application Line:61 [||||] - Started JobAdminApplication in 20.655 seconds (JVM running for 21.696)

3次FullGC都是Metadata不足引发的，说明初始Metadata太小了，发生了3次扩容
那么应该增加初始Metaspace大小
查看内存，发现Metaspace大小为89m，因此设置初始Metaspace大小为90M，可以避免启动过程中的FullGC

> jcmd 6 GC.heap_info
6:
 def new generation   total 629120K, used 256799K [0x0000000080000000, 0x00000000aaaa0000, 0x00000000aaaa0000)
  eden space 559232K,  45% used [0x0000000080000000, 0x000000008fac7fc8, 0x00000000a2220000)
  from space 69888K,   0% used [0x00000000a6660000, 0x00000000a6660000, 0x00000000aaaa0000)
  to   space 69888K,   0% used [0x00000000a2220000, 0x00000000a2220000, 0x00000000a6660000)
 tenured generation   total 1398144K, used 49997K [0x00000000aaaa0000, 0x0000000100000000, 0x0000000100000000)
   the space 1398144K,   3% used [0x00000000aaaa0000, 0x00000000adb737e0, 0x00000000adb73800, 0x0000000100000000)
 Metaspace       used 87689K, capacity 91522K, committed 91776K, reserved 1130496K
  class space    used 10638K, capacity 11347K, committed 11392K, reserved 1048576K

增加参数 -XX:MetaspaceSize=90m，重启服务，查看gc和内存
启动过程中没有发生FullGC

> jstat -gcutil 6
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00  57.06  83.22   0.49  95.57  93.31      7    0.400     0    0.000    0.400
> jcmd 6 VM.uptime
6:
48.879 s
> jcmd 6 GC.heap_info
6:
 def new generation   total 629120K, used 545143K [0x0000000080000000, 0x00000000aaaa0000, 0x00000000aaaa0000)
  eden space 559232K,  90% used [0x0000000080000000, 0x000000009ed6ba70, 0x00000000a2220000)
  from space 69888K,  57% used [0x00000000a6660000, 0x00000000a8d52478, 0x00000000aaaa0000)
  to   space 69888K,   0% used [0x00000000a2220000, 0x00000000a2220000, 0x00000000a6660000)
 tenured generation   total 1398144K, used 6802K [0x00000000aaaa0000, 0x0000000100000000, 0x0000000100000000)
   the space 1398144K,   0% used [0x00000000aaaa0000, 0x00000000ab144820, 0x00000000ab144a00, 0x0000000100000000)
 Metaspace       used 85629K, capacity 89366K, committed 89728K, reserved 1128448K
  class space    used 10596K, capacity 11273K, committed 11392K, reserved 1048576K

至此，此次OOM和调优完成