JVM_下篇_第五章：GC日志分析

于 2023-12-25 07:46:23 发布
阅读量1.1k 收藏 23
点赞数 18
分类专栏： # java jvm 文章标签： jvm
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
本文链接：https://blog.csdn.net/wufagang/article/details/108422784
版权

JVM_13GC日志分析

通过阅读GC日志，我们可以了解Java虛拟机内存分配与回收策略。内存分配与垃圾回收的参数列表

1. 日志相关参数

一XX： +PrintGC 输出Gc日志。类似： 一verbose：gc
一XX： +PrintGCDetails 输出GC的详细日志
一XX： +PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）
一XX： +PrintGCDateStamps输出GC的时间戳（以日期的形式，如2013一05一04T21 ： 53：59.234+0800 ）
一XX： +PrintHeapAtGC 在进行GC的前后打印出堆的信息
一Xloggc：. . /logs/gc. log日志文件的输出路径

-Xms60m -Xmx60m 
-XX:+PrintGC
-XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps
 -XX:+PrintGCDateStamps
  -XX:+PrintHeapAtGC
   -Xloggc:./log/gc.txt

测试代码

public class GCLogTest {

    public static void main(String[] args) {
        List<Byte[]> list = new ArrayList<>();
        for (int i = 0; i < 500; i++) {
            Byte[] bytes = new Byte[1024*100] ; //100k
            list.add(bytes);
//            try {
//                TimeUnit.MILLISECONDS.sleep(200);
//            } catch (InterruptedException e) {
//                e.printStackTrace();
//            }
        }
    }
}

1.1 +PrintGC

打开GC日志：一verbose：gc
这个只会显示总的GC堆的变化， 如下

[GC (Allocation Failure)  32933K->30729K(125952K), 0.0158301 secs]
[GC (Allocation Failure)  63775K->63490K(159232K), 0.0226294 secs]
[Full GC (Ergonomics)  63490K->63441K(215040K), 0.0748636 secs]
[GC (Allocation Failure)  129672K->128275K(215040K), 0.0440920 secs]
[Full GC (Ergonomics)  128275K->128244K(332800K), 0.1068971 secs]
[GC (Allocation Failure)  194734K->197479K(363520K), 0.0448888 secs]
[Full GC (Ergonomics)  197479K->194647K(468480K), 0.0889446 secs]

参数解析：
GC、Full GC： GC的类型，GC只在新生代上进行，Full GC包括永生代，新生代， 老年代。
Allocation Failure： GC发生的原因。
80832K一> 19298K：堆在GC前的大小和GC后的大小。
228840k：现在的堆大小。
0.0084018 secs： GC持续的时间。

在这里插入图片描述

[GC (Allocation Failure) [PSYoungGen: 15354K->2296K(17920K)] 15354K->13904K(58880K), 0.0092782 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC (Allocation Failure) [PSYoungGen: 17394K->2328K(17920K)] 29003K->28737K(58880K), 0.0135170 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
[Full GC (Ergonomics) [PSYoungGen: 2328K->0K(17920K)] [ParOldGen: 26409K->28639K(40960K)] 28737K->28639K(58880K), [Metaspace: 3274K->3274K(1056768K)], 0.0425995 secs] [Times: user=0.08 sys=0.00, real=0.04 secs] 
[Full GC (Ergonomics) [PSYoungGen: 15008K->2400K(17920K)] [ParOldGen: 28639K->40640K(40960K)] 43648K->43040K(58880K), [Metaspace: 3274K->3274K(1056768K)], 0.0265506 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 
[Full GC (Ergonomics) [PSYoungGen: 15096K->14801K(17920K)] [ParOldGen: 40640K->40639K(40960K)] 55736K->55440K(58880K), [Metaspace: 3276K->3276K(1056768K)], 0.0319406 secs] [Times: user=0.09 sys=0.00, real=0.03 secs] 
[Full GC (Ergonomics) [PSYoungGen: 15201K->15201K(17920K)] [ParOldGen: 40639K->40639K(40960K)] 55840K->55840K(58880K), [Metaspace: 3276K->3276K(1056768K)], 0.0323722 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
[Full GC (Allocation Failure) [PSYoungGen: 15201K->15201K(17920K)] [ParOldGen: 40639K->40621K(40960K)] 55840K->55822K(58880K), [Metaspace: 3276K->3276K(1056768K)], 0.0364635 secs] [Times: user=0.09 sys=0.00, real=0.04 secs] 
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
	at com.wfg.GC3.GCLogTest.main(GCLogTest.java:26)
Heap
 PSYoungGen      total 17920K, used 15360K [0x00000000fec00000, 0x0000000100000000, 0x0000000100000000)
  eden space 15360K, 100% used [0x00000000fec00000,0x00000000ffb00000,0x00000000ffb00000)
  from space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000)
  to   space 2560K, 0% used [0x00000000ffb00000,0x00000000ffb00000,0x00000000ffd80000)
 ParOldGen       total 40960K, used 40625K [0x00000000fc400000, 0x00000000fec00000, 0x00000000fec00000)
  object space 40960K, 99% used [0x00000000fc400000,0x00000000febac770,0x00000000fec00000)
 Metaspace       used 3308K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 363K, capacity 388K, committed 512K, reserved 1048576K

Process finished with exit code 1

1.2 PrintGCDetails

在这里插入图片描述

1.3 PrintGCTimeStamps

2020-09-18T06:26:41.700+0800: 0.218: [GC (Allocation Failure) [PSYoungGen: 15354K->2312K(17920K)] 15354K->13920K(58880K), 0.0098038 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2020-09-18T06:26:41.712+0800: 0.231: [GC (Allocation Failure) [PSYoungGen: 17564K->2296K(17920K)] 29172K->28713K(58880K), 0.0098811 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2020-09-18T06:26:41.722+0800: 0.241: [Full GC (Ergonomics) [PSYoungGen: 2296K->0K(17920K)] [ParOldGen: 26417K->28629K(40960K)] 28713K->28629K(58880K), [Metaspace: 3171K->3171K(1056768K)], 0.0508557 secs] [Times: user=0.09 sys=0.02, real=0.05 secs] 
2020-09-18T06:26:41.776+0800: 0.295: [Full GC (Ergonomics) [PSYoungGen: 15108K->2800K(17920K)] [ParOldGen: 28629K->40211K(40960K)] 43738K->43011K(58880K), [Metaspace: 3221K->3221K(1056768K)], 0.0623329 secs] [Times: user=0.09 sys=0.00, real=0.06 secs] 
2020-09-18T06:26:41.845+0800: 0.364: [Full GC (Ergonomics) [PSYoungGen: 15160K->14830K(17920K)] [ParOldGen: 40211K->40210K(40960K)] 55372K->55040K(58880K), [Metaspace: 3280K->3280K(1056768K)], 0.0318266 secs] [Times: user=0.09 sys=0.00, real=0.03 secs] 
2020-09-18T06:26:41.878+0800: 0.397: [Full GC (Ergonomics) [PSYoungGen: 15273K->15230K(17920K)] [ParOldGen: 40210K->40210K(40960K)] 55483K->55440K(58880K), [Metaspace: 3280K->3280K(1056768K)], 0.0290101 secs] [Times: user=0.13 sys=0.00, real=0.03 secs] 
2020-09-18T06:26:41.908+0800: 0.427: [Full GC (Ergonomics) [PSYoungGen: 15230K->15230K(17920K)] [ParOldGen: 40610K->40610K(40960K)] 55840K->55840K(58880K), [Metaspace: 3280K->3280K(1056768K)], 0.0470187 secs] [Times: user=0.06 sys=0.00, real=0.05 secs] 
2020-09-18T06:26:41.955+0800: 0.474: [Full GC (Allocation Failure) Exception in thread "main" java.lang.OutOfMemoryError: Java heap space[PSYoungGen: 15230K->15229K(17920K)] [ParOldGen: 40610K->40593K(40960K)] 55840K->55822K(58880K), [Metaspace: 3280K->3280K(1056768K)], 0.0382040 secs] [Times: user=0.09 sys=0.00, real=0.04 secs] 

	at com.wfg.GC3.GCLogTest.main(GCLogTest.java:28)
Heap
 PSYoungGen      total 17920K, used 15360K [0x00000000fec00000, 0x0000000100000000, 0x0000000100000000)
  eden space 15360K, 100% used [0x00000000fec00000,0x00000000ffb00000,0x00000000ffb00000)
  from space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000)
  to   space 2560K, 0% used [0x00000000ffb00000,0x00000000ffb00000,0x00000000ffd80000)
 ParOldGen       total 40960K, used 40597K [0x00000000fc400000, 0x00000000fec00000, 0x00000000fec00000)
  object space 40960K, 99% used [0x00000000fc400000,0x00000000feba5758,0x00000000fec00000)
 Metaspace       used 3311K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 363K, capacity 388K, committed 512K, reserved 1048576K

Process finished with exit code 1

在这里插入图片描述
在这里插入图片描述
在这里插入图片描述

在这里插入图片描述

在这里插入图片描述

列子：

/**
 * 在jdk7 和 jdk8中分别执行
 * -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseSerialGC
 */
public class GCLogTest1 {
    private static final int _1MB = 1024 * 1024;

    public static void testAllocation() {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[2 * _1MB];
        allocation2 = new byte[2 * _1MB];
        allocation3 = new byte[2 * _1MB];
        allocation4 = new byte[4 * _1MB];
    }

    public static void main(String[] agrs) {
        testAllocation();
    }
}

jdk7
在这里插入图片描述
jdk 8
在这里插入图片描述
在这里插入图片描述

在这里插入图片描述

2 日志分析工具使用

可以用一些工具去分析这些gc日志。
常用的日志分析.工具有： GCViewer、GCEasy、GCHisto、GCLogViewer 、Hpjmeter、garbagecat等。

https://gceasy.io/

5. 分析 GC 日志

5.1. GC 分类

针对 HotSpot VM 的实现，它里面的 GC 按照回收区域又分为两大种类型：一种是部分收集（Partial GC），一种是整堆收集（Full GC）

  • 部分收集（Partial GC）：不是完整收集整个 Java 堆的垃圾收集。其中又分为：

    • 新生代收集（Minor GC / Young GC）：只是新生代（Eden / S0, S1）的垃圾收集
    • 老年代收集（Major GC / Old GC）：只是老年代的垃圾收集。目前，只有 CMS GC 会有单独收集老年代的行为。注意，很多时候 Major GC 会和 Full GC 混淆使用，需要具体分辨是老年代回收还是整堆回收。

  • 混合收集（Mixed GC）：收集整个新生代以及部分老年代的垃圾收集。目前，只有 G1 GC 会有这种行为

  • 整堆收集（Full GC）：收集整个 java 堆和方法区的垃圾收集。

5.2. GC 日志分类

MinorGC

MinorGC（或 young GC 或 YGC）日志：

[GC (Allocation Failure) [PSYoungGen: 31744K->2192K (36864K) ] 31744K->2200K (121856K), 0.0139308 secs] [Times: user=0.05 sys=0.01, real=0.01 secs]

image-20210506202126562

image-20210506202156090

FullGC

[Full GC (Metadata GC Threshold) [PSYoungGen: 5104K->0K (132096K) ] [Par01dGen: 416K->5453K (50176K) ]5520K->5453K (182272K), [Metaspace: 20637K->20637K (1067008K) ], 0.0245883 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

image-20210506202330868

image-20210506202349072

5.3. GC 日志结构剖析

透过日志看垃圾收集器

  • Serial 收集器：新生代显示 “[DefNew”，即 Default New Generation

  • ParNew 收集器：新生代显示 “[ParNew”，即 Parallel New Generation

  • Parallel Scavenge 收集器：新生代显示"[PSYoungGen"，JDK1.7 使用的即 PSYoungGen

  • Parallel Old 收集器：老年代显示"[ParoldGen"

  • G1 收集器：显示”garbage-first heap“

透过日志看 GC 原因

  • Allocation Failure：表明本次引起 GC 的原因是因为新生代中没有足够的区域存放需要分配的数据
  • Metadata GCThreshold：Metaspace 区不够用了
  • FErgonomics：JVM 自适应调整导致的 GC
  • System：调用了 System.gc()方法

透过日志看 GC 前后情况

通过图示，我们可以发现 GC 日志格式的规律一般都是：GC 前内存占用-＞ GC 后内存占用（该区域内存总大小）

[PSYoungGen: 5986K->696K (8704K) ] 5986K->704K (9216K)

  • 中括号内：GC 回收前年轻代堆大小，回收后大小，（年轻代堆总大小）

  • 括号外：GC 回收前年轻代和老年代大小，回收后大小，（年轻代和老年代总大小）

注意：Minor GC 堆内存总容量 = 9/10 年轻代 + 老年代。原因是 Survivor 区只计算 from 部分，而 JVM 默认年轻代中 Eden 区和 Survivor 区的比例关系，Eden:S0:S1=8:1:1。

透过日志看 GC 时间

GC 日志中有三个时间：user，sys 和 real

  • user：进程执行用户态代码（核心之外）所使用的时间。这是执行此进程所使用的实际 CPU 时间，其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下，表示 GC 线程执行所使用的 CPU 总时间。
  • sys：进程在内核态消耗的 CPU 时间，即在内核执行系统调用或等待系统事件所使用的 CPU 时间
  • real：程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待 I/O 完成）。对于并行 gc，这个数字应该接近（用户时间＋系统时间）除以垃圾收集器使用的线程数。

由于多核的原因，一般的 GC 事件中，real time 是小于 sys time ＋ user time 的，因为一般是多个线程并发的去做 GC，所以 real time 是要小于 sys ＋ user time 的。如果 real ＞ sys ＋ user 的话，则你的应用可能存在下列问题：IO 负载非常重或 CPU 不够用。

5.4. GC 日志分析工具

GCEasy

GCEasy 是一款在线的 GC 日志分析器，可以通过 GC 日志分析进行内存泄露检测、GC 暂停原因分析、JVM 配置建议优化等功能，大多数功能是免费的。

官网地址：https://gceasy.io/

GCViewer

GCViewer 是一款离线的 GC 日志分析器，用于可视化 Java VM 选项 -verbose:gc 和 .NET 生成的数据 -Xloggc:<file>。还可以计算与垃圾回收相关的性能指标（吞吐量、累积的暂停、最长的暂停等）。当通过更改世代大小或设置初始堆大小来调整特定应用程序的垃圾回收时，此功能非常有用。

源码下载：https://github.com/chewiebug/GCViewer

运行版本下载：https://github.com/chewiebug/GCViewer/wiki/Changelog

GChisto

  • 官网上没有下载的地方，需要自己从 SVN 上拉下来编译
  • 不过这个工具似乎没怎么维护了，存在不少 bug

HPjmeter

  • 工具很强大，但是只能打开由以下参数生成的 GC log，-verbose:gc -Xloggc:gc.log。添加其他参数生成的 gc.log 无法打开
  • HPjmeter 集成了以前的 HPjtune 功能，可以分析在 HP 机器上产生的垃圾回收日志文件
吴法刚
关注
专栏目录
jvm_gc.rar_jvm_垃圾回收
09-24
5. **GC日志分析**：通过分析JVM产生的GC日志，可以了解垃圾回收的效率和内存使用情况，从而调整参数以优化性能。 6. **内存泄漏检测**：关注长期未被释放的对象，可能暗示存在内存泄漏问题。开发者可以通过工具如...
JVM关于GC的日志分析
qq_52896771的博客
04-02 1242
通过阅读GC日志，我们可以了解Java虛拟机内存分配与回收策略。内存分配与垃圾回收的参数列表。
JVM GC 日志详解 --打印GC日志
yinni11的博客
10-16 1万+
本文采用的JDK版本： java version "1.8.0_144" Java(TM) SE Runtime Environment (build 1.8.0_144-b01) Java HotSpot(TM) 64-Bit Server VM (build 25.144-b01, mixed mode) 一、GC 日志参数 设置JVM GC格式日志的主要参数包括如下8个： -X...
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails 日志分析
lxlmycsdnfree的博客
10-26 1万+
-XX:+PrintGCTimeStamps输出格式： 289.556:[GC[PSYoungGen:314113K->15937K(300928K)]405513K->107901K(407680K),0.0178568secs][Times:user=0.06sys=0.00,real=0.01secs] 293.271:[GC[PSYoungGen...
java gc 打印,Java GC日志常用打印参数
weixin_42315616的博客
03-13 1970
1. PrintGC最简单的GC参数。启用配置：-XX:+PrintGC2. PrintGCDetails打印GC的详细信息启用配置：-XX:+PrintGCDetails不同的垃圾回收器，GC日志(表示年代的词)可能会不一样， 通常包含GC前后各分区的使用量Times: user表示用户态CPU耗时，sys表示系统CPU耗时，real表示GC实际耗时3. PrintGCTimeStampsGC时...
JVM常用GC日志打印参数
热门推荐
程序猿的樊笼
05-09 2万+
1. PrintGC 最简单的GC参数。 启用配置：-XX:+PrintGC 日志如下： 根据上面红色方框内的数字1、2、3、4、5说明，1是GC类型，GC:minor GC(young gc),Full GC：major GC,2是GC前堆内存使用量，3是GC后堆内存使用量，4是堆内存总量，5是本次GC耗时 2. PrintGCDetails 打印GC的详细信息 启用配置：-X...
IBM-JVM.rar_jvm_site:www.pudn.com
09-23
此外，JVM参数的设置也至关重要，例如堆大小、新生代和老年代的比例、GC策略等，都需要根据应用特性和资源状况进行合理配置。 总的来说，IBM JVM的深入理解和优化是提升Java应用性能的关键。这个压缩包中的IBM JVM....
JVM、GC详解及调优_jvm_JVM、GC详解及调优_
09-29
2. **GC日志分析**：通过分析GC日志，了解GC行为，找出性能瓶颈。 3. **并行与并发设置**：调整并行GC线程数和并发GC策略，优化性能。 4. **对象存活率预估**：通过调整Survivor区比例，减少Full GC的发生。 5. **...
JVM_GC调优
09-22
### JVM_GC调优详解 #### 一、JVM体系结构概览 Java虚拟机(JVM)作为Java程序的运行环境，其内部结构复杂且高效。为了更好地理解JVM_GC调优，我们首先来了解一下JVM的基本组成部分。 1. **类装载器子系统(Class ...
jvmgc日志分析工具
03-20
"jvmgc日志分析工具"专为解析和可视化JVM生成的GC日志而设计，帮助开发者识别内存瓶颈，调整内存设置，以及诊断可能的性能问题。 GC日志是JVM在运行过程中记录的关于垃圾收集活动的详细信息，包括垃圾收集的起始...
jvm中GC日志格式详解（十）
qq_35151346的博客
09-12 1885
一、日志相关参数 1.-XX:+PrintGCDetails 2.-XX:+PrintGCTimeStamps 打印时间戳 3.-XX:+PrintGCDateStamps 4.-Xloggc:/tmp/gc.log 将GC日志输出到指定文件 5.-XX:PrintHeapAtGC 发生GC时，打印堆的使用情况 6.-XX:PrintTenuringDistribution 发生GC...
JVM参数
ccsmile的博客
05-04 570
常见参数java启动参数 参数 说明 - 所有jvm实现都必须实现这些参数的功能，向后兼容 -X 默认jvm实现这些参数的功能，不保证所有jvm实现都满足，不保证向后兼容 -XX 各个jvm实现有所不同，可能会随时取消 输出jvm的信息参数 参数 说明 -verbose:gc 输出每次GC的相关信息 -XX:+PrintGCDetails 获取的信
GC 日志相关选项
实践求真知
09-06 1654
一常用选项 -XX:+PrintGC <==> -verbose:gc打印简要日志信息，独立使用 -XX:+PrintGCDetails打印详细日志信息，独立使用 -XX:+PrintGCTimeStamps打印程序启动到GC发生的时间，搭配 -XX:+PrintGCDetails 使用，不可以独立使用 -XX:+PrintGCDateStamps打印GC发生时的时间戳，搭配 -XX:+PrintGCDetails 使用，不可以独立使用 -XX:...
JVM GC相关参数总结
最新发布
hanxiaozhang的博客
07-16 915
【代码】JVM GC相关参数总结。
jvm调优原理及实战案例
轻松入门网
02-11 413
jvm调优原理及实战案例
技术自查第三篇：JVM/GC日志查看篇
banbeisudashui的博客
08-23 2593
调优
JDK11 GC日志输出
qq_43653951的博客
12-13 5306
总结一下日志输出的几个命令： -XX:+PrintGC 输出简略信息 -XX:+PrintGCDetails 输出详细信息 -XX:+PrintGCTimeStamps 输出时间戳 -XX:+PrintGCDateStamps 输出日期 -XX:+XLoggc:.logs/a.log 输出到文件 上述gc日志是在JDK1.8中常用到的，但是在jdk11中已经被标记为过时 那么在jdk11中...
JAVA开发中GC日志打印简单通用的配置详解
sakura的博客
02-13 2036
生产环境上，或者其他要测试 GC 问题的环境上，一定会配置上打印GC日志的参数，便于分析 GC 相关的问题。 但是可能很多人配置的都不够“完美”，要么是打印的内容过少，要么是输出到控制台，要么是一个大文件被覆盖，要么是……
GC 日志打印实践
weixin_42073629的博客
06-03 1032
1.1 -XX:+PrintGC与-verbose:gc 如果只设置-XX:+PrintGC那么打印的日志如下所示： [GC (Allocation Failure) 61805K->9849K(256000K), 0.0041139 secs] 1、GC类型，GC:minor GC(young gc),Full GC：major GC 2、Allocation Failure 表示是失败的类型 3、68896K->5080K 表示年轻代从68896K降为5080K 4、2560
评论 1
添加红包

请填写红包祝福语或标题

个

红包个数最小为10个

元

红包金额最低5元

当前余额3.43元 前往充值 >
需支付：10.00元
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付元
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明：

1.余额是钱包充值的虚拟货币，按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载，可以购买VIP、付费专栏及课程。

余额充值