Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

src: add tracing category macros #19155

Closed
wants to merge 2 commits into from
Closed

src: add tracing category macros #19155

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
ce65bb0
src: add tracing category macros
jasnell Mar 5, 2018
a2e5cd5
[Squash] Fix tests
jasnell Mar 8, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 7 additions & 5 deletions lib/internal/trace_events_async_hooks.js
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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