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: nodejs#19155
Reviewed-By: Andreas Madsen <amwebdk@gmail.com>

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,23 +39,23 @@ 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);
   },
 
   after(asyncId) {
     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);
   },
 
   destroy(asyncId) {
     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();
   }
 };

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<int64_t>(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<int64_t>(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<int64_t>(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<int64_t>(get_async_id()),                      \
         "executionAsyncId",                                                   \
         static_cast<int64_t>(env()->execution_async_id()),                    \

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
 
 

src/node_perf.cc

@@ -135,7 +135,8 @@ void Mark(const FunctionCallbackInfo<Value>& 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<Object> obj = entry.ToObject();
@@ -183,9 +184,11 @@ void Measure(const FunctionCallbackInfo<Value>& 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<Object> obj = entry.ToObject();
@@ -301,13 +304,15 @@ void TimerFunctionCall(const FunctionCallbackInfo<Value>& 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<Object> 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<Value>& 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<Value> 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();

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;

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;

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