From 8664da91ebe5eecfe2d1cd15f102681f7c23b27b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=98yvind=20Raddum=20Berg?= Date: Sun, 2 Aug 2026 16:03:28 +0200 Subject: [PATCH] telemetry: record linking, the one expensive thing the server never mentioned MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A compile has compile_start/compile_end, a forked test JVM has five events joined on pid, and a link had nothing. That is the operation which forks a whole toolchain — for Scala Native, NIR -> LLVM IR -> clang -> executable — and #603 already charges it a cost against the machine governor. So it was accounted for and then invisible, and "why was this build slow" could not be answered for any build that links. link_start/link_end carry project, workspace, platform, release_mode, is_test and the usual duration/success. `release_mode` is there because it is the field that predicts the number: the same project linked Debug and linked ReleaseFast differ by a large factor, and a total with both mixed in explains nothing. `platform` for the same reason across the four toolchains. Emitted through one `withLinkMetrics` helper rather than the same guaranteeCase block copied into both link handlers. `guaranteeCase`, not `flatMap`, for the reason the compile path uses it: a link that is cancelled or throws must still emit its end event, or the start is left dangling and the duration is unknowable — the bug shape fork_end exists to close. Both readers are updated in the same commit, deliberately. #630 was the fix for these two having drifted apart, and the dashboard silently dropping six of twenty event types via `case _ => ()` is what that drift looked like: - server-metrics gains a Linking card, red when a link failed. - The CI summariser groups by platform and mode, so a Scala Native release link and a Scala.js debug link are not summed into one meaningless total. Scope worth stating: this instruments the SERVER's link path, which is what a real build uses. It does not measure the linking inside bleep-bsp-tests, where the suites drive the bridges directly in a forked test JVM — that cost is already visible per suite via suite_finished, which is how it was measured when those suites were tagged `slow`. Verified against synthetic events: the summariser reports `3 links (1 failed), total 1.8m` split into `Scala Native release 1.5m` / `Scala Native 14.0s` / `Scala.js 3.0s`, and the dashboard renders `Linking — 3 links, 107.0s, 1 release-mode, 1 failed`. Co-Authored-By: Claude Opus 5 (1M context) --- .github/scripts/summarise-bsp-metrics.py | 15 +++++++ .../src/scala/bleep/bsp/BspMetrics.scala | 31 +++++++++++++ .../bleep/bsp/MultiWorkspaceBspServer.scala | 43 ++++++++++++++++++- .../scala/bleep/commands/ServerMetrics.scala | 19 ++++++++ 4 files changed, 106 insertions(+), 2 deletions(-) diff --git a/.github/scripts/summarise-bsp-metrics.py b/.github/scripts/summarise-bsp-metrics.py index ac4edebc8..6f42b2604 100755 --- a/.github/scripts/summarise-bsp-metrics.py +++ b/.github/scripts/summarise-bsp-metrics.py @@ -58,6 +58,21 @@ def summarise(path: pathlib.Path, rows: list[dict]) -> None: for r in worst: print(f" {fmt_ms(r.get('duration_ms', 0)):>8} {r.get('project', '?')}") + links = [r for r in rows if r.get("type") == "link_end"] + if links: + total = sum(r.get("duration_ms", 0) for r in links) + failed = sum(1 for r in links if not r.get("success", True)) + print(f"\n links: {len(links)} ({failed} failed), total {fmt_ms(total)}") + # Grouped by platform and mode rather than listed flat: a Scala Native release link and a Scala.js debug link are + # different work by a large factor, and a single total with both in it explains nothing. + per = defaultdict(lambda: [0, 0]) + for r in links: + key = f"{r.get('platform', '?')}{' release' if r.get('release_mode') else ''}" + per[key][0] += 1 + per[key][1] += r.get("duration_ms", 0) + for key, (n, ms) in sorted(per.items(), key=lambda kv: -kv[1][1]): + print(f" {fmt_ms(ms):>8} {key} ({n})") + allocs = [r for r in rows if r.get("type") == "compile_allocation"] if allocs: per = defaultdict(int) diff --git a/bleep-bsp/src/scala/bleep/bsp/BspMetrics.scala b/bleep-bsp/src/scala/bleep/bsp/BspMetrics.scala index 0156e1d5c..5aa5d5997 100644 --- a/bleep-bsp/src/scala/bleep/bsp/BspMetrics.scala +++ b/bleep-bsp/src/scala/bleep/bsp/BspMetrics.scala @@ -317,6 +317,37 @@ object BspMetrics { def recordSourcegenEnd(scriptName: String, durationMs: Long, success: Boolean): Unit = writeEvent(s"""{"type":"sourcegen_end","ts":${now()},"script":"${esc(scriptName)}","duration_ms":$durationMs,"success":$success}""") + /** Linking a non-JVM target: Scala.js, Scala Native, Kotlin/JS, Kotlin/Native. + * + * Recorded because it was the one expensive thing the server did and never mentioned. A compile has `compile_start` / `compile_end`, a forked JVM has five + * events, and a link — which forks a whole linker toolchain, and for Scala Native means NIR -> LLVM IR -> clang -> executable — had none. It was charged a + * cost by the governor and then vanished, so "why was this build slow" could not be answered for any build that links. + * + * `release_mode` is here because it is the field that predicts the number: the same project linked Debug and linked ReleaseFast are different work by a + * large factor, and without it a slow link and a fast one are one population. `platform` for the same reason across toolchains. + */ + def recordLinkStart(project: String, workspace: String, platform: String, releaseMode: Boolean, isTest: Boolean): Unit = + writeEvent( + s"""{"type":"link_start","ts":${now()},"project":"${esc(project)}","workspace":"${esc(workspace)}","platform":"${esc( + platform + )}","release_mode":$releaseMode,"is_test":$isTest}""" + ) + + def recordLinkEnd( + project: String, + workspace: String, + platform: String, + releaseMode: Boolean, + isTest: Boolean, + durationMs: Long, + success: Boolean + ): Unit = + writeEvent( + s"""{"type":"link_end","ts":${now()},"project":"${esc(project)}","workspace":"${esc(workspace)}","platform":"${esc( + platform + )}","release_mode":$releaseMode,"is_test":$isTest,"duration_ms":$durationMs,"success":$success}""" + ) + def recordCompilePhase(project: String, phase: String, trackedApis: Int): Unit = writeEvent( s"""{"type":"compile_phase","ts":${now()},"project":"${esc(project)}","phase":"${esc(phase)}","tracked_apis":$trackedApis}""" diff --git a/bleep-bsp/src/scala/bleep/bsp/MultiWorkspaceBspServer.scala b/bleep-bsp/src/scala/bleep/bsp/MultiWorkspaceBspServer.scala index a04e1625c..8ca7582b1 100644 --- a/bleep-bsp/src/scala/bleep/bsp/MultiWorkspaceBspServer.scala +++ b/bleep-bsp/src/scala/bleep/bsp/MultiWorkspaceBspServer.scala @@ -1696,7 +1696,9 @@ class MultiWorkspaceBspServer( val classpath = projectPaths.classes :: resolved.classpath.map(p => Path.of(p.toString)).toList val linkLogger = createLinkLogger() val outputDir = projectPaths.targetDir.resolve("link-output") - LinkExecutor.execute(linkTask, classpath.map(_.toAbsolutePath), project.platform.flatMap(_.mainClass), outputDir, linkLogger, taskKillSignal) + withLinkMetrics(linkTask, started.buildPaths.buildDir.toString) { + LinkExecutor.execute(linkTask, classpath.map(_.toAbsolutePath), project.platform.flatMap(_.mainClass), outputDir, linkLogger, taskKillSignal) + } } // No-op handlers for task types absent from compile/link DAGs (no DiscoverTasks, TestSuiteTasks here). @@ -2292,7 +2294,9 @@ class MultiWorkspaceBspServer( val projectPaths = started.projectPaths(linkTask.project) val logger = createLinkLogger() val outputDir = projectPaths.targetDir - LinkExecutor.execute(linkTask, classpath.map(_.toAbsolutePath), None, outputDir, logger, killSignal) + withLinkMetrics(linkTask, started.buildPaths.buildDir.toString) { + LinkExecutor.execute(linkTask, classpath.map(_.toAbsolutePath), None, outputDir, logger, killSignal) + } } val apHandler = makeAnnotationProcessorHandler(started, params.originId, apResults) @@ -3830,6 +3834,41 @@ class MultiWorkspaceBspServer( } /** Send a log message without project scope (for rare error cases only) */ + /** Wraps a link with its telemetry, so the two call sites cannot drift. + * + * Deliberately one helper rather than the same `guaranteeCase` block copied into both link handlers: the compile path already has that shape inline, and + * duplicated telemetry is how you end up with two events that disagree about what counts as success. + * + * `guaranteeCase` rather than `flatMap`, for the same reason the compile path uses it — a link that is cancelled or that throws must still emit its end + * event, or the start event is left dangling and the duration is unknowable. That is the bug shape `fork_end` was added to close for test JVMs. + */ + private def withLinkMetrics(linkTask: TaskDag.LinkTask, workspace: String)( + run: IO[(TaskDag.TaskResult, TaskDag.LinkResult)] + ): IO[(TaskDag.TaskResult, TaskDag.LinkResult)] = { + val project = linkTask.project.value + val platform = linkTask.platform.name.wireValue + val startedAt = System.currentTimeMillis() + + def end(success: Boolean): IO[Unit] = + IO( + BspMetrics.recordLinkEnd( + project, + workspace, + platform, + linkTask.releaseMode, + linkTask.isTest, + System.currentTimeMillis() - startedAt, + success + ) + ) + + IO(BspMetrics.recordLinkStart(project, workspace, platform, linkTask.releaseMode, linkTask.isTest)) >> + run.guaranteeCase { + case cats.effect.Outcome.Succeeded(resultIO) => resultIO.flatMap { case (taskResult, _) => end(taskResult == TaskDag.TaskResult.Success) } + case _ => end(false) + } + } + private def createLinkLogger(): LinkExecutor.LinkLogger = new LinkExecutor.LinkLogger { def trace(message: String): Unit = () def debug(message: String): Unit = () diff --git a/bleep-cli/src/scala/bleep/commands/ServerMetrics.scala b/bleep-cli/src/scala/bleep/commands/ServerMetrics.scala index 12d076096..c8009518a 100644 --- a/bleep-cli/src/scala/bleep/commands/ServerMetrics.scala +++ b/bleep-cli/src/scala/bleep/commands/ServerMetrics.scala @@ -97,6 +97,9 @@ case class ServerMetrics(logger: Logger, userPaths: UserPaths, pid: Option[Long] val forkEnd: ArrayBuffer[JsonObject] = ArrayBuffer.empty val suiteScheduled: ArrayBuffer[JsonObject] = ArrayBuffer.empty val suiteFinished: ArrayBuffer[JsonObject] = ArrayBuffer.empty + // Non-JVM linking. The server forks a whole linker toolchain here — for Scala Native, clang — and used to say nothing about it at all. + val linkStart: ArrayBuffer[JsonObject] = ArrayBuffer.empty + val linkEnd: ArrayBuffer[JsonObject] = ArrayBuffer.empty } private def parseMetrics(path: Path): Events = { @@ -134,6 +137,8 @@ case class ServerMetrics(logger: Logger, userPaths: UserPaths, pid: Option[Long] case "fork_end" => events.forkEnd += obj case "suite_scheduled" => events.suiteScheduled += obj case "suite_finished" => events.suiteFinished += obj + case "link_start" => events.linkStart += obj + case "link_end" => events.linkEnd += obj // compile_phase is deliberately not charted: it fires per phase per project and says more about zinc's internals than about this build. case _ => () } @@ -168,6 +173,8 @@ case class ServerMetrics(logger: Logger, userPaths: UserPaths, pid: Option[Long] events.forkEnd.foreach(collectTs) events.suiteScheduled.foreach(collectTs) events.suiteFinished.foreach(collectTs) + events.linkStart.foreach(collectTs) + events.linkEnd.foreach(collectTs) val t0 = if (allTs.isEmpty) 0L else allTs.min def relS(tsMs: Long): Double = (tsMs - t0) / 1000.0 @@ -570,6 +577,18 @@ case class ServerMetrics(logger: Logger, userPaths: UserPaths, pid: Option[Long] cards += stat("Suites run", s"${events.suiteFinished.size}" + (if (failed > 0) s" ($failed not ok)" else ""), if (failed > 0) "#ef4444" else "#22c55e") } + if (events.linkEnd.nonEmpty) { + val totalMs = events.linkEnd.map(_.get("duration_ms").getAsLong).sum + val failed = events.linkEnd.count(e => !e.get("success").getAsBoolean) + // Release mode is called out because it is the difference between a link that takes seconds and one that takes + // minutes, and a total with both mixed in explains nothing. + val release = events.linkEnd.count(e => e.has("release_mode") && e.get("release_mode").getAsBoolean) + val detail = f"${events.linkEnd.size} links, ${totalMs / 1000.0}%.1fs" + + (if (release > 0) s", $release release-mode" else "") + + (if (failed > 0) s", $failed failed" else "") + cards += stat("Linking", detail, if (failed > 0) "#ef4444" else "#a855f7") + } + if (cards.isEmpty) "" else cards.mkString("\n") + "\n" }