java - for循环防止上下文切换

Question

随后的简单 Java 程序的行为相当奇怪。启动两个线程后，两个线程都先做自己的工作。同时之后，似乎第一个线程不再被抢占，因为第二个线程停止打印跟踪消息。第一个线程完成后，第二个线程继续工作。

当使用第二个版本的 for 循环时(i 在循环开始时递增)，程序的行为符合预期。当我在 Windows (Windows 10) 和 Linux (Ubuntu) 下执行程序时，我观察到这种行为。我使用 Java 8 编译器和 Java 8 运行时。

package test;

import java.time.LocalDateTime;
import java.time.LocalTime;

public class NoContextSwitch {

  private static volatile boolean stopT2 = false;

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

    Thread t1 = new Thread(() -> {
      System.out.printf("%s (%s): starting calculation", LocalTime.now(),
                        Thread.currentThread().getName());    
      long sum = 0;
      for (int i = 0; i < 1000000; i++) {   // version 1 of loop
      // for (int i = 0; i++ < 1000000; ) { // version 2 of loop
        for (int j = 0; j < 300000; j++)
          sum += 1;
      }      
      System.out.printf("%s (%s): finished calculation: sum=%d%n",
                        Thread.currentThread().getName(), LocalTime.now(), sum);    
    });

    Thread t2 = new Thread(() -> {
      for (int i = 1; i <= 1000000; i++) {
        System.out.printf("%s (%s): i=%d%n", Thread.currentThread().getName(), 
                          LocalTime.now(), i);
        if (stopT2)
          return;
      }
    });

    t1.start();
    t2.start();

    t1.join();
    stopT2 = true;
  }
}

输出:

...
Thread-1 (13:24:23.617): i=25362
Thread-1 (13:24:23.617): i=25363
Thread-1 (13:24:23.617): i=25364
Thread-1 (13:24:23.617): i=25365
Thread-1 (13:24:23.617): i=25366
Thread-1 (13:24:23.617): i=25367
Thread-1 (13:24:23.617): i=25368
Thread-1 (13:24:23.617): i=25369
Thread-1 (13:24:23.617): i=25370
Thread-1 (13:24:23.617): i=25371
Thread-1 (13:24:23.617): i=25372
Thread-1 (13:24:23.617): i=25373
Thread-1 (13:24:23.617): i=25374
Thread-1 (13:24:23.617): i=25375 // Thread-1 gets no time slice for 6 seconds
Thread-1 (13:24:29.646): i=25376
Thread-0 (13:24:29.646): finished calculation: sum=300000000000
Thread-1 (13:24:29.646): i=25377

编辑:程序行为摘要

做了一些进一步的实验后，我对该程序行为的看法如下:

• 一开始(直到大约 80000 次通过外循环)两个线程同时执行。
• 然后发生了一些事情，导致运行时将 CPU 独占地分配给第一个线程。只要执行该线程，就不会调度其他线程(甚至不是主线程)。程序行为发生这种变化的原因可能是热点编译器变得活跃(请参阅下面 lorenzo 的全面答案)。
• 当第一个线程完成时，所有其他线程将再次获得控制权。
• 更改线程优先级没有任何效果。
• 如果将 Thread.sleep(0)、Thread.yield() 或 print 语句插入第一个线程的循环中，程序将按预期运行(所有线程都从 CPU 时间中获得其份额)。即使访问 volatile 变量也足够了。

Answer 1

起初我以为这是 GC 启动的，即使没有进行大量的分配。所以我这样运行程序:

java -verbose:gc test.NoContextSwitch

事实上，在长时间暂停之前就存在 GC Activity ，但使用更多堆来运行它:

java -Xms1024m -Xmx1024m -verbose:gc test.NoContextSwitch

并没有让延迟消失。

所以我的第二个猜测是 HotSpot 优化器。在正常的程序执行期间，会对代码进行分析，当优化器检测到代码的“热点”部分时，就会对其进行动态优化。嗯，几乎是在飞行中，需要一点时间。这是用于检查这一点的命令行:

java -XX:+PrintCompilation -XX:+CITime test.NoContextSwitch

(有关详细信息，请参阅 here)，这样您就可以看到 HotSpot 正在执行其工作:

java.util.Formatter$FormatSpecifier::printString (105 bytes)   made not entrant
   8507  298 %     4       test.NoContextSwitch::lambda$main$0 @ -2 (98 bytes)   made not entrant

我无法告诉您所执行的优化类型，但一般来说，匿名类、lambda 等比标准代码慢，并且是优化的常见目标(至少前段时间确实如此。 ..)。老实说，这么小的类(class)花了很多时间!

出于好奇，我尝试提取两个 Thread 子类来分离顶级类，得到了相同的结果。

作为旁注:我的第一个想法是在工作线程中添加 Thread.yield 来看看它是否有任何区别。当你有一个非常紧密的循环时，这是需要考虑的事情。该命令是否会对现代 JVM 执行其操作产生影响以及产生什么影响，需要根据每种情况进行评估/测量。

迭代次数如何以及为何影响行为

我在工作线程的外部迭代中使用不同的数字进行了一些测试:

0.1百万

Thread-1 (17:30:38.704): i=12936
Thread-1 (17:30:38.704   1856  281 %     4       test.NoContextSwitch::lambda$main$0 @ -2 (98 bytes)   made not entrant
): i=12937
Thread-1 (17:30:39.534): i=12938
Thread-0 (17:30:39.533): finished calculation: sum=   1856  572       4       java.lang.Long::getChars (221 bytes)   made not entrant
30000000000
Thread-1 (17:30:39.534): i=12939
   1857  571       4       java.util.Formatter::parse (151 bytes)   made not entrant

0.5百万

Thread-1 (17:13:02.380): i=30139
Thread-1 (17:13:02.380): i=30140
Thread-1   4215  299 %     4       ( test.NoContextSwitch::lambda$main$0 @ -2 (98 bytes)   made not entrant
17:13:05.687): i=30141
Thread-1 (17:13:05.687): i=30142
Thread-1 (17:13:05.687): i=30143

100万(原值)

Thread-1 (17:20:47.435): i=30010
Thread-1 (17:20:47.435): i=30011
Thread-1 (17:20:55.851): i=30012
Thread-1 (17:20:55.851): i=   9324 30013 286 
%     4      Thread-1 test.NoContextSwitch:: (lambda$main$017:20:55.851 @ -2): i= (98 bytes)   made not entrant30014
Thread-1 (17:20:55.851): i=30015

200万

Thread-1 (17:20:03.778): i=25926
Thread-1 (17:20:03.778): i=   1011  486   !   3       java.util.Formatter::format (271 bytes)   made not entrant
25927
Thread-1 (  24471  565       4       java.util.Formatter$FormatSpecifier::print (243 bytes)   made not entrant
  24471  288 %     4       test.NoContextSwitch::lambda$main$0 @ -2 (98 bytes)   made not entrant
17:20:27.250): i=25928
Thread-0 (  24471  577       4       java.util.Formatter$FormatSpecifier::printString (105 bytes)   made not entrant
17:20:27.250): finished calculation: sum=  24472  603       4       java.util.Formatter$FormatSpecifier::print (463 bytes)   made not entrant
600000000000
Thread-1 (17:20:27.250): i=25929
Thread-1 (17:20:27.250): i=25930
Thread-1 (17:20:27.251): i=25931
  24472  581       4       java.util.Formatter::parse (151 bytes)   made not entrant

300万

Thread-1 (17:19:10.247): i=12161
Thread-1 (17:19:40.630): i=12162
Thread-1  31405  ( 594 17:19:40.630      ): i=3      12163 java.lang.ClassLoader::
checkName (43 bytes)
Thread-1 (17:19:40.630  31405 ): i= 293 12164%     
4       test.NoContextSwitch::lambda$main$0Thread-1 @ -2 ( (98 bytes)17:19:40.630   made not entrant): i=
12165
Thread-1 (17:19:40.630): i=12166
Thread-1 (17:19:40.630): i=12167
Thread-0 (17:19:40.630): finished calculation: sum=  31405  584       4       java.lang.Long::getChars (221 bytes)   made not entrant
900000000000
Thread-1 (17:19:40.630): i=12168
  31405  585       4       java.util.Formatter::parse (151 bytes)   made not entrant

400万

Thread-1 (17:16:56.893): i=11209
Thread-1  40277  284  (%     4      17:17:36.150 test.NoContextSwitch::): i=lambda$main$0 @ -2 (98 bytes)   made not entrant11210

Thread-1 (17:17:36.150): i=11211
Thread-1 (17:17:36.150): i=11212
Thread-1 (17:17:36.150): i=11213
Thread-1 (17:17:36.150): i=11214
Thread-1 (17:17:36.150): i=11215
Thread-0 (17:17:36.150): finished calculation: sum=  40278  585       4       java.lang.Long::getChars (221 bytes)   made not entrant
1200000000000
Thread-1 (17:17:36.150): i=11216
  40278  584       4       java.util.Formatter::parse (151 bytes)   made not entrant
Done  40278  456       3       java.util.Formatter$FormatSpecifier::printString (105 bytes)   made not entrant
  40278  601       4       java.io.PrintStream::printf (7 bytes)

所以是的，暂停持续时间“取决于”迭代次数。我可以推测一些事情:

• 如果数字较大，则会产生很长的延迟，一旦大暂停结束，程序就会终止(在上面的输出中查找“完成计算”字符串)。我的直觉是工作线程正在减慢整个大优化步骤的优化器，这使得暂停时间更长。当值为 1mil 时，优化器启动并开始工作，但同时工作线程结束，优化器得出结论，它的工作速度更快。这部分反射(reflect)在数据中:“大停顿”在 100 万之后接近 20/30 秒并以某种方式稳定下来。我认为大约有 1/2 百万人已经到了分水岭。这意味着优化器正在阻塞“打印机线程”，而另一个线程仍在运行。也许是因为它只优化这个 lambda(lambda$main$1 与 lambda$main$0)。

• 如果数字很短，则不会触发大的优化步骤，因此只有小的停顿。换句话说，我们可能不会考虑相同的优化，或者我们可能有一个更温和的版本。例如，“test.NoContextSwitch::lambda$main$0”优化行会进行多次比较。

• 最后，更改循环“结构”可能会改变优化器的看待方式。

请注意，“打印机线程”数字不是一个很好的引用，它们欺骗了我几次，因为它们完全独立于其他任何东西(多次运行相同的代码将在不同的“地方”产生大的停顿) .

(*) 我做了几次写入文件而不是控制台的实验，但没有得到太多结果。