【问题标题】:Call to System.nanoTime() in busy wait takes much longer time than usual randomly在忙碌等待中调用 System.nanoTime() 随机花费比平时更长的时间
【发布时间】:2017-07-21 12:46:00
【问题描述】:

我需要重复发送 tcp 包到服务器。发送速度为每秒 800 条消息,每条消息要匀速发送,1.25 毫秒。我计算发送所用的时间,并将线程休眠 1.25 毫秒 - 使用 Thread.sleep() 发送时间。但是我发现 Thread.sleep() 在我的机器上至少需要 1ms,即使我将 1ns 传递给它。在网上搜索了一番后,我将睡眠方式改为忙等待:

long delayNanoSec = 1250000;

long endTime = System.nanoTime() + delayNanoSec;
while (System.nanoTime() < endTime);

这在delayNanoSec 12500000 时运行良好,它会在delayNanoSec 左右花费一些时间,但是当设置为1250000 时,它会比delayNanoSec 随机花费更长的时间。我将代码更改为记录 System.nanoTime() 在每个循环中使用的时间:

long[] timeUsed = new long[50000];

long delayNanoSec = 1250000;

long endTime = System.nanoTime() + delayNanoSec;
long lastTime = 0;
int index = 0;
do {
    lastTime = System.nanoTime();
    timeUsed[index++] = lastTime;
}while(lastTime < endTime);

for(int i = 0; i < times-1; i++) {
    System.out.println("INDEX: " + i + " TIME USED: " + (nanos[i+1] - nanos[i]));
}

我得到了这样的东西:

INDEX: 1729 TIME USED: 226
INDEX: 1730 TIME USED: 387
INDEX: 1731 TIME USED: 240
INDEX: 1732 TIME USED: 240
INDEX: 1733 TIME USED: 219
INDEX: 1734 TIME USED: 246
INDEX: 1735 TIME USED: 289
INDEX: 1736 TIME USED: 283
INDEX: 1737 TIME USED: 245
INDEX: 1738 TIME USED: 244
INDEX: 1739 TIME USED: 4254974

在多次测试这段代码后,看起来 System.nanoTime() 会花费很长时间才能随机返回。在大多数情况下,它花费大约 250ns,但有时花费超过 3-4ms。

有谁知道这其中的原因吗?还是有更好的方法来完成这项工作? (控制每次发送之间的时间)

顺便说一句,对不起我的英语,希望你明白我的意思。

【问题讨论】:

  • 你试过 ScheduledExecutorService 吗?
  • 不要期望来自 JVM 的实时行为。 JVM 可能会随时暂停应用程序以执行 GC、去优化、偏向锁撤销、代码缓存清理或其他维护任务。
  • 是否总是在循环的最后一次迭代中较长时间,当它因为超过 endTime 而爆发时?
  • @ChrisNauroth 它大部分时间都发生在最后一次调用中,并且花费超过 1 毫秒。并且在某个时候发生在中间,但通常花费不超过90000ns。当延迟小于 12500 或大于 12500000 时,它几乎不会发生。我尝试了 jdk 6 和 jdk 8,得到相同的结果。
  • @apangin 我写了一个测试类,只包括一个忙碌的等待来测试它。只有一个原始的 int 类型来存储时间,以及一个反复调用 nanoTime 方法的 while 循环。非常简单,没有我自己编写的对象创建代码,并且总是在延迟在我的问题中描述的范围内时发生。这感觉很奇怪。

标签: java performance


【解决方案1】:

总结

您的代码示例构成了一个 JVM 微基准,但您没有控制外部因素。特别是,我的测试表明 JIT 编译在测试运行期间仍然很忙。这个特殊问题可以通过在进行任何测量之前运行足够的预热阶段来解决。

详情

众所周知,对在 JVM 上运行的代码进行微基准测试非常棘手,因为在被测代码无法控制的情况下,可能会出现多个不确定的混杂因素。这些因素包括垃圾收集、类加载、类的静态初始化和 JIT 编译。这些中的每一个都无需被测量的代码直接调用而发生,并且它们都可能导致执行被测代码所花费的额外时间。

关于 JVM 上的微基准测试主题有一个很好的先前问题。

How do I write a correct micro-benchmark in Java?

特别注意关于预热阶段的规则 1,建议“...[经验] 规则是数万次内循环迭代。”

我决定将这些技术应用到您的代码示例中。首先,我将测试代码简化为:

class TestNano {

    public static void main(String[] args) throws Exception {
        long[] nano = new long[10000];

        for (int i = 0; i < nano.length; ++i) {
            nano[i] = System.nanoTime();
        }

        for (int i = 0; i < nano.length; ++i) {
            System.err.println("INDEX: " + i
                    + " NANO: " + nano[i]
                    + " TIME USED: " + (i == 0 ? 0 : (nano[i] - nano[i - 1])));
        }
    }
}

我使用这个命令执行了它:

java -XX:+UnlockDiagnosticVMOptions \
        -XX:CompileCommand=print,*.* \
        -XX:+PrintAssembly \
        -Xbatch \
        -XX:CICompilerCount=1 \
        -XX:+PrintGCDetails \
        -XX:+PrintGCTimeStamps \
        -verbose:gc \
        TestNano 2>&1 | tee TestNano.out

请注意,在代码中使用System.err 很重要。额外的 JVM 诊断信息打印到 stderr,我希望该输出和我们自己的“INDEX:...”输出在同一个文件中,以便我们可以看到 JVM 活动如何与循环迭代一致。

这产生了一些类似于你的结果:

INDEX: 9976 NANO: 1500876274305377000 TIME USED: 0
INDEX: 9977 NANO: 1500876274305377000 TIME USED: 0
INDEX: 9978 NANO: 1500876274305377000 TIME USED: 0
INDEX: 9979 NANO: 1500876274307294000 TIME USED: 1917000
INDEX: 9980 NANO: 1500876274307295000 TIME USED: 1000
INDEX: 9981 NANO: 1500876274307295000 TIME USED: 0
INDEX: 9982 NANO: 1500876274307295000 TIME USED: 0

INDEX: 14560 NANO: 1500876274307599000 TIME USED: 0
INDEX: 14561 NANO: 1500876274307599000 TIME USED: 0
INDEX: 14562 NANO: 1500876274307599000 TIME USED: 0
INDEX: 14563 NANO: 1500876274312344000 TIME USED: 4745000
INDEX: 14564 NANO: 1500876274312358000 TIME USED: 14000
INDEX: 14565 NANO: 1500876274312358000 TIME USED: 0
INDEX: 14566 NANO: 1500876274312358000 TIME USED: 0

当我看到这种模式时,我总是怀疑垃圾收集,但在这种情况下,我没有从我启用的详细 GC 日志记录中看到垃圾收集的证据。

相反,每次我有一个多毫秒的光点,它大致对应于编译信息的打印,看起来类似于:

Compiled method (c2)     647   64             java.lang.StringBuilder::toString (17 bytes)
 total in heap  [0x000000010aae8610,0x000000010aae8d80] = 1904
 relocation     [0x000000010aae8730,0x000000010aae8760] = 48
 main code      [0x000000010aae8760,0x000000010aae8a40] = 736
 stub code      [0x000000010aae8a40,0x000000010aae8a58] = 24
 oops           [0x000000010aae8a58,0x000000010aae8a80] = 40
 scopes data    [0x000000010aae8a80,0x000000010aae8b60] = 224
 scopes pcs     [0x000000010aae8b60,0x000000010aae8d20] = 448
 dependencies   [0x000000010aae8d20,0x000000010aae8d28] = 8
 handler table  [0x000000010aae8d28,0x000000010aae8d70] = 72
 nul chk table  [0x000000010aae8d70,0x000000010aae8d80] = 16
Decoding compiled method 0x000000010aae8610:
Code:
[Entry Point]
[Constants]
  # {method} 'toString' '()Ljava/lang/String;' in 'java/lang/StringBuilder'
  #           [sp+0x50]  (sp of caller)
  0x000000010aae8760: mov    0x8(%rsi),%r10d
  0x000000010aae8764: shl    $0x3,%r10
  0x000000010aae8768: cmp    %r10,%rax

我看到在前 20,000 次循环迭代中间歇性地发生了重要的 JIT 编译活动。在那之后,我没有看到编译活动,TIME USED 一直是亚毫秒级的。

以上所有内容都附带一个警告,即您的结果可能会有所不同。性能分析通常特定于执行测试的环境。在我的例子中,我在 Mac 上使用这个 JVM 版本运行测试:

java version "1.7.0_79"
Java(TM) SE Runtime Environment (build 1.7.0_79-b15)
Java HotSpot(TM) 64-Bit Server VM (build 24.79-b02, mixed mode)

尽管如此,我认为我们这里有足够的证据表明,根本原因是预热时间不足导致 JIT 编译导致停顿。

您的程序的一个关键结论是,您不能依赖 JVM 来精确执行到最后期​​限,尤其是这样一个以纳秒为单位的紧迫期限。正如评论者所说,您不会获得实时行为。它可能在大多数情况下都可以正常工作,但是会有像这样延迟较长的异常值。 (根据您的应用程序,偶尔这样的停顿可能是可以接受的。)

【讨论】:

    猜你喜欢
    • 1970-01-01
    • 2019-11-22
    • 2012-02-18
    • 1970-01-01
    • 2014-06-19
    • 1970-01-01
    • 1970-01-01
    • 2011-11-05
    • 1970-01-01
    相关资源
    最近更新 更多