about performance.now() to test function execute time

Question

I am currently creating a short javascript demo by myself just for inspect function performance purpose. The code is below:

(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.');
	}));
})();

Those three functions i want to test, their execute time suppose to be close, but the output from Chrome console I got is interesting, like below:

running by foo2. function foo2 spent time: 5.1000000021304

running. function foo spent time: 0.11000000085914508

running. function --- spent time: 0.115999995614402

even if I swap the order of functions, the first one always consume more time to execute, so could somebody give me a hint that what is really going on?

Answer 1

Quick answer:

It's the way engine V8 optimizes the Javascript code.

1. The first time your function run, the Javascript code is transformed directly into machine code, allows it to be executed immediately.

2. Another thread is called to handle optimization steps. The Javascript code is now turned into an intermediate bytecode.

3. The next time you call that function, the optimized code is called.

You can read more here.

Investigation steps:

Here's my investigating on Node.js environment:

1. If you change the order of function calls like this:

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

Result: foo will take a longer time to run than foo2.

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

2. The interesting part is if you run this code:

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()}`);
}

Result: the first call of the same function always takes a longer time to be executed than the others.

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. Here're 2 things come into my mind:

   • The event-loop of Node.js takes a small time to initiate, conditions checking,...
   • Or it's the way V8 engine (which is used both in Chrome and Node.js to compile Javascript code) optimize code.
     
     

   So, to figure out, here's a small modification to the above code:

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()}`);
}

Result:

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. Conclusion:

   So, clearly that it's the way V8 engine works. Your getFunctionExecuteTime function is the thing that got optimized here.