Instrument lockfile discovery, refresh, and validation (#91)

.github/workflows/ci.yml

@@ -25,7 +25,11 @@ jobs:
 
       - name: Install CLI tools
         run: |
-          for tool in mbake ty ruff; do uv tool install ${tool}; done
+          for tool in mbake ty; do uv tool install ${tool}; done
+          # Pin ruff to the same version as the dev dependency group in
+          # pyproject.toml so the linter behaves identically across the uv tool,
+          # the synced virtualenv, and developer PATH. Bump both sites together.
+          uv tool install ruff==0.15.12
           npm install -g markdownlint-cli2
 
       - name: Validate Makefile

docs/developers-guide.md

@@ -626,6 +626,15 @@ Defined metrics:
 | Metric                           | Labels                        | Incremented when                                                                                                      |
 | -------------------------------- | ----------------------------- | --------------------------------------------------------------------------------------------------------------------- |
 | `publish.index_lookup_downgrade` | `subcommand`, `missing_crate` | `_handle_index_missing_version` downgrades a crates.io index-lookup failure to a warning (in-plan, override enabled). |
+| `lockfile.discovered`            | (none)                        | Incremented by the number of tracked lockfiles each `discover_tracked_lockfiles` call returns.                        |
+| `lockfile.refresh`               | `outcome`                     | One increment per `refresh_lockfile` invocation; `outcome` is `success` or `failure`.                                 |
+| `lockfile.refresh.duration`      | (none)                        | Duration observation around each `cargo generate-lockfile` invocation.                                                |
+| `lockfile.validate`              | `outcome`                     | One increment per `validate_lockfile_freshness` call; `outcome` is `fresh`, `stale`, or `failed`.                     |
+| `lockfile.validate.duration`     | (none)                        | Duration observation around each `cargo metadata --locked` probe.                                                     |
+
+Duration metrics aggregate a count and total seconds per label set via
+`observe_duration` / `duration_stats` and appear in the exit summary with
+`count` and `total_seconds` fields.
 
 ### Command runners (`lading.runtime`)
 

lading/commands/lockfile.py

@@ -31,10 +31,12 @@
 import collections.abc as cabc
 import dataclasses as dc
 import logging
+import time
 import typing as typ
 from pathlib import Path
 
 from lading.exceptions import LadingError
+from lading.utils import metrics
 from lading.utils.process import append_detail, command_detail, with_detail
 
 if typ.TYPE_CHECKING:
@@ -43,6 +45,13 @@
 LOGGER = logging.getLogger(__name__)
 _ManifestExists = cabc.Callable[[Path], bool]
 
+# Metric names (issue #91); documented in docs/developers-guide.md.
+DISCOVERED_LOCKFILES_METRIC = "lockfile.discovered"
+REFRESH_METRIC = "lockfile.refresh"
+REFRESH_DURATION_METRIC = "lockfile.refresh.duration"
+VALIDATE_METRIC = "lockfile.validate"
+VALIDATE_DURATION_METRIC = "lockfile.validate.duration"
+
 
 class LockfileRefreshError(LadingError):
     """Raised when Cargo cannot regenerate a lockfile."""
@@ -153,6 +162,7 @@ def discover_tracked_lockfiles(
     if error_result is not None:
         return error_result
     lockfiles = _lockfiles_with_manifests(stdout, workspace_root, manifest_exists)
+    metrics.increment_counter(DISCOVERED_LOCKFILES_METRIC, amount=len(lockfiles))
     LOGGER.info(
         "Discovered %d tracked lockfile(s) with adjacent manifests in %s",
         len(lockfiles),
@@ -189,13 +199,17 @@ def refresh_lockfile(
     """
     lockfile_path = manifest_path.parent / "Cargo.lock"
     LOGGER.info("Refreshing %s", lockfile_path)
+    started_at = time.perf_counter()
     exit_code, stdout, stderr = runner(
         ("cargo", "generate-lockfile", "--manifest-path", str(manifest_path)),
         cwd=manifest_path.parent,
     )
+    metrics.observe_duration(REFRESH_DURATION_METRIC, time.perf_counter() - started_at)
     if exit_code != 0:
+        metrics.increment_counter(REFRESH_METRIC, outcome="failure")
         message = with_detail(f"Failed to refresh {lockfile_path}", stdout, stderr)
         raise LockfileRefreshError(message)
+    metrics.increment_counter(REFRESH_METRIC, outcome="success")
     LOGGER.info("Refreshed %s", lockfile_path)
     return lockfile_path
 
@@ -221,6 +235,7 @@ def validate_lockfile_freshness(
         because Cargo says it needs updating under ``--locked``, or failed for
         another reason.
     """
+    started_at = time.perf_counter()
     exit_code, stdout, stderr = runner(
         (
             "cargo",
@@ -232,12 +247,14 @@ def validate_lockfile_freshness(
         ),
         cwd=manifest_path.parent,
     )
+    metrics.observe_duration(VALIDATE_DURATION_METRIC, time.perf_counter() - started_at)
     detail = command_detail(stdout, stderr)
     is_fresh = exit_code == 0
     is_stale = _is_lockfile_stale_detail(detail)
     state = "fresh"
     if not is_fresh:
         state = "stale" if is_stale else "failed"
+    metrics.increment_counter(VALIDATE_METRIC, outcome=state)
     LOGGER.info(
         "Validated lockfile freshness for %s: %s",
         manifest_path,

lading/utils/metrics.py

@@ -23,6 +23,7 @@
 
 import atexit
 import collections
+import dataclasses as dc
 import json
 import logging
 import threading
@@ -34,6 +35,17 @@
 _summary_hook_registered = threading.Event()
 
 
+@dc.dataclass(slots=True)
+class DurationStats:
+    """Aggregated duration observations for one metric/label set."""
+
+    count: int = 0
+    total_seconds: float = 0.0
+
+
+_DURATIONS: dict[_CounterKey, DurationStats] = {}
+
+
 def _counter_key(name: str, labels: dict[str, str]) -> _CounterKey:
     """Return the registry key for ``name`` with sorted ``labels``."""
     return (name, tuple(sorted(labels.items())))
@@ -56,6 +68,30 @@ def counter_value(name: str, **labels: str) -> int:
         return _COUNTERS[_counter_key(name, labels)]
 
 
+def observe_duration(name: str, seconds: float, **labels: str) -> None:
+    """Record one duration observation for ``name``.
+
+    Examples
+    --------
+    >>> observe_duration("demo.duration", 0.25, operation="refresh")
+    """
+    with _LOCK:
+        stats = _DURATIONS.setdefault(_counter_key(name, labels), DurationStats())
+        stats.count += 1
+        stats.total_seconds += seconds
+
+
+def duration_stats(name: str, **labels: str) -> DurationStats:
+    """Return the aggregated durations recorded for ``name``."""
+    with _LOCK:
+        stats = _DURATIONS.get(_counter_key(name, labels))
+        return (
+            DurationStats()
+            if stats is None
+            else DurationStats(stats.count, stats.total_seconds)
+        )
+
+
 def snapshot() -> dict[_CounterKey, int]:
     """Return a copy of the counter registry for assertions."""
     with _LOCK:
@@ -66,6 +102,7 @@ def reset() -> None:
     """Clear all recorded metrics; intended for test isolation."""
     with _LOCK:
         _COUNTERS.clear()
+        _DURATIONS.clear()
 
 
 def emit_summary() -> None:
@@ -74,12 +111,21 @@ def emit_summary() -> None:
     Emits nothing when no metrics were recorded, so quiet runs stay quiet.
     """
     with _LOCK:
-        if not _COUNTERS:
+        if not _COUNTERS and not _DURATIONS:
             return
-        rendered = [
+        rendered: list[dict[str, object]] = [
             {"metric": name, "labels": dict(labels), "value": value}
             for (name, labels), value in sorted(_COUNTERS.items())
         ]
+        rendered.extend(
+            {
+                "metric": name,
+                "labels": dict(labels),
+                "count": stats.count,
+                "total_seconds": round(stats.total_seconds, 6),
+            }
+            for (name, labels), stats in sorted(_DURATIONS.items())
+        )
     _LOGGER.info("lading metrics summary: %s", json.dumps(rendered))
 
 
@@ -99,9 +145,12 @@ def register_summary_atexit() -> None:
 
 
 __all__ = [
+    "DurationStats",
     "counter_value",
+    "duration_stats",
     "emit_summary",
     "increment_counter",
+    "observe_duration",
     "register_summary_atexit",
     "reset",
     "snapshot",

pyproject.toml

@@ -32,7 +32,12 @@ dev = [
     "pytest",
     "pytest-bdd",
     "pytest-cov",
-    "ruff",
+    # Pin ruff so the lockfile-installed linter matches the version CI installs
+    # as a uv tool (.github/workflows/ci.yml) and the one developers run from
+    # PATH. Keeping them identical avoids version-skew lint failures such as
+    # preview-only rules firing in one environment but not another. Bump both
+    # sites together.
+    "ruff==0.15.12",
     "pyright",
     "pytest-timeout",
     "cmd-mox@git+https://github.com/leynos/cmd-mox@f583c279a15760aba5cfd9bddf1fbbe9b1f8c429",

tests/unit/test_lockfile.py

@@ -11,6 +11,7 @@
 from hypothesis import given
 
 from lading.commands import lockfile
+from lading.utils import metrics
 
 # ---------------------------------------------------------------------------
 # Hypothesis strategies for _lockfiles_with_manifests property tests
@@ -332,3 +333,91 @@ def test_returned_paths_are_subset_of_git_stdout(stdout: str) -> None:
             f"Returned path {path} (relative: {relative!r}) "
             f"does not appear in git stdout lines: {tracked_lines!r}"
         )
+
+
+# ---------------------------------------------------------------------------
+# Metrics instrumentation (issue #91)
+# ---------------------------------------------------------------------------
+
+
+@pytest.fixture
+def _metrics_registry() -> cabc.Iterator[None]:
+    """Isolate the metric registry for instrumentation tests."""
+    metrics.reset()
+    yield
+    metrics.reset()
+
+
+def _static_runner(
+    exit_code: int, stdout: str, stderr: str
+) -> cabc.Callable[..., tuple[int, str, str]]:
+    """Return a runner producing a fixed result."""
+
+    def runner(
+        command: cabc.Sequence[str],
+        *,
+        cwd: Path | None = None,
+        env: cabc.Mapping[str, str] | None = None,
+    ) -> tuple[int, str, str]:
+        del command, cwd, env
+        return exit_code, stdout, stderr
+
+    return runner
+
+
+@pytest.mark.usefixtures("_metrics_registry")
+def test_discovery_records_lockfile_count(tmp_path: Path) -> None:
+    """Discovery increments the discovered-lockfiles counter by the count."""
+    (tmp_path / "Cargo.toml").write_text("", encoding="utf-8")
+    (tmp_path / "Cargo.lock").write_text("", encoding="utf-8")
+
+    lockfile.discover_tracked_lockfiles(tmp_path, _static_runner(0, "Cargo.lock\n", ""))
+
+    assert metrics.counter_value(lockfile.DISCOVERED_LOCKFILES_METRIC) == 1
+
+
+@pytest.mark.usefixtures("_metrics_registry")
+def test_refresh_records_success_outcome_and_duration(tmp_path: Path) -> None:
+    """A successful refresh counts a success and observes a duration."""
+    lockfile.refresh_lockfile(tmp_path / "Cargo.toml", _static_runner(0, "", ""))
+
+    assert metrics.counter_value(lockfile.REFRESH_METRIC, outcome="success") == 1
+    assert metrics.counter_value(lockfile.REFRESH_METRIC, outcome="failure") == 0
+    assert metrics.duration_stats(lockfile.REFRESH_DURATION_METRIC).count == 1
+
+
+@pytest.mark.usefixtures("_metrics_registry")
+def test_refresh_records_failure_outcome(tmp_path: Path) -> None:
+    """A failed refresh counts a failure and still observes a duration."""
+    with pytest.raises(lockfile.LockfileRefreshError):
+        lockfile.refresh_lockfile(
+            tmp_path / "Cargo.toml", _static_runner(101, "", "boom")
+        )
+
+    assert metrics.counter_value(lockfile.REFRESH_METRIC, outcome="failure") == 1
+    assert metrics.duration_stats(lockfile.REFRESH_DURATION_METRIC).count == 1
+
+
+@pytest.mark.usefixtures("_metrics_registry")
+@pytest.mark.parametrize(
+    ("exit_code", "stderr", "expected_state"),
+    [
+        (0, "", "fresh"),
+        (
+            101,
+            "the lock file needs to be updated but --locked was passed",
+            "stale",
+        ),
+        (101, "unrelated explosion", "failed"),
+    ],
+)
+def test_validation_records_outcome_and_duration(
+    tmp_path: Path, exit_code: int, stderr: str, expected_state: str
+) -> None:
+    """Validation counts each outcome state and observes a duration."""
+    lockfile.validate_lockfile_freshness(
+        tmp_path / "Cargo.toml", _static_runner(exit_code, "", stderr)
+    )
+
+    assert metrics.counter_value(lockfile.VALIDATE_METRIC, outcome=expected_state) == 1
+    assert metrics.duration_stats(lockfile.VALIDATE_DURATION_METRIC).count == 1

tests/unit/utils/test_metrics.py

@@ -3,6 +3,7 @@
 from __future__ import annotations
 
 import collections.abc as cabc
+import json
 import logging
 import operator
 import threading
@@ -161,6 +162,35 @@ def test_emit_summary_is_silent_without_metrics(
     assert not caplog.records
 
 
+def test_observe_duration_aggregates() -> None:
+    """Duration observations aggregate count and total seconds."""
+    metrics.observe_duration("demo.duration", 0.25, operation="refresh")
+    metrics.observe_duration("demo.duration", 0.5, operation="refresh")
+
+    stats = metrics.duration_stats("demo.duration", operation="refresh")
+    assert stats.count == 2
+    assert stats.total_seconds == pytest.approx(0.75)
+    assert metrics.duration_stats("demo.duration", operation="other").count == 0
+
+
+def test_emit_summary_includes_durations(caplog: LogCaptureFixture) -> None:
+    """The summary payload renders duration aggregates alongside counters."""
+    caplog.set_level(logging.INFO, logger="lading.utils.metrics")
+    metrics.observe_duration("demo.duration", 0.25)
+
+    metrics.emit_summary()
+
+    payload = json.loads(caplog.records[-1].getMessage().partition(": ")[2])
+    assert payload == [
+        {
+            "metric": "demo.duration",
+            "labels": {},
+            "count": 1,
+            "total_seconds": 0.25,
+        }
+    ]
+
+
 def test_register_summary_atexit_registers_once(
     monkeypatch: pytest.MonkeyPatch,
 ) -> None: