jvm频繁full gc问题排查

飞行的大狗
6,613 阅读6分钟

线上案例 1

频繁full gc的场景

先聊聊哪些场景会导致频繁Full GC：

  1. 内存泄漏（代码有问题，对象引用没及时释放，导致对象不能及时回收）。
  2. 死循环。
  3. 大对象。 尤其是大对象，80%以上的情况就是他。 那么大对象从哪里来的呢？
  4. 数据库（包括MySQL和MongoDB等NoSQL数据库），结果集太大。
  5. 第三方接口传输的大对象。
  6. 消息队列，消息太大。

绝大部分情况是数据库大结果集导致。

在没有任何发布的情况下，系统突然报警，疯狂fullgc，观察堆内存监控没内存泄漏，回滚到前一版本，问题仍然存在。

一方面一个人去看系统监控，一个人去jmap导出堆内存快照（jmap -dump:format=b,file=文件名 [pid]）然后用mat等工具分析出什么对象占用了大量空间，再查看相关引用找到问题代码。这种方式定位问题周期会比较长，如果是关键服务，长时间不能定位解决问题，影响太大。

为了进一步排查原因，我们在线上开启了 -XX:+HeapDumpBeforeFullGC在其中一台机子上开启了 -XX:HeapDumpBeforeFullGC，总体JVM参数如下：

-Xmx2g
-XX:+HeapDumpBeforeFullGC
-XX:HeapDumpPath=.
-Xloggc:gc.log
-XX:+PrintGC
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=10
-XX:GCLogFileSize=100m
-XX:HeapDumpOnOutOfMemoryError

注意：JVM 在执行 dump操作的时候是会发生 stop the word事件的，也就是说此时所有的用户线程都会暂停运行。为了在此期间也能对外正常提供服务，建议采用分布式部署，并采用合适的负载均衡算法

  • top：找到占用内存(RES列)高的Java进程PID。

  • jmap -heap PID：查看heap内存使用情况。

打印一个堆的摘要信息，包括使用的GC算法、堆配置信息和各内存区域内存使用信息

C:\Users\jjs>jmap -heap 5932
Attaching to process ID 5932, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.91-b15

using thread-local object allocation.
Parallel GC with 4 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 1073741824 (1024.0MB)
   NewSize                  = 42991616 (41.0MB)
   MaxNewSize               = 357564416 (341.0MB)
   OldSize                  = 87031808 (83.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 60293120 (57.5MB)
   used     = 44166744 (42.120689392089844MB)
   free     = 16126376 (15.379310607910156MB)
   73.25337285580842% used
From Space:
   capacity = 5242880 (5.0MB)
   used     = 0 (0.0MB)
   free     = 5242880 (5.0MB)
   0.0% used
To Space:
   capacity = 14680064 (14.0MB)
   used     = 0 (0.0MB)
   free     = 14680064 (14.0MB)
   0.0% used
PS Old Generation
   capacity = 120061952 (114.5MB)
   used     = 19805592 (18.888084411621094MB)
   free     = 100256360 (95.6119155883789MB)
   16.496143590935453% used

20342 interned Strings occupying 1863208 bytes.

  • jps -lv ：查看JVM参数配置。

  • jstat -gc PID 1000：收集每秒堆的各个区域具体占用大小的gc信息。

image.png

  • jmap -dump:live,format=b,file=heap_dump.hprof PID ：导出堆文件。

  • 使用MAT打开堆文件，分析问题。

一方面去查业务监控，db,redis 等信息看看是否出现异常

如果数据库服务器网络IO有明显上升，并且时间点吻合，基本可以确定是数据库大结果集导致了Full GC，赶紧找DBA快速定位大SQL（对DBA来说很简单，分分钟搞定，如果DBA不知道怎么定位，那他要被开除了，哈哈），定位到SQL后再定位代码就非常简单了。

按照这种办法，我们很快定位了问题。原来是一个接口必传的参数没传进来，也没加校验，导致SQL语句where后面少了两个条件，一次查几万条记录出来，真坑啊！这种方法是不是要快很多，哈哈，5分钟搞定

这个原因是数据库存了设备的cid(每个用户下载一个app标识)，查询的时候的有的设备cid没有，数据很多数据也没存，查询的时候导致一下子查出来几万条空的cid数据。

线上案例 2 内存泄漏

介绍案例前，先了解一下内存泄漏和内存溢出的区别。

内存溢出：程序没有足够的内存使用时，就会发生内存溢出。内存溢出后程序基本上就无法正常运行了。

内存泄漏：当程序不能及时释放内存，导致占用内存逐渐增加，就是内存泄漏。内存泄漏一般不会导致程序无法运行。不过持续的内存泄漏，累积到内存上限时，就会发生内存溢出。在Java中，如果发生内存泄漏，会导致GC回收不彻底，每次GC后，堆内存使用率逐渐增高。

下图是JVM发生内存泄漏的监控图，我们可以看到每次GC后堆内存使用率都比以前提高了：

当时内存泄漏的场景是，用本地缓存（公司基础架构组自己研发的框架）存放了商品数据，商品数量不算太多，几十万的样子。如果只存热点商品，内存占用不会太大，但是如果存放全量商品，内存就不够了。

初期我们给每个缓存记录都加了7天的过期时间，这样就可以保证缓存中绝大部分都是热点商品。不过后来本地缓存框架经过一次重构，过期时间被去掉了。没有了过期时间，日积月累本地缓存越来越大，很多冷数据也被加载到了缓存。

直到有一天接到告警短信，提示堆内存过高。赶紧通过jmap（jmap -dump:format=b,file=文件名 [pid] ）下载了堆内存快照，然后用eclipse的mat工具分析快照，发现了本地缓存中有大量的商品记录。定位问题后赶紧让架构组加上了过期时间，然后逐个节点重启了服务。

亏了我们加了服务器内存和JVM堆内存监控，及时发现了内存泄漏的问题。否则随着泄漏问题日积月累，如果哪天真的OOM就惨了。

所以技术团队除了做好CPU，内存等运维监控，JVM监控也非常重要

avatar
文章
阅读
粉丝