围绕几个方法调用使用 System.nanoTime() 的经过时间提供的值低于每个方法中经过时间的总和？答案

【问题标题】：Elapsed time using System.nanoTime() around several method calls delivers a lower value than the sum of of the elapsed times in each method?围绕几个方法调用使用 System.nanoTime() 的经过时间提供的值低于每个方法中经过时间的总和？
【发布时间】：2013-02-11 18:44:20
【问题描述】：

我正在使用 System.nanoTime() 来测量调用多个方法所需的时间。在每种方法中，我都会做同样的事情来衡量每种方法需要多长时间。最后经过时间的总和应该小于总经过时间，或者我认为。然而，事实并非如此。

例子：

public static void main(String[] args){
  long startTime = System.nanoTime();
  method1();
  method2();
  method3();
  System.out.println( "Total Time: " + (System.nanoTime() - startTime) / 1000000);
}
private void method1(){
  long startTime = System.nanoTime();
  //Stuff
  System.out.println( "Method 1: " + (System.nanoTime() - startTime) / 1000000);
}
// same for all other methods

在我的情况下，总时间约为 950 毫秒，但每个经过时间的总和为 1300 毫秒以上。这是为什么呢？

编辑：

好吧，说得更清楚一点，我在多次写入数组时（我只是在测试中这样做）时没有得到这种行为。当我这样做时，我得到了非常精确的结果（+-1ms）。

我实际上在做的是这样的：

我将两个相当大的文本文件读入字符串数组（第一个文件中 1000 * ~2000 个字符，第二个文件中 200 * ~100 个字符）。

然后我对读取第一个文件得到的字符串数组进行大量比较，并使用结果来计算一些概率。

EDIT2：我的错误，我在方法中调用方法并总结了那些时间，这些时间已经包含在内。没有这些双倍，这一切都加起来了。感谢您解决这个问题！

【问题讨论】：

他们都在同一个线程吗？
都在同一个线程中，是的。尝试不除法，Sum = 1 280 182 306 Total = 953 483 065，所以不，这不是舍入错误。
为了获得更好的答案，您应该尝试创建一个重现该行为的最小示例。这将帮助人们更好地评估问题所在。
JVM可以对涉及System.nanoTime的代码重新排序多少？可以通过以相反的顺序执行两个 nanoTime 调用来解释该症状，以便将一小段时间计算两次。
您确实有三个方法调用需要求和，还是很多？因为将许多小数字相加会累积很多错误。

标签： java

【解决方案1】：

为了进一步研究这件事，也许你可以打印出每个方法和全局过程的开始和结束时间。这里你只是打印每个人花费的时间和总时间，但你可以输出如下内容：

Global start   : (result of System.nanoTime() here)
Method 1 Start : ...
Method 1 End   : ....
Method 2 Start : ....
Method 2 End   : ....
Method 3 Start : ....
Method 3 End   : ....
Global end     : ....

我建议您这样做的原因如下：您期望GlobalEnd - GlobalStart 大于或等于(End1-Start1) + (End2-Start2) + (End3-Start3)。但这种关系实际上源于这样一个事实，即如果一切都是顺序的，则以下情况成立：

GlobalStart <= Start1 <= End1 <= Start2 <= End2 <= Start3 <= End3 <= GlobalEnd

不是吗？

那么对你来说有趣的是知道在这个不等式列表中什么是不正确的。这可能会给你一些见解。

【讨论】：

运行：MAIN方法启动：30495884497522方法1开始：30495885305501方法1开始：30496199980102方法1结束：30496200498200方法3开始：30496201642783方法2开始：30496201691097方法2结束：30496264901276方法 3 结束： 30496637264023 方法 5 开始： 30496637324414 方法 4 开始： 30496637348253 方法 4 结束： 30497332544531 方法 5 结束： 30497364712059 主要方法结束： 30497376773253 构建秒数？ /跨度>
感谢您提供结果。显然方法 2 和 3 是同时运行的（即在前一个尚未完成时开始一个），方法 4 和 5 也是。这些方法的作用是什么？
顺便说一句，告诉我，你不是从方法 3 调用方法 2，从方法 5 调用方法 4，不是吗？
其实我是。方法 3 调用 2，5 调用 4。这就是为什么开始和结束时间适合（？）
你将经过的时间相加在 1、2、3、4 和 5 中？？当您从 3 调用 2 时，2 中的经过时间包含在方法 3 的经过时间中。因此它们不能相加。如果您想要有意义的结果，您可以将 1、3 和 5 中的时间相加。

【解决方案2】：

我认为您的代码没有任何问题。在我的测试中，我从您的代码中得到了正确的经过时间。

这是我的输出：

方法一：600 方法二：500 方法三：10 总时间：1110 构建成功（总时间：2 秒）

【讨论】：

仅在大量写入数组时，我得到了准确的结果（相差 1 毫秒）。在我的实际项目中，我将两个文件读入字符串，对这些字符串进行大量比较并计算一些东西。我现在最好的猜测是，因为我是在多核 CPU 上运行它，所以这会搞砸时间（在某处读到 nanoTime() 在多核上可能会出错）。

【解决方案3】：

尝试将你的 doe 更改为这样的：

public static void main(String[] args)
{
    long elaspeTime = 0;
    elaspeTime += method1();
    elaspeTime += method2();
    elaspeTime += method3();
    System.out.println("Total Time: " + elaspeTime / 1000000);
}

private static long method1()
{
    long startTime = System.nanoTime();
    //Do some work here...
    System.out.println("Method 1: " + (System.nanoTime() - startTime) / 1000000);
    return System.nanoTime() - startTime;

}

【讨论】：