记录一次pre环境OOM异常解决过程

问题发现

部署在客户机器上的程序经常发生OOM异常:java.lang.OutOfMemoryError: GC overhead limit exceeded。

初步排查

1、系统本身代码问题；
2、系统大量调用了第三方接口http超时或者被第三方服务超量调用；
3、机器问题；
这个程序的主要作用就是拉取kafka里的消息落地到mysql，外加两个kafka消息写入及堆积的监控接口，不涉及到被其它系统调用或调用第三方接口；走查程序代码及日志，也没有发现明显的会出现死循环之类的bug和错误日志；查看机器的tcp状态也是正常的。

开始解决

1、使用top命令查看CPU情况发现8核CPU几乎被打满，发现是进程pid=32024导致；

2、查看进程pid=32024对应的服务：ps -ef |grep 32024，确认过眼神，是我的那个java程序进程，程序使用nohup java -Xms2048m -Xmx2048m -jar ×××.jar >/dev/null 2>&1 &命令启动的；

3、查看pid=32024进程的线程情况：top -Hp 32024

发现pid=32031/32027/32032/32029/32034/32030/32028/32033均占用了90%以上的CPU，把这几个十进制数抓换成十六进制表示(直接在linux上执行printf “%x\n” 32031)，得到7d1f……

4、使用jstack打印线程堆栈日志，查找cpu耗时最多的线程，输出到根目录下的32024.txt文本里：jstack -l 32024 > /32024.txt，我这里只截取了最后的几行日志

"VM Thread" os_prio=0 tid=0x00007fb3281c6800 nid=0x7d23 runnable
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fb32801e000 nid=0x7d1b runnable
"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fb32801f800 nid=0x7d1c runnable
"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007fb328021800 nid=0x7d1d runnable
"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007fb328023800 nid=0x7d1e runnable
"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x00007fb328025000 nid=0x7d1f runnable
"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x00007fb328027000 nid=0x7d20 runnable
"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x00007fb328028800 nid=0x7d21 runnable
"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x00007fb32802a800 nid=0x7d22 runnable
"VM Periodic Task Thread" os_prio=0 tid=0x00007fb328236800 nid=0x7d2c waiting on condition
JNI global references: 2869

发现nid=0x~，对应的就是步骤三得到的占用线程pid，也就是说大量的GC动作导致了程序变慢，最后OOM

5、使用jstat查看进程32024的内存占用情况：jstat -gcutil 32024 1s 5，间隔1秒打印一次，共5次

  S0      S1     E     O      M      CCS     YGC   YGCT   FGC    FGCT         GCT   0.00   0.00 100.00  99.98  94.79  91.73   2132   22.344 18637 22794.374 22816.7190.00   0.00 100.00  99.98  94.79  91.73   2132   22.344 18637 22794.374 22816.7190.00   0.00 100.00  99.98  94.79  91.73   2132   22.344 18638 22795.902 22818.2470.00   0.00 100.00  99.98  94.79  91.73   2132   22.344 18639 22797.042 22819.3870.00   0.00 100.00  99.98  94.79  91.73   2132   22.344 18640 22798.052 22820.396

发现Eden、Survivor、老年代空间占用比例近100%，GC的次数和时间也比较高

6、使用jmap查看进程32024里占用的对象情况：jamp -histo 32024，我这里截取占用内存最多的部分日志

num     #instances         #bytes  class name
----------------------------------------------1:         60659      879225944  [B2:       2569438      194899192  [C3:       1791132      108050840  [Ljava.util.HashMap$Node;4:       3355102      107363264  java.util.HashMap$Node5:       2604306      104172240  java.util.LinkedHashMap$Entry6:       1467554       82183024  java.util.LinkedHashMap7:       2568223       61637352  java.lang.String8:       1041842       46497648  [Ljava.lang.Object;9:       1248847       39963104  java.util.concurrent.ConcurrentHashMap$Node10:          9415       33631640  [J11:        923899       29564768  org.apache.kafka.common.MetricName12:        923899       29564768  org.apache.kafka.common.metrics.KafkaMetric13:       1191788       28602912  org.apache.kafka.common.requests.ApiVersionsResponse$ApiVersion14:       1031412       24753888  java.util.ArrayList15:        445931       21404688  java.util.HashMap16:        425192       17007680  io.micrometer.core.instrument.Meter$Id17:        258692       16556288  org.apache.kafka.common.metrics.Sensor18:        926570       14825120  java.util.LinkedHashMap$LinkedEntrySet19:        304886       14634528  org.apache.kafka.common.metrics.stats.SampledStat$Sample20:         37121       14036960  [Ljava.util.concurrent.ConcurrentHashMap$Node;21:        295803       11832120  io.micrometer.shaded.org.pcollections.IntTree22:        296597        9491104  java.lang.ref.WeakReference23:        295803        9465696  io.micrometer.shaded.org.pcollections.ConsPStack24:        295712        9462784  io.micrometer.core.instrument.binder.kafka.KafkaConsumerMetrics$$Lambda$1382/119056635725:        286409        9165088  org.apache.kafka.common.metrics.stats.Meter26:        559525        8952400  java.lang.Object27:        258692        8278144  org.apache.kafka.common.MetricNameTemplate28:        305083        7321992  java.util.AbstractMap$SimpleImmutableEntry29:        286409        6873816  org.apache.kafka.common.metrics.stats.Rate30:        286409        6873816  org.apache.kafka.common.metrics.stats.Total31:        268050        6433200  io.micrometer.core.instrument.internal.DefaultGauge32:        304994        4879904  java.util.concurrent.atomic.AtomicReference33:        147824        4730368  org.apache.kafka.common.metrics.stats.Avg34:        147824        4730368  org.apache.kafka.common.metrics.stats.Rate$SampledTotal35:        194215        4661160  javax.management.ObjectName$Property36:        166470        4439320  [Ljavax.management.ObjectName$Property;37:        138585        4434720  org.apache.kafka.common.metrics.stats.Count38:        138584        4434688  org.apache.kafka.common.metrics.stats.Max39:        258692        4286896  [Lorg.apache.kafka.common.metrics.Sensor;40:        261683        4186928  java.util.LinkedHashSet41:         83235        3329400  javax.management.ObjectName42:         15980        3243304  [I43:         27735        3106320  sun.nio.ch.SocketChannelImpl44:        129380        3105120  io.micrometer.core.instrument.MeterRegistry$$Lambda$348/31955832745:        129380        3105120  io.micrometer.core.instrument.MeterRegistry$146:         37453        2396992  java.util.concurrent.ConcurrentHashMap47:        140245        2243920  java.util.LinkedHashMap$LinkedKeySet48:         46248        2219904  java.nio.HeapByteBuffer49:        129412        2070592  java.util.HashMap$EntrySet50:         83227        1997448  com.sun.jmx.mbeanserver.NamedObject51:        120943        1935088  java.util.LinkedHashMap$LinkedValues52:         73912        1773888  org.apache.kafka.common.metrics.JmxReporter$KafkaMbean53:         27717        1773888  org.apache.kafka.common.network.KafkaChannel54:         15256        1687808  java.lang.Class55:         27717        1552152  org.apache.kafka.clients.ClusterConnectionStates$NodeConnectionState56:         92963        1487408  java.util.HashSet57:         36954        1478160  org.apache.kafka.common.network.NetworkReceive58:          9239        1404328  org.apache.kafka.clients.consumer.internals.ConsumerCoordinator59:         42802        1369664  java.net.InetAddress$InetAddressHolder60:         55466        1331184  java.net.InetSocketAddress$InetSocketAddressHolder61:         55434        1330416  org.apache.kafka.common.utils.LogContext$LocationAwareKafkaLogger62:         37815        1210080  java.util.Hashtable$Entry63:          9239        1182592  org.apache.kafka.clients.consumer.internals.FetcherMetricsRegistry64:         27735        1109400  sun.nio.ch.SelectionKeyImpl65:         27735        1109400  sun.nio.ch.SocketAdaptor66:         27733        1109320  java.util.EnumMap

占用最多的是HashMap对象，存放大量KafkaConsumer里的Metric对象

7、基本上问题已经定位到了，走查代码发现：程序里有个获取kafka消息堆积量的接口，里面使用到了KafkaConsumer连接kafka，由于要统计的是多个topic，我们是在循环里每次用KafkaConsumer去连接的(KafkaMetric就是在KafkaConsumer对象里的)，每次连接完没有关闭KafkaConcumer连接，而且这个接口前端调用的比较频繁，导致大量KafkaConsumery引用一直存活，且越来越多(GCRoot可达)，修改代码后版本迭代，观察了几天没问题了。

8、为了直观一些的话，步骤6也可以直接dump程序的堆转储快照下来分析，用JAVA_HOME/bin/jvisualvm.exe可视化开分析，生成堆转储快照的命令是：jmap -dump:live,format=b,file=×××.dump 32024

其它相关

首先要正确区分内存溢出和内存泄露，这是两个不同的概念，本质上都是没有合理使用JVM导致。内存溢出是指虚拟机扩展无法申请到足够的内存(系统没有多余的内存可以分配给你)，内存泄露是指使用完内存空间没有释放，当内存中加载了太多对象，比如一次性从数据库中查询返回了太多对象、循环或者死循环创建太多对象且没有释放引用、jvm启动参数设置的过小……都有可能导致JVM内存泄露或溢出。