From bbaf003e80ec4a3390d4b1637b100d7dcdd971dd Mon Sep 17 00:00:00 2001 From: Andreas Madsen Date: Tue, 21 Nov 2017 15:46:06 +0100 Subject: [PATCH 1/2] trace_events: add executionAsyncId to init events 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. --- lib/internal/trace_events_async_hooks.js | 4 ++- src/async_wrap.cc | 7 +++-- src/node_trace_events.cc | 27 ++++++++++++++----- .../parallel/test-trace-events-async-hooks.js | 10 ++++++- test/parallel/test-trace-events-binding.js | 19 ++++++++++--- 5 files changed, 53 insertions(+), 14 deletions(-) diff --git a/lib/internal/trace_events_async_hooks.js b/lib/internal/trace_events_async_hooks.js index 9f47f2aa5fd658..6724e0fdef5f15 100644 --- a/lib/internal/trace_events_async_hooks.js +++ b/lib/internal/trace_events_async_hooks.js @@ -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) { diff --git a/src/async_wrap.cc b/src/async_wrap.cc index b1a8f689ab3fab..c5e97bd4a66714 100644 --- a/src/async_wrap.cc +++ b/src/async_wrap.cc @@ -703,9 +703,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(get_async_id()), \ - "triggerAsyncId", static_cast(get_trigger_async_id())); \ + "executionAsyncId", \ + static_cast(env()->execution_async_id()), \ + "triggerAsyncId", \ + static_cast(get_trigger_async_id())); \ break; NODE_ASYNC_PROVIDER_TYPES(V) #undef V diff --git a/src/node_trace_events.cc b/src/node_trace_events.cc index b0ffe68eae3f47..64a6fc439b7f34 100644 --- a/src/node_trace_events.cc +++ b/src/node_trace_events.cc @@ -70,20 +70,20 @@ static void Emit(const FunctionCallbackInfo& 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 +94,19 @@ static void Emit(const FunctionCallbackInfo& 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 diff --git a/test/parallel/test-trace-events-async-hooks.js b/test/parallel/test-trace-events-async-hooks.js index 7f8fb106200b1a..e1f78f791a636d 100644 --- a/test/parallel/test-trace-events-async-hooks.js +++ b/test/parallel/test-trace-events-async-hooks.js @@ -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); + })); })); })); diff --git a/test/parallel/test-trace-events-binding.js b/test/parallel/test-trace-events-binding.js index 628c9cace71973..9a182821bac18e 100644 --- a/test/parallel/test-trace-events-binding.js +++ b/test/parallel/test-trace-events-binding.js @@ -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, { }); })); })); From 6e48ed35d73f28c81e53097c6a1a9b86216a048e Mon Sep 17 00:00:00 2001 From: Andreas Madsen Date: Wed, 22 Nov 2017 12:36:25 +0100 Subject: [PATCH 2/2] [squash] DeMorgan --- src/node_trace_events.cc | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/src/node_trace_events.cc b/src/node_trace_events.cc index 64a6fc439b7f34..f269b32fbef869 100644 --- a/src/node_trace_events.cc +++ b/src/node_trace_events.cc @@ -82,8 +82,7 @@ static void Emit(const FunctionCallbackInfo& args) { Utf8Value arg2NameValue(env->isolate(), args[6]); if (args.Length() >= 6 && - !args[4]->IsUndefined() && - !args[5]->IsUndefined()) { + (!args[4]->IsUndefined() || !args[5]->IsUndefined())) { num_args = 1; arg_types[0] = TRACE_VALUE_TYPE_INT; @@ -95,8 +94,7 @@ static void Emit(const FunctionCallbackInfo& args) { } if (args.Length() >= 8 && - !args[6]->IsUndefined() && - !args[7]->IsUndefined()) { + (!args[6]->IsUndefined() || !args[7]->IsUndefined())) { num_args = 2; arg_types[1] = TRACE_VALUE_TYPE_INT;