Skip to content

Commit

Permalink
src: add tracing category macros
Browse files Browse the repository at this point in the history 
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]>
  • Loading branch information
@jasnell
jasnell committed Mar 9, 2018
1 parent 45277e2 commit 1dd9c97
Show file tree
Hide file tree
Showing 7 changed files with 50 additions and 26 deletions.
12 changes: 7 additions & 5 deletions lib/internal/trace_events_async_hooks.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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());
Expand All @@ -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
Expand All @@ -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();
}
};
12 changes: 8 additions & 4 deletions src/async_wrap.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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()), \
Expand Down
9 changes: 9 additions & 0 deletions src/node_internals.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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


Expand Down
21 changes: 14 additions & 7 deletions src/node_perf.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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();
Expand All @@ -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();
Expand Down
4 changes: 2 additions & 2 deletions test/parallel/test-trace-events-all.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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;
Expand Down
4 changes: 2 additions & 2 deletions test/parallel/test-trace-events-async-hooks.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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;
Expand Down
14 changes: 8 additions & 6 deletions test/parallel/test-trace-events-perf.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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();
Expand Down

0 comments on commit 1dd9c97

Please sign in to comment.