v8: patch for thenables in PromiseHook API #33560

Qard · 2020-05-25T22:32:20Z

Thenables produce an additional promise which is not currently emitting before/after hooks from the PromiseHook API in V8. This change makes that additional promise also emit the proper events.

I spent some time digging into V8 trying to figure out a fix for the thenables issue which I previously attempted a higher-level fix for in #33189 and got some resistance. With this change, async_hooks and therefore AsyncLocalStorage will now be able to correctly propagate context into the then(...) method call of a thenable.

I'm submitting this as a PR here to seek help in getting this change into V8 and for us to have the option to land it as a patch, if we want. I haven't written tests for it, though I've tested it manually, as I'm not yet sure how we want to approach landing this.

cc @nodejs/v8 @nodejs/diagnostics @nodejs/async_hooks

Thenables produce an additional promise which is not currently emitting before/after hooks from the PromiseHook API in V8. This change makes that additional promise also emit the proper events.

devsnek · 2020-05-25T22:34:33Z

I can submit this upstream in V8 if you would like.

benjamingr · 2020-05-25T22:36:43Z

Thank you for doing this, this change looks a lot better to me than #33189 in terms of the performance impact

Qard · 2020-05-25T22:42:27Z

@devsnek That'd be much appreciated! I'll get to work on figuring out a V8 test for it too. :)

devsnek · 2020-05-25T22:44:11Z

deps/v8/src/builtins/builtins-microtask-queue-gen.cc

@@ -198,11 +198,20 @@ void MicrotaskQueueBuiltinsAssembler::RunSingleMicrotask(
    const TNode<Object> thenable = LoadObjectField(
        microtask, PromiseResolveThenableJobTask::kThenableOffset);

+    // Run the promise before/debug hook if enabled.
+    RunPromiseHook(Runtime::kPromiseHookBefore, microtask_context,


I'm looking through the history of promise hooks (v8:4643 and such) trying to understand why this would've been left out and I haven't found anything, but it does seem suspicious...

It looks like it was just missed. I think "thenables" just weren't considered. I don't see anything in v8:4643 suggesting otherwise.

Agreed. They have it for the other branches in there, but not thenables. Makes me think there could be a specific reason for that. As far as I can tell though it's just been overlooked. In testing it locally though, it fixes the problem perfectly for our needs.

I think there was a discussion at diagnostics summit in munich if v8 should call promise hooks for non user visible promises or not. The agreement was it is not needed as it improves performance and assumption was that no hooks are needed for "invisible" promises. Promisehooks are quite expensive for v8 - in special since they did more optimizations of promises/await that time.
To me this looks like some corner case regarding visibility of the promise created here. The Promise itself is not visible in the sense that user can access it as it is only used within the await statemachine. On the other hand the side effects are visible.

devsnek · 2020-05-26T03:38:50Z

https://crrev.com/c/2215624

Qard · 2020-05-26T03:49:28Z

Thanks, @devsnek!

mcollina · 2020-05-26T05:47:56Z

This seems the path to follow, good work!

Have you run the async_hooks benchmarks to see if this impacts at all?

Flarna · 2020-05-26T06:12:02Z

Good finding!

I expect the impact havily depends on the sample. Currently we have no sample using thenables or non native promises.

Qard · 2020-05-26T17:20:57Z

I haven't run it through the benchmarks, but just structurally, it's a branch within another branch so it should have zero cost in any non-thenable case, and only a single load and branch in the thenable case, so basically zero. 🤷

AndreasMadsen · 2020-05-30T13:48:08Z

@quad Could you explain how this integrates with the async_hooks init hook? I see it emits before and after, but what about init?

quad · 2020-05-30T13:59:19Z

@Qard

…

On 30 May 2020, at 23:48, Andreas Madsen ***@***.***> wrote: @quad <https://github.com/quad> Could you explain how this integrates with the async_hooks init hook? I see it emits before and after, but what about init? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#33560 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAF3WMEFSLCC7ELYXTDK6TRUEFCLANCNFSM4NJ2C42A>.

Qard · 2020-05-31T07:28:03Z

So what we have now with a thenable is a wrapper promise with all lifecycle events and the thenable itself which only lacks before/after events. It was actually already producing init and promiseResolve just fine, it just lacked the microtask queue codegen stuff to emit before/after events for that specific type of promise job.

If you run this on master:

'use strict';

const { AsyncLocalStorage, createHook } = require('async_hooks');

function hookFn(name) {
  return (asyncId, type, triggerId) => {
    let message = `${name} ${asyncId}`;
    if (name === 'init') {
      message += ` for ${type} from ${triggerId}`;
    }
    process._rawDebug(message);
  };
}

createHook({
  init: hookFn('init'),
  before: hookFn('before'),
  after: hookFn('after'),
  promiseResolve: hookFn('promiseResolve')
}).enable();

const store = new AsyncLocalStorage();

function thenable() {
  return {
    then(cb) {
      console.log('store in then is', store.getStore());
      process._rawDebug('before then');
      setImmediate(cb);
      process._rawDebug('after then');
    }
  };
}

store.run({}, async () => {
  process._rawDebug('before thenable()');
  await thenable();
  process._rawDebug('after thenable()');
  console.log('store after run is', store.getStore());
});

You'll get this:

init 2 for AsyncLocalStorage from 1
before 2
init 3 for PROMISE from 2
before thenable()
init 4 for PROMISE from 3
init 5 for PROMISE from 4
promiseResolve 4
after 2
init 6 for TTYWRAP from 0
init 7 for SIGNALWRAP from 0
store in then is undefined
init 8 for TickObject from 0
before then
init 9 for Immediate from 0
after then
before 8
after 8
before 9
promiseResolve 4
after 9
before 5
after thenable()
store after run is {}
init 10 for TickObject from 5
promiseResolve 3
promiseResolve 5
after 5
before 10
after 10

Note the lack of before/after events for the promise with async id 4. Now if you run this again after the fix, you get this:

init 2 for AsyncLocalStorage from 1
before 2
init 3 for PROMISE from 2
before thenable()
init 4 for PROMISE from 3
init 5 for PROMISE from 4
promiseResolve 4
after 2
before 4
init 6 for TTYWRAP from 4
init 7 for SIGNALWRAP from 4
store in then is {}
init 8 for TickObject from 4
before then
init 9 for Immediate from 4
after then
after 4
before 8
after 8
before 9
promiseResolve 4
after 9
before 5
after thenable()
store after run is {}
init 10 for TickObject from 5
promiseResolve 3
promiseResolve 5
after 5
before 10
after 10

Here you can see the promise with async id 4 does run the before and after hooks, and the store check within the then(...) method succeeds this time.

AndreasMadsen · 2020-05-31T08:22:45Z

Thanks, this is great 🙂

devsnek · 2020-05-31T16:05:54Z

@Qard can you run some benchmarks with this enabled and disabled?

Qard · 2020-06-01T03:54:27Z

@devsnek Yep. I'll put something together on Monday. 👍

Qard · 2020-06-02T00:06:03Z

This is a run of benchmark/async_hooks/promises.js with the await in the run() method replaced with a thenable:

async function run(n) {
  for (let i = 0; i < n; i++) {
    await { then(cb) { cb(); } };
  }
}

[00:06:32|% 100| 1/1 files | 60/60 runs | 3/3 configs]: Done
                                                                    confidence improvement accuracy (*)    (**)   (***)
 async_hooks/promises.js asyncHooks='disabled' n=1000000                          -3.16 %       ±9.94% ±13.24% ±17.24%
 async_hooks/promises.js asyncHooks='enabled' n=1000000                            0.18 %       ±6.39%  ±8.50% ±11.08%
 async_hooks/promises.js asyncHooks='enabledWithDestroy' n=1000000                -1.91 %       ±7.44%  ±9.90% ±12.89%

Be aware that when doing many comparisons the risk of a false-positive
result increases. In this case there are 3 comparisons, you can thus
expect the following amount of false-positive results:
  0.15 false positives, when considering a   5% risk acceptance (*, **, ***),
  0.03 false positives, when considering a   1% risk acceptance (**, ***),
  0.00 false positives, when considering a 0.1% risk acceptance (***)

Qard · 2020-06-05T17:38:02Z

The fix has landed in V8. How do we proceed from here? Float a patch until we update to the version of V8 with the fix? Can we get that backported too?

devsnek · 2020-06-05T17:52:39Z

@Qard cherry-picking it into our v8 should be fine.

targos · 2020-06-06T10:38:46Z

@Qard would you like to change this PR into a cherry-pick from upstream?
The command to run with node-core-utils is git node v8 backport eec10a2fd8fa4d0e7f5e32dedbd239d938a5dd87

Qard · 2020-06-06T17:47:42Z

Yep, sounds good to me. I’ll see about doing that on Monday. 🙂

Qard · 2020-06-06T20:54:14Z

Just tried it locally and it seems to be stuck spinning at "apply patch" forever. I left it and came back an hour later to find it still spinning. 🤔

Qard · 2020-06-06T21:12:22Z

Ah, it appears to be due to nodejs/node-core-utils#421 which looks like it's been fixed but the fix has not yet been released. 🤔

Flarna · 2020-06-06T22:35:04Z

PR to cherry-pick the v8 fix: #33778

v8: patch for thenables in PromiseHook API

8f51950

Thenables produce an additional promise which is not currently emitting before/after hooks from the PromiseHook API in V8. This change makes that additional promise also emit the proper events.

Qard added discuss Issues opened for discussions and feedbacks. async_hooks Issues and PRs related to the async hooks subsystem. labels May 25, 2020

nodejs-github-bot added the v8 engine Issues and PRs related to the V8 dependency. label May 25, 2020

devsnek reviewed May 25, 2020

View reviewed changes

mcollina mentioned this pull request May 27, 2020

Node.js Technical Steering Committee (TSC) Meeting 2020-05-27 nodejs/TSC#871

Closed

BridgeAR mentioned this pull request May 30, 2020

async_hooks: fix async/await context loss in AsyncLocalStorage #33189

Closed

3 tasks

BridgeAR force-pushed the master branch 2 times, most recently from 8ae28ff to 2935f72 Compare May 31, 2020 12:18

Qard closed this Jun 6, 2020

Qard deleted the thenables-fix-2-the-refixening branch June 7, 2020 07:28

harish2704 mentioned this pull request Jun 28, 2020

Preserving execution async resource in events knex/knex#3879

Closed

This was referenced Jul 2, 2020

Async Hooks do not recognize execution contexts created when processing thenables #22360

Closed

[async_hooks] Cannot properly propagate context in its current state nodejs/diagnostics#300

Closed

rochdev mentioned this pull request Oct 7, 2020

Context lost when awaiting on custom thenable Jeff-Lewis/cls-hooked#37

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

v8: patch for thenables in PromiseHook API #33560

v8: patch for thenables in PromiseHook API #33560

Qard commented May 25, 2020

devsnek commented May 25, 2020

benjamingr commented May 25, 2020

Qard commented May 25, 2020

devsnek May 25, 2020

benjamingr May 25, 2020

Qard May 25, 2020

Flarna May 26, 2020

devsnek commented May 26, 2020

Qard commented May 26, 2020

mcollina commented May 26, 2020

Flarna commented May 26, 2020

Qard commented May 26, 2020

AndreasMadsen commented May 30, 2020

quad commented May 30, 2020 via email

Qard commented May 31, 2020

AndreasMadsen commented May 31, 2020

devsnek commented May 31, 2020

Qard commented Jun 1, 2020

Qard commented Jun 2, 2020

Qard commented Jun 5, 2020

devsnek commented Jun 5, 2020

targos commented Jun 6, 2020

Qard commented Jun 6, 2020

Qard commented Jun 6, 2020

Qard commented Jun 6, 2020

Flarna commented Jun 6, 2020

v8: patch for thenables in PromiseHook API #33560

v8: patch for thenables in PromiseHook API #33560

Conversation

Qard commented May 25, 2020

devsnek commented May 25, 2020

benjamingr commented May 25, 2020

Qard commented May 25, 2020

devsnek May 25, 2020

Choose a reason for hiding this comment

benjamingr May 25, 2020

Choose a reason for hiding this comment

Qard May 25, 2020

Choose a reason for hiding this comment

Flarna May 26, 2020

Choose a reason for hiding this comment

devsnek commented May 26, 2020

Qard commented May 26, 2020

mcollina commented May 26, 2020

Flarna commented May 26, 2020

Qard commented May 26, 2020

AndreasMadsen commented May 30, 2020

quad commented May 30, 2020 via email

Qard commented May 31, 2020

AndreasMadsen commented May 31, 2020

devsnek commented May 31, 2020

Qard commented Jun 1, 2020

Qard commented Jun 2, 2020

Qard commented Jun 5, 2020

devsnek commented Jun 5, 2020

targos commented Jun 6, 2020

Qard commented Jun 6, 2020

Qard commented Jun 6, 2020

Qard commented Jun 6, 2020

Flarna commented Jun 6, 2020