JVM-27-GC LOG 垃圾回收日志

情境导入

产线一个问题：业务系统调用后台超时，问是不是 FULL GC 的问题。

查看方式

• 知道 GC 文件的位置

··· locate xxx.log ···

• 知道如何查看 FULL GC 日志

cat /XXX/gc.log | grep -a 'Full'| more

简单分析

直接根据 full gc 的关键词查看。

一般在并发较高的系统中会出现这种日志，且几天出现一次。

但是一旦出现，一次 FULL GC 可能时间多达 10S，就会导致外部调用超时。

教训

你应该知道如何让系统打印 GC 日志，并且当系统调用超时的时候，可以联系到 FULL GC，并会排查。

• 问题2

线上每台机器去看的效率实在不高，建议有一个监控系统。

可以在第一时间获取到 FULL GC 的日志，并且发送邮件/短信通知给相关负责人。

IDEA 中打印 GC 日志

编写测试类

public class Main {

    public static void main(String[] args) throws InterruptedException {
        List<String> stringList = new ArrayList<>();
        while (true) {
            for(int i = 0; i < 10000; i++) {
                stringList.add(UUID.randomUUID().toString());
            }
            TimeUnit.SECONDS.sleep(1);
            System.out.println(stringList.size());
        }
    }
}

配置运行 jvm 参数

【run】=>【Edit Configration】=>【vm option】

• 打印 GC 日志信息

-XX:+PrintGCDetails

测试日志如下：

10000
20000
30000
[GC (Allocation Failure) [PSYoungGen: 33280K->4689K(38400K)] 33280K->4697K(125952K), 0.0032247 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
40000
50000
60000
70000
[GC (Allocation Failure) [PSYoungGen: 37969K->5112K(38400K)] 37977K->9224K(125952K), 0.0046176 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
80000

简单分析

[GC (Allocation Failure) [PSYoungGen: 33280K->4689K(38400K)] 33280K->4697K(125952K), 0.0032247 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

GC 日志

GC 原因：Allocation Failure

GC 类型：PSYoungGen

GC 效果： 33280K->4689K(38400K)

GC 消耗时间：Times: user=0.00 sys=0.00, real=0.00 secs

没有打印 gc.log

场景

有时候一台机器会出现，没有设置 jvm 打印日志怎么办呢。

命令 jstat

jstat -gcutil <pid>

如何查看 pid

$ jps
29296 Jps
28710 jboss-modules.jar

首先获取 pid

$ps -ef | grep "projectName"
projectName   15599 15514 52 Jul02 ?        08:45:15 /bea/jdk1.7.0_99/bin/java -D[Standalone] 

可知对应 pid=15599

执行命令

jstat -gcutil 15599

日志信息如下：

S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   
0.00  98.97   2.71  79.48  53.54   3759  118.032     2    0.951  118.984

• 字段解释

S0 ：年轻代中第一个survivor（幸存区）已使用的占当前容量百分比 S1 ：年轻代中第二个survivor（幸存区）已使用的占当前容量百分比 E ：年轻代中Eden（伊甸园）已使用的占当前容量百分比 O ：old代已使用的占当前容量百分比 P ：perm代已使用的占当前容量百分比 YGC ：从应用程序启动到采样时年轻代中gc次数 YGCT ：从应用程序启动到采样时年轻代中gc所用时间(s) FGC ：从应用程序启动到采样时old代(全gc)gc次数 FGCT ：从应用程序启动到采样时old代(全gc)gc所用时间(s) GCT：从应用程序启动到采样时gc用的总时间(s)

统计监控

jstat -gcutil pid 300 >/tmp/gc.log

300 是一个时间间隔，单位为 ms，但是不要低于 50，会失去意义。

这个对性能损耗比较小，生产可以使用，但是不要使用 jmap/jstatck

如何查看的 GC 器类型

命令

java -XX:+PrintCommandLineFlags -version

效果

-XX:InitialHeapSize=128975232 -XX:MaxHeapSize=2063603712 -XX:+PrintCommandLineFlags -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
java version "1.8.0_121"
Java(TM) SE Runtime Environment (build 1.8.0_121-b13)
Java HotSpot(TM) 64-Bit Server VM (build 25.121-b13, mixed mode)

各个版本默认类型

jdk1.7 默认垃圾收集器Parallel Scavenge（新生代）+Parallel Old（老年代）

jdk1.8 默认垃圾收集器Parallel Scavenge（新生代）+Parallel Old（老年代）

jdk1.9 默认垃圾收集器G1

jboss 默认配置文件地址

/app/xxx/jboss/bin/standalone.conf

chat

Q1-java 链路压测性能降低 50%，涉及到多个应用。应该如何分析呢？

链路压测性能降低50%可能是由多种原因引起的，需要进行系统性的分析来找到根本原因。以下是一些可能的步骤和方法，帮助你进行分析：

1. 性能监控和日志分析： 检查应用程序的性能监控和日志记录系统。查看是否有任何异常或错误信息。重点关注慢查询、错误率、资源利用率等指标。

2. 系统资源分析： 使用系统工具（例如top、htop、iostat等）来监控服务器的 CPU、内存、磁盘和网络使用情况。检查是否有资源瓶颈。

3. 网络延迟和带宽： 检查网络延迟和带宽。如果涉及多个应用程序，可能存在网络通信方面的问题。使用网络分析工具（例如Wireshark）进行深入分析。

4. 数据库性能分析： 如果应用程序涉及数据库，检查数据库的性能。查看慢查询日志，检查索引是否正确使用，以及是否有不必要的数据库连接。

5. 代码分析： 进行应用程序代码的审查。查看最近的代码更改是否可能导致性能问题。重点关注与性能相关的代码段，例如循环、嵌套查询等。

6. 压测环境配置： 检查链路压测的环境配置是否与生产环境一致。确保测试环境的硬件、网络等条件与实际环境相似。

7. 版本管理： 检查应用程序和依赖库的版本。有时升级到新版本可能导致性能问题，特别是在一些库或框架存在Bug的情况下。

8. 并发连接数： 考虑检查并发连接数是否达到系统的极限。可能是由于并发连接数过多导致性能下降。

9. 缓存机制： 如果应用程序使用了缓存，检查缓存的命中率和性能。不正确的缓存配置可能导致性能问题。

10. 分布式系统调试： 如果涉及多个应用程序，确保分布式系统的各个组件协同工作。检查服务之间的通信是否有异常。

11. 第三方服务： 如果应用程序依赖于第三方服务，检查这些服务的性能。可能是由于第三方服务的问题导致性能下降。

12. 内存泄漏： 检查是否存在内存泄漏问题。使用工具如Java VisualVM或MAT（Memory Analyzer Tool）来分析内存使用情况。

13. 线程分析： 使用工具如VisualVM或Thread Dump Analyzer分析应用程序的线程情况，查找是否有死锁或线程争用。

以上步骤并非详尽无遗，但它们可以为你提供一些方向来定位性能问题。在进行分析时，建议逐步排查，逐步缩小范围，以找到问题的确切位置。

Q2-怀疑是 gc 造成的，应该如何分析？

如果怀疑是GC（垃圾回收）引起的性能问题，你可以采取以下步骤来进行分析：

1. GC日志分析： 开启Java应用程序的GC日志，并对日志进行分析。GC日志中包含了GC事件的详细信息，包括每次GC的类型、持续时间、频率等。你可以使用工具如jstat、jvisualvm或其他GC日志分析工具来帮助分析GC情况。

   通过以下JVM参数开启GC日志：

    -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/path/to/gc.log
   

2. GC暂停时间分析： 查看GC暂停时间，特别关注Full GC的暂停时间。长时间的GC暂停可能导致性能下降。你可以通过GC日志中的时间戳信息来确定GC暂停的时间点。

3. GC日志分析工具： 使用工具如GCViewer、GCEasy等来分析GC日志。这些工具可以以图形化的方式展示GC事件，帮助你更直观地理解GC行为。

4. 内存使用情况： 观察应用程序的内存使用情况，包括堆内存和非堆内存的使用情况。GC问题可能与内存泄漏或内存过度分配有关。

5. Heap Dump分析： 在GC发生时生成Heap Dump，并使用Heap Dump分析工具（如Eclipse Memory Analyzer）来检查内存中的对象。这可以帮助你确定是否存在内存泄漏或不必要的对象。

   通过以下JVM参数生成Heap Dump：

    -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/path/to/heapdump.hprof
   

6. 调整GC策略： 根据GC日志的分析结果，考虑调整GC策略。你可以选择不同的垃圾回收器，调整堆大小，或者使用GC相关的JVM参数进行优化。

7. 分析业务代码： 在GC问题的背后可能是业务代码中的一些问题，例如内存泄漏、不合理的对象创建等。仔细审查业务代码，特别关注与内存管理相关的部分。

8. 使用JVM Profiler： 使用JVM性能分析工具，如VisualVM、YourKit等，来检查应用程序的性能瓶颈。这些工具可以提供更详细的性能分析信息，包括方法级别的性能分析。

在进行分析时，记得采用科学的方法，逐步排除可能性。

同时，对于生产环境，谨慎地进行任何调整，确保在非生产环境中进行充分的测试和验证。

Q3-gc log 要怎么看？

GC（垃圾回收）日志包含了有关Java应用程序中垃圾回收事件的详细信息。GC日志的分析可以帮助你了解垃圾回收的性能表现，找到潜在的性能问题。以下是一些常见的GC日志参数和如何读取它们：

GC日志参数

为了生成GC日志，你可以使用以下JVM参数：

-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/path/to/gc.log

• -XX:+PrintGC： 开启GC日志输出。
• -XX:+PrintGCDetails： 输出更详细的GC信息。
• -XX:+PrintGCDateStamps： 在每条GC日志行前加上时间戳。
• -Xloggc:/path/to/gc.log： 将GC日志输出到指定文件。

GC日志样例

一条典型的GC日志条目如下：

2023-11-13T10:30:45.678-0700: 156.456: [GC (Allocation Failure) [PSYoungGen: 4194304K->524288K(4718592K)] 6291456K->2097152K(9437184K), 0.1234567 secs] [Times: user=0.12 sys=0.01, real=0.12 secs]

这个例子中包含以下信息：

• 时间戳（2023-11-13T10:30:45.678-0700）： 记录了GC事件的发生时间。
• GC类型（GC (Allocation Failure)）： 表示发生的GC类型，例如垃圾收集的原因。
• 堆内存变化（PSYoungGen: 4194304K->524288K(4718592K)）： 描述了年轻代（Young Generation）的变化，包括垃圾回收前后的大小以及总大小。
• 堆内存总变化（6291456K->2097152K(9437184K)）： 描述了整个堆内存的变化，包括垃圾回收前后的大小以及总大小。
• GC持续时间（0.1234567 secs）： 表示垃圾回收的持续时间。
• 用户、系统、实际时间（[Times: user=0.12 sys=0.01, real=0.12 secs]）： 提供了垃圾回收阶段的用户态、内核态、以及实际时间。

GC日志分析

在分析GC日志时，你可以关注以下几点：

1. GC类型： 查看GC日志中的GC类型，了解垃圾回收的原因。例如，Allocation Failure 表示由于分配失败触发的GC。

2. 堆内存变化： 观察堆内存的变化，特别关注垃圾回收前后的大小和总大小。这可以帮助你确定GC的频率以及堆内存的使用情况。

3. GC持续时间： 注意垃圾回收的持续时间，尤其是Full GC。长时间的GC暂停可能影响应用程序的性能。

4. 分析GC频率和时长： 查看GC事件的频率和时长。如果GC事件频繁或者持续时间较长，可能需要调整堆大小或GC策略。

5. GC时间与业务操作关联： 将GC日志的时间戳与业务操作日志对比，看是否有GC事件与业务操作的相关性。这有助于找到可能导致GC的业务代码。

6. 使用GC日志分析工具： 使用工具如GCViewer、GCEasy等来图形化地分析GC日志，以更清晰地了解GC事件的模式和影响。

通过这些分析，你可以更好地理解应用程序的GC行为，找到潜在的性能问题，并进行相应的优化。

Q4-前面不是时间戳 而是 81415.284 这种时间，如何转换为一般的时间？

这种时间格式通常是相对于应用程序启动的时间的毫秒数。要将这种相对时间转换为一般的日期和时间格式，你需要知道应用程序启动的确切时间。

以下是一个简单的步骤，假设 81415.284 表示从应用程序启动开始的毫秒数：

1. 获取应用程序启动时间： 记录应用程序启动的确切时间，可以使用系统时间或者应用程序日志中的时间戳。

2. 转换相对时间： 将相对时间 81415.284 加上应用程序启动的时间戳。这将得到一个以毫秒为单位的绝对时间。

3. 转换为一般时间格式： 使用你喜欢的编程语言或工具，将绝对时间转换为一般的日期和时间格式。以下是一个示例使用Java的代码：

   long relativeTimeMillis = 81415; // 这里假设是 81415.284 的整数部分
   long applicationStartTimeMillis = System.currentTimeMillis(); // 应用程序启动的时间戳
   
   long absoluteTimeMillis = applicationStartTimeMillis + relativeTimeMillis;
   java.util.Date date = new java.util.Date(absoluteTimeMillis);
   
   System.out.println(date);
   

   这段代码中，absoluteTimeMillis 是相对时间和应用程序启动时间的和，然后使用 java.util.Date 类来创建一个日期对象，最后打印出来。

请注意，这是一个简化的例子，实际上可能需要对时区、日期格式等进行更多的处理，具体取决于你的需求和使用的编程语言。

Q5-如何根据 ps -ef | grep java 的信息，获取应用的启动时间？

在Linux系统上，你可以使用ps命令结合grep和awk等工具来获取Java应用的启动时间。启动时间通常在ps输出的一些列参数中。以下是一个可能的方法：

ps -eo pid,lstart,cmd | grep java

上述命令中：

• -eo pid,lstart,cmd：指定ps命令输出的列为进程ID（pid）、启动时间（lstart）、和命令行（cmd）。

• grep java：过滤出包含”java”的进程。

输出可能类似于：

1234 Mon Nov 13 10:30:45 2023 java -jar your-application.jar

其中，1234是Java应用程序的进程ID，Mon Nov 13 10:30:45 2023是启动时间，后面是Java应用程序的命令行。

你可以使用awk来提取启动时间：

ps -eo pid,lstart,cmd | grep java | awk '{print $2, $3, $4, $5, $6}'

这将输出类似于：

Mon Nov 13 10:30:45 2023

你可以根据需要调整awk命令的参数来选择输出的时间信息。

然后，你可以使用这个时间信息与相对时间（例如 81415.284）进行计算，从而得到相对于应用程序启动的绝对时间。

拓展阅读

jmap

jstat

jconsole

参考资料

在IDE的后台打印GC日志

JVM的GC日志的主要参数

【GC分析】Java GC日志查看

jvm 性能调优工具之 jstat

JVM系列:查看JVM使用的什么垃圾收集器

• 情境导入
  • 查看方式
  • 简单分析
  • 教训
• IDEA 中打印 GC 日志
  • 编写测试类
  • 配置运行 jvm 参数
  • 测试日志如下：
  • 简单分析
• 没有打印 gc.log
  • 场景
  • 命令 jstat
    • 如何查看 pid
    • 首先获取 pid
    • 执行命令
  • 统计监控
• 如何查看的 GC 器类型
  • 命令
  • 各个版本默认类型
  • jboss 默认配置文件地址
• chat
  • Q1-java 链路压测性能降低 50%，涉及到多个应用。应该如何分析呢？
  • Q2-怀疑是 gc 造成的，应该如何分析？
  • Q3-gc log 要怎么看？
    • GC日志参数
    • GC日志样例
    • GC日志分析
  • Q4-前面不是时间戳 而是 81415.284 这种时间，如何转换为一般的时间？
  • Q5-如何根据 ps -ef | grep java 的信息，获取应用的启动时间？
• 拓展阅读
• 参考资料