Env-gated launch timing summary and median bench harness

README.md

@@ -614,6 +614,32 @@ dl blooop/devlaunch stop         # Stop workspace
 - **Fast Autocomplete**: Completion cache for ~3ms response time (vs ~700ms without cache)
 - **One Round-Trip Per Question**: every `devpod` call costs ~0.45s, far more than `dl` itself, so a command reads the workspace list at most once — and `dl <ws> -- <cmd>` skips the extra round-trip that names an interactive prompt, since a one-shot command has none
 
+## Measuring launch time
+
+Set `DEVLAUNCH_TIMING=1` and a `dl` command ends with one summary on stderr,
+naming each subprocess round trip and the total. Unset (or `0`) records nothing
+and prints nothing.
+
+```bash
+$ DEVLAUNCH_TIMING=1 dl myws -- true
+dl-timing: devpod status 0.412s
+dl-timing: devpod ssh 0.583s
+dl-timing: devpod ssh 1.102s
+dl-timing: total 2.201s (in-process, excluding interpreter startup)
+```
+
+For before/after numbers, `scripts/bench_launch.py` runs a command N times and
+reports the median — one command per side of a change:
+
+```bash
+python scripts/bench_launch.py -n 5 -- dl-next owner/repo -- true   # warm launch
+```
+
+(`pixi run bench -n 5 -- ...` in the devcontainer.) It reports no median if any
+run fails, so a broken launch cannot pass as a fast one. See `bench_launch.py
+--help` for `--before` — the per-run reset that makes a *cold* median cold —
+and for why its wall clock and `dl-timing: total` are not the same quantity.
+
 ## Worktree Backend
 
 For git repositories, devlaunch uses an efficient worktree backend by default:

devlaunch/dl.py

@@ -36,7 +36,7 @@
 from urllib.parse import urlparse
 from urllib.request import url2pathname
 
-from . import devpod_ssh, disk_usage, gh_auth, tools, tty_session, workspace_state
+from . import devpod_ssh, disk_usage, gh_auth, timing, tools, tty_session, workspace_state
 from .completion import install_completions
 from .workspace_id import TARGET_LENGTH, WorkspaceId, slug, source_workspace_id, validate_ref_name
 from .worktree.config import get_worktree_config
@@ -1394,13 +1394,14 @@ def _git_ls_remote(owner_repo: str, *args: str) -> Optional[str]:
     """
     url = f"git@github.com:{owner_repo}.git"
     try:
-        result = subprocess.run(
-            ["git", "ls-remote", url, *args],
-            capture_output=True,
-            text=True,
-            check=False,
-            timeout=5,
-        )
+        with timing.span("git ls-remote"):
+            result = subprocess.run(
+                ["git", "ls-remote", url, *args],
+                capture_output=True,
+                text=True,
+                check=False,
+                timeout=5,
+            )
         if result.returncode == 0 and result.stdout.strip():
             return result.stdout
     except (OSError, subprocess.SubprocessError, subprocess.TimeoutExpired):
@@ -1533,13 +1534,16 @@ def run_devpod(
     cmd = ["devpod"] + args
     logging.debug("Running: %s", " ".join(cmd))
     try:
-        if capture:
+        # Timed by subcommand, not full argv: the summary should name each
+        # round trip (status, ssh, up...) without leaking workspace ids into it.
+        with timing.span(" ".join(cmd[:2])):
+            if capture:
+                # nosec B603 - using list form, not shell=True; no command injection risk
+                return subprocess.run(
+                    cmd, capture_output=True, text=True, check=False, env=env, stdin=stdin_file
+                )
             # nosec B603 - using list form, not shell=True; no command injection risk
-            return subprocess.run(
-                cmd, capture_output=True, text=True, check=False, env=env, stdin=stdin_file
-            )
-        # nosec B603 - using list form, not shell=True; no command injection risk
-        return subprocess.run(cmd, check=False, env=env, stdin=stdin_file)
+            return subprocess.run(cmd, check=False, env=env, stdin=stdin_file)
     except FileNotFoundError as e:
         raise DevpodNotInstalled(DEVPOD_MISSING_MESSAGE) from e
 
@@ -1557,22 +1561,25 @@ def run_devpod_session(
     """
     cmd = ["devpod"] + args
     logging.debug("Running: %s", " ".join(cmd))
-    # nosec B603 - using list form, not shell=True; no command injection risk
-    with subprocess.Popen(
-        cmd,
-        stderr=subprocess.PIPE,
-        text=True,
-        encoding="utf-8",
-        errors="replace",
-        env=env,
-    ) as proc:
-        # proc.stderr is a pipe because PIPE was asked for, but Popen's type
-        # cannot express that, so the narrowing happens here rather than by
-        # widening filter_devpod_stderr to a None it would have no answer for.
-        pipe = proc.stderr
-        remote_status = (
-            devpod_ssh.filter_devpod_stderr(pipe, sys.stderr) if pipe is not None else None
-        )
+    # The span covers the whole session: what the summary names is the round
+    # trip the user waited on, not just the process spawn.
+    with timing.span(" ".join(cmd[:2])):
+        # nosec B603 - using list form, not shell=True; no command injection risk
+        with subprocess.Popen(
+            cmd,
+            stderr=subprocess.PIPE,
+            text=True,
+            encoding="utf-8",
+            errors="replace",
+            env=env,
+        ) as proc:
+            # proc.stderr is a pipe because PIPE was asked for, but Popen's type
+            # cannot express that, so the narrowing happens here rather than by
+            # widening filter_devpod_stderr to a None it would have no answer for.
+            pipe = proc.stderr
+            remote_status = (
+                devpod_ssh.filter_devpod_stderr(pipe, sys.stderr) if pipe is not None else None
+            )
     return devpod_ssh.interpret(proc.returncode, remote_status)
 
 
@@ -2019,8 +2026,9 @@ def run_ssh(args: List[str], env: Optional[Dict[str, str]] = None) -> subprocess
     """
     logging.debug("Running: %s", " ".join(args))
     try:
-        # nosec B603 B607 - list form, not shell=True; no command injection risk
-        return subprocess.run(list(args), check=False, env=env)
+        with timing.span("ssh"):
+            # nosec B603 B607 - list form, not shell=True; no command injection risk
+            return subprocess.run(list(args), check=False, env=env)
     except FileNotFoundError as e:
         raise SshNotInstalled(SSH_MISSING_MESSAGE) from e
 
@@ -2361,6 +2369,10 @@ def main(argv: Optional[List[str]] = None) -> int:
     # a caller that drives main() twice (a test, a shell wrapper) must not have
     # the first command's view of devpod answer the second command's questions.
     invalidate_workspace_list_cache()
+    # Timing is per-command, like the workspace-list snapshot: begin() here so
+    # a second main() in the same process starts a fresh summary, emit() in the
+    # finally so the summary lands on stderr however the command ended.
+    timing.begin()
     try:
         return _run_cli(argv)
     except MissingBinary as e:
@@ -2369,6 +2381,8 @@ def main(argv: Optional[List[str]] = None) -> int:
     except UnreadableWorkspaceList as e:
         print(f"error: {e}", file=sys.stderr)
         return UNREADABLE_WORKSPACE_LIST_EXIT_CODE
+    finally:
+        timing.emit()
 
 
 def _run_cli(argv: Optional[List[str]] = None) -> int:

devlaunch/gh_auth.py

@@ -27,6 +27,7 @@
 import tempfile
 from typing import Dict, Iterator, List, Optional, Tuple
 
+from devlaunch import timing
 from devlaunch.xdg import config_home
 
 # The variable set inside the container. gh consults it before its config file.
@@ -64,17 +65,18 @@ def _token_from_gh_cli() -> Optional[str]:
     if not shutil.which("gh"):
         return None
     try:
-        # nosec B603 B607 - list form, not shell=True; no command injection risk
-        result = subprocess.run(
-            ["gh", "auth", "token"],
-            capture_output=True,
-            text=True,
-            check=False,
-            # gh must not eat stdin that belongs to the command `dl` was asked
-            # to run, and must not leave the terminal in a state of its own.
-            stdin=subprocess.DEVNULL,
-            timeout=_GH_TIMEOUT_SECONDS,
-        )
+        with timing.span("gh auth token"):
+            # nosec B603 B607 - list form, not shell=True; no command injection risk
+            result = subprocess.run(
+                ["gh", "auth", "token"],
+                capture_output=True,
+                text=True,
+                check=False,
+                # gh must not eat stdin that belongs to the command `dl` was asked
+                # to run, and must not leave the terminal in a state of its own.
+                stdin=subprocess.DEVNULL,
+                timeout=_GH_TIMEOUT_SECONDS,
+            )
     except (OSError, subprocess.SubprocessError) as e:
         logging.warning(
             "Could not read a GitHub token from gh (%s), so this workspace opens "

devlaunch/timing.py

@@ -0,0 +1,91 @@
+"""Env-gated wall-clock timing for dl's subprocess round trips.
+
+Set ``DEVLAUNCH_TIMING=1`` and every dl process ends with one summary on
+stderr: a ``dl-timing: <label> <seconds>s`` line per recorded subprocess call,
+then a ``total`` for the whole command. Unset (or ``0``) records nothing and
+prints nothing — the hot path must not pay for its own thermometer, so the off
+state is a single ``None`` check. stderr because stdout is parsed by the
+completion machinery, and one summary at the end rather than a line per event,
+so the numbers land after the command's own output, not interleaved with it.
+"""
+
+import contextlib
+import os
+import sys
+import time
+from dataclasses import dataclass, field
+from typing import Iterator, List, Optional, TextIO, Tuple
+
+ENV_VAR = "DEVLAUNCH_TIMING"
+
+# `total` runs from the top of main(), so it is a smaller quantity than the wall
+# time an outside stopwatch (`scripts/bench_launch.py`) reports for the same
+# command: interpreter startup and this package's imports happen before main().
+# The two get quoted side by side, so each line carries its epoch.
+TOTAL_EPOCH = "in-process, excluding interpreter startup"
+
+
+@dataclass
+class _Recorder:
+    """One dl process's records: a start instant and the spans since."""
+
+    started: float
+    entries: List[Tuple[str, float]] = field(default_factory=list)
+
+
+# On/off is this one optional recorder, not a flag plus fields that would have
+# to agree with it: off, there is nothing to hold.
+_recorder: Optional[_Recorder] = None
+
+
+def begin() -> None:
+    """Start recording iff DEVLAUNCH_TIMING asks for it.
+
+    Called once at the top of main(), replacing any recorder left from an
+    earlier main() in the same process, so one command's spans never leak into
+    the next command's summary.
+    """
+    global _recorder  # pylint: disable=global-statement
+    if os.environ.get(ENV_VAR, "").strip() in ("", "0"):
+        _recorder = None
+        return
+    _recorder = _Recorder(started=time.perf_counter())
+
+
+@contextlib.contextmanager
+def _record(recorder: _Recorder, label: str) -> Iterator[None]:
+    """Time the block, recording in ``finally`` and re-raising: a spawn that
+    failed still took time, and dropping it would make the parts add up to
+    less than the total."""
+    start = time.perf_counter()
+    try:
+        yield
+    finally:
+        recorder.entries.append((label, time.perf_counter() - start))
+
+
+def span(label: str):
+    """Time one subprocess round trip as *label*; when timing is off, hand back
+    the stdlib no-op instead — no clock read, nothing recorded."""
+    recorder = _recorder
+    if recorder is None:
+        return contextlib.nullcontext()
+    return _record(recorder, label)
+
+
+def emit(stream: Optional[TextIO] = None) -> None:
+    """Write the summary and stop recording; silent if recording never began.
+
+    *stream* defaults to sys.stderr resolved now, not at import, so capture
+    fixtures and redirections see the output.
+    """
+    global _recorder  # pylint: disable=global-statement
+    recorder = _recorder
+    _recorder = None
+    if recorder is None:
+        return
+    out = stream if stream is not None else sys.stderr
+    total = time.perf_counter() - recorder.started
+    for label, seconds in recorder.entries:
+        print(f"dl-timing: {label} {seconds:.3f}s", file=out)
+    print(f"dl-timing: total {total:.3f}s ({TOTAL_EPOCH})", file=out)

pyproject.toml

@@ -90,6 +90,8 @@ lint = { depends-on = ["ruff-lint", "ty", "pylint"] }
 style = { depends-on = ["format", "lint"] }
 commit-format = "git commit -a -m'autoformat code' || true"
 test = "pytest"
+# Median wall time of a command over N runs; see "Measuring launch time" in README.md.
+bench = "python scripts/bench_launch.py"
 # Needs a real Docker daemon and a real devpod. Inside this repo's devcontainer
 # that daemon is the container's own, via the docker-in-docker feature; on an
 # ephemeral CI runner or a machine you do not mind writing to, it is the host's.