werkator/docs/prs/2026-09-15-PR#70-where-the-time-went.md

WARNING: This document describes only the change applied in this PR. It may already be outdated once the next PR is merged. Historic PR-documentation is not maintained along with new PRs — treat it as a snapshot, not as current documentation.

Related Links

• Plan step 14 — the step this PR implements.
• PR#67 — processor time per build, the measurement this one completes.

The Problem

A build's duration says how long it took and nothing about where the time went.

That was tolerable while the only thing between the commit and the build command was a checkout. It is not tolerable now: a build prepares a worktree, may build a container image or unpack a sandbox rootfs, waits for a free slot, and stores its artifacts afterwards. Every one of those can grow without anyone touching a build command, and when one does, the only thing that shows is that builds got slower.

This has already happened and cost weeks. The legacy measurements of 2026-08-10 on vm2176 found about two minutes per build before Gradle even started — 58 seconds waiting for the build lock, 57 more before the Docker cache volume was ready. Every suspect along that path was measured afterwards and was cheap; the two minutes stayed unattributed, because the orchestration kept no record of its own phases and the only evidence left was journal timestamps and file mtimes.

Two builds taking three minutes each are a different problem depending on whether the build command took 2:55 or 1:00, and until now Werkator could not tell the two apart.

Non-Goals

• No historical series and no alerting over the phases: a per-build breakdown plus a warning in the journal is what step 14 asks for, and the duration trend on the History page already watches the totals.
• No second number per row in the build tables. The overhead is a per-build question, asked when one build looks wrong; the tables answer "how long did this take", and a second figure in every row buys little against the clutter. This follows how the processor time of PR#67 was placed: measured for every build, shown on the build's own page.
• Nothing is stopped, failed or throttled by the budget. It is a measurement that says its own name, not a policy.
• The ownership repair after a Docker build (step 14, item 3) is not part of this PR — see Follow-up PRs.

The Scenarios

Feature: a build says where its time went

Background

• A phase is one measured stretch of a build's life: queue, workspace, prepare, clean, build, archive.
• The overhead is what the orchestration itself is answerable for: workspace, prepare and archive. clean and build are the repository's own commands. queue is measured but not counted as overhead — a build waiting for a slot on a host that runs one build at a time is the machine doing what it was configured to do, and a warning on it would fire on every second build without naming anything anyone could fix.
• A phase entered twice — the preparation before the clean command and before the build command — keeps the first start and adds up the time, exactly as the two commands' seconds add up to the build's duration.

Scenario#70.01: A build records its phases

So that the question "where did the non-build time go" is answered by the build itself and not by shell access to the host.

• Given a build with a clean command and a build command
• When it finishes
• Then its stored result carries the phases queue, workspace, prepare, clean, build and archive, in the order they occurred
  • and archive is among them, although it happens after the terminal status is written

Verified by

• BuildExecutorTest — a build records where its time went, phase by phase

Scenario#70.02: The build phase measures the command, not the build

So that the split between the build and its orchestration is the split the figures show.

• Given a build whose build command takes a second
• When it finishes
• Then the build phase is about that second
  • and the workspace phase is nothing like it

Verified by

• BuildExecutorTest — the build phase measures the command, not the build

Scenario#70.03: Overhead beyond the budget says so and names the phase

So that a regression in Werkator's own cost becomes a finding instead of a slow build.

• Given a host with executor.overheadBudget: 1s
  • and a build whose worktree preparation takes longer than that
• When the build finishes
• Then the journal carries a warning naming what the build spent outside its own commands
  • and it names workspace as the slowest of those phases

Verified by

• BuildExecutorTest — a build over the overhead budget says so and names the slowest phase

Scenario#70.04: A build inside the budget stays quiet

So that the warning keeps meaning something.

• Given a host with the default budget
• When an ordinary build finishes
• Then nothing is written about its overhead

Verified by

• BuildExecutorTest — a build inside the overhead budget says nothing

Scenario#70.05: Phases survive the stored result

So that the breakdown is still there when the page is opened tomorrow.

• Given a result with phases, one of them shorter than a second
• When it is written and read back
• Then every phase comes back with its name, its start and its duration, the sub-second one included

Verified by

• FileBuildResultRepositoryTest — round-trips the phase timings of a build

Scenario#70.06: A build from before this measurement reads as one without phases

So that an existing history stays readable and nothing invents figures it never had.

• Given a result stored before phases were measured
• When it is read back
• Then it carries no phases, and the page shows none

Verified by

• FileBuildResultRepositoryTest — a result written before phases were measured reloads with none

Scenario#70.07: A short phase is shown as a figure, not as a zero

So that the phases this display exists for are the ones it can show.

• Given a phase of 340 milliseconds
• When it is displayed
• Then it reads 0.3s, and only from ten seconds on does it read m:ss

Verified by

• UiViewsTest — phase durations keep a decimal below ten seconds

Scenario#70.08: The artifact page shows the breakdown

So that the acceptance criterion of step 14 holds: the question is answered without shell access to the host.

• Given a build whose result carries phases
• When its artifact page is opened
• Then the page lists every phase with its duration
  • and marks the ones the orchestration itself is answerable for

Verified by

• UiControllerTest — the artifact page says where the build spent its time

The Solution

BuildResult carries a list of BuildPhase (name, start, duration). The executor records them as it goes: the queue wait the moment the build leaves the queue, the worktree preparation around BranchWorkspaces.prepare, everything the build runtime does before the command's own process exists as prepare, each command as its own phase, and the artifact persist as archive.

Two details are deliberate.

The prepare phase is measured around BuildRunner.start rather than inside the runners. That is what makes it the same figure for all three runtimes: whatever the native, Docker or werkdock runner has to do before it can hand back a process — building an image, chowning a cache volume, unpacking a rootfs — is time the build command has not started yet.

The archive phase forces one extra write. The terminal status has to be stored before the artifacts (the ordering invariant in BuildExecutor.execute), so the phase list is complete only afterwards; the executor then updates the stored result once more, without an event and without a Gitea status, because nothing about the build changed — the record of it merely got its last figure. Everything measured before is written with the status transitions, so a build that crashes still says how far it got.

executor.overheadBudget (default 30s, empty disables) is checked once at the end: if workspace + prepare + archive exceed it, one warning names the total and the slowest of the three. It is an instance-level key like the rest of executor, and executor is stripped from a branch layer — a branch cannot raise its own budget any more than it can raise its timeout.

The artifact page shows the phases beside the duration, with the orchestration's own phases underlined; GET /api/builds/… carries them in milliseconds, because the phases worth exposing are the short ones and whole seconds would round prepare away.

Additional Changes

• Three items of plan step 14 turned out to be done or gone in the rewrite, and the step file now says so:
  • the repository-size metric already excludes artifacts, worktrees and build environments — RFC 0002 made each of them its own category of the breakdown;
  • nothing rewrites static assets per build state, because the UI is server-rendered from templates;
  • the Gitea status is published before the checkout and takes 17 ms, so it is not on the critical path in any way that matters — and if that ever changes, this PR is what will show it.
• docs/plan/README.md marks steps 17, 21 and 23 as done; all three were merged long ago and only their checkboxes were left behind.

Follow-up PRs

• Ownership repair after a Docker build (step 14, item 3): the repair still covers build and .gradle only — the very whitelist the legacy script had, which is why root-owned files under buildSrc/build/ survived it. It is a Docker-only concern, so it affects vm4006 and needs a container test of its own.
• Whether any phase deserves a series of its own, once there is a month of phase data to look at. Step 14 says no for now, and the duration trend already watches the totals.