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

Jump to bottom

trace_events,async_hooks: use intrinsic trace #22127

Closed
wants to merge 4 commits into from
Closed

trace_events,async_hooks: use intrinsic trace #22127

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
c0246c7
trace_events,async_hooks: use intrinsic trace
jasnell Aug 4, 2018
c5e0db7
src: remove old process.binding('trace_events').emit
jasnell Aug 9, 2018
23091d0
[Squash] fix lint issue
jasnell Aug 9, 2018
534de19
[Squash] add suggested comment
jasnell Aug 10, 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
29 changes: 2 additions & 27 deletions benchmark/misc/trace.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@ const common = require('../common.js');

const bench = common.createBenchmark(main, {
n: [100000],
method: ['trace', 'emit', 'isTraceCategoryEnabled', 'categoryGroupEnabled']
method: ['trace', 'isTraceCategoryEnabled']
}, {
flags: ['--expose-internals', '--trace-event-categories', 'foo']
});
Expand All @@ -13,14 +13,6 @@ const {
TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN: kBeforeEvent
} = process.binding('constants').trace;

function doEmit(n, emit) {
bench.start();
for (var i = 0; i < n; i++) {
emit(kBeforeEvent, 'foo', 'test', 0, 'arg1', 1);
}
bench.end(n);
}

function doTrace(n, trace) {
bench.start();
for (var i = 0; i < n; i++) {
Expand All @@ -38,39 +30,22 @@ function doIsTraceCategoryEnabled(n, isTraceCategoryEnabled) {
bench.end(n);
}

function doCategoryGroupEnabled(n, categoryGroupEnabled) {
bench.start();
for (var i = 0; i < n; i++) {
categoryGroupEnabled('foo');
categoryGroupEnabled('bar');
}
bench.end(n);
}

function main({ n, method }) {
const { internalBinding } = require('internal/test/binding');

const {
trace,
isTraceCategoryEnabled,
emit,
categoryGroupEnabled
isTraceCategoryEnabled
} = internalBinding('trace_events');

switch (method) {
case '':
case 'trace':
doTrace(n, trace);
break;
case 'emit':
doEmit(n, emit);
break;
case 'isTraceCategoryEnabled':
doIsTraceCategoryEnabled(n, isTraceCategoryEnabled);
break;
case 'categoryGroupEnabled':
doCategoryGroupEnabled(n, categoryGroupEnabled);
break;
default:
throw new Error(`Unexpected method "${method}"`);
}
Expand Down
2 changes: 1 addition & 1 deletion lib/internal/bootstrap/node.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -103,7 +103,7 @@
const traceEvents = internalBinding('trace_events');
const traceEventCategory = 'node,node.async_hooks';

if (traceEvents.categoryGroupEnabled(traceEventCategory)) {
if (traceEvents.isTraceCategoryEnabled(traceEventCategory)) {
NativeModule.require('internal/trace_events_async_hooks')
.setup(traceEvents, traceEventCategory);
}
Expand Down
20 changes: 10 additions & 10 deletions lib/internal/trace_events_async_hooks.js
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
'use strict';

exports.setup = function(traceEvents, traceEventCategory) {
const { trace } = traceEvents;
const async_wrap = process.binding('async_wrap');
const async_hooks = require('async_hooks');

Expand All @@ -27,34 +28,33 @@ exports.setup = function(traceEvents, traceEventCategory) {
if (nativeProviders.has(type)) return;

typeMemory.set(asyncId, type);
traceEvents.emit(BEFORE_EVENT, traceEventCategory,
type, asyncId,
'triggerAsyncId', triggerAsyncId,
'executionAsyncId', async_hooks.executionAsyncId());
trace(BEFORE_EVENT, traceEventCategory,
type, asyncId,
{
triggerAsyncId,
executionAsyncId: async_hooks.executionAsyncId()
});
},

before(asyncId) {
const type = typeMemory.get(asyncId);
if (type === undefined) return;

traceEvents.emit(BEFORE_EVENT, traceEventCategory,
type + '_CALLBACK', asyncId);
trace(BEFORE_EVENT, traceEventCategory, `${type}_CALLBACK`, asyncId);
},

after(asyncId) {
const type = typeMemory.get(asyncId);
if (type === undefined) return;

traceEvents.emit(END_EVENT, traceEventCategory,
type + '_CALLBACK', asyncId);
trace(END_EVENT, traceEventCategory, `${type}_CALLBACK`, asyncId);
},

destroy(asyncId) {
const type = typeMemory.get(asyncId);
if (type === undefined) return;

traceEvents.emit(END_EVENT, traceEventCategory,
type, asyncId);
trace(END_EVENT, traceEventCategory, type, asyncId);

// cleanup asyncId to type map
typeMemory.delete(asyncId);
Expand Down
20 changes: 13 additions & 7 deletions src/async_wrap.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@
#include "env-inl.h"
#include "node_internals.h"
#include "util-inl.h"
#include "tracing/traced_value.h"

#include "v8.h"
#include "v8-profiler.h"
Expand Down Expand Up @@ -608,13 +609,18 @@ void AsyncWrap::AsyncReset(double execution_async_id, bool silent) {
switch (provider_type()) {
#define V(PROVIDER) \
case PROVIDER_ ## PROVIDER: \
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()), \
"triggerAsyncId", \
static_cast<int64_t>(get_trigger_async_id())); \
if (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED( \
TRACING_CATEGORY_NODE1(async_hooks))) { \
auto data = tracing::TracedValue::Create(); \
data->SetInteger("executionAsyncId", \
static_cast<int64_t>(env()->execution_async_id())); \
data->SetInteger("triggerAsyncId", \
static_cast<int64_t>(get_trigger_async_id())); \
TRACE_EVENT_NESTABLE_ASYNC_BEGIN1( \
TRACING_CATEGORY_NODE1(async_hooks), \
#PROVIDER, static_cast<int64_t>(get_async_id()), \
"data", std::move(data)); \
} \
break;
NODE_ASYNC_PROVIDER_TYPES(V)
#undef V
Expand Down
126 changes: 0 additions & 126 deletions src/node_trace_events.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,7 +13,6 @@ using v8::Array;
using v8::Context;
using v8::FunctionCallbackInfo;
using v8::FunctionTemplate;
using v8::Int32;
using v8::Local;
using v8::Object;
using v8::String;
Expand Down Expand Up @@ -99,137 +98,12 @@ void GetEnabledCategories(const FunctionCallbackInfo<Value>& args) {
}
}

// The tracing APIs require category groups to be pointers to long-lived
// strings. Those strings are stored here.
static std::unordered_set<std::string> category_groups;
static Mutex category_groups_mutex;

// Gets a pointer to the category-enabled flags for a tracing category group,
// if tracing is enabled for it.
static const uint8_t* GetCategoryGroupEnabled(const char* category_group) {
CHECK_NOT_NULL(category_group);
return TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(category_group);
}

static const char* GetCategoryGroup(Environment* env,
const Local<Value> category_value) {
CHECK(category_value->IsString());

Utf8Value category(env->isolate(), category_value);
Mutex::ScopedLock lock(category_groups_mutex);
// If the value already exists in the set, insertion.first will point
// to the existing value. Thus, this will maintain a long lived pointer
// to the category c-string.
auto insertion = category_groups.insert(category.out());

// The returned insertion is a pair whose first item is the object that was
// inserted or that blocked the insertion and second item is a boolean
// indicating whether it was inserted.
return insertion.first->c_str();
}

static void Emit(const FunctionCallbackInfo<Value>& args) {
Environment* env = Environment::GetCurrent(args);
Local<Context> context = env->context();

// Args: [type, category, name, id, argName, argValue]
CHECK_GE(args.Length(), 3);

// Check the category group first, to avoid doing more work if it's not
// enabled.
const char* category_group = GetCategoryGroup(env, args[1]);
const uint8_t* category_group_enabled =
GetCategoryGroupEnabled(category_group);
if (*category_group_enabled == 0) return;

// get trace_event phase
CHECK(args[0]->IsNumber());
char phase = static_cast<char>(args[0]->Int32Value(context).ToChecked());

// get trace_event name
CHECK(args[2]->IsString());
Utf8Value name_value(env->isolate(), args[2]);
const char* name = name_value.out();

// get trace_event id
int64_t id = 0;
bool has_id = false;
if (args.Length() >= 4 && !args[3]->IsUndefined() && !args[3]->IsNull()) {
has_id = true;
CHECK(args[3]->IsNumber());
id = args[3]->IntegerValue(context).ToChecked();
}

// TODO(AndreasMadsen): String values are not supported.
int32_t num_args = 0;
const char* arg_names[2];
uint8_t arg_types[2];
uint64_t arg_values[2];

// Create Utf8Value in the function scope to prevent deallocation.
// The c-string will be copied by TRACE_EVENT_API_ADD_TRACE_EVENT at the end.
Utf8Value arg1NameValue(env->isolate(), args[4]);
Utf8Value arg2NameValue(env->isolate(), args[6]);

if (args.Length() >= 6 &&
(!args[4]->IsUndefined() || !args[5]->IsUndefined())) {
num_args = 1;
arg_types[0] = TRACE_VALUE_TYPE_INT;

CHECK(args[4]->IsString());
arg_names[0] = arg1NameValue.out();

CHECK(args[5]->IsNumber());
arg_values[0] = args[5]->IntegerValue(context).ToChecked();
}

if (args.Length() >= 8 &&
(!args[6]->IsUndefined() || !args[7]->IsUndefined())) {
num_args = 2;
arg_types[1] = TRACE_VALUE_TYPE_INT;

CHECK(args[6]->IsString());
arg_names[1] = arg2NameValue.out();

CHECK(args[7]->IsNumber());
arg_values[1] = args[7]->IntegerValue(context).ToChecked();
}

// The TRACE_EVENT_FLAG_COPY flag indicates that the name and argument
// name should be copied thus they don't need to long-lived pointers.
// The category name still won't be copied and thus need to be a long-lived
// pointer.
uint32_t flags = TRACE_EVENT_FLAG_COPY;
if (has_id) {
flags |= TRACE_EVENT_FLAG_HAS_ID;
}

const char* scope = node::tracing::kGlobalScope;
uint64_t bind_id = node::tracing::kNoId;

TRACE_EVENT_API_ADD_TRACE_EVENT(
phase, category_group_enabled, name, scope, id, bind_id,
num_args, arg_names, arg_types, arg_values,
flags);
}

static void CategoryGroupEnabled(const FunctionCallbackInfo<Value>& args) {
Environment* env = Environment::GetCurrent(args);

const char* category_group = GetCategoryGroup(env, args[0]);
const uint8_t* category_group_enabled =
GetCategoryGroupEnabled(category_group);
args.GetReturnValue().Set(*category_group_enabled > 0);
}

void Initialize(Local<Object> target,
Local<Value> unused,
Local<Context> context,
void* priv) {
Environment* env = Environment::GetCurrent(context);

env->SetMethod(target, "emit", Emit);
env->SetMethod(target, "categoryGroupEnabled", CategoryGroupEnabled);
env->SetMethod(target, "getEnabledCategories", GetEnabledCategories);

Local<FunctionTemplate> category_set =
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 @@ -61,8 +61,8 @@ proc.once('exit', common.mustCall(() => {
return (trace.ph === 'b' && !trace.name.includes('_CALLBACK'));
});
assert.ok(initEvents.every((trace) => {
return (trace.args.executionAsyncId > 0 &&
trace.args.triggerAsyncId > 0);
return (trace.args.data.executionAsyncId > 0 &&
trace.args.data.triggerAsyncId > 0);
}), `Unexpected initEvents format: ${util.inspect(initEvents)}`);
}));
}));
22 changes: 11 additions & 11 deletions test/parallel/test-trace-events-binding.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,15 +9,14 @@ if (!common.isMainThread)

const CODE = `
const { internalBinding } = require('internal/test/binding');
const { emit } = internalBinding('trace_events');
emit('b'.charCodeAt(0), 'custom',
'type-value', 10, 'extra-value', 20);
emit('b'.charCodeAt(0), 'custom',
'type-value', 20, 'first-value', 20, 'second-value', 30);
emit('b'.charCodeAt(0), 'custom',
'type-value', 30);
emit('b'.charCodeAt(0), 'missing',
'type-value', 10, 'extra-value', 20);
const { trace } = internalBinding('trace_events');
trace('b'.charCodeAt(0), 'custom',
'type-value', 10, {'extra-value': 20 });
trace('b'.charCodeAt(0), 'custom',
'type-value', 20, {'first-value': 20, 'second-value': 30 });
trace('b'.charCodeAt(0), 'custom', 'type-value', 30);
trace('b'.charCodeAt(0), 'missing',
'type-value', 10, {'extra-value': 20 });
`;
const FILE_NAME = 'node_trace.1.log';

Expand All @@ -27,6 +26,7 @@ process.chdir(tmpdir.path);

const proc = cp.spawn(process.execPath,
[ '--trace-event-categories', 'custom',
'--no-warnings',
'--expose-internals',
'-e', CODE ]);

Expand All @@ -42,14 +42,14 @@ proc.once('exit', common.mustCall(() => {
assert.strictEqual(traces[0].cat, 'custom');
assert.strictEqual(traces[0].name, 'type-value');
assert.strictEqual(traces[0].id, '0xa');
assert.deepStrictEqual(traces[0].args, { 'extra-value': 20 });
assert.deepStrictEqual(traces[0].args.data, { 'extra-value': 20 });

assert.strictEqual(traces[1].pid, proc.pid);
assert.strictEqual(traces[1].ph, 'b');
assert.strictEqual(traces[1].cat, 'custom');
assert.strictEqual(traces[1].name, 'type-value');
assert.strictEqual(traces[1].id, '0x14');
assert.deepStrictEqual(traces[1].args, {
assert.deepStrictEqual(traces[1].args.data, {
'first-value': 20,
'second-value': 30
});
Expand Down
6 changes: 4 additions & 2 deletions test/parallel/test-trace-events-category-used.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,9 +8,9 @@ if (!common.isMainThread)

const CODE = `
const { internalBinding } = require('internal/test/binding');
const { categoryGroupEnabled } = internalBinding('trace_events');
const { isTraceCategoryEnabled } = internalBinding('trace_events');
console.log(
categoryGroupEnabled("custom")
isTraceCategoryEnabled("custom")
);
`;

Expand All @@ -21,6 +21,7 @@ process.chdir(tmpdir.path);
const procEnabled = cp.spawn(
process.execPath,
[ '--trace-event-categories', 'custom',
'--no-warnings',
'--expose-internals',
'-e', CODE ]
);
Expand All @@ -35,6 +36,7 @@ procEnabled.once('exit', common.mustCall(() => {
const procDisabled = cp.spawn(
process.execPath,
[ '--trace-event-categories', 'other',
'--no-warnings',
Copy link
Member

@AndreasMadsen AndreasMadsen Aug 10, 2018 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why this? Maybe add a comment.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

just to make the test less noisy since the import of internal/test/binding emits a warning

'--expose-internals',
'-e', CODE ]
);
Expand Down