jvm GC日志解读

简介: 0.产生日志 0.1 IDE 运行下面代码会得到gc日志。 0.2 server -Xloggc:../gclogdir/logc.txt   指定gc日志的打印位置,注意必须指定到文件,不能为目录。 当应用重启时,会产生新的gc.log,旧的gc.log自动被重命名为形如 "gc.log.20161103103532"这样的格式。 1.Parallel Scave

0.产生日志

0.1 IDE

运行下面代码会得到gc日志。

0.2 server

-Xloggc:../gclogdir/logc.txt  
指定gc日志的打印位置,注意必须指定到文件,不能为目录。
当应用重启时,会产生新的gc.log,旧的gc.log自动被重命名为形如 " gc.log.20161103103532"这样的格式。

1.Parallel Scavenge

这是一款年轻代GC器。
293.271: [GC [PSYoungGen: 300865K->6577K(310720K)] 392829K->108873K(417472K), 0.0176464 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
每行是一次GC的信息,以本条为例,解读如下。
293.271是本次GC发生的时间,从jvm启动起开始计时,单位为秒。
GC表示这是一次Minor GC(新生代垃圾收集)。
[PSYoungGen: 300865K->6577K(310720K)] 。格式为[PSYoungGen: a->b(c)].
PSYoungGen,表示新生代使用的是多线程垃圾收集器Parallel Scavenge。a为GC前新生代已占用空间,b为GC后新生代已占用空间。新生代又细分为一个Eden区和两个Survivor区,Minor GC之后Eden区为空,b就是Survivor中已被占用的空间。括号里的c表示整个年轻代的大小。
392829K->108873K(417472K),格式为x->y(z)。x表示GC前堆的已占用空间,y表示GC后堆已占用空间,z表示堆的总大小。
由新生代和Java堆占用大小可以算出年老代占用空间,此例中就是417472K-310720K=106752K。
0.0176464 secs表示本次GC所消耗的时间。
[Times: user=0.06 sys=0.00, real=0.01 secs] 提供cpu使用及时间消耗,user是用户态消耗的cpu时间,sys是系统态消耗的cpu时间,real是实际的消耗时间。

2.Parallel Old

这是Parallel Scavenge收集器的老年代版本。
0.107: [Full GC (Ergonomics) [PSYoungGen: 1664K->0K(8192K)] [ParOldGen: 8200K->9739K(10240K)] 9864K->9739K(18432K), [Metaspace: 2508K->2508K(1056768K)], 0.0038104 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

3.CMS

2016-11-02T10:17:27.849+0800: 48234.161: [GC [1 CMS-initial-mark: 1781099K(2097152K)] 1962885K(4019584K), 0.0530810 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 
2016-11-02T10:17:27.903+0800: 48234.214: [CMS-concurrent-mark-start]
2016-11-02T10:17:30.294+0800: 48236.606: [CMS-concurrent-mark: 2.384/2.391 secs] [Times: user=2.55 sys=0.04, real=2.39 secs] 
2016-11-02T10:17:30.294+0800: 48236.606: [CMS-concurrent-preclean-start]
2016-11-02T10:17:30.303+0800: 48236.615: [CMS-concurrent-preclean: 0.009/0.009 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2016-11-02T10:17:30.303+0800: 48236.615: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-11-02T10:17:35.525+0800: 48241.836: [CMS-concurrent-abortable-preclean: 5.216/5.221 secs] [Times: user=5.41 sys=0.06, real=5.23 secs] 
2016-11-02T10:17:35.526+0800: 48241.837: [GC[YG occupancy: 289491 K (1922432 K)]48241.838: [Rescan (parallel) , 0.0558290 secs]48241.893: [weak refs processing, 0.0063180 secs]48241.900: [class unloading, 0.0323730 secs]48241.932: [scrub symbol & string tables, 0.0297790 secs] [1 CMS-remark: 1781099K(2097152K)] 2070590K(4019584K), 0.1310790 secs] [Times: user=0.26 sys=0.00, real=0.13 secs] 
2016-11-02T10:17:35.657+0800: 48241.969: [CMS-concurrent-sweep-start]
2016-11-02T10:17:36.176+0800: 48242.488: [CMS-concurrent-sweep: 0.503/0.519 secs] [Times: user=0.52 sys=0.01, real=0.52 secs] 
2016-11-02T10:17:36.176+0800: 48242.488: [CMS-concurrent-reset-start]
2016-11-02T10:17:36.183+0800: 48242.495: [CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

一共经历 了4个阶段。需要关注的耗时为 初始标记重新标记,低于0.2秒就没什么问题。
[CMS-xxx   1781099K(2097152K)] 1962885K(4019584K),形如[CMS-xxx   a(b)] c(d)
a: old区占用大小
b: old区总大小
c: heap占用大小
d: heap 总大小
[YG occupancy: 289491 K (1922432 K)] ,形如 [YG occupancy: a (b)]
a: young区占用大小
b: yong区总大小

3.1 CMS-initial-mark

此阶段暂停工作线程,用时0.05秒。

3.2 CMS-concurrent-mark

与工作线程并发运行。

3.3 CMS-remark 

此阶段暂停工作线程,用时0.13秒。

3.4 CMS-concurrent-sweep

与工作线程并发运行。

4. -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC

2016-11-03T14:41:12.877+0800: 14740.294: [GC 14740.295: [ParNew
Desired survivor size 178946048 bytes, new threshold 16 (max 20)
- age   1:   12374344 bytes,   12374344 total
- age   2:    2538032 bytes,   14912376 total
- age   3:    2081880 bytes,   16994256 total
- age   4:     290784 bytes,   17285040 total
- age   5:     787312 bytes,   18072352 total
- age   6:     450520 bytes,   18522872 total
- age   7:     335016 bytes,   18857888 total
- age   8:     661552 bytes,   19519440 total
- age   9:    1021048 bytes,   20540488 total
- age  10:     130816 bytes,   20671304 total
- age  11:     172536 bytes,   20843840 total
- age  12:     384968 bytes,   21228808 total
- age  13:     556328 bytes,   21785136 total
- age  14:      99112 bytes,   21884248 total
- age  15:   19091864 bytes,   40976112 total
: 3551236K->58224K(3844800K), 0.0259700 secs] 5186234K->1693221K(5941952K), 0.0262100 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
Heap after GC invocations=73 (full 2):
 par new generation   total 3844800K, used 58224K [0x0000000668000000, 0x0000000768000000, 0x0000000768000000)
  eden space 3495296K,   0% used [0x0000000668000000, 0x0000000668000000, 0x000000073d560000)
  from space 349504K,  16% used [0x0000000752ab0000, 0x000000075638c030, 0x0000000768000000)
  to   space 349504K,   0% used [0x000000073d560000, 0x000000073d560000, 0x0000000752ab0000)
 concurrent mark-sweep generation total 2097152K, used 1634997K [0x0000000768000000, 0x00000007e8000000, 0x00000007e8000000)
 concurrent-mark-sweep perm gen total 274488K, used 197983K [0x00000007e8000000, 0x00000007f8c0e000, 0x0000000800000000)
}
{Heap before GC invocations=73 (full 2):
 par new generation   total 3844800K, used 3553520K [0x0000000668000000, 0x0000000768000000, 0x0000000768000000)
  eden space 3495296K, 100% used [0x0000000668000000, 0x000000073d560000, 0x000000073d560000)
  from space 349504K,  16% used [0x0000000752ab0000, 0x000000075638c030, 0x0000000768000000)
  to   space 349504K,   0% used [0x000000073d560000, 0x000000073d560000, 0x0000000752ab0000)
 concurrent mark-sweep generation total 2097152K, used 1634997K [0x0000000768000000, 0x00000007e8000000, 0x00000007e8000000)
 concurrent-mark-sweep perm gen total 274488K, used 197985K [0x00000007e8000000, 0x00000007f8c0e000, 0x0000000800000000)


相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
目录
相关文章
|
3天前
|
监控 Java Linux
JVM工作原理与实战(三十七):Shenandoah GC和ZGC
JVM作为Java程序的运行环境,其负责解释和执行字节码,管理内存,确保安全,支持多线程和提供性能监控工具,以及确保程序的跨平台运行。本文主要介绍了垃圾回收器的技术演进、Shenandoah GC、ZGC等内容。
10 0
|
3天前
|
存储 缓存 监控
JVM工作原理与实战(三十四):解决GC问题的方法
JVM作为Java程序的运行环境,其负责解释和执行字节码,管理内存,确保安全,支持多线程和提供性能监控工具,以及确保程序的跨平台运行。本文主要介绍了常见的垃圾回收(GC)模式、解决GC问题的方法(优化基础JVM参数、减少对象产生、更换垃圾回收器、优化垃圾回收器的参数)等内容。
|
3天前
|
Prometheus 监控 Cloud Native
JVM工作原理与实战(三十三):监控GC过程的工具
JVM作为Java程序的运行环境,其负责解释和执行字节码,管理内存,确保安全,支持多线程和提供性能监控工具,以及确保程序的跨平台运行。本文主要介绍了jstat工具、VisualVM插件、Prometheus + Grafana、GC日志等内容。
14 0
|
3天前
|
监控 负载均衡 算法
JVM工作原理与实战(三十二):GC调优
JVM作为Java程序的运行环境,其负责解释和执行字节码,管理内存,确保安全,支持多线程和提供性能监控工具,以及确保程序的跨平台运行。本文主要介绍了GC调优、GC调优的核心指标等内容。
|
5天前
|
Java 程序员 Python
JVM的垃圾回收机制(GC机制)
Java的JVM实行自动垃圾回收机制(GC),主要针对堆中的对象。当对象无引用可达时,被视为垃圾。垃圾回收包含“找垃圾”和“回收垃圾”两步。找垃圾通过引用计数(非Java使用)和可达性分析(Java使用)来识别无用对象。可达性分析从根对象开始遍历,未被标记的对象视为垃圾。回收垃圾常用标记清除方法,但可能导致内存碎片。此过程消耗资源,且碎片化影响内存分配效率。
|
2月前
|
存储 算法 Java
精华推荐 | 【JVM深层系列】「GC底层调优专题」一文带你彻底加强夯实底层原理之GC垃圾回收技术的分析指南(GC原理透析)
精华推荐 | 【JVM深层系列】「GC底层调优专题」一文带你彻底加强夯实底层原理之GC垃圾回收技术的分析指南(GC原理透析)
57 0
|
2月前
|
运维 监控 数据可视化
九、GC收集日志
九、GC收集日志
36 4
九、GC收集日志
|
3月前
|
算法 Java
深入理解JVM - 解读GC日志
深入理解JVM - 解读GC日志
53 0
|
4天前
|
C++
JNI Log 日志输出
JNI Log 日志输出
12 1
|
4天前
|
存储 运维 大数据
聊聊日志硬扫描,阿里 Log Scan 的设计与实践
泛日志(Log/Trace/Metric)是大数据的重要组成,伴随着每一年业务峰值的新脉冲,日志数据量在快速增长。同时,业务数字化运营、软件可观测性等浪潮又在对日志的存储、计算提出更高的要求。