traces

tcmts.cli.main.traces · #sye3z2nc · term · runs on the server

uses node:path

tcm traces: what the app's server spent its time on (tcm start, tcm dev record it), from .tcm/data/traces.sqlite. A definition's spans are by hash, shown by its name now: renamed since, it's shown by the new one. With a name, that definition's versions (each hash it has had) side by side, its slowest calls and its errors; with --trace, one trace as a tree.

import type { Codebase } from "#codebase/tcmts/cli/codebase";
import type { routeTraces } from "#codebase/tcmts/cli/commands";
import { changesBetween, errorKey, shownMs, sinceMs, versionsOf, versionVerdict } from "#codebase/tcmts/cli/main";
import { bold, dim, green, red, yellow } from "#codebase/tcmts/cli/style";
import { UsageError } from "#codebase/tcmts/cli/ui";
import { shortHash } from "#codebase/tcmts/core/hash";
import type { parse } from "@bomb.sh/router";
import fs from "node:fs";
import path from "node:path";
import { DatabaseSync } from "node:sqlite";
import { stripVTControlCharacters } from "node:util";

export function traces(
  cb: Codebase,
  r: Extract<ReturnType<typeof parse<ReturnType<typeof routeTraces>>>, { method: "execute" }>,
): number {
  const file = path.join(cb.lay.tcmDir, "data", "traces.sqlite");
  if (!fs.existsSync(file))
    return (
      console.log(dim("no traces yet: tcm start and tcm dev record them as the app is used")), 0
    );
  const db = new DatabaseSync(file, { readOnly: true });
  try {
    const { since: ago, limit } = r.model;
    const since = Date.now() - sinceMs(ago);
    const when = (ms: number) => new Date(ms).toISOString().replace("T", " ").slice(0, 19);
    // a span's definition by its name now; one no longer named is an earlier version of what it was called
    const named = (s: { hash: string | null; name: string }) => {
      if (!s.hash) return s.name;
      return (
        cb.store.pathsOf(s.hash)[0] ?? `${s.name} ${dim(`(${shortHash(s.hash)}, no longer named)`)}`
      );
    };
    const firstLine = (e: string) => e.split("\n")[0]!;
    // how many calls, how many failed, and the p95, of the spans `where` says
    const statsOf = (where: string, args: (string | number)[]) => {
      const s = db
        .prepare(`SELECT count(*) AS n, sum(error IS NOT NULL) AS errors FROM spans WHERE ${where}`)
        .get(...args) as { n: number; errors: number | null };
      return { n: s.n, errors: s.errors ?? 0, p95: s.n ? percentile(where, args, s.n, 0.95) : 0 };
    };
    // the history entry that made a version what its name points at
    const sinceOf = (v: { title: string; causal: string; ts: number }) =>
      `"${v.title.length > 60 ? `${v.title.slice(0, 59)}…` : v.title}" ${dim(`#${v.causal.slice(0, 8)}, ${when(v.ts)}`)}`;
    const percentile = (where: string, args: (string | number)[], n: number, p: number) =>
      (
        db
          .prepare(`SELECT dur FROM spans WHERE ${where} ORDER BY dur LIMIT 1 OFFSET ?`)
          .get(...args, Math.min(n - 1, Math.floor(n * p))) as { dur: number }
      ).dur;
    const table = (head: string[], rows: string[][]) => {
      const plain = stripVTControlCharacters;
      const widths = head.map((h, i) =>
        Math.max(plain(h).length, ...rows.map((row) => plain(row[i]!).length)),
      );
      // the first column to the left, numbers to the right
      const line = (cells: string[]) =>
        cells
          .map((c, i) => {
            const pad = " ".repeat(widths[i]! - plain(c).length);
            return i === 0 ? c + pad : pad + c;
          })
          .join("  ");
      console.log(dim(line(head)));
      for (const row of rows) console.log(line(row));
    };

    if (r.model.trace) {
      const ids = db
        .prepare("SELECT DISTINCT trace FROM spans WHERE trace LIKE ? LIMIT 2")
        .all(`${r.model.trace.toLowerCase()}%`) as { trace: string }[];
      if (ids.length !== 1)
        throw new UsageError(
          ids.length
            ? `'${r.model.trace}' matches more than one trace`
            : `no trace '${r.model.trace}'`,
        );
      const trace = ids[0]!.trace;
      const spans = db
        .prepare("SELECT * FROM spans WHERE trace = ? ORDER BY start")
        .all(trace) as unknown as {
        id: string;
        parent: string | null;
        kind: string;
        name: string;
        hash: string | null;
        build: string | null;
        start: number;
        dur: number;
        error: string | null;
        attrs: string;
        link: string | null;
      }[];
      const t0 = spans[0]!.start;
      const here = new Set(spans.map((s) => s.id));
      // (a span whose parent isn't kept here, a caller's, is a root of what this server did)
      const children = new Map<string | null, typeof spans>();
      for (const s of spans) {
        const up = s.parent && here.has(s.parent) ? s.parent : null;
        children.set(up, [...(children.get(up) ?? []), s]);
      }
      const build = spans.find((s) => s.build)?.build;
      console.log(
        `${bold("trace")} ${trace}  ${dim(`${when(t0)}${build ? `  build ${shortHash(build)}` : ""}`)}`,
      );
      const show = (s: (typeof spans)[number], depth: number) => {
        const attrs = JSON.parse(s.attrs) as Record<string, unknown>;
        const status = attrs["http.response.status_code"];
        const from = attrs["tcm.from"];
        const extra = [
          typeof from === "string" ? `from ${named({ hash: from, name: shortHash(from) })}` : "",
          status !== undefined && status !== 200 ? String(status) : "",
          attrs["db.rows"] !== undefined ? `${String(attrs["db.rows"])} row(s)` : "",
          attrs["url.path"] !== undefined ? String(attrs["url.path"]) : "",
        ].filter(Boolean);
        const indent = "  ".repeat(depth);
        console.log(
          `${dim(`+${shownMs(s.start - t0)}`.padStart(9))} ${shownMs(s.dur).padStart(8)}  ${indent}${dim(s.kind)}${s.name === s.kind ? "" : ` ${named(s)}`}${extra.length ? dim(`  ${extra.join(", ")}`) : ""}${s.error ? `  ${red(firstLine(s.error))}` : ""}`,
        );
        if (s.link)
          console.log(
            `${" ".repeat(20)}${indent}${dim(`enqueued in trace ${s.link.split("-")[1]!.slice(0, 8)}`)}`,
          );
        for (const c of children.get(s.id) ?? []) show(c, depth + 1);
      };
      for (const s of children.get(null) ?? []) show(s, 0);
      // what it caused in traces of their own: the jobs it enqueued
      const caused = db
        .prepare("SELECT DISTINCT trace, name, hash FROM spans WHERE link LIKE ?")
        .all(`00-${trace}-%`) as { trace: string; name: string; hash: string | null }[];
      for (const c of caused)
        console.log(dim(`  enqueued ${named(c)}: trace ${c.trace.slice(0, 8)}`));
      return 0;
    }

    if (r.model.errors) {
      // the server's and pages' (a call as the page saw it is the server's error over again)
      const errors = db
        .prepare(
          `SELECT trace, start, error, kind, name, hash, json_extract(attrs, '$."tcm.thrown_in"') AS thrown FROM spans WHERE error IS NOT NULL AND kind != 'client' AND start >= ? ORDER BY start`,
        )
        .all(since) as {
        trace: string;
        start: number;
        error: string;
        kind: string;
        name: string;
        hash: string | null;
        thrown: string | null;
      }[];
      if (!errors.length) return (console.log(dim(`no errors in the last ${ago}`)), 0);
      // by the definition that threw them (as named now: each version of it alike) and what they said, alike; an
      // error each span it went up through says is one error, once a trace
      const groups = new Map<
        string,
        {
          name?: string;
          error: string;
          traces: Set<string>;
          first: number;
          last: number;
          newest: string;
          versions: string[];
          through: Set<string>;
          inBrowser: boolean;
        }
      >();
      for (const e of errors) {
        const name = e.thrown
          ? (cb.store.pathsOf(e.thrown)[0] ?? `#${e.thrown.slice(0, 8)}`)
          : undefined;
        const id = `${name ?? ""}\n${errorKey(e.error)}`;
        let g = groups.get(id);
        if (!g)
          groups.set(
            id,
            (g = {
              name,
              error: firstLine(e.error),
              traces: new Set(),
              first: e.start,
              last: e.start,
              newest: e.trace,
              versions: [],
              through: new Set(),
              inBrowser: false,
            }),
          );
        g.traces.add(e.trace);
        g.last = e.start;
        g.newest = e.trace;
        if (e.thrown && !g.versions.includes(e.thrown)) g.versions.push(e.thrown);
        if (e.kind === "error") g.inBrowser = true;
        else if (e.kind !== "sql" && e.kind !== "transaction")
          g.through.add(`${named(e)} ${dim(`(${e.kind})`)}`);
      }
      console.log(
        dim(`errors in the last ${ago}, by the definition that threw them, as named now`),
      );
      for (const g of [...groups.values()]
        .sort((a, b) => b.traces.size - a.traces.size)
        .slice(0, limit)) {
        console.log(
          `\n${bold(g.name ?? "(not thrown in the codebase's code)")}${g.inBrowser ? dim(" in the browser") : ""}  ${red(g.error)}`,
        );
        console.log(
          `  ${g.traces.size} time(s), ${when(g.first)} – ${when(g.last).slice(11)}, the newest in trace ${g.newest.slice(0, 8)}`,
        );
        // the version it began with, and the history entry that made it
        const began = g.versions[0];
        const v =
          began && g.name ? versionsOf(cb, g.name).find((x) => x.hash === began) : undefined;
        if (began)
          console.log(
            `  began with ${shortHash(began)}${v ? `: ${sinceOf(v)}` : ""}${g.versions.length > 1 ? dim(`, and ${g.versions.length - 1} version(s) since`) : ""}`,
          );
        if (g.through.size) console.log(`  through ${[...g.through].slice(0, 4).join(", ")}`);
      }
      return 0;
    }

    if (r.model.name) {
      const name = r.model.name;
      let now: string | undefined;
      try {
        now = cb.lookupOne(name, "value");
      } catch {
        // no longer a name of code, or never one: what was recorded under it is all there is
      }
      // every version: the hash it names now, and each one recorded under the name (before a change, or a rename)
      const recorded = [
        ...new Set([
          ...(now ? [now] : []),
          ...(
            db
              .prepare("SELECT DISTINCT hash FROM spans WHERE name = ? AND hash IS NOT NULL")
              .all(name) as { hash: string }[]
          ).map((h) => h.hash),
        ]),
      ];
      // newest first, as history has them (one it doesn't, under the name, after)
      const history = recorded.length ? versionsOf(cb, name) : [];
      const order = (h: string) => {
        const i = history.findIndex((v) => v.hash === h);
        return i < 0 ? history.length : i;
      };
      const hashes = recorded.sort((a, b) => order(a) - order(b));
      // a definition's by hash (as the server ran it: the browser's calls of it are below); a SQL statement's or a
      // page's (no hash) by name
      const groups = hashes.length
        ? hashes.map((h) => ({
            label: `${shortHash(h)}${h === now ? " (now)" : ""}`,
            where: "hash = ? AND kind != 'client'",
            args: [h],
          }))
        : [{ label: name, where: "hash IS NULL AND name = ?", args: [name] }];
      const rows: string[][] = [];
      const hit: typeof groups = [];
      const stats = new Map<string, ReturnType<typeof statsOf>>();
      for (const g of groups) {
        const where = `${g.where} AND start >= ?`;
        const args = [...g.args, since];
        stats.set(g.args[0]!, statsOf(where, args));
        const v = history.find((x) => x.hash === g.args[0]);
        const s = db
          .prepare(
            `SELECT count(*) AS n, max(dur) AS max, sum(error IS NOT NULL) AS errors, min(start) AS first, max(start) AS last FROM spans WHERE ${where}`,
          )
          .get(...args) as { n: number; max: number; errors: number; first: number; last: number };
        if (!s.n) continue;
        hit.push(g);
        rows.push([
          g.label,
          String(s.n),
          s.errors ? red(String(s.errors)) : "0",
          shownMs(percentile(where, args, s.n, 0.5)),
          shownMs(percentile(where, args, s.n, 0.95)),
          shownMs(s.max),
          dim(`${when(s.first)} – ${when(s.last).slice(11)}`),
          ...(hashes.length ? [v ? sinceOf(v) : dim("—")] : []),
        ]);
      }
      if (!rows.length)
        return (console.log(dim(`nothing recorded for ${name} in the last ${ago}`)), 0);
      console.log(`${bold(name)} ${dim(`in the last ${ago}`)}`);
      table(
        [
          "version",
          "calls",
          "errors",
          "p50",
          "p95",
          "max",
          "seen",
          ...(hashes.length ? ["since"] : []),
        ],
        rows,
      );
      // each version beside the one before it: what changed, and how it runs for it
      const changes: string[] = [];
      const seen = hashes.length ? hit.map((g) => g.args[0]!) : [];
      for (let i = 0; i + 1 < seen.length; i++) {
        const [newer, older] = [seen[i]!, seen[i + 1]!];
        const changed = changesBetween(cb, older, newer);
        const verdict = versionVerdict(stats.get(older)!, stats.get(newer)!);
        changes.push(
          `  ${shortHash(newer)} ← ${shortHash(older)}  ${changed.length ? `${changed.join(", ")} changed` : dim("nothing it reaches changed")}${verdict ? `  ${verdict.worse ? red(verdict.said) : green(verdict.said)}` : ""}`,
        );
      }
      if (changes.length) {
        console.log(dim("\nwhat changed, version by version"));
        for (const c of changes) console.log(c);
      }
      const any = `(${hit.map((g) => g.where).join(" OR ")}) AND start >= ?`;
      const args = [...hit.flatMap((g) => g.args), since];
      const versions = (h: string | null) => (hit.length > 1 && h ? dim(`  ${shortHash(h)}`) : "");
      const slowest = db
        .prepare(`SELECT trace, start, dur, hash FROM spans WHERE ${any} ORDER BY dur DESC LIMIT 5`)
        .all(...args) as { trace: string; start: number; dur: number; hash: string | null }[];
      console.log(dim("\nslowest"));
      for (const s of slowest)
        console.log(
          `  ${shownMs(s.dur).padStart(8)}  ${dim(when(s.start))}  trace ${s.trace.slice(0, 8)}${versions(s.hash)}`,
        );
      const errors = db
        .prepare(
          `SELECT trace, start, error, hash FROM spans WHERE ${any} AND error IS NOT NULL ORDER BY start DESC LIMIT 5`,
        )
        .all(...args) as { trace: string; start: number; error: string; hash: string | null }[];
      if (errors.length) {
        console.log(dim("\nerrors, newest first"));
        for (const e of errors)
          console.log(
            `  ${dim(when(e.start))}  trace ${e.trace.slice(0, 8)}  ${red(firstLine(e.error))}${versions(e.hash)}`,
          );
      }
      // where its calls came from: the definitions calling it in the browser, each with the time the page waited
      if (hashes.length) {
        const browser = `hash IN (${hashes.map(() => "?").join(", ")}) AND kind = 'client' AND start >= ?`;
        const fromOf = `json_extract(attrs, '$."tcm.from"')`;
        const callers = db
          .prepare(
            `SELECT ${fromOf} AS caller, count(*) AS n, max(dur) AS max, sum(error IS NOT NULL) AS errors FROM spans WHERE ${browser} GROUP BY caller ORDER BY n DESC LIMIT 10`,
          )
          .all(...hashes, since) as {
          caller: string | null;
          n: number;
          max: number;
          errors: number;
        }[];
        if (callers.length) {
          console.log(dim("\nfrom the browser, as the page waited for it"));
          table(
            ["called from", "calls", "errors", "p50", "p95", "max"],
            callers.map((c) => {
              const where = `${browser} AND ${c.caller === null ? `${fromOf} IS NULL` : `${fromOf} = ?`}`;
              const args = [...hashes, since, ...(c.caller === null ? [] : [c.caller])];
              return [
                c.caller ? named({ hash: c.caller, name: shortHash(c.caller) }) : dim("(the page)"),
                String(c.n),
                c.errors ? red(String(c.errors)) : "0",
                shownMs(percentile(where, args, c.n, 0.5)),
                shownMs(percentile(where, args, c.n, 0.95)),
                shownMs(c.max),
              ];
            }),
          );
        }
      }
      return 0;
    }

    const groups = db
      .prepare(
        `SELECT hash, kind, name, count(*) AS n, sum(dur) AS total, max(dur) AS max, sum(error IS NOT NULL) AS errors
         FROM spans WHERE start >= ? GROUP BY coalesce(hash || ' ' || kind, kind || ' ' || name) ORDER BY total DESC LIMIT ?`,
      )
      .all(since, limit) as {
      hash: string | null;
      kind: string;
      name: string;
      n: number;
      total: number;
      max: number;
      errors: number;
    }[];
    if (!groups.length) return (console.log(dim(`nothing recorded in the last ${ago}`)), 0);
    console.log(
      dim(
        `what the server spent its time on in the last ${ago}, by definition as named now (client: a call as the page waited for it)`,
      ),
    );
    table(
      ["", "kind", "calls", "errors", "p50", "p95", "max", "total"],
      groups.map((g) => {
        const [where, args]: [string, (string | number)[]] = g.hash
          ? ["hash = ? AND kind = ? AND start >= ?", [g.hash, g.kind, since]]
          : ["hash IS NULL AND kind = ? AND name = ? AND start >= ?", [g.kind, g.name, since]];
        return [
          named(g),
          dim(g.kind),
          String(g.n),
          g.errors ? red(String(g.errors)) : "0",
          shownMs(percentile(where, args, g.n, 0.5)),
          shownMs(percentile(where, args, g.n, 0.95)),
          shownMs(g.max),
          yellow(shownMs(g.total)),
        ];
      }),
    );
    // what runs worse than its version before, and the change that did it: what changed in what it reaches, and the
    // history entry that made it so
    const worse: string[] = [];
    for (const g of groups) {
      const named_ = g.hash ? cb.store.pathsOf(g.hash)[0] : undefined;
      if (!g.hash || !named_) continue;
      const before = db
        .prepare(
          "SELECT hash, max(start) AS last FROM spans WHERE name = ? AND kind = ? AND hash IS NOT NULL AND hash != ? AND start >= ? GROUP BY hash ORDER BY last DESC LIMIT 1",
        )
        .get(g.name, g.kind, g.hash, since) as { hash: string } | undefined;
      if (!before) continue;
      const of = (h: string) => statsOf("hash = ? AND kind = ? AND start >= ?", [h, g.kind, since]);
      const verdict = versionVerdict(of(before.hash), of(g.hash));
      if (!verdict?.worse) continue;
      const v = versionsOf(cb, named_).find((x) => x.hash === g.hash);
      const changed = changesBetween(cb, before.hash, g.hash);
      worse.push(
        `  ${named_} ${dim(g.kind)}  ${red(verdict.said)}${v ? `\n    since ${sinceOf(v)}` : ""}${changed.length ? `\n    changed: ${changed.join(", ")}` : ""}`,
      );
    }
    if (worse.length) {
      console.log(yellow("\nworse than the version before"));
      for (const w of worse) console.log(w);
    }
    return 0;
  } finally {
    db.close();
  }
}

uses

used by