vm,trace_events: add node.vm trace events category

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.

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_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();
@@ -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_NODE2(vm, script),
+          "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_NODE2(vm, script),
+        "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_NODE2(vm, script), "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_NODE2(vm, script), "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_NODE2(vm, script), "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_NODE2(vm, script), "RunInContext", wrapped_script);
   }
 
   static void DecorateErrorStack(Environment* env, const TryCatch& try_catch) {

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));
+      });
+    }));
+  }));
+}