trace_events: add trace category enabled tracking #22128

jasnell · 2018-08-04T18:26:00Z

Track state of async_hooks trace event category enablement.
Enable/disable the async_hooks trace event dynamically.

Checklist

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

nodejs-github-bot · 2018-08-04T18:26:01Z

@jasnell build started: https://ci.nodejs.org/blue/organizations/jenkins/node-test-pull-request-lite-pipeline/detail/node-test-pull-request-lite-pipeline/427/pipeline

jasnell · 2018-08-04T18:30:35Z

Note: without this, the JS async_hooks trace event is not enabled if trace events are enabled dynamically at runtime.

jasnell · 2018-08-04T18:41:33Z

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

devsnek · 2018-08-04T18:46:30Z

so async_hooks registers a c++ callback, which gets called, emits to js, gets caught by async_hooks_trace_events, then calls back into c++ to the tracing api?

jasnell · 2018-08-04T18:48:07Z

The current impl is.... Less than ideal. I'm planning to work on refactoring soon.

jasnell · 2018-08-06T22:00:40Z

This was broken by the recent refactoring improvements that landed. Will have to revisit and figure out a slightly different way of doing it.

jasnell · 2018-08-06T23:06:09Z

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

jasnell · 2018-08-07T14:22:35Z

Trying CI again: https://ci.nodejs.org/job/node-test-pull-request/16251/

jasnell · 2018-08-07T14:54:33Z

CI, again: https://ci.nodejs.org/job/node-test-pull-request/16252/

jasnell · 2018-08-07T15:34:09Z

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

jasnell · 2018-08-07T17:02:28Z

Trying again on windows: https://ci.nodejs.org/job/node-test-commit-windows-fanned/19734/

jasnell · 2018-08-08T20:20:42Z

One more run on ci-lite to make sure the linting issue is resolved: https://ci.nodejs.org/job/node-test-pull-request-lite-pipeline/467/

jasnell · 2018-08-08T20:27:18Z

Ping @nodejs/diagnostics @nodejs/async_hooks @nodejs/trace-events ... CI is good on this, can I get a few eyes on the PR? :-)

mcollina · 2018-08-09T10:09:04Z

test/parallel/test-bootstrap-modules.js

@@ -11,4 +11,4 @@ const list = process.moduleLoadList.slice();

 const assert = require('assert');

-assert(list.length <= 73, list);
+assert(list.length <= 76, list);


I'm not really in favor of adding 3 more modules in our bootstrap.

Agree, will try to cut this down :-)

Made this a little bit better.

mcollina · 2018-08-09T10:09:57Z

lib/internal/trace_events.js

+'use strict';
+
+const { traceCategoryState } = process.binding('trace_events');
+const { createHook } = require('internal/trace_events_async_hooks');


Can you dynamically require this?

AndreasMadsen · 2018-08-09T11:13:50Z

lib/internal/trace_events.js

+  const asyncHooksEnabled = !!traceCategoryState[kCategoryAsyncHooks];
+
+  if (asyncHooksEnabled && !traceEventsAsyncHook) {
+    traceEventsAsyncHook = createHook();


In my opinion, trace_events_async_hooks.js should depend on trace_events.js. Making trace_events.js depend on trace_events_async_hooks.js makes the code very coupled.

I disagree. I think the dependency ordering actually makes more sense this way. Rather than burying the loading of trace_events_async_hooks.js inside bootstrap, it's loaded on demand only when tracing for that category is actually enabled.

it's loaded on demand only when tracing for that category is actually enabled.

This I agree with.

I think the dependency ordering actually makes more sense this way.

This I disagree with.

I don't see the connection between thoese two statements. To me, the current implementations corresponds to putting http.js code in events.js.

With this change, the async hook is only created and enabled when the callback within internal/trace_events.js is called and the node.async_hooks category is enabled. I'm not sure how that dependency would be worked if flipped. Can you suggest an alternative approach?

make trace_events.js an EventEmitter and make trace_events_async_hooks.js a listener.

Code not tested and didn't do any cleanup. Also didn't dynamically load trace_events_async_hooks.js. However you could do that by moving the listener to the bootstrap. It is less nice, but at least a more futureprof API.

diff --git a/lib/internal/bootstrap/node.js b/lib/internal/bootstrap/node.js index 66d734a5b2..e93321a777 100644 --- a/lib/internal/bootstrap/node.js +++ b/lib/internal/bootstrap/node.js @@ -303,10 +303,12 @@ } function setupTraceCategoryState() { - const { toggleTraceCategoryState } = - NativeModule.require('internal/trace_events'); - toggleTraceCategoryState(); - _setupTraceCategoryState(toggleTraceCategoryState); + const traceEventsModule = NativeModule.require('internal/trace_events'); + _setupTraceCategoryState( + traceEventsModule.emit.bind(traceEventsModule, 'categoryStateUpdated') + ); + + NativeModule.require('internal/trace_events_async_hooks').setup(); } function setupProcessObject() { diff --git a/lib/internal/trace_events.js b/lib/internal/trace_events.js index 577738466c..6b0054c45e 100644 --- a/lib/internal/trace_events.js +++ b/lib/internal/trace_events.js @@ -1,26 +1,6 @@ 'use strict'; const { internalBinding } = require('internal/bootstrap/loaders'); -const { traceCategoryState } = internalBinding('trace_events'); -const kCategoryAsyncHooks = 0; -let createHook; -let traceEventsAsyncHook; -function toggleTraceCategoryState() { - // Dynamically enable/disable the traceEventsAsyncHook - const asyncHooksEnabled = !!traceCategoryState[kCategoryAsyncHooks]; - - if (asyncHooksEnabled && !traceEventsAsyncHook) { - if (!createHook) - createHook = require('internal/trace_events_async_hooks').createHook; - traceEventsAsyncHook = createHook(); - traceEventsAsyncHook.enable(); - } else if (!asyncHooksEnabled && traceEventsAsyncHook) { - traceEventsAsyncHook.disable(); - traceEventsAsyncHook = undefined; - } -} - -module.exports = { - toggleTraceCategoryState -}; +class TraceEvents extends events.EventEmitter {} +module.exports = new TraceEvents(); diff --git a/lib/internal/trace_events_async_hooks.js b/lib/internal/trace_events_async_hooks.js index 0b9ffed818..bcd877fee9 100644 --- a/lib/internal/trace_events_async_hooks.js +++ b/lib/internal/trace_events_async_hooks.js @@ -1,7 +1,8 @@ 'use strict'; const { internalBinding } = require('internal/bootstrap/loaders'); -const { trace } = internalBinding('trace_events'); +const traceEvents = require('internal/bootstrap/trace_events'); +const { trace, isTraceCategoryEnabled } = internalBinding('trace_events'); const async_wrap = process.binding('async_wrap'); const async_hooks = require('async_hooks'); @@ -64,4 +65,16 @@ function createHook() { }); } -module.exports = { createHook }; +const hook = createHook(); + +function setup() { + traceEvents.on('categoryStateUpdated', function () { + if (isTraceCategoryEnabled('async_hooks')) { + hook.enable(); + } else { + hook.disable(); + } + }); +} + +module.exports = { setup };

Not really a fan of this approach and don't see it as much of an improvement.

A file named trace_events_async_hooks.js should logically depend on trace_events and async_hooks. I wouldn't expect a file named trace_events.js to depend on async_hooks.js. This is more than just file naming, but what is intuitive in a dependency tree.

If we generalize this to more things that are going to depend on trace_events, should we then continue to inline hooks into the trace_events.js file? Wouldn't it make more sense to being able to listen to an event, in a way that doesn't couple everything into the same function?

PS: Could you please provide arguments other than "Not really a fan of this approach".

jasnell · 2018-08-09T23:02:41Z

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

jasnell · 2018-08-09T23:25:53Z

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

mcollina

LGTM

jasnell · 2018-08-10T14:46:56Z

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

jasnell · 2018-08-10T16:23:27Z

CI after yet another rebase: https://ci.nodejs.org/job/node-test-pull-request/16340/

Rerun on linuxone due to known unrelated flaky: https://ci.nodejs.org/job/node-test-commit-linuxone/3815/

jasnell · 2018-08-12T05:20:10Z

@mcollina ... just collapsed this in to internal/bootstrap/node.js to avoid the additional require on bootstrap.

AndreasMadsen · 2018-08-12T10:40:27Z

lib/internal/trace_events_async_hooks.js

@@ -64,4 +64,4 @@ function createHook() {
  });
 }

-module.exports = { createHook };
+module.exports = createHook;


At least make this a singleton. Meaning module.exports = createHook();

I had it that way in the original version but I've got concerns over the internal state tracking... Specifically, we end up with a memory leak if tracing is dynamically disabled and we still have items in the map that are waiting for a destroy. Doing it this way resets the internal state. Will think of another way of doing that.

@jasnell Thanks. That actually makes sense. But yeah, it is still wired it is not a singleton.

One approach we could take is to add a reset function to the async_hook instance. I could do that in a one off way or we could make it part of the async_hook API. Internally, the async_hook can call reset when disable is called.

@jasnell I think it is best to do it in a "one-off way". I would even consider just exposing a enable and a disable function, that simply relays to async_hooks and clears the state.

In general, I think async_hooks should be as state-free as possible. As it can get very heavy performance wise and is easily implemented in userland.

I can live with that :-) making the updates now, will push a new commit shortly

BridgeAR · 2018-08-13T10:22:37Z

It would be great to get another review here @nodejs/diagnostics @nodejs/async_hooks @nodejs/trace-events

ofrobots · 2018-08-13T23:40:35Z

lib/internal/bootstrap/node.js

+            NativeModule.require('internal/trace_events_async_hooks');
+        }
+        traceEventsAsyncHook.enable();
+      } else if (!asyncHooksEnabled && traceEventsAsyncHook) {


is the !asyncHooksEnabled && necessary in the condition here?

Yes, we only want to turn it off if that specific category is turned off

I might be missing something, but isn't asyncHooksEnabled necessarily false on the else side of branch?

Ha! Yeah you're right. I changed the if condition going in and didn't even think about that one ;)

jasnell · 2018-08-14T19:55:58Z

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

jasnell · 2018-08-15T02:47:16Z

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

jasnell · 2018-08-15T16:02:20Z

Re-run linux-containered... again: https://ci.nodejs.org/job/node-test-commit-linux-containered/6285/

jasnell · 2018-08-16T18:27:42Z

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

Track state of async_hooks trace event category enablement. Enable/disable the async_hooks trace event dynamically.

jasnell · 2018-08-16T19:40:40Z

one of the CI jobs failed again for unrelated reasons... rebased, squashed, trying again: https://ci.nodejs.org/job/node-test-pull-request/16496/

jasnell · 2018-08-16T21:13:15Z

Good CI... finally. @AndreasMadsen can I ask you to take another look?

AndreasMadsen

deleted dublicate.

AndreasMadsen

Looks Okay To Me.

I do think this would benefit from a userland consumable API to check what categories are enabled (as a list) and an event emitter for when that changes.

The kCategoryAsyncHooks and setupTraceCategoryState is very customized for async_hooks. I often find hard to reason about that kind of complexity.

jasnell · 2018-08-17T16:07:13Z

A userland API is in my list of todos as we progress. I don't want to enable that too soon because there's still quite a bit of churn in the trace events stuff and categories/formats/apis are likely to continue to evolve. Once those settle down and become more stable, exposing user facing APIs that can be depended upon becomes much easier :-)

Thank you for the review @AndreasMadsen ! :-)

Track state of async_hooks trace event category enablement. Enable/disable the async_hooks trace event dynamically. PR-URL: #22128 Reviewed-By: Matteo Collina <[email protected]> Reviewed-By: Andreas Madsen <[email protected]>

jasnell · 2018-08-17T16:46:32Z

Landed in 4b7cd4b

ofrobots · 2018-08-17T16:52:47Z

lib/internal/bootstrap/node.js

@@ -311,6 +302,32 @@
    }
  }

+  function setupTraceCategoryState() {
+    const { traceCategoryState } = internalBinding('trace_events');
+    const kCategoryAsyncHooks = 0;


Apologies that I took so long to do a full review. Post-landing LGTM w/ the following comment, which can be addressed as a follow-on.

AFAICT, this 0 is a hard-coded constant that appears here and also at env.cc:109. Is it possible to define this symbolically somewhere?

targos · 2018-08-19T18:23:58Z

Should this be backported to v10.x-staging? If yes please follow the guide and raise a backport PR, if not let me know or add the dont-land-on label.

jasnell · 2018-08-19T18:27:36Z

Yes it needs to be landed in 10.x

targos · 2018-08-29T06:50:09Z

Do you plan to backport it or should we open an issue to ask for help?

targos · 2018-09-02T19:36:41Z

Ping

nodejs-github-bot added the lib / src Issues and PRs related to general changes in the lib or src directory. label Aug 4, 2018

jasnell force-pushed the trace-state branch from 4e63845 to 9811ee1 Compare August 4, 2018 18:41

jasnell force-pushed the trace-state branch from 9811ee1 to eb67671 Compare August 6, 2018 23:05

jasnell force-pushed the trace-state branch from eb67671 to b12e1e9 Compare August 7, 2018 14:22

jasnell requested a review from addaleax August 8, 2018 20:27

mcollina reviewed Aug 9, 2018

View reviewed changes

AndreasMadsen reviewed Aug 9, 2018

View reviewed changes

jasnell force-pushed the trace-state branch 2 times, most recently from 904ca94 to 375de3b Compare August 9, 2018 23:00

mcollina approved these changes Aug 10, 2018

View reviewed changes

jasnell force-pushed the trace-state branch from e97c79e to 508dfcd Compare August 10, 2018 16:22

jasnell added the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Aug 11, 2018

jasnell force-pushed the trace-state branch from 508dfcd to ed28b41 Compare August 12, 2018 04:41

AndreasMadsen reviewed Aug 12, 2018

View reviewed changes

jasnell force-pushed the trace-state branch from 57225b8 to f40afd8 Compare August 13, 2018 21:20

ofrobots reviewed Aug 13, 2018

View reviewed changes

joyeecheung mentioned this pull request Aug 15, 2018

CI failures: 20180815 nodejs/reliability#13

Closed

trace_events: add trace category enabled tracking

a677f81

Track state of async_hooks trace event category enablement. Enable/disable the async_hooks trace event dynamically.

jasnell force-pushed the trace-state branch from 34b3352 to a677f81 Compare August 16, 2018 19:39

AndreasMadsen approved these changes Aug 17, 2018

View reviewed changes

jasnell closed this Aug 17, 2018

ofrobots reviewed Aug 17, 2018

View reviewed changes

joyeecheung mentioned this pull request Aug 17, 2018

CI Failures: 20180817 nodejs/reliability#14

Closed

targos added backport-requested-v10.x and removed author ready PRs that have at least one approval, no pending requests for changes, and a CI started. labels Aug 19, 2018

targos mentioned this pull request Sep 5, 2018

[v10.x needs a backport] - trace_events: add trace category enabled tracking #22708

Closed

trace_events: add trace category enabled tracking #22128

trace_events: add trace category enabled tracking #22128

Conversation

jasnell commented Aug 4, 2018

Checklist

nodejs-github-bot commented Aug 4, 2018

jasnell commented Aug 4, 2018

jasnell commented Aug 4, 2018

devsnek commented Aug 4, 2018

jasnell commented Aug 4, 2018

jasnell commented Aug 6, 2018

jasnell commented Aug 6, 2018

jasnell commented Aug 7, 2018

jasnell commented Aug 7, 2018

jasnell commented Aug 7, 2018

jasnell commented Aug 7, 2018

jasnell commented Aug 8, 2018

jasnell commented Aug 8, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jasnell commented Aug 9, 2018 • edited Loading

jasnell commented Aug 9, 2018

mcollina left a comment

Choose a reason for hiding this comment

jasnell commented Aug 10, 2018

jasnell commented Aug 10, 2018 • edited Loading

jasnell commented Aug 12, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

AndreasMadsen Aug 12, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

BridgeAR commented Aug 13, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jasnell commented Aug 14, 2018

jasnell commented Aug 15, 2018

jasnell commented Aug 15, 2018

jasnell commented Aug 16, 2018

jasnell commented Aug 16, 2018

jasnell commented Aug 16, 2018

AndreasMadsen left a comment • edited Loading

Choose a reason for hiding this comment

AndreasMadsen left a comment

Choose a reason for hiding this comment

jasnell commented Aug 17, 2018

jasnell commented Aug 17, 2018

Choose a reason for hiding this comment

targos commented Aug 19, 2018

jasnell commented Aug 19, 2018

targos commented Aug 29, 2018

targos commented Sep 2, 2018

jasnell commented Aug 9, 2018 •

edited

Loading

jasnell commented Aug 10, 2018 •

edited

Loading

AndreasMadsen Aug 12, 2018 •

edited

Loading

AndreasMadsen left a comment •

edited

Loading