JVM Safepoint停顿时间过长？ThreadLocalHandshakes与GC日志STW分析

大家好，今天我们来聊聊JVM中的一个常见问题：Safepoint停顿时间过长，以及如何利用ThreadLocalHandshakes和GC日志来分析并解决这个问题。

什么是Safepoint以及为什么需要它？

在深入分析之前，我们需要理解什么是Safepoint。简单来说，Safepoint是JVM执行过程中的一个特殊位置，在这个位置上，所有的线程都必须暂停执行，以便JVM可以执行一些全局性的操作。这些操作包括：

垃圾收集（GC）： GC需要暂停所有线程，以确保堆内存中的对象状态一致，避免出现并发修改的问题。
JIT编译优化： JIT编译器可能需要在运行时对代码进行优化，这需要暂停所有线程，以便安全地修改代码。
偏向锁撤销： 当一个线程持有的偏向锁需要被撤销时，需要暂停所有线程。
类卸载： 当JVM需要卸载一个类时，需要暂停所有线程。
调试诊断： 例如，执行jmap或jstack命令时，需要暂停所有线程以获取堆转储或线程快照。

所以，Safepoint的本质是为了保证JVM内部操作的正确性和一致性。但是，过长的Safepoint停顿时间会导致应用程序的响应变慢，甚至出现卡顿现象。

Safepoint停顿时间过长的原因分析

Safepoint停顿时间过长可能由多种原因引起，其中一些常见的原因包括：

GC压力过大： 如果堆内存不足，导致GC频繁发生，每次GC都需要进入Safepoint，从而增加停顿时间。
线程无法到达Safepoint： 某些线程可能由于以下原因无法及时到达Safepoint，导致JVM需要等待这些线程：
- 长时间运行的本地代码（JNI）： 如果线程长时间执行本地代码，JVM无法控制线程的执行，导致线程无法进入Safepoint。
- 死循环或长时间阻塞： 如果线程进入死循环或长时间阻塞，也无法进入Safepoint。
- 进入不可中断区域： 某些代码区域可能会禁用中断，导致线程无法响应Safepoint请求。
JIT编译耗时过长： JIT编译器在运行时对代码进行优化，如果编译耗时过长，也会导致Safepoint停顿时间增加。
锁竞争激烈： 激烈的锁竞争会导致线程频繁地进行上下文切换，从而影响线程到达Safepoint的速度。
大对象分配： 分配大对象需要更多的内存空间，如果堆内存碎片化严重，会导致分配失败，触发GC，从而增加Safepoint停顿时间。

使用ThreadLocalHandshakes排查问题

在JDK 8 Update 60之后，引入了ThreadLocalHandshakes这个诊断工具，可以帮助我们定位哪些线程导致Safepoint停顿时间过长。它通过在Safepoint停顿时记录各个线程的状态，帮助我们找出哪些线程正在执行本地代码、阻塞在锁上或处于其他状态，从而找到导致Safepoint停顿的瓶颈。

如何使用ThreadLocalHandshakes？

启用诊断： 需要在JVM启动时添加以下参数：
```
-XX:+UnlockDiagnosticVMOptions -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 -XX:+SafepointTimeout -XX:SafepointTimeoutDelay=1000
```
- -XX:+UnlockDiagnosticVMOptions: 允许使用诊断JVM选项。
- -XX:+PrintSafepointStatistics: 打印Safepoint统计信息。
- -XX:PrintSafepointStatisticsCount=1: 打印Safepoint统计信息的间隔次数。
- -XX:+SafepointTimeout: 启用Safepoint超时机制。
- -XX:SafepointTimeoutDelay=1000: 设置Safepoint超时时间为1秒。如果线程超过这个时间没有到达Safepoint，JVM会打印警告信息。

观察输出： 当Safepoint停顿时间超过SafepointTimeoutDelay设置的时间时，JVM会打印类似下面的警告信息：

[1.234s][warning][safepoint] Safepoint "Application runtime" timeout, vmop: ThreadLocalHandshakes, total time: 1.500s
[1.234s][warning][safepoint] VM Thread blocked for 1.500s
[1.234s][warning][safepoint] Threads which did not reach safepoint:
[1.234s][warning][safepoint] "Thread-1" id=0x000000000fa00000 waiting on monitor entry [0x00007f2d6b000000]
[1.234s][warning][safepoint] "Thread-2" id=0x000000000fb00000 executing native code

从上面的输出可以看出，Thread-1正在等待monitor entry，可能存在锁竞争；Thread-2正在执行本地代码，这可能是导致Safepoint停顿的原因。

示例代码：

public class SafepointExample {

    private static final Object lock = new Object();

    public static void main(String[] args) throws InterruptedException {
        // 线程1：模拟锁竞争
        Thread thread1 = new Thread(() -> {
            while (true) {
                synchronized (lock) {
                    try {
                        Thread.sleep(10); // 模拟持有锁的时间
                    } catch (InterruptedException e) {
                        e.printStackTrace();
                    }
                }
            }
        }, "Thread-1");

        // 线程2：模拟执行本地代码
        Thread thread2 = new Thread(() -> {
            while (true) {
                nativeMethod(); // 调用本地方法
            }
        }, "Thread-2");

        thread1.start();
        thread2.start();

        Thread.sleep(10000); // 运行一段时间后结束
    }

    // 声明一个本地方法
    public static native void nativeMethod();

    static {
        System.loadLibrary("native"); // 加载本地库
    }
}

为了运行这个示例，你需要编写一个简单的C/C++本地库：

#include <iostream>
#include <thread>
#include <chrono>
#include "SafepointExample.h"

JNIEXPORT void JNICALL Java_SafepointExample_nativeMethod(JNIEnv *env, jclass clazz) {
    while (true) {
        std::this_thread::sleep_for(std::chrono::milliseconds(1)); // 模拟本地代码执行时间
    }
}

编译这个C++代码生成动态链接库（例如libnative.so），并确保JVM可以找到这个库。编译指令（linux）：

g++ -shared -fPIC -I${JAVA_HOME}/include -I${JAVA_HOME}/include/linux SafepointExample.cpp -o libnative.so

运行这个Java程序，并添加上面提到的JVM参数。观察输出，你应该可以看到Thread-1和Thread-2相关的警告信息。

注意事项：

ThreadLocalHandshakes只能帮助你定位哪些线程导致Safepoint停顿，但并不能直接解决问题。你需要根据线程的状态进一步分析问题的原因。
启用ThreadLocalHandshakes会增加JVM的开销，因此不建议在生产环境长期启用。

分析GC日志

除了ThreadLocalHandshakes，GC日志也是分析Safepoint停顿时间的重要工具。GC日志可以提供GC发生的频率、每次GC的耗时、以及堆内存的使用情况等信息，帮助我们判断GC是否是导致Safepoint停顿的原因。

如何启用GC日志？

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

-XX:+UseG1GC -Xms2g -Xmx2g -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:gc.log

-XX:+UseG1GC：使用G1垃圾收集器。
-Xms2g -Xmx2g：设置堆内存的初始大小和最大大小为2GB。
-XX:+PrintGCDetails：打印详细的GC信息。
-XX:+PrintGCTimeStamps：打印GC发生的时间戳。
-XX:+PrintGCDateStamps：打印GC发生的日期和时间。
-XX:+PrintHeapAtGC：在每次GC前后打印堆内存的使用情况。
-Xloggc:gc.log：将GC日志输出到gc.log文件。

分析GC日志：

GC日志包含大量信息，我们需要关注以下几个方面：

GC的类型： GC分为Minor GC（Young GC）和Major GC（Full GC）。Minor GC通常比较快，而Major GC通常比较慢。频繁的Major GC是导致Safepoint停顿时间过长的常见原因。
GC的耗时： GC日志会记录每次GC的耗时，包括User time、Sys time和Real time。Real time是指GC的实际耗时，User time和Sys time是指GC使用的CPU时间。如果Real time远大于User time和Sys time，说明GC可能受到了I/O瓶颈的限制。
堆内存的使用情况： GC日志会记录每次GC前后堆内存的使用情况，包括Young Generation、Old Generation和Metaspace的使用情况。如果Old Generation的使用率很高，说明可能存在内存泄漏或对象生命周期过长的问题。
Safepoint信息： 在开启-XX:+PrintSafepointStatistics参数后，GC日志中会包含Safepoint的统计信息，包括Safepoint的类型、数量和平均停顿时间。

GC日志示例：

下面是一个G1垃圾收集器的GC日志示例：

2023-10-27T10:00:00.123+0800: 1.234: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0102345 secs]
   [Eden: 1024M(1024M)->0B(1024M) Survivors: 0B->16M Heap: 1536M(2048M)->512M(2048M)]
   [Times: user=0.01s, sys=0.00s, real=0.01s]
2023-10-27T10:00:01.456+0800: 2.567: [GC pause (G1 Evacuation Pause) (mixed), 0.0204690 secs]
   [Eden: 0B(1024M)->0B(1024M) Survivors: 16M->32M Heap: 512M(2048M)->256M(2048M)]
   [Old: 512M->256M(1024M)]
   [Times: user=0.02s, sys=0.00s, real=0.02s]

从上面的GC日志可以看出，发生了两种类型的GC：G1 Evacuation Pause (young) (initial-mark) 和 G1 Evacuation Pause (mixed)。 (young) 表示这是一次Young GC，(mixed) 表示这是一次Mixed GC。每次GC的耗时分别为0.0102345秒和0.0204690秒。堆内存的使用情况也显示在日志中。

解决GC问题：

如果GC是导致Safepoint停顿时间过长的原因，可以采取以下措施：

调整堆内存大小： 根据应用程序的实际需求，调整堆内存的大小。如果堆内存太小，会导致GC频繁发生。
选择合适的垃圾收集器： 不同的垃圾收集器适用于不同的场景。例如，G1垃圾收集器适用于大堆内存的应用程序，而CMS垃圾收集器适用于对停顿时间要求比较高的应用程序。
优化代码： 减少对象的创建和销毁，避免内存泄漏，优化对象生命周期，可以减少GC的压力。
使用对象池： 对于频繁创建和销毁的对象，可以使用对象池来重用对象，减少GC的压力。
调整GC参数： 可以通过调整GC参数来优化GC的行为。例如，可以调整Young Generation的大小，调整晋升阈值等。

其他排查思路

除了ThreadLocalHandshakes和GC日志，还可以使用其他工具和技术来排查Safepoint停顿时间过长的问题：

JFR（Java Flight Recorder）： JFR是JDK自带的性能分析工具，可以记录JVM的运行状态，包括Safepoint事件、GC事件、线程活动等。可以使用JFR来分析Safepoint停顿时间过长的原因。
JProfiler/YourKit： 这些是商业的Java性能分析工具，提供了更强大的性能分析功能，可以帮助你定位Safepoint停顿的瓶颈。
Arthas： 阿里巴巴开源的Java诊断工具，提供了丰富的命令，可以帮助你实时监控JVM的运行状态，包括线程状态、内存使用情况、GC情况等。
代码审查： 仔细审查代码，查找可能导致长时间运行、死循环、锁竞争等问题的代码。
压力测试： 通过压力测试来模拟生产环境的负载，可以帮助你发现潜在的性能问题。

案例分析

假设我们遇到了一个Safepoint停顿时间过长的问题，通过GC日志发现Major GC的频率很高，每次Major GC的耗时也很长。进一步分析发现，Old Generation的使用率很高，而且每次GC后Old Generation的回收率很低。这说明可能存在内存泄漏或对象生命周期过长的问题。

为了定位内存泄漏的原因，我们可以使用JProfiler或YourKit等内存分析工具，对堆内存进行快照分析。通过分析堆内存中的对象，可以找到哪些对象占用了大量的内存，并且这些对象的引用链是什么。如果发现某些对象应该被回收但仍然存在于堆内存中，就说明可能存在内存泄漏。

解决内存泄漏的方法是修复代码中的Bug，确保不再使用的对象能够被及时回收。例如，可以检查是否存在静态集合类持有对象的引用，或者是否存在未关闭的资源。

总结性的建议

Safepoint停顿时间过长是一个复杂的问题，需要综合运用多种工具和技术进行分析。首先，可以使用ThreadLocalHandshakes定位导致Safepoint停顿的线程，然后可以使用GC日志分析GC是否是导致Safepoint停顿的原因。如果GC是瓶颈，需要调整GC参数或优化代码，减少GC的压力。此外，还可以使用JFR、JProfiler/YourKit等工具进行更深入的分析。记住，排查Safepoint问题需要耐心和细致，需要不断地尝试和验证。

提升性能的思考方向

最终，解决Safepoint停顿时间过长的问题，不仅需要掌握相关的工具和技术，还需要深入理解JVM的运行机制和GC原理。通过不断学习和实践，才能更好地解决性能问题，提升应用程序的性能。