4506aff
@@ -9,6 +9,7 @@
 * bigger.
 */
import { notePhase, takeSessionTime } from "../../core/route_timing.ts";
import { cardPath } from "../og/path.ts";
import { pullProposalOf } from "../../core/proposal_token.ts";
import { getIssueById } from "../../core/issues.ts";
@@ -287,7 +288,7 @@
export const changePage = pullPage;
 * disagree. Bounded the way the page is: `pullWord` and one `pullStatus`, no
 * diff, no query per comment.
 */
async function pullPanels(ctx: Ctx, repo: Repo, pull: Pull) {
async function pullPanels(ctx: Ctx, repo: Repo, pull: Pull, spent: Spent = newSpent()) {
  const record: AppRecord | undefined = getAppByRepo(ctx.app.db, repo.id);
  const db = ctx.app.db;
  const base = repoBase(repo);
@@ -305,7 +306,9 @@
async function pullPanels(ctx: Ctx, repo: Repo, pull: Pull) {
    history: servingHistory(),
    viewer: ctx.auth.user,
  };
  const { word, note: checkNote } = await pullWord(wordCtx, pull);
  const { word, note: checkNote } = await lap(spent, "checks", () =>
    pullWord(wordCtx, pull),
  );
  // Whether this change still merges into its base is asked here, on its own
  // page, and nowhere a list of changes renders — a git call per open pull
  // would undo the home's own bound (`askCandidatesFor`). Only an open,
@@ -314,10 +317,12 @@
async function pullPanels(ctx: Ctx, repo: Repo, pull: Pull) {
  // a change `mergePull` would refuse for want of an approval.
  const status =
    pull.mergedAt === null && pull.state !== "closed"
      ? await pullStatus(wordCtx.dir, pull, {
          db,
          requireReview: repo.requireReview,
        })
      ? await lap(spent, "diff", () =>
          pullStatus(wordCtx.dir, pull, {
            db,
            requireReview: repo.requireReview,
          }),
        )
      : undefined;
  const conflicted =
    status !== undefined && !status.mergeable && status.conflicts.length > 0;
@@ -335,7 +340,9 @@
async function pullPanels(ctx: Ctx, repo: Repo, pull: Pull) {
  // down, and the word above is judged by production regardless.
  let deploy: { id: string; commitOid: string } | undefined;
  if (pull.mergedAt === null) {
    const run = checkSummary(db, pull.id, pull.headOid).run;
    const run = (await lap(spent, "checks", async () =>
      
        junipercrew
        24d ago
        
      
      checkSummary is synchronous; wrapping it in an async lap just to time it adds an await. Time it inline, or give lap a sync twin.
    
      checkSummary(db, pull.id, pull.headOid),
    )).run;
    if (run) deploy = { id: run.id, commitOid: run.commitOid };
  } else {
    const production =
@@ -419,20 +426,28 @@
async function changeConversation(
  repo: Repo,
  pull: Pull,
): Promise<Response> {
  const { request } = ctx;
  const began = performance.now();
  const spent = newSpent();
  notePhase(request, "session", takeSessionTime(request));
  const { record, db, base, thread, wordCtx, word, status, conflicted, note, checkLine, preview } =
    await pullPanels(ctx, repo, pull);
    await pullPanels(ctx, repo, pull, spent);
  // The check's own line, live, with a running check's counts: the one the
  // Files step draws (`pullChecksLineFor`), for an open change.
  const runLine =
    status === undefined
      ? undefined
      : await pullChecksLineFor(ctx, repo, pull, status, wordCtx.dir);
      : await lap(spent, "checks", () =>
          pullChecksLineFor(ctx, repo, pull, status, wordCtx.dir),
        );
  // A change that loosens the policy is a person's call: said here, above
  // the decision, as well as on the Files step beside the merge box.
  const wall =
    status === undefined
      ? undefined
      : await wallOf(wordCtx.dir, status.baseOid, status.headOid);
      : await lap(spent, "diff", () =>
          wallOf(wordCtx.dir, status.baseOid, status.headOid),
        );
  const crewDecision = decisionsFor(ctx, [repo], { evenDismissed: true }).find(
    (d) => d.pull?.id === pull.id,
  );
@@ -559,11 +574,13 @@
async function changeConversation(
  const siblings = variantSiblings(db, [pull])[0] ?? [];
  const glyph = originGlyph(repo);
  const headOid = status?.headOid ?? pull.headOid;
  const reviewsAt = performance.now();
  const reviews = listReviews(db, pull.id);
  const reviewerMarks = marksByName(
    db,
    reviews.map((r) => r.authorName),
  );
  spent.reviews += performance.now() - reviewsAt;
  const talk = conversation(ctx, repo, pull, {
    openVerb: "opened this",
    extra: reviews.map((review) =>
@@ -622,7 +639,7 @@
async function changeConversation(
      head: pull.mergedOid ?? pull.headOid,
    })}`;
  return page({
  const response = page({
    ctx,
    title: `${pull.title} · ${repo.name}`,
    ogImage: cardPath("pull", repo, pull),
@@ -637,4 +654,34 @@
async function changeConversation(
    body,
    scriptJs: `${liveClientJs}\n${liveRegionsJs}`,
  });
  // Each phase is named once, from what the laps added up to; render is what
  // is left of the page's own time, so the phases never exceed `app`.
  const { diff, checks, reviews: reviewMs } = spent;
  notePhase(request, "diff", diff);
  notePhase(request, "checks", checks);
  notePhase(request, "reviews", reviewMs);
  notePhase(
    request,
    "render",
    Math.max(0, performance.now() - began - diff - checks - reviewMs),
  );
  return response;
}
/** Milliseconds a change's page spent in each of its named phases. */
interface Spent {
  diff: number;
  checks: number;
  reviews: number;
}
const newSpent = (): Spent => ({ diff: 0, checks: 0, reviews: 0 });
/** Run `work` and add the time it took to `spent[key]`. */
async function lap<T>(spent: Spent, key: "diff" | "checks", work: () => Promise<T>): Promise<T> {
  const started = performance.now();
  try {
    return await work();
  } finally {
    spent[key] += performance.now() - started;
  }
}
@@ -0,0 +1,89 @@
/** `/:owner/:name/pulls/:n`'s Server-Timing names its phases (#3192). */
import { afterAll, beforeAll, expect, test } from "bun:test";
import { mkdtemp, rm } from "node:fs/promises";
import { tmpdir } from "node:os";
import { join } from "node:path";
import { createApp, type App } from "../src/app.ts";
import { openPull } from "../src/actions/pulls.ts";
import { commitToBranch, createRepo } from "../src/actions/repos.ts";
import { createRun } from "../src/core/runs.ts";
import { createSession } from "../src/core/sessions.ts";
import { createUser } from "../src/core/users.ts";
import { serve, type Servers } from "../src/http/server.ts";
import { quietLogs } from "./helpers/globals.ts";
quietLogs();
let dataDir: string;
let app: App;
let servers: Servers;
let cookie = "";
let number = 0;
const cells = process.env["FORGE_CELLS"];
beforeAll(async () => {
  process.env["FORGE_CELLS"] = "off";
  dataDir = await mkdtemp(join(tmpdir(), "forge-pull-timing-"));
  app = createApp({ dataDir, port: 0 });
  servers = await serve(app);
  const made = await createUser(app.db, {
    origin: "seed",
    trusted: true,
    username: "alice",
    email: "[email protected]",
    password: "a-good-passphrase",
    adminIfFirst: true,
  });
  if (!made.ok) throw new Error(String(made.error));
  const alice = made.value;
  cookie = `forge_session=${createSession(app.db, alice.id).token}`;
  const repo = await createRepo(app, alice, { name: "r", visibility: "public" });
  if (!repo.ok) throw new Error(String(repo.error));
  for (const [branch, file] of [[undefined, "forge.json"], ["topic", "t.txt"]] as const) {
    const done = await commitToBranch(app, alice, repo.value, {
      ...(branch === undefined ? {} : { branch }),
      message: "change",
      files: [{ path: file, content: file === "forge.json" ? "{}" : "x" }],
    });
    if (!done.ok) throw new Error(JSON.stringify(done.error));
  }
  const pull = await openPull(app, alice, repo.value, {
    title: "t",
    body: "",
    baseBranch: "main",
    headBranch: "topic",
  });
  if (!pull.ok) throw new Error(JSON.stringify(pull.error));
  number = pull.value.number;
  createRun(app.db, {
    repoId: repo.value.id,
    kind: "check",
    issueId: pull.value.id,
    env: `pull-${number}`,
    commitOid: pull.value.headOid,
  });
});
afterAll(async () => {
  await servers.stop();
  app.close();
  if (cells === undefined) delete process.env["FORGE_CELLS"];
  else process.env["FORGE_CELLS"] = cells;
  await rm(dataDir, { recursive: true, force: true });
});
test("a pull names session, diff, checks, reviews and render after app, summing to no more than app", async () => {
  const res = await fetch(`${servers.url}/alice/r/pulls/${number}`, { headers: { cookie } });
  expect(res.status).toBe(200);
  await res.arrayBuffer();
  const parts = (res.headers.get("server-timing") ?? "").split(", ");
  const names = parts.map((p) => p.split(";")[0]!);
  const after = names.slice(names.indexOf("app") + 1);
  expect(after).toEqual(["session", "diff", "checks", "reviews", "render"]);
  const ms = (n: string) => Number(parts[names.indexOf(n)]!.match(/dur=([\d.]+)/)![1]);
  const sum = after.reduce((t, n) => t + ms(n), 0);
  // Each is rounded to 0.1 ms, so allow one step per phase.
  expect(sum).toBeLessThanOrEqual(ms("app") + 0.1 * after.length);
  expect(ms("diff")).toBeGreaterThan(0);
  expect(ms("checks")).toBeGreaterThan(0);
      
        junipercrew
        24d ago
        
      
      toBeGreaterThan(0) on a sub-millisecond phase can flake on a fast box. Prefer asserting the names, their order and the sum bound.
    
});
		@@ -9,6 +9,7 @@
9	9	* bigger.
10	10	*/
11	11
	12	import { notePhase, takeSessionTime } from "../../core/route_timing.ts";
12	13	import { cardPath } from "../og/path.ts";
13	14	import { pullProposalOf } from "../../core/proposal_token.ts";
14	15	import { getIssueById } from "../../core/issues.ts";
		@@ -287,7 +288,7 @@ export const changePage = pullPage;
287	288	* disagree. Bounded the way the page is: `pullWord` and one `pullStatus`, no
288	289	* diff, no query per comment.
289	290	*/
290		async function pullPanels(ctx: Ctx, repo: Repo, pull: Pull) {
	291	async function pullPanels(ctx: Ctx, repo: Repo, pull: Pull, spent: Spent = newSpent()) {
291	292	const record: AppRecord \| undefined = getAppByRepo(ctx.app.db, repo.id);
292	293	const db = ctx.app.db;
293	294	const base = repoBase(repo);
		@@ -305,7 +306,9 @@ async function pullPanels(ctx: Ctx, repo: Repo, pull: Pull) {
305	306	history: servingHistory(),
306	307	viewer: ctx.auth.user,
307	308	};
308		const { word, note: checkNote } = await pullWord(wordCtx, pull);
	309	const { word, note: checkNote } = await lap(spent, "checks", () =>
	310	pullWord(wordCtx, pull),
	311	);
309	312	// Whether this change still merges into its base is asked here, on its own
310	313	// page, and nowhere a list of changes renders — a git call per open pull
311	314	// would undo the home's own bound (`askCandidatesFor`). Only an open,
		@@ -314,10 +317,12 @@ async function pullPanels(ctx: Ctx, repo: Repo, pull: Pull) {
314	317	// a change `mergePull` would refuse for want of an approval.
315	318	const status =
316	319	pull.mergedAt === null && pull.state !== "closed"
317		? await pullStatus(wordCtx.dir, pull, {
318		db,
319		requireReview: repo.requireReview,
320		})
	320	? await lap(spent, "diff", () =>
	321	pullStatus(wordCtx.dir, pull, {
	322	db,
	323	requireReview: repo.requireReview,
	324	}),
	325	)
321	326	: undefined;
322	327	const conflicted =
323	328	status !== undefined && !status.mergeable && status.conflicts.length > 0;
		@@ -335,7 +340,9 @@ async function pullPanels(ctx: Ctx, repo: Repo, pull: Pull) {
335	340	// down, and the word above is judged by production regardless.
336	341	let deploy: { id: string; commitOid: string } \| undefined;
337	342	if (pull.mergedAt === null) {
338		const run = checkSummary(db, pull.id, pull.headOid).run;
	343	const run = (await lap(spent, "checks", async () =>
		junipercrew 24d ago checkSummary is synchronous; wrapping it in an async lap just to time it adds an await. Time it inline, or give lap a sync twin.
	344	checkSummary(db, pull.id, pull.headOid),
	345	)).run;
339	346	if (run) deploy = { id: run.id, commitOid: run.commitOid };
340	347	} else {
341	348	const production =
		@@ -419,20 +426,28 @@ async function changeConversation(
419	426	repo: Repo,
420	427	pull: Pull,
421	428	): Promise<Response> {
	429	const { request } = ctx;
	430	const began = performance.now();
	431	const spent = newSpent();
	432	notePhase(request, "session", takeSessionTime(request));
422	433	const { record, db, base, thread, wordCtx, word, status, conflicted, note, checkLine, preview } =
423		await pullPanels(ctx, repo, pull);
	434	await pullPanels(ctx, repo, pull, spent);
424	435	// The check's own line, live, with a running check's counts: the one the
425	436	// Files step draws (`pullChecksLineFor`), for an open change.
426	437	const runLine =
427	438	status === undefined
428	439	? undefined
429		: await pullChecksLineFor(ctx, repo, pull, status, wordCtx.dir);
	440	: await lap(spent, "checks", () =>
	441	pullChecksLineFor(ctx, repo, pull, status, wordCtx.dir),
	442	);
430	443	// A change that loosens the policy is a person's call: said here, above
431	444	// the decision, as well as on the Files step beside the merge box.
432	445	const wall =
433	446	status === undefined
434	447	? undefined
435		: await wallOf(wordCtx.dir, status.baseOid, status.headOid);
	448	: await lap(spent, "diff", () =>
	449	wallOf(wordCtx.dir, status.baseOid, status.headOid),
	450	);
436	451	const crewDecision = decisionsFor(ctx, [repo], { evenDismissed: true }).find(
437	452	(d) => d.pull?.id === pull.id,
438	453	);
		@@ -559,11 +574,13 @@ async function changeConversation(
559	574	const siblings = variantSiblings(db, [pull])[0] ?? [];
560	575	const glyph = originGlyph(repo);
561	576	const headOid = status?.headOid ?? pull.headOid;
	577	const reviewsAt = performance.now();
562	578	const reviews = listReviews(db, pull.id);
563	579	const reviewerMarks = marksByName(
564	580	db,
565	581	reviews.map((r) => r.authorName),
566	582	);
	583	spent.reviews += performance.now() - reviewsAt;
567	584	const talk = conversation(ctx, repo, pull, {
568	585	openVerb: "opened this",
569	586	extra: reviews.map((review) =>
		@@ -622,7 +639,7 @@ async function changeConversation(
622	639	head: pull.mergedOid ?? pull.headOid,
623	640	})}`;
624	641
625		return page({
	642	const response = page({
626	643	ctx,
627	644	title: `${pull.title} · ${repo.name}`,
628	645	ogImage: cardPath("pull", repo, pull),
		@@ -637,4 +654,34 @@ async function changeConversation(
637	654	body,
638	655	scriptJs: `${liveClientJs}\n${liveRegionsJs}`,
639	656	});
	657	// Each phase is named once, from what the laps added up to; render is what
	658	// is left of the page's own time, so the phases never exceed `app`.
	659	const { diff, checks, reviews: reviewMs } = spent;
	660	notePhase(request, "diff", diff);
	661	notePhase(request, "checks", checks);
	662	notePhase(request, "reviews", reviewMs);
	663	notePhase(
	664	request,
	665	"render",
	666	Math.max(0, performance.now() - began - diff - checks - reviewMs),
	667	);
	668	return response;
	669	}
	670
	671	/** Milliseconds a change's page spent in each of its named phases. */
	672	interface Spent {
	673	diff: number;
	674	checks: number;
	675	reviews: number;
	676	}
	677	const newSpent = (): Spent => ({ diff: 0, checks: 0, reviews: 0 });
	678
	679	/** Run `work` and add the time it took to `spent[key]`. */
	680	async function lap<T>(spent: Spent, key: "diff" \| "checks", work: () => Promise<T>): Promise<T> {
	681	const started = performance.now();
	682	try {
	683	return await work();
	684	} finally {
	685	spent[key] += performance.now() - started;
	686	}
640	687	}
		@@ -0,0 +1,89 @@
	1	/** `/:owner/:name/pulls/:n`'s Server-Timing names its phases (#3192). */
	2	import { afterAll, beforeAll, expect, test } from "bun:test";
	3	import { mkdtemp, rm } from "node:fs/promises";
	4	import { tmpdir } from "node:os";
	5	import { join } from "node:path";
	6	import { createApp, type App } from "../src/app.ts";
	7	import { openPull } from "../src/actions/pulls.ts";
	8	import { commitToBranch, createRepo } from "../src/actions/repos.ts";
	9	import { createRun } from "../src/core/runs.ts";
	10	import { createSession } from "../src/core/sessions.ts";
	11	import { createUser } from "../src/core/users.ts";
	12	import { serve, type Servers } from "../src/http/server.ts";
	13	import { quietLogs } from "./helpers/globals.ts";
	14
	15	quietLogs();
	16
	17	let dataDir: string;
	18	let app: App;
	19	let servers: Servers;
	20	let cookie = "";
	21	let number = 0;
	22	const cells = process.env["FORGE_CELLS"];
	23
	24	beforeAll(async () => {
	25	process.env["FORGE_CELLS"] = "off";
	26	dataDir = await mkdtemp(join(tmpdir(), "forge-pull-timing-"));
	27	app = createApp({ dataDir, port: 0 });
	28	servers = await serve(app);
	29	const made = await createUser(app.db, {
	30	origin: "seed",
	31	trusted: true,
	32	username: "alice",
	33	email: "[email protected]",
	34	password: "a-good-passphrase",
	35	adminIfFirst: true,
	36	});
	37	if (!made.ok) throw new Error(String(made.error));
	38	const alice = made.value;
	39	cookie = `forge_session=${createSession(app.db, alice.id).token}`;
	40	const repo = await createRepo(app, alice, { name: "r", visibility: "public" });
	41	if (!repo.ok) throw new Error(String(repo.error));
	42	for (const [branch, file] of [[undefined, "forge.json"], ["topic", "t.txt"]] as const) {
	43	const done = await commitToBranch(app, alice, repo.value, {
	44	...(branch === undefined ? {} : { branch }),
	45	message: "change",
	46	files: [{ path: file, content: file === "forge.json" ? "{}" : "x" }],
	47	});
	48	if (!done.ok) throw new Error(JSON.stringify(done.error));
	49	}
	50	const pull = await openPull(app, alice, repo.value, {
	51	title: "t",
	52	body: "",
	53	baseBranch: "main",
	54	headBranch: "topic",
	55	});
	56	if (!pull.ok) throw new Error(JSON.stringify(pull.error));
	57	number = pull.value.number;
	58	createRun(app.db, {
	59	repoId: repo.value.id,
	60	kind: "check",
	61	issueId: pull.value.id,
	62	env: `pull-${number}`,
	63	commitOid: pull.value.headOid,
	64	});
	65	});
	66
	67	afterAll(async () => {
	68	await servers.stop();
	69	app.close();
	70	if (cells === undefined) delete process.env["FORGE_CELLS"];
	71	else process.env["FORGE_CELLS"] = cells;
	72	await rm(dataDir, { recursive: true, force: true });
	73	});
	74
	75	test("a pull names session, diff, checks, reviews and render after app, summing to no more than app", async () => {
	76	const res = await fetch(`${servers.url}/alice/r/pulls/${number}`, { headers: { cookie } });
	77	expect(res.status).toBe(200);
	78	await res.arrayBuffer();
	79	const parts = (res.headers.get("server-timing") ?? "").split(", ");
	80	const names = parts.map((p) => p.split(";")[0]!);
	81	const after = names.slice(names.indexOf("app") + 1);
	82	expect(after).toEqual(["session", "diff", "checks", "reviews", "render"]);
	83	const ms = (n: string) => Number(parts[names.indexOf(n)]!.match(/dur=([\d.]+)/)![1]);
	84	const sum = after.reduce((t, n) => t + ms(n), 0);
	85	// Each is rounded to 0.1 ms, so allow one step per phase.
	86	expect(sum).toBeLessThanOrEqual(ms("app") + 0.1 * after.length);
	87	expect(ms("diff")).toBeGreaterThan(0);
	88	expect(ms("checks")).toBeGreaterThan(0);
		junipercrew 24d ago toBeGreaterThan(0) on a sub-millisecond phase can flake on a fast box. Prefer asserting the names, their order and the sum bound.
	89	});