关于 performance.now() 测试函数执行时间

Question

我目前正在创建一个简短的 JavaScript 示例，仅用于检查函数性能。 以下是代码：

(function(){
 'use strict';
 
 var getFunctionExecuteTime = function(myFoo) {
  if(typeof myFoo !== 'function'){
   return -1;
  }else{
   var t1 = performance.now();
   myFoo();
   var t2 = performance.now();
      
   return t2-t1;
  }
 };
 
 var foo = function() {
  console.log('running.'); 
 };
 
 function foo2(){
  console.log('running by foo2.');
 }
 
 console.log('function foo2 spent time: ', getFunctionExecuteTime(foo2));
 console.log('function foo spent time: ', getFunctionExecuteTime(foo));
 console.log('function --- spent time: ', getFunctionExecuteTime(function(){
  console.log('running.');
 }));
})();

我想测试这三个函数，它们的执行时间应该是接近的，但是从Chrome控制台输出的结果很有趣，如下所示：

运行foo2。 函数foo2花费的时间：5.1000000021304

运行。 函数foo花费的时间：0.11000000085914508

运行。 函数---花费的时间：0.115999995614402

即使我交换函数的顺序，第一个函数始终需要更多的时间来执行，所以有人能给我一个提示，到底发生了什么？

- Gary Yang

---

我不知道为什么会发生这种情况，我会看看是否有关于此的任何信息。但我仍然认为这与控制台的打开有关。 - Dave Chen

我同意，我认为控制台在背后进行了初始化。 - Gary Yang

现在，我在所有内容上方添加了一个console.log调用，现在它得到了我期望的结果。 - Gary Yang

@DaveChen，你可能是对的：没有初始调用console.log()，Chrome总是返回第一个最慢的（FF不会）。但是，有了初始调用，结果就会有所不同。 - Kaiido

Answer 1

简短回答：

这是引擎V8优化Javascript代码的方式。

1. 当您的函数第一次运行时，Javascript代码直接转换为机器码，使其能够立即执行。

2. 另一个线程被调用来处理优化步骤。Javascript代码现在被转换为中间字节码。

3. 下次调用该函数时，将调用优化后的代码。

您可以在这里阅读更多信息。

调查步骤：

以下是我对Node.js环境进行的调查：

1. 如果您像这样更改函数调用顺序：

console.log('function foo spent time: ', getFunctionExecuteTime(foo));
console.log('function foo2 spent time: ', getFunctionExecuteTime(foo2));

结果：foo的运行时间比foo2长。

running.
function foo spent time:  2.8903000000864267
running by foo2.
function foo2 spent time:  0.10759999975562096
running.
function --- spent time:  0.058200000785291195

有趣的是，如果您运行此代码：

const { performance } = require('perf_hooks');

const perf = () => {
  const t1 = performance.now();
  const t2 = performance.now();

  return t2 - t1;
};

for (let i = 0; i < 10; i++) {
  console.log(`Called ${i + 1} times. Time spent: ${perf()}`);
}

结果：同一函数的第一次调用总是比其他调用花费更长的时间来执行。

Called 1 times. Time spent: 0.4595999997109175
Called 2 times. Time spent: 0.026399999856948853
Called 3 times. Time spent: 0.018099999986588955
Called 4 times. Time spent: 0.0015000002458691597
Called 5 times. Time spent: 0.0015000002458691597
Called 6 times. Time spent: 0.0014000004157423973
Called 7 times. Time spent: 0.0021000001579523087
Called 8 times. Time spent: 0.0034999996423721313
Called 9 times. Time spent: 0.002199999988079071
Called 10 times. Time spent: 0.0027000000700354576

3. 我想到了两件事情：

   • Node.js的事件循环需要花费一定时间来初始化、检查条件等操作...
   • 或者这是V8引擎（Chrome和Node.js都使用它来编译JavaScript代码）优化代码的方式。
     
     

   因此，为了弄清楚这个问题，我们对上述代码进行了一些小修改：

const { performance } = require('perf_hooks');

console.log('Waiting 1...');
console.log('Waiting 2...');
console.log('Waiting 3...');
console.log('Waiting 4...');
console.log('Waiting 5...');

const perf = () => {
  const t1 = performance.now();
  const t2 = performance.now();

  return t2 - t1;
};

for (let i = 0; i < 10; i++) {
  console.log(`Called ${i + 1} times. Time spent: ${perf()}`);
}

结果：

Waiting 1...
Waiting 2...
Waiting 3...
Waiting 4...
Waiting 5...
Called 1 times. Time spent: 0.8381999991834164
Called 2 times. Time spent: 0.00279999990016222
Called 3 times. Time spent: 0.0024000005796551704
Called 4 times. Time spent: 0.0026000002399086952
Called 5 times. Time spent: 0.00279999990016222
Called 6 times. Time spent: 0.0018000006675720215
Called 7 times. Time spent: 0.021200000308454037
Called 8 times. Time spent: 0.001600000075995922
Called 9 times. Time spent: 0.0014000004157423973
Called 10 times. Time spent: 0.001499999314546585

4. 结论：

   很明显这就是V8引擎的工作方式。你的getFunctionExecuteTime函数是被优化的部分。

- Dat Le