深入理解Thread.sleep(1000)的注意事项及原理分析

一、前言

最近服务器上出现了一次长时间的STW，原因也比较诡异.

通过jstack分析，可疑代码居然是Thread.sleep(1000)。

通过测试代码模拟，发现确实如此：

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x000000012700e800 nid=0x4d03 in Object.wait() [0x000000016f036000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x0000000715586c08> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:502)
        at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
        - locked <0x0000000715586c08> (a java.lang.ref.Reference$Lock)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=31 tid=0x000000013700c800 nid=0x2903 sleeping[0x000000016d9b2000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at com.zhufeng.gc.TestSavePoint.main(TestSavePoint.java:29)

"VM Thread" os_prio=31 tid=0x0000000126847000 nid=0x3303 runnable

其实在使用定时任务、心跳检测或者批量处理时，经常用线程来处理，并添加Thread.sleep(xxx)来进行时间控制，趁着中秋假期，花了点时间研究了一下Thread.sleep(xxx)的相关知识，果然不是平时使用的这么简单。

二、什么是SWT

本篇设计的内容比较深入，为了更好的理解，先介绍下什么是SWT。

STW: Stop-The-World，是在垃圾回收算法执⾏过程当中，将JVM内存冻结丶应用程序停顿的⼀种状态。

如果系统卡顿很明显，大概率就是频繁执行GC垃圾回收,频繁进入STW状态产生停顿的缘故

在STW 状态下，JAVA的所有线程都是停⽌执⾏的 -> GC线程除外
一旦Stop-the-world发生，除了GC所需的线程外，其他线程都将停止工作，中断了的线程直到GC任务结束才继续它们的任务。
STW是不可避免的,垃圾回收算法执⾏一定会出现STW，我们要做的只是减少停顿的时间
GC各种算法优化的重点，就是减少STW(暂停)，同时这也是JVM调优的重点。

三、代码示例

先通过测试代码，演示下Thread.sleep()导致的问题，然后再分析原因。

1、Thread.sleep(500)

/**
 * @ClassName: TestSavePoint
 * @Description GC 安全点测试
 * @author 月夜烛峰
 * @date 2022/9/9 14:21
 */
public class TestSavePoint {

    static AtomicInteger atomicInteger = new AtomicInteger(0);

    public static void main(String[] args) throws InterruptedException {

        Runnable runnable = () -> {
            for (int i = 0; i < 500000000; i++) {
                atomicInteger.incrementAndGet();
            }
            System.out.println(Thread.currentThread().getName() + " 执行结束...");
        };
        Thread t1 = new Thread(runnable);
        Thread t2 = new Thread(runnable);

        t1.start();
        t2.start();
        Thread.sleep(500);
        System.out.println("num="+atomicInteger);

    }
}

在main方法中启动两个线程t1和t2，两个线程对AtomicInteger对象进行递增，因为AtomicInteger通过CAS机制保证了原子性，所以在两个线程并发循环中，AtomicInteger递增不会有影响。

上面代码经过测试，for循环5亿次，需要8秒左右的时间，所以应该会先打印：

System.out.println("num="+atomicInteger);

实际运行下：

运行结果符合预期，然后修改代码，将Thread.sleep(500)改为Thread.sleep(1000)。

2、 Thread.sleep(1000)

通过上图动态执行结果可以看到，System.out.println("num="+atomicInteger) 等到两个线程执行完成后才执行，期间已经过去了几秒钟，而且打印结果为t1和t2循环次数的总和。Thread.sleep(1000)好像没有生效，而且长时间的停顿是如何出现的？

四、原因分析

1、安全点(Safepoint)

在《深入理解JVM虚拟机(第三版)》5.2.8 小节提到：由安全点导致长时间停顿。

是HotSpot虚拟机为了避免安全点过多带来过重的负担，对循环还有一项优化措施，认为循环次数较少的话，执行时间应该也不会太长，所以使用int类型或范围更小的数据类型作为索引值的循环默认是不会被放置安全点的。这种循环被称为可数循环（Counted Loop），相对应地，使用long或者范围更大的数据类型作为索引值的循环就被称为不可数循环（Uncounted Loop），将会被放置安全点。

安全点又是什么？

2、源码分析

看下Safepoint.cpp源码，通过注释可以了解，Java线程可能处于几种不同的状态，不同的状态提供了几种不同的处理方案。

第二点内容最多，有可能是重点，所以简单梳理第一点后，从第二点开始重点分析。

When returning from the native code, a Java thread must check the safepoint _state to see if we must block.

看到第二点的第一句话中有一个must，意思就是一个线程在运行 native 方法后，返回到 Java 线程后，一定会进行 safepoint 的检测。

想起开篇测试代码中奇怪的现象是由Thread.sleep(xxx) 导致，所以先看下Thread.sleep(xxx)的源码：

心中不免有一丝兴奋，果然有个native！

3、JVM参数

经过理论分析，我们断定肯定因为Thread.sleep(1000)进入safepoints，然后导致所有线程停止运行。

通过官网可知：

HotSpot JVM调用 safepoints 周期由 -XX:GuaranteedSafepointInterval 选项控制，每经过-XX:GuaranteedSafepointInterval 配置的时间，都会让所有线程进入 Safepoint，该选项默认为 1000ms。

安全点JVM默认值查看命令：

java -XX:+UnlockDiagnosticVMOptions -XX:+PrintFlagsFinal 2>&1 | grep Safepoint

接下来开始抓去GC日志信息进行验证。

4、GC日志抓取

运行测试代码时，添加VM参数：-XX:GuaranteedSafepointInterval

运行代码：

说明：

JVM 想执行「no vm operation」，这个操作需要线程都进入安全点，整个期间一共有 12 个线程，正在运行的线程有 2 个，需要等待这两个线程进入安全点，等待这 2 个线程进入安全点并阻塞耗费了 7285 毫秒

查看正在运行的线程：

添加VM参数：

-XX:+SafepointTimeout -XX:SafepointTimeoutDelay=7000

说明：

7000为超时时间

正在运行的线程为Thread-1和Thread-0，为了更好的区分可以修改下线程名称重新打印：

Thread t1 = new Thread(runnable,"线程一");
Thread t2 = new Thread(runnable,"线程二");

5、JVM源码定位

抓区GC日志时，显示执行「no vm operation」操作时进入了安全点，那么什么是no vm operation？

在HotSpot代码中搜索：no vm operation

搜索结果只有几个，可以很容易找到日志输出的方法。

sstats->_vmop_type == -1 ? "no vm operation" :
VM_Operation::name(sstats->_vmop_type)

这里是一个三目运算，当_vmop_type不等于-1时，才会输出no vm operation

  typedef struct {
    float  _time_stamp;                        // record when the current safepoint occurs in seconds
    int    _vmop_type;                         // type of VM operation triggers the safepoint
    int    _nof_total_threads;                 // total number of Java threads
    int    _nof_initial_running_threads;       // total number of initially seen running threads
    int    _nof_threads_wait_to_block;         // total number of threads waiting for to block
    bool   _page_armed;                        // true if polling page is armed, false otherwise
    int    _nof_threads_hit_page_trap;         // total number of threads hitting the page trap
    jlong  _time_to_spin;                      // total time in millis spent in spinning
    jlong  _time_to_wait_to_block;             // total time in millis spent in waiting for to block
    jlong  _time_to_do_cleanups;               // total time in millis spent in performing cleanups
    jlong  _time_to_sync;                      // total time in millis spent in getting to _synchronized
    jlong  _time_to_exec_vmop;                 // total time in millis spent in vm operation itself
  } SafepointStats;

通过代码注释可以了解_vmop_type只是一种可以触发安全点的类型，继续在代码里搜索有关_vmop_type的赋值逻辑：

在这里搜到了计数统计，通过方法名就可以知判断，这个方法作为安全点调用的统计方法，当然是在触发安全点调用的。

void SafepointSynchronize::begin_statistics(int nof_threads, int nof_running) {...}

begin_statistics这里加了一个statistics的后缀，说明肯定有配套的begin方法，顺着这个思路搜索：SafepointSynchronize::begin()

当出现vmThread.cpp的时候，应该是找对路子了：

loop()方法里列举了几种VM操作，从标注的三个地方可以看出是进入安全点的主要判断逻辑。

包括：线程是否正常运行，时间点是否设置，以及缓存处理。

经过以上分析，进入安全点，会导致：

主线程进入睡眠状态 1 秒钟。

在1000 ms（GuaranteedSafepointInterval）之后，JVM尝试在安全点停止，以便Java线程进行定期清理，但是直到计数循环完成后才能执行此操作。

Thread.sleep 方法从 native 返回，发现安全点操作正在进行中，于是把自己挂起，直到操作结束。

但是还有一个很大的疑问，JVM默认参数设置下，等间隔一秒中后，会进入安全点，但是为什么主线程的结果打印一直等待其它线程运行结束后才会运行？

五、int与long

我们再回头看第四节的第1点：

是HotSpot虚拟机为了避免安全点过多带来过重的负担，对循环还有一项优化措施，认为循环次数较少的话，执行时间应该也不会太长，所以使用int类型或范围更小的数据类型作为索引值的循环默认是不会被放置安全点的。这种循环被称为可数循环（Counted Loop），相对应地，使用long或者范围更大的数据类型作为索引值的循环就被称为不可数循环（Uncounted Loop），将会被放置安全点。

简单讲，也就是int被虚拟机认为比较小，使用int循环时，会等到循环结束后进入安全点，这也就说明了为什么主线程的打印信息在Thread.sleep(1000)时要等到其它两个线程处理完成后才会打印。

看下使用long 打印：

主线程并没有等到其它两个线程结束后，再打印，与我们的预期相符。

RocketMQ的作者在MQ中使用了这样一种处理，Thread.sleep(0)。

这是为了避免循环较大时，最后进入安全点导致性能问题，因此我们也可以修改为如下方式：

/**
 * @ClassName: TestSavePoint
 * @Description GC 安全点测试
 * @author 月夜烛峰
 * @date 2022/9/9 14:21
 */
public class TestSavePoint {

    static AtomicInteger atomicInteger = new AtomicInteger(0);

    public static void main(String[] args) throws InterruptedException {

        Runnable runnable = () -> {
            for (int i = 0; i < 500000000; i++) {
                atomicInteger.incrementAndGet();
                if(i%1000==0){
                    try {
                        Thread.sleep(0);
                    } catch (InterruptedException e) {
                        e.printStackTrace();
                    }
                }
            }
            System.out.println(Thread.currentThread().getName() + " 执行结束...");
        };
        Thread t1 = new Thread(runnable);
        Thread t2 = new Thread(runnable);

        t1.start();
        t2.start();
        Thread.sleep(1000);
        System.out.println("num="+atomicInteger);

    }
}

Thread.sleep(1000)的问题，果然解决。

标签： jvm java HotSpot

本文转载自: https://blog.csdn.net/yueyezhufeng/article/details/126828120
版权归原作者 月夜烛峰 所有，如有侵权，请联系我们删除。

深入理解Thread.sleep(1000)的注意事项及原理分析

一、前言

二、什么是SWT

三、代码示例

1、Thread.sleep(500)

2、 Thread.sleep(1000)

四、原因分析

1、安全点(Safepoint)

2、源码分析

3、JVM参数

4、GC日志抓取

5、JVM源码定位

五、int与long

发表评论

“深入理解Thread.sleep(1000)的注意事项及原理分析”的评论:

关于作者

overfit同步小助手

相关阅读

文章导航