feat: expose timing data to userland code (#49)

Author: addaleax

resources/entry-point-trampoline.js

@@ -60,7 +60,8 @@ module.exports = (src, codeCacheMode, codeCache) => {
   const __dirname = path.dirname(process.execPath);
   let innerRequire;
   const exports = {};
-  const usesSnapshot = !!v8?.startupSnapshot?.isBuildingSnapshot();
+  const isBuildingSnapshot = () => !!v8?.startupSnapshot?.isBuildingSnapshot();
+  const usesSnapshot = isBuildingSnapshot();
 
   if (usesSnapshot) {
     innerRequire = outerRequire; // Node.js snapshots currently do not support userland require()
@@ -119,6 +120,27 @@ module.exports = (src, codeCacheMode, codeCache) => {
   // https://github.com/nodejs/node/pull/46320
   process.boxednode.rejectedCodeCache = mainFunction.cachedDataRejected;
 
+  let jsTimingEntries = [];
+  if (usesSnapshot) {
+    v8.startupSnapshot.addDeserializeCallback(() => {
+      jsTimingEntries = [];
+    });
+  }
+  process.boxednode.markTime = (label) => {
+    jsTimingEntries.push([label, process.hrtime.bigint()]);
+  };
+  process.boxednode.getTimingData = () => {
+    if (isBuildingSnapshot()) {
+      throw new Error('getTimingData() is not available during snapshot building');
+    }
+    const data = [
+      ...jsTimingEntries,
+      ...process._linkedBinding('boxednode_linked_bindings').getTimingData()
+    ].sort((a, b) => Number(a[1] - b[1]));
+    // Adjust times so that process initialization happens at time 0
+    return data.map(([label, time]) => [label, Number(time - data[0][1])]);
+  };
+
   mainFunction(__filename, __dirname, require, exports, module);
   return module.exports;
 };

resources/main-template.cc

@@ -7,6 +7,7 @@
 #include "node_api.h"
 #include "uv.h"
 #include "brotli/decode.h"
+#include <atomic>
 #if HAVE_OPENSSL
 #include <openssl/err.h>
 #include <openssl/ssl.h>
@@ -50,9 +51,54 @@ void TearDownOncePerProcess();
 }
 #endif
 namespace boxednode {
+namespace {
+struct TimingEntry {
+  const char* const label;
+  uint64_t const time;
+  TimingEntry* next = nullptr;
+  ~TimingEntry() {
+    delete next;
+  }
+};
+TimingEntry start_time_entry { "Process initialization", uv_hrtime() };
+std::atomic<TimingEntry*> current_time_entry { &start_time_entry };
+
+void MarkTime(const char* label) {
+  TimingEntry* new_entry = new TimingEntry { label, uv_hrtime() };
+  do {
+    new_entry->next = current_time_entry.load();
+  } while(!current_time_entry.compare_exchange_strong(new_entry->next, new_entry));
+}
+} // anonymous namespace
+
 Local<String> GetBoxednodeMainScriptSource(Isolate* isolate);
 Local<Uint8Array> GetBoxednodeCodeCacheBuffer(Isolate* isolate);
 std::vector<char> GetBoxednodeSnapshotBlobVector();
+
+void GetTimingData(const FunctionCallbackInfo<Value>& info) {
+  Isolate* isolate = info.GetIsolate();
+  TimingEntry* head = current_time_entry.load();
+  std::vector<Local<Value>> entries;
+  while (head != nullptr) {
+    Local<Value> elements[] = {
+      String::NewFromUtf8(isolate, head->label).ToLocalChecked(),
+      BigInt::NewFromUnsigned(isolate, head->time)
+    };
+    entries.push_back(Array::New(isolate, elements, sizeof(elements)/sizeof(elements[0])));
+    head = head->next;
+  }
+  Local<Array> retval = Array::New(isolate, entries.data(), entries.size());
+  info.GetReturnValue().Set(retval);
+}
+
+void boxednode_linked_bindings_register(
+    Local<Object> exports,
+    Local<Value> module,
+    Local<Context> context,
+    void* priv) {
+  NODE_SET_METHOD(exports, "getTimingData", GetTimingData);
+}
+
 }
 
 extern "C" {
@@ -97,13 +143,15 @@ static MaybeLocal<Value> LoadBoxednodeEnvironment(Local<Context> context) {
             String::NewFromUtf8Literal(isolate, BOXEDNODE_CODE_CACHE_MODE),
             boxednode::GetBoxednodeCodeCacheBuffer(isolate),
           };
+          boxednode::MarkTime("Calling entrypoint");
           if (entrypoint_ret.As<Function>()->Call(
               context,
               Null(isolate),
               sizeof(trampoline_args) / sizeof(trampoline_args[0]),
               trampoline_args).IsEmpty()) {
             return {}; // JS exception.
           }
+          boxednode::MarkTime("Called entrypoint");
           return Null(isolate);
       }
 #endif
@@ -160,15 +208,18 @@ static int RunNodeInstance(MultiIsolatePlatform* platform,
 #else
   loop = uv_default_loop();
 #endif
+  boxednode::MarkTime("Initialized Loop");
 
   std::shared_ptr<ArrayBufferAllocator> allocator =
       ArrayBufferAllocator::Create();
 
 #ifdef BOXEDNODE_CONSUME_SNAPSHOT
   std::vector<char> snapshot_blob_vec = boxednode::GetBoxednodeSnapshotBlobVector();
+  boxednode::MarkTime("Decoded snapshot");
   assert(EmbedderSnapshotData::CanUseCustomSnapshotPerIsolate());
   node::EmbedderSnapshotData::Pointer snapshot_blob =
     EmbedderSnapshotData::FromBlob(snapshot_blob_vec);
+  boxednode::MarkTime("Read snapshot");
   Isolate* isolate = NewIsolate(allocator, loop, platform, snapshot_blob.get());
 #elif NODE_VERSION_AT_LEAST(14, 0, 0)
   Isolate* isolate = NewIsolate(allocator, loop, platform);
@@ -179,6 +230,7 @@ static int RunNodeInstance(MultiIsolatePlatform* platform,
     fprintf(stderr, "%s: Failed to initialize V8 Isolate\n", args[0].c_str());
     return 1;
   }
+  boxednode::MarkTime("Created Isolate");
 
   {
     Locker locker(isolate);
@@ -194,6 +246,7 @@ static int RunNodeInstance(MultiIsolatePlatform* platform,
         ),
         node::FreeIsolateData);
 
+    boxednode::MarkTime("Created IsolateData");
     HandleScope handle_scope(isolate);
     Local<Context> context;
 #ifndef BOXEDNODE_CONSUME_SNAPSHOT
@@ -209,6 +262,7 @@ static int RunNodeInstance(MultiIsolatePlatform* platform,
     // node::LoadEnvironment() are being called.
     Context::Scope context_scope(context);
 #endif
+    boxednode::MarkTime("Created Context");
 
     // Create a node::Environment instance that will later be released using
     // node::FreeEnvironment().
@@ -222,6 +276,7 @@ static int RunNodeInstance(MultiIsolatePlatform* platform,
     Context::Scope context_scope(context);
 #endif
     assert(isolate->InContext());
+    boxednode::MarkTime("Created Environment");
 
     const void* node_mod;
     const void* napi_mod;
@@ -238,6 +293,11 @@ static int RunNodeInstance(MultiIsolatePlatform* platform,
         AddLinkedBinding(env.get(), *static_cast<const napi_module*>(napi_mod));
 #endif
     }
+    AddLinkedBinding(
+        env.get(),
+        "boxednode_linked_bindings",
+        boxednode::boxednode_linked_bindings_register, nullptr);
+    boxednode::MarkTime("Added bindings");
 
     // Set up the Node.js instance for execution, and run code inside of it.
     // There is also a variant that takes a callback and provides it with
@@ -251,6 +311,7 @@ static int RunNodeInstance(MultiIsolatePlatform* platform,
     if (LoadBoxednodeEnvironment(context).IsEmpty()) {
       return 1; // There has been a JS exception.
     }
+    boxednode::MarkTime("Loaded Environment, entering loop");
 
     {
       // SealHandleScope protects against handle leaks from callbacks.
@@ -335,11 +396,13 @@ static int BoxednodeMain(std::vector<std::string> args) {
   if (args.size() > 1)
     args.insert(args.begin() + 1, "--openssl-shared-config");
 #endif
+  boxednode::MarkTime("Start InitializeOncePerProcess");
   auto result = node::InitializeOncePerProcess(args, {
     node::ProcessInitializationFlags::kNoInitializeV8,
     node::ProcessInitializationFlags::kNoInitializeNodeV8Platform,
     node::ProcessInitializationFlags::kNoPrintHelpOrVersionOutput
   });
+  boxednode::MarkTime("Finished InitializeOncePerProcess");
   for (const std::string& error : result->errors())
     fprintf(stderr, "%s: %s\n", args[0].c_str(), error.c_str());
   if (result->exit_code() != 0) {
@@ -364,6 +427,7 @@ static int BoxednodeMain(std::vector<std::string> args) {
   V8::InitializePlatform(platform.get());
   V8::Initialize();
 
+  boxednode::MarkTime("Initialized V8");
   // See below for the contents of this function.
   int ret = RunNodeInstance(platform.get(), args, exec_args);
 
@@ -412,6 +476,7 @@ int wmain(int argc, wchar_t* wargv[]) {
 int main(int argc, char** argv) {
   argv = uv_setup_args(argc, argv);
   std::vector<std::string> args(argv, argv + argc);
+  boxednode::MarkTime("Enter BoxednodeMain");
   return BoxednodeMain(std::move(args));
 }
 #endif

test/index.ts

@@ -96,6 +96,17 @@ describe('basic functionality', () => {
         assert(stdout.includes('bananananana'), `Missed process.title change in ${stdout}`);
         proc.kill();
       }
+
+      {
+        const { stdout } = await execFile(
+          path.resolve(__dirname, `resources/example${exeSuffix}`), [
+            'process.boxednode.markTime("running js");JSON.stringify(process.boxednode.getTimingData())'
+          ],
+          { encoding: 'utf8' });
+        const timingData = JSON.parse(stdout);
+        assert.strictEqual(timingData[0][0], 'Process initialization');
+        assert.strictEqual(timingData[timingData.length - 1][0], 'running js');
+      }
     });
 
     it('works with a Nan addon', async function () {
@@ -216,11 +227,12 @@ describe('basic functionality', () => {
         const { stdout } = await execFile(
           path.resolve(__dirname, `resources/snapshot-echo-args${exeSuffix}`), ['a', 'b', 'c'],
           { encoding: 'utf8' });
-        const { currentArgv, originalArgv } = JSON.parse(stdout);
+        const { currentArgv, originalArgv, timingData } = JSON.parse(stdout);
         assert(currentArgv[0].includes('snapshot-echo-args'));
         assert(currentArgv[1].includes('snapshot-echo-args'));
         assert.deepStrictEqual(currentArgv.slice(2), ['a', 'b', 'c']);
         assert.strictEqual(originalArgv.length, 2); // [execPath, execPath]
+        assert.strictEqual(timingData[0][0], 'Process initialization');
       }
     });
   });

test/resources/snapshot-echo-args.js

@@ -7,6 +7,7 @@ const originalArgv = [...process.argv];
 setDeserializeMainFunction(() => {
   console.log(JSON.stringify({
     currentArgv: process.argv,
-    originalArgv
+    originalArgv,
+    timingData: process.boxednode.getTimingData()
   }));
 });