testSlowerVersionsNameTheirChange

tcmts.cli.test.e2e.traces.testSlowerVersionsNameTheirChange · #2gm6i2np · term

A version that runs worse than the one before says the change that did it: a server function re-hashed because something it uses changed is found slower than its last version, with the definition whose own code changed and the history entry (its message) that made it so.

import { okIn, plainEnv, strip, tcmBin, tempDir, withChildren } from "#codebase/tcmts/cli/test/e2e/harness";
import { hashOf } from "#codebase/tcmts/cli/test/e2e/jobs";
import { ORDER } from "#codebase/tcmts/cli/test/e2e/traces";
import assert from "node:assert/strict";
import { spawn } from "node:child_process";
import fs from "node:fs";
import path from "node:path";

export const testSlowerVersionsNameTheirChange = () =>
  withChildren(async (keep) => {
    const dir = tempDir("traces-worse");
    const tcm = (...args: string[]) => strip(okIn(dir, ...args));
    const waitFor = async (cond: () => boolean | Promise<boolean>, what: string, ms = 20000) => {
      for (
        const end = Date.now() + ms;
        Date.now() < end;
        await new Promise((r) => setTimeout(r, 200))
      )
        if (await cond()) return;
      throw new Error(`timed out waiting for ${what}`);
    };
    tcm("init");
    tcm("lib", "add", "tcm", "server", "--at", "lib.server");
    const scratch = path.join(dir, "scratch.ts");
    fs.writeFileSync(
      scratch,
      `${ORDER(0)}import { table } from "#codebase/lib/server";
export const items = table<{ name: string }>("items");
export async function list(): Promise<string[]> {
  return order((await items.find()).map((r) => r.value.name));
}
export async function main() {
  document.body.textContent = (await list()).join();
}
`,
    );
    tcm("add");
    const child = keep(
      spawn(process.execPath, [tcmBin(), "start", "shop.main", "--port", "0"], {
        cwd: dir,
        env: plainEnv(),
      }),
    );
    let out = "";
    child.stdout.setEncoding("utf8").on("data", (d: string) => (out += d));
    child.stderr.setEncoding("utf8").on("data", (d: string) => (out += d));
    await waitFor(() => /traces\s+kept/.test(out), "tcm start");
    const url = /url\s+(http:\/\/\S+)/.exec(out)![1]!;
    const list = async () =>
      (
        await fetch(new URL(`/__tcm/rpc/${hashOf(dir, "shop.list")}`, url), {
          method: "POST",
          headers: { "content-type": "application/json" },
          body: "[]",
        })
      ).status;
    for (let i = 0; i < 6; i++) assert.equal(await list(), 200);

    // what list uses gets slower: list is re-hashed, its own code the same
    // (slower by far more than a loaded machine's noise: the verdict needs half as long again)
    fs.writeFileSync(scratch, ORDER(150));
    tcm("update", "-m", "Shop: order items by hand");
    await waitFor(async () => (await list()) === 200, "the new build");
    for (let i = 0; i < 6; i++) await list();

    await waitFor(() => /worse than the version before/.test(tcm("traces")), "the verdict");
    const overview = tcm("traces");
    assert.match(
      overview,
      /worse than the version before\n {2}shop\.list call {2}p95 \S+ → \S+ \(\d+\.\d× slower\)\n {4}since "Shop: order items by hand" #[a-z2-7]{8}, [^\n]+\n {4}changed: shop\.order\n/,
    );
    const versions = tcm("traces", "shop.list");
    assert.match(
      versions,
      /\(now\)[^\n]*"Shop: order items by hand"/,
      "each version says the entry that made it",
    );
    assert.match(
      versions,
      /what changed, version by version\n {2}\S+ ← \S+ {2}shop\.order changed {2}p95 [^\n]*slower/,
    );
  })

uses