Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

async-hooks: add trace events to AsyncWrap #14347

Closed
wants to merge 1 commit into from
Closed

async-hooks: add trace events to AsyncWrap #14347

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
44 changes: 44 additions & 0 deletions src/async-wrap.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -218,6 +218,16 @@ bool DomainExit(Environment* env, v8::Local<v8::Object> object) {


static bool PreCallbackExecution(AsyncWrap* wrap, bool run_domain_cbs) {
switch (wrap->provider_type()) {
#define V(PROVIDER) \
case AsyncWrap::PROVIDER_ ## PROVIDER: \
TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("node", #PROVIDER " cb", \
static_cast<int64_t>(wrap->get_id())); \
break;
NODE_ASYNC_PROVIDER_TYPES(V)
#undef V
}

if (wrap->env()->using_domains() && run_domain_cbs) {
bool is_disposed = DomainEnter(wrap->env(), wrap->object());
if (is_disposed)
Expand Down Expand Up @@ -249,6 +259,16 @@ bool AsyncWrap::EmitBefore(Environment* env, double async_id) {


static bool PostCallbackExecution(AsyncWrap* wrap, bool run_domain_cbs) {
switch (wrap->provider_type()) {
#define V(PROVIDER) \
case AsyncWrap::PROVIDER_ ## PROVIDER: \
TRACE_EVENT_NESTABLE_ASYNC_END0("node", #PROVIDER " cb", \
static_cast<int64_t>(wrap->get_id())); \
break;
NODE_ASYNC_PROVIDER_TYPES(V)
#undef V
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.


if (!AsyncWrap::EmitAfter(wrap->env(), wrap->get_id()))
return false;

Expand Down Expand Up @@ -617,10 +637,29 @@ AsyncWrap::AsyncWrap(Environment* env,

// Use AsyncReset() call to execute the init() callbacks.
AsyncReset(silent);

switch (provider_type()) {
#define V(PROVIDER) \
case PROVIDER_ ## PROVIDER: \
TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("node", #PROVIDER, \
static_cast<int64_t>(get_id())); \
break;
NODE_ASYNC_PROVIDER_TYPES(V)
#undef V
}
}


AsyncWrap::~AsyncWrap() {
switch (provider_type()) {
#define V(PROVIDER) \
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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().

case PROVIDER_ ## PROVIDER: \
TRACE_EVENT_NESTABLE_ASYNC_END0("node", #PROVIDER, \
static_cast<int64_t>(get_id())); \
break;
NODE_ASYNC_PROVIDER_TYPES(V)
#undef V
}
PushBackDestroyId(env(), get_id());
}

Expand Down Expand Up @@ -774,6 +813,9 @@ async_context EmitAsyncInit(Isolate* isolate,
trigger_async_id // trigger_async_id_
};

TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("node", "custom_event",
static_cast<int64_t>(context.async_id));

// Run init hooks
Local<String> type =
String::NewFromUtf8(isolate, name, v8::NewStringType::kInternalized)
Expand All @@ -785,6 +827,8 @@ async_context EmitAsyncInit(Isolate* isolate,
}

void EmitAsyncDestroy(Isolate* isolate, async_context asyncContext) {
TRACE_EVENT_NESTABLE_ASYNC_END0("node", "custom_event",
static_cast<int64_t>(asyncContext.async_id));
PushBackDestroyId(Environment::GetCurrent(isolate), asyncContext.async_id);
}

Expand Down
15 changes: 13 additions & 2 deletions test/parallel/test-trace-event.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,8 @@ const assert = require('assert');
const cp = require('child_process');
const fs = require('fs');

const CODE = 'for (var i = 0; i < 100000; i++) { "test" + i }';
const CODE =
'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
const FILE_NAME = 'node_trace.1.log';

common.refreshTmpDir();
Expand All @@ -24,7 +25,7 @@ proc_no_categories.once('exit', common.mustCall(() => {
fs.readFile(FILE_NAME, common.mustCall((err, data) => {
const traces = JSON.parse(data.toString()).traceEvents;
assert(traces.length > 0);
// Values that should be present on all runs to approximate correctness.
// V8 trace events should be generated.
assert(traces.some((trace) => {
if (trace.pid !== proc.pid)
return false;
Expand All @@ -34,6 +35,16 @@ proc_no_categories.once('exit', common.mustCall(() => {
return false;
return true;
}));
// Async wrap trace events should be generated.
assert(traces.some((trace) => {
if (trace.pid !== proc.pid)
return false;
if (trace.cat !== 'node')
return false;
if (trace.name !== 'TIMERWRAP')
return false;
return true;
}));
}));
}));
}));