Nested GC callback

[theanarkh]

Version

v19.0.0-pre

Platform

Darwin Kernel Version 20.3.0

Subsystem

perf_hooks

What steps will reproduce the bug?

The example code that triggers this bug has not been found. I found this bug in my project. I add some logs into node_perf.cc.

and found the log as follows.

This will make the value of gc duration inaccurate (node_perf.cc). The 4 and 16 is defined in GCType.

enum GCType {
  kGCTypeScavenge = 1 << 0,
  kGCTypeMinorMarkCompact = 1 << 1,
  kGCTypeMarkSweepCompact = 1 << 2,
  kGCTypeIncrementalMarking = 1 << 3,
  kGCTypeProcessWeakCallbacks = 1 << 4,
};

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

it is difficult to reproduce currently.

What is the expected behavior?

it should be 4 4 16 16.

What do you see instead?

4 16 16 4.

Additional information

cc @bnoordhuis

[bnoordhuis]

Weak phantom callbacks run during the prologue or epilogue of major GCs¹ so the output you're seeing is not unexpected, just an artifact of how V8 implements them.

¹ The relevant method is Heap::CollectGarbage() in deps/v8/src/heap/heap.cc.

[theanarkh]

Thanks. So is it wrong to calculate the elapsed time for each GC type through prologue and epilogue callbacks ?

[bnoordhuis]

Yes. No. Depends on whether you count kGCTypeProcessWeakCallbacks as a separate type. :-)

[theanarkh]

Get it ! Thank you very much !