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

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

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秒内阻塞所有其他线程。我试图改变线程优先级和其他设置,没有工作。

如果你有任何建议来解决这个问题(包括调整操作系统上下文切换设置) ,请让我知道。

8715 次浏览

经过这里的所有解释(多亏了 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编译器完全抛弃了循环内的安全点轮询。

更新

在分析阶段变量 i从未被看到等于0。这就是为什么 C2推测性地优化了这个分支,这样循环就变成了

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

注意,最初的无限循环被重新形成了一个带有计数器的常规有限循环!由于 JIT 优化消除了有限计数循环中的安全点轮询,所以在这个循环中也没有安全点轮询。

过了一段时间,i包回到 0,并采取了不寻常的陷阱。该方法被解除了优化,并在解释器中继续执行。在重新编译的过程中,C2用一种新的知识识识别出了无限循环,放弃了编译。其余的方法在有适当安全点的解释器中进行。

有一个伟大的必须阅读的博客文章 “安全点: 含义、副作用和管理费用”Nitsan Wakart涵盖安全点和这个特殊的问题。

在非常长的计数循环中消除安全点已知是一个问题。Bug JDK-5014723(多亏了 弗拉基米尔 · 伊万诺夫)解决了这个问题。

The workaround is available until the bug is finally fixed.

  1. 您可以尝试使用 -XX:+UseCountedLoopSafepoints(它的 will导致整体性能损失和 may lead to JVM crash JDK-8161147)。在使用它 C2编译器继续保持安全点在后跳和原来的暂停完全消失。
  2. 可以使用以下方法显式禁用编译有问题的方法
    -XX:CompileCommand='exclude,binary/class/Name,methodName'

  3. 或者可以通过手动添加安全点来重写代码。例如,在周期结束时 Thread.yield()呼叫,甚至改变 int ilong i(感谢,Nitsan Wakart)也将修复暂停。

简而言之,除非到达 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 资源。

在跟踪了注释线程和我自己的一些测试之后,我相信暂停是由 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 =  排除,PACKAGE.TestBlockingThread: : infLoop (用您的包信息替换 PACKAGE)

您应该得到这样的消息来指示方法何时会被 JIT 编译: < br/> # # # 排除编译: 静态阻塞。TestBlockingThread: : infLoop
you may notice that I put the class into a package called blocking

找到 为什么的答案了。它们被称为安全点,最著名的是因 GC 而发生的“停止世界”(Stop-The-World)。

请看这篇文章: 记录 JVM 中的 stop-the-world 暂停

不同的事件可能导致 JVM 暂停所有应用程序线程。这种暂停称为“停止世界”(Stop-The-World,STW)暂停。引发 STW 暂停的最常见原因是垃圾收集(例如 github) ,但是不同的 JIT actions(例如)、偏向锁撤销(例如)、某些 JVMTI 操作以及更多操作也需要停止应用程序。

可以安全地停止应用程序线程的点称为 安全点。这个词也经常用来指所有的 STW 暂停。

启用 GC 日志或多或少是常见的。但是,这并不能捕获所有安全点的信息。要获得所有这些信息,请使用以下 JVM 选项:

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

If you are wondering about the naming explicitly referring to GC, don’t be alarmed – turning on these options logs all of the safepoints, not just garbage collection pauses. If you run a following example (source in github) with the flags specified above.

阅读 HotSpot 术语词汇表,它定义了这一点:

safepoint

在程序执行过程中,所有 GC 根都已知且所有堆对象内容一致的一个点。从全局角度来看,所有线程都必须在安全点阻塞,然后 GC 才能运行。(作为特殊情况,运行 JNI 代码的线程可以继续运行,因为它们只使用句柄。在安全点期间,它们必须阻塞而不是加载句柄的内容。)从本地的角度来看,安全点是代码块中的一个可分辨点,在这个代码块中,正在执行的线程可能会阻塞 GC。Most call sites qualify as safepoints.强不变量在每个安全点都成立,在非安全点可能被忽略。编译的 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秒
Stopping threads took: 10.7950774 seconds

JIT 本身几乎没有花费任何时间,但是一旦 JVM 决定执行 JIT 编译,它就进入了 STW 模式,然而由于要编译的代码(无限循环)没有 呼叫网站,因此没有达到安全点。

当 JIT 最终放弃等待并断定代码处于无限循环中时,STW 结束。