test(server): measure child startup during npm journey

packages/server/src/server/plugins/index.posix.test.ts

@@ -1,4 +1,7 @@
+import type { ChildProcess } from "node:child_process";
+import { channel } from "node:diagnostics_channel";
 import { randomUUID } from "node:crypto";
+import { writeSync } from "node:fs";
 import {
   cp,
   rename,
@@ -1612,7 +1615,44 @@ export default function contribute() {
     ]);
   }, 120_000);
 
-  it("preserves dependencies and metadata, and reloads without npm", async () => {
+  it("preserves dependencies and metadata, and reloads without npm", async ({ onTestFinished }) => {
+    const processes = channel("child_process");
+    const observe = (event: unknown) => {
+      const child = (event as { process: ChildProcess }).process;
+      const began = performance.now();
+      child.on("message", (message: unknown) => {
+        if (
+          typeof message === "object" &&
+          message !== null &&
+          "type" in message &&
+          message.type === "ready"
+        ) {
+          writeSync(
+            2,
+            `npm journey child: plugin ready; ${Math.round(performance.now() - began)}ms\n`,
+          );
+        }
+      });
+      child.once("close", () => {
+        const command = child.spawnargs.join(" ");
+        let kind = "other child";
+        if (command.includes("--version")) kind = "version probe";
+        else if (/\bnpm(?:\.cmd|\.exe)?(?:[" ]|$)/i.test(command)) kind = "npm command";
+        writeSync(2, `npm journey child: ${kind}; ${Math.round(performance.now() - began)}ms\n`);
+      });
+    };
+    processes.subscribe(observe);
+    onTestFinished(() => processes.unsubscribe(observe));
+    const started = performance.now();
+    let previous = started;
+    const mark = (phase: string) => {
+      const now = performance.now();
+      writeSync(
+        2,
+        `npm journey: ${phase}; phase=${Math.round(now - previous)}ms total=${Math.round(now - started)}ms\n`,
+      );
+      previous = now;
+    };
     const home = await mkdtemp(path.join(tmpdir(), "paseo-npm-service-"));
     roots.push(home);
     const previousConfig = process.env.npm_config_userconfig;
@@ -1628,6 +1668,7 @@ export default function contribute() {
     let service = open();
     try {
       await service.start();
+      mark("start complete");
       const installed = await service.installSource({ source: "npm:paseo-fixture-plugin@^1.0.0" });
       expect(installed).toMatchObject({
         id: "npm-review",
@@ -1656,6 +1697,7 @@ export default function contribute() {
           "node_modules/paseo-fixture-dependency"
         ].version,
       ).toBe("1.0.0");
+      mark("initial install complete");
       for (const [source, id, version] of [
         ["npm:paseo-fixture-plugin@1.0.0", "exact", "1.0.0"],
         ["paseo-fixture-plugin@stable", "tag", "1.0.0"],
@@ -1667,6 +1709,7 @@ export default function contribute() {
           installation: { currentRevision: version },
         });
       }
+      mark("selector installs complete");
       const [preview] = await service.previewUpdates({ pluginId: "exact" });
       expect(preview).toMatchObject({
         outcome: "update",
@@ -1721,6 +1764,7 @@ export default function contribute() {
       ]);
       expect((await service.previewUpdates({ pluginId: "exact" }))[0]?.outcome).toBe("update");
       await expect(service.updateSources("exact")).rejects.toThrow("Update the client");
+      mark("update journey complete");
       const prepared = await service.installSource({
         source: "npm:paseo-prepared-plugin@1.0.0:nested",
       });
@@ -1739,6 +1783,7 @@ export default function contribute() {
         "already configured",
       );
       expect(await readdir(path.join(home, "plugins", ".staging"))).toEqual([]);
+      mark("prepared and rejected inputs complete");
       for (const name of [
         "bad-manifest",
         "bad-build",
@@ -1755,6 +1800,7 @@ export default function contribute() {
         ]);
         expect(await readdir(path.join(home, "plugins", ".staging"))).toEqual([]);
       }
+      mark("failed packages complete");
       await service.disablePlugin("scoped");
       await service.stopAllPlugins();
       const recordsPath = path.join(home, "plugins", "sources.json");
@@ -1788,6 +1834,7 @@ export default function contribute() {
         service.installSource({ source: "npm:paseo-fixture-plugin", id: "missing-npm" }),
       ).rejects.toThrow("npm is required on the daemon host");
       expect(await readdir(path.join(home, "plugins", ".staging"))).toEqual([]);
+      mark("restart without npm complete");
       const packagePath = path.join(installed.path, "package.json");
       const packageJson = await readFile(packagePath, "utf8");
       await writeFile(
@@ -1803,6 +1850,7 @@ export default function contribute() {
       });
       expect(await service.reloadPlugin("npm-review")).toMatchObject({ status: "running" });
       await writeFile(packagePath, packageJson);
+      mark("corrupt metadata complete");
       await service.removePlugin("npm-review");
       await expect(stat(installRoot)).rejects.toMatchObject({ code: "ENOENT" });
       expect(
@@ -1816,6 +1864,7 @@ export default function contribute() {
       else process.env.npm_config_userconfig = previousConfig;
       await service.stopAllPlugins();
       await registry.close();
+      mark("cleanup complete");
     }
   }, 120_000);
 });