Retain async context when notifying PerformanceObservers by ZauberNerd · Pull Request #36343 · nodejs/node

ZauberNerd · 2020-12-01T14:20:07Z

Problem description:
Using the perf_hooks module (specifically the User Timing API), to collect timings in an async context (i.e. to collect metrics during the lifetime of an HTTP request), it is not possible to correlate the PerformanceEntrys with a single request (except for using workarounds, such as prefixing all mark names with a unique id).
This is required, when implementing e.g. tracing solutions, where one wants to have timings per requests.

Solution:
With the changes in this PR we are able to retain async contexts when calling the PerformanceObserver, which enables us to, for example, access an AsyncLocalStorage in the observer callback to store the collected metrics per request.

Additional notes:

The above mentioned solution won't work when the PerformanceObserver is buffered.

Questions:

What, if anything, should go into the documentation? I suppose we should mention that buffered observers do not retain the async context?
Would this change get back-ported to the v12 release?

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
documentation is changed or added
commit message follows commit guidelines

addaleax

I’ll mark this as request changes only because it already has an approval but still needs tests in order to land :) But I’m fine with the approach here

ZauberNerd · 2020-12-03T09:20:21Z

Hi @addaleax could you please take another look here?
I've added a test and @nicstange answered your comment with a question: #36343 (comment) it would be great if you could give us some directions on what to do :)

nodejs-github-bot · 2020-12-07T18:00:11Z

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

There are situations where one wants to invoke a JS callback's ->Call() from C++ and in particular retain any existing async_context state, but where it's not obvious that a plain ->Call() would be safe at the point in question. Such callsites usually resort to node::MakeCallback(..., async_context{0, 0}), which unconditionally pushes the async_context{0, 0} and takes the required provisions for the ->Call() itself such as triggering the tick after its return, if needed. An example would be the PerformanceObserver invocation from PerformanceEntry::Notify(): this can get called when coming from JS through e.g. perf_hooks.performance.mark() and alike, but perhaps also from nghttp2 (c.f. EmitStatistics() in node_http2.cc). In the former case, a plain ->Call() would be safe and it would be desirable to retain the current async_context so that PerformanceObservers can access it resp. the associated AsyncLocalStorage. However, in the second case the additional provisions taken by node::MakeCallback() might potentially be strictly required. So PerformanceEntry::Notify() bites the bullet and invokes the PerformanceObservers through node::MakeCallback() unconditionally, thereby always rendering any possibly preexisting async_context inaccessible. Introduce the convenience node::MakeSyncCallback() for such usecases, which would basically forward to ->Call() if safe and to node::MakeCallback(..., async_context{0, 0}) otherwise. Co-Authored-By: ZauberNerd <zaubernerd@zaubernerd.de> PR-URL: nodejs#36343 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Rich Trott <rtrott@gmail.com>

It's desirable to retain async_contexts active at callsites of perf_hooks.performance.mark() and alike in the subsequent PerformanceObserver invocations such that the latter can access e.g. associated AsyncLocalStorage instances. In working towards this goal replace the node::MakeCallback(..., async_context{0, 0}) in PerformanceEntry::doNotify() by the new node::MakeSyncCallback() introduced specifically for this purpose. This change will retain the original async_context, if any, in perf_hook's observersCallback() and thus, for the subsequent doNotify() on unbuffered PerformanceObservers. Co-Authored-By: ZauberNerd <zaubernerd@zaubernerd.de> PR-URL: nodejs#36343 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Rich Trott <rtrott@gmail.com>

This reverts commit 009e418. AFAIU the discussion at [1], PerformanceObserver had been made to inherit from AsyncResource more or less as a band-aid in lack of a better async_context candidate to invoke it in. In order to enable access to AsyncLocalStores from PerformanceObservers invoked synchronously through e.g. measure() or mark(), the current async_context, if any, should be retained. Note that this is a breaking change, but - as has been commented at [1], PerformanceObserver being derived from AsyncResource is a "minor divergence from the spec" anyway, - to my knowledge this is an internal implementation detail which has never been documented and - I can't think of a good reason why existing PerformanceObserver implementations would possibly rely on it. OTOH, it's probably worthwhile to not potentially invoke before() and after() async_hooks for each and every PerformanceObserver notification. [1] nodejs#18789 Co-Authored-By: ZauberNerd <zaubernerd@zaubernerd.de> PR-URL: nodejs#36343 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Rich Trott <rtrott@gmail.com>

This test proves that the PerformanceObserver callback gets called with the async context of the callsite of performance.mark()/measure() and therefore AsyncLocalStorage can be used inside a PerformanceObserver. PR: nodejs#36343 PR-URL: nodejs#36343 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Rich Trott <rtrott@gmail.com>

Trott · 2020-12-11T12:48:06Z

Landed in f49cef5...ef0f5b1

It's desirable to retain async_contexts active at callsites of perf_hooks.performance.mark() and alike in the subsequent PerformanceObserver invocations such that the latter can access e.g. associated AsyncLocalStorage instances. In working towards this goal replace the node::MakeCallback(..., async_context{0, 0}) in PerformanceEntry::doNotify() by the new node::MakeSyncCallback() introduced specifically for this purpose. This change will retain the original async_context, if any, in perf_hook's observersCallback() and thus, for the subsequent doNotify() on unbuffered PerformanceObservers. Co-Authored-By: ZauberNerd <zaubernerd@zaubernerd.de> PR-URL: #36343 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Rich Trott <rtrott@gmail.com>

This reverts commit 009e418. AFAIU the discussion at [1], PerformanceObserver had been made to inherit from AsyncResource more or less as a band-aid in lack of a better async_context candidate to invoke it in. In order to enable access to AsyncLocalStores from PerformanceObservers invoked synchronously through e.g. measure() or mark(), the current async_context, if any, should be retained. Note that this is a breaking change, but - as has been commented at [1], PerformanceObserver being derived from AsyncResource is a "minor divergence from the spec" anyway, - to my knowledge this is an internal implementation detail which has never been documented and - I can't think of a good reason why existing PerformanceObserver implementations would possibly rely on it. OTOH, it's probably worthwhile to not potentially invoke before() and after() async_hooks for each and every PerformanceObserver notification. [1] #18789 Co-Authored-By: ZauberNerd <zaubernerd@zaubernerd.de> PR-URL: #36343 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Rich Trott <rtrott@gmail.com>

This test proves that the PerformanceObserver callback gets called with the async context of the callsite of performance.mark()/measure() and therefore AsyncLocalStorage can be used inside a PerformanceObserver. PR: #36343 PR-URL: #36343 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Rich Trott <rtrott@gmail.com>

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. perf_hooks Issues and PRs related to the implementation of the Performance Timing API. labels Dec 1, 2020

jasnell requested a review from addaleax December 1, 2020 16:39

jasnell reviewed Dec 1, 2020
View reviewed changes

Comment threadsrc/api/callback.cc Outdated

jasnell approved these changes Dec 1, 2020
View reviewed changes

addaleax requested changes Dec 1, 2020
View reviewed changes

Comment threadsrc/node.h Outdated
Comment threadsrc/api/callback.cc Outdated

ZauberNerd force-pushed the retain-async-context-perf-hooks branch from d5353bf to f24f3faCompare December 2, 2020 22:10

ZauberNerd force-pushed the retain-async-context-perf-hooks branch from f24f3fa to 88d44a7Compare December 2, 2020 22:41

ZauberNerd force-pushed the retain-async-context-perf-hooks branch from 88d44a7 to 64e45a9Compare December 4, 2020 22:59

jasnell reviewed Dec 5, 2020
View reviewed changes

Comment threadtest/parallel/test-performanceobserver-asynccontext.js Outdated

jasnell reviewed Dec 5, 2020
View reviewed changes

Comment threadtest/parallel/test-performanceobserver-asynccontext.js Outdated

jasnell reviewed Dec 5, 2020
View reviewed changes

Comment threadtest/parallel/test-performanceobserver-asynccontext.js Outdated

ZauberNerd force-pushed the retain-async-context-perf-hooks branch from 64e45a9 to dbe0e87Compare December 5, 2020 09:45

addaleax approved these changes Dec 5, 2020
View reviewed changes

jasnell added the request-ci Add this label to start a Jenkins CI on a PR. label Dec 7, 2020

github-actionsBot removed the request-ci Add this label to start a Jenkins CI on a PR. label Dec 7, 2020

Trott approved these changes Dec 10, 2020
View reviewed changes

nicstangeand others added 4 commits December 11, 2020 04:43

Trott force-pushed the retain-async-context-perf-hooks branch from dbe0e87 to ef0f5b1Compare December 11, 2020 12:47

Trott closed this Dec 11, 2020

targos mentioned this pull request Dec 22, 2020
v15.5.0 release proposal #36597
Merged

targos added the backport-requested-v14.x label May 16, 2021

This was referenced Aug 16, 2022
[Snyk] Security upgrade gatsby-source-filesystem from 2.1.43 to 4.21.0 Rednickle/node-1#52
Open
[Snyk] Security upgrade gatsby-source-filesystem from 2.1.43 to 4.21.0 aliceUnhinged613/node#65
Open

Dmarch28 mentioned this pull request Aug 16, 2022
[Snyk] Security upgrade gatsby-source-filesystem from 2.3.23 to 4.21.0 Dmarch28/node#63
Open

wedataintelligence mentioned this pull request Aug 16, 2022
[Snyk] Security upgrade gatsby-source-filesystem from 2.1.43 to 4.21.0 wedataintelligence/node#39
Open

kissofire mentioned this pull request Aug 16, 2022
[Snyk] Security upgrade gatsby-source-filesystem from 2.1.21 to 4.21.0 kissofire/node#74
Open

molllyn1 mentioned this pull request Aug 17, 2022
[Snyk] Security upgrade gatsby-source-filesystem from 2.1.43 to 4.21.0 molllyn1/node#54
Open

snyk-bot mentioned this pull request Aug 17, 2022
[Snyk] Security upgrade gatsby-source-filesystem from 2.1.43 to 4.21.0 137717unity/node#63
Open

baby636 mentioned this pull request Aug 17, 2022
[Snyk] Security upgrade gatsby-source-filesystem from 2.3.23 to 4.21.0 baby636/node#63
Open

ron-a20 mentioned this pull request Aug 17, 2022
[Snyk] Security upgrade gatsby-source-filesystem from 2.1.43 to 4.21.0 ron-a20/node#72
Open

snyk-bot mentioned this pull request Sep 25, 2022
[Snyk] Fix for 22 vulnerabilities 137717unity/node#70
Open

wedataintelligence mentioned this pull request Sep 26, 2022
[Snyk] Fix for 22 vulnerabilities wedataintelligence/node#44
Open

137717unity mentioned this pull request Sep 26, 2022
[Snyk] Fix for 22 vulnerabilities 137717unity/node#73
Open

snyk-bot mentioned this pull request Sep 27, 2022
[Snyk] Fix for 21 vulnerabilities Rednickle/node-1#56
Open

wedataintelligence mentioned this pull request Sep 29, 2022
[Snyk] Fix for 24 vulnerabilities wedataintelligence/node#50
Open

This was referenced Sep 29, 2022
[Snyk] Fix for 24 vulnerabilities 137717unity/node#75
Open
[Snyk] Fix for 23 vulnerabilities Rednickle/node-1#60
Open

This was referenced Oct 5, 2022
[Snyk] Fix for 24 vulnerabilities wedataintelligence/node#51
Open
[Snyk] Fix for 24 vulnerabilities wedataintelligence/node#52
Open

snyk-bot mentioned this pull request Oct 6, 2022
[Snyk] Fix for 24 vulnerabilities wedataintelligence/node#53
Open

137717unity mentioned this pull request Oct 7, 2022
[Snyk] Fix for 24 vulnerabilities 137717unity/node#76
Open

wedataintelligence mentioned this pull request Oct 7, 2022
[Snyk] Fix for 24 vulnerabilities wedataintelligence/node#54
Open

This was referenced Oct 8, 2022
[Snyk] Fix for 24 vulnerabilities wedataintelligence/node#55
Open
[Snyk] Fix for 24 vulnerabilities 137717unity/node#77
Open

137717unity mentioned this pull request Oct 9, 2022
[Snyk] Fix for 24 vulnerabilities 137717unity/node#78
Open

snyk-bot mentioned this pull request Oct 9, 2022
[Snyk] Fix for 23 vulnerabilities Rednickle/node-1#63
Open

Navigation Menu

Uh oh!

Uh oh!

Retain async context when notifying PerformanceObservers - #36343

Retain async context when notifying PerformanceObservers#36343
ZauberNerd wants to merge 4 commits into
nodejs:masterfrom
ZauberNerd:retain-async-context-perf-hooks

ZauberNerd commented Dec 1, 2020•
edited
Loading

Uh oh!

Uh oh!

addaleax left a comment

Uh oh!

Uh oh!

Uh oh!

ZauberNerd commented Dec 3, 2020

Uh oh!

Uh oh!

Uh oh!

Uh oh!

nodejs-github-bot commented Dec 7, 2020

Uh oh!

Trott commented Dec 11, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

Uh oh!

Uh oh!

Conversation

ZauberNerd commented Dec 1, 2020• edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Checklist

Uh oh!

Uh oh!

addaleax left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

ZauberNerd commented Dec 3, 2020

Uh oh!

Uh oh!

Uh oh!

Uh oh!

nodejs-github-bot commented Dec 7, 2020

Uh oh!

Trott commented Dec 11, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

ZauberNerd commented Dec 1, 2020•
edited
Loading