Java循环在循环中执行余数操作会阻塞所有其他线程

Question

以下代码片段执行两个线程,一个是每秒记录一次的简单计时器,第二个是执行余数操作的无限循环:

public class TestBlockingThread {
    private static final Logger LOGGER = LoggerFactory.getLogger(TestBlockingThread.class);

    public static final void main(String[] args) throws InterruptedException {
        Runnable task = () -> {
            int i = 0;
            while (true) {
                i++;
                if (i != 0) {
                    boolean b = 1 % i == 0;
                }
            }
        };

        new Thread(new LogTimer()).start();
        Thread.sleep(2000);
        new Thread(task).start();
    }

    public static class LogTimer implements Runnable {
        @Override
        public void run() {
            while (true) {
                long start = System.currentTimeMillis();
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    // do nothing
                }
                LOGGER.info("timeElapsed={}", System.currentTimeMillis() - start);
            }
        }
    }
}

这给出了以下结果:

[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1004
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1003
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=13331
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1006
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1003
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1004
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1004

我不明白为什么无限任务阻止所有其他线程13.3秒.我试图改变线程优先级和其他设置,没有任何效果.

如果您有任何解决此问题的建议(包括调整操作系统上下文切换设置),请告诉我.

Answer 1

经过这里的所有解释(感谢Peter Lawrey),我们发现这个暂停的主要来源是循环内部的安全点很少到达,因此需要很长时间才能停止所有线程以进行JIT编译的代码替换.

但我决定深入研究为什么很少达到安全点.我发现while在这种情况下为什么循环的后跳不是"安全" 有点令人困惑.

所以我尽其所能地召唤-XX:+PrintAssembly出来帮助

-XX:+UnlockDiagnosticVMOptions \
-XX:+TraceClassLoading \
-XX:+DebugNonSafepoints \
-XX:+PrintCompilation \
-XX:+PrintGCDetails \
-XX:+PrintStubCode \
-XX:+PrintAssembly \
-XX:PrintAssemblyOptions=-Mintel

经过一番调查,我发现在第三次重新编译lambda C2编译器后,完全抛弃了内部循环中的安全点轮询.

UPDATE

在分析阶段,变量i从未被视为等于0.这就是为什么C2推测性地优化了这个分支,以便循环转换为类似

for (int i = OSR_value; i != 0; i++) {
    if (1 % i == 0) {
        uncommon_trap();
    }
}
uncommon_trap();

请注意,最初的无限循环被重新整形为带有计数器的常规有限循环!由于JIT优化以消除有限计数循环中的安全点轮询,因此在该循环中也没有安全点轮询.

过了一段时间,i包裹回来0,并采取了不常见的陷阱.该方法被去优化并在解释器中继续执行.在重新编译期间,使用新知识C2识别无限循环并放弃编译.该方法的其余部分在解释器中以适当的安全点进行.

有一个伟大的必读博客文章"Safepoints:含义,副作用和管理费用"由Nitsan Wakart覆盖safepoints和这一具体问题.

已知非常长的计数循环中的安全点消除是一个问题.这个错误JDK-5014723(感谢Vladimir Ivanov)解决了这个问题.

在最终修复错误之前,可以使用解决方法.

1. 您可以尝试使用-XX:+UseCountedLoopSafepoints(这将导致整体性能损失并可能导致JVM崩溃 JDK-8161147).使用后,C2编译器继续保持后跳的安全点,原始暂停完全消失.

2. 您可以使用显式禁用有问题的方法的编译
   -XX:CompileCommand='exclude,binary/class/Name,methodName'

3. 或者您可以通过手动添加safepoint来重写代码.例如Thread.yield(),在周期结束时调用甚至更改int i为long i(感谢,Nitsan Wakart)也将修复暂停.

Answer 2

简而言之,除了i == 0到达时,你所拥有的循环内部没有安全点.编译此方法并触发要替换的代码时,需要将所有线程都置于安全点,但这需要很长时间,不仅要锁定运行代码的线程,还要锁定JVM中的所有线程.

我添加了以下命令行选项.

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:+PrintCompilation

我还修改了代码以使用浮点,这似乎需要更长的时间.

boolean b = 1.0 / i == 0;

我在输出中看到的是

timeElapsed=100
Application time: 0.9560686 seconds
  41423  280 %     4       TestBlockingThread::lambda$main$0 @ -2 (27 bytes)   made not entrant
Total time for which application threads were stopped: 40.3971116 seconds, Stopping threads took: 40.3967755 seconds
Application time: 0.0000219 seconds
Total time for which application threads were stopped: 0.0005840 seconds, Stopping threads took: 0.0000383 seconds
  41424  281 %     3       TestBlockingThread::lambda$main$0 @ 2 (27 bytes)
timeElapsed=40473
  41425  282 %     4       TestBlockingThread::lambda$main$0 @ 2 (27 bytes)
  41426  281 %     3       TestBlockingThread::lambda$main$0 @ -2 (27 bytes)   made not entrant
timeElapsed=100

注意:对于要替换的代码,必须在安全点停止线程.然而,在这里似乎很少达到这样一个安全点(可能仅在i == 0将任务更改为时)

Runnable task = () -> {
    for (int i = 1; i != 0 ; i++) {
        boolean b = 1.0 / i == 0;
    }
};

我看到类似的延迟.

timeElapsed=100
Application time: 0.9587419 seconds
  39044  280 %     4       TestBlockingThread::lambda$main$0 @ -2 (28 bytes)   made not entrant
Total time for which application threads were stopped: 38.0227039 seconds, Stopping threads took: 38.0225761 seconds
Application time: 0.0000087 seconds
Total time for which application threads were stopped: 0.0003102 seconds, Stopping threads took: 0.0000105 seconds
timeElapsed=38100
timeElapsed=100

仔细地将代码添加到循环中会导致更长的延迟.

for (int i = 1; i != 0 ; i++) {
    boolean b = 1.0 / i / i == 0;
}

得到

 Total time for which application threads were stopped: 59.6034546 seconds, Stopping threads took: 59.6030773 seconds

但是,更改代码以使用始终具有安全点的本机方法(如果它不是内在的)

for (int i = 1; i != 0 ; i++) {
    boolean b = Math.cos(1.0 / i) == 0;
}

版画

Total time for which application threads were stopped: 0.0001444 seconds, Stopping threads took: 0.0000615 seconds

注意:添加if (Thread.currentThread().isInterrupted()) { ... }到循环会添加一个安全点.

注意:这发生在16核机器上,因此不缺CPU资源.

Answer 3

找到了原因的答案.它们被称为安全点,最出名的是由于GC而发生的Stop-The-World.

请参阅此文章:在JVM中记录stop-the-world暂停

不同的事件可能导致JVM暂停所有应用程序线程.这种暂停被称为世界各地(STW)暂停.触发STW暂停的最常见原因是垃圾收集(github中的示例),但是不同的JIT操作(示例),偏向锁撤销(示例),某些JVMTI操作以及更多还需要停止应用程序.

应用程序线程可以安全停止的点称为惊讶安全点.该术语通常也用于指代所有STW暂停.

GC日志启用或多或少都很常见.但是,这不会捕获有关所有安全点的信息.要完成所有操作,请使用以下JVM选项:

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

如果您想知道明确引用GC的命名,请不要惊慌 - 打开这些选项会记录所有安全点,而不仅仅是垃圾收集暂停.如果您使用上面指定的标志运行以下示例(github中的源代码).

阅读HotSpot术语表,它定义了这个:

还原点

程序执行期间的所有GC根已知并且所有堆对象内容一致的点.从全局的角度来看,所有线程必须在GC运行之前在安全点阻塞.(作为一种特殊情况,运行JNI代码的线程可以继续运行,因为它们只使用句柄.在安全点期间,它们必须阻塞而不是加载句柄的内容.)从本地的角度来看,安全点是一个区别点在执行线程可能阻止GC的代码块中.大多数呼叫站点都有资格作为安全点.在每个安全点都存在强大的不变量,在非安全点可能会被忽视.编译的Java代码和C/C++代码都在安全点之间进行了优化,但在安全点之间却不那么好.JIT编译器在每个安全点发出GC映射.VM中的C/C++代码使用基于宏的基于惯例的约定(例如,TRAPS)来标记潜在的安全点.

运行上面提到的标志,我得到这个输出:

Application time: 0.9668750 seconds
Total time for which application threads were stopped: 0.0000747 seconds, Stopping threads took: 0.0000291 seconds
timeElapsed=1015
Application time: 1.0148568 seconds
Total time for which application threads were stopped: 0.0000556 seconds, Stopping threads took: 0.0000168 seconds
timeElapsed=1015
timeElapsed=1014
Application time: 2.0453971 seconds
Total time for which application threads were stopped: 10.7951187 seconds, Stopping threads took: 10.7950774 seconds
timeElapsed=11732
Application time: 1.0149263 seconds
Total time for which application threads were stopped: 0.0000644 seconds, Stopping threads took: 0.0000368 seconds
timeElapsed=1015

注意第三个STW事件:
停止的总时间: 10.7951187秒
停止线程: 10.7950774秒

JIT本身几乎没有时间,但是一旦JVM决定执行JIT编译,它就进入了STW模式,但是由于要编译的代码(无限循环)没有调用站点,所以没有达到安全点.

当JIT最终放弃等待并且结束代码处于无限循环时,STW结束.

Answer 4

在我自己跟踪注释线程和一些测试之后,我认为暂停是由JIT编译器引起的.为什么JIT编译器花了这么长时间超出了我的调试能力.

但是,由于您只询问如何防止这种情况,我有一个解决方案:

将无限循环拉入可以从JIT编译器中排除的方法

public class TestBlockingThread {
    private static final Logger LOGGER = Logger.getLogger(TestBlockingThread.class.getName());

    public static final void main(String[] args) throws InterruptedException     {
        Runnable task = () -> {
            infLoop();
        };
        new Thread(new LogTimer()).start();
        Thread.sleep(2000);
        new Thread(task).start();
    }

    private static void infLoop()
    {
        int i = 0;
        while (true) {
            i++;
            if (i != 0) {
                boolean b = 1 % i == 0;
            }
        }
    }

使用此VM参数运行程序:

-XX:CompileCommand = exclude,PACKAGE.TestBlockingThread :: infLoop(用包信息替换PACKAGE)

您应该得到一条这样的消息来指示该方法何时进行JIT编译:
###排除编译:static blocking.TestBlockingThread :: infLoop
您可能会注意到我将该类放入一个名为blocking的包中