标签:失败 ges red 核数 拷贝 version read form 类型
让我们先简单的看下整个堆年轻代和年老代的垃圾收集器组合(以下配合java8完美支持,其他版本可能稍有不同),其中标红线的则是我们今天要着重讲的内容:
"Concurrent Mark and Sweep" 是CMS的全称,官方给予的名称是:“Mostly Concurrent Mark and Sweep Garbage Collector”;
年轻代:采用 stop-the-world mark-copy 算法;
年老代:采用 Mostly Concurrent mark-sweep 算法;
设计目标:年老代收集的时候避免长时间的暂停;
能够达成该目标主要因为以下两个原因:
1 它不会花时间整理压缩年老代,而是维护了一个叫做 free-lists 的数据结构,该数据结构用来管理那些回收再利用的内存空间;
2 mark-sweep分为多个阶段,其中一大部分阶段GC的工作是和Application threads的工作同时进行的(当然,gc线程会和用户线程竞争CPU的时间),默认的GC的工作线程为你服务器物理CPU核数的1/4;
补充:当你的服务器是多核同时你的目标是低延时,那该GC的搭配则是你的不二选择。
首先对整个GC日志有一个大概的认知
2016-08-23T02:23:07.219-0200: 64.322: [GC (Allocation Failure) 64.322: [ParNew: 613404K->68068K(613440K), 0.1020465 secs] 10885349K->10880154K(12514816K), 0.1021309 secs] [Times: user=0.78 sys=0.01, real=0.11 secs]
2016-08-23T02:23:07.321-0200: 64.425: [GC (CMS Initial Mark) [1 CMS-initial-mark: 10812086K(11901376K)] 10887844K(12514816K), 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2016-08-23T02:23:07.321-0200: 64.425: [CMS-concurrent-mark-start] 2016-08-23T02:23:07.357-0200: 64.460: [CMS-concurrent-mark: 0.035/0.035 secs] [Times: user=0.07 sys=0.00, real=0.03 secs] 2016-08-23T02:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start] 2016-08-23T02:23:07.373-0200: 64.476: [CMS-concurrent-preclean: 0.016/0.016 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 2016-08-23T02:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start] 2016-08-23T02:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean: 0.167/1.074 secs] [Times: user=0.20 sys=0.00, real=1.07 secs] 2016-08-23T02:23:08.447-0200: 65.550: [GC (CMS Final Remark) [YG occupancy: 387920 K (613440 K)]65.550: [Rescan (parallel) , 0.0085125 secs]65.559: [weak refs processing, 0.0000243 secs]65.559: [class unloading, 0.0013120 secs]65.560: [scrub symbol table, 0.0008345 secs]65.561: [scrub string table, 0.0001759 secs][1 CMS-remark: 10812086K(11901376K)] 11200006K(12514816K), 0.0110730 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 2016-08-23T02:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start] 2016-08-23T02:23:08.485-0200: 65.588: [CMS-concurrent-sweep: 0.027/0.027 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 2016-08-23T02:23:08.485-0200: 65.589: [CMS-concurrent-reset-start] 2016-08-23T02:23:08.497-0200: 65.601: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2016-08-23T02:23:07.219-02001: 64.3222:[GC3(Allocation Failure4) 64.322: [ParNew5: 613404K->68068K6(613440K)7, 0.1020465 secs8] 10885349K->10880154K9(12514816K)10, 0.1021309 secs11][Times: user=0.78 sys=0.01, real=0.11 secs]12
我们来分析下对象晋升问题(原文中的计算方式有问题):
开始的时候:整个堆的大小是 10885349K,年轻代大小是613404K,这说明老年代大小是 10885349-613404=10271945K,
收集完成之后:整个堆的大小是 10880154K,年轻代大小是68068K,这说明老年代大小是 10880154-68068=10812086K,
老年代的大小增加了:10812086-10271945=608209K,也就是说 年轻代到年老代promot了608209K的数据;
图形分析:
2016-08-23T11:23:07.321-0200: 64.425: [GC (CMS Initial Mark)1 [1 CMS-initial-mark: 10812086K(11901376K)] 10887844K(12514816K), 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2016-08-23T11:23:07.321-0200: 64.425: [CMS-concurrent-mark-start] 2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-mark2: 0.035/0.035 secs] [Times: user=0.07 sys=0.00, real=0.03 secs] 2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start] 2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-preclean3: 0.016/0.016 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start] 2016-08-23T11:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean4: 0.167/1.074 secs] [Times: user=0.20 sys=0.00, real=1.07 secs] 2016-08-23T11:23:08.447-0200: 65.550: [GC (CMS Final Remark5)
[YG occupancy: 387920 K (613440 K)]65.550: [Rescan (parallel) , 0.0085125 secs]65.559:
[weak refs processing, 0.0000243 secs]65.559: [class unloading, 0.0013120 secs]65.560:
[scrub symbol table, 0.0008345 secs]65.561: [scrub string table, 0.0001759 secs][1 CMS-remark: 10812086K(11901376K)] 11200006K(12514816K), 0.0110730 secs]
[Times: user=0.06 sys=0.00, real=0.01 secs] 2016-08-23T11:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start] 2016-08-23T11:23:08.485-0200: 65.588: [CMS-concurrent-sweep6: 0.027/0.027 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 2016-08-23T11:23:08.485-0200: 65.589: [CMS-concurrent-reset-start] 2016-08-23T11:23:08.497-0200: 65.601: [CMS-concurrent-reset7: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
这是CMS中两次stop-the-world事件中的一次。它有两个目标:一是标记老年代中所有的GC Roots;二是标记被年轻代中活着的对象引用的对象。
标记结果如下:
分析:
2016-08-23T11:23:07.321-0200: 64.421: [GC (CMS Initial Mark2[1 CMS-initial-mark: 10812086K3(11901376K)4] 10887844K5(12514816K)6, 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]7
这个阶段会遍历整个老年代并且标记所有存活的对象,从“初始化标记”阶段找到的GC Roots开始。并发标记的特点是和应用程序线程同时运行。并不是老年代的所有存活对象都会被标记,因为标记的同时应用程序会改变一些对象的引用等。
标记结果如下:
在上边的图中,一个引用的箭头已经远离了当前对象(current obj)
分析:
2016-08-23T11:23:07.321-0200: 64.425: [CMS-concurrent-mark-start]
2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-mark1: 035/0.035 secs2] [Times: user=0.07 sys=0.00, real=0.03 secs]3
这个阶段又是一个并发阶段,和应用线程并行运行,不会中断他们。前一个阶段在并行运行的时候,一些对象的引用已经发生了变化,当这些引用发生变化的时候,JVM会标记堆的这个区域为Dirty Card(包含被标记但是改变了的对象,被认为"dirty"),这就是 Card Marking。
如下图:
在pre-clean阶段,那些能够从dirty card对象到达的对象也会被标记,这个标记做完之后,dirty card标记就会被清除了,如下:
另外,一些必要的清扫工作也会做,还会做一些final remark阶段需要的准备工作;
2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start]
2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-preclean1: 0.016/0.016 secs2] [Times: user=0.02 sys=0.00, real=0.02 secs]3
又一个并发阶段不会停止应用程序线程。这个阶段尝试着去承担STW的Final Remark阶段足够多的工作。这个阶段持续的时间依赖好多的因素,由于这个阶段是重复的做相同的事情直到发生aboart的条件(比如:重复的次数、多少量的工作、持续的时间等等)之一才会停止。
2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start]
2016-08-23T11:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean1: 0.167/1.074 secs2] [Times: user=0.20 sys=0.00, real=1.07 secs]3
这个阶段很大程度的影响着即将来临的Final Remark的停顿,有相当一部分重要的 configuration options 和 失败的模式;
这个阶段是CMS中第二个并且是最后一个STW的阶段。该阶段的任务是完成标记整个年老代的所有的存活对象。由于之前的预处理是并发的,它可能跟不上应用程序改变的速度,这个时候,STW是非常需要的来完成这个严酷考验的阶段。
通常CMS尽量运行Final Remark阶段在年轻代是足够干净的时候,目的是消除紧接着的连续的几个STW阶段。
分析:
2016-08-23T11:23:08.447-0200: 65.5501: [GC (CMS Final Remark2) [YG occupancy: 387920 K (613440 K)3]65.550: [Rescan (parallel) , 0.0085125 secs]465.559: [weak refs processing, 0.0000243 secs]65.5595: [class unloading, 0.0013120 secs]65.5606: [scrub string table, 0.0001759 secs7][1 CMS-remark: 10812086K(11901376K)8] 11200006K(12514816K) 9, 0.0110730 secs10] [[Times: user=0.06 sys=0.00, real=0.01 secs]11
通过以上5个阶段的标记,老年代所有存活的对象已经被标记并且现在要通过Garbage Collector采用清扫的方式回收那些不能用的对象了。
和应用线程同时进行,不需要STW。这个阶段的目的就是移除那些不用的对象,回收他们占用的空间并且为将来使用。
如图:
分析:
2016-08-23T11:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start] 2016-08-23T11:23:08.485-0200: 65.588: [CMS-concurrent-sweep1: 0.027/0.027 secs2] [[Times: user=0.03 sys=0.00, real=0.03 secs] 3
这个阶段并发执行,重新设置CMS算法内部的数据结构,准备下一个CMS生命周期的使用。
2016-08-23T11:23:08.485-0200: 65.589: [CMS-concurrent-reset-start] 2016-08-23T11:23:08.497-0200: 65.601: [CMS-concurrent-reset1: 0.012/0.012 secs2] [[Times: user=0.01 sys=0.00, real=0.01 secs]3
https://plumbr.eu/handbook/garbage-collection-algorithms-implementations#concurrent-mark-and-sweep
http://www.cnblogs.com/zhangxiaoguang/p/5792468.html
"Allocation Failure" is a cause of GC cycle to kick.
"Allocation Failure" means that no more space left in Eden to allocate object. So, it is normal cause of young GC.
Older JVM were not printing GC cause for minor GC cycles.
"Allocation Failure" is almost only possible cause for minor GC. Another reason for minor GC to kick could be CMS remark phase (if +XX:+ScavengeBeforeRemark is enabled).
https://stackoverflow.com/questions/28342736/java-gc-allocation-failure
本文主要分析一个频繁GC (Allocation Failure)及young gc时间过长的case。
allocation failure为主
),平均270多毫秒,最大值将近7秒-XX:+UseParallelGC -XX:+UseParallelOldGC -XX:ParallelGCThreads=4 -XX:+UseAdaptiveSizePolicy -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=1073741824 -XX:NewSize=1073741824 -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -XX:+PrintGCTimeStamps
复制代码
jdk版本
java -version
java version "1.8.0_66"
Java(TM) SE Runtime Environment (build 1.8.0_66-b17)
Java HotSpot(TM) 64-Bit Server VM (build 25.66-b17, mixed mode)
复制代码
27.066: [Full GC (Metadata GC Threshold) [PSYoungGen: 19211K->0K(917504K)] [ParOldGen: 80K->18440K(1048576K)] 19291K->18440K(1966080K), [Metaspace: 20943K->20943K(1069056K)], 0.5005658 secs] [Times: user=0.24 sys=0.01, real=0.50 secs]
100.675: [Full GC (Metadata GC Threshold) [PSYoungGen: 14699K->0K(917504K)] [ParOldGen: 18464K->23826K(1048576K)] 33164K->23826K(1966080K), [Metaspace: 34777K->34777K(1081344K)], 0.7937738 secs] [Times: user=0.37 sys=0.01, real=0.79 secs]
195.073: [Full GC (Metadata GC Threshold) [PSYoungGen: 24843K->0K(1022464K)] [ParOldGen: 30048K->44782K(1048576K)] 54892K->44782K(2071040K), [Metaspace: 58220K->58220K(1101824K)], 3.7936515 secs] [Times: user=1.86 sys=0.02, real=3.79 secs]
242605.669: [Full GC (Ergonomics) [PSYoungGen: 67276K->0K(882688K)] [ParOldGen: 1042358K->117634K(1048576K)] 1109635K->117634K(1931264K), [Metaspace: 91365K->90958K(1132544K)], 22.1573804 secs] [Times: user=2.50 sys=3.51, real=22.16 secs]
复制代码
可以发现发生的4次full gc,前三次都是由于Metadata GC Threshold造成的,只有最后一次是由于Ergonomics引发的。
这里使用的是java8,参数没有明确指定metaspace的大小和上限,查看一下
jstat -gcmetacapacity 7
MCMN MCMX MC CCSMN CCSMX CCSC YGC FGC FGCT GCT
0.0 1136640.0 99456.0 0.0 1048576.0 12160.0 38009 16 275.801 14361.992
复制代码
相关参数
即元数据在当前分配大小的最大占用大小
),如果空闲比小于这个参数(即超过了最大占用大小
),那么将对meta space进行扩容。即元数据在当前分配大小的最小占用大小
),如果空闲比大于这个参数(即小于最小占用大小
),那么将对meta space进行缩容.由于没有设置,在机器上的默认值为:
java -XX:+PrintFlagsFinal | grep Meta
uintx InitialBootClassLoaderMetaspaceSize = 4194304 {product}
uintx MaxMetaspaceExpansion = 5451776 {product}
uintx MaxMetaspaceFreeRatio = 70 {product}
uintx MaxMetaspaceSize = 18446744073709547520 {product}
uintx MetaspaceSize = 21807104 {pd product}
uintx MinMetaspaceExpansion = 339968 {product}
uintx MinMetaspaceFreeRatio = 40 {product}
bool TraceMetadataHumongousAllocation = false {product}
bool UseLargePagesInMetaspace = false {product}
复制代码
可以看到MinMetaspaceFreeRatio为40,MaxMetaspaceFreeRatio为70,MetaspaceSize为20M,Full GC (Metadata GC Threshold)主要分为了三次
可以看到metaspace的阈值不断动态调整,至于具体调整的逻辑,官方文档貌似没讲,这里暂时不深究。只要没有超过Max值就没有致命影响,但是对于低延时的应用来讲,是要尽量避免动态调整引起的gc耗时,可以根据调优计算并设置初始阈值来解决。
这里可以到full gc的reason是Ergonomics,是因为开启了UseAdaptiveSizePolicy,jvm自己进行自适应调整引发的full gc
分析完full gc之后我们看下young gc,看log里头99%都是GC (Allocation Failure)造成的young gc。Allocation Failure表示向young generation(eden)给新对象申请空间,但是young generation(eden)剩余的合适空间不够所需的大小导致的minor gc。
Desired survivor size 75497472 bytes, new threshold 2 (max 15)
- age 1: 68407384 bytes, 68407384 total
- age 2: 12494576 bytes, 80901960 total
- age 3: 79376 bytes, 80981336 total
- age 4: 2904256 bytes, 83885592 total
复制代码
作用于下次gc
)。下次gc如果对象没释放的话,超过阈值的对象将晋升到old generation。59.463: [GC (Allocation Failure)
Desired survivor size 134217728 bytes, new threshold 7 (max 15)
[PSYoungGen: 786432K->14020K(917504K)] 804872K->32469K(1966080K), 0.1116049 secs] [Times: user=0.10 sys=0.01, real=0.20 secs]
复制代码
这里Desired survivor size这行下面并没有各个age对象的分布,那就表示此次gc之后,当前survivor区域并没有age小于max threshold的存活对象。而这里一个都没有输出,表示此次gc回收对象之后,没有存活的对象可以拷贝到新的survivor区。
gc之后survivor有对象的例子
jstat -gcutil -h10 7 10000 10000
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 99.99 90.38 29.82 97.84 96.99 413 158.501 4 14.597 173.098
11.60 0.00 76.00 29.83 97.84 96.99 414 158.511 4 14.597 173.109
11.60 0.00 77.16 29.83 97.84 96.99 414 158.511 4 14.597 173.109
0.00 13.67 60.04 29.83 97.84 96.99 415 158.578 4 14.597 173.176
0.00 13.67 61.05 29.83 97.84 96.99 415 158.578 4 14.597 173.176
复制代码
722914.974: [GC (Allocation Failure)
Desired survivor size 109576192 bytes, new threshold 15 (max 15)
[PSYoungGen: 876522K->8608K(941568K)] 1526192K->658293K(1990144K), 0.0102709 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
722975.207: [GC (Allocation Failure)
Desired survivor size 103284736 bytes, new threshold 15 (max 15)
[PSYoungGen: 843168K->39278K(941568K)] 1492853K->688988K(1990144K), 0.3607036 secs] [Times: user=0.17 sys=0.00, real=0.36 secs]
复制代码
里头有大于将近300次的gc的real time时间大于usr time + sys time。
墙钟时间包括各种非运算的等待耗时,例如等待磁盘I/O、等待线程阻塞,而CPU时间不包括这些耗时,但当系统有多CPU或者多核的话,多线程操作会叠加这些CPU时间,所以看到user或sys时间超过real时间是完全正常的。
user + sys 就是CPU花费的实际时间,注意这个值统计了所有CPU上的时间,如果进程工作在多线程的环境下,叠加了多线程的时间,这个值是会超出 real 所记录的值的,即 user + sys >= real 。
这里300多次real time时间大于usr time + sys time,表明可能有两个问题,一个是IO操作密集,另一个是cpu(
分配
)的额度不够。
-XX:PretenureSizeThreshold设置大对象直接进入年老代的阈值,当对象大小超过这个值时,将直接在年老代分配。
),不行则最后考虑在eden申请空间 从上面的分析可以看出,young generation貌似有点大,ygc时间长;另外每次ygc之后survivor空间基本是空的,说明新生对象产生快,生命周期也短,原本设计的survivor空间没有派上用场。因此可以考虑缩小下young generation的大小,或者改为G1试试。
关于-XX:+PrintTenuringDistribution有几个要点,要明确一下:
survivor
)gc之后打印
)对象的年龄就是他经历的MinorGC次数,对象首次分配时,年龄为0,第一次经历MinorGC之后,若还没有被回收,则年龄+1,由于是第一次经历MinorGC,因此进入survivor区。因此对象第一次进入survivor区域的时候年龄为1.
如果底下age的total大小大于Desired survivor size的大小,那么就代表了survivor空间溢出了,被填满,然后会重新计算threshold。
This post is the last teaser before we publish the Plumbr GC handbook next week. In this post, we will review how garbage collector logs look like and what useful information one can obtain from them. For this purpose, we have turned on GC logging for a JVM running with -XX:+UseSerialGC by using the following startup parameters:
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps
This resulted in the output similar to following:
2015-05-26T14:45:37.987-0200: 151.126: [GC (Allocation Failure) 151.126: [DefNew: 629119K->69888K(629120K), 0.0584157 secs] 1619346K->1273247K(2027264K), 0.0585007 secs] [Times: user=0.06 sys=0.00, real=0.06 secs] 2015-05-26T14:45:59.690-0200: 172.829: [GC (Allocation Failure) 172.829: [DefNew: 629120K->629120K(629120K), 0.0000372 secs]172.829: [Tenured: 1203359K->755802K(1398144K), 0.1855567 secs] 1832479K->755802K(2027264K), [Metaspace: 6741K->6741K(1056768K)], 0.1856954 secs] [Times: user=0.18 sys=0.00, real=0.18 secs]
The above short snippet from the GC logs exposes a lot of information about what is going on inside the JVM. As a matter of fact, in this snippet there were two Garbage Collection events taking place, one of them cleaning Young generation and the other one taking care of entire heap. Lets look at the first one of these events, a minor GC, taking place in Young generation:
2015-05-26T14:45:37.987-02001:151.1262:[GC3(Allocation Failure4) 151.126: [DefNew5:629119K->69888K6(629120K)7, 0.0584157 secs]1619346K->1273247K8(2027264K)9,0.0585007 secs10][Times: user=0.06 sys=0.00, real=0.06 secs]11
From the above snippet we can understand exactly what was happening with memory consumption inside the JVM during the GC event. Before this collection heap usage totaled at 1,619,346K. Out of this amount, the Young generation consumed 629,119K. From this we can calculate the Old generation usage being equal to 990,227K.
A more important conclusion is hidden in the next batch of numbers, indicating that after the collection young generation usage decreased by 559,231K, but total heap usage decreased only by 346,099K. From this we can again derive that 213,132K of objects had been promoted from Young generation to Old.
This GC event can be illustrated with the following snapshots depicting memory usage right before the GC started and right after it finished:
If you found the content to be useful, check out the entire Java Garbage Collection Handbook where this example was extracted from.
https://plumbr.io/blog/garbage-collection/understanding-garbage-collection-logs
标签:失败 ges red 核数 拷贝 version read form 类型
原文地址:https://www.cnblogs.com/softidea/p/10044785.html