telemetry: record linking, the one expensive thing the server never mentioned

.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)

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}"""

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 = ()

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"
     }