Skip to content

Commit 7c1764c

Browse files
sxlong0205sxlong0205
committed
完成第26章-分析GC日志
1 parent 3798cbc commit 7c1764c

2 files changed

Lines changed: 184 additions & 1 deletion

File tree

‎JVM/img/image-20220521230634169.png‎

127 KB
Loading

‎JVM/第26章-分析GC日志.md‎

Lines changed: 184 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1 +1,184 @@
1-
# 分析GC日志
1+
# 分析GC日志
2+
3+
## GC 日志参数
4+
5+
- `-verbose:gc`：输出 GC 日志信息，默认输出到标准输出。
6+
- `-XX:+PrintGC`：输出 GC 日志。类似：`-verbose:gc`。
7+
- `-XX:+PrintGCDetails`：在发生垃圾回收时打印内存回收详细的日志，并在进程退出时输出当前内存各区域分配情况。
8+
- `-XX:+PrintGCTimeStamps`：输出 GC 发生时的时间戳。
9+
- `-XX:+PrintGCDateStamps`：输出 GC 发生时的时间戳（以日期的形式，如 2013-05-04T21:53:59.534+0800）。
10+
- `-XX:+PrintHeapAtGC`：每一次 GC 前和 GC 后，都打印堆信息。
11+
- `-Xloggc:<file>`：表示把 GC 日志写入到一个文件中去，而不是打印到标准输出中。
12+
13+
## GC 日志格式
14+
15+
### GC 分类
16+
17+
针对 HotSpot VM 的实现，它里面的 GC 按照回收区域又分为两大种类型：一种是部分收集（Partial GC），一种是整堆手机（Full GC）。
18+
19+
- 部分收集：不是完整收集整个 Java 堆的垃圾收集，其中又分为：
20+
- 新生代收集（Minor GC / Young GC）：只是新生代（Eden / S0 / S1）的垃圾收集。
21+
- 老年代收集（Major GC / Old GC）：只是老年代的垃圾收集。
22+
- 目前，只有 CMS GC 会有单独收集老年代的行为。
23+
- 注意，很多时候 Major GC 会和 Full GC 混淆使用，需要具体分辨是老年代回收还是整堆回收。
24+
- 混合收集（Mixed GC）：收集整个新生代以及部分老年代的垃圾收集。
25+
- 目前，只有 G1 GC 会有这种行为。
26+
- 整堆收集（Full GC）：收集整个 Java 堆和方法区的垃圾收集。
27+
28+
### GC 日志分类
29+
30+
- Minor GC
31+
32+
```
33+
[GC (Allocation Failure) [PSYoungGen: 31744K -> 2192K(36864K)]
34+
31744K -> 2200K(121856K), 0.0139308 secs] [Times: user=0.05 sys=0.01, real=0.01 secs]
35+
```
36+
37+
- Full GC
38+
39+
```
40+
[Full GC (Metadata GC Threshold) [PSYoungGen: 5104K -> 0K(132096K)]
41+
[ParOldGen: 416K -> 5453K(50176K)] 5520K -> 5453K(182272K), [MetaSpace:
42+
20637K -> 20637K(106700)]， 0.0245883 secs] [Times: user=0.06 sys=0.00,
43+
real=0.02 secs]
44+
```
45+
46+
### GC 日志结构剖析
47+
48+
- 垃圾收集器
49+
50+
> - 使用 Serial 收集器在新生代的名字是 Default New Generation，因此显示的是"[DefNew"。
51+
> - 使用 ParNew 收集器在新生代的名字会变成"[ParNew"，意思是"Parallel New Generation"。
52+
> - 使用 Parallel Scavenge 收集器在新生代的名字是"[PSYoungGen"，这里的 JDK 1.7 使用的就是 PSYoungGen。
53+
> - 使用 Parallel Old Generation 收集器在老年代的名字是"[ParOldGen"。
54+
> - 使用 G1 收集器的话，会显示为"Garbage-First Heap"。
55+
>
56+
>
57+
>
58+
> Allocation Failure：表明本次引起 GC 的原因是因为在年轻代中没有足够的空间能够存储新的数据了。
59+
60+
- GC 前后情况
61+
62+
> 可以发现 GC 日志格式的规律一般都是：GC 前内存占用 -> GC 后内存占用（该区域内存总大小）
63+
>
64+
> [PSYoungGen: 5986K -> 696K(8704K)] 5986K -> 704K(9216K)
65+
>
66+
>
67+
>
68+
> 中括号内：GC 回收前年轻代堆大小，回收后大小。（年轻代堆总大小）
69+
>
70+
> 括号外：GC 回收前年轻代和老年代大小，回收后大小。（年轻代和老年代总大小）
71+
72+
- GC 时间
73+
74+
> GC 日志中有三个时间：user、sys 和 real
75+
>
76+
> - user：进程执行用户态代码（核心之外）所使用的时间。这是执行此进程所使用的的实际 CPU 时间，其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下，表示 GC 线程执行所使用的 CPU 总时间。
77+
> - sys：进程在内核态消耗的 CPU 时间，即在内核执行系统调用或等待系统事件所使用的的 CPU 时间。
78+
> - real：程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待 I/O 完成）。对于并行 GC，这个数字应该接近（用户时间+系统时间）除以垃圾收集器使用的线程数。
79+
>
80+
>
81+
>
82+
> 由于多核的原因，一般的 GC 事件中，Real Time 是小于 sys + user time 的，因为一般是多个线程并发的去做 GC，所以 Real Time 是要小于 sys + user time 的。如果 real > sys + user 的话，则你的应用可能存在下列问题：IO 负载非常重或者是 CPU 不够用。
83+
84+
### Minor GC 日志解析
85+
86+
```
87+
2020-11-20T17:19:43.265-0800:0.822:[GC (ALLOCATION FAILURE) [PSYOUNGGEN:
88+
76800k -> 8433K(89600K)] 76800K -> 8449K(294400K), 0.0088371 SECS [TIMES:
89+
USER=0.02 SYS=0.01, REAL=0.01 SECS]]
90+
```
91+
92+
> - 2020-11-20T17:19:43.265-0800：日志打印时间日期格式。
93+
> - 0.822:：GC 发生时，Java 虚拟机启动以来经过的秒数。
94+
> - GC (ALLOCATION FAILURE)：发生了一次垃圾回收，这是一次 Minor GC。它不区分新生代 GC 还是老年代 GC，括号里的内容是 GC 发生的原因，这里的 Allocation Failure 的原因是新生代中没有足够区域能够存放需要分配的数据而失败。
95+
> - [PSYOUNGGEN:76800k -> 8433K(89600K)]：
96+
> - PSYoungGen：表示 GC 发生的区域，区域名称与使用的 GC 收集器是密切相关的。
97+
> - Serial 收集器：Default New Generation 显示 DefNew。
98+
> - ParNew 收集器：ParNew。
99+
> - Parallel Scanvenge 收集器：PSYoung，老年代和新生代同理，也是和收集器名称相关。
100+
> - 76800k -> 8433K(89600K)：GC 前该内存区域已使用容量 -> GC 后该区域容量（该区域总容量）。
101+
> - 如果是新生代，总容量则会显示整个新生代内存的 9/10，即 Eden + From/To 区。
102+
> - 如果是老年代，总容量则是全部内存大小，无变化。
103+
> - 76800K -> 8449K(294400K)：在显示完区域容量 GC 的情况之后，会接着显示整个堆内存区域的 GC 情况：GC 前堆内存已使用容量 -> GC 堆内存容量（堆内存总容量）堆内存总容量 = 9/10 新生代 + 老年代 < 初始化的内存大小。
104+
> - 0.0088371 SECS：整个 GC 所花费的时间，单位是秒。
105+
> - [TIMES:USER=0.02 SYS=0.01, REAL=0.01 SECS]：
106+
> - user：指的是 CPU 工作在用户态所花费的时间。
107+
> - sys：指的是 CPU 工作在内核态所花费的时间。
108+
> - real：指的是在此次 GC 事件中所花费的总时间。
109+
110+
### Full GC 日志解析
111+
112+
```
113+
2020-11-20T17:19:43.794-0800: 1.351: [FULL GC (METADATA GC THRESHOLD)
114+
[PSYOUNGGEN:10082K -> 0K(89600K)] [PAROLDGEN: 32K -> 9638K(204800K)]
115+
10114K -> 9638K(294400K),
116+
[METASPACE: 20158K -> 20156K(1067008K)], 0.0285388 SECS] [TIMES: USER=0.11 SYS=0.0, REAL=0.03 SECS]
117+
```
118+
119+
> - 2020-11-20T17:19:43.794-0800：日志打印时间日期格式。
120+
> - 1.351：GC 发生时，Java 虚拟机启动以来经过的秒数。
121+
> - FULL GC (METADATA GC THRESHOLD)：发生了一次垃圾回收，这是一次 FULL GC。它不区分新生代 GC 还是老年代 GC。括号里的内容是 GC 发生的原因，这里的 Metadata GC Threshold 的原因是 Metaspace 区不够用了。
122+
> - Full GC（Ergonomics）：JVM 自适应调整导致的 GC。
123+
> - Full GC（System）：调整了 System.gc() 方法。
124+
> - [PSYOUNGGEN:10082K -> 0K(89600K)]：
125+
> - PSYoungGen：表示 GC 发生的区域，区域名称与使用的 GC 收集器是密切相关的。
126+
> - Serial 收集器：Default New Generation 显示 DefNew。
127+
> - ParNew 收集器：ParNew。
128+
> - Parallel Scanvenge 收集器：PSYoung，老年代和新生代同理，也是和收集器名称相关。
129+
> - 10082K -> 0K(89600K)：GC 前该内存区域已使用容量 -> GC 后该区域容量（该区域总容量）。
130+
> - 如果是新生代，总容量则会显示整个新生代内存的 9/10，即 Eden + From/To 区。
131+
> - 如果是老年代，总容量则是全部内存大小，无变化。
132+
> - [PAROLDGEN: 32K -> 9638K(204800K)]：老年代区域没有发生 GC，因为本次 GC 是 Metaspace 引起的。
133+
> - 10114K -> 9638K(294400K)：在显示完区域容量 GC 的情况之后，会接着显示整个堆内存区域的 GC 情况：GC 前堆内存已使用容量 -> GC 堆内存容量（堆内存总容量）堆内存总容量 = 9/10 新生代 + 老年代 < 初始化的内存大小。
134+
> - [METASPACE: 20158K -> 20156K(1067008K)]：Metaspace GC 回收 2K 空间。
135+
> - 0.0285388 SECS：整个 GC 所花费的时间，单位是秒。
136+
> - [TIMES:USER=0.11 SYS=0.00, REAL=0.03 SECS]：
137+
> - user：指的是 CPU 工作在用户态所花费的时间。
138+
> - sys：指的是 CPU 工作在内核态所花费的时间。
139+
> - real：指的是在此次 GC 事件中所花费的总时间。
140+
141+
## GC 日志分析工具
142+
143+
上节介绍了 GC 日志的打印及含义，但是 GC 日志看起来比较麻烦，本节将会介绍一下 GC 日志可视化分析工具 GCeasy 和 GCViewer 等。通过 GC 日志可视化分析工具，我们可以很方便的看到 JVM 各个分代的内存使用情况、垃圾回收次数、垃圾回收的原因、垃圾回收占用的时间、吞吐量等，这些指标在我们进行 JVM 调优的时候是很有用的。
144+
145+
如果想把 GC 日志存到文件的话，是下面这个参数：
146+
147+
```
148+
-Xloggc:/path/to/gc.log
149+
```
150+
151+
然后就可以用一些工具去分析这些 GC 日志。
152+
153+
### GCeasy
154+
155+
- 基本概念：
156+
157+
官网地址：https://gceasy.io/，GCeasy 是一款在线的 GC 日志分析器，可以通过 GC 日志分析进行内存泄漏检测、GC 暂停原因分析、JVM 配置建议优化等功能，而且是可以免费使用的（有一些服务是收费的）。
158+
159+
### GCViewer
160+
161+
- 基本概念
162+
163+
上面介绍了一款在线的 GC 日志分析器，下面介绍一个离线版的 GCViewer。GCViewer 是一个免费的、开源的分析小工具，用于可视化查看由 SUN/Oracle、IBM、HP 和 BEA Java 虚拟机产生的垃圾收集器的日志。GCViewer 用于可视化 Java VM 选项 `-verbose:gc` 和 .NET 生成的数据 `-Xloggc:<file>`。它还计算与垃圾回收相关的性能指标（吞吐量、累积的暂停、最长的暂停等）。当通过更改世代大小或设置初始堆大小来调整特定应用程序的垃圾回收时，此功能非常有用。
164+
165+
- 安装
166+
167+
- 下载 GCViewer 工具
168+
169+
> 源码下载：https://github.com/chewiebug/GCViewer
170+
>
171+
> 运行版本下载：https://github.com/chewiebug/GCViewer/wiki/Changelog
172+
173+
- 只需双击 gcviewer-1.3x.jar 或运行 java -jar gcviewer-1.3x.jar（它需要运行 Java 1.8 VM），即可启动 GCViewer（GUI）。
174+
175+
### 其他工具
176+
177+
- GChisto
178+
179+
GChisto 是一款专业分析 GC 日志的工具，可以通过 GC 日志来分析：Minor GC、Full GC 的次数、频率、持续时间等，通过列表、报表、图表等不同形式来反应 GC 的情况。
180+
181+
- HPjmeter
182+
183+
工具很强大，但只能打开由一下参数生成的 GC log，`-verbose:gc、-Xloggc:gc.log`。添加其他参数生成的 gc.log 无法打开。HPjmeter 集成了以前的 HPjtune 功能，可以分析在 HP 机器上产生的垃圾回收日志文件。
184+

0 commit comments

Comments
 (0)