JVM的JFR事件：如何追踪应用中的GC暂停时间与应用停顿的关联

JVM JFR事件：追踪GC暂停时间与应用停顿的关联

大家好，今天我们来聊聊如何利用JVM的Java Flight Recorder (JFR) 事件，来追踪应用中的GC暂停时间，并分析它与应用停顿之间的关联。这对于性能优化，尤其是减少延迟至关重要。

1. JFR简介与基础概念

Java Flight Recorder (JFR) 是一个内建于JVM的性能监控和分析工具。它以低开销的方式收集运行时的JVM和应用程序的数据，并可以用于事后分析。JFR事件是JFR的核心，它们记录了JVM运行时的各种事件，例如GC、线程活动、锁竞争等等。

不同于传统的profiler，JFR的开销非常低，通常低于1%。这使得它可以长期运行在生产环境中，而不会对应用性能造成显著影响。

2. 关键的JFR事件与GC暂停

要理解GC暂停与应用停顿的关系，我们需要关注以下几个关键的JFR事件：

• GarbageCollection: 记录了每次GC事件的开始和结束时间，以及GC的类型（例如 Young GC, Full GC）。
• GCPhasePause: 记录了GC的每个暂停阶段的细节，例如扫描根集合，更新引用等。这个事件提供了GC暂停时间的更细粒度信息。
• CPULoad: 记录了JVM和系统的CPU使用情况。这有助于判断GC暂停期间CPU的利用率，从而排除因CPU瓶颈导致的性能问题。
• ThreadPark: 记录了线程被阻塞（parked）的时间和原因。如果应用线程因为GC而阻塞，这个事件会显示出来。
• JavaMonitorEnter: 记录了Java Monitor的进入事件，可以帮助我们分析锁竞争是否导致线程长时间等待，从而加剧GC的影响。
• ExecutionSample: 记录了线程的执行采样，可以帮助我们分析在GC期间，哪些代码正在执行，以及GC对这些代码执行的影响。

这些事件共同提供了关于GC暂停时间、CPU使用率和线程状态的全面信息，使我们能够诊断GC暂停是否以及如何影响了应用程序的响应能力。

3. 使用JFR记录数据

JFR可以通过命令行选项或编程方式启动。

3.1 命令行启动

在启动JVM时，可以使用以下选项启用JFR：

java -XX:StartFlightRecording=duration=60s,filename=myrecording.jfr,settings=profile MyApp

这个命令会启动一个持续60秒的JFR录制，将数据保存到myrecording.jfr文件中，并使用profile设置。profile设置提供了更详细的信息，但也会带来更高的开销。default设置则开销更低。

3.2 编程方式启动

可以使用jdk.management.jfr.FlightRecorderMXBean接口通过编程方式控制JFR。

import jdk.management.jfr.FlightRecorderMXBean;

import javax.management.*;
import java.io.IOException;
import java.nio.file.Paths;
import java.util.HashMap;
import java.util.Map;

public class JFRControl {

    public static void main(String[] args) throws MalformedObjectNameException, NotCompliantMBeanException, InstanceAlreadyExistsException, MBeanRegistrationException, IOException, AttributeNotFoundException, MBeanException, ReflectionException {

        MBeanServer mbs = java.lang.management.ManagementFactory.getPlatformMBeanServer();
        ObjectName objectName = new ObjectName("jdk.management.jfr:type=FlightRecorder");
        FlightRecorderMXBean bean =  java.lang.management.ManagementFactory.getPlatformMXBean(FlightRecorderMXBean.class);

        if (bean == null) {
            System.err.println("FlightRecorderMXBean not found!");
            return;
        }

        Map<String, String> options = new HashMap<>();
        options.put("duration", "60s");
        options.put("filename", "myrecording_programmatic.jfr");
        options.put("settings", "profile");

        long recordingId = bean.newRecording(options);
        bean.startRecording(recordingId);

        System.out.println("JFR recording started with id: " + recordingId);

        try {
            Thread.sleep(60000); // Record for 60 seconds
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        bean.stopRecording(recordingId);
        String destination = bean.dumpRecording(recordingId, Paths.get("myrecording_programmatic.jfr"));

        System.out.println("JFR recording stopped and dumped to: " + destination);
    }
}

这个示例代码演示了如何通过编程方式启动、停止和转储JFR录制。

4. 分析JFR数据

JFR数据可以使用JDK Mission Control (JMC) 或其他JFR分析工具进行分析。JMC是一个免费的工具，可以从Oracle官网下载。

4.1 使用JMC分析GC暂停

打开JMC，加载JFR文件。在JMC的界面中，可以找到“Garbage Collections”选项卡。在这个选项卡中，可以查看GC的统计信息，例如GC的次数、总暂停时间、平均暂停时间等等。

JMC还可以显示每次GC事件的细节，包括GC的类型、暂停时间、堆使用情况等。通过分析这些数据，可以了解GC暂停对应用的影响。

4.2 分析线程活动

在JMC的“Threads”选项卡中，可以查看线程的活动情况。可以查看线程的阻塞时间、等待时间、CPU使用率等。如果应用线程因为GC而阻塞，可以在这个选项卡中看到。

此外，可以查看线程的堆栈信息，了解线程在GC暂停期间正在执行的代码。这有助于确定哪些代码受到了GC的影响。

4.3 分析锁竞争

在JMC的“Locks”选项卡中，可以查看锁竞争的情况。可以查看哪些线程在争夺锁，以及线程等待锁的时间。如果锁竞争导致线程长时间等待，可能会加剧GC的影响。

4.4 利用JFR API 进行自定义分析

除了使用JMC外，还可以使用JFR API进行自定义分析。JFR API允许你以编程方式访问JFR数据，并进行自定义的分析和报告。

例如，可以使用以下代码来分析JFR文件中的GC暂停事件：

import jdk.jfr.*;
import jdk.jfr.consumer.*;

import java.io.IOException;
import java.nio.file.Path;
import java.nio.file.Paths;
import java.time.Duration;
import java.util.List;

public class JFRAnalysis {

    public static void main(String[] args) throws IOException {
        Path jfrFile = Paths.get("myrecording.jfr");

        try (RecordingFile recordingFile = new RecordingFile(jfrFile)) {
            while (recordingFile.hasMoreEvents()) {
                Event event = recordingFile.readEvent();

                if (event instanceof jdk.jfr.event.GarbageCollectionEvent) {
                    jdk.jfr.event.GarbageCollectionEvent gcEvent = (jdk.jfr.event.GarbageCollectionEvent) event;
                    Duration duration = gcEvent.getDuration();
                    String gcName = gcEvent.getName();
                    System.out.println("GC Event: " + gcName + ", Duration: " + duration);
                } else if (event instanceof jdk.jfr.event.GCPhasePauseEvent) {
                    jdk.jfr.event.GCPhasePauseEvent gcPauseEvent = (jdk.jfr.event.GCPhasePauseEvent) event;
                    Duration duration = gcPauseEvent.getDuration();
                    String phase = gcPauseEvent.getPhase();
                    System.out.println("GC Pause Phase: " + phase + ", Duration: " + duration);
                }
            }
        }
    }
}

这个示例代码读取JFR文件，并打印出每个GC事件和GC暂停阶段的持续时间。你可以根据自己的需求，编写更复杂的分析代码。

5. 案例分析：GC暂停导致的应用停顿

假设我们有一个应用，在负载较高时，偶尔会出现明显的停顿。我们使用JFR记录数据，并进行分析。

通过JMC，我们发现应用中存在频繁的Full GC，每次Full GC的暂停时间都在几百毫秒甚至几秒。

进一步分析线程活动，我们发现，在Full GC期间，所有的应用线程都处于阻塞状态。这意味着Full GC导致了应用的完全停顿。

通过分析堆栈信息，我们发现，在Full GC期间，大量的对象被回收。这表明应用中可能存在内存泄漏或者不合理的内存使用模式。

为了解决这个问题，我们可以采取以下措施：

1. 优化代码，减少内存分配: 减少不必要的对象创建，尽量重用对象。
2. 调整JVM参数: 调整堆大小，选择合适的垃圾回收器。例如，使用G1垃圾回收器可以减少Full GC的频率和暂停时间。
3. 排查内存泄漏: 使用内存分析工具，例如MAT (Memory Analyzer Tool)，查找内存泄漏的原因。

通过以上措施，我们可以减少Full GC的频率和暂停时间，从而减少应用停顿的发生。

6. 深入理解GC事件的关联

以下表格更详细地描述了各种JFR事件及其与GC暂停和应用停顿的关联，以及如何使用这些事件进行问题诊断：

JFR事件	描述	与GC关联	如何用于诊断应用停顿
GarbageCollection	记录GC事件的开始、结束时间、类型（Young/Full GC）等。	直接记录GC事件，是分析GC的基础。	分析GC的频率、持续时间，判断是否频繁发生Full GC，长时间的GC暂停是否与应用停顿的时间吻合。
GCPhasePause	记录GC暂停阶段的细节，例如扫描根集合、更新引用等。	提供更细粒度的GC暂停信息，有助于了解GC暂停的瓶颈所在。	分析GC暂停的各个阶段的耗时，找出最耗时的阶段，例如是根扫描还是对象移动。针对性地优化GC配置或代码，例如，优化根集合大小，减少对象移动。
CPULoad	记录JVM和系统的CPU使用情况。	可以帮助排除因CPU瓶颈导致的性能问题。	分析GC暂停期间的CPU使用率，如果CPU利用率很高，可能是CPU瓶颈导致GC暂停时间过长。如果CPU利用率很低，可能是I/O或其他资源瓶颈。
ThreadPark	记录线程被阻塞（parked）的时间和原因。	可以显示应用线程是否因为GC而阻塞。	如果大量线程在GC期间处于Thread.State.WAITING或Thread.State.BLOCKED状态，说明应用线程因为GC而阻塞。可以进一步分析堆栈信息，了解线程在等待什么资源。
JavaMonitorEnter	记录Java Monitor的进入事件。	可以帮助分析锁竞争是否导致线程长时间等待，从而加剧GC的影响。	分析锁竞争是否导致线程长时间等待，如果锁竞争严重，可能会加剧GC的影响，因为线程需要等待锁释放才能继续执行，而GC暂停又会进一步延迟锁的释放。可以考虑优化锁的使用方式，例如使用更细粒度的锁，或者使用无锁数据结构。
ExecutionSample	记录线程的执行采样。	可以帮助分析在GC期间，哪些代码正在执行，以及GC对这些代码执行的影响。	分析GC期间的执行采样，了解哪些代码在GC期间仍在执行，如果这些代码分配了大量的内存，可能会加剧GC的压力。还可以分析GC暂停是否导致某些关键代码的执行被延迟，从而导致应用停顿。
AllocationInNewTLAB	记录在Thread-Local Allocation Buffer (TLAB) 中分配的对象。	TLAB的分配情况可以反映年轻代的内存分配压力，有助于调整年轻代的大小。	分析TLAB的分配情况，如果TLAB分配频繁，说明年轻代的内存分配压力较大，可以考虑增大年轻代的大小，以减少Minor GC的频率。
AllocationOutsideTLAB	记录在TLAB之外分配的对象。	TLAB之外的分配通常开销较高，需要尽量避免。	分析TLAB之外的分配，找出导致这些分配的代码，并尝试优化，例如使用对象池，或者减少对象的创建。

通过结合这些事件的信息，我们可以更全面地了解GC暂停与应用停顿之间的关系，并采取相应的优化措施。

7. 总结要点

JFR是一个强大的工具，可以帮助我们诊断JVM和应用程序的性能问题。通过分析JFR事件，我们可以了解GC暂停的时间、频率和影响，并找出导致应用停顿的原因。结合JMC等工具，我们可以进行深入的分析，并采取相应的优化措施，以提高应用的性能和稳定性。