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 <anna@addaleax.net>
Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

1 files changed, 36 insertions, 0 deletions

diff --git a/src/node_contextify.cc b/src/node_contextify.cc
index 8571b9e0be..13863985a4 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_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) {