Garbage Collection performance events have startTime values that aren't consistent with earlier versions.

[sixcircuit]

Version

v16.13.1

Platform

Darwin halcyon 20.6.0 Darwin Kernel Version 20.6.0: Mon Aug 30 06:12:21 PDT 2021; root:xnu-7195.141.6~3/RELEASE_X86_64 x86_64

Subsystem

performance

What steps will reproduce the bug?

// repro.js

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

(function watch_gc(){

   console.log("performance.now():  ", performance.now());

   const gc_observer = new PerformanceObserver(function(items){
      items.getEntries().forEach(function(e){ 
         console.log("gc_event.startTime: ", e.startTime);
      });
   });

   gc_observer.observe({ entryTypes: ['gc'] });
   performance.measure('gc');

   setTimeout(function(){
      const a = Array(1_000_000);
      for(let i = 0; i < a.length; i++){
         a[i] = i;
      }
      const aj = JSON.stringify(a);
      const ao = JSON.parse(aj);
   }, 10);

})();

How often does it reproduce? Is there a required condition?

Reproduces every time.

What is the expected behavior?

# nvm run 14 repro.js
Running node v14.16.0 (npm v6.14.11)
performance.now():   30.141408920288086
gc_event.startTime:  57.791597
gc_event.startTime:  66.010531
gc_event.startTime:  75.778828
gc_event.startTime:  83.907098
gc_event.startTime:  109.8279
gc_event.startTime:  120.04116
gc_event.startTime:  155.110458

What do you see instead?

# nvm run 16 repro.js
Running node v16.13.1 (npm v8.1.2)
performance.now():   28.35008192062378
gc_event.startTime:  3103256681.180727
gc_event.startTime:  3103256684.168806
gc_event.startTime:  3103256699.37817
gc_event.startTime:  3103256702.559265
gc_event.startTime:  3103256734.279041
gc_event.startTime:  3103256739.367369
gc_event.startTime:  3103256774.450093

Additional information

In earlier versions (at least in 14) you could correlate GC startTime runs with other performance.now() values and detect when the GC ran during your code. It was helpful, or at least made sense.

Maybe this is getting passed straight from v8 and it's a system timestamp of some sort, but if it is, I can't figure out a way to make it sensible.

Thanks for any help with this. Let me know if you need more information.

Best,

Kendrick

[sixcircuit]

Ok. After looking at it some more, my guess is that startTime was changed from performance.now() to Number(process.hrtime.bigint()) / 1_000_000. So I guess it should either be documented, or changed back the way it was. Definitely a breaking change. I don't know what the policy is for those. I'm happy to chip in if you point me in the right direction. Don't know who makes the decision or how.

[Trott]

There doesn't seem to be a @nodejs/perf_hooks team so I guess I'll tag @jasnell directly. If I had to guess, I'd guess that f3eb224 is the source of this discrepancy, intentionally or otherwise. (Or maybe it's a V8 change?)