关于G1收集器的收集过程,看过一些博客和书,基本上十有八九都说的不同,若是要肯定哪一个是正确的仍是得去看实现代码。固然我不打算去学C语言看代码了,接下来就结合本身的理解和资料来介绍G1收集器收集过程,力求作到初次接触G1也能看明白。php
G1能够说是个里程碑式的产品,从提出到正式商业使用几乎用了差很少10年,从jdk9开始默认使用的垃圾收集器就是G1,日后会逐步取代CMS。G1与以前的垃圾收集器相比有着明显的区别。好比它能够进行新时代和老年代的收集,而其余的收集器都是新生代收集器 + 老年代收集器的组合;同时对堆的划分与传统的堆划分也有着明显的区别;算法
若是忽略掉永久代的话,能够将堆划分为新生代的1个Eden + 2 个Survivor以及一大块老年代而后进行分代收集,以下图所示:shell
再看G1收集器,则是将整个大堆划分为不少大小相同的region,region大小为2的n次幂,并且不要求region间是空间上连续的。每一个Region则能够扮演eden、survivor、old三种角色之一。其实还有humonous区,其专门用来存储大对象,大对象定义为大小达到region一半大小的对象,由于G1会把它当作老年代,因此这里放到老年代一块儿了。另外每一个region扮演的角色不是一直不变的。数组
到这就能够解释为何取名叫G1收集器了:收集器根据用户指定的停顿时间来制定回收计划,简单来讲就是,对各个区域的回收价值排序收集,好比有的region中对象存活的极少,那么该region确定排的很是靠前而优先被收集。由于收集这块region只须要移动不多的对象,那么就只须要不多的时间,同时还能释放大量的内存,必然优先收集该区域。这就是G1(Garbage First)名字的由来。浏览器
G1只有YongGC(YGC)和mixed gc,YGC用于收集所有的新生代,而mixed gc则是收集所有的年轻代和收益高的老年代。当发生Full GC则会使用单线程进行GC,很是耗时,应该极力去避免Full GC的发生。下面经过介绍G1的回收过程来阐述使用G1的相比其余收集器的优点。bash
具体的GC过程不会说的太细,不然得写几万字,由于还要介绍记忆集,卡表等。数据结构
收集后以下:多线程
如图所示,年轻代被挑选出来后,收集的时候会将存活对象移动到一块空的region中去,而后再一次性清理原来的内存空间释放内存,须要强调的是YGC针对的是整个新生代,不少状况下原来Eden区域有个1-2G,一次YGC后所有清零,而survivor区域内存占用会上涨一些,毕竟绝大部分对象都是朝生夕死,因此YGC效率仍是很高的。如下有几点须要强调:并发
mixed gc(混合收集)是G1独有的gc方式,mixed gc会收集所有新生代和收益高的老年代。mixed gc主要分为两步:app
而全局并发标记又分为四步:
初始标记(包含了根区域扫描);
并发标记;
从新标记;
清理;
初始标记阶段: 标记了从GC Roots开始直接可达的根对象, 须要STW。混合收集中的初始标记和新生代的初始标记几乎同样,因此常常会看到文章说与YGC的时候同步完成的,因此G1收集器在这个阶段实际并无额外的停顿。实际上混合收集的初始标记是借用了新生代收集的结果,即新生代垃圾回收后的新生代Survivor分区做为根,因此混合收集必定发生在新生代回收以后,且不须要再进行一次初始标记。在gc日志中表现为GC pause (young)(inital-mark)
.
并发标记阶段:当YGC执行结束以后,若是发现知足并发标记的条件,并发线程就开始进行并发标记。根据新生代的Survivor分区以及老生代的RSet开始并发标记。时机是在YGC后,只有达到InitiatingHeapOccupancyPercent阈值后,才会触发并发标记。InitiatingHeapOccupancyPercent默认值是45,表示的是当已经分配的内存加上即将分配的内存超过内存总容量的45%就能够开始并发标记。并发标记会对全部的分区进行标记。这个阶段并不须要STW。
小tips:若是你发现收集完后占用的堆内存达到了总的堆内存的40%之后,下次可能就会发生mixed gc了,若是发现堆内存2G,下次成了1.3G,极可能就是发生了mixed gc,频繁的mixed gc那确定是有问题的。关于如何查看日志中有效信息这会在后面具体介绍。
从新标记阶段:用来标记那些在并发标记阶段引用发生变化的对象,须要对用户线程作个短暂的STW。
清理阶段:在该阶段也是须要STW的。主要统计存活对象,统计的结果将会用来排序分区region,以用于下一次的Collect Set(简称CSet,见该节最后的介绍)的选择;须要把新分配的对象,即不在本次并发标记范围内的新分配对象,都视为活跃对象。
该阶段比较容易引发误解地方在于,清理操做并不会清理垃圾对象,也不会执行存活对象的拷贝。也就是说,在极端状况下,该阶段结束以后,JVM的内存使用状况毫无变化。
混合垃圾回收阶段: 混合回收实际上与YGC是同样的, 第一个步骤是从分区中选出若干个分区进行回收,这些被选中的分区称为Collect Set(简称CSet);第二个步骤是把这些分区中存活的对象复制到空闲的分区中去,同时把这些已经被回收的分区放到空闲分区列表中。在日志中标记为[GC pause (mixed)], 即年轻代和老年代会被同时收集。见下图:
回收完以后就成了下面这个样子:
CSet:收集集合(CSet) 是一组可被回收的分区的集合。 在CSet中存活的数据会在GC过程当中被移动到另外一个可用分区,CSet中的分区能够来自eden空间、survivor空间、或者老年代。
分代G1模式下选择CSet有两种子模式, 分别对应Young GC和Mixed GC:
说到G1收集器不得不说记忆集(Remembered Set, 简称RSet)和卡表(Card Table),不少文章都会穿插在GC过程当中来讲,若是不了解可能会看不下去,其实不介绍这两个数据结构更容易了解GC流程。
考虑这样一个问题:YGC的时候针对的是所有新生代,那么选GC Roots的时候,由于存在跨代引用的问题而很差肯定哪些是roots,其实不少root是在老年代。可是老年代那么大,总不能每次都花那么多时间扫描整个老年代,这就至关于扫描了整个堆了,由于新生代确定是要所有扫描的。所以在新生代引入了记忆集RSet这样一个数据结构,用来记录哪些Region中的对象指向了当前分区中的对象(记忆集是一种用于记录从非收集区域指向收集区域的指针集合的抽象数据结构,用以免把整个老年代加进GC Roots扫描范围),下面经过简单的画图来理解。
容易知道的是若是忽略老年代做为根而不去扫描的话,显然对象E就是垃圾对象,这就会致使误判;可是也不能去扫描所有的老年代,因此在该Eden Region中使用的RSet,记录了Old Region中有对象指向了本区域中的对象。说到这可能猜到了RSet是怎样的数据结构了。没错,就是哈希表,key为别的Region的起始地址,value则是一个集合,集合中的元素地址(实际上是卡表中元素的下标index)。
一个卡表会将一个分区Region划分为固定大小的连续区域,每一个区域又称为卡。卡表一般为字节数组,由卡的索引(数组下标)来标识每一个分区的地址。默认状况下每一个卡都未被引用。当一个卡被引用的时候,则将该卡地址对应的数组下标的值标记为0。同时根据须要在RSet中记录下来,好比O指向了E,那么在该Eden区的RSet中会记录O在Old区域中卡表的索引,看下面的图可能会明白我说的啥。
说明: 比较权威的书和部分文章写的是记忆集是一种抽象,卡表则是其实现,二者的关系就像Map和HashMap,但因为上面这种方式对于我来讲更易于理解,因此就介绍了上面这种方式。
再说第二个问题:在并发标记阶段如何保证收集线程与用户线程互不干扰地运行?
首先要解决的是用户线程改变对象引用关系时,必须保证其不能打破本来的对象图结构,致使标记结果出现错误。
G1就是采用了SATB(Snapshot-At-The-Beginning,原始快照)算法来实现的:SATB能够理解成在GC开始以前对堆内存里的对象作一次快照,此时活的对象就认为是活的,从而造成一个对象图。在GC收集的时候,新生代的对象也认为是活的对象,除此以外其余不可达的对象都认为是垃圾对象。SATB算法主要分红如下三个步骤:
关于步骤2能够这样理解,假设存在这样的关系A.b = B, C.b=null(此时B是白色的),并发标记中发生了这样的变化A.b=null,C.b=B。 那么这个时候因为旧的引用A所指向的对象是B,因此将B标记为非白。标记最后若是对象为白色那就是垃圾对象,此外还有灰色和黑色(黑色是存活对象,灰色多是垃圾对象或者不是),这属于三色标记算法内容,避免越说越糊涂就很少介绍(SATB其实依赖三色标记),下图简单展现了变化过程。
其次要解决的问题是,前面说了并发过程新分配的对象认为是存活对象,那么如何找到GC过程当中新分配的对象呢?
每一个region记录着两个top-at-mark-start(TAMS指针, 分别为prev TAMS和next TAMS。在TAMS以上的对象就是新分配的, 于是被视为隐式marked。经过这种方式咱们就找到了在GC过程当中新分配的对象,并把这些对象认为是活的对象。
最后,解决了对象在GC过程当中分配的问题,那么在GC过程当中引用发生变化的问题怎么解决呢?G1给出的解决办法是经过Write Barrier。 Write Barrier就是对引用字段进行赋值作了额外处理,这个额外处理前面也说了,其实就是全部旧的引用所指向的对象都变成非白的,这样就能够了解到哪些引用对象发生了什么样的变化
先看YGC日志的样子 GC pause (G1 Evacuation Pause) (young)
:
class space used 5944K, capacity 6094K, committed 6144K, reserved 1048576K
2020-03-23T17:32:14.984+0800: 9.925: [GC pause (G1 Evacuation Pause) (young)2020-03-23T17:32:15.005+0800: 9.947: [SoftReference, 0 refs, 0.0000722 secs]2020-03-23T17:32:15.005+0800: 9.947: [WeakReference, 71 refs, 0.0000329 secs]2020-03-23T17:32:15.005+0800: 9.947: [FinalReference, 1660 refs, 0.0018747 secs]2020-03-23T17:32:15.007+0800: 9.949: [PhantomReference, 0 refs, 3 refs, 0.0000193 secs]2020-03-23T17:32:15.007+0800: 9.949: [JNI Weak Reference, 0.0000216 secs], 0.0252556 secs]
[Parallel Time: 20.4 ms, GC Workers: 23]
[GC Worker Start (ms): Min: 9925.6, Avg: 9925.7, Max: 9925.8, Diff: 0.2]
[Ext Root Scanning (ms): Min: 0.9, Avg: 2.3, Max: 10.1, Diff: 9.2, Sum: 53.9]
[Update RS (ms): Min: 0.0, Avg: 1.2, Max: 2.8, Diff: 2.8, Sum: 27.9]
[Processed Buffers: Min: 0, Avg: 3.3, Max: 13, Diff: 13, Sum: 75]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 2.9]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.7, Max: 4.3, Diff: 4.3, Sum: 15.0]
[Object Copy (ms): Min: 8.7, Avg: 14.6, Max: 18.6, Diff: 10.0, Sum: 336.1]
[Termination (ms): Min: 0.0, Avg: 1.1, Max: 1.4, Diff: 1.4, Sum: 25.4]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 23]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.5]
[GC Worker Total (ms): Min: 19.9, Avg: 20.1, Max: 20.2, Diff: 0.3, Sum: 461.7]
[GC Worker End (ms): Min: 9945.8, Avg: 9945.8, Max: 9945.8, Diff: 0.1]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.4 ms]
[Other: 4.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 2.6 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.7 ms]
[Eden: 284.0M(284.0M)->0.0B(310.0M) Survivors: 20.0M->38.0M Heap: 336.1M(4096.0M)->94.7M(4096.0M)]
Heap after GC invocations=8 (full 0):
garbage-first heap total 4194304K, used 96923K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
region size 2048K, 19 young (38912K), 19 survivors (38912K)
Metaspace used 49410K, capacity 49926K, committed 50428K, reserved 1093632K
class space used 5944K, capacity 6094K, committed 6144K, reserved 1048576K
}
[Times: user=0.38 sys=0.06, real=0.02 secs]
复制代码
YGC的详细过程就不说了,只说我的认为关键的日志信息:
[Object Copy (ms): Min: 8.7, Avg: 14.6, Max: 18.6, Diff: 10.0, Sum: 336.1]
[Times: user=0.38 sys=0.06, real=0.02 secs]
复制代码
这两行表示拷贝对象花费的时间和耗时,主要看平均时间Avg
和耗时real
。若是你发现YGC耗时比较长,特别要留意这两行信息,好比real=0.56 secs;Object Copy (ms): Avg: 501
那你就知道是对象复制花费了太多时间,可是新生代基本都是招生夕死,那么为何还有那么多对象存活呢?接下来就须要根据本身的业务具体分析了,后面会结合咱们项目遇到过的问题来进行分析。
[Eden: 284.0M(284.0M)->0.0B(310.0M) Survivors: 20.0M->38.0M Heap: 336.1M(4096.0M)->94.7M(4096.0M)]
复制代码
这行表示了内存回收的状况,能够看到的是Eden
区域是所有会被回收的,幸存区涨了18M,最后堆内存状况是从回收前的336.1M到回收后的94.7M。若是你发现间歇性的幸存区域从较小的内存占用,回收后占用飙升,那极可能就有问题了,也便是存在大量对象存活了。固然若是回收后堆内存仍是一直上涨,好比咱们这里最大堆内存是4G,若是回收后一直飙到了2000M(通常是占用45%左右)那你可能就要分析下是否正常了,好比是否常常有大对象申请内存,大对象进入了老年代而没有获得回收致使一直上升。不过通常这时会进行mixed gc
了,具体的后面会分析遇到的一些问题。
再来看mixed gc
,实际上是和YGC分析是很相似的,因为全局并发标记中的初始标记是伴随着YGC,因此在这一阶段看到的实际上是YGC内容
2020-03-24T19:34:12.416+0800: 7388.991: [GC pause (G1 Evacuation Pause) (young) (initial-mark)2020-03-24T19:34:12.447+0800: 7389.022: [SoftReference, 0 refs, 0.0000844 secs]2020-03-24T19:34:12.447+0800: 7389.022: [WeakReference, 24 refs, 0.0000157 secs]2020-03-24T19:34:12.447+0800: 7389.022: [FinalReference, 20 refs, 0.0000212 secs]2020-03-24T19:34:12.447+0800: 7389.022: [PhantomReference, 0 refs, 0 refs, 0.0000098 secs]2020-03-24T19:34:12.447+0800: 7389.022: [JNI Weak Reference, 0.0000400 secs], 0.0336560 secs]
[Parallel Time: 28.3 ms, GC Workers: 18]
[GC Worker Start (ms): Min: 7388993.6, Avg: 7388994.1, Max: 7388994.7, Diff: 1.2]
... 内容同YGC
2020-03-24T19:34:12.450+0800: 7389.025: [GC concurrent-root-region-scan-start]
2020-03-24T19:34:12.450+0800: 7389.025: Total time for which application threads were stopped: 0.0366523 seconds, Stopping threads took: 0.0006589 seconds
2020-03-24T19:34:12.461+0800: 7389.036: [GC concurrent-root-region-scan-end, 0.0111133 secs]
2020-03-24T19:34:12.461+0800: 7389.036: [GC concurrent-mark-start]
2020-03-24T19:34:12.917+0800: 7389.493: [GC concurrent-mark-end, 0.4565315 secs]
2020-03-24T19:34:12.919+0800: 7389.494: [GC remark 2020-03-24T19:34:12.919+0800: 7389.494: [Finalize Marking, 0.0016538 secs] 2020-03-24T19:34:12.920+0800: 7389.496: [GC ref-proc2020-03-24T19:34:12.920+0800: 7389.496: [SoftReference, 2129 refs, 0.0008546 secs]2020-03-24T19:34:12.921+0800: 7389.497: [WeakReference, 1891 refs, 0.0006409 secs]2020-03-24T19:34:12.922+0800: 7389.497: [FinalReference, 947 refs, 0.0009644 secs]2020-03-24T19:34:12.923+0800: 7389.498: [PhantomReference, 2 refs, 279 refs, 0.0002176 secs]2020-03-24T19:34:12.923+0800: 7389.498: [JNI Weak Reference, 0.0000991 secs], 0.0030448 secs] 2020-03-24T19:34:12.923+0800: 7389.499: [Unloading, 0.0516170 secs], 0.0587406 secs]
[Times: user=0.20 sys=0.67, real=0.06 secs]
2020-03-24T19:34:12.978+0800: 7389.553: Total time for which application threads were stopped: 0.0604210 seconds, Stopping threads took: 0.0002143 seconds
2020-03-24T19:34:12.979+0800: 7389.554: [GC cleanup 1993M->1296M(4096M), 0.0411176 secs]
[Times: user=0.04 sys=0.31, real=0.05 secs]
2020-03-24T19:34:13.020+0800: 7389.596: Total time for which application threads were stopped: 0.0426097 seconds, Stopping threads took: 0.0001096 seconds
2020-03-24T19:34:13.020+0800: 7389.596: [GC concurrent-cleanup-start]
2020-03-24T19:34:13.021+0800: 7389.597: [GC concurrent-cleanup-end, 0.0009866 secs]
2020-03-24T19:36:25.421+0800: 7521.996: [GC pause (G1 Evacuation Pause) (mixed)2020-03-24T19:36:25.438+0800: 7522.013: [SoftReference, 0 refs, 0.0000595 secs]2020-03-24T19:36:25.438+0800: 7522.013: [WeakReference, 45 refs, 0.0000194 secs]2020-03-24T19:36:25.438+0800: 7522.013: [FinalReference, 0 refs, 0.0000086 secs]2020-03-24T19:36:25.438+0800: 7522.013: [PhantomReference, 0 refs, 5 refs, 0.0000110 secs]2020-03-24T19:36:25.438+0800: 7522.013: [JNI Weak Reference, 0.0000482 secs], 0.0193059 secs]
[Parallel Time: 13.0 ms, GC Workers: 18]
[GC Worker Start (ms): Min: 7521999.3, Avg: 7521999.7, Max: 7522000.2, Diff: 0.9]
... 内容同YGC
复制代码
须要注意的是GC pause (G1 Evacuation Pause) (young) (initial-mark)和GC pause (G1 Evacuation Pause) (mixed)
之间可能会穿插YGC,这两段的内容和YGC是同样的因此不须要解释了。关于mixed gc
的步骤从日志信息里面很容易读出来,好比初始标记GC pause (G1 Evacuation Pause) (young) (initial-mark)
, 根Region扫描,并发标记等,对着 1.3的步骤介绍很容易看明白。
一般来讲当某次回收后(大部分是YGC)堆内存占用达到45%左右,后面若是没降下去那很快就会进行mixed gc
来整理老年代了。若是程序正常的话mixed gc
频率应该是很低的,咱们的项目可能还有点问题,可是通常也就30分钟一次。若是你的项目出现的频率很高,好比1-5分钟一次,那你就可能须要考虑是否出现了问题。频繁的mixed gc
极可能说明了老年代内存得不到释放,同时可能还在增长,可能最后内存回收的速度跟不上分配的速度那就要full gc
了,动不动就会十几秒,并且会不断进行下去,因为full gc
是单线程STW的,此时服务基本就不可用了。因此full gc
是要极力去避免的。
-XX:+CrashOnOutOfMemoryError 若是启用了此选项,当出现内存不足错误时,JVM将崩溃并产生文本和二进制崩溃文件(若是启用了核心文件),jdk8加的。
-XX:GCLogFileSize=xxxxxxxxx GC日志文件大小上限
-XX:NumberOfGCLogFiles=100 GC日志文件数量上限
-XX:+HeapDumpOnOutOfMemoryError 内存溢出的时候dump文件
-XX:InitialHeapSize=4294967296 初始堆内存大小
-XX:MaxDirectMemorySize=805306368 最大直接内存大小
-XX:MaxHeapSize=4294967296 最大堆内存大小
-XX:MaxGCPauseMillis=200 GC时候STW最大停顿时间
-XX:+PrintGCDateStamps 打印GC时间(当前时间,好比2020-03-23T17:33:07.939+0800)
-XX:+PrintGCDetails 输出GC详细日志
-XX:+PrintGCTimeStamps 打印GC时间(jvm启动直到垃圾收集发生所经历的时间,好比63表示经历了64秒)
-XX:+UseG1GC 使用G1收集器
-XX:G1HeapRegionSize=n 每一个Region的大小
-G1HeapWastePercent 在global concurrent marking结束以后,咱们能够知道old generegions中有多少空间要被回收,在每次YGC以后和再次发生Mixed GC以前,会检查垃圾占比是否达到此参数,只有达到了,下次才会发生Mixed GC
-G1MixedGCLiveThresholdPercent old generation region中的存活对象的占比,只有在此参数之下,才会被选入CSet
-G1MixedGCCountTarget 一次global concurrent marking以后,最多执行MixedGC的次数
复制代码
写参数的时候记得初始堆内存和最大堆内存要同样,以免每次垃圾回收完成后JVM从新分配内存,若是不一致极可能会致使full gc问题。
使用的G1收集器,不要去指定新生代(-Xmn)和老年代的大小,让收集器动态调整便可。不然可能带来下面两个问题
经过-XX:MaxGCPauseMillis=x
能够设置启动应用程序暂停的时间,G1在运行的时候会根据这个参数选择CSet来知足响应时间的设置。通常状况下这个值设置到100ms或者200ms都是能够的(不一样状况下会不同),但若是设置成50ms就不太合理。暂停时间设置的过短,就会致使出现G1跟不上垃圾产生的速度。最终退化成Full GC。因此对这个参数的调优是一个持续的过程,逐步调整到最佳状态。对于如何设置官方有个tips:时间小于等于程序响应客户端的时间的10%,好比http服务响应浏览器的时间通常就1000ms,那么能够设置停顿时间是100ms,固然具体的还得去调试看看。记住:暂停时间是一个目标,并不能保证老是能达到。
最后须要注意是否有Evacuation Failure,full x,这都是不该该出现的,出现了要当即解决掉。
当时运维人员通知了项目不停full gc
后,首先登机器dump文件,而后重启机器暂时保住线上恢复,而后将 dump文件发送到本机使用Mat进行分析。
1.dump文件:
- 命令: jmap -dump:format=b,file=./myfile 324576
- myfile为dump的文件名,324576为pid
关于jmap还有两个实用的命令:
1. jmap -histo:live pid 查看存活对象分布状况(可能会触发full gc不要在线上使用,不加live能够,加了live会强制执行一次full gc);
2. jmap -heap pid 查看heap参数,使用状况等;
复制代码
2.dump文件下载到本地:
- 命令:scp -r ./myfile tom@192.168.25.128: /home/tom/mydir
- 下载完以后给文件名加个.hprof后缀(或者dump的时候就加上),由于mat打开dump文件的时候只选择hprof文件。
复制代码
3.下载MAT并进行分析:
- 下载地址: https://www.eclipse.org/mat/downloads.php, 注意选国内镜像;
- 下载完以后基本上是打不开大点的dump文件(该文件有6个G),因此须要使用命令行启动MAT同时指定最大堆内存参数;
- 进入到安装目录,启动命令:MemoryAnalyzer.exe -vmargs -Xmx8g
复制代码
打开后看到
显然占用3G的对象是有问题的,点击左上角的图标查看对象分布,找到占用内存过大的对象
基本一个对象占了5M左右,到这里基本就知道问题在哪了,找到代码去解决BUG吧,其实不少时候full gc仍是代码写的有问题,这样的代码是真的存在的,遇到几回了。 有时候须要注意使用System.gc()
致使的full gc,这个会有相似提示Full GC(System.gc())
,须要根据业务考虑是否要避免,由于大部分是引用的包,本身确定是不会写这么个东西的,好比项目刚启动的时候可能作一些加载啥的会用一次,后续不会再出现那就没问题。
对于上面的full gc问题其实从GC日志一开始也分析出来了,只是当时还没出现full gc就打算次日去解决,可是晚了。根据公司老司机分享的经验,首先看下eden区域状况
cat gc.log | grep 'Eden'|less
复制代码
回收后基本都在3000M左右,老年代占用了那么多基本上会大批量的进行mixed gc,查看下频率
$ cat gc.log | grep 'mixed'|awk '{print $1}'
$ cat gc.log | grep 'real'|awk '{print $4}'|sort -n -k 2 -t = # 这条能够不看
复制代码
其实这个频率是不合理的,几乎是一分钟一次 mixed gc,再来看gc 内容:从mixed gc往下找,发现了mixed gc前的yong gc总会有大对象内存分配申请。
说明不停的有大对象内存申请,而后大对象会直接进入老年代Humongous 区(若是是5M那么得三个连续的Humongous 区),致使内存不断上涨,可是得不到释放后又不断申请。若是使用jmap -histo pid
基本就能查到是啥子对象了。
一般状况下因为新生对象存活率低,YGC的时间是很短的,由于不须要拷贝大量存活对象。可是还真见过两次YGC时间过长的问题(1-3秒),因为会STW因此这个问题是须要解决的。以前有人反馈服务存在间歇性抖动问题(内存也存在抖动,当时只分配了2G内存,因此问题很是明显,后续是改了4G才改善了不少,下面的分析则是基于改善后的分析)。
一样仍是先grep 'Eden'区域:
前面还好都是上图那样,属于正常。可是继续翻发现了问题:
内存忽然陡增,固然几回gc后又下来了,显然这里一定作了mixed gc
(多是几回),查一些mixed gc频率发现是每30分钟一次(若是对堆内存有监控那更是一目了然),到这里能够猜想是否是什么定时任务致使的(好比lettuce的拓扑结构每隔n分钟刷新一次也须要考虑),可使用jmap查看对象占用内存状况,而后肯定该对象属于哪一块功能从而肯定问题点,其实最后发现就是定时任务致使的。
进入到日志内容的时候能够发现,大量的内存拷贝占了过多的时间
由于定时任务致使了建立不少对象分配在Eden区域,gc后对这些对象进行拷贝,致使survivor区域暴涨,同时可能由于survivor不能彻底容纳这些对象,致使直接进入到了老年代,从而占用内存一下涨了1G,此时2G内存已经占了最大堆内存的一半了,接下来基本是会进行mixed gc来回收所有新生代的和部分有价值的老年代了。