技术侦探日记 01 - FULL GC篇

Posted

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了技术侦探日记 01 - FULL GC篇相关的知识，希望对你有一定的参考价值。

参考技术A

众里寻他千百度，蓦然回首，还是垃圾回收；内存占用过高，cpu负载居高不下，如何高效的借助工具来排查问题，让我们跟随本文来抽丝剥茧，让头疼的垃圾回收和full gc问题浮出水面...
上周四微信上收到智能告警，某应用出现full gc频繁问题，初步观察了下sgm和线上机器情况，定位问题。每次告警都是对我们每个金融消防员的考验：如履薄冰，胆战心惊。

另外sgm上看了下jvm监控，发现堆内存从14号上午窜上去后再没下来过，下面这个图很容易定位是发生了内存泄漏，以下的思路就顺着定位内存泄漏的程序进行

在sure上使用jmap命令，发现char占据大量内存，怀疑存在大字符串。

周五找运维下了一份详细的dump文件，使用亮哥之前分享过的IBMHeapAnalyzer工具，分析发现问题可能出在EnterRealNameApplyUploadImgReqModel类里，这个类是用于实名申请时图片上传接口的入参实体类，里面包含了图片的base64的string串，占用较大空间。

排查mapi底层biz系统，查看EnterRealNameApplyUploadImgReqModel对应的实现类，发现biz中有对图片大小进行限制，最大为2M，但是mapi无限制，怀疑可能为此接口中上传图片过大。

经磊哥点拨，发现sdk中对base串做了加密，并在mapi中做了解密处理，加解密工具为静态（static）工具方法，可能导致内存泄漏。

定位到问题后，再使用亮哥推荐的visualVM插件，在本地启了mapi应用，在sdk写了个死循环去调图片上传接口，并故意将照片设置为3M，同时在idea的VM Option中JVM内存调至300M，此时效果如下：

可以很清楚的发现，old区增长速度特别快，同时gc次数频繁，并且无法有效的降低old区占用，old区整体呈现递增趋势，很容易发生内存溢出，经过之前的定位流程，猜测为图片本身较大，在亚当区无法容纳该对象时，直接塞到old区，同时加解密方法为静态方法，被持续引用，导致无法进行垃圾回收，导致old区持续递增。

处理方案：

处理后可以很明显的发现无论是Old Gen区的递增速度还是gc次数相较于之前发生了很大的变化，趋于正常。

以上过程其实问题已经得到解决，但发现频繁报fullgc的机器，cpu一直占用在10%以上，怀着打破砂锅问到底的态度对cup的问题也进行了下分析：

1、通过top命令查看占用cpu过高的进程

可以看到占用cpu的进程PID为7975

2、通过命令查找到占用cpu最高的线程

命令：top -H -p [进程id] top –H –p 7975

3、将线程号转化为16进制（jstack线程堆栈中使用的16进制）

printf "%x\\n" [线程id]

4、 查找线程号对应的线程

执行： jstack [进程id] |grep -A 10 [线程id的16进制]

由上图可以看到，一直在占用CPU的线程是CMS垃圾回收线程，由于堆内存占用过高程序又不释放，垃圾回收线程一直在尝试回收内存导致cpu过高。

上面再分析触发垃圾回收的时候留了一个小尾巴，为什么老年代和永久代占用不高的时候频繁的发生了full gc呢。由于此应用使用的是jdk1.6，垃圾回收器使用的是CMS，它是基于“标记--清除”算法实现的，特点是在收集结束的时候会有大量的空间碎片产生。空间碎片太多的时候，将会给大对象的分配带来很大的麻烦，往往会出现老年代还有很大的空间剩余，但是无法找到足够大的连续空间来分配当前对象的，只能提前触发 full gc。如果jdk调整为1.7u4及以上即可使用G1垃圾回收算法不会产生大量的空间碎片。

JVM问题一般不是很容易遇到，程序有bug或者并发量大的时候均可能导致jvm异常，通过以上问题的分析过程及以往的经验简单总结下排查jvm问题的一般思路：

上面只是个大概的流程，具体问题还需具体分析，重点还是需要 掌握jvm原理并灵活应用 。

JVM技术专题彻底弄清楚Minor GC和Major GC及Full GC「原理篇」

每日一句

每一日你所付出的代价都比前一日高，因为你的生命又消短了一天，所以每一日你都要更用心。
[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-FxRMwJPm-1666755856202)(https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/638df33ef9f24fb6800d2ce5c68fdfe4~tplv-k3u1fbpfcp-watermark.image)]

前提概要

对于JVM而言，最难能够掌握的就是GC回收部分的研究和探索。而对于虚拟机而言根据不同的区域以及范围和方案分为Minor GC、Major GC和Full GC等，此处暂时不描述Mixed GC，后续章节会详细做专题探究。

GC的引入

堆内存划分为Eden、Survivor（2）和Tenured/Old空间。

发生在年轻代的GC——Minor GC

[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-NLkAE5V1-1666755856203)(https://p9-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/46a0afc01ea24b9491ab86a4769dda36~tplv-k3u1fbpfcp-watermark.image)]

其中Minor GC如下图所示

  • 虚拟机给每个对象定义一个对象年龄（Age）计数器。对象在Eden生并经过第一次Minor GC后仍然存活，并且能被Survivor容纳的话，将被移动到Survivor空间中，并将对象年龄设为 1。

  • 对象在Survivor区中每熬过一次Minor GC，年龄就增加1岁，当它的年龄增加到一定程度（默认为15岁）时，就会被晋升到老年代中。

  • 对象晋升老年代的年龄阈值，可以通过参数-XX:MaxTenuringThreshold来设置。

[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-ZMNl0xHK-1666755856204)(https://p1-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/b57cd4d3a86a4816826b76063c316acb~tplv-k3u1fbpfcp-watermark.image)]

从年轻代空间（包括Eden和Survivor区域）回收内存被称为Minor GC。这一定义既清晰又易于理解，因为Java对象大多都具备朝生夕灭的特性，所以Minor GC非常频繁，一般回收速度也比较快。

  • JVM无法为一个新的对象分配空间时会触发Minor GC，比如当Eden区满了。所以分配率越高，越频繁执行Minor GC。

    • 内存池被填满的时候，其中的内容全部会被复制，指针会从0开始跟踪空闲内存。

    • Eden和Survivor区进行了标记和复制操作，取代了经典的标记、扫描、压缩、清理操作。

    • 所以Eden和Survivor区不存在内存碎片，写指针总是停留在所使用内存池的顶部。

  • 执行Minor GC操作时，不会影响到方法区。从方法区到年轻代的引用被当成GCRoots，从年轻代到方法区的引用在标记阶段被直接忽略掉。

  • 质疑常规的认知，所有的Minor GC都会触发 “全世界的暂停（stop-the-world）”，停止应用程序的线程。对于大部分应用程序，停顿导致的延迟都是可以忽略不计的。

    • 其中的真相就是，大部分Eden区中的对象都能被认为是垃圾，永远也不会被复制到Survivor区或者老年代空间。

  • 如果正好相反，Eden区大部分新生对象不符合GC条件，Minor GC执行时暂停的时间将会长很多。

Minor GC触发机制：

当年轻代满时就会触发Minor GC，这里的年轻代满指的是Eden代满，Survivor满不会引发GC。

发生在老年代的GC——Major GC/Full GC

  • Major GC：主要是清理老年代：MajorGC的速度一般会比Minor GC慢 10倍以上

  • Full GC：主要是清理整个堆空间—包括年轻代和老年代。

    1. 首先，许多Major GC是由Minor GC触发，所以很多情况下将这两种GC分离是不太可能的。
    2. 另一方面，许多现代垃圾收集机制会清理部分老年代空间，所以使用“cleaning”一词只是部分正确。

这使得我们不用去关心到底是叫Major GC还是Full GC，大家应该关注当前的GC是否停止了所有应用程序的线程，还是能够并发的处理而不用停掉应用程序的线程。

老年代GC（Major GC/Full GC）：指发生在老年代的GC，出现了Major GC，经常会伴随至少一次的Minor GC（但非绝对的，ParallelScavenge收集器的收集策略里就有直接进行Major GC的策略选择过程） 。

Full GC触发机制：

  • （1）调用System.gc时，系统建议执行Full GC，但是不必然执行
  • （2）老年代空间不足
  • （3）方法区空间不足：当永久代/元数据空间满时也会引发Full GC，会导致Class、Method元信息的卸载。
  • （4）通过Minor GC后进入老年代的平均大小大于老年代的可用内存
  • （5）由Eden区、survivor space1（From Space）区向survivor space2（To Space）区复制时，对象大小大于To Space可用内存，则把该对象转存到老年代，且老年代的可用内存小于该对象大小

Full GC定义是相对明确的，就是针对整个新生代、老生代、元空间（metaspace，java8以上版本取代perm gen）的全局范围的GC；

Minor GC和Major GC是俗称，在Hotspot JVM实现的Serial GC, Parallel GC, CMS, G1 GC中大致可以对应到某个Young GC和Old GC算法组合；

第一次尝试通过 jstat 输出：

my-precious: me$ jstat -gc -t 4235 1s

Time S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
 5.7 34048.0 34048.0  0.0   34048.0 272640.0 194699.7 1756416.0   181419.9  18304.0 17865.1 2688.0 2497.6      3    0.275   0      0.000    0.275
 6.7 34048.0 34048.0 34048.0  0.0   272640.0 247555.4 1756416.0   263447.9  18816.0 18123.3 2688.0 2523.1      4    0.359   0      0.000    0.359
 7.7 34048.0 34048.0  0.0   34048.0 272640.0 257729.3 1756416.0   345109.8  19072.0 18396.6 2688.0 2550.3      5    0.451   0      0.000    0.451
 8.7 34048.0 34048.0 34048.0 34048.0 272640.0 272640.0 1756416.0  444982.5  19456.0 18681.3 2816.0 2575.8      7    0.550   0      0.000    0.550
 9.7 34048.0 34048.0 34046.7  0.0   272640.0 16777.0  1756416.0   587906.3  20096.0 19235.1 2944.0 2631.8      8    0.720   0      0.000    0.720
10.7 34048.0 34048.0  0.0   34046.2 272640.0 80171.6  1756416.0   664913.4  20352.0 19495.9 2944.0 2657.4      9    0.810   0      0.000    0.810
11.7 34048.0 34048.0 34048.0  0.0   272640.0 129480.8 1756416.0   745100.2  20608.0 19704.5 2944.0 2678.4     10    0.896   0      0.000    0.896
12.7 34048.0 34048.0  0.0   34046.6 272640.0 164070.7 1756416.0   822073.7  20992.0 19937.1 3072.0 2702.8     11    0.978   0      0.000    0.978
13.7 34048.0 34048.0 34048.0  0.0   272640.0 211949.9 1756416.0   897364.4  21248.0 20179.6 3072.0 2728.1     12    1.087   1      0.004    1.091
14.7 34048.0 34048.0  0.0   34047.1 272640.0 245801.5 1756416.0   597362.6  21504.0 20390.6 3072.0 2750.3     13    1.183   2      0.050    1.233
15.7 34048.0 34048.0  0.0   34048.0 272640.0 21474.1  1756416.0   757347.0  22012.0 20792.0 3200.0 2791.0     15    1.336   2      0.050    1.386
16.7 34048.0 34048.0 34047.0  0.0   272640.0 48378.0  1756416.0   838594.4  22268.0 21003.5 3200.0 2813.2     16    1.433   2      0.050    1.484

这个片段是 JVM 启动后第17秒提取的。基于该信息，我们可以得出这样的结果，运行了12次 Minor GC、2次 Full GC，时间总跨度为50毫秒。

java -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC eu.plumbr.demo.GarbageProducer

3.157: [GC (Allocation Failure) 3.157: [ParNew: 272640K->34048K(306688K), 0.0844702 secs] 272640K->69574K(2063104K), 0.0845560 secs] [Times: user=0.23 sys=0.03, real=0.09 secs] 
4.092: [GC (Allocation Failure) 4.092: [ParNew: 306688K->34048K(306688K), 0.1013723 secs] 342214K->136584K(2063104K), 0.1014307 secs] [Times: user=0.25 sys=0.05, real=0.10 secs] 
... cut for brevity ...
11.292: [GC (Allocation Failure) 11.292: [ParNew: 306686K->34048K(306688K), 0.0857219 secs] 971599K->779148K(2063104K), 0.0857875 secs] [Times: user=0.26 sys=0.04, real=0.09 secs] 
12.140: [GC (Allocation Failure) 12.140: [ParNew: 306688K->34046K(306688K), 0.0821774 secs] 1051788K->856120K(2063104K), 0.0822400 secs] [Times: user=0.25 sys=0.03, real=0.08 secs] 
12.989: [GC (Allocation Failure) 12.989: [ParNew: 306686K->34048K(306688K), 0.1086667 secs] 1128760K->931412K(2063104K), 0.1087416 secs] [Times: user=0.24 sys=0.04, real=0.11 secs] 
13.098: [GC (CMS Initial Mark) [1 CMS-initial-mark: 897364K(1756416K)] 936667K(2063104K), 0.0041705 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
13.102: [CMS-concurrent-mark-start]
13.341: [CMS-concurrent-mark: 0.238/0.238 secs] [Times: user=0.36 sys=0.01, real=0.24 secs] 
13.341: [CMS-concurrent-preclean-start]
13.350: [CMS-concurrent-preclean: 0.009/0.009 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
13.350: [CMS-concurrent-abortable-preclean-start]
13.878: [GC (Allocation Failure) 13.878: [ParNew: 306688K->34047K(306688K), 0.0960456 secs] 1204052K->1010638K(2063104K), 0.0961542 secs] [Times: user=0.29 sys=0.04, real=0.09 secs] 
14.366: [CMS-concurrent-abortable-preclean: 0.917/1.016 secs] [Times: user=2.22 sys=0.07, real=1.01 secs] 
14.366: [GC (CMS Final Remark) [YG occupancy: 182593 K (306688 K)]14.366: [Rescan (parallel) , 0.0291598 secs]14.395: [weak refs processing, 0.0000232 secs]14.395: [class unloading, 0.0117661 secs]14.407: [scrub symbol table, 0.0015323 secs]14.409: [scrub string table, 0.0003221 secs][1 CMS-remark: 976591K(1756416K)] 1159184K(2063104K), 0.0462010 secs] [Times: user=0.14 sys=0.00, real=0.05 secs] 
14.412: [CMS-concurrent-sweep-start]
14.633: [CMS-concurrent-sweep: 0.221/0.221 secs] [Times: user=0.37 sys=0.00, real=0.22 secs] 
14.633: [CMS-concurrent-reset-start]
14.636: [CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

在点头同意这个结论之前，让我们看看来自同一个 JVM 启动收集的垃圾收集日志的输出。显然- XX ： + PrintGCDetails 告诉我们一个不同且更详细的故事：

基于这些信息，我们可以看到12次 Minor GC 后开始有些和上面不一样了。没有运行两次Full GC，这不同的地方在于单个GC在永久代中不同阶段运行了两次：

最初的标记阶段，用了0.0041705秒也就是4ms左右。这个阶段会暂停“全世界（ stop-the-world）”的事件，停止所有应用程序的线程，然后开始标记。

并行执行标记和清洗阶段。这些都是和应用程序线程并行的。
最后 Remark 阶段，花费了0.0462010秒约46ms。这个阶段会再次暂停所有的事件。
并行执行清理操作。正如其名，此阶段也是并行的，不会停止其他线程。

所以，正如我们从垃圾回收日志中所看到的那样，实际上只是执行了 Major GC 去清理老年代空间而已，而不是执行了两次 Full GC。

以上是关于技术侦探日记 01 - FULL GC篇的主要内容，如果未能解决你的问题，请参考以下文章

初一英语日记60字作文

关于搬新家的日记200字5篇

实习的日记

小刘同学的一百三十二篇日记

少女学习日记——正则表达式专题篇

万圣节日记300字