From 3d7cacec53c85544d61d95e2791e292f374bcc95 Mon Sep 17 00:00:00 2001 From: brinkflew Date: Sun, 26 Jul 2026 19:40:25 +0200 Subject: [PATCH 1/3] [IMP] common: halve the time odev takes to start and exit Every invocation paid ~1.6s of framework overhead before the requested command even began, and kept the user waiting ~0.35s after it had already printed its result. For a tool run dozens of times a day that overhead is the dominant part of how slow odev feels, and none of it was the command itself: `odev version` measured 1.59s median, of which 0.02s was the command. Five causes, all of them paid unconditionally: - Telemetry blocked the main thread on an HTTPS round-trip in `run_command`'s `finally`. Records are now spooled locally when a command ends and submitted in the background by a later run, so no invocation ever waits on the endpoint. This also fixes `Telemetry.update()`, which never ran: its `len(_command_stack) != 1` guard was evaluated after the stack had been popped, so exit codes and execution times were silently dropped. The employee check, which ran a vault lookup, an SSH-agent decryption and a call to git on every command, is now cached in the configuration. - Scanning the sources for interactive debuggers spawned two `grep` processes at import time. It now runs on demand and its result is cached on disk, keyed on a walk of the command trees that costs a fraction of the scan itself. - The GitHub API client, paramiko, InquirerPy and black were imported by the framework although only a handful of commands need them; the connector and mixin packages re-exported everything they contained. Those imports moved to their point of use and the packages resolve their names lazily. Networkx was only used to sort the plugin dependency graph and is replaced by a topological sort, reporting the same cycles. - Discovering commands executed all 46 command modules only to read their names, so every run paid for every command, plugins included. Names, aliases and help texts are now cached in an index and a command module is only imported once that command runs. Plugin patching is replayed from the recorded registration order, leaving the output of `odev help` unchanged. - `CaptureOutput` attached its handlers to the loggers that existed when it was entered, which no longer covers command modules imported while a command runs. It now captures on the root logger, like odev does in production. `odev version` goes from 1.59s to 0.73s median, measured by interleaving runs against a clean checkout, and imports 1022 modules instead of 1503. `tools/benchmark_startup.py` reports the breakdown, and the new tests guard the structural causes rather than timings, which are too noisy to assert on. Claude-Session: https://claude.ai/code/session_012tWyDuUYenE92nsBtG19Du --- .ruff.toml | 3 + odev/_version.py | 2 +- odev/commands/utilities/help.py | 13 +- odev/common/commands/registry.py | 318 ++++++++++++++++++ odev/common/config.py | 19 ++ odev/common/connectors/__init__.py | 32 +- odev/common/connectors/git.py | 16 +- odev/common/connectors/rpc.py | 4 +- odev/common/console.py | 139 +++++--- odev/common/debug.py | 139 ++++++-- odev/common/lazy.py | 36 ++ odev/common/mixins/__init__.py | 34 +- odev/common/mixins/connectors/__init__.py | 24 +- odev/common/odev.py | 203 +++++++---- odev/common/progress.py | 36 +- odev/common/ssh_crypt.py | 14 +- odev/common/store/tables/secrets.py | 22 +- odev/common/telemetry.py | 211 +++++++++--- odev/common/utils.py | 17 + tests/fixtures/capture.py | 19 +- tests/fixtures/case.py | 4 +- tests/tests/common/test_odev.py | 8 +- .../tests/common/test_startup_performance.py | 117 +++++++ tools/benchmark_startup.py | 140 ++++++++ 24 files changed, 1343 insertions(+), 227 deletions(-) create mode 100644 odev/common/commands/registry.py create mode 100644 odev/common/lazy.py create mode 100644 tests/tests/common/test_startup_performance.py create mode 100644 tools/benchmark_startup.py diff --git a/.ruff.toml b/.ruff.toml index b34b48653..55e209384 100644 --- a/.ruff.toml +++ b/.ruff.toml @@ -106,6 +106,9 @@ ignore = [ "F403", # ignore * imports "I001", # ignore unsorted imports ] +"tools/*" = [ + "T201", # standalone developer scripts report their results on stdout +] [lint.pydocstyle] convention = "pep257" diff --git a/odev/_version.py b/odev/_version.py index 7306664df..12aa2f183 100644 --- a/odev/_version.py +++ b/odev/_version.py @@ -22,4 +22,4 @@ # or merged change. # ------------------------------------------------------------------------------ -__version__ = "4.29.9" +__version__ = "4.29.10" diff --git a/odev/commands/utilities/help.py b/odev/commands/utilities/help.py index 3d3725b90..b5e874ee4 100644 --- a/odev/commands/utilities/help.py +++ b/odev/commands/utilities/help.py @@ -125,22 +125,23 @@ def all_commands_help(self) -> str: arguments without brackets ('arg') are required. """ - commands = [command for name, command in self.odev.commands.items() if name == command._name] + # Read the registry's index rather than the command classes: listing every command must not import them all. + commands = self.odev.commands.summaries() message_indent = string.min_indent(message) commands_list = string.indent( string.format_options_list( [ ( - command._name, - command._help + command.name, + command.help + ( f"\nAliases: " - f"{string.join_and([f'[italic]{alias}[/italic]' for alias in sorted(command._aliases)])}" - if command._aliases + f"{string.join_and([f'[italic]{alias}[/italic]' for alias in sorted(command.aliases)])}" + if command.aliases else "" ), ) - for command in sorted(commands, key=lambda command: command._name) + for command in commands ], blanks=1, ), diff --git a/odev/common/commands/registry.py b/odev/common/commands/registry.py new file mode 100644 index 000000000..543b18c88 --- /dev/null +++ b/odev/common/commands/registry.py @@ -0,0 +1,318 @@ +"""Registry of the commands odev can run, resolved on demand.""" + +import json +from collections.abc import Iterator, MutableMapping +from dataclasses import asdict, dataclass, field +from importlib.util import module_from_spec, spec_from_file_location +from pathlib import Path +from typing import TYPE_CHECKING, Any + +from odev.common.config import CONFIG_DIR +from odev.common.logging import logging + + +if TYPE_CHECKING: + from odev.common.commands.base import Command + from odev.common.odev import Odev + + +logger = logging.getLogger(__name__) + + +@dataclass(frozen=True) +class CommandSource: + """Module defining a command class, as found on disk.""" + + module: str + """Name the module is imported under.""" + + path: str + """Path to the file defining the command.""" + + command_class: str + """Name of the command class within that module.""" + + +@dataclass +class CommandEntry: + """What odev knows about a command before importing the module implementing it.""" + + name: str + """Name the command is invoked with.""" + + aliases: list[str] = field(default_factory=list) + """Alternative names the command answers to.""" + + help: str = "" + """Description of the command, as displayed by the help command.""" + + sources: list[CommandSource] = field(default_factory=list) + """Modules defining the command, in registration order: the core one first, then the plugins patching it.""" + + +class CommandRegistry(MutableMapping): + """Mapping of command names and aliases to the class implementing them. + + A command module imports everything its command needs at module level, so executing all of them only to read + their names makes every odev invocation pay for every command, plugins included. Names, aliases and help texts + are therefore cached on disk, and a command module is only executed once that command is actually requested. + """ + + def __init__(self, framework: "Odev"): + self.framework: Odev = framework + """Framework the commands are registered against.""" + + self.entries: dict[str, CommandEntry] = {} + """Known commands, by name.""" + + self.names: dict[str, str] = {} + """Name of the command each name and alias refers to.""" + + self.classes: dict[str, type[Command]] = {} + """Command classes that were imported during this run, by command name.""" + + def __repr__(self) -> str: + return f"{self.__class__.__name__}({len(self.entries)} commands, {len(self.classes)} imported)" + + # --- Mapping interface ---------------------------------------------------- + + def __getitem__(self, name: str) -> type["Command"]: + command_name = self.names[name] + + if command_name not in self.classes: + self.classes[command_name] = self.__resolve(self.entries[command_name]) + + return self.classes[command_name] + + def __setitem__(self, name: str, command_class: type["Command"]) -> None: + entry = self.entries.setdefault(command_class._name, CommandEntry(command_class._name)) + entry.aliases = list(command_class._aliases or []) + entry.help = command_class._help + self.names[name] = entry.name + self.classes[entry.name] = command_class + + def __delitem__(self, name: str) -> None: + command_name = self.names.pop(name) + + if command_name not in self.names.values(): + self.entries.pop(command_name, None) + self.classes.pop(command_name, None) + + def __iter__(self) -> Iterator[str]: + return iter(self.names) + + def __len__(self) -> int: + return len(self.names) + + def clear(self) -> None: + """Forget every registered command.""" + self.entries.clear() + self.names.clear() + self.classes.clear() + + # --- Registration --------------------------------------------------------- + + def register(self, command_class: type["Command"], module_path: Path) -> None: + """Register a command shipped with odev itself. + + :param command_class: The command class to register. + :param module_path: Path to the module defining the command class. + :raise ValueError: If another command already answers to one of its names. + """ + names = self.__names_of(command_class) + + if any(name in self.names for name in names): + raise ValueError(f"Another command {command_class._name!r} is already registered") + + logger.debug(f"Registering command {command_class._name!r}") + source = self.__source_of(command_class, module_path) + command_class.prepare_command(self.framework) + self.__store(command_class, names, source) + + def patch(self, command_class: type["Command"], module_path: Path) -> None: + """Register a command provided by a plugin, letting it patch a command of the same name. + + :param command_class: The command class provided by the plugin. + :param module_path: Path to the module defining the command class. + """ + names = self.__names_of(command_class) + registered = self[command_class._name] if command_class._name in self.names else None + source = self.__source_of(command_class, module_path) + + if registered is not None and command_class.__bases__ != registered.__bases__: + logger.debug(f"Patching command {command_class._name!r}") + command_class = self.__patched(command_class, registered) + else: + logger.debug(f"Registering command {command_class._name!r}") + + command_class.prepare_command(self.framework) + self.__store(command_class, names, source) + + def summaries(self) -> list[CommandEntry]: + """Describe every registered command without importing any of them. + + :return: The known commands, sorted by name. + :rtype: List[CommandEntry] + """ + return sorted(self.entries.values(), key=lambda entry: entry.name) + + # --- On-disk index -------------------------------------------------------- + + @property + def index_path(self) -> Path: + """Path to the file caching what odev knows about its commands.""" + return CONFIG_DIR / f"{self.framework.name}-commands.json" + + def load(self, fingerprint: Any) -> bool: + """Restore the command index cached by a previous run. + + :param fingerprint: Signature of the command sources, the index is discarded when it does not match. + :return: Whether the index could be restored. + :rtype: bool + """ + try: + with self.index_path.open(encoding="utf-8") as index: + cached = json.load(index) + except (OSError, json.JSONDecodeError): + return False + + if cached.get("fingerprint") != fingerprint: + logger.debug("Command index is out of date, commands will be imported again") + return False + + self.clear() + + for name, entry in cached["commands"].items(): + self.entries[name] = CommandEntry( + name=name, + aliases=entry["aliases"], + help=entry["help"], + sources=[CommandSource(**source) for source in entry["sources"]], + ) + + for alias in [name, *entry["aliases"]]: + self.names[alias] = name + + logger.debug(f"Loaded {len(self.entries)} commands from the index") + + return True + + def save(self, fingerprint: Any) -> None: + """Cache what odev knows about its commands so the next runs do not have to import them. + + :param fingerprint: Signature of the command sources this index was built from. + """ + index = { + "fingerprint": fingerprint, + "commands": { + entry.name: { + "aliases": entry.aliases, + "help": entry.help, + "sources": [asdict(source) for source in entry.sources], + } + for entry in self.entries.values() + }, + } + + try: + self.index_path.parent.mkdir(parents=True, exist_ok=True) + + with self.index_path.open("w", encoding="utf-8") as file: + json.dump(index, file) + except OSError as error: + logger.debug(f"Failed to cache the command index: {error}") + + # --- Private methods ------------------------------------------------------ + + def __store(self, command_class: type["Command"], names: list[str], source: CommandSource) -> None: + """Record a prepared command class and the module it came from. + + :param command_class: The command class to record. + :param names: Names and aliases the command answers to. + :param source: Module the command class was defined in, before any patching. + """ + entry = self.entries.setdefault(command_class._name, CommandEntry(command_class._name)) + entry.aliases = list(command_class._aliases or []) + entry.help = command_class._help + + if source not in entry.sources: + entry.sources.append(source) + + for name in names: + self.names[name] = entry.name + + self.classes[entry.name] = command_class + + def __resolve(self, entry: CommandEntry) -> type["Command"]: + """Import the modules defining a command and rebuild the class that was registered for it. + + Replaying the sources in the order they were registered in reproduces the patching a plugin applied to a + command of the same name, without having imported any of the commands that were not asked for. + + :param entry: The command to resolve. + :return: The command class to run. + :rtype: Type[Command] + """ + resolved: type[Command] | None = None + + for source in entry.sources: + command_class = self.__import(source) + + if resolved is not None and command_class.__bases__ != resolved.__bases__: + command_class = self.__patched(command_class, resolved) + + command_class.prepare_command(self.framework) + resolved = command_class + + if resolved is None: + raise ValueError(f"Command {entry.name!r} has no module to import") + + return resolved + + def __import(self, source: CommandSource) -> type["Command"]: + """Import the module defining a command and return its class. + + :param source: The module to import. + :return: The command class it defines. + :rtype: Type[Command] + """ + spec = spec_from_file_location(source.module, source.path) + + if spec is None or spec.loader is None: + raise ImportError(f"Cannot load module {source.module} from {source.path}") + + module = module_from_spec(spec) + spec.loader.exec_module(module) + + return getattr(module, source.command_class) + + @staticmethod + def __patched(command_class: type["Command"], registered: type["Command"]) -> type["Command"]: + """Combine a command provided by a plugin with the command it patches. + + :param command_class: The command class provided by the plugin. + :param registered: The command class already registered under the same name. + :return: A class inheriting from both. + :rtype: Type[Command] + """ + + class PatchedCommand(command_class, registered, *registered.__bases__): # type: ignore [misc, valid-type] + pass + + PatchedCommand.__name__ = registered.__name__ + + return PatchedCommand + + @staticmethod + def __names_of(command_class: type["Command"]) -> list[str]: + """List the names and aliases a command answers to.""" + return [command_class._name, *(command_class._aliases or [])] + + @staticmethod + def __source_of(command_class: type["Command"], module_path: Path) -> CommandSource: + """Describe where a command class is defined, so that it can be imported again later.""" + return CommandSource( + module=command_class.__module__, + path=module_path.as_posix(), + command_class=command_class.__name__, + ) diff --git a/odev/common/config.py b/odev/common/config.py index 5f7384cd9..c2512735f 100644 --- a/odev/common/config.py +++ b/odev/common/config.py @@ -19,6 +19,8 @@ CONFIG_DIR: Path = Path.home() / ".config" / "odev" DATETIME_FORMAT = "%Y-%m-%d %H:%M:%S" +XGRAM_UNKNOWN = "" +"""Marker stored in the configuration while the user's trigram has never been resolved.""" class Section: @@ -299,6 +301,23 @@ def enabled(self, value: bool): self.set("enabled", "true" if value else "false") +class UserSection(Section): + """Configuration about the developer running odev.""" + + @property + def xgram(self) -> str: + """Odoo trigram of the current user, cached across runs. + + Resolving it requires a vault lookup and a call to git, which is too expensive to repeat on every command. + An empty value means the user is known not to be an Odoo employee, `` that the check never ran. + """ + return cast(str, self.get("xgram", XGRAM_UNKNOWN)) + + @xgram.setter + def xgram(self, value: str): + self.set("xgram", value) + + class Config: """Odev configuration. Light wrapper around configparser to write and retrieve configuration values saved on disk. diff --git a/odev/common/connectors/__init__.py b/odev/common/connectors/__init__.py index 3341a3f0b..3523703cd 100644 --- a/odev/common/connectors/__init__.py +++ b/odev/common/connectors/__init__.py @@ -1,10 +1,19 @@ """Connectors to external services.""" -from .base import Connector -from .git import GitConnector, GitWorktree, Stash -from .postgres import PostgresConnector -from .rest import RestConnector -from .rpc import RpcConnector +from typing import TYPE_CHECKING + +from odev.common.lazy import lazy_exports + + +# Declared for type checkers and IDEs only: at runtime the names below are resolved by `__getattr__`, so that +# importing this package does not import every connector it exposes. +if TYPE_CHECKING: + from odev.common.connectors.base import Connector + from odev.common.connectors.git import GitConnector, GitWorktree, Stash + from odev.common.connectors.postgres import PostgresConnector + from odev.common.connectors.rest import RestConnector + from odev.common.connectors.rpc import RpcConnector + __all__ = [ "Connector", @@ -15,3 +24,16 @@ "RpcConnector", "Stash", ] + +__getattr__ = lazy_exports( + __name__, + { + "Connector": "base", + "GitConnector": "git", + "GitWorktree": "git", + "Stash": "git", + "PostgresConnector": "postgres", + "RestConnector": "rest", + "RpcConnector": "rpc", + }, +) diff --git a/odev/common/connectors/git.py b/odev/common/connectors/git.py index 3f0011d28..47b22fa10 100644 --- a/odev/common/connectors/git.py +++ b/odev/common/connectors/git.py @@ -6,13 +6,13 @@ from pathlib import Path from types import FrameType from typing import ( + TYPE_CHECKING, ClassVar, cast, ) from urllib.parse import urlparse from git import GitCommandError, InvalidGitRepositoryError, NoSuchPathError, Remote, RemoteReference, Repo -from github import Auth as GithubAuth, Github, GithubException from odev.common import bash, progress, string from odev.common.connectors.base import Connector @@ -23,6 +23,10 @@ from odev.common.signal_handling import capture_signals +if TYPE_CHECKING: + from github import Github + + GITHUB_DOMAIN = "github.com" """The domain of the GitHub API.""" @@ -236,7 +240,7 @@ class GitConnector(Connector): _token: str | None = None """The Github API token for the current session.""" - _connection: Github | None = None + _connection: "Github | None" = None """The connection to the Github API.""" _organization: str @@ -373,7 +377,7 @@ def default_branch(self) -> str | None: return self.repository.heads[0].name.split("/")[-1] with self: - return cast(Github, self._connection).get_repo(self.name).default_branch + return cast("Github", self._connection).get_repo(self.name).default_branch @property def branch(self) -> str | None: @@ -404,6 +408,8 @@ def authenticated(self) -> bool: if self._connection is None: return False + from github import GithubException # noqa: PLC0415 - importing the GitHub API client is expensive + try: self._connection.get_user().login # noqa: B018 - login is a property except GithubException: @@ -426,6 +432,8 @@ def update(self): def connect(self): """Connect to the Github API.""" + from github import Auth as GithubAuth, Github # noqa: PLC0415 - importing the GitHub API client is expensive + if self._token is None: def get_token(prompt: bool) -> str | None: @@ -996,7 +1004,7 @@ def list_remote_branches(self) -> list[str]: :rtype: List[str] """ with self: - branches = cast(Github, self._connection).get_repo(self.name).get_branches() + branches = cast("Github", self._connection).get_repo(self.name).get_branches() return [branch.name for branch in branches] diff --git a/odev/common/connectors/rpc.py b/odev/common/connectors/rpc.py index 1dbd7b2d8..610df3b9d 100644 --- a/odev/common/connectors/rpc.py +++ b/odev/common/connectors/rpc.py @@ -10,7 +10,6 @@ ) from urllib.parse import urlparse -import black import odoolib # type: ignore [import] from odev.common import string @@ -374,6 +373,9 @@ def _format_key_value(key: str, value: Any) -> str: call += f".with_context({_context})" call += f".{args[4]}({', '.join(filter(None, [_args, _kwargs]))})" + + import black # noqa: PLC0415 - only needed to pretty-print calls in debug mode + call = black.format_str(call, mode=black.FileMode(line_length=120)).rstrip() logger.debug(f"RPC call to {self.database.platform.display} database {self.database.name!r}") console.code(string.indent(call, indent=4), "python") diff --git a/odev/common/console.py b/odev/common/console.py index c8987bc52..24341fa71 100644 --- a/odev/common/console.py +++ b/odev/common/console.py @@ -6,19 +6,15 @@ from collections.abc import Sequence from contextlib import contextmanager from dataclasses import dataclass +from functools import cache from pathlib import Path from typing import ( + TYPE_CHECKING, Any, ClassVar, Literal, ) -from InquirerPy import inquirer -from InquirerPy.base.control import Choice -from InquirerPy.base.simple import BaseSimplePrompt -from InquirerPy.utils import get_style -from InquirerPy.validator import EmptyInputValidator, NumberValidator, PathValidator -from prompt_toolkit.validation import ValidationError from rich import box from rich.console import Console as RichConsole, RenderableType from rich.control import Control @@ -32,6 +28,11 @@ from odev.common.deprecation import deprecated +if TYPE_CHECKING: + from InquirerPy.utils import InquirerPyStyle + from InquirerPy.validator import PathValidator + + __all__ = ["Colors", "console"] @@ -173,19 +174,29 @@ class Colors: INQUIRER_MARK = "[?]" -INQUIRER_STYLE = get_style( - style_override=False, - style={ - "questionmark": f"fg:{Colors.PURPLE} bold", - "answermark": f"fg:{Colors.PURPLE} bold", - "answer": Colors.PURPLE, - "input": Colors.CYAN, - "pointer": Colors.CYAN, - "validator": f"fg:{Colors.RED} bg: bold", - "skipped": Colors.GRAY, - "checkbox": Colors.CYAN, - }, -) + +@cache +def inquirer_style() -> "InquirerPyStyle": + """Style applied to every prompt shown to the user. + + Building it requires InquirerPy, which pulls in prompt_toolkit and is by far the most expensive dependency of + this module. Since odev only prompts in interactive sessions, it is imported on first use rather than on import. + """ + from InquirerPy.utils import get_style # noqa: PLC0415 - importing prompt_toolkit is expensive + + return get_style( + style_override=False, + style={ + "questionmark": f"fg:{Colors.PURPLE} bold", + "answermark": f"fg:{Colors.PURPLE} bold", + "answer": Colors.PURPLE, + "input": Colors.CYAN, + "pointer": Colors.CYAN, + "validator": f"fg:{Colors.RED} bg: bold", + "skipped": Colors.GRAY, + "checkbox": Colors.CYAN, + }, + ) # --- Logging highlighter customization ---------------------------------------- @@ -211,24 +222,36 @@ def __init__(self, *args, **kwargs): # Validators for inquirer prompts. -class PurportedPathValidator(PathValidator): - """Path validator that doesn't check if the path exists.""" +@cache +def purported_path_validator() -> type["PathValidator"]: + """Build the validator accepting paths that do not exist yet. - def validate(self, document) -> None: - """Check if user input is a valid path.""" - path = Path(document.text).expanduser() + It derives from an InquirerPy class, so it can only be declared once InquirerPy has been imported, which this + module defers until the user is actually prompted. + """ + from InquirerPy.validator import PathValidator # noqa: PLC0415 - importing prompt_toolkit is expensive + from prompt_toolkit.validation import ValidationError # noqa: PLC0415 - if self._is_file and path.is_dir(): - raise ValidationError( - message=self._message, - cursor_position=document.cursor_position, - ) + class PurportedPathValidator(PathValidator): + """Path validator that doesn't check if the path exists.""" - if self._is_dir and path.is_file(): - raise ValidationError( - message=self._message, - cursor_position=document.cursor_position, - ) + def validate(self, document) -> None: + """Check if user input is a valid path.""" + path = Path(document.text).expanduser() + + if self._is_file and path.is_dir(): + raise ValidationError( + message=self._message, + cursor_position=document.cursor_position, + ) + + if self._is_dir and path.is_file(): + raise ValidationError( + message=self._message, + cursor_position=document.cursor_position, + ) + + return PurportedPathValidator # --- Rich console ------------------------------------------------------------- @@ -464,17 +487,19 @@ def code(self, text: str, language: str = "python", file: Path | None = None, ** kwargs.setdefault("theme", "github-dark") self.print(Syntax(text, language, **kwargs)) - def __prompt_factory(self, prompt_type: type[BaseSimplePrompt], message: str, **kwargs) -> Any: + def __prompt_factory(self, prompt_name: str, message: str, **kwargs) -> Any: """Create a prompt object. - :param prompt_type: Type of prompt to create. + :param prompt_name: Name of the InquirerPy prompt to create. :param message: Prompt message. :param kwargs: Keyword arguments to pass to the prompt constructor. :return: The result of the prompt. """ + from InquirerPy import inquirer # noqa: PLC0415 - importing prompt_toolkit is expensive + self.pause_live() - prompt = prompt_type( + prompt = getattr(inquirer, prompt_name)( raise_keyboard_interrupt=True, - style=INQUIRER_STYLE, + style=inquirer_style(), amark=INQUIRER_MARK, qmark=INQUIRER_MARK, message=message, @@ -484,7 +509,7 @@ def __prompt_factory(self, prompt_type: type[BaseSimplePrompt], message: str, ** def patched_run(): if self.bypass_prompt: - default_key = "defaults" if prompt_type == "checkbox" else "default" + default_key = "defaults" if prompt_name == "checkbox" else "default" if default_key in kwargs: prompt.status = { @@ -519,8 +544,10 @@ def text(self, message: str, default: str = "") -> str: :return: The text entered by the user :rtype: str """ + from InquirerPy.validator import EmptyInputValidator # noqa: PLC0415 - importing prompt_toolkit is expensive + return self.__prompt_factory( - inquirer.text, + "text", message=message, default=default, validate=EmptyInputValidator(), @@ -542,8 +569,10 @@ def integer( :return: The selected choice :rtype: int or None """ + from InquirerPy.validator import NumberValidator # noqa: PLC0415 - importing prompt_toolkit is expensive + return self.__prompt_factory( - inquirer.number, + "number", message=message, default=default, min_allowed=min_value, @@ -569,8 +598,10 @@ def floating( :return: The selected choice :rtype: float or None """ + from InquirerPy.validator import NumberValidator # noqa: PLC0415 - importing prompt_toolkit is expensive + return self.__prompt_factory( - inquirer.number, + "number", message=message, default=default, min_allowed=min_value, @@ -590,7 +621,7 @@ def secret(self, message: str = "Password") -> str: :rtype: str """ return self.__prompt_factory( - inquirer.secret, + "secret", message=message, mandatory=True, mandatory_message="A value is required", @@ -605,7 +636,7 @@ def confirm(self, message: str, default: bool = False) -> bool: :rtype: bool """ return self.__prompt_factory( - inquirer.confirm, + "confirm", message=message, default=default, ) @@ -619,11 +650,11 @@ def directory(self, message: str, default: str | None = None) -> str | None: :rtype: str or None """ return self.__prompt_factory( - inquirer.filepath, + "filepath", message=message, default=default, only_directories=True, - validate=PurportedPathValidator(message="Path must not be a file", is_dir=True), + validate=purported_path_validator()(message="Path must not be a file", is_dir=True), ) def filepath(self, message: str, default: str | None = None) -> str | None: @@ -635,11 +666,11 @@ def filepath(self, message: str, default: str | None = None) -> str | None: :rtype: str or None """ return self.__prompt_factory( - inquirer.filepath, + "filepath", message=message, default=default, only_directories=True, - validate=PurportedPathValidator(message="Path must not be a directory", is_file=True), + validate=purported_path_validator()(message="Path must not be a directory", is_file=True), ) def select( @@ -655,8 +686,10 @@ def select( :return: The selected choice :rtype: str or None """ + from InquirerPy.base.control import Choice # noqa: PLC0415 - importing prompt_toolkit is expensive + return self.__prompt_factory( - inquirer.select, + "select", message=message, choices=[Choice(choice[0], name=choice[-1]) for choice in choices], default=default, @@ -673,10 +706,12 @@ def checkbox(self, message: str, choices: Sequence[tuple[Any, str | None]], defa :return: The selected choice :rtype: str or None """ + from InquirerPy.base.control import Choice # noqa: PLC0415 - importing prompt_toolkit is expensive + defaults = defaults or [] return self.__prompt_factory( - inquirer.checkbox, + "checkbox", message=message, choices=[Choice(choice[0], name=choice[-1], enabled=choice[0] in defaults) for choice in choices], transformer=lambda selected: string.join_and(selected) if selected else "None", @@ -693,8 +728,10 @@ def fuzzy(self, message: str, choices: Sequence[tuple[str, str | None]], default :return: The selected choice :rtype: str or None """ + from InquirerPy.base.control import Choice # noqa: PLC0415 - importing prompt_toolkit is expensive + return self.__prompt_factory( - inquirer.fuzzy, + "fuzzy", message=message, choices=[Choice(choice[0], name=choice[-1]) for choice in choices], default=default, diff --git a/odev/common/debug.py b/odev/common/debug.py index c61637b4e..f78feb034 100644 --- a/odev/common/debug.py +++ b/odev/common/debug.py @@ -1,11 +1,11 @@ """Shared method for debugging odev or interacting with debuggers.""" +import json +import os import subprocess -from collections.abc import Generator -from functools import lru_cache from pathlib import Path -from odev.common import bash, string +from odev.common import bash from odev.common.config import CONFIG_DIR from odev.common.logging import logging @@ -13,16 +13,19 @@ logger = logging.getLogger(__name__) -DEBUG_MODE: bool = False -"""Whether odev is currently in debug mode.""" +DEBUG_CACHE_PATH: Path = CONFIG_DIR / "debuggers.json" +"""Path to the file caching the result of the last scan for interactive debuggers.""" -@lru_cache -def find_debuggers(root: str | Path, *, follow_symlinks: bool = True) -> Generator[tuple[Path, int], None, None]: +_debuggers: list[str] | None = None +"""Calls to interactive debuggers found in odev's sources, resolved on first access.""" + + +def find_debuggers(root: str | Path, *, follow_symlinks: bool = True) -> list[tuple[Path, int]]: """Find all call to interactive debuggers in the given directory and its subdirectories. :param root: The directory to search for debugger instances. :param follow_symlinks: Whether to descend into symlinked directories found under the root. - :return: A generator of tuples containing the file path and the line number of the call to the debugger. + :return: A list of tuples containing the file path and the line number of the call to the debugger. """ if isinstance(root, str): root = Path(root) @@ -40,27 +43,113 @@ def find_debuggers(root: str | Path, *, follow_symlinks: bool = True) -> Generat except subprocess.CalledProcessError: output = "" + found: list[tuple[Path, int]] = [] + for line in output.splitlines(): file, position, _ = line.split(":", 2) - yield Path(file), int(position) + found.append((Path(file), int(position))) + + return found + + +def debuggers() -> list[str]: + """List the calls to interactive debuggers found in odev's sources and its plugins. + + :return: The locations of the calls, formatted as `path:line`. + """ + global _debuggers # noqa: PLW0603 + + if _debuggers is None: + _debuggers = _resolve_debuggers() + + return _debuggers + + +def debug_mode() -> bool: + """Whether odev's sources contain a call to an interactive debugger. + + A live display and an interactive debugger cannot share the terminal, so odev degrades spinners and progress + bars to plain log messages as soon as one is found. + """ + return bool(debuggers()) + + +def _sources() -> list[tuple[Path, bool]]: + """List the directories to scan, and whether symlinks must be followed within them. + + The repository may contain an `odev/plugins` symlink used for IDE import resolution: do not follow symlinks when + scanning the package, the installed plugins are scanned separately from their canonical location. + """ + sources: list[tuple[Path, bool]] = [(Path(__file__).parents[1], False)] + plugins_path = CONFIG_DIR / "plugins" + + if plugins_path.is_dir(): + sources.append((plugins_path, True)) + return sources -# ------------------------------------------------------------------------------ -# Find calls to interactive debuggers within odev's source code. -# The repository may contain an `odev/plugins` symlink used for IDE import resolution: do not follow symlinks when -# scanning the package, the installed plugins are scanned separately from their canonical location. -sources: list[tuple[Path, bool]] = [(Path(__file__).parents[1], False)] -plugins_path = CONFIG_DIR / "plugins" -if plugins_path.is_dir(): - sources.append((plugins_path, True)) +def _fingerprint(sources: list[tuple[Path, bool]]) -> list[float]: + """Compute a cheap signature of the sources, used to detect changes since the last scan. -debuggers = [ - f"{file.as_posix()}:{line}" - for source, follow_symlinks in sources - for file, line in find_debuggers(source, follow_symlinks=follow_symlinks) -] + Walking the trees for their modification times costs a fraction of what grepping through their content does, so + the actual scan only runs again once a Python file was added, removed or modified. + + :param sources: The directories to scan, and whether symlinks must be followed within them. + :return: The number of Python files found, and the most recent modification time among them. + """ + count: int = 0 + newest: float = 0.0 + + for root, follow_symlinks in sources: + for directory, _, filenames in os.walk(root, followlinks=follow_symlinks): + for filename in filenames: + if filename.endswith(".py"): + count += 1 + newest = max(newest, os.stat(Path(directory, filename)).st_mtime) + + return [count, newest] + + +def _resolve_debuggers() -> list[str]: + """Scan the sources for calls to interactive debuggers, reusing the cached result when they did not change.""" + sources = _sources() + fingerprint = _fingerprint(sources) + cached = _read_cache() + + if cached is not None and cached.get("fingerprint") == fingerprint: + return cached["debuggers"] + + found = [ + f"{file.as_posix()}:{line}" + for source, follow_symlinks in sources + for file, line in find_debuggers(source, follow_symlinks=follow_symlinks) + ] + + _write_cache(fingerprint, found) + + return found + + +def _read_cache() -> dict | None: + """Read the result of the last scan, or None if it is missing or unusable.""" + try: + with DEBUG_CACHE_PATH.open(encoding="utf-8") as cache: + return json.load(cache) + except (OSError, json.JSONDecodeError): + return None + + +def _write_cache(fingerprint: list[float], found: list[str]) -> None: + """Save the result of a scan so that the next runs can reuse it. + + :param fingerprint: Signature of the sources that were scanned. + :param found: The locations of the calls to interactive debuggers that were found. + """ + try: + DEBUG_CACHE_PATH.parent.mkdir(parents=True, exist_ok=True) -if debuggers: - logger.warning(f"Interactive debuggers detected:\n{string.join_bullet(debuggers)}") - DEBUG_MODE = True + with DEBUG_CACHE_PATH.open("w", encoding="utf-8") as cache: + json.dump({"fingerprint": fingerprint, "debuggers": found}, cache) + except OSError as error: + logger.debug(f"Failed to cache the scan for interactive debuggers: {error}") diff --git a/odev/common/lazy.py b/odev/common/lazy.py new file mode 100644 index 000000000..83c49a148 --- /dev/null +++ b/odev/common/lazy.py @@ -0,0 +1,36 @@ +"""Helpers to re-export names from a package without importing their module eagerly.""" + +import sys +from collections.abc import Callable, Mapping +from importlib import import_module +from typing import Any + + +__all__ = ["lazy_exports"] + + +def lazy_exports(package: str, exports: Mapping[str, str]) -> Callable[[str], Any]: + """Build the `__getattr__` of a package re-exporting names from its submodules. + + Importing a package should not drag in every module it re-exports: the connectors alone pull in a GitHub API + client, an RPC client and a database driver, none of which most commands ever touch. Names are instead resolved + the first time they are accessed, then cached on the package so subsequent accesses are plain lookups. + + :param package: Name of the package the names are re-exported from, usually its `__name__`. + :param exports: Mapping of each re-exported name to the submodule defining it, relative to the package. + :return: A function to assign to the package's `__getattr__`. + :rtype: Callable[[str], Any] + """ + + def resolve(name: str) -> Any: + module = exports.get(name) + + if module is None: + raise AttributeError(f"module {package!r} has no attribute {name!r}") + + value = getattr(import_module(f"{package}.{module}"), name) + setattr(sys.modules[package], name, value) + + return value + + return resolve diff --git a/odev/common/mixins/__init__.py b/odev/common/mixins/__init__.py index dd162ed76..19b1fa185 100644 --- a/odev/common/mixins/__init__.py +++ b/odev/common/mixins/__init__.py @@ -1,4 +1,34 @@ """Mixins to extend the functionality of command classes.""" -from .connectors import * -from .databases import ListLocalDatabasesMixin +from typing import TYPE_CHECKING + +from odev.common.lazy import lazy_exports + + +# Declared for type checkers and IDEs only: at runtime the names below are resolved by `__getattr__`, so that +# importing this package does not import the connectors the mixins wrap. +if TYPE_CHECKING: + from odev.common.mixins.connectors.base import ConnectorMixin, ensure_connected + from odev.common.mixins.connectors.github import GitConnectorMixin + from odev.common.mixins.connectors.postgres import PostgresConnectorMixin + from odev.common.mixins.databases.list import ListLocalDatabasesMixin + + +__all__ = [ + "ConnectorMixin", + "GitConnectorMixin", + "ListLocalDatabasesMixin", + "PostgresConnectorMixin", + "ensure_connected", +] + +__getattr__ = lazy_exports( + __name__, + { + "ConnectorMixin": "connectors.base", + "ensure_connected": "connectors.base", + "GitConnectorMixin": "connectors.github", + "PostgresConnectorMixin": "connectors.postgres", + "ListLocalDatabasesMixin": "databases.list", + }, +) diff --git a/odev/common/mixins/connectors/__init__.py b/odev/common/mixins/connectors/__init__.py index aee67c689..c7e25eb5c 100644 --- a/odev/common/mixins/connectors/__init__.py +++ b/odev/common/mixins/connectors/__init__.py @@ -1,8 +1,16 @@ """Connector mixins.""" -from .base import ConnectorMixin, ensure_connected -from .github import GitConnectorMixin -from .postgres import PostgresConnectorMixin +from typing import TYPE_CHECKING + +from odev.common.lazy import lazy_exports + + +# Declared for type checkers and IDEs only: at runtime the names below are resolved by `__getattr__`, so that +# importing this package does not import the connectors the mixins wrap. +if TYPE_CHECKING: + from odev.common.mixins.connectors.base import ConnectorMixin, ensure_connected + from odev.common.mixins.connectors.github import GitConnectorMixin + from odev.common.mixins.connectors.postgres import PostgresConnectorMixin __all__ = [ @@ -11,3 +19,13 @@ "PostgresConnectorMixin", "ensure_connected", ] + +__getattr__ = lazy_exports( + __name__, + { + "ConnectorMixin": "base", + "ensure_connected": "base", + "GitConnectorMixin": "github", + "PostgresConnectorMixin": "postgres", + }, +) diff --git a/odev/common/odev.py b/odev/common/odev.py index c84426e36..4d02b460b 100644 --- a/odev/common/odev.py +++ b/odev/common/odev.py @@ -9,9 +9,10 @@ import sys from argparse import Namespace from collections import defaultdict -from collections.abc import Generator, Iterable, Iterator, Mapping, MutableMapping, Sequence +from collections.abc import Generator, Iterable, Iterator, Mapping, Sequence from datetime import datetime from functools import lru_cache +from hashlib import sha256 from importlib.abc import Loader from importlib.machinery import FileFinder, ModuleSpec from importlib.util import module_from_spec, spec_from_file_location @@ -30,13 +31,13 @@ ) from git import GitCommandError, NoSuchPathError, Repo -from networkx import DiGraph, NetworkXUnfeasible, simple_cycles, topological_sort from packaging import version from odev._version import __version__ from odev.common import progress, string from odev.common.commands import CommandType from odev.common.commands.database import DatabaseType +from odev.common.commands.registry import CommandRegistry from odev.common.config import CONFIG_DIR, Config from odev.common.connectors.git import GitConnector, Stash from odev.common.console import Console, console @@ -116,8 +117,8 @@ class Odev(Generic[CommandType]): store: ClassVar[DataStore] """Odev data storage.""" - commands: MutableMapping[str, type[CommandType]] = {} - """Collection of existing and loaded commands.""" + commands: "CommandRegistry" + """Collection of existing commands, imported on demand.""" executable: ClassVar[Path] = Path(sys.argv[0]).parent.resolve() / "odev.sh" """Path to the current executable.""" @@ -142,6 +143,9 @@ def __init__(self, test: bool = False): self.in_test_mode = test """Whether the framework is in testing mode.""" + self.commands = CommandRegistry(self) + """Collection of existing commands, imported on demand.""" + self._load_config() self.__class__.store = DataStore(self.name) self.telemetry = Telemetry(self) @@ -288,10 +292,18 @@ def start(self, start_time: float | None = None) -> None: with progress.spinner("Loading commands"): self.load_plugins() - self.register_commands() - self.register_plugin_commands() + + # Importing every command module only to read its name makes each run pay for every command, plugins + # included. Do it once and remember the outcome until the commands on disk actually change. + fingerprint = self._commands_fingerprint() + + if not self.commands.load(fingerprint): + self.register_commands() + self.register_plugin_commands() + self.commands.save(fingerprint) self.prune_databases() + self.telemetry.flush() self._started = True def update(self, restart: bool = True, upgrade: bool = False) -> bool: @@ -532,15 +544,15 @@ def list_commands(self, sources: Iterable[Path]) -> Iterator[pkgutil.ModuleInfo] command_dirs = [path for path in sources if path.is_dir() and not path.name.startswith("_")] return pkgutil.iter_modules([d.as_posix() for d in command_dirs]) - def import_commands(self, sources: Iterable[Path]) -> list[type[CommandType]]: + def import_commands(self, sources: Iterable[Path]) -> list[tuple[type[CommandType], Path]]: """Import all commands from the source directories. :param sources: Source directories to search for commands. - :return: List of imported command classes - :rtype: List[CommandType] + :return: List of imported command classes, paired with the module they were defined in + :rtype: List[Tuple[CommandType, Path]] """ command_modules = self.list_commands(sources) - command_classes: list[type[CommandType]] = [] + command_classes: list[tuple[type[CommandType], Path]] = [] for module_info in command_modules: if not isinstance(module_info.module_finder, FileFinder): @@ -558,23 +570,18 @@ def import_commands(self, sources: Iterable[Path]) -> list[type[CommandType]]: command_module: ModuleType = module_from_spec(spec) spec.loader.exec_module(command_module) - command_classes.extend(command[1] for command in inspect.getmembers(command_module, self.__filter_commands)) + command_classes.extend( + (command[1], module_path) for command in inspect.getmembers(command_module, self.__filter_commands) + ) return command_classes def register_commands(self) -> None: """Register all commands from the commands directory.""" - for command_class in self.import_commands(self.commands_path.iterdir()) + self.import_commands( + for command_class, module_path in self.import_commands(self.commands_path.iterdir()) + self.import_commands( [self.commands_path] ): - logger.debug(f"Registering command {command_class._name!r}") - command_names = [command_class._name] + (list(command_class._aliases) or []) - - if any(name in command_names for name in self.commands): - raise ValueError(f"Another command {command_class._name!r} is already registered") - - command_class.prepare_command(self) - self.commands.update(dict.fromkeys(command_names, command_class)) + self.commands.register(command_class, module_path) def load_plugins(self) -> None: """Import all enabled plugins to allow them to patch the framework.""" @@ -715,31 +722,31 @@ def register_plugin_commands(self) -> None: def _register_plugin_commands(self) -> None: """Register all commands from the plugins directories.""" for plugin in self.plugins: - for command_class in self.import_commands(plugin.path.glob("commands/**")): - command_names = [command_class._name] + (list(command_class._aliases) or []) - base_command_class = self.commands.get(command_class._name) - action = ( - "Registering" - if base_command_class is None or issubclass(base_command_class, command_class) - else "Patching" - ) + for command_class, module_path in self.import_commands(plugin.path.glob("commands/**")): + self.commands.patch(command_class, module_path) - logger.debug(f"{action} command {command_class._name!r}") + def _commands_fingerprint(self) -> list[Any]: + """Compute a cheap signature of the command modules available to odev. - if ( - command_class._name in self.commands - and base_command_class is not None - and command_class.__bases__ != base_command_class.__bases__ - ): + Walking the command directories for their names and modification times costs a fraction of what importing + them does, so the commands are only discovered again once one of them was added, removed, renamed or + modified. - class PatchedCommand(command_class, base_command_class, *base_command_class.__bases__): - pass + :return: The odev version, the version of each enabled plugin, and the state of the command directories + :rtype: List[Any] + """ + modules: list[str] = [] - command_class = PatchedCommand # noqa: PLW2901 - we want to override the variable - PatchedCommand.__name__ = base_command_class.__name__ + for commands_path in [self.commands_path, *(plugin.path / "commands" for plugin in self.plugins)]: + modules.extend( + f"{module_path.as_posix()}:{module_path.stat().st_mtime}" for module_path in commands_path.rglob("*.py") + ) - command_class.prepare_command(self) - self.commands.update(dict.fromkeys(command_names, command_class)) + return [ + self.version, + {plugin.name: plugin.manifest["version"] for plugin in self.plugins}, + sha256("\n".join(sorted(modules)).encode()).hexdigest(), + ] def _load_config(self) -> None: """Reload the configuration file.""" @@ -903,32 +910,103 @@ def _plugins_dependency_tree(self) -> list[str]: """Order plugins by mutual dependencies, the first one in the returned list being the first one that needs to be imported to respect the dependency graph. """ - graph = DiGraph() + dependents: dict[str, list[str]] = {} for plugin_path in self.plugins_path.iterdir(): manifest = self._load_plugin_manifest(plugin_path) - graph.add_node(manifest["name"]) + dependents.setdefault(manifest["name"], []) for dependency in manifest["depends"]: - graph.add_edge(dependency, manifest["name"]) + dependents.setdefault(dependency, []).append(manifest["name"]) - try: - resolved_graph: list[str] = list(topological_sort(graph)) - logger.debug(f"Resolved plugins dependency tree:\n{join_bullet(resolved_graph)}") - except NetworkXUnfeasible as exception: - cycles = list(simple_cycles(graph))[:20] - if cycles: - parts: list[str] = [] - for c in cycles: - if len(c) == 1: - parts.append(f"{c[0]} depends on itself") - else: - parts.append(" → ".join([*c, c[0]])) - raise OdevError("Circular dependency detected in plugins: " + "; ".join(parts)) from exception - raise OdevError("Circular dependency detected in plugins") from exception + resolved_graph = self.__topological_sort(dependents) + logger.debug(f"Resolved plugins dependency tree:\n{join_bullet(resolved_graph)}") return resolved_graph + @classmethod + def __topological_sort(cls, dependents: Mapping[str, list[str]]) -> list[str]: + """Order nodes of a dependency graph so that each one comes after the nodes it depends on. + + :param dependents: Mapping of each node to the nodes that directly depend on it. + :return: The ordered nodes. + :rtype: List[str] + :raise OdevError: If the graph contains a circular dependency. + """ + indegrees = dict.fromkeys(dependents, 0) + + for node_dependents in dependents.values(): + for dependent in node_dependents: + indegrees[dependent] += 1 + + ordered: list[str] = [] + generation = [node for node, indegree in indegrees.items() if not indegree] + + while generation: + ordered.extend(generation) + next_generation: list[str] = [] + + for node in generation: + for dependent in dependents[node]: + indegrees[dependent] -= 1 + + if not indegrees[dependent]: + next_generation.append(dependent) + + generation = next_generation + + if len(ordered) == len(dependents): + return ordered + + cycles = cls.__find_cycles(dependents, set(dependents) - set(ordered)) + + if not cycles: + raise OdevError("Circular dependency detected in plugins") + + described = [ + f"{cycle[0]} depends on itself" if len(cycle) == 1 else " → ".join([*cycle, cycle[0]]) for cycle in cycles + ] + + raise OdevError("Circular dependency detected in plugins: " + "; ".join(described)) + + @staticmethod + def __find_cycles(dependents: Mapping[str, list[str]], nodes: set[str], limit: int = 20) -> list[list[str]]: + """Find the circular dependencies formed by the given nodes, for reporting purposes. + + :param dependents: Mapping of each node to the nodes that directly depend on it. + :param nodes: The nodes known to take part in a cycle. + :param limit: Maximum number of cycles to report. + :return: The cycles found, each as the list of nodes it goes through. + :rtype: List[List[str]] + """ + cycles: list[list[str]] = [] + reported: set[tuple[str, ...]] = set() + + def walk(path: list[str]) -> None: + if len(cycles) >= limit: + return + + for dependent in dependents.get(path[-1], []): + if dependent not in nodes: + continue + + if dependent not in path: + walk([*path, dependent]) + continue + + cycle = path[path.index(dependent) :] + start = cycle.index(min(cycle)) + canonical = tuple(cycle[start:] + cycle[:start]) + + if canonical not in reported: + reported.add(canonical) + cycles.append(list(canonical)) + + for node in sorted(nodes): + walk([node]) + + return cycles + def parse_arguments(self, command_cls: type[CommandType], *args) -> Namespace: """Parse arguments for a command. @@ -1015,12 +1093,11 @@ def run_command( command.cleanup() command.console.bypass_prompt = command._bypass_prompt_orig - if telemetry is not None and self.config.telemetry.enabled: - telemetry[0].join() - telemetry_line = telemetry[1].get() - - if telemetry_line is not None: - self.telemetry.update(telemetry_line) + if telemetry is not None: + telemetry.finish( + exit_code=int(command_errored), + execution_time=(monotonic() - self.start_time) / 60, + ) return not command_errored diff --git a/odev/common/progress.py b/odev/common/progress.py index e450d79a6..21bb5cb8f 100644 --- a/odev/common/progress.py +++ b/odev/common/progress.py @@ -20,7 +20,7 @@ from odev.common import string from odev.common.console import console -from odev.common.debug import DEBUG_MODE +from odev.common.debug import debug_mode, debuggers from odev.common.logging import OdevRichHandler, logging @@ -30,11 +30,31 @@ logger = logging.getLogger(__name__) -if DEBUG_MODE: - logger.warning( - "Disabling live status due to debugger usage:\n" - + string.join_bullet(["Progress bars will not be shown", "Spinners will be replaced with log messages"]) - ) +_debug_warning_shown: bool = False +"""Whether the user was already told that live statuses are disabled.""" + + +def live_status_disabled() -> bool: + """Whether live statuses must be degraded to plain log messages. + + An interactive debugger and a live display cannot share the terminal, so the presence of a call to a debugger + in odev's sources disables spinners and progress bars. The check is only performed when a live status is about + to be displayed: scanning the sources is far too expensive to pay on every odev invocation. + """ + global _debug_warning_shown # noqa: PLW0603 + + if not debug_mode(): + return False + + if not _debug_warning_shown: + _debug_warning_shown = True + logger.warning(f"Interactive debuggers detected:\n{string.join_bullet(debuggers())}") + logger.warning( + "Disabling live status due to debugger usage:\n" + + string.join_bullet(["Progress bars will not be shown", "Spinners will be replaced with log messages"]) + ) + + return True class Progress(RichProgress): @@ -111,7 +131,7 @@ def __enter__(self) -> "Status": if self.stack: self.stack[-1].stop() - if DEBUG_MODE or getattr(console, "headless", False): + if getattr(console, "headless", False) or live_status_disabled(): return self console.is_live = True @@ -176,7 +196,7 @@ def spinner(message: str) -> StackedStatus: :param message: The message to display. :type message: str """ - if not getattr(console, "headless", False) and (DEBUG_MODE or not console.is_interactive): + if not getattr(console, "headless", False) and (not console.is_interactive or live_status_disabled()): logger.info(message) status = StackedStatus(console.render_str(message), console=console, spinner="arc") diff --git a/odev/common/ssh_crypt.py b/odev/common/ssh_crypt.py index ea684ef85..c1c33ddc4 100644 --- a/odev/common/ssh_crypt.py +++ b/odev/common/ssh_crypt.py @@ -8,11 +8,15 @@ import random from collections import deque from hashlib import sha3_256 +from typing import TYPE_CHECKING from cryptography.hazmat.backends import default_backend from cryptography.hazmat.primitives import padding from cryptography.hazmat.primitives.ciphers import Cipher, algorithms, modes -from paramiko.agent import AgentKey + + +if TYPE_CHECKING: + from paramiko.agent import AgentKey VALID_SSH_NAME = ["ssh-rsa", "ssh-ed25519"] @@ -105,7 +109,7 @@ def decode(self, data: bytes) -> bytes: class Encryptor: """High-level encryptor using SSH agent.""" - def __init__(self, ssh_key: AgentKey, binary: bool = False): + def __init__(self, ssh_key: "AgentKey", binary: bool = False): """Initialize the encryptor. :param ssh_key: The SSH key to use for signing. @@ -143,7 +147,7 @@ def send(self, data: bytes) -> bytes: class Decryptor: """High-level decryptor using SSH agent.""" - def __init__(self, ssh_key: AgentKey, binary: bool = False): + def __init__(self, ssh_key: "AgentKey", binary: bool = False): """Initialize the decryptor. :param ssh_key: The SSH key to use for signing. @@ -200,7 +204,7 @@ def send(self, data: bytes) -> bytes: return self.decoder.decode(raw_data) -def encrypt(data: str | bytes, ssh_key: AgentKey, binary: bool = False) -> bytes: +def encrypt(data: str | bytes, ssh_key: "AgentKey", binary: bool = False) -> bytes: """Encrypt data using an SSH key. :param data: The data to encrypt. @@ -218,7 +222,7 @@ def encrypt(data: str | bytes, ssh_key: AgentKey, binary: bool = False) -> bytes class E: """A wrapper for decrypting data lazily or as a string.""" - def __init__(self, data: str | bytes, ssh_key: AgentKey, binary: bool = False): + def __init__(self, data: str | bytes, ssh_key: "AgentKey", binary: bool = False): """Initialize the decryptor wrapper. :param data: The encrypted data. diff --git a/odev/common/store/tables/secrets.py b/odev/common/store/tables/secrets.py index eba6c5513..3be1bd2d4 100644 --- a/odev/common/store/tables/secrets.py +++ b/odev/common/store/tables/secrets.py @@ -2,17 +2,17 @@ from base64 import b64decode, b64encode from collections.abc import Sequence from dataclasses import dataclass -from typing import Literal - -from paramiko.agent import Agent as SSHAgent, AgentKey -from paramiko.ssh_exception import SSHException +from typing import TYPE_CHECKING, Literal from odev.common.config import Config from odev.common.console import console from odev.common.errors import OdevError from odev.common.logging import logging from odev.common.postgres import PostgresTable -from odev.common.ssh_crypt import E as ssh_decrypt, encrypt as ssh_encrypt # noqa: N811 + + +if TYPE_CHECKING: + from paramiko.agent import AgentKey logger = logging.getLogger(__name__) @@ -68,8 +68,10 @@ class SecretStore(PostgresTable): """Configuration parameters.""" @classmethod - def _list_ssh_keys(cls) -> list[AgentKey]: + def _list_ssh_keys(cls) -> list["AgentKey"]: """List all SSH keys available in the ssh-agent.""" + from paramiko.agent import Agent as SSHAgent # noqa: PLC0415 - importing paramiko is expensive + keys = list(SSHAgent().get_keys()) if not keys and not os.environ.get("ODEV_NO_SSH_AGENT"): @@ -93,6 +95,10 @@ def encrypt(cls, plaintext: str) -> str: :return: The encrypted string. :rtype: str """ + from paramiko.ssh_exception import SSHException # noqa: PLC0415 - importing paramiko is expensive + + from odev.common.ssh_crypt import encrypt as ssh_encrypt # noqa: PLC0415 + ciphered: str | None = None keys = cls._list_ssh_keys() @@ -121,6 +127,10 @@ def decrypt(cls, ciphertext: str) -> str: :return: The decrypted string. :rtype: str """ + from paramiko.ssh_exception import SSHException # noqa: PLC0415 - importing paramiko is expensive + + from odev.common.ssh_crypt import E as ssh_decrypt # noqa: N811, PLC0415 + deciphered: str | None = None keys = cls._list_ssh_keys() diff --git a/odev/common/telemetry.py b/odev/common/telemetry.py index 26f9c64ec..6fe2f1347 100644 --- a/odev/common/telemetry.py +++ b/odev/common/telemetry.py @@ -1,19 +1,28 @@ -"""Telemetry module for odev.""" +"""Telemetry module for odev. + +Reporting a command must never delay the CLI: waiting for the telemetry endpoint after a command printed its result +is directly perceptible to the user. Records are therefore written to a local spool file when a command completes, +and submitted in the background by a later odev run, which has the whole duration of its own command to do so. +""" import json import re import threading import uuid -from queue import Queue -from time import monotonic +from pathlib import Path +from typing import TYPE_CHECKING, Any from urllib.error import URLError from urllib.request import Request, urlopen -from odev.common.commands.base import Command +from odev.common.config import CONFIG_DIR from odev.common.logging import logging from odev.common.utils import EmployeeUtils +if TYPE_CHECKING: + from odev.common.commands.base import Command + + logger = logging.getLogger(__name__) TELEMETRY_ENDPOINT = "https://odev-telemetry.odoo.com" @@ -23,6 +32,44 @@ # This is not ideal but it will already prevent most automated bots from sending fake data. TELEMETRY_KEY = "xEGGxJLlTuRfGO8f5STWpehXKGRB8RbVpo3DgWYA7nJquh16I5Q59SU+ucyhcZoy" +REQUEST_TIMEOUT = 1 +"""Timeout in seconds for a single request to the telemetry endpoint.""" + +MAX_SPOOLED_RECORDS = 100 +"""Number of records kept in the spool file when the endpoint cannot be reached. + +Old records are dropped past this limit so that a long-lasting outage cannot grow the file indefinitely. +""" + + +class TelemetryRun: + """Handle on the telemetry record of a single command. + + The record is only complete once the command finished, since it carries its exit code and execution time. + Callers must therefore signal completion through :meth:`finish`, which spools the record for submission. + """ + + def __init__(self, telemetry: "Telemetry", payload: dict[str, Any]): + self.telemetry: Telemetry = telemetry + """Telemetry manager this record belongs to.""" + + self.payload: dict[str, Any] = payload + """Data describing the command being reported.""" + + def finish(self, exit_code: int = 0, execution_time: float = 0.0) -> None: + """Complete the record with the outcome of the command and spool it for submission. + + :param exit_code: Exit code of the command. + :param execution_time: Time the command took to run, in minutes. + """ + self.telemetry.spool( + { + "payload": self.payload, + "exit_code": exit_code, + "execution_time": execution_time, + } + ) + class Telemetry: """Telemetry manager.""" @@ -30,6 +77,11 @@ class Telemetry: def __init__(self, odev): self.odev = odev + @property + def spool_path(self) -> Path: + """Path to the file holding the telemetry records awaiting submission.""" + return CONFIG_DIR / f"{self.odev.name}-telemetry.jsonl" + def _get_client_id(self) -> str: """Get or generate the client ID.""" client_id = self.odev.config.telemetry.client_id @@ -55,7 +107,24 @@ def _prepare_request(self, path: str, payload: dict) -> Request: data=data, ) - def _sanitize_arguments(self, command: Command) -> tuple[str, str]: + def _send_request(self, path: str, payload: dict) -> dict[str, Any] | None: + """Send telemetry data to the given endpoint and return the decoded response. + + :param path: Path of the endpoint to send the data to. + :param payload: Data to send. + :return: The decoded response, or None if the data could not be sent. + """ + try: + with urlopen(self._prepare_request(path, payload), timeout=REQUEST_TIMEOUT) as response: # noqa: S310 + return json.loads(response.read()) + except (URLError, OSError) as error: + logger.debug(f"Telemetry failed: {error}") + except json.JSONDecodeError as error: + logger.debug(f"Telemetry returned an invalid response: {error}") + + return None + + def _sanitize_arguments(self, command: "Command") -> tuple[str, str]: """Sanitize arguments for telemetry so that sensitive data is not sent.""" arguments = " ".join(command._argv) if command._argv else "" additional_args = "" @@ -88,17 +157,25 @@ def _sanitize_arguments(self, command: Command) -> tuple[str, str]: return arguments, additional_args - def send(self, command: Command) -> tuple[threading.Thread, Queue] | None: - """Send telemetry data.""" + def send(self, command: "Command") -> TelemetryRun | None: + """Start recording the execution of a command. + + The returned handle must be completed through :meth:`TelemetryRun.finish` once the command is done, so that + its exit code and execution time are recorded as well. + + :param command: The command being run. + :return: A handle on the record, or None if this command must not be reported. + """ if len(self.odev._command_stack) != 1 or self.odev.in_test_mode: return None + enabled = self.odev.config.telemetry.enabled payload = { "client_id": self._get_client_id(), - "is_telemetry_agreed": self.odev.config.telemetry.enabled, + "is_telemetry_agreed": enabled, } - if self.odev.config.telemetry.enabled: + if enabled: args, additional_args = self._sanitize_arguments(command) payload.update( { @@ -114,42 +191,100 @@ def send(self, command: Command) -> tuple[threading.Thread, Queue] | None: } ) - def _send(_queue: Queue): - try: - request = self._prepare_request("odev/telemetry", payload) + return TelemetryRun(self, payload) - with urlopen(request, timeout=1) as response: # noqa: S310 - content = response.read() + def spool(self, record: dict[str, Any]) -> None: + """Append a record to the spool file, to be submitted by a later run. - result = json.loads(content).get("result", {}).get("id") - _queue.put(result) - except (URLError, OSError) as e: - logger.debug(f"Telemetry failed: {e}") - _queue.put(None) + :param record: The record to spool. + """ + try: + self.spool_path.parent.mkdir(parents=True, exist_ok=True) - queue = Queue(maxsize=1) - thread = threading.Thread(target=_send, args=(queue,)) - thread.start() - return thread, queue + with self.spool_path.open("a", encoding="utf-8") as spool: + spool.write(json.dumps(record) + "\n") + except OSError as error: + logger.debug(f"Failed to spool telemetry: {error}") - def update(self, line_id: int) -> None: - """Update a specific line in the telemetry data.""" - if len(self.odev._command_stack) != 1 or self.odev.in_test_mode: + def flush(self) -> None: + """Submit the records spooled by previous runs in a background thread. + + The thread is a daemon: whatever it did not manage to send stays in the spool and is retried by the next + run, so that exiting odev never waits on the telemetry endpoint. + """ + if self.odev.in_test_mode or not self.spool_path.is_file(): return - payload = { - "telemetry_id": line_id, - "exit_code": 0, - "execution_time": (monotonic() - self.odev.start_time) / 60, - } + threading.Thread(target=self._flush, name="odev-telemetry", daemon=True).start() + + def _flush(self) -> None: + """Submit every spooled record, keeping in the spool the ones that could not be sent.""" + records = self._claim_spooled_records() + + if not records: + return + + logger.debug(f"Submitting {len(records)} spooled telemetry records") + unsent = [record for record in records if not self._submit(record)] + + if unsent: + self._respool(unsent) + + def _claim_spooled_records(self) -> list[dict[str, Any]]: + """Read the spooled records and empty the spool file so that they are not submitted twice. + + :return: The records that were waiting in the spool. + """ + records: list[dict[str, Any]] = [] - def _update(): + try: + with self.spool_path.open("r+", encoding="utf-8") as spool: + lines = spool.readlines() + spool.seek(0) + spool.truncate() + except OSError as error: + logger.debug(f"Failed to read spooled telemetry: {error}") + return records + + for line in lines: try: - request = self._prepare_request("odev/telemetry/update", payload) + records.append(json.loads(line)) + except json.JSONDecodeError: + logger.debug(f"Discarding malformed telemetry record: {line.strip()!r}") + + return records + + def _respool(self, records: list[dict[str, Any]]) -> None: + """Put records that could not be submitted back into the spool. + + :param records: The records to keep for a later run. + """ + for record in records[-MAX_SPOOLED_RECORDS:]: + self.spool(record) + + def _submit(self, record: dict[str, Any]) -> bool: + """Submit a single spooled record to the telemetry endpoint. - with urlopen(request, timeout=1): # noqa: S310 - pass - except (URLError, OSError) as e: - logger.debug(f"Telemetry failed: {e}") + :param record: The record to submit. + :return: Whether the record was submitted successfully. + """ + response = self._send_request("odev/telemetry", record["payload"]) + + if response is None: + return False + + line_id = response.get("result", {}).get("id") + + if line_id is None or not record["payload"].get("is_telemetry_agreed"): + return True + + self._send_request( + "odev/telemetry/update", + { + "telemetry_id": line_id, + "exit_code": record["exit_code"], + "execution_time": record["execution_time"], + }, + ) - threading.Thread(target=_update).start() + return True diff --git a/odev/common/utils.py b/odev/common/utils.py index 595e467fa..5377c0277 100644 --- a/odev/common/utils.py +++ b/odev/common/utils.py @@ -1,6 +1,7 @@ """Utility classes and functions for odev.""" from odev.common import bash +from odev.common.config import XGRAM_UNKNOWN from odev.common.logging import logging @@ -16,6 +17,22 @@ def __init__(self, odev): def get_xgram(self) -> str | None: """Get the user's xgram from their Odoo email. + The result is cached in the configuration file: resolving it requires a vault lookup and a call to git, + which would otherwise be paid on every single odev invocation. + """ + cached = self.odev.config.user.xgram + + if cached != XGRAM_UNKNOWN: + return cached or None + + xgram = self._resolve_xgram() + self.odev.config.user.xgram = xgram or "" + + return xgram + + def _resolve_xgram(self) -> str | None: + """Resolve the user's xgram from their Odoo email. + Checks secrets first, then falls back to git configuration. """ # 1. Try from secrets diff --git a/tests/fixtures/capture.py b/tests/fixtures/capture.py index 37297bd22..b702949cd 100644 --- a/tests/fixtures/capture.py +++ b/tests/fixtures/capture.py @@ -24,6 +24,7 @@ def __init__(self): self._stderr_value = "" self._stdout_handler = None self._stderr_handler = None + self._root_level = logging.NOTSET def __enter__(self): self._stdout = StringIO() @@ -33,12 +34,18 @@ def __enter__(self): sys.stdout = self._stdout sys.stderr = self._stderr + # Capture on the root logger rather than on each existing one: command modules are only imported when their + # command runs, so their logger does not exist yet when the capture starts. + root = logging.getLogger() + self._root_level = root.level + root.setLevel(logging.INFO) + root.addHandler(self._stdout_handler) + root.addHandler(self._stderr_handler) + for logger in logging.Logger.manager.loggerDict.values(): if isinstance(logger, logging.Logger): logger.propagate = True logger.setLevel(logging.INFO) - logger.addHandler(self._stdout_handler) - logger.addHandler(self._stderr_handler) return self @@ -46,10 +53,10 @@ def __exit__(self, *args): if self._stdout_handler is None or self._stderr_handler is None: raise AssertionError("CaptureOutput not properly initialized") - for logger in logging.Logger.manager.loggerDict.values(): - if isinstance(logger, logging.Logger): - logger.removeHandler(self._stdout_handler) - logger.removeHandler(self._stderr_handler) + root = logging.getLogger() + root.removeHandler(self._stdout_handler) + root.removeHandler(self._stderr_handler) + root.setLevel(self._root_level) if self._stderr is None or self._stdout is None: raise AssertionError("CaptureOutput streams not properly initialized") diff --git a/tests/fixtures/case.py b/tests/fixtures/case.py index 5d17f7dc4..81de06ac0 100644 --- a/tests/fixtures/case.py +++ b/tests/fixtures/case.py @@ -182,8 +182,8 @@ def _patch_object( def __patch_cli(cls): """Patch interactions with the CLI to avoid waiting for user input or showing live status during tests.""" cls._patch_object("odev.common.console.Console", properties=[("bypass_prompt", True)]) - cls._patch_object("odev.common.debug", [("DEBUG_MODE", True)]) - cls._patch_object("odev.common.progress", [("DEBUG_MODE", True)]) + cls._patch_object("odev.common.debug", [("debug_mode", True)]) + cls._patch_object("odev.common.progress", [("live_status_disabled", True)]) @classmethod def __patch_framework(cls): diff --git a/tests/tests/common/test_odev.py b/tests/tests/common/test_odev.py index 146abed80..0d24ec0c8 100644 --- a/tests/tests/common/test_odev.py +++ b/tests/tests/common/test_odev.py @@ -81,9 +81,15 @@ class FirstCommand(Command): class SecondCommand(Command): _name = "duplicate" + module_path = Path(__file__) + with ( self.assertRaises(ValueError) as error, - self.patch(self.odev, "import_commands", return_value=[FirstCommand, SecondCommand]), + self.patch( + self.odev, + "import_commands", + return_value=[(FirstCommand, module_path), (SecondCommand, module_path)], + ), ): self.odev.register_commands() diff --git a/tests/tests/common/test_startup_performance.py b/tests/tests/common/test_startup_performance.py new file mode 100644 index 000000000..fd902ad3e --- /dev/null +++ b/tests/tests/common/test_startup_performance.py @@ -0,0 +1,117 @@ +"""Guard the cost odev pays before running the command it was asked to run. + +Startup is paid by every single invocation, so an import creeping back into the framework's module graph is a +regression the whole tool feels. Timings are too noisy to assert on, so these tests check the structural cause +instead: what got imported, and when. +""" + +import subprocess +import sys +from pathlib import Path +from unittest import TestCase + + +REPOSITORY_PATH = Path(__file__).parents[3] +"""Path to the odev repository, from which the probed process is started.""" + +PROBE_MARKER = "ODEV_PROBE:" +"""Prefix identifying the result of a probe among everything odev itself prints.""" + +PROBE_PREAMBLE = f""" +PROBE = {PROBE_MARKER!r} +import sys +sys.argv = ["odev", "version"] +from odev.common import init_framework +framework = init_framework() +""" +"""Source prepended to every probe, leaving it an initialized but not yet started framework.""" + +HEAVY_MODULES = ( + "black", + "copier", + "github", + "InquirerPy", + "networkx", + "paramiko", + "prompt_toolkit", +) +"""Third-party modules that are expensive to import and that the framework must not need in order to start. + +Each is only useful to a fraction of odev's commands: a GitHub API client, an SSH agent client, a code formatter, +a project scaffolder, a graph library and an interactive prompt toolkit. They belong at their point of use. +""" + + +class TestStartupPerformance(TestCase): + """Check that odev does not import what it does not need in order to start.""" + + def probe(self, source: str) -> str: + """Run a snippet in a fresh interpreter and return what it reported. + + A subprocess is required: whatever the test suite itself imported would otherwise pollute the measurement. + + :param source: Python source to run, on top of :data:`PROBE_PREAMBLE`. + :return: The line the snippet printed, without its marker. + :rtype: str + """ + process = subprocess.run( # noqa: S603 + [sys.executable, "-c", source], + cwd=REPOSITORY_PATH, + capture_output=True, + text=True, + check=False, + ) + + self.assertEqual(process.returncode, 0, f"Probe failed:\n{process.stderr}") + + # Odev writes to stdout as well, only the marked line holds the result. + reported = next((line for line in process.stdout.splitlines() if line.startswith(PROBE_MARKER)), None) + self.assertIsNotNone(reported, f"Probe did not report anything:\n{process.stdout}\n{process.stderr}") + + return str(reported).removeprefix(PROBE_MARKER) + + def test_01_importing_the_framework_stays_lean(self): + """Importing odev must not pull in the dependencies only a few of its commands need.""" + reported = self.probe( + f"import odev.common\nimport sys\nprint({PROBE_MARKER!r} + ' '.join(" + f"name for name in {HEAVY_MODULES!r} if name in sys.modules))" + ) + imported = set(reported.split()) + + self.assertEqual( + imported, + set(), + f"Importing odev.common pulled in {', '.join(sorted(imported))}. " + "Import those where they are used, so that commands that do not need them do not pay for them.", + ) + + def test_02_starting_the_framework_imports_no_command(self): + """Starting the framework must know every command without executing any of their modules. + + A command module imports whatever its command needs at module level, so importing all of them to discover + their names makes every invocation pay for every command, plugins included. + """ + reported = self.probe( + f"{PROBE_PREAMBLE}\n" + "framework.start()\n" + "print(PROBE + f'{len(framework.commands.entries)} {len(framework.commands.classes)}')\n" + ) + known, imported = (int(value) for value in reported.split()) + + self.assertGreater(known, 0, "The framework did not register any command") + self.assertEqual(imported, 0, f"Starting the framework imported {imported} command modules, expected none") + + def test_03_running_a_command_imports_only_that_command(self): + """Resolving a command must import that command alone, not the ones registered alongside it.""" + reported = self.probe( + f"{PROBE_PREAMBLE}\n" + "framework.start()\n" + "framework.commands['version']\n" + "print(PROBE + ' '.join(sorted(framework.commands.classes)))\n" + ) + + self.assertEqual( + reported.split(), + ["version"], + f"Resolving the 'version' command imported '{reported.strip()}', expected only 'version'", + ) diff --git a/tools/benchmark_startup.py b/tools/benchmark_startup.py new file mode 100644 index 000000000..64cf27ff6 --- /dev/null +++ b/tools/benchmark_startup.py @@ -0,0 +1,140 @@ +#!/usr/bin/env python3 +"""Measure how long odev takes to start up and shut down. + +Every odev invocation pays the framework's startup cost before the command it was asked to run even begins, and +pays an exit cost after that command printed its result. Both are directly perceptible for a tool run dozens of +times a day, so this script reports them separately instead of a single wall-clock number. + +Usage: + ~/.config/odev/venv/bin/python tools/benchmark_startup.py [--runs N] [--command NAME] +""" + +import argparse +import statistics +import subprocess +import sys +import time +from pathlib import Path + + +REPOSITORY_PATH = Path(__file__).parents[1] +"""Path to the odev repository, from which the measured process is started.""" + +HEAVY_MODULES = ("copier", "networkx", "black", "github", "paramiko", "InquirerPy", "prompt_toolkit") +"""Third-party modules that are expensive to import and that a trivial command has no reason to load.""" + +PHASES_PROBE = """ +import sys +from time import monotonic + +start = monotonic() +from odev.common import init_framework +imported = monotonic() + +odev = init_framework() +odev.start(start) +started = monotonic() + +odev.dispatch() +dispatched = monotonic() + +heavy = [module for module in {heavy!r} if module in sys.modules] +print( + f"PROBE {{imported - start}} {{started - imported}} {{dispatched - started}} {{len(sys.modules)}} {{','.join(heavy)}}", + file=sys.stderr, +) +""" + + +def measure_process(command: str) -> tuple[float, float]: + """Run odev in a subprocess and measure its total duration and its exit tail. + + The exit tail is the time between the last byte the command wrote and the moment the process actually died: it + covers everything odev still does once the user can already read the result. + + :param command: Name of the odev command to run. + :return: The total duration and the exit tail, both in seconds. + :rtype: Tuple[float, float] + """ + start = time.monotonic() + process = subprocess.Popen( # noqa: S603 + [sys.executable, "main.py", command], + cwd=REPOSITORY_PATH, + stdout=subprocess.PIPE, + stderr=subprocess.STDOUT, + ) + + last_output = start + + for _ in process.stdout: # type: ignore [union-attr] + last_output = time.monotonic() + + process.wait() + end = time.monotonic() + + return end - start, end - last_output + + +def measure_phases(command: str) -> tuple[list[float], int, list[str]]: + """Measure the duration of each startup phase from inside the process. + + :param command: Name of the odev command to run. + :return: The duration of the import, start and dispatch phases, the number of imported modules and the heavy + modules that were loaded. + :rtype: Tuple[List[float], int, List[str]] + """ + probe = PHASES_PROBE.format(heavy=list(HEAVY_MODULES)) + process = subprocess.run( # noqa: S603 + [sys.executable, "-c", probe, command], + cwd=REPOSITORY_PATH, + capture_output=True, + text=True, + check=False, + ) + + line = next((line for line in process.stderr.splitlines() if line.startswith("PROBE ")), None) + + if line is None: + raise RuntimeError(f"Probe did not report any timing:\n{process.stderr}") + + _, imports, start, dispatch, modules, heavy = line.split(" ") + + return [float(imports), float(start), float(dispatch)], int(modules), [name for name in heavy.split(",") if name] + + +def main() -> int: + """Run the benchmark and print its report.""" + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("--runs", type=int, default=10, help="Number of times the command is run (default: 10)") + parser.add_argument("--command", default="version", help="Odev command to measure (default: version)") + arguments = parser.parse_args() + + print(f"Measuring 'odev {arguments.command}' over {arguments.runs} runs...\n") + + totals: list[float] = [] + tails: list[float] = [] + + for _ in range(arguments.runs): + total, tail = measure_process(arguments.command) + totals.append(total) + tails.append(tail) + + phases, modules, heavy = measure_phases(arguments.command) + + print(f"{'Phase':<28} {'Median':>9} {'Min':>9}") + print("-" * 48) + print(f"{'import odev.common':<28} {phases[0]:>8.3f}s {'':>9}") + print(f"{'init_framework + start':<28} {phases[1]:>8.3f}s {'':>9}") + print(f"{'dispatch (command)':<28} {phases[2]:>8.3f}s {'':>9}") + print(f"{'exit tail':<28} {statistics.median(tails):>8.3f}s {min(tails):>8.3f}s") + print("-" * 48) + print(f"{'total wall clock':<28} {statistics.median(totals):>8.3f}s {min(totals):>8.3f}s") + + print(f"\nImported modules: {modules}") + print(f"Heavy modules loaded: {', '.join(heavy) if heavy else 'none'}") + + return 0 + + +if __name__ == "__main__": + sys.exit(main()) From f01d03f47bdb4269d2be0b6111d03a634d2ede42 Mon Sep 17 00:00:00 2001 From: brinkflew Date: Sun, 26 Jul 2026 20:19:17 +0200 Subject: [PATCH 2/3] [FIX] tests: warm the command index before asserting it stays lazy The first run of a new version has no index yet and legitimately imports every command to build one, so the startup tests only passed on a machine where a previous run had already warmed it up. On a clean checkout they measured the cold path and failed, and test_03 only passed because test_02 happened to run first and leave an index behind. Claude-Session: https://claude.ai/code/session_012tWyDuUYenE92nsBtG19Du --- tests/tests/common/test_startup_performance.py | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/tests/tests/common/test_startup_performance.py b/tests/tests/common/test_startup_performance.py index fd902ad3e..ec443aaea 100644 --- a/tests/tests/common/test_startup_performance.py +++ b/tests/tests/common/test_startup_performance.py @@ -70,6 +70,14 @@ def probe(self, source: str) -> str: return str(reported).removeprefix(PROBE_MARKER) + def warm_up_command_index(self) -> None: + """Make sure the commands were already discovered once before measuring. + + The first run of a new version has no index yet and legitimately imports every command to build one. What + must stay free is every run after it, so give the index a chance to exist first. + """ + self.probe(f"{PROBE_PREAMBLE}\nframework.start()\nprint(PROBE + 'warmed')\n") + def test_01_importing_the_framework_stays_lean(self): """Importing odev must not pull in the dependencies only a few of its commands need.""" reported = self.probe( @@ -91,6 +99,8 @@ def test_02_starting_the_framework_imports_no_command(self): A command module imports whatever its command needs at module level, so importing all of them to discover their names makes every invocation pay for every command, plugins included. """ + self.warm_up_command_index() + reported = self.probe( f"{PROBE_PREAMBLE}\n" "framework.start()\n" @@ -103,6 +113,8 @@ def test_02_starting_the_framework_imports_no_command(self): def test_03_running_a_command_imports_only_that_command(self): """Resolving a command must import that command alone, not the ones registered alongside it.""" + self.warm_up_command_index() + reported = self.probe( f"{PROBE_PREAMBLE}\n" "framework.start()\n" From 2b6f2956a7c5067cbe8fce843ea467805a28caac Mon Sep 17 00:00:00 2001 From: brinkflew Date: Sun, 26 Jul 2026 20:20:38 +0200 Subject: [PATCH 3/3] [FIX] tooling: mark the startup benchmark as executable The script carries a shebang and is meant to be run directly, which ruff enforces through EXE001. The mode bit went unnoticed locally because the working tree lives on a filesystem that does not report it faithfully. Claude-Session: https://claude.ai/code/session_012tWyDuUYenE92nsBtG19Du --- tools/benchmark_startup.py | 0 1 file changed, 0 insertions(+), 0 deletions(-) mode change 100644 => 100755 tools/benchmark_startup.py diff --git a/tools/benchmark_startup.py b/tools/benchmark_startup.py old mode 100644 new mode 100755