From a3be450521dd16b4e03f24edef4a8b7dde93be52 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Mon, 5 Mar 2018 14:46:19 -0800 Subject: [PATCH] src: add tracing category macros Adds `TRACING_CATEGORY_NODE`, `TRACING_CATEGORY_NODE1` and `TRACING_CATEGORY_NODE2` helper macros for consistently building trace event category strings. For instance, `TRACING_CATEGORY_NODE2(foo, bar)` would generate the category string `node,node.foo,node.foo.bar`, such that... ``` TRACE_EVENT_NESTABLE_ASYNC_BEGIN0( TRACING_CATEGORY_NODE2(foo, bar), "baz", 1); ``` Would emit if trace events are enabled for categories: `node`, `node.foo`, or `node.foo.bar`. This allows a natural scoping down of what trace events a user may want to receive. Enabling the `node` category would receive everything Node.js produces. PR-URL: https://github.com/nodejs/node/pull/19155 Reviewed-By: Andreas Madsen --- lib/internal/trace_events_async_hooks.js | 12 ++++++----- src/async_wrap.cc | 12 +++++++---- src/node_internals.h | 9 ++++++++ src/node_perf.cc | 21 ++++++++++++------- test/parallel/test-trace-events-all.js | 4 ++-- .../parallel/test-trace-events-async-hooks.js | 4 ++-- test/parallel/test-trace-events-perf.js | 14 +++++++------ 7 files changed, 50 insertions(+), 26 deletions(-) diff --git a/lib/internal/trace_events_async_hooks.js b/lib/internal/trace_events_async_hooks.js index 704da98e14412b..db38fe99adcc9c 100644 --- a/lib/internal/trace_events_async_hooks.js +++ b/lib/internal/trace_events_async_hooks.js @@ -15,6 +15,8 @@ const END_EVENT = 'e'.charCodeAt(0); // non-init events, use a map to manually map the asyncId to the type name. const typeMemory = new Map(); +const trace_event_category = 'node,node.async_hooks'; + // It is faster to emit trace_events directly from C++. Thus, this happens in // async_wrap.cc. However, events emitted from the JavaScript API or the // Embedder C++ API can't be emitted from async_wrap.cc. Thus they are @@ -27,7 +29,7 @@ const hook = async_hooks.createHook({ if (nativeProviders.has(type)) return; typeMemory.set(asyncId, type); - trace_events.emit(BEFORE_EVENT, 'node.async_hooks', + trace_events.emit(BEFORE_EVENT, trace_event_category, type, asyncId, 'triggerAsyncId', triggerAsyncId, 'executionAsyncId', async_hooks.executionAsyncId()); @@ -37,7 +39,7 @@ const hook = async_hooks.createHook({ const type = typeMemory.get(asyncId); if (type === undefined) return; - trace_events.emit(BEFORE_EVENT, 'node.async_hooks', + trace_events.emit(BEFORE_EVENT, trace_event_category, type + '_CALLBACK', asyncId); }, @@ -45,7 +47,7 @@ const hook = async_hooks.createHook({ const type = typeMemory.get(asyncId); if (type === undefined) return; - trace_events.emit(END_EVENT, 'node.async_hooks', + trace_events.emit(END_EVENT, trace_event_category, type + '_CALLBACK', asyncId); }, @@ -53,7 +55,7 @@ const hook = async_hooks.createHook({ const type = typeMemory.get(asyncId); if (type === undefined) return; - trace_events.emit(END_EVENT, 'node.async_hooks', + trace_events.emit(END_EVENT, trace_event_category, type, asyncId); // cleanup asyncId to type map @@ -63,7 +65,7 @@ const hook = async_hooks.createHook({ exports.setup = function() { - if (trace_events.categoryGroupEnabled('node.async_hooks')) { + if (trace_events.categoryGroupEnabled(trace_event_category)) { hook.enable(); } }; diff --git a/src/async_wrap.cc b/src/async_wrap.cc index e2656e4eec3970..239e607b05ab77 100644 --- a/src/async_wrap.cc +++ b/src/async_wrap.cc @@ -179,7 +179,8 @@ void AsyncWrap::EmitTraceEventBefore() { switch (provider_type()) { #define V(PROVIDER) \ case PROVIDER_ ## PROVIDER: \ - TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("node.async_hooks", \ + TRACE_EVENT_NESTABLE_ASYNC_BEGIN0( \ + TRACING_CATEGORY_NODE1(async_hooks), \ #PROVIDER "_CALLBACK", static_cast(get_async_id())); \ break; NODE_ASYNC_PROVIDER_TYPES(V) @@ -207,7 +208,8 @@ void AsyncWrap::EmitTraceEventAfter() { switch (provider_type()) { #define V(PROVIDER) \ case PROVIDER_ ## PROVIDER: \ - TRACE_EVENT_NESTABLE_ASYNC_END0("node.async_hooks", \ + TRACE_EVENT_NESTABLE_ASYNC_END0( \ + TRACING_CATEGORY_NODE1(async_hooks), \ #PROVIDER "_CALLBACK", static_cast(get_async_id())); \ break; NODE_ASYNC_PROVIDER_TYPES(V) @@ -631,7 +633,8 @@ void AsyncWrap::EmitTraceEventDestroy() { switch (provider_type()) { #define V(PROVIDER) \ case PROVIDER_ ## PROVIDER: \ - TRACE_EVENT_NESTABLE_ASYNC_END0("node.async_hooks", \ + TRACE_EVENT_NESTABLE_ASYNC_END0( \ + TRACING_CATEGORY_NODE1(async_hooks), \ #PROVIDER, static_cast(get_async_id())); \ break; NODE_ASYNC_PROVIDER_TYPES(V) @@ -664,7 +667,8 @@ void AsyncWrap::AsyncReset(double execution_async_id, bool silent) { switch (provider_type()) { #define V(PROVIDER) \ case PROVIDER_ ## PROVIDER: \ - TRACE_EVENT_NESTABLE_ASYNC_BEGIN2("node.async_hooks", \ + TRACE_EVENT_NESTABLE_ASYNC_BEGIN2( \ + TRACING_CATEGORY_NODE1(async_hooks), \ #PROVIDER, static_cast(get_async_id()), \ "executionAsyncId", \ static_cast(env()->execution_async_id()), \ diff --git a/src/node_internals.h b/src/node_internals.h index 43c2b5f112bac7..2faa6f93475ad7 100644 --- a/src/node_internals.h +++ b/src/node_internals.h @@ -776,6 +776,15 @@ static inline const char *errno_string(int errorno) { #define NODE_MODULE_CONTEXT_AWARE_INTERNAL(modname, regfunc) \ NODE_MODULE_CONTEXT_AWARE_CPP(modname, regfunc, nullptr, NM_F_INTERNAL) +#define TRACING_CATEGORY_NODE "node" +#define TRACING_CATEGORY_NODE1(one) \ + TRACING_CATEGORY_NODE "," \ + TRACING_CATEGORY_NODE "." #one +#define TRACING_CATEGORY_NODE2(one, two) \ + TRACING_CATEGORY_NODE "," \ + TRACING_CATEGORY_NODE "." #one "," \ + TRACING_CATEGORY_NODE "." #one "." #two + } // namespace node diff --git a/src/node_perf.cc b/src/node_perf.cc index bf9746e429d31c..8260d78c3296a5 100644 --- a/src/node_perf.cc +++ b/src/node_perf.cc @@ -135,7 +135,8 @@ void Mark(const FunctionCallbackInfo& args) { (*marks)[*name] = now; TRACE_EVENT_COPY_MARK_WITH_TIMESTAMP( - "node.perf,node.perf.usertiming", *name, now / 1000); + TRACING_CATEGORY_NODE2(perf, usertiming), + *name, now / 1000); PerformanceEntry entry(env, *name, "mark", now, now); Local obj = entry.ToObject(); @@ -183,9 +184,11 @@ void Measure(const FunctionCallbackInfo& args) { endTimestamp = startTimestamp; TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( - "node.perf,node.perf.usertiming", *name, *name, startTimestamp / 1000); + TRACING_CATEGORY_NODE2(perf, usertiming), + *name, *name, startTimestamp / 1000); TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( - "node.perf,node.perf.usertiming", *name, *name, endTimestamp / 1000); + TRACING_CATEGORY_NODE2(perf, usertiming), + *name, *name, endTimestamp / 1000); PerformanceEntry entry(env, *name, "measure", startTimestamp, endTimestamp); Local obj = entry.ToObject(); @@ -301,13 +304,15 @@ void TimerFunctionCall(const FunctionCallbackInfo& args) { if (args.IsConstructCall()) { start = PERFORMANCE_NOW(); TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( - "node.perf,node.perf.timerify", *name, *name, start / 1000); + TRACING_CATEGORY_NODE2(perf, timerify), + *name, *name, start / 1000); v8::MaybeLocal ret = fn->NewInstance(context, call_args.size(), call_args.data()); end = PERFORMANCE_NOW(); TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( - "node.perf,node.perf.timerify", *name, *name, end / 1000); + TRACING_CATEGORY_NODE2(perf, timerify), + *name, *name, end / 1000); if (ret.IsEmpty()) { try_catch.ReThrow(); @@ -317,14 +322,16 @@ void TimerFunctionCall(const FunctionCallbackInfo& args) { } else { start = PERFORMANCE_NOW(); TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( - "node.perf,node.perf.timerify", *name, *name, start / 1000); + TRACING_CATEGORY_NODE2(perf, timerify), + *name, *name, start / 1000); v8::MaybeLocal ret = fn->Call(context, args.This(), call_args.size(), call_args.data()); end = PERFORMANCE_NOW(); TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( - "node.perf,node.perf.timerify", *name, *name, end / 1000); + TRACING_CATEGORY_NODE2(perf, timerify), + *name, *name, end / 1000); if (ret.IsEmpty()) { try_catch.ReThrow(); diff --git a/test/parallel/test-trace-events-all.js b/test/parallel/test-trace-events-all.js index 07c53236597220..51d0f3c5a265f1 100644 --- a/test/parallel/test-trace-events-all.js +++ b/test/parallel/test-trace-events-all.js @@ -35,7 +35,7 @@ proc.once('exit', common.mustCall(() => { assert(traces.some((trace) => { if (trace.pid !== proc.pid) return false; - if (trace.cat !== 'node.async_hooks') + if (trace.cat !== 'node,node.async_hooks') return false; if (trace.name !== 'TIMERWRAP') return false; @@ -47,7 +47,7 @@ proc.once('exit', common.mustCall(() => { assert(traces.some((trace) => { if (trace.pid !== proc.pid) return false; - if (trace.cat !== 'node.async_hooks') + if (trace.cat !== 'node,node.async_hooks') return false; if (trace.name !== 'Timeout') return false; diff --git a/test/parallel/test-trace-events-async-hooks.js b/test/parallel/test-trace-events-async-hooks.js index b15d83b07a5799..7fb11223c3141d 100644 --- a/test/parallel/test-trace-events-async-hooks.js +++ b/test/parallel/test-trace-events-async-hooks.js @@ -37,7 +37,7 @@ proc.once('exit', common.mustCall(() => { assert(traces.some((trace) => { if (trace.pid !== proc.pid) return false; - if (trace.cat !== 'node.async_hooks') + if (trace.cat !== 'node,node.async_hooks') return false; if (trace.name !== 'TIMERWRAP') return false; @@ -48,7 +48,7 @@ proc.once('exit', common.mustCall(() => { assert(traces.some((trace) => { if (trace.pid !== proc.pid) return false; - if (trace.cat !== 'node.async_hooks') + if (trace.cat !== 'node,node.async_hooks') return false; if (trace.name !== 'Timeout') return false; diff --git a/test/parallel/test-trace-events-perf.js b/test/parallel/test-trace-events-perf.js index e73579f87eec02..57f886d272447a 100644 --- a/test/parallel/test-trace-events-perf.js +++ b/test/parallel/test-trace-events-perf.js @@ -26,12 +26,12 @@ if (process.argv[2] === 'child') { const expectedMarks = ['A', 'B']; const expectedBegins = [ - { cat: 'node.perf,node.perf.timerify', name: 'f' }, - { cat: 'node.perf,node.perf.usertiming', name: 'A to B' } + { cat: 'node,node.perf,node.perf.timerify', name: 'f' }, + { cat: 'node,node.perf,node.perf.usertiming', name: 'A to B' } ]; const expectedEnds = [ - { cat: 'node.perf,node.perf.timerify', name: 'f' }, - { cat: 'node.perf,node.perf.usertiming', name: 'A to B' } + { cat: 'node,node.perf,node.perf.timerify', name: 'f' }, + { cat: 'node,node.perf,node.perf.usertiming', name: 'A to B' } ]; const proc = cp.fork(__filename, @@ -60,8 +60,10 @@ if (process.argv[2] === 'child') { assert.strictEqual(trace.pid, proc.pid); switch (trace.ph) { case 'R': - assert.strictEqual(trace.cat, 'node.perf,node.perf.usertiming'); - assert.strictEqual(trace.name, expectedMarks.shift()); + assert.strictEqual(trace.cat, + 'node,node.perf,node.perf.usertiming'); + assert.strictEqual(trace.name, + expectedMarks.shift()); break; case 'b': const expectedBegin = expectedBegins.shift();