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.
nodejs · jasnell · May 14, 2018 · May 14, 2018 · May 15, 2018 · May 16, 2018
commit 6023cc0bc04c44e84a4abffd97f2dbe020d24a76
diff --git 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
@@ -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<Value>& 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<Value>& 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
@@ -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));
+      });
+    }));
+  }));
+}