Skip to content

Commit 1dd9c97

Browse files
jasnelljasnell
committed
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: #19155 Reviewed-By: Andreas Madsen <[email protected]>
1 parent 45277e2 commit 1dd9c97

File tree

7 files changed

+50
-26
lines changed

7 files changed

+50
-26
lines changed

‎lib/internal/trace_events_async_hooks.js‎

Lines changed: 7 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,8 @@ const END_EVENT = 'e'.charCodeAt(0);
1515
// non-init events, use a map to manually map the asyncId to the type name.
1616
const typeMemory = new Map();
1717

18+
const trace_event_category = 'node,node.async_hooks';
19+
1820
// It is faster to emit trace_events directly from C++. Thus, this happens in
1921
// async_wrap.cc. However, events emitted from the JavaScript API or the
2022
// Embedder C++ API can't be emitted from async_wrap.cc. Thus they are
@@ -27,7 +29,7 @@ const hook = async_hooks.createHook({
2729
if (nativeProviders.has(type)) return;
2830

2931
typeMemory.set(asyncId, type);
30-
trace_events.emit(BEFORE_EVENT, 'node.async_hooks',
32+
trace_events.emit(BEFORE_EVENT, trace_event_category,
3133
type, asyncId,
3234
'triggerAsyncId', triggerAsyncId,
3335
'executionAsyncId', async_hooks.executionAsyncId());
@@ -37,23 +39,23 @@ const hook = async_hooks.createHook({
3739
const type = typeMemory.get(asyncId);
3840
if (type === undefined) return;
3941

40-
trace_events.emit(BEFORE_EVENT, 'node.async_hooks',
42+
trace_events.emit(BEFORE_EVENT, trace_event_category,
4143
type + '_CALLBACK', asyncId);
4244
},
4345

4446
after(asyncId) {
4547
const type = typeMemory.get(asyncId);
4648
if (type === undefined) return;
4749

48-
trace_events.emit(END_EVENT, 'node.async_hooks',
50+
trace_events.emit(END_EVENT, trace_event_category,
4951
type + '_CALLBACK', asyncId);
5052
},
5153

5254
destroy(asyncId) {
5355
const type = typeMemory.get(asyncId);
5456
if (type === undefined) return;
5557

56-
trace_events.emit(END_EVENT, 'node.async_hooks',
58+
trace_events.emit(END_EVENT, trace_event_category,
5759
type, asyncId);
5860

5961
// cleanup asyncId to type map
@@ -63,7 +65,7 @@ const hook = async_hooks.createHook({
6365

6466

6567
exports.setup = function() {
66-
if (trace_events.categoryGroupEnabled('node.async_hooks')) {
68+
if (trace_events.categoryGroupEnabled(trace_event_category)) {
6769
hook.enable();
6870
}
6971
};

‎src/async_wrap.cc‎

Lines changed: 8 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -179,7 +179,8 @@ void AsyncWrap::EmitTraceEventBefore() {
179179
switch (provider_type()) {
180180
#define V(PROVIDER) \
181181
case PROVIDER_ ## PROVIDER: \
182-
TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("node.async_hooks", \
182+
TRACE_EVENT_NESTABLE_ASYNC_BEGIN0( \
183+
TRACING_CATEGORY_NODE1(async_hooks), \
183184
#PROVIDER "_CALLBACK", static_cast<int64_t>(get_async_id())); \
184185
break;
185186
NODE_ASYNC_PROVIDER_TYPES(V)
@@ -207,7 +208,8 @@ void AsyncWrap::EmitTraceEventAfter() {
207208
switch (provider_type()) {
208209
#define V(PROVIDER) \
209210
case PROVIDER_ ## PROVIDER: \
210-
TRACE_EVENT_NESTABLE_ASYNC_END0("node.async_hooks", \
211+
TRACE_EVENT_NESTABLE_ASYNC_END0( \
212+
TRACING_CATEGORY_NODE1(async_hooks), \
211213
#PROVIDER "_CALLBACK", static_cast<int64_t>(get_async_id())); \
212214
break;
213215
NODE_ASYNC_PROVIDER_TYPES(V)
@@ -631,7 +633,8 @@ void AsyncWrap::EmitTraceEventDestroy() {
631633
switch (provider_type()) {
632634
#define V(PROVIDER) \
633635
case PROVIDER_ ## PROVIDER: \
634-
TRACE_EVENT_NESTABLE_ASYNC_END0("node.async_hooks", \
636+
TRACE_EVENT_NESTABLE_ASYNC_END0( \
637+
TRACING_CATEGORY_NODE1(async_hooks), \
635638
#PROVIDER, static_cast<int64_t>(get_async_id())); \
636639
break;
637640
NODE_ASYNC_PROVIDER_TYPES(V)
@@ -664,7 +667,8 @@ void AsyncWrap::AsyncReset(double execution_async_id, bool silent) {
664667
switch (provider_type()) {
665668
#define V(PROVIDER) \
666669
case PROVIDER_ ## PROVIDER: \
667-
TRACE_EVENT_NESTABLE_ASYNC_BEGIN2("node.async_hooks", \
670+
TRACE_EVENT_NESTABLE_ASYNC_BEGIN2( \
671+
TRACING_CATEGORY_NODE1(async_hooks), \
668672
#PROVIDER, static_cast<int64_t>(get_async_id()), \
669673
"executionAsyncId", \
670674
static_cast<int64_t>(env()->execution_async_id()), \

‎src/node_internals.h‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -776,6 +776,15 @@ static inline const char *errno_string(int errorno) {
776776
#define NODE_MODULE_CONTEXT_AWARE_INTERNAL(modname, regfunc) \
777777
NODE_MODULE_CONTEXT_AWARE_CPP(modname, regfunc, nullptr, NM_F_INTERNAL)
778778

779+
#define TRACING_CATEGORY_NODE "node"
780+
#define TRACING_CATEGORY_NODE1(one) \
781+
TRACING_CATEGORY_NODE "," \
782+
TRACING_CATEGORY_NODE "." #one
783+
#define TRACING_CATEGORY_NODE2(one, two) \
784+
TRACING_CATEGORY_NODE "," \
785+
TRACING_CATEGORY_NODE "." #one "," \
786+
TRACING_CATEGORY_NODE "." #one "." #two
787+
779788
} // namespace node
780789

781790

‎src/node_perf.cc‎

Lines changed: 14 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -135,7 +135,8 @@ void Mark(const FunctionCallbackInfo<Value>& args) {
135135
(*marks)[*name] = now;
136136

137137
TRACE_EVENT_COPY_MARK_WITH_TIMESTAMP(
138-
"node.perf,node.perf.usertiming", *name, now / 1000);
138+
TRACING_CATEGORY_NODE2(perf, usertiming),
139+
*name, now / 1000);
139140

140141
PerformanceEntry entry(env, *name, "mark", now, now);
141142
Local<Object> obj = entry.ToObject();
@@ -183,9 +184,11 @@ void Measure(const FunctionCallbackInfo<Value>& args) {
183184
endTimestamp = startTimestamp;
184185

185186
TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
186-
"node.perf,node.perf.usertiming", *name, *name, startTimestamp / 1000);
187+
TRACING_CATEGORY_NODE2(perf, usertiming),
188+
*name, *name, startTimestamp / 1000);
187189
TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
188-
"node.perf,node.perf.usertiming", *name, *name, endTimestamp / 1000);
190+
TRACING_CATEGORY_NODE2(perf, usertiming),
191+
*name, *name, endTimestamp / 1000);
189192

190193
PerformanceEntry entry(env, *name, "measure", startTimestamp, endTimestamp);
191194
Local<Object> obj = entry.ToObject();
@@ -301,13 +304,15 @@ void TimerFunctionCall(const FunctionCallbackInfo<Value>& args) {
301304
if (args.IsConstructCall()) {
302305
start = PERFORMANCE_NOW();
303306
TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
304-
"node.perf,node.perf.timerify", *name, *name, start / 1000);
307+
TRACING_CATEGORY_NODE2(perf, timerify),
308+
*name, *name, start / 1000);
305309
v8::MaybeLocal<Object> ret = fn->NewInstance(context,
306310
call_args.size(),
307311
call_args.data());
308312
end = PERFORMANCE_NOW();
309313
TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
310-
"node.perf,node.perf.timerify", *name, *name, end / 1000);
314+
TRACING_CATEGORY_NODE2(perf, timerify),
315+
*name, *name, end / 1000);
311316

312317
if (ret.IsEmpty()) {
313318
try_catch.ReThrow();
@@ -317,14 +322,16 @@ void TimerFunctionCall(const FunctionCallbackInfo<Value>& args) {
317322
} else {
318323
start = PERFORMANCE_NOW();
319324
TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
320-
"node.perf,node.perf.timerify", *name, *name, start / 1000);
325+
TRACING_CATEGORY_NODE2(perf, timerify),
326+
*name, *name, start / 1000);
321327
v8::MaybeLocal<Value> ret = fn->Call(context,
322328
args.This(),
323329
call_args.size(),
324330
call_args.data());
325331
end = PERFORMANCE_NOW();
326332
TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
327-
"node.perf,node.perf.timerify", *name, *name, end / 1000);
333+
TRACING_CATEGORY_NODE2(perf, timerify),
334+
*name, *name, end / 1000);
328335

329336
if (ret.IsEmpty()) {
330337
try_catch.ReThrow();

‎test/parallel/test-trace-events-all.js‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,7 @@ proc.once('exit', common.mustCall(() => {
3535
assert(traces.some((trace) => {
3636
if (trace.pid !== proc.pid)
3737
return false;
38-
if (trace.cat !== 'node.async_hooks')
38+
if (trace.cat !== 'node,node.async_hooks')
3939
return false;
4040
if (trace.name !== 'TIMERWRAP')
4141
return false;
@@ -47,7 +47,7 @@ proc.once('exit', common.mustCall(() => {
4747
assert(traces.some((trace) => {
4848
if (trace.pid !== proc.pid)
4949
return false;
50-
if (trace.cat !== 'node.async_hooks')
50+
if (trace.cat !== 'node,node.async_hooks')
5151
return false;
5252
if (trace.name !== 'Timeout')
5353
return false;

‎test/parallel/test-trace-events-async-hooks.js‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -37,7 +37,7 @@ proc.once('exit', common.mustCall(() => {
3737
assert(traces.some((trace) => {
3838
if (trace.pid !== proc.pid)
3939
return false;
40-
if (trace.cat !== 'node.async_hooks')
40+
if (trace.cat !== 'node,node.async_hooks')
4141
return false;
4242
if (trace.name !== 'TIMERWRAP')
4343
return false;
@@ -48,7 +48,7 @@ proc.once('exit', common.mustCall(() => {
4848
assert(traces.some((trace) => {
4949
if (trace.pid !== proc.pid)
5050
return false;
51-
if (trace.cat !== 'node.async_hooks')
51+
if (trace.cat !== 'node,node.async_hooks')
5252
return false;
5353
if (trace.name !== 'Timeout')
5454
return false;

‎test/parallel/test-trace-events-perf.js‎

Lines changed: 8 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -26,12 +26,12 @@ if (process.argv[2] === 'child') {
2626

2727
const expectedMarks = ['A', 'B'];
2828
const expectedBegins = [
29-
{ cat: 'node.perf,node.perf.timerify', name: 'f' },
30-
{ cat: 'node.perf,node.perf.usertiming', name: 'A to B' }
29+
{ cat: 'node,node.perf,node.perf.timerify', name: 'f' },
30+
{ cat: 'node,node.perf,node.perf.usertiming', name: 'A to B' }
3131
];
3232
const expectedEnds = [
33-
{ cat: 'node.perf,node.perf.timerify', name: 'f' },
34-
{ cat: 'node.perf,node.perf.usertiming', name: 'A to B' }
33+
{ cat: 'node,node.perf,node.perf.timerify', name: 'f' },
34+
{ cat: 'node,node.perf,node.perf.usertiming', name: 'A to B' }
3535
];
3636

3737
const proc = cp.fork(__filename,
@@ -60,8 +60,10 @@ if (process.argv[2] === 'child') {
6060
assert.strictEqual(trace.pid, proc.pid);
6161
switch (trace.ph) {
6262
case 'R':
63-
assert.strictEqual(trace.cat, 'node.perf,node.perf.usertiming');
64-
assert.strictEqual(trace.name, expectedMarks.shift());
63+
assert.strictEqual(trace.cat,
64+
'node,node.perf,node.perf.usertiming');
65+
assert.strictEqual(trace.name,
66+
expectedMarks.shift());
6567
break;
6668
case 'b':
6769
const expectedBegin = expectedBegins.shift();

0 commit comments

Comments
 (0)