GC日志中times表示什么含义？_问答_ThinkSAAS
GC日志中times表示什么含义？
GC日志中times表示什么含义？
最近系统出现了运行一段时间后就无法响应的问题，表现就是浏览器的圈圈一直在转，页面没有加载出来。
查看GC的日志，有一些疑问是关于日志中的时间，如下面部分日志：
: [GC[YG occupancy: 8729512 K (9216000 K)]: [Rescan (parallel) , 7.6001940 secs]: [weak refs processing, 0.0000190 secs] [1 CMS-remark: 6904K)] 52904K), 7.6004580 secs] [Times: user=86.06 sys=0.42, real=7.60 secs]
: [GC : [ParNew: 8766574K-&16000K), 1.9300940 secs] K-&578944K), 1.9309390 secs] [Times: user=13.68 sys=0.07, real=1.93 secs]
我有两个问题：
这两段日志中后面Times的3个时间分别是什么含义？
因为看到第一个user有86秒多，不知道这个有没有什么影响？
我是刚进新公司，系统最近老是出现无响应，自己就看了日志。我看了下jvm的参数配置，觉得有问题，各位看看这些参数有问题么：
-server -Xms10200m -Xmx13200m -Xmn10000m -XX:MaxPermSize=4040m -XX:+UseConcMarkSweepGC -XX:+DisableExplicitGC -Dsun.reflect.inflationThreshold= -XX:PermSize=3000m -XX:+PrintGCDetails -Xloggc:/data/resin/gc_detail.log -verbose:class -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/resin/heapdump.bin
再贴一段CMS的GC日志：
800.344: [CMS-concurrent-mark-start]
800.733: [CMS-concurrent-mark: 0.312/0.389 secs] [Times: user=1.82 sys=0.03, real=0.39 secs]
800.734: [CMS-concurrent-preclean-start]
800.750: [CMS-concurrent-preclean: 0.016/0.017 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
800.750: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 809.299: [CMS-concurrent-abortable-preclean: 8.527/8.549 secs] [Times: user=10.60 sys=0.09, real=8.55 secs]
809.299: [GC[YG occupancy: 1120816 K (9216000 K)]809.300: [Rescan (parallel) , 0.2415390 secs]809.541: [weak refs processing, 0.0000210 secs] [1 CMS-remark: 4800K)] 20800K), 0.2416930 secs] [Times: user=2.91 sys=0.01, real=0.24 secs]
809.542: [CMS-concurrent-sweep-start]
809.674: [CMS-concurrent-sweep: 0.132/0.132 secs] [Times: user=0.15 sys=0.00, real=0.13 secs]
809.674: [CMS-concurrent-reset-start]
809.879: [CMS-concurrent-reset: 0.205/0.205 secs] [Times: user=0.12 sys=0.20, real=0.21 secs]
810.546: [GC [1 CMS-initial-mark: 9288K)] 25288K), 1.1555440 secs] [Times: user=1.15 sys=0.00, real=1.16 secs]
811.702: [CMS-concurrent-mark-start]
811.951: [CMS-concurrent-mark: 0.245/0.249 secs] [Times: user=1.02 sys=0.01, real=0.25 secs]
811.951: [CMS-concurrent-preclean-start]
811.961: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
811.961: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 820.526: [CMS-concurrent-abortable-preclean: 8.556/8.565 secs] [Times: user=9.18 sys=0.09, real=8.56 secs]
820.528: [GC[YG occupancy: 1169864 K (9216000 K)]820.528: [Rescan (parallel) , 0.7405100 secs]821.269: [weak refs processing, 0.0000120 secs] [1 CMS-remark: 9288K)] 25288K), 0.7406440 secs] [Times: user=8.58 sys=0.03, real=0.74 secs]
821.270: [CMS-concurrent-sweep-start]
821.401: [CMS-concurrent-sweep: 0.131/0.131 secs] [Times: user=0.16 sys=0.00, real=0.14 secs]
821.401: [CMS-concurrent-reset-start]
这些时间是GC花费的时间，user是用户态耗费的时间，sys是内核态耗费的时间，real是整个过程实际花费的时间。user+sys是CPU时间，每个CPU core单独计算，所以这个时间可能会是real的好几倍。
从你的日志看，一次ParNew居然回收掉了8G多的内存，程序真得要好好优化一下了。
几点优化的建议：
Xms可以和Xmx设成一样大小，这样可以避免GC之后重新分配内存
Xmn太大，这其实是你遇到的问题的根本原因，官方推荐配置为整个堆的3/8，对于你的情况，可以试试-Xmn=4G
86秒的意思是指一个CPU需要的用户态时间, 楼主应该关注的是 real 的 7.6 秒时间.
因为有多核的关系, 所以 real 时间肯定比 user + sys 少的.
楼主给的 CMS GC 的日志并不全, 在此之前应该还有 GC 的日志.
单看这个 GC 日志, 就需要 7 秒多, 而且基本上都是发生在 CMS 的 remark 阶段, 而且这时候 Young 区已经使用了 90% 的内存, 可能是内存涨的太快, 中断了 CMS 前面的工作, 导致 remark 时间过长.
影响肯定很大的, 因为 remark 是 stop the world 的(既然选择了CMS, 说明应用还是很重视响应时间的), 建议楼主查找原因.
添加你想要问的问题
PHP开发框架
开发工具/编程工具
服务器环境
ThinkSAAS商业授权：
ThinkSAAS为用户提供有偿个性定制开发服务
ThinkSAAS将为商业授权用户提供二次开发指导和技术支持
让ThinkSAAS更好，把建议拿来。
开发客服微信这个是之前处理过的一个线上问题，处理过程断断续续，经历了两周多的时间，中间各种尝试，总结如下。这篇文章分三部分：
1、问题的场景和处理过程；2、GC的一些理论东西；3、看懂GC的日志
先说一下问题吧
问题场景：线上机器在半夜会推送一个700M左右的数据，这个时候有个数据置换的过程，也就是说有700M*2的数据在heap区域中，线上系统超时比较多，导致了很严重（严重程度就不说了）的问题。
问题原因：看日志，系统接口超时的时候，系统出现了FullGC，这个时候stop-the-world了，也就停机了。分析gc的日志，发现有promotion failed，根据FullGC触发的条件，这个时候就会出现FullGC了。日志如下：
: [ParNew (promotion failed): 1877376K-&77376K),
15.7989680
: [CMS: 2144171K-&46304K),
10.4200280
s] 3514052K-&23680K), [CMS Perm : 119979K-&0132K)],
26.2193500
secs] [Times: user=
问题解决：中间调整过几次，先搞了几台机器做了验证，后来逐步推广的。
1、调大heap区，由原来的4g，调整到5g，young区的大小不变，还是2g，这时候old区就由2g变为3g了（这样保证old区有足够的空间）；
2、设置-XX：UseCMSInitiatingOccupancyOnly，其实这个不关这个问题，只是发现半夜CMS进行的有点频繁，就禁止掉了悲观策略；
3、设置CMS区回收的比例，从80%调整到75%，让old区尽早的进行，有足够的空间剩余；
为什么要有GC（垃圾回收）？
JVM通过GC来回收堆和方法区中的内存，GC的基本原理就是找到程序中不再被使用的对象，然后回收掉这些对象占用的内存。
主要的收集器有哪些？
引用计数器和跟踪计数器两种。
引用计数器记录对象是否被引用，当计数器为零时，说明对象已经不再被使用，可以进行回收。java中的对象有复杂的引用关系，不是很适合引用计数器，所以sun jdk中并没有实现这种GC方式。
跟踪收集器，全局记录数据的引用状态，基于一定的条件触发。执行的时候，从根集合开始扫描对象的引用关系，主要有复制（copying）、标记-清除（Mark-Sweep）、标记-压缩(Mark-Compact)那种算法。
跟踪计数器的三种算法简介？
复制：从根集合搜扫描出存活的对象，然后将存活的对象复制到一块新的未使用的空间中，当要回收的空间中存活的对象较少时，比较高效；
标记清除：从根集合开始扫描，对存活的对象进行标记，比较完毕后，再扫描整个空间中未标记的对象，然后进行回收，不需要对对象进行移动；
标记压缩：标记形式和“标记清除”一样，但是回收不存活的对象后，会把所有存活的对象在内存空间中进行移动，好处是减少了内存碎片，缺点是成本比较高；
java内存区域的形式是啥样的？
这里就不再介绍了，之前有一篇文章中专门介绍这个的（
新生代可用的GC？
新生代中对象存活的时间比较短，因此给予Copying算法实现，Eden区域存放新创建的对象，S0和S1区其中一块用于存放在Minor GC的时候作为复制存活对象的目标空间，另外一块清空。
串行GC（Serial GC）比较适合单CPU的情况，可以通过-XX：UseSerialGC来强行制定；
并行回收GC（Parallel Scavenge），启动的时候按照设置的参数来划定Eden/S0/S1区域的大小，但是在运行时，会根据Minor GC的频率、消耗时间来动态调整三个区域的大小，可以用过-XX：UseAdaptiveSizePolicy来固定大小，不进行动态调整；
并行GC（ParNew）划分Eden、S1、S0的区域上和串行GC一样。并行GC需要配合旧生代使用CMS GC（这是他和并行回收GC的不同）（如果配置了CMS GC的方式，那么新生代默认采取的就是并行GC的方式）；
啥时候会触发Minor GC？
当Eden区域分配内存时，发现空间不足，JVM就会触发Minor GC，程序中System.gc()也可以来触发。
旧生代可用的GC方式有哪几种？
串行GC（Serial MSC）、并行GC（Parallel MSC）、并发GC（CMS）；
采用CMS时候，新生代必须使用Serial GC或者ParNew GC两种。CMS共有七个步骤，只有Initial Marking和Final Marking两个阶段是stop-the-world的，其他步骤均和应用并行进行。持久代的GC也采用CMS，通过-XX：CMSPermGenSweepingEnabled -XX：CMSClassUnloadingEnabled来制定。在采用cms gc的情况下，ygc变慢的原因通常是由于old gen出现了大量的碎片。
为啥CMS会有内存碎片，如何避免？
由于在CMS的回收步骤中，没有对内存进行压缩，所以会有内存碎片出现，CMS提供了一个整理碎片的功能，通过-XX：UseCompactAtFullCollection来启动此功能，启动这个功能后，默认每次执行Full GC的时候会进行整理（也可以通过-XX：CMSFullGCsBeforeCompaction=n来制定多少次Full GC之后来执行整理），整理碎片会stop-the-world.
啥时候会触发CMS GC？
1、旧生代或者持久代已经使用的空间达到设定的百分比时（CMSInitiatingOccupancyFraction这个设置old区，perm区也可以设置）；
2、JVM自动触发(JVM的动态策略，也就是悲观策略)（基于之前GC的频率以及旧生代的增长趋势来评估决定什么时候开始执行），如果不希望JVM自行决定，可以通过-XX：UseCMSInitiatingOccupancyOnly=true来制定；
3、设置了 -XX：CMSClassUnloadingE考虑nabled 这个则考虑Perm区；
啥时候会触发Full GC？
一、旧生代空间不足：java.lang.outOfMemoryError：java heap space；
二、Perm空间满：java.lang.outOfMemoryError：PermGen space；
三、CMS GC时出现promotion failed
和concurrent
mode failure（Concurrent mode failure发生的原因一般是CMS正在进行，但是由于old区内存不足，需要尽快回收old区里面的死的java对象，这个时候foreground gc需要被触发，停止所有的java线程，同时终止CMS，直接进行MSC。）；
四、统计得到的minor GC晋升到旧生代的平均大小大于旧生代的剩余空间；
五、主动触发Full GC（执行jmap -histo:live [pid]）来避免碎片问题；
为啥heap小于3g不建议使用CMS GC这种方式？
毕大师的这篇文章讲的很清楚。
1、触发比例不好设置，设置大了，那么剩余的空间就少了很多，设置小了，那old区还没放置多少东西，就要进行回收了；
2、CMS进行的时候，是并行的，也就意味着如果过于频繁的话，会和应用的强占CPU；
3、CMS会有内存 碎片问题；
4、YGC的速率变慢（由于CMS GC的实现原理，导致对象从新生代晋升到旧生代时，寻找哪里能放下的这个步骤比ParallelOld GC是慢一些的，因此就导致了YGC速度会有一定程度的下降。）；
JVM的悲观策略是啥？
所谓的悲观策略（
我们性能测试团队一个同学分析的案例），就是JVM不按照JVM指定的参数来进行CMS GC，而是根据内存情况以及之前回收的方式动态调整，自行进行GC。旧生代剩余的空间（available）大于新生代中使用的空间（max_promotion_in_bytes），或者大于之前平均晋升的old的大小（av_promo），返回false。cms gc是每隔一个周期（默认2s）就会做一次这个检查，如果为false，则不执行YGC，而触发cms gc。
我们经常使用的是啥GC方式？
针对目前线上机器的情况（8G的物流内存），heap区一般设置在4g或者5g左右，一般是使用CMS GC，这时候：
young区使用ParNew（并行GC），Old+Perm(需要单独设置)使用CMS，整个堆（young+old+perm）使用MSC（（Mark Sweep Compact）是CMS GC算法的Full GC算法,单线程回收整个堆，回收过程有严格的步骤。压缩，所以回收完理论上任何Generation都不会有内存碎片）压缩回收的方式。
读懂GC日志？
基本上都是这种格式：回收前区域占用的大小-&回收后区域占用的大小（区域设置的大小），占用的时间
1、promotion failed的一段日志
: [ParNew (promotion failed): 1877376K-&77376K),
15.7989680
: [CMS: 2144171K-&46304K),
10.4200280
s] 3514052K-&23680K), [CMS Perm : 119979K-&0132K)],
26.2193500
secs] [Times: user=
解释如下：
1877376K-&77376K),
15.7989680
2144171K-&46304K),
10.4200280
3514052K-&23680K)
heap区情况
119979K-&0132K)],
26.2193500
perm区情况
[Times: user=
整个过程的时间消耗
2、一段正常的CMS的日志
CMS-initial-mark: 46304K)] 23680K),
secs] [Times: user=
: [CMS-concurrent-mark-start]
: [CMS-concurrent-mark:
secs] [Times: user=
: [CMS-concurrent-preclean-start]
: [CMS-concurrent-preclean:
secs] [Times: user=
: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time
: [CMS-concurrent-abortable-preclean:
secs] [Times: user=
: [GC[YG occupancy:
: [Rescan (parallel) ,
: [weak refs processing,
ss unloading,
: [scrub symbol & string tables,
CMS-remark: 46304K)] 23680K),
secs] [Times: user=
: [CMS-concurrent-sweep-start]
: [CMS-concurrent-sweep:
secs] [Times: user=
: [CMS-concurrent-reset-start]
: [CMS-concurrent-reset:
secs] [Times: user=
这个是一个正常的CMS的日志，共分为七个步骤，重点关注initial-mark和remark这两个阶段，因为这两个是停机的。
A、[GC [1 CMS-initial-mark: 46304K)] 23680K), 0.1390860 secs] [Times: user=0.14 sys=0.00, real=0.14 secs]
各个数据依次表示标记前后old区的所有对象占内存大小和old的capacity，整个JavaHeap（不包括perm）所有对象占内存总的大小和JavaHeap的capacity。
B、T04:00:25.253+.177: [GC[YG occupancy: 573705 K (1877376 K)]: [Rescan (parallel) , 0.3685690 secs]: [weak refs processing, 0.0024100 secs]: [class unloading, 0.0177600 secs]: [scrub symbol & string tables, 0.0154090 secs] [1 CMS-remark: 46304K)] 23680K), 0.4229380 secs] [Times: user=1.41 sys=0.01, real=0.43 secs]
Rescan (parallel)表示的是多线程处理young区和多线程扫描old+perm的卡表的总时间， parallel 表示多GC线程并行。
weak refs processing 处理old区的弱引用的总时间，用于回收native memory。
class unloading 回收SystemDictionary消耗的总时间。
3、一段正常的Young GC的日志
: [ParNew: 1791076K-&77376K),
secs] 2988366K-&23680K),
secs] [Times: user=
ParNew这个表明是并行的回收方式，具体的分别是young区、整个heap区的情况；
4、一段通过system.gc产生的FullGC日志
: [Full GC (System)
: [CMS: 943772K-&220K(2596864K),
secs] 1477000K-&220K(4061184K), [CMS Perm : 3361K-&K)],
secs] [Times: user=
解释如下：
Full GC (System)意味着这是个system.gc调用产生的MSC。
“943772K-&220K(2596864K), 2.3424070 secs”表示：这次MSC前后old区内总对象大小，old的capacity及这次MSC耗时。
“1477000K-&220K(4061184K)”表示：这次MSC前后JavaHeap内总对象大小，JavaHeap的capacity。
“3361K-&K)], 2.3425410 secs”表示：这次MSC前后Perm区内总对象大小，Perm区的capacity。
5、一个特殊的GC日志，根据动态计算直接进行的FullGC（MSC的方式）
: [ParNew: 471872K-&1872K),
: [CMS: 366666K-&4288K),
27.0023450
secs] 838538K-&6160K), [CMS Perm : 3196K-&K)],
27.0025170
ParNew的时间特别短，jvm在minor gc前会首先确认old是不是足够大，如果不够大，这次young gc直接返回，进行MSC。
参考文章：
JVM参数大全
CMS GC不建议3G的原因
毕玄的《分布式java基础》
相关 [cms gc 问题] 推荐：
- ITeye博客
这个是之前处理过的一个线上问题，处理过程断断续续，经历了两周多的时间，中间各种尝试，总结如下. 1、问题的场景和处理过程；2、GC的一些理论东西；3、看懂GC的日志. 问题场景：线上机器在半夜会推送一个700M左右的数据，这个时候有个数据置换的过程，也就是说有700M*2的数据在heap区域中，线上系统超时比较多，导致了很严重（严重程度就不说了）的问题.
- 编程语言 - ITeye博客
声明：原文转自http://www.blogjava.net/killme2008/archive//295931.html，该文所有合法权益归原作者所有，仅在此做技术分享使用. 首先感谢阿宝同学的帮助，我才对这个gc算法的调整有了一定的认识，而不是停留在过去仅仅了解的阶段. 在读过sun的文档和跟阿宝讨论之后，做个小小的总结.
- 舒の随想日记
某台机器的内存比较大，之前的JVM参数是4G的堆，在压测过程中发现当QPS上来以后，Full GC会开始抬头，YoungGC的频率就不用说了，比较高. 观察GC日志和jstat -gcutil，感觉是QPS在峰值的时候对象创建比较多，也有大对象产生. 于是打算加大堆的大小来延缓GC的时机，并且有一些GC参数的优化，反复调整后找到了一个适合我们的参数（没有一个best的参数，还是得按照应用的的情况去测量，最好是一遍压测一遍调整，最终找到一个best fit的参数组）.
- Java译站
这篇文章正好接上前一年我们做的一次现实环境下不同GC算法性能比较的试验. 这次我们仍然进行同样的试验，不过增加了对G1回收器的测试，并且在多个平台进行测试. 今年我们测试的垃圾回收器有如下几个：. 我们使用现成的
JIRA任务来运行这个测试. 选择它的原因非常简单——除去Minecraft（一款著名网游），愤怒的小鸟，以及Eclipse不说， JIRA应该是最著名的Java应用程序了.
- JavaRanger - 专注JAVA高性能程序开发、JVM、Mysql优化、算法
上周开始系统在业务高峰期一直收到Full gc报警，监控显示fgc频繁，下图是监控图，左边红框是优化前效果，右边是优化后，优化后fgc基本为0. 1.查看gc日志，发现old区fgc后大小没有变化，如下图：. 2.去线上dump内存看是什么对象，用memory analyzer分析，Retained Size竟然有2.4G，全是sun.awt.SunToolkit这个对象，其实到这一步已经可以确定是什么问题了，只是自己对系统不是很熟悉，导致定位具体的问题代码花了一些时间.
- C++博客-首页原创精华区
通常情况下GC分为两种，分别是：扫描GC(Tracing GC)和引用计数GC(Reference counting GC). 其中扫描GC是比较常用的GC实现方法，其原理是：把正在使用的对象找出来，然后把未被使用的对象释放. 而引用计数GC则是对每个对象都添加一个计数器，引用增加一个计数器就加一，引用减少一个计数器就减一，当计数器减至零时，把对象回收释放.
- 码蜂笔记
不同的JVM及其选项会输出不同的日志. 生成下面日志使用的选项：
-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails
-Xloggc:d:/GClogs/tomcat6-gc.log. 最前面的数字
4.445 代表虚拟机启动以来的秒数.
- loudly - BlueDavy之技术Blog
前两天碰到一个很诡异的GC频繁的现象，走了不少弯路，N种方法查找后才终于查明原因了，在这篇blog中记录下，以便以后碰到这类问题时能更快的解决. 前两天一位同学找到我，说有个应用在启动后就一直Full GC，拿到GC log先看了下，确实是非常的诡异，截取的部分log如下：. 这个日志中诡异的地方在于每次Full GC的时候旧生代都还有很多的空间，于是去看来下启动参数，此时的启动参数如下：.
- 并发编程网 -
Java程序员在编码过程中通常不需要考虑内存问题，JVM经过高度优化的GC机制大部分情况下都能够很好地处理堆(Heap)的清理问题. 以至于许多Java程序员认为，我只需要关心何时创建对象，而回收对象，就交给GC来做吧. 甚至有人说，如果在编程过程中频繁考虑内存问题，是一种退化，这些事情应该交给编译器，交给虚拟机来解决.
- Java - 编程语言 - ITeye博客
Java中的GC有哪几种类型. 虚拟机运行在Client模式的默认值，打开此开关参数后，. 使用Serial+Serial Old收集器组合进行垃圾收集. 打开此开关参数后，使用ParNew+Serial Old收集器组合进行垃圾收集. 打开此开关参数后，使用ParNew+CMS+Serial Old收集器组合进行垃圾收集.
坚持分享优质有趣的原创文章，并保留作者信息和版权声明，任何问题请联系：@。