当 busy-spining Java 线程绑定到物理内核时，是否会因为到达代码中的新分支而发生上下文切换？

Question

我对低延迟代码很感兴趣，这就是我尝试配置线程亲和性的原因。特别是，它应该有助于避免上下文切换。

我已经使用 https://github.com/OpenHFT/Java-Thread-Affinity 配置了线程关联。我运行非常简单的测试代码，只是在一个循环中旋转检查时间条件。

    long now = start;
    while (true)
    {
        if (now < start + TimeUtils.NANOS_IN_SECOND * delay)
        {
            now = TimeUtils.now();
        }
        else
        {
            // Will be printed after 30 sec
            if (TimeUtils.now() > start + TimeUtils.NANOS_IN_SECOND * (delay + 30))
            {
                final long finalNow = now;
                System.out.println("Time is over at " +
                        TimeUtils.toInstant(finalNow) + " now: " +
                        TimeUtils.toInstant(TimeUtils.now()));
                System.exit(0);
            }
        }
    }

因此，在指定的延迟执行后转到“else”并且大约在同一时间我看到上下文切换。这是预期的行为吗？这其中的具体原因是什么？在这种情况下如何避免上下文切换？

测试详情

我从这个 repo 构建 shadowJar：https://github.com/stepan2271/thread-affinity-example。然后我运行它使用以下命令（可以在这里玩弄数字，当延迟 > 60 时它对测试没有显着影响）：

taskset -c 19 java -DtestLoopBindingCpu=3 -Ddelay=74 -cp demo-all.jar main.TestLoop

我还有以下测试脚本来监控上下文切换（应该是运行，带有绑定到核心的Java线程的ID）

#!/bin/bash
while [ true ]
do
date >> ~/demo-ctxt-switches.log
cat /proc//status | grep ctxt >> ~/demo-ctxt-switches.log
sleep 3
done

此脚本的典型输出如下：

Fri Oct 16 18:23:29 MSK 2020
voluntary_ctxt_switches:    90
nonvoluntary_ctxt_switches: 37
Fri Oct 16 18:23:32 MSK 2020
voluntary_ctxt_switches:    90
nonvoluntary_ctxt_switches: 37
Fri Oct 16 18:23:35 MSK 2020
voluntary_ctxt_switches:    90
nonvoluntary_ctxt_switches: 37
Fri Oct 16 18:23:38 MSK 2020
voluntary_ctxt_switches:    90
nonvoluntary_ctxt_switches: 37
Fri Oct 16 18:23:41 MSK 2020
voluntary_ctxt_switches:    91
nonvoluntary_ctxt_switches: 37
Fri Oct 16 18:23:44 MSK 2020
voluntary_ctxt_switches:    91
nonvoluntary_ctxt_switches: 37
Fri Oct 16 18:23:47 MSK 2020
voluntary_ctxt_switches:    91
nonvoluntary_ctxt_switches: 37

因此，在开始时间发生一些变化之后，这些数字变得稳定，然后我在代码到达“else”分支时准确地看到从 1 到 3 个开关（差异小于 1 秒）。

偏差

基本配置几乎每次都会重现此行为，而有些偏差会导致我无法重现的情况。示例：

https://github.com/stepan2271/thread-affinity-example/tree/without-log4j

https://github.com/stepan2271/thread-affinity-example/tree/without-cached-nano-clock

测试环境

2 * Intel(R) Xeon(R) Gold 6244 CPU @ 3.60GHz

红帽企业版 Linux 8.1 (Ootpa)

在 /etc/systemd/system.conf 和 /etc/systemd/user.conf

中使用 CPUAffinity 隔离核心

/etc/sysconfig/irqbalance 已配置。

Openjdk 11.0.6 2020-01-14 LTS 运行时环境 18.9

Answer 1

自愿上下文切换通常意味着线程正在等待某事，例如释放锁。

async-profiler 可以帮助找到上下文切换发生的位置。这是我使用的命令行：

./profiler.sh -d 80 -e context-switches -i 2 -t -f switches.svg -I 'main*' -X 'exit_to_usermode_loop*' PID

让我们详细了解一下：

-d 80 运行分析器最多 80 秒。
-e context-switches 要分析的事件。
-i 2 间隔 = 2 个事件。我每秒分析一次context-switch，因为分析信号本身会导致上下文切换，我不想陷入递归。
-t 按线程拆分配置文件。
-f switches.svg输出文件名； svg 扩展自动选择 Flame Graph 格式。
-I 'main*' 仅在输出中包含主线程。
-X 'exit_to_usermode_loop*' 排除与非自愿上下文切换相关的事件。
PID Java 要分析的进程 ID。

结果可能与运行不同。通常我会在每个图表上看到 0 到 3 个上下文切换。

以下是上下文切换最常见的地方。它们确实与等待互斥锁有关。

ThreadSafepointState::handle_polling_page_exception() 从 TestLoop.main 呼叫。这意味着，一个线程已在另一个线程请求的安全点处停止。要调查安全点的原因，请添加 -Xlog:safepoint* JVM 选项。

[75.889s][info][safepoint        ] Application time: 74.0071000 seconds
[75.889s][info][safepoint        ] Entering safepoint region: Cleanup
[75.889s][info][safepoint,cleanup] deflating idle monitors, 0.0000003 secs
[75.889s][info][safepoint,cleanup] updating inline caches, 0.0000058 secs
[75.890s][info][safepoint,cleanup] compilation policy safepoint handler, 0.0000004 secs
[75.890s][info][safepoint,cleanup] purging class loader data graph, 0.0000001 secs
[75.890s][info][safepoint,cleanup] resizing system dictionaries, 0.0000009 secs
[75.890s][info][safepoint,cleanup] safepoint cleanup tasks, 0.0001440 secs
[75.890s][info][safepoint        ] Leaving safepoint region

是的，清理安全点在 74 秒后不久发生（正好是指定的延迟）。 is to run periodic tasks; in this case - to update inline caches. If there is cleanup work to do, a safepoint may happen every GuaranteedSafepointInterval milliseconds (1000 by default). You can disable periodic safepoints by setting -XX:GuaranteedSafepointInterval=0, but this may have performance implications.

的目的

SharedRuntime::handle_wrong_method() 来自 TimeUtils.now。当编译代码中的调用站点已创建 non-entrant 时，就会发生这种情况。由于这与 JIT 编译有关，因此添加 -XX:+PrintCompilation 选项。

  75032 1430 %     4       main.TestLoop::main @ 149 (245 bytes)   made not entrant
  75033 1433 %     3       main.TestLoop::main @ 149 (245 bytes)
  75033 1434       4       util.RealtimeNanoClock::nanoTime (8 bytes)
  75034 1431       3       util.RealtimeNanoClock::nanoTime (8 bytes)   made not entrant
  75039 1435 %     4       main.TestLoop::main @ 149 (245 bytes)
  75043 1433 %     3       main.TestLoop::main @ 149 (245 bytes)   made not entrant

是的，TestLoop.main 和 RealtimeNanoClock.nanoTime 都在 JVM 启动 75 秒后重新编译。要找出原因，请添加-XX:+UnlockDiagnosticVMOptions -XX:+LogCompilation.

这将产生一个大的编译日志，我们将在其中查找第 75 秒发生的事件。

<uncommon_trap thread='173414' reason='unstable_if' action='reinterpret' debug_id='0' compile_id='1232' compile_kind='osr' compiler='c2' level='4' stamp='75.676'>
<jvms bci='161' method='main.TestLoop main ([Ljava/lang/String;)V' bytes='245' count='1' backedge_count='533402' iicount='1'/>

由于 unstable_if 在字节码索引 161 处，这是一个。换句话说，当 main 是 JIT 编译时，HotSpot 没有为 else 分支，因为它之前从未执行过（这样一个推测性的死代码消除）。然而，为了保持编译后代码的正确性，HotSpot 设置了一个陷阱来取消优化并在推测条件失败时回退到解释器。当 if 条件变为 false.

时，这正是您的情况

Runtime1::counter_overflow()。这又与重新编译有关。运行在C1编译代码一段时间后，HotSpot发现代码很热，决定用C2重新编译。

在这种情况下，我在编译器队列上发现了争用锁。

结论

HotSpot JIT 编译器严重依赖推测优化。当推测条件失败时，这会导致去优化。去优化对于低延迟应用程序确实非常不利：除了在解释器中切换到缓慢执行之外，这可能会间接导致由于在 JVM 运行时间获取锁或将 JVM 带到安全点而导致的意外暂停。

取消优化的常见原因是 unstable_if 和 class_check。如果您想避免延迟关键路径上的去优化，请确保“warm-up”所有代码路径和虚拟方法的所有可能接收器。

当 busy-spining Java 线程绑定到物理内核时，是否会因为到达代码中的新分支而发生上下文切换？

When busy-spining Java thread is bound to physical core, can context switch happen by the reason that new branch in code is reached?

java

performance

multithreading

jvm

low-latency