src: set PromiseHooks by Environment

[bengl]

The new JS PromiseHooks introduced in the referenced PR are per
v8::Context. This meant that code depending on them, such as
AsyncLocalStorage, wouldn't behave correctly across vm.Context
instances.

PromiseHooks are now synchronized across the main Context and any
Context created via vm.Context.

Refs: #36394
Fixes: #38781
Signed-off-by: Bryan English bryan@bryanenglish.com

[jasnell]

Any indications on any performance impact here? The changes LGTM modulo @Qard's comments but it would be good to know if this erases any of the performance boost moving to the new model introduced.

[bengl]

@jasnell

$ node -v
v16.2.0
$ node benchmark/async_hooks/promises.js
async_hooks/promises.js asyncHooks="enabled" n=1000000: 988,948.9406156435
async_hooks/promises.js asyncHooks="enabledWithDestroy" n=1000000: 177,732.39844667522
async_hooks/promises.js asyncHooks="enabledWithInitOnly" n=1000000: 949,161.9536836644
async_hooks/promises.js asyncHooks="disabled" n=1000000: 1,510,627.0817555273
$ ./node -v
v17.0.0-pre
$ ./node benchmark/async_hooks/promises.js
async_hooks/promises.js asyncHooks="enabled" n=1000000: 1,007,064.1369893635
async_hooks/promises.js asyncHooks="enabledWithDestroy" n=1000000: 186,349.95616517004
async_hooks/promises.js asyncHooks="enabledWithInitOnly" n=1000000: 964,554.1856452228
async_hooks/promises.js asyncHooks="disabled" n=1000000: 1,552,148.7418675767

It looks like it did not erase any of the performance boost.

[Qard]

Much thanks @bengl for taking this off my hands. :)

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/38346/

[Qard]

Looks like this is failing the pummel/test-vm-memleak test. Probably the contexts need to be stored as weak references?

[bengl]

@Qard yeah I switched that up in the fixup commit. It worked locally, and we'll see what the tests do.

[aduh95]

Benchmark CI: https://ci.nodejs.org/view/Node.js%20benchmark/job/benchmark-node-micro-benchmarks/1032/

                                                                   confidence improvement accuracy (*)   (**)  (***)
async_hooks/promises.js asyncHooks='disabled' n=1000000                           -2.90 %       ±3.28% ±4.37% ±5.69%
async_hooks/promises.js asyncHooks='enabled' n=1000000                      *     -2.41 %       ±2.39% ±3.20% ±4.19%
async_hooks/promises.js asyncHooks='enabledWithDestroy' n=1000000         ***      2.55 %       ±1.42% ±1.89% ±2.47%
async_hooks/promises.js asyncHooks='enabledWithInitOnly' n=1000000                 0.15 %       ±3.28% ±4.36% ±5.67%

[targos]

https://ci.nodejs.org/job/node-test-commit-linuxone/27454/nodes=rhel7-s390x/testReport/junit/(root)/test/pummel_test_vm_memleak/

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/38353/

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/38354/

[bengl]

I'm able to replicate the crash that seems to be happening nondeterministically in CI. I made a build with --debug-node and used lldb, but I think I need some help in interpreting the results. it seems to be occurring inside V8::Context::New, so I'm not sure how that would be affected by the changes I introduced here.

Expand this to see the lldb session

$ lldb -- ./node --max-old-space-size=32 --expose-gc test/pummel/test-vm-memleak.js
(lldb) target create "./node"
Current executable set to '/home/bengl/node/node' (x86_64).
(lldb) settings set -- target.run-args  "--max-old-space-size=32" "--expose-gc" "test/pummel/test-vm-memleak.js"
(lldb) r
Process 716429 launched: '/home/bengl/node/node' (x86_64)
Process 716429 exited with status = 0 (0x00000000)
(lldb) r
Process 716498 launched: '/home/bengl/node/node' (x86_64)
Process 716498 stopped
* thread #1, name = 'node', stop reason = signal SIGSEGV: invalid address (fault address: 0xca10)
    frame #0: 0x000000000143e4b0 node`v8::internal::FixStaleLeftTrimmedHandlesVisitor::VisitRootPointers(v8::internal::Root, char const*, v8::internal::FullObjectSlot, v8::internal::FullObjectSlot) + 32
node`v8::internal::FixStaleLeftTrimmedHandlesVisitor::VisitRootPointers:
->  0x143e4b0 <+32>: movq   -0x1(%rax), %rdx
    0x143e4b4 <+36>: testb  $0x1, %dl
    0x143e4b7 <+39>: je     0x143e4a0                 ; <+16>
    0x143e4b9 <+41>: movq   -0x1(%rax), %rax
(lldb) bt
* thread #1, name = 'node', stop reason = signal SIGSEGV: invalid address (fault address: 0xca10)
  * frame #0: 0x000000000143e4b0 node`v8::internal::FixStaleLeftTrimmedHandlesVisitor::VisitRootPointers(v8::internal::Root, char const*, v8::internal::FullObjectSlot, v8::internal::FullObjectSlot) + 32
    frame #1: 0x0000000001298be4 node`v8::internal::HandleScopeImplementer::IterateThis(v8::internal::RootVisitor*) + 68
    frame #2: 0x000000000143537f node`v8::internal::Heap::IterateRoots(v8::internal::RootVisitor*, v8::base::EnumSet<v8::internal::SkipRoot, int>) + 511
    frame #3: 0x0000000001443958 node`v8::internal::IncrementalMarking::StartMarking() + 376
    frame #4: 0x0000000001443718 node`v8::internal::IncrementalMarking::Start(v8::internal::GarbageCollectionReason) + 968
    frame #5: 0x000000000142c71a node`v8::internal::Heap::StartIncrementalMarkingIfAllocationLimitIsReached(int, v8::GCCallbackFlags) + 410
    frame #6: 0x00000000014ac11d node`v8::internal::PagedSpace::AllocateRawSlow(int, v8::internal::AllocationAlignment, v8::internal::AllocationOrigin) + 61
    frame #7: 0x0000000001407266 node`v8::internal::Heap::AllocateRaw(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) + 470
    frame #8: 0x0000000001436be1 node`v8::internal::Heap::AllocateRawWithLightRetrySlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) + 33
    frame #9: 0x0000000001436c81 node`v8::internal::Heap::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) + 33
    frame #10: 0x00000000017e12a4 node`v8::internal::Deserializer::ReadObject(v8::internal::SnapshotSpace) + 196
    frame #11: 0x00000000017e3f7f node`int v8::internal::Deserializer::ReadSingleBytecodeData<v8::internal::SlotAccessorForHeapObject>(unsigned char, v8::internal::SlotAccessorForHeapObject) + 271
    frame #12: 0x00000000017e15c8 node`v8::internal::Deserializer::ReadObject(v8::internal::SnapshotSpace) + 1000
    frame #13: 0x00000000017e2feb node`int v8::internal::Deserializer::ReadSingleBytecodeData<v8::internal::SlotAccessorForHandle>(unsigned char, v8::internal::SlotAccessorForHandle) + 219
    frame #14: 0x00000000017e2eef node`v8::internal::Deserializer::ReadObject() + 47
    frame #15: 0x00000000017df7ae node`v8::internal::ContextDeserializer::Deserialize(v8::internal::Isolate*, v8::internal::Handle<v8::internal::JSGlobalProxy>, v8::DeserializeInternalFieldsCallback) + 1150
    frame #16: 0x00000000017df306 node`v8::internal::ContextDeserializer::DeserializeContext(v8::internal::Isolate*, v8::internal::SnapshotData const*, bool, v8::internal::Handle<v8::internal::JSGlobalProxy>, v8::DeserializeInternalFieldsCallback) + 118
    frame #17: 0x00000000017fc657 node`v8::internal::Snapshot::NewContextFromSnapshot(v8::internal::Isolate*, v8::internal::Handle<v8::internal::JSGlobalProxy>, unsigned long, v8::DeserializeInternalFieldsCallback) + 295
    frame #18: 0x00000000014f4765 node`v8::internal::Genesis::Genesis(v8::internal::Isolate*, v8::internal::MaybeHandle<v8::internal::JSGlobalProxy>, v8::Local<v8::ObjectTemplate>, unsigned long, v8::DeserializeInternalFieldsCallback, v8::MicrotaskQueue*) + 245
    frame #19: 0x00000000014dd62d node`v8::internal::Bootstrapper::CreateEnvironment(v8::internal::MaybeHandle<v8::internal::JSGlobalProxy>, v8::Local<v8::ObjectTemplate>, v8::ExtensionConfiguration*, unsigned long, v8::DeserializeInternalFieldsCallback, v8::MicrotaskQueue*) + 77
    frame #20: 0x0000000001285cea node`v8::NewContext(v8::Isolate*, v8::ExtensionConfiguration*, v8::MaybeLocal<v8::ObjectTemplate>, v8::MaybeLocal<v8::Value>, unsigned long, v8::DeserializeInternalFieldsCallback, v8::MicrotaskQueue*) + 1690
    frame #21: 0x0000000001286127 node`v8::Context::New(v8::Isolate*, v8::ExtensionConfiguration*, v8::MaybeLocal<v8::ObjectTemplate>, v8::MaybeLocal<v8::Value>, v8::DeserializeInternalFieldsCallback, v8::MicrotaskQueue*) + 39
    frame #22: 0x0000000000f96482 node`node::contextify::ContextifyContext::CreateV8Context(this=0x0000000004da66e0, env=0x0000000004ca01a0, sandbox_obj=(val_ = 0x00007fffffffd008), options=0x00007fffffffcd28) at node_contextify.cc:199:24
    frame #23: 0x0000000000f96066 node`node::contextify::ContextifyContext::ContextifyContext(this=0x0000000004da66e0, env=0x0000000004ca01a0, sandbox_obj=(val_ = 0x00007fffffffd008), options=0x00007fffffffcd28) at node_contextify.cc:117:36
    frame #24: 0x0000000000f9e4c4 node`std::_MakeUniq<node::contextify::ContextifyContext>::__single_object std::make_unique<node::contextify::ContextifyContext, node::Environment*&, v8::Local<v8::Object>&, node::contextify::ContextOptions&>(__args=0x00007fffffffcd80, __args=0x00007fffffffcd70, __args=0x00007fffffffcd28) at unique_ptr.h:962:34
    frame #25: 0x0000000000f97edb node`node::contextify::ContextifyContext::MakeContext(args=0x00007fffffffce30) at node_contextify.cc:308:7
    frame #26: 0x00000000012d5ca7 node`v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo) + 535
    frame #27: 0x00000000012d52e3 node`v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) + 691
    frame #28: 0x00000000012d4987 node`v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) + 247
    frame #29: 0x0000000001ad83f9 node`Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_BuiltinExit + 57
    frame #30: 0x0000000001a70ea5 node`Builtins_InterpreterEntryTrampoline + 197
    frame #31: 0x0000000001a70ea5 node`Builtins_InterpreterEntryTrampoline + 197
    frame #32: 0x0000000001a70ea5 node`Builtins_InterpreterEntryTrampoline + 197
    frame #33: 0x0000000001a714e0 node
    frame #34: 0x0000000001a70ea5 node`Builtins_InterpreterEntryTrampoline + 197
    frame #35: 0x0000000001a6f11b node`Builtins_JSEntryTrampoline + 91
    frame #36: 0x0000000001a6eea3 node`Builtins_JSEntry + 131
    frame #37: 0x00000000013b4282 node`v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) + 2658
    frame #38: 0x00000000013b3805 node`v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*) + 213
    frame #39: 0x00000000012822c9 node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 425
    frame #40: 0x0000000000ee86c1 node`node::Environment::RunTimers(handle=0x0000000004ca0358) at env.cc:870:15
    frame #41: 0x0000000001a52b36 node`uv__run_timers(loop=0x0000000004b87130) at timer.c:178:5
    frame #42: 0x0000000001a5589b node`uv_run(loop=0x0000000004b87130, mode=UV_RUN_DEFAULT) at core.c:376:5
    frame #43: 0x0000000000e2adfc node`node::SpinEventLoop(env=0x0000000004ca01a0) at embed_helpers.cc:35:7
    frame #44: 0x0000000001036776 node`node::NodeMainInstance::Run(this=0x00007fffffffdb00, env_info=0x0000000004b8bb30) at node_main_instance.cc:143:19
    frame #45: 0x0000000000f50d93 node`node::Start(argc=4, argv=0x00007fffffffdd98) at node.cc:1125:38
    frame #46: 0x0000000001d99e62 node`main(argc=4, argv=0x00007fffffffdd98) at node_main.cc:127:10
    frame #47: 0x00007ffff7a5fcb2 libc.so.6`__libc_start_main + 242
    frame #48: 0x0000000000dd2abe node`_start + 46

[addaleax]

/cc @joyeecheung based on the stack trace

[joyeecheung]

I'm able to replicate the crash that seems to be happening nondeterministically in CI. I made a build with --debug-node and used lldb, but I think I need some help in interpreting the results. it seems to be occurring inside V8::Context::New, so I'm not sure how that would be affected by the changes I introduced here.

From a quick look this looks more like a bug in V8, either the GC is visiting things that it's not supposed to, or something is wiped off by GC unintentionally. Does this reproduce consistently?

[bengl]

@joyeecheung

Does this reproduce consistently?

I'm able to reproduce it in roughly (I'm guessing) 20% of the runs of that test (test/pummel/test-vm-memleak.js) on my (Linux) machine.

[Qard]

It reproduces on macOS too.

[Qard]

Is there a specific reason for the --max_old_space_size=32? It doesn't crash at all at 64.