Skip to content

Commit

Permalink
trace_events: add executionAsyncId to init events
Browse files Browse the repository at this point in the history
async_hooks emits trace_events. This adds the executionAsyncId to the
init events. In theory this could be inferred from the before and after
events but this is much simpler and doesn't require knowledge of all
events.

PR-URL: nodejs#17196
Backport-PR-URL: nodejs#18179
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Franziska Hinkelmann <franziska.hinkelmann@gmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
AndreasMadsen authored and gibfahn committed Jan 17, 2018

Verified

This commit was created on GitHub.com and signed with GitHub’s verified signature. The key has expired.
1 parent a515d48 commit 66c6650
Showing 5 changed files with 51 additions and 14 deletions.
4 changes: 3 additions & 1 deletion lib/internal/trace_events_async_hooks.js
Original file line number Diff line number Diff line change
@@ -28,7 +28,9 @@ const hook = async_hooks.createHook({

typeMemory.set(asyncId, type);
trace_events.emit(BEFORE_EVENT, 'node.async_hooks',
type, asyncId, 'triggerAsyncId', triggerAsyncId);
type, asyncId,
'triggerAsyncId', triggerAsyncId,
'executionAsyncId', async_hooks.executionAsyncId());
},

before(asyncId) {
7 changes: 5 additions & 2 deletions src/async_wrap.cc
Original file line number Diff line number Diff line change
@@ -704,9 +704,12 @@ void AsyncWrap::AsyncReset(double execution_async_id, bool silent) {
switch (provider_type()) {
#define V(PROVIDER) \
case PROVIDER_ ## PROVIDER: \
TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("node.async_hooks", \
TRACE_EVENT_NESTABLE_ASYNC_BEGIN2("node.async_hooks", \
#PROVIDER, static_cast<int64_t>(get_async_id()), \
"triggerAsyncId", static_cast<int64_t>(get_trigger_async_id())); \
"executionAsyncId", \
static_cast<int64_t>(env()->execution_async_id()), \
"triggerAsyncId", \
static_cast<int64_t>(get_trigger_async_id())); \
break;
NODE_ASYNC_PROVIDER_TYPES(V)
#undef V
25 changes: 18 additions & 7 deletions src/node_trace_events.cc
Original file line number Diff line number Diff line change
@@ -70,20 +70,19 @@ static void Emit(const FunctionCallbackInfo<Value>& args) {
id = args[3]->IntegerValue(context).ToChecked();
}

// TODO(AndreasMadsen): Two extra arguments are not supported.
// TODO(AndreasMadsen): String values are not supported.
int32_t num_args = 0;
const char* arg_names[1];
uint8_t arg_types[1];
uint64_t arg_values[1];
const char* arg_names[2];
uint8_t arg_types[2];
uint64_t arg_values[2];

// Create Utf8Value in the function scope to prevent deallocation.
// The c-string will be copied by TRACE_EVENT_API_ADD_TRACE_EVENT at the end.
Utf8Value arg1NameValue(env->isolate(), args[4]);
Utf8Value arg2NameValue(env->isolate(), args[6]);

if (args.Length() < 6 || (args[4]->IsUndefined() && args[5]->IsUndefined())) {
num_args = 0;
} else {
if (args.Length() >= 6 &&
(!args[4]->IsUndefined() || !args[5]->IsUndefined())) {
num_args = 1;
arg_types[0] = TRACE_VALUE_TYPE_INT;

@@ -94,6 +93,18 @@ static void Emit(const FunctionCallbackInfo<Value>& args) {
arg_values[0] = args[5]->IntegerValue(context).ToChecked();
}

if (args.Length() >= 8 &&
(!args[6]->IsUndefined() || !args[7]->IsUndefined())) {
num_args = 2;
arg_types[1] = TRACE_VALUE_TYPE_INT;

CHECK(args[6]->IsString());
arg_names[1] = arg2NameValue.out();

CHECK(args[7]->IsNumber());
arg_values[1] = args[7]->IntegerValue(context).ToChecked();
}

// The TRACE_EVENT_FLAG_COPY flag indicates that the name and argument
// name should be copied thus they don't need to long-lived pointers.
// The category name still won't be copied and thus need to be a long-lived
10 changes: 9 additions & 1 deletion test/parallel/test-trace-events-async-hooks.js
Original file line number Diff line number Diff line change
@@ -43,7 +43,6 @@ proc.once('exit', common.mustCall(() => {
return true;
}));


// JavaScript async_hooks trace events should be generated.
assert(traces.some((trace) => {
if (trace.pid !== proc.pid)
@@ -54,5 +53,14 @@ proc.once('exit', common.mustCall(() => {
return false;
return true;
}));

// Check args in init events
const initEvents = traces.filter((trace) => {
return (trace.ph === 'b' && !trace.name.includes('_CALLBACK'));
});
assert(initEvents.every((trace) => {
return (trace.args.executionAsyncId > 0 &&
trace.args.triggerAsyncId > 0);
}));
}));
}));
19 changes: 16 additions & 3 deletions test/parallel/test-trace-events-binding.js
Original file line number Diff line number Diff line change
@@ -10,7 +10,10 @@ const CODE = `
'type-value', 10, 'extra-value', 20);
process.binding("trace_events").emit(
'b'.charCodeAt(0), 'custom',
'type-value', 20);
'type-value', 20, 'first-value', 20, 'second-value', 30);
process.binding("trace_events").emit(
'b'.charCodeAt(0), 'custom',
'type-value', 30);
process.binding("trace_events").emit(
'b'.charCodeAt(0), 'missing',
'type-value', 10, 'extra-value', 20);
@@ -29,7 +32,7 @@ proc.once('exit', common.mustCall(() => {
assert(common.fileExists(FILE_NAME));
fs.readFile(FILE_NAME, common.mustCall((err, data) => {
const traces = JSON.parse(data.toString()).traceEvents;
assert.strictEqual(traces.length, 2);
assert.strictEqual(traces.length, 3);

assert.strictEqual(traces[0].pid, proc.pid);
assert.strictEqual(traces[0].ph, 'b');
@@ -43,6 +46,16 @@ proc.once('exit', common.mustCall(() => {
assert.strictEqual(traces[1].cat, 'custom');
assert.strictEqual(traces[1].name, 'type-value');
assert.strictEqual(traces[1].id, '0x14');
assert.deepStrictEqual(traces[1].args, { });
assert.deepStrictEqual(traces[1].args, {
'first-value': 20,
'second-value': 30
});

assert.strictEqual(traces[2].pid, proc.pid);
assert.strictEqual(traces[2].ph, 'b');
assert.strictEqual(traces[2].cat, 'custom');
assert.strictEqual(traces[2].name, 'type-value');
assert.strictEqual(traces[2].id, '0x1e');
assert.deepStrictEqual(traces[2].args, { });
}));
}));

0 comments on commit 66c6650

Please sign in to comment.