Javaで発生したOOMの原因をGCログとヒープダンプから探る
javaGCログの可視化
- -Xloggc:/tmp/gc.log
- -XX:+PrintGCDetails
- -XX:+PrintGCDateStamps
で次のようなGCのログが出力される。
$ cat /tmp/gc.log
2022-08-08T16:35:30.738+0000: [GC (Allocation Failure) [PSYoungGen: 638269K->3108K(665600K)] 2017703K->1382542K(2063872K), 0.0084360 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
2022-08-08T16:35:31.320+0000: [GC (Allocation Failure) [PSYoungGen: 640548K->2565K(666624K)] 2019982K->1382000K(2064896K), 0.0086070 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
2022-08-08T16:35:31.878+0000: [GC (Allocation Failure) [PSYoungGen: 640005K->2565K(667136K)] 2019440K->1382000K(2065408K), 0.0086495 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
2022-08-08T16:35:32.451+0000: [GC (Allocation Failure) [PSYoungGen: 643589K->3301K(668672K)] 2023024K->1382736K(2066944K), 0.0087513 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
GCViewerでこのファイルを開くと次のようなグラフが描画される。 上部がNew領域、下部がOld領域を表し、Old領域の使用量である紫の線が一杯になると黒い線のFull GCが走り、ヒープ使用量の合計である青い線も下がっている。 この例では徐々にGCでの減り分が少なくなっていき、後半はほとんど真っ黒なので常にFull GCが発生していることが分かる。
JVMのヒープ領域とFull GC - sambaiz-net
Full GC対策としては -XX:NewRatio で New領域の大きさを変えたり、 -XX:+UseG1GC で性能の良いG1GCにして -XX:InitiatingHeapOccupancyPercent でGC開始の閾値を下げるというものがあるが、 今回はそもそもメモリが足りてないように見える。ひょっとするとメモリリークしているのかもしれない。
ヒープダンプの分析
そこで
- -XX:+HeapDumpOnOutOfMemoryError
- -XX:HeapDumpPath=/tmp
でOOM時にヒープダンプを出してEclipse Memory Analyzer (MAT)で見てみる。
Leak Suspectsに明らかに問題がありそうなオブジェクトがなければ -Xms, -Xmx でヒープメモリを増やすしかなさそうだ。