console.time measuring lot of time the first time that is being executed

[jngd]

• Version: v11.15.0
• Platform: Darwin MacBook-Pro.local 18.5.0 Darwin Kernel Version 18.5.0: Mon Mar 11 20:40:32 PDT 2019; root:xnu-4903.251.3~3/RELEASE_X86_64 x86_64
• Subsystem: Not known

The first time that console.time function is used, it is measuring more time than the following calls. This is a minimum code to reproduce the issue:

console.time('time1');
console.timeEnd('time1');

console.time('time2');
console.timeEnd('time2');

It results in:

time1: 0.380ms
time2: 0.035ms

This impact directly in time measurement for any function executed in node and can lead to false results.

Any idea about?

[BridgeAR]

I am able to reproduce this and it's one of the reasons why I always measure the same thing at least twice and take the second example instead of the first. Looking just at the code does not bring up anything obviously wrong though. I guess we have to check closer what's actually executed the first and the second time and we should probably also check the function compiled and optimized or not.

[mscdex]

Perhaps some kind of initialization is happening? Adding a console.timeEnd() before anything else results in the first measurement time being reduced from ~0.112ms to ~0.02ms on my machine. Adding a process.hrtime() to the top as well brings it down further from ~0.02ms to ~0.013ms.

[Trott]

Perhaps some kind of initialization is happening? Adding a console.timeEnd() before anything else results in the first measurement time being reduced from ~0.112ms to ~0.02ms on my machine. Adding a process.hrtime() to the top as well brings it down further from ~0.02ms to ~0.013ms.

@mscdex Are you also on macOS or something else?

[mscdex]

I tested on Linux.

[antsmartian]

Testing with different versions. Looks like the first call always took a bit of time in all versions until 11, where the difference is bit high:

node-8.12.0
time1: 0.069ms
time2: 0.004ms

node-9.11.2
time1: 0.075ms
time2: 0.004ms

node-10.0.0
time1: 0.079ms
time2: 0.005ms

node-11.1.0
time1: 0.225ms
time2: 0.021ms //difference with second call also noticeable

Edit: I'm on macOS.

[tsyeyuanfeng]

What I did below may offer some clues.

Actually console.time and console.timeEnd use process.hrtime to measure time, I think there is a problem with process.hrtime, so I use demo below to confirm my guess.

const t1 = process.hrtime()
const t2 = process.hrtime()
const t3 = process.hrtime()
const t4 = process.hrtime()
const t5 = process.hrtime()

console.log('node interval 1: ', t2[1] - t1[1], 'nanos')
console.log('node interval 2: ', t3[1] - t2[1], 'nanos')
console.log('node interval 3: ', t4[1] - t3[1], 'nanos')
console.log('node interval 4: ', t5[1] - t4[1], 'nanos')

node interval 1:  110704 nanos
node interval 2:  13197 nanos
node interval 3:  6347 nanos
node interval 4:  5509 nanos

It seems that the first three calls do something time-consuming.

As process.hrtime is based on mach_absolute_time on MacOS, I use another demo to confirm if mach_absolute_time function normally.

#include <stdio.h>
#include <mach/mach_time.h>
#include <inttypes.h>

int main() {
    static mach_timebase_info_data_t info;
    mach_timebase_info(&info);

    u_int64_t t1 = mach_absolute_time() * info.numer / info.denom;    
    u_int64_t t2 = mach_absolute_time()  * info.numer / info.denom;
    u_int64_t t3 = mach_absolute_time()  * info.numer / info.denom;
    u_int64_t t4 = mach_absolute_time()  * info.numer / info.denom;
    u_int64_t t5 = mach_absolute_time()  * info.numer / info.denom;

    printf("native interval 1: %" PRIu64 " nanos\n", t2 - t1); 
    printf("native interval 2: %" PRIu64 " nanos\n", t3 - t2);
    printf("native interval 3: %" PRIu64 " nanos\n", t4 - t3);
    printf("native interval 4: %" PRIu64 " nanos\n", t5 - t4);
}

native interval 1: 43 nanos
native interval 2: 42 nanos
native interval 3: 44 nanos
native interval 4: 42 nanos

The intervals between calls are normal and stable.

So I think node may do something time-consuming in the first 2 or 3 calls of internal binding module, other methods should have the same problem. I pick process.cpuUsage to test. I put a time log at the start of CPUUsage.

static void CPUUsage(const FunctionCallbackInfo<Value>& args) {
  uint64_t t = uv_hrtime();
  printf("cpu usage time: %" PRIu64 "\n", t);

  // omit...
}

Make several calls from javascript.

process.cpuUsage()
process.cpuUsage()
process.cpuUsage()
process.cpuUsage()
process.cpuUsage()
process.cpuUsage()
process.cpuUsage()

Output

cpu usage time: 47534149403985
cpu usage time: 47534149533758
cpu usage time: 47534149592956
cpu usage time: 47534149613795
cpu usage time: 47534149622485
cpu usage time: 47534149629442
cpu usage time: 47534149636316

Intervals between calls

interval 1: 47534149533758 - 47534149403985 = 129773 nanos
interval 2: 47534149592956 - 47534149533758 = 59198 nanos
interval 3: 47534149613795 - 47534149592956 = 20839 nanos
interval 4: 47534149622485 - 47534149613795 = 8690 nanos
interval 5: 47534149629442 - 47534149622485 = 6957 nanos
interval 6: 47534149636316 - 47534149629442 = 6874 nanos

So it may be a common problem with internal binding module, but I didn't figure out the truth yet...

[bnoordhuis]

This is (largely) caused by V8's lazy compilation feature: V8 doesn't actually compile JS code until first use. Compare:

$ ./out/Release/node tmp/bug27549.js
time1: 0.121ms
time2: 0.01ms  # 1/12th

With:

$ ./out/Release/node --nolazy tmp/bug27549.js
time1: 0.014ms
time2: 0.008ms

The difference with --nolazy is small enough as to be insignificant, IMO.

I'm going to close the issue but leave a comment if you think there's something that can be done to improve the status quo.