From 740bf783e58a81f155cdf5e6f13f3772071d8209 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Mon, 14 May 2018 14:24:58 -0700 Subject: [PATCH] vm,trace_events: add node.vm.script 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.script 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. PR-URL: https://github.com/nodejs/node/pull/20728 Reviewed-By: Anna Henningsen Reviewed-By: Ali Ijaz Sheikh Reviewed-By: Colin Ihrig --- 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..ca91b8aac78cc3 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.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. 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 fa2c86e809542c..7567b2433675e1 100644 --- a/src/node_contextify.cc +++ b/src/node_contextify.cc @@ -665,6 +665,16 @@ class ContextifyScript : public BaseObject { ContextifyScript* contextify_script = new ContextifyScript(env, args.This()); + if (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED( + TRACING_CATEGORY_NODE2(vm, script)) != 0) { + Utf8Value fn(isolate, filename); + TRACE_EVENT_NESTABLE_ASYNC_BEGIN1( + TRACING_CATEGORY_NODE2(vm, script), + "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(); @@ -694,6 +704,10 @@ class ContextifyScript : public BaseObject { DecorateErrorStack(env, try_catch); no_abort_scope.Close(); try_catch.ReThrow(); + TRACE_EVENT_NESTABLE_ASYNC_END0( + TRACING_CATEGORY_NODE2(vm, script), + "ContextifyScript::New", + contextify_script); return; } contextify_script->script_.Reset(isolate, v8_script.ToLocalChecked()); @@ -717,6 +731,10 @@ class ContextifyScript : public BaseObject { env->cached_data_produced_string(), Boolean::New(isolate, cached_data_produced)); } + TRACE_EVENT_NESTABLE_ASYNC_END0( + TRACING_CATEGORY_NODE2(vm, script), + "ContextifyScript::New", + contextify_script); } @@ -729,6 +747,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_NODE2(vm, script), "RunInThisContext", wrapped_script); + CHECK_EQ(args.Length(), 3); CHECK(args[0]->IsNumber()); @@ -742,11 +766,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_NODE2(vm, script), "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()); @@ -759,6 +789,9 @@ class ContextifyScript : public BaseObject { if (contextify_context->context().IsEmpty()) return; + TRACE_EVENT_NESTABLE_ASYNC_BEGIN0( + TRACING_CATEGORY_NODE2(vm, script), "RunInContext", wrapped_script); + CHECK(args[1]->IsNumber()); int64_t timeout = args[1]->IntegerValue(env->context()).FromJust(); @@ -775,6 +808,9 @@ class ContextifyScript : public BaseObject { display_errors, break_on_sigint, args); + + TRACE_EVENT_NESTABLE_ASYNC_END0( + 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 new file mode 100644 index 00000000000000..fc7af34d8866d2 --- /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.script' + ] + }); + + 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)); + }); + })); + })); +}