From c0246c759e54e9b1245edb104d46f3c25beb5b91 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Sat, 4 Aug 2018 09:48:50 -0700 Subject: [PATCH 1/4] trace_events,async_hooks: use intrinsic trace Switch to using the intrinsic trace event method for async_hooks. This is a breaking change because of the switch to a nested data argument for exec id and trigger id values. --- lib/internal/trace_events_async_hooks.js | 20 +++++++++---------- src/async_wrap.cc | 20 ++++++++++++------- .../parallel/test-trace-events-async-hooks.js | 4 ++-- 3 files changed, 25 insertions(+), 19 deletions(-) diff --git a/lib/internal/trace_events_async_hooks.js b/lib/internal/trace_events_async_hooks.js index 011dc6bbead187..f687f1ced8e155 100644 --- a/lib/internal/trace_events_async_hooks.js +++ b/lib/internal/trace_events_async_hooks.js @@ -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'); @@ -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); diff --git a/src/async_wrap.cc b/src/async_wrap.cc index 7f2a0ece2f0055..51072bb8c9c8e9 100644 --- a/src/async_wrap.cc +++ b/src/async_wrap.cc @@ -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" @@ -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(get_async_id()), \ - "executionAsyncId", \ - static_cast(env()->execution_async_id()), \ - "triggerAsyncId", \ - static_cast(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(env()->execution_async_id())); \ + data->SetInteger("triggerAsyncId", \ + static_cast(get_trigger_async_id())); \ + TRACE_EVENT_NESTABLE_ASYNC_BEGIN1( \ + TRACING_CATEGORY_NODE1(async_hooks), \ + #PROVIDER, static_cast(get_async_id()), \ + "data", std::move(data)); \ + } \ break; NODE_ASYNC_PROVIDER_TYPES(V) #undef V diff --git a/test/parallel/test-trace-events-async-hooks.js b/test/parallel/test-trace-events-async-hooks.js index 13cd523de7ae9c..7c82eb9364a27e 100644 --- a/test/parallel/test-trace-events-async-hooks.js +++ b/test/parallel/test-trace-events-async-hooks.js @@ -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)}`); })); })); From c5e0db76d53cb3939b96a4aa61c128b1bbeb59c7 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Thu, 9 Aug 2018 13:44:44 -0700 Subject: [PATCH 2/4] src: remove old process.binding('trace_events').emit Remove the older emit and categoryGroupEnabled bindings in favor of the new intrinsics --- benchmark/misc/trace.js | 25 +--- lib/internal/bootstrap/node.js | 2 +- src/node_trace_events.cc | 125 ------------------ test/parallel/test-trace-events-binding.js | 22 +-- .../test-trace-events-category-used.js | 6 +- 5 files changed, 17 insertions(+), 163 deletions(-) diff --git a/benchmark/misc/trace.js b/benchmark/misc/trace.js index 7ac80ca4cf8528..62be1e4dae4594 100644 --- a/benchmark/misc/trace.js +++ b/benchmark/misc/trace.js @@ -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'] }); @@ -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++) { @@ -38,15 +30,6 @@ 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'); @@ -62,15 +45,9 @@ function main({ n, method }) { 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}"`); } diff --git a/lib/internal/bootstrap/node.js b/lib/internal/bootstrap/node.js index 5cd00932bd8667..7299e71db52970 100644 --- a/lib/internal/bootstrap/node.js +++ b/lib/internal/bootstrap/node.js @@ -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); } diff --git a/src/node_trace_events.cc b/src/node_trace_events.cc index 8413620e3f5f5b..e20a5debd6ad3a 100644 --- a/src/node_trace_events.cc +++ b/src/node_trace_events.cc @@ -99,137 +99,12 @@ void GetEnabledCategories(const FunctionCallbackInfo& args) { } } -// The tracing APIs require category groups to be pointers to long-lived -// strings. Those strings are stored here. -static std::unordered_set 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 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& args) { - Environment* env = Environment::GetCurrent(args); - Local 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(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& 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 target, Local unused, Local context, void* priv) { Environment* env = Environment::GetCurrent(context); - env->SetMethod(target, "emit", Emit); - env->SetMethod(target, "categoryGroupEnabled", CategoryGroupEnabled); env->SetMethod(target, "getEnabledCategories", GetEnabledCategories); Local category_set = diff --git a/test/parallel/test-trace-events-binding.js b/test/parallel/test-trace-events-binding.js index 2544c196acee49..163d9c4cbd6290 100644 --- a/test/parallel/test-trace-events-binding.js +++ b/test/parallel/test-trace-events-binding.js @@ -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'; @@ -27,6 +26,7 @@ process.chdir(tmpdir.path); const proc = cp.spawn(process.execPath, [ '--trace-event-categories', 'custom', + '--no-warnings', '--expose-internals', '-e', CODE ]); @@ -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 }); diff --git a/test/parallel/test-trace-events-category-used.js b/test/parallel/test-trace-events-category-used.js index 4f9ad69366fdb0..15a07611331a87 100644 --- a/test/parallel/test-trace-events-category-used.js +++ b/test/parallel/test-trace-events-category-used.js @@ -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") ); `; @@ -21,6 +21,7 @@ process.chdir(tmpdir.path); const procEnabled = cp.spawn( process.execPath, [ '--trace-event-categories', 'custom', + '--no-warnings', '--expose-internals', '-e', CODE ] ); @@ -35,6 +36,7 @@ procEnabled.once('exit', common.mustCall(() => { const procDisabled = cp.spawn( process.execPath, [ '--trace-event-categories', 'other', + '--no-warnings', '--expose-internals', '-e', CODE ] ); From 23091d03722fcd82fa0c7923705d45bb540ba125 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Thu, 9 Aug 2018 14:34:02 -0700 Subject: [PATCH 3/4] [Squash] fix lint issue --- benchmark/misc/trace.js | 4 +--- src/node_trace_events.cc | 1 - 2 files changed, 1 insertion(+), 4 deletions(-) diff --git a/benchmark/misc/trace.js b/benchmark/misc/trace.js index 62be1e4dae4594..fb51c91e9e3e7e 100644 --- a/benchmark/misc/trace.js +++ b/benchmark/misc/trace.js @@ -35,9 +35,7 @@ function main({ n, method }) { const { trace, - isTraceCategoryEnabled, - emit, - categoryGroupEnabled + isTraceCategoryEnabled } = internalBinding('trace_events'); switch (method) { diff --git a/src/node_trace_events.cc b/src/node_trace_events.cc index e20a5debd6ad3a..219e142a319556 100644 --- a/src/node_trace_events.cc +++ b/src/node_trace_events.cc @@ -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; From 534de190ead06de219ae4d250d0cb0714de050c7 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Fri, 10 Aug 2018 07:16:09 -0700 Subject: [PATCH 4/4] [Squash] add suggested comment --- test/parallel/test-trace-events-category-used.js | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/test/parallel/test-trace-events-category-used.js b/test/parallel/test-trace-events-category-used.js index 15a07611331a87..249ccd4aa3a3f3 100644 --- a/test/parallel/test-trace-events-category-used.js +++ b/test/parallel/test-trace-events-category-used.js @@ -21,6 +21,8 @@ process.chdir(tmpdir.path); const procEnabled = cp.spawn( process.execPath, [ '--trace-event-categories', 'custom', + // make test less noisy since internal/test/binding + // emits a warning. '--no-warnings', '--expose-internals', '-e', CODE ] @@ -36,6 +38,8 @@ procEnabled.once('exit', common.mustCall(() => { const procDisabled = cp.spawn( process.execPath, [ '--trace-event-categories', 'other', + // make test less noisy since internal/test/binding + // emits a warning. '--no-warnings', '--expose-internals', '-e', CODE ]