async-hooks: add trace events to AsyncWrap

[matthewloring]

This will allow trace event to record timing information for all
asynchronous operations that are observed by AsyncWrap.

Checklist

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

Affected core subsystem(s)

async-hooks, tracing

[AndreasMadsen]

This doesn't integrate with the Embedder API. The JavaScript Embedder API may be tricky, but I think it would be worth looking into integrating with the C++ Embedder API.

Also, were there not a trace-events related to the callbacks?

[matthewloring]

@AndreasMadsen I agree that integrating with the embedder apis would be good. C++ should be achievable now (maybe in a follow on PR) and JS embedder API could be accomplished once there is a JS tracing API (nodejs/node-eps#48).

Which callbacks were you referring to in "Also, were there not a trace-events related to the callbacks?"?

[AndreasMadsen]

C++ should be achievable now (maybe in a follow on PR)

The overlap between this and the C++ Embedding API is too great, I think we should just do it in this PR.

Which callbacks were you referring to in "Also, were there not a trace-events related to the callbacks?"?

This informs about the init and destroy hook, but we also have a before and after hook. Maybe I remember incorrectly but is there not a trace-event API for those too.

[matthewloring]

@AndreasMadsen Looking at the C++ Embedding API, it seems that the corresponding points are EmitAsyncInit and PushBackDestroyId (called by both EmitAsyncDestroy and ~AsyncWrap). In order to end a trace event, we must call TRACE_EVENT_NESTABLE_ASYNC_END(category_group, name, uid). I have been using the provider string as the name. Can that be made available in EmitAsyncDestroy?

For before and after, I've added nested events with the names <PROVIDERTYPE> cb.

[AndreasMadsen]

Looking at the C++ Embedding API, it seems that the corresponding points are EmitAsyncInit and PushBackDestroyId (called by both EmitAsyncDestroy and ~AsyncWrap). In order to end a trace event, we must call TRACE_EVENT_NESTABLE_ASYNC_END(category_group, name, uid).

Correct. That is why I'm thinking the overlap is too great.

Can that be made available in EmitAsyncDestroy?

I see. That might be problematic, for AsyncResource it is trivial but for the C-style api (EmitAsyncInit, EmitAsyncDestroy) I don't see how. We are expecting the user to keep track of such information if they need it.

/cc @nodejs/async_hooks

[trevnorris]

Here are places where this will fail:

1. HTTPParser when require('_http_common').freeParser() is called. An internal pool of parsers is created and every time one is used it's assigned a new async id. To get around this TRACE_EVENT_NESTABLE_ASYNC_BEGIN0 needs to be placed in Parser::Reinitialize() (src/node_http_parser.cc) and TRACE_EVENT_NESTABLE_ASYNC_END0 at the emitDestroy() call in freeParser() (lib/_http_common.js).
2. Every Timeout and Immediate, since they're all pseudo async resources (depending on the TimerWrap to fire). Since they depend on the TimerWrap there will still be an associated async id, just not the greater detail of each JS object.

Neither of these would be a blocker for me landing this PR. Just note that (1) will not have the same async ids going in as it does going out. Also I would suggest we exclude nextTick() calls.

[matthewloring]

Just to make sure I understand, currently, no trace events will be reported for httpparser or the js side of timers. Is there a chance for any malformed events (start without end, etc)? Why should nextTick be excluded?

[trevnorris]

Just to make sure I understand, currently, no trace events will be reported for httpparser

You will get an init() every time an http node::Parser is initialized, and you'll get before()/after() for that one as well, but you won't get a destroy() for that parser if it's placed in the freeParser() pool.

When the Parser is reused a new async_id is assigned, then you'll get a before()/after() call for the async_id that hasn't had init() called yet. Creating a broken call graph.

The init() call can be fixed by placing TRACE_EVENT_NESTABLE_ASYNC_BEGIN0 in node::Parser::Reinitialize(), but there's no way to track when the node::Parser instance has been placed in the pool from C++. So it would require a JS call.

The freeParser() code path isn't hot, so it's not unreasonable to put a JS call in there to notify C++ that the parser is done and it can emit destroy().

[matthewloring]

@AndreasMadsen I think adding one begin/end pair to EmitAsyncInit and EmitAsyncDestroy that have the category "custom_event" and another pair in AsyncWrap::AsyncWrap and AsyncWrap::~AsyncWrap with provider information should cover the code paths without overlap. How does that sound?

[AndreasMadsen]

I think adding one begin/end pair to EmitAsyncInit and EmitAsyncDestroy that have the category "custom_event" and another pair in AsyncWrap::AsyncWrap and AsyncWrap::~AsyncWrap with provider information should cover the code paths without overlap.

I think that is okay, there isn't much else we can do.

[matthewloring]

+cc @danielkhan

[trevnorris]

Is there a way to place these switch statements into a conditional that checks whether trace events are enabled?

[matthewloring]

We could expose a check for whether trace events are enabled if necessary but each of these macros starts by running such a check and I would guess the overhead of the switch alone would be minimal.

[matthewloring]

@AndreasMadsen @trevnorris Having added the trace events for before/after, I wonder whether measuring synchronous callback execution time provides value. What do you think about adding a begin event in init and an end event in before. This would display the time spent doing async work and would smooth over the http parser issues (having a stray end with no corresponding begin will just be dropped by the trace UI). Longer term it might make sense to ensure that retrieving a parser from the pool results in an init call.

/cc @lpy in case he has suggestions on naming or event placement.

[BridgeAR]

This needs a rebase

[BridgeAR]

Ping @matthewloring

[AndreasMadsen]

Having added the trace events for before/after, I wonder whether measuring synchronous callback execution time provides value. What do you think about adding a begin event in init and an end event in before. This would display the time spent doing async work and would smooth over the http parser issues (having a stray end with no corresponding begin will just be dropped by the trace UI). Longer term it might make sense to ensure that retrieving a parser from the pool results in an init call.

I agree, that measuring the time between init and before is more valuable. However, we need to log all the information. It is also possible for before to emit more than once, which makes what you suggest tricky.

---

JS Embedder API

It appears that the trace_event module is on hold. Having looked at the code it seems like it should be reasonably trivial to provide a minimal process.binding('trace_event') interface that we can use from the JS side. We can then enable the binding between async_hooks and trace_event when --trace-event is enabled. This is similar to how we handle the binding between inspector and async_hooks.

This also solves the issue with the C++ Embedder API and the missing event name, since it will be trivial for us to track that using a basic new Map(asyncId, name) structure.

To avoid unnecessary C++ binding calls from JavaScript, we can filter the calls using process.bindings('async_wrap').Providers.

[jasnell]

@AndreasMadsen .. since you're looking into this area, a related effort would be implementing the WITH_TIMESTAMP variants of the trace macros...

[AndreasMadsen]

@jasnell How is it relevant and do you know where I can find the documentation?

[AndreasMadsen]

@matthewloring I have rebased this in AndreasMadsen@b3d025e. For some reason, I get a segmentation fault when --trace-events-enabled isn't used. Could you look into it?

My commit also fixes the HTTP_PARSER issue and removes the trace_event integration with the C++ Embedder API. I plan to setup the C++ Embedder API and JavaScript Embedder API as I suggested, but I want to benchmark the current implementation first.

[jasnell]

@AndreasMadsen ... not directly related to this specific PR. There aren't any docs as far as I know. The Macros are there but they are currently not implemented. We can discuss this separately.

[matthewloring]

@AndreasMadsen I am not able to reproduce a segfault with your rebased patch. What was the specific code you were trying to run?

[AndreasMadsen]

@matthewloring simply running node (REPL) will cause a crash.

[trevnorris]

@AndreasMadsen

To avoid unnecessary C++ binding calls from JavaScript, we can filter the calls using process.bindings('async_wrap').Providers.

The original AsyncListener API did this way way back when, but it was removed. Can't remember the reasoning though. Possibly to do w/ filtering out user supplied providers.

[AndreasMadsen]

The original AsyncListener API did this way way back when, but it was removed. Can't remember the reasoning though. Possibly to do w/ filtering out user supplied providers.

Properly the situation is different. Besides ignoring the events we don't really have another option.

[matthewloring]

@AndreasMadsen What platform are you running on? I am able to run the repl without a crash on my mac.

[AndreasMadsen]

@matthewloring also mac :( I will try with a clean build. If that doesn't work I will make a PR and run the CI.

[matthewloring]

Closing in favor of #15538.