Separate queue wait from build duration

BuildResult gains runningSince, set when a build leaves the queue; the
recorded duration now measures pure build time from that point, so build
runtimes can be tracked without queue wait. A build cancelled while still
queued records neither. The UI shows the live wait time in italics while
pending and switches to the real build time once the build runs; the Gitea
"after mm:ss" descriptions now also report pure build time.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
mhoennig
2026-08-10 15:55:36 +02:00
co-authored by Claude Fable 5
parent a03f85bc17
commit 56aa306481
12 changed files with 112 additions and 17 deletions
@@ -120,6 +120,7 @@ class BuildExecutor(
return return
} }
build.running = true build.running = true
build.runningBuild.runningSince = Instant.now()
transition(build, BuildStatus.RUNNING, duration = null) transition(build, BuildStatus.RUNNING, duration = null)
val preparedWorkspace = val preparedWorkspace =
workspaces.prepare( workspaces.prepare(
@@ -140,7 +141,8 @@ class BuildExecutor(
log.error("build of branch {} crashed", build.runningBuild.branch, e) log.error("build of branch {} crashed", build.runningBuild.branch, e)
appendToLiveLog(build, "\nbuild crashed: ${e.message}\n") appendToLiveLog(build, "\nbuild crashed: ${e.message}\n")
} finally { } finally {
val duration = Duration.between(build.runningBuild.startedAt, Instant.now()) // pure build time, without the queue wait; null when the build never started executing
val duration = build.runningBuild.runningSince?.let { Duration.between(it, Instant.now()) }
val result = transition(build, finalStatus, duration) val result = transition(build, finalStatus, duration)
try { try {
artifactStore.persist(result, build.runningBuild.stagingDir, workspace) artifactStore.persist(result, build.runningBuild.stagingDir, workspace)
@@ -277,12 +279,17 @@ class BuildExecutor(
val runningBuild = build.runningBuild val runningBuild = build.runningBuild
val updated = val updated =
repository.updateByArtifactKey(runningBuild.artifactKey) { repository.updateByArtifactKey(runningBuild.artifactKey) {
it.copy(status = status, duration = duration ?: it.duration) it.copy(
status = status,
runningSince = runningBuild.runningSince ?: it.runningSince,
duration = duration ?: it.duration,
)
} ?: BuildResult( } ?: BuildResult(
branch = runningBuild.branch, branch = runningBuild.branch,
commit = runningBuild.commit, commit = runningBuild.commit,
status = status, status = status,
startedAt = runningBuild.startedAt, startedAt = runningBuild.startedAt,
runningSince = runningBuild.runningSince,
duration = duration, duration = duration,
artifactKey = runningBuild.artifactKey, artifactKey = runningBuild.artifactKey,
).also { repository.append(it) } ).also { repository.append(it) }
@@ -7,7 +7,11 @@ data class BuildResult(
val branch: String, val branch: String,
val commit: String, val commit: String,
val status: BuildStatus, val status: BuildStatus,
/** When the build was accepted (enqueued); the time until [runningSince] is queue wait. */
val startedAt: Instant, val startedAt: Instant,
/** When the build actually started executing; null while queued or when cancelled in the queue. */
val runningSince: Instant? = null,
/** Pure build execution time (from [runningSince]), without the queue wait. */
val duration: Duration? = null, val duration: Duration? = null,
val artifactKey: String, val artifactKey: String,
) )
@@ -13,7 +13,11 @@ data class RunningBuild(
val stagingDir: Path, val stagingDir: Path,
/** Combined stdout+stderr log, written live while the build runs. */ /** Combined stdout+stderr log, written live while the build runs. */
val liveLogFile: Path, val liveLogFile: Path,
) ) {
/** Set by the executor when the build leaves the queue and starts executing. */
@Volatile
var runningSince: Instant? = null
}
/** Published via Spring's `ApplicationEventPublisher` on every persisted status transition. */ /** Published via Spring's `ApplicationEventPublisher` on every persisted status transition. */
data class BuildStatusChangedEvent( data class BuildStatusChangedEvent(
@@ -13,6 +13,8 @@ data class BuildResultDto(
val commit: String, val commit: String,
val status: String, val status: String,
val startedAt: Instant, val startedAt: Instant,
/** When the build left the queue; the UI derives the live build time from this, the wait time from [startedAt]. */
val runningSince: Instant? = null,
val durationSeconds: Long?, val durationSeconds: Long?,
val artifactKey: String, val artifactKey: String,
) { ) {
@@ -23,6 +25,7 @@ data class BuildResultDto(
commit = result.commit, commit = result.commit,
status = result.status.jsonName, status = result.status.jsonName,
startedAt = result.startedAt, startedAt = result.startedAt,
runningSince = result.runningSince,
durationSeconds = result.duration?.seconds, durationSeconds = result.duration?.seconds,
artifactKey = result.artifactKey, artifactKey = result.artifactKey,
) )
@@ -40,6 +43,7 @@ data class BranchDto(
val commit: String, val commit: String,
val status: String, val status: String,
val startedAt: Instant?, val startedAt: Instant?,
val runningSince: Instant? = null,
val durationSeconds: Long?, val durationSeconds: Long?,
val artifactKey: String, val artifactKey: String,
val latestGreenUrl: String? = null, val latestGreenUrl: String? = null,
@@ -65,6 +69,7 @@ data class BranchDto(
commit = latest.commit, commit = latest.commit,
status = latest.status.jsonName, status = latest.status.jsonName,
startedAt = latest.startedAt, startedAt = latest.startedAt,
runningSince = latest.runningSince,
durationSeconds = latest.duration?.seconds, durationSeconds = latest.duration?.seconds,
artifactKey = latest.artifactKey, artifactKey = latest.artifactKey,
latestGreenUrl = if (hasGreenBuild) BranchPermalinks.permanentUrl(branch) else null, latestGreenUrl = if (hasGreenBuild) BranchPermalinks.permanentUrl(branch) else null,
@@ -80,6 +85,7 @@ data class CurrentBuildDto(
val artifactKey: String, val artifactKey: String,
val status: String, val status: String,
val startedAt: Instant, val startedAt: Instant,
val runningSince: Instant? = null,
val logSize: Long, val logSize: Long,
) )
@@ -60,6 +60,7 @@ class BuildsApiController(
(results.firstOrNull { it.artifactKey == build.artifactKey }?.status ?: BuildStatus.RUNNING) (results.firstOrNull { it.artifactKey == build.artifactKey }?.status ?: BuildStatus.RUNNING)
.jsonName, .jsonName,
startedAt = build.startedAt, startedAt = build.startedAt,
runningSince = build.runningSince,
logSize = liveLogSize(build.liveLogFile), logSize = liveLogSize(build.liveLogFile),
) )
} }
@@ -87,6 +87,7 @@ class UiController(
.jsonName, .jsonName,
startedAtIso = build.startedAt.toString(), startedAtIso = build.startedAt.toString(),
startedAt = UiFormats.timestamp(build.startedAt), startedAt = UiFormats.timestamp(build.startedAt),
runningSinceIso = build.runningSince?.toString() ?: "",
artifactKey = build.artifactKey, artifactKey = build.artifactKey,
branchUrl = links.branchUrl(build.branch), branchUrl = links.branchUrl(build.branch),
commitUrl = links.commitUrl(build.commit), commitUrl = links.commitUrl(build.commit),
@@ -75,6 +75,8 @@ data class BuildRowView(
val status: String, val status: String,
val startedAtIso: String, val startedAtIso: String,
val startedAt: String, val startedAt: String,
/** ISO timestamp of the run start for the live build-time ticker; empty while queued. */
val runningSinceIso: String,
val duration: String, val duration: String,
val artifactKey: String, val artifactKey: String,
val branchUrl: String?, val branchUrl: String?,
@@ -94,6 +96,7 @@ data class BuildRowView(
status = result.status.jsonName, status = result.status.jsonName,
startedAtIso = result.startedAt.toString(), startedAtIso = result.startedAt.toString(),
startedAt = UiFormats.timestamp(result.startedAt), startedAt = UiFormats.timestamp(result.startedAt),
runningSinceIso = result.runningSince?.toString() ?: "",
duration = UiFormats.duration(result.duration), duration = UiFormats.duration(result.duration),
artifactKey = result.artifactKey, artifactKey = result.artifactKey,
branchUrl = links.branchUrl(result.branch), branchUrl = links.branchUrl(result.branch),
@@ -112,6 +115,7 @@ data class BuildRowView(
status = entry.status, status = entry.status,
startedAtIso = entry.startedAt?.toString() ?: "", startedAtIso = entry.startedAt?.toString() ?: "",
startedAt = entry.startedAt?.let { UiFormats.timestamp(it) } ?: "", startedAt = entry.startedAt?.let { UiFormats.timestamp(it) } ?: "",
runningSinceIso = entry.runningSince?.toString() ?: "",
duration = UiFormats.duration(entry.durationSeconds?.let { Duration.ofSeconds(it) }), duration = UiFormats.duration(entry.durationSeconds?.let { Duration.ofSeconds(it) }),
artifactKey = entry.artifactKey, artifactKey = entry.artifactKey,
branchUrl = links.branchUrl(entry.branch), branchUrl = links.branchUrl(entry.branch),
@@ -130,6 +134,7 @@ data class CurrentBuildView(
val status: String, val status: String,
val startedAtIso: String, val startedAtIso: String,
val startedAt: String, val startedAt: String,
val runningSinceIso: String,
val artifactKey: String, val artifactKey: String,
val branchUrl: String?, val branchUrl: String?,
val commitUrl: String?, val commitUrl: String?,
+2
View File
@@ -88,6 +88,8 @@ tbody tr:hover { background: color-mix(in srgb, var(--link) 8%, transparent); }
tbody.is-stale { opacity: 0.55; } tbody.is-stale { opacity: 0.55; }
.branch { font-weight: 650; } .branch { font-weight: 650; }
.duration-cell { white-space: nowrap; } .duration-cell { white-space: nowrap; }
/* queue wait time of a pending build — italic to distinguish it from real build time */
.duration-wait { font-style: italic; color: var(--muted); }
.empty { padding: 28px 14px; color: var(--muted); text-align: center; } .empty { padding: 28px 14px; color: var(--muted); text-align: center; }
/* system metrics */ /* system metrics */
+29 -11
View File
@@ -63,15 +63,24 @@ function elapsedSeconds(startedAtIso) {
} }
/** /**
* The duration to display for a build: the recorded duration once finished, the * The duration to display for a build, computed at render time so re-rendered
* live elapsed time while running or pending — so re-rendered rows never show an * rows never show an empty cell that the ticker fills back in (visible flicker):
* empty cell that the once-per-second ticker fills back in (visible flicker). * the recorded build time once finished, the live build time (since the build
* left the queue) while running, and the wait time while pending — the latter
* is styled italic via `duration-wait` to distinguish it from build time.
*/ */
function displayDurationSeconds(build) { function displayDurationSeconds(build) {
if (build.durationSeconds != null) { if (build.status === "running") {
return elapsedSeconds(build.runningSince || build.startedAt);
}
if (build.status === "pending") {
return elapsedSeconds(build.startedAt);
}
return build.durationSeconds; return build.durationSeconds;
} }
return build.status === "running" || build.status === "pending" ? elapsedSeconds(build.startedAt) : null;
function durationCellClass(status) {
return "duration-cell" + (status === "pending" ? " duration-wait" : "");
} }
// ---- shared infrastructure ------------------------------------------------- // ---- shared infrastructure -------------------------------------------------
@@ -197,6 +206,7 @@ function renderBuildRow(build, allowRestart) {
row.dataset.artifactKey = build.artifactKey || ""; row.dataset.artifactKey = build.artifactKey || "";
row.dataset.branch = build.branch; row.dataset.branch = build.branch;
row.dataset.startedAt = build.startedAt || ""; row.dataset.startedAt = build.startedAt || "";
row.dataset.runningSince = build.runningSince || "";
row.dataset.status = build.status || "unknown"; row.dataset.status = build.status || "unknown";
const statusCell = elem("td"); const statusCell = elem("td");
@@ -234,7 +244,7 @@ function renderBuildRow(build, allowRestart) {
startedCell.dataset.label = "Started"; startedCell.dataset.label = "Started";
row.appendChild(startedCell); row.appendChild(startedCell);
const durationCell = elem("td", "duration-cell", formatDuration(displayDurationSeconds(build))); const durationCell = elem("td", durationCellClass(build.status), formatDuration(displayDurationSeconds(build)));
durationCell.dataset.label = "Duration"; durationCell.dataset.label = "Duration";
row.appendChild(durationCell); row.appendChild(durationCell);
@@ -309,6 +319,7 @@ function renderBuildCard(build) {
const card = elem("section", "build-card"); const card = elem("section", "build-card");
card.dataset.artifactKey = build.artifactKey; card.dataset.artifactKey = build.artifactKey;
card.dataset.startedAt = build.startedAt || ""; card.dataset.startedAt = build.startedAt || "";
card.dataset.runningSince = build.runningSince || "";
card.dataset.status = build.status || "running"; card.dataset.status = build.status || "running";
const header = elem("header", "build-card-header"); const header = elem("header", "build-card-header");
@@ -328,7 +339,9 @@ function renderBuildCard(build) {
); );
header.appendChild(commitCode); header.appendChild(commitCode);
header.appendChild(elem("span", "muted", "started " + formatTimestamp(build.startedAt))); header.appendChild(elem("span", "muted", "started " + formatTimestamp(build.startedAt)));
header.appendChild(elem("span", "duration-cell running-duration", formatDuration(displayDurationSeconds(build)))); header.appendChild(
elem("span", durationCellClass(build.status) + " running-duration", formatDuration(displayDurationSeconds(build))),
);
const cardActions = elem("span", "build-card-actions"); const cardActions = elem("span", "build-card-actions");
cardActions.appendChild( cardActions.appendChild(
actionButton("× Cancel", "Cancel build", "cancel-button", { actionButton("× Cancel", "Cancel build", "cancel-button", {
@@ -398,6 +411,7 @@ function initCurrentBuilds() {
card = container.appendChild(renderBuildCard(build)); card = container.appendChild(renderBuildCard(build));
} else { } else {
card.dataset.status = build.status; card.dataset.status = build.status;
card.dataset.runningSince = build.runningSince || card.dataset.runningSince;
const badge = card.querySelector(".status"); const badge = card.querySelector(".status");
badge.className = statusCssClass(build.status); badge.className = statusCssClass(build.status);
badge.textContent = build.status; badge.textContent = build.status;
@@ -453,16 +467,20 @@ function initSystemTable() {
// ---- running-duration ticking ------------------------------------------------ // ---- running-duration ticking ------------------------------------------------
function tickRunningDurations() { function tickRunningDurations() {
const now = Date.now();
document.querySelectorAll("[data-started-at]").forEach((element) => { document.querySelectorAll("[data-started-at]").forEach((element) => {
const status = element.dataset.status; const status = element.dataset.status;
if (status !== "running" && status !== "pending") { if (status !== "running" && status !== "pending") {
return; return;
} }
const startedAt = new Date(element.dataset.startedAt).getTime(); // running: live build time since leaving the queue; pending: wait time (italic)
const basisIso = status === "running"
? (element.dataset.runningSince || element.dataset.startedAt)
: element.dataset.startedAt;
const elapsed = elapsedSeconds(basisIso);
const durationCell = element.querySelector(".duration-cell"); const durationCell = element.querySelector(".duration-cell");
if (durationCell && !Number.isNaN(startedAt)) { if (durationCell && elapsed != null) {
durationCell.textContent = formatDuration((now - startedAt) / 1000); durationCell.textContent = formatDuration(elapsed);
durationCell.classList.toggle("duration-wait", status === "pending");
} }
}); });
} }
+1 -1
View File
@@ -24,7 +24,7 @@
<td class="empty" colspan="7" th:text="${emptyMessage}">No builds recorded yet.</td> <td class="empty" colspan="7" th:text="${emptyMessage}">No builds recorded yet.</td>
</tr> </tr>
<tr th:each="row : ${rows}" <tr th:each="row : ${rows}"
th:attr="data-artifact-key=${row.artifactKey},data-branch=${row.branch},data-started-at=${row.startedAtIso},data-status=${row.status}"> th:attr="data-artifact-key=${row.artifactKey},data-branch=${row.branch},data-started-at=${row.startedAtIso},data-running-since=${row.runningSinceIso},data-status=${row.status}">
<td data-label="Status"> <td data-label="Status">
<span th:class="'status status-' + ${row.status}" th:text="${row.status}">success</span> <span th:class="'status status-' + ${row.status}" th:text="${row.status}">success</span>
</td> </td>
+1 -1
View File
@@ -10,7 +10,7 @@
No build is currently running. No build is currently running.
</p> </p>
<section class="build-card" th:each="build : ${currentBuilds}" <section class="build-card" th:each="build : ${currentBuilds}"
th:attr="data-artifact-key=${build.artifactKey},data-started-at=${build.startedAtIso},data-status=${build.status}"> th:attr="data-artifact-key=${build.artifactKey},data-started-at=${build.startedAtIso},data-running-since=${build.runningSinceIso},data-status=${build.status}">
<header class="build-card-header"> <header class="build-card-header">
<span th:class="'status status-' + ${build.status}" th:text="${build.status}">running</span> <span th:class="'status status-' + ${build.status}" th:text="${build.status}">running</span>
<span class="branch link-tools"> <span class="branch link-tools">
@@ -11,6 +11,8 @@ import io.kotest.matchers.collections.shouldContain
import io.kotest.matchers.collections.shouldContainExactly import io.kotest.matchers.collections.shouldContainExactly
import io.kotest.matchers.collections.shouldContainExactlyInAnyOrder import io.kotest.matchers.collections.shouldContainExactlyInAnyOrder
import io.kotest.matchers.ints.shouldBeGreaterThan import io.kotest.matchers.ints.shouldBeGreaterThan
import io.kotest.matchers.longs.shouldBeGreaterThan
import io.kotest.matchers.longs.shouldBeLessThan
import io.kotest.matchers.nulls.shouldNotBeNull import io.kotest.matchers.nulls.shouldNotBeNull
import io.kotest.matchers.shouldBe import io.kotest.matchers.shouldBe
import io.kotest.matchers.shouldNotBe import io.kotest.matchers.shouldNotBe
@@ -157,6 +159,51 @@ class BuildExecutorTest : FunSpec() {
awaitStatus(h, "main", BuildStatus.CANCELLED) awaitStatus(h, "main", BuildStatus.CANCELLED)
} }
test("the duration measures build time only, not the queue wait") {
// the first build sleeps, the second (queued behind it) finishes instantly
val h = harness("test -f slow-done || { touch slow-done; sleep 2; }")
h.executor.startBuild("main", "abc123", h.workingDir)
val second = h.executor.startBuild("main", "abc124", h.workingDir)
eventually(30.seconds) {
h.repository
.history()
.first { it.artifactKey == second.artifactKey }
.status shouldBe BuildStatus.SUCCESS
}
val result = h.repository.history().first { it.artifactKey == second.artifactKey }
val runningSince = result.runningSince.shouldNotBeNull()
val waitMillis =
java.time.Duration
.between(result.startedAt, runningSince)
.toMillis()
waitMillis shouldBeGreaterThan 1000L
result.duration.shouldNotBeNull().toMillis() shouldBeLessThan waitMillis
}
test("a build cancelled while still queued records neither runningSince nor a duration") {
val h = harness("sleep 30")
val first = h.executor.startBuild("main", "abc123", h.workingDir)
val second = h.executor.startBuild("main", "abc124", h.workingDir)
eventually(30.seconds) {
h.executor.currentBuilds().map { it.artifactKey } shouldContain first.artifactKey
}
h.executor.cancel(second.artifactKey).shouldBeTrue()
h.executor.cancel(first.artifactKey).shouldBeTrue()
eventually(30.seconds) {
h.repository
.history()
.first { it.artifactKey == second.artifactKey }
.status shouldBe BuildStatus.CANCELLED
}
val cancelled = h.repository.history().first { it.artifactKey == second.artifactKey }
cancelled.runningSince shouldBe null
cancelled.duration shouldBe null
}
test("a failing build command records FAILED with a duration") { test("a failing build command records FAILED with a duration") {
val h = harness("exit 3") val h = harness("exit 3")