From 6023cc0bc04c44e84a4abffd97f2dbe020d24a76 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Mon, 14 May 2018 14:24:58 -0700 Subject: [PATCH 1/3] vm,trace_events: add node.vm trace events category Add basic trace events for node_contextify. These generally align very well with V8.ScriptCompile and V8.ScriptExecute trace events and provide good additional context. For instance, using the node.vm trace category at startup allows us to see exactly how long compilation and init of each of our core modules adds to the startup time. --- doc/api/tracing.md | 2 ++ src/node_contextify.cc | 36 +++++++++++++++++++++++ test/parallel/test-trace-events-vm.js | 42 +++++++++++++++++++++++++++ 3 files changed, 80 insertions(+) create mode 100644 test/parallel/test-trace-events-vm.js diff --git a/doc/api/tracing.md b/doc/api/tracing.md index 228d3a6678482c..01f821bc040845 100644 --- a/doc/api/tracing.md +++ b/doc/api/tracing.md @@ -24,6 +24,8 @@ The available categories are: * `node.perf.timerify` - Enables capture of only Performance API timerify measurements. * `node.fs.sync` - Enables capture of trace data for file system sync methods. +* `node.vm` - Enables capture of trace data for the `vm` module's + `runInNewContext()`, `runInContext()`, and `runInThisContext()` methods. * `v8` - The [V8] events are GC, compiling, and execution related. By default the `node`, `node.async_hooks`, and `v8` categories are enabled. diff --git a/src/node_contextify.cc b/src/node_contextify.cc index 8571b9e0be32bc..16dfc30ce258bd 100644 --- a/src/node_contextify.cc +++ b/src/node_contextify.cc @@ -666,6 +666,16 @@ class ContextifyScript : public BaseObject { ContextifyScript* contextify_script = new ContextifyScript(env, args.This()); + if (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED( + TRACING_CATEGORY_NODE1(vm)) != 0) { + Utf8Value fn(isolate, filename); + TRACE_EVENT_NESTABLE_ASYNC_BEGIN1( + TRACING_CATEGORY_NODE1(vm), + "ContextifyScript::New", + contextify_script, + "filename", TRACE_STR_COPY(*fn)); + } + ScriptCompiler::CachedData* cached_data = nullptr; if (!cached_data_buf.IsEmpty()) { ArrayBuffer::Contents contents = cached_data_buf->Buffer()->GetContents(); @@ -695,6 +705,10 @@ class ContextifyScript : public BaseObject { DecorateErrorStack(env, try_catch); no_abort_scope.Close(); try_catch.ReThrow(); + TRACE_EVENT_NESTABLE_ASYNC_END0( + TRACING_CATEGORY_NODE1(vm), + "ContextifyScript::New", + contextify_script); return; } contextify_script->script_.Reset(isolate, v8_script.ToLocalChecked()); @@ -718,6 +732,10 @@ class ContextifyScript : public BaseObject { env->cached_data_produced_string(), Boolean::New(isolate, cached_data_produced)); } + TRACE_EVENT_NESTABLE_ASYNC_END0( + TRACING_CATEGORY_NODE1(vm), + "ContextifyScript::New", + contextify_script); } @@ -730,6 +748,12 @@ class ContextifyScript : public BaseObject { static void RunInThisContext(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); + ContextifyScript* wrapped_script; + ASSIGN_OR_RETURN_UNWRAP(&wrapped_script, args.Holder()); + + TRACE_EVENT_NESTABLE_ASYNC_BEGIN0( + TRACING_CATEGORY_NODE1(vm), "RunInThisContext", wrapped_script); + CHECK_EQ(args.Length(), 3); CHECK(args[0]->IsNumber()); @@ -743,11 +767,17 @@ class ContextifyScript : public BaseObject { // Do the eval within this context EvalMachine(env, timeout, display_errors, break_on_sigint, args); + + TRACE_EVENT_NESTABLE_ASYNC_END0( + TRACING_CATEGORY_NODE1(vm), "RunInThisContext", wrapped_script); } static void RunInContext(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); + ContextifyScript* wrapped_script; + ASSIGN_OR_RETURN_UNWRAP(&wrapped_script, args.Holder()); + CHECK_EQ(args.Length(), 4); CHECK(args[0]->IsObject()); @@ -760,6 +790,9 @@ class ContextifyScript : public BaseObject { if (contextify_context->context().IsEmpty()) return; + TRACE_EVENT_NESTABLE_ASYNC_BEGIN0( + TRACING_CATEGORY_NODE1(vm), "RunInContext", wrapped_script); + CHECK(args[1]->IsNumber()); int64_t timeout = args[1]->IntegerValue(env->context()).FromJust(); @@ -776,6 +809,9 @@ class ContextifyScript : public BaseObject { display_errors, break_on_sigint, args); + + TRACE_EVENT_NESTABLE_ASYNC_END0( + TRACING_CATEGORY_NODE1(vm), "RunInContext", wrapped_script); } static void DecorateErrorStack(Environment* env, const TryCatch& try_catch) { diff --git a/test/parallel/test-trace-events-vm.js b/test/parallel/test-trace-events-vm.js new file mode 100644 index 00000000000000..f9e0640621efb2 --- /dev/null +++ b/test/parallel/test-trace-events-vm.js @@ -0,0 +1,42 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const cp = require('child_process'); +const path = require('path'); +const fs = require('fs'); +const tmpdir = require('../common/tmpdir'); + +const names = [ + 'ContextifyScript::New', + 'RunInThisContext', + 'RunInContext' +]; + +if (process.argv[2] === 'child') { + const vm = require('vm'); + vm.runInNewContext('1 + 1'); +} else { + tmpdir.refresh(); + process.chdir(tmpdir.path); + + const proc = cp.fork(__filename, + [ 'child' ], { + execArgv: [ + '--trace-event-categories', + 'node.vm' + ] + }); + + proc.once('exit', common.mustCall(() => { + const file = path.join(tmpdir.path, 'node_trace.1.log'); + + assert(common.fileExists(file)); + fs.readFile(file, common.mustCall((err, data) => { + const traces = JSON.parse(data.toString()).traceEvents; + traces.forEach((trace) => { + assert.strictEqual(trace.pid, proc.pid); + assert(names.includes(trace.name)); + }); + })); + })); +} From 0cb02f28c4acc02c36cf3a83bd514cca6954287d Mon Sep 17 00:00:00 2001 From: James M Snell Date: Mon, 14 May 2018 15:24:12 -0700 Subject: [PATCH 2/3] [Squash] rename event --- src/node_contextify.cc | 16 ++++++++-------- test/parallel/test-trace-events-vm.js | 2 +- 2 files changed, 9 insertions(+), 9 deletions(-) diff --git a/src/node_contextify.cc b/src/node_contextify.cc index 16dfc30ce258bd..13863985a46676 100644 --- a/src/node_contextify.cc +++ b/src/node_contextify.cc @@ -667,10 +667,10 @@ class ContextifyScript : public BaseObject { new ContextifyScript(env, args.This()); if (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED( - TRACING_CATEGORY_NODE1(vm)) != 0) { + TRACING_CATEGORY_NODE2(vm, script)) != 0) { Utf8Value fn(isolate, filename); TRACE_EVENT_NESTABLE_ASYNC_BEGIN1( - TRACING_CATEGORY_NODE1(vm), + TRACING_CATEGORY_NODE2(vm, script), "ContextifyScript::New", contextify_script, "filename", TRACE_STR_COPY(*fn)); @@ -706,7 +706,7 @@ class ContextifyScript : public BaseObject { no_abort_scope.Close(); try_catch.ReThrow(); TRACE_EVENT_NESTABLE_ASYNC_END0( - TRACING_CATEGORY_NODE1(vm), + TRACING_CATEGORY_NODE2(vm, script), "ContextifyScript::New", contextify_script); return; @@ -733,7 +733,7 @@ class ContextifyScript : public BaseObject { Boolean::New(isolate, cached_data_produced)); } TRACE_EVENT_NESTABLE_ASYNC_END0( - TRACING_CATEGORY_NODE1(vm), + TRACING_CATEGORY_NODE2(vm, script), "ContextifyScript::New", contextify_script); } @@ -752,7 +752,7 @@ class ContextifyScript : public BaseObject { ASSIGN_OR_RETURN_UNWRAP(&wrapped_script, args.Holder()); TRACE_EVENT_NESTABLE_ASYNC_BEGIN0( - TRACING_CATEGORY_NODE1(vm), "RunInThisContext", wrapped_script); + TRACING_CATEGORY_NODE2(vm, script), "RunInThisContext", wrapped_script); CHECK_EQ(args.Length(), 3); @@ -769,7 +769,7 @@ class ContextifyScript : public BaseObject { EvalMachine(env, timeout, display_errors, break_on_sigint, args); TRACE_EVENT_NESTABLE_ASYNC_END0( - TRACING_CATEGORY_NODE1(vm), "RunInThisContext", wrapped_script); + TRACING_CATEGORY_NODE2(vm, script), "RunInThisContext", wrapped_script); } static void RunInContext(const FunctionCallbackInfo& args) { @@ -791,7 +791,7 @@ class ContextifyScript : public BaseObject { return; TRACE_EVENT_NESTABLE_ASYNC_BEGIN0( - TRACING_CATEGORY_NODE1(vm), "RunInContext", wrapped_script); + TRACING_CATEGORY_NODE2(vm, script), "RunInContext", wrapped_script); CHECK(args[1]->IsNumber()); int64_t timeout = args[1]->IntegerValue(env->context()).FromJust(); @@ -811,7 +811,7 @@ class ContextifyScript : public BaseObject { args); TRACE_EVENT_NESTABLE_ASYNC_END0( - TRACING_CATEGORY_NODE1(vm), "RunInContext", wrapped_script); + TRACING_CATEGORY_NODE2(vm, script), "RunInContext", wrapped_script); } static void DecorateErrorStack(Environment* env, const TryCatch& try_catch) { diff --git a/test/parallel/test-trace-events-vm.js b/test/parallel/test-trace-events-vm.js index f9e0640621efb2..fc7af34d8866d2 100644 --- a/test/parallel/test-trace-events-vm.js +++ b/test/parallel/test-trace-events-vm.js @@ -23,7 +23,7 @@ if (process.argv[2] === 'child') { [ 'child' ], { execArgv: [ '--trace-event-categories', - 'node.vm' + 'node.vm.script' ] }); From 2a9679a9bf38b7b870c777a145d66c2edc330c8a Mon Sep 17 00:00:00 2001 From: James M Snell Date: Tue, 15 May 2018 14:31:42 -0700 Subject: [PATCH 3/3] update doc --- doc/api/tracing.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/doc/api/tracing.md b/doc/api/tracing.md index 01f821bc040845..ca91b8aac78cc3 100644 --- a/doc/api/tracing.md +++ b/doc/api/tracing.md @@ -24,7 +24,7 @@ The available categories are: * `node.perf.timerify` - Enables capture of only Performance API timerify measurements. * `node.fs.sync` - Enables capture of trace data for file system sync methods. -* `node.vm` - Enables capture of trace data for the `vm` module's +* `node.vm.script` - Enables capture of trace data for the `vm` module's `runInNewContext()`, `runInContext()`, and `runInThisContext()` methods. * `v8` - The [V8] events are GC, compiling, and execution related.