diff --git a/README.md b/README.md index e986228f..1fdcdd4f 100644 --- a/README.md +++ b/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 -- ` 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: diff --git a/devlaunch/dl.py b/devlaunch/dl.py index 991cd159..a5e5085b 100644 --- a/devlaunch/dl.py +++ b/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: diff --git a/devlaunch/gh_auth.py b/devlaunch/gh_auth.py index 85cd3f27..f234bbf5 100644 --- a/devlaunch/gh_auth.py +++ b/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 " diff --git a/devlaunch/timing.py b/devlaunch/timing.py new file mode 100644 index 00000000..e40652e5 --- /dev/null +++ b/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: