1berry/nodejs
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

src: add tracing category macros

Browse Source 
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 <amwebdk@gmail.com>
This commit is contained in:
James M Snell 2018-03-05 14:46:19 -08:00
parent 45277e23d5
commit 1dd9c9787b
7 changed files with 50 additions and 26 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

12
lib/internal/trace_events_async_hooks.js
View File

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

12
src/async_wrap.cc
View File

@ -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()), \

9
src/node_internals.h
View File

@ -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

21
src/node_perf.cc
View File

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

4
test/parallel/test-trace-events-all.js
View File

@ -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;

4
test/parallel/test-trace-events-async-hooks.js
View File

@ -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;

14
test/parallel/test-trace-events-perf.js
View File

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