From 24bd13f9d9d35dbbe6e1d83163b71386650174ab Mon Sep 17 00:00:00 2001 From: Andraxion Date: Wed, 29 Jul 2026 05:07:16 -0400 Subject: [PATCH] Add structured compiler diagnostics --- DEVELOPMENT_NOTES.md | 39 ++++ Makefile | 11 +- README.md | 7 +- benchmarks/README.md | 18 ++ docs/MCP_CONTRACT.md | 6 + docs/USER_MANUAL.md | 15 +- schemas/result.schema.json | 136 +++++++++++- src/docforge/adapter_contract.py | 30 ++- src/docforge/cli.py | 26 ++- src/docforge/index.py | 21 ++ src/docforge/mcp_server.py | 167 +++++++++++--- src/docforge/project.py | 17 +- src/docforge/rendering.py | 24 +- src/docforge/telemetry.py | 220 ++++++++++++++++++ src/docforge/viewer_manager.py | 9 +- tests/test_adapter_contract.py | 48 ++++ tests/test_mcp_server.py | 23 +- tests/test_observability.py | 370 +++++++++++++++++++++++++++++++ tools/milestone0_baseline.py | 29 +++ tools/milestone1_benchmark.py | 228 +++++++++++++++++++ 20 files changed, 1386 insertions(+), 58 deletions(-) create mode 100644 src/docforge/telemetry.py create mode 100644 tests/test_observability.py create mode 100644 tools/milestone1_benchmark.py diff --git a/DEVELOPMENT_NOTES.md b/DEVELOPMENT_NOTES.md index 2305a00..6bd51c1 100644 --- a/DEVELOPMENT_NOTES.md +++ b/DEVELOPMENT_NOTES.md @@ -207,6 +207,40 @@ version 3, so existing version-2 indexes rebuild without changing canonical sour Frontier cursors are streamed and stop immediately on the first omitted unique result. A focused core, CLI, MCP, Ruff, and Pyright gate passes for this work-in-progress slice. +#### Structured profiling and zero-work gates + +DocForge now has an opt-in, request-local diagnostics collector backed by `ContextVar`. It emits +one bounded version-1 aggregate with a fixed operation name, outcome, total elapsed nanoseconds, +fixed stage timing keys, and fixed integer counters. It never records paths, node IDs, queries, +source text, or SQL. Disabled mode reads no clock and adds no response field, preserving the +existing CLI and MCP payloads. + +The generic loader, adapter projection and extraction paths, source-generation checks, index +checks/synchronization/build/read transactions, render status/preparation/output hashing, MCP +runtime validation, and viewer-manager requests now expose direct proof counters. A warm +incremental adapter cache hit still counts the enclosing project load, so the counters cannot hide +full adapter assembly merely because extraction was reused. + +MCP servers and the CLI accept the additive `--diagnostics` startup option. Diagnostics are +attached to structured successes and errors only when the complete MCP response still fits its +configured output budget; they are discarded before any primary result or compact mutation +receipt. Warm generic error decoration now reads the persisted source generation before falling +back to complete loading. Render- and visualization-status error paths explicitly disable both +recovery synchronization and complete identity loading. + +Context isolation tests cover threads, concurrent async tasks, repeated stages, nested collectors, +exceptions, and disabled collection. Repository tests assert that warm success and error reads, +render status, and visualization status perform zero project loads, source parses, adapter +projection/extraction, index builds, render preparation, output construction, and output hashing. +The result JSON schema contains the same closed operation, stage, and counter sets as the +implementation. + +The maintained `tools/milestone1_benchmark.py` harness adds hard counter and p95 latency gates to a +disposable generic project. The smoke target is part of `make gate`; the 1,000-node evidence run +will be recorded only from a clean committed revision. The historical Milestone 0 harness remains +behaviorally unchanged as comparison evidence; it only exposes shared fixture and measurement +helpers to the Milestone 1 harness. + ### Initial design constraints - Full rebuild remains the recovery and equivalence oracle. @@ -225,5 +259,10 @@ These are notes, not commitments: generic project and one incremental adapter prove the same boundary. - Profiling receipts could eventually feed the human-facing project control panel, but Milestone 1 should expose structured data before adding UI. +- A durable telemetry exporter remains deliberately deferred. Request-local bounded aggregates are + enough to prove compiler work in Milestone 1 without adding persistence, cardinality, or privacy + risks. +- Visualization freshness needs a separate source/index snapshot contract. Lifecycle health alone + must not be relabeled as current documentation state. - Large context and changeset payloads may need cursor pagination or compact immutable receipts. The choice should follow actual client workflows rather than generic pagination machinery. diff --git a/Makefile b/Makefile index fb51ec5..572cf59 100644 --- a/Makefile +++ b/Makefile @@ -5,7 +5,7 @@ NPM := npm PYTHONPYCACHEPREFIX := /tmp/docforge-quality-pycache PYTEST_BASETEMP := /tmp/docforge-quality-pytest -.PHONY: benchmark benchmark-smoke build compile contract dependencies format-check gate lint lock test type +.PHONY: benchmark benchmark-m1 benchmark-m1-smoke benchmark-smoke build compile contract dependencies format-check gate lint lock test type format-check: $(PYTHON) -m ruff format --check src tests tools @@ -49,4 +49,11 @@ benchmark-smoke: benchmark: $(PYTHON) tools/milestone0_baseline.py --nodes 1000 --samples 10 --cold-samples 3 -gate: format-check lint type compile contract test lock dependencies build benchmark-smoke +benchmark-m1-smoke: + $(PYTHON) tools/milestone1_benchmark.py --nodes 25 --samples 1 \ + --output /tmp/docforge-milestone1-smoke.json > /dev/null + +benchmark-m1: + $(PYTHON) tools/milestone1_benchmark.py --nodes 1000 --samples 10 + +gate: format-check lint type compile contract test lock dependencies build benchmark-smoke benchmark-m1-smoke diff --git a/README.md b/README.md index d55ce3e..1fe2f62 100644 --- a/README.md +++ b/README.md @@ -156,8 +156,13 @@ make gate ``` Focused entry points are available as `make contract`, `make test`, `make type`, -`make benchmark-smoke`, and `make benchmark`. +`make benchmark-smoke`, `make benchmark`, `make benchmark-m1-smoke`, and +`make benchmark-m1`. The committed 1,000-node baseline and its measurement method are under `benchmarks/`. +Pass `--diagnostics` to `docforge` or `docforge-mcp` to attach bounded request-local stage timings +and compiler-work counters. Diagnostics are disabled by default and are dropped before primary MCP +results when the configured output budget is tight. + See [AGENTS.md](AGENTS.md) before changing core boundaries. diff --git a/benchmarks/README.md b/benchmarks/README.md index 8d9e470..d6ec101 100644 --- a/benchmarks/README.md +++ b/benchmarks/README.md @@ -15,6 +15,18 @@ Run the 1,000-node generic baseline: make benchmark ``` +Run the Milestone 1 warm-operation counter and latency smoke gate: + +```bash +make benchmark-m1-smoke +``` + +Run the maintained 1,000-node Milestone 1 benchmark: + +```bash +make benchmark-m1 +``` + The benchmark creates canonical sources, derived state, changesets, rendered output, and caches only in a disposable temporary directory. It does not read another project, self-host DocForge, or mutate repository content. @@ -27,3 +39,9 @@ must explain fixture or environment changes before comparing results. The generic fixture exposes whole-source scaling. It does not replace the incremental adapter equivalence tests and does not claim to measure a portable graph renderer, because Milestone 0 has no portable graph-planning or graph-rendering contract. + +The Milestone 1 harness treats wall time and structured work counters as separate gates. Warm +operations fail if they load a complete project, parse source files, reconstruct an adapter +projection, extract adapter sources, build an index, prepare a render, construct rendered output, +or hash complete rendered output. Its latency ceilings are the Milestone 1 targets, not claims +about all hardware. diff --git a/docs/MCP_CONTRACT.md b/docs/MCP_CONTRACT.md index d2d7fc4..bcc77ae 100644 --- a/docs/MCP_CONTRACT.md +++ b/docs/MCP_CONTRACT.md @@ -6,6 +6,12 @@ configured `--proposal-writer`. It opens no network listener at startup. The exp `docforge_visualize` read tool may start one token-protected loopback-only HTTP listener for the same immutable project binding. +The additive `--diagnostics` startup option attaches a bounded version-1 request-local aggregate +to successes and structured errors. Fixed stage timings and counters expose source parsing, +adapter projection/extraction, index work, rendering work, and viewer-manager requests without +including content, paths, queries, node IDs, or SQL. Diagnostics are disabled by default. They are +the first response field discarded when the configured output limit would otherwise be exceeded. + Canonical application is a second independent startup gate. The generic server accepts `--canonical-applier WRITER_ID`. A project adapter must also supply a compatible project-owned canonical applier implementation. diff --git a/docs/USER_MANUAL.md b/docs/USER_MANUAL.md index b3f76d6..66e29a6 100644 --- a/docs/USER_MANUAL.md +++ b/docs/USER_MANUAL.md @@ -502,6 +502,11 @@ docforge-mcp \ Omit `--proposal-writer` when the MCP client should not create or append proposals. +Add `--diagnostics` when profiling a development or benchmark session. Each MCP response then +includes bounded stage timings and compiler-work counters. The same flag is available on +`docforge`. Diagnostics are disabled by default, record no project content or paths, and never +displace a primary MCP result that already needs the configured output budget. + To expose canonical application, add a separate explicit startup gate: ```bash @@ -811,13 +816,11 @@ the process so it binds the new descriptor deliberately. Run the complete release gate from the DocForge repository: ```bash -npx pyright -npm run lint:web -uv run ruff check src tests tools -uv run ruff format --check src tests tools -uv run python -m compileall -q src tests tools -uv run pytest -q +make gate ``` +Use `make benchmark` for the historical Milestone 0 baseline and `make benchmark-m1` for the +counter-gated 1,000-node warm-operation benchmark. + Project-specific vocabulary, extraction rules, and serialization belong in the project adapter. Generic core behavior must remain deterministic, project-bound, and recoverable. diff --git a/schemas/result.schema.json b/schemas/result.schema.json index 86624ac..c8fcdc0 100644 --- a/schemas/result.schema.json +++ b/schemas/result.schema.json @@ -2,6 +2,138 @@ "$schema": "https://json-schema.org/draft/2020-12/schema", "$id": "https://docforge.local/schema/result-v1.json", "title": "DocForge result envelope", + "$defs": { + "diagnostics": { + "type": "object", + "required": [ + "schema_version", + "operation", + "outcome", + "elapsed_ns", + "stages", + "counters" + ], + "properties": { + "schema_version": { "const": 1 }, + "operation": { + "enum": [ + "test", + "benchmark.m1", + "mcp.invoke", + "mcp.bootstrap", + "mcp.sync", + "mcp.project_info", + "mcp.contract", + "mcp.get_node", + "mcp.get_logic", + "mcp.search", + "mcp.filter", + "mcp.backlinks", + "mcp.dependencies", + "mcp.impact", + "mcp.context", + "mcp.validate_project", + "mcp.render_status", + "mcp.visualize", + "mcp.visualization_status", + "mcp.stop_visualization", + "mcp.changeset", + "mcp.mutation", + "cli.onboard", + "cli.info", + "cli.validate", + "cli.build", + "cli.reindex", + "cli.sync", + "cli.check", + "cli.validate-index", + "cli.show", + "cli.search", + "cli.filter", + "cli.backlinks", + "cli.dependencies", + "cli.impact", + "cli.context", + "cli.render", + "cli.render-status", + "cli.preview", + "cli.apply", + "cli.visualize", + "cli.visualization-status", + "cli.visualization-stop" + ] + }, + "outcome": { "enum": ["ok", "error"] }, + "elapsed_ns": { "type": "integer", "minimum": 0 }, + "stages": { + "type": "object", + "maxProperties": 14, + "propertyNames": { + "enum": [ + "source.generation", + "source.parse", + "adapter.projection", + "adapter.extract", + "index.check", + "index.synchronize", + "index.build", + "index.read", + "render.status", + "render.prepare", + "render.output_hash", + "visualization.status", + "viewer.manager", + "mcp.runtime_validation" + ] + }, + "additionalProperties": { + "type": "object", + "required": ["calls", "elapsed_ns"], + "properties": { + "calls": { "type": "integer", "minimum": 1 }, + "elapsed_ns": { "type": "integer", "minimum": 0 } + }, + "additionalProperties": false + } + }, + "counters": { + "type": "object", + "required": [ + "project_loads", + "source_files_parsed", + "source_bytes_parsed", + "adapter_projection_loads", + "adapter_source_extractions", + "source_generation_checks", + "index_checks", + "index_synchronizations", + "index_builds", + "render_prepare_calls", + "render_output_bytes_built", + "render_output_bytes_hashed", + "viewer_manager_requests" + ], + "properties": { + "project_loads": { "type": "integer", "minimum": 0 }, + "source_files_parsed": { "type": "integer", "minimum": 0 }, + "source_bytes_parsed": { "type": "integer", "minimum": 0 }, + "adapter_projection_loads": { "type": "integer", "minimum": 0 }, + "adapter_source_extractions": { "type": "integer", "minimum": 0 }, + "source_generation_checks": { "type": "integer", "minimum": 0 }, + "index_checks": { "type": "integer", "minimum": 0 }, + "index_synchronizations": { "type": "integer", "minimum": 0 }, + "index_builds": { "type": "integer", "minimum": 0 }, + "render_prepare_calls": { "type": "integer", "minimum": 0 }, + "render_output_bytes_built": { "type": "integer", "minimum": 0 }, + "render_output_bytes_hashed": { "type": "integer", "minimum": 0 }, + "viewer_manager_requests": { "type": "integer", "minimum": 0 } + }, + "additionalProperties": false + } + }, + "additionalProperties": false + } + }, "oneOf": [ { "type": "object", @@ -14,7 +146,8 @@ "type": ["string", "null"], "pattern": "^[0-9a-f]{64}$" }, - "adapter": { "type": "string" } + "adapter": { "type": "string" }, + "diagnostics": { "$ref": "#/$defs/diagnostics" } }, "additionalProperties": true }, @@ -38,6 +171,7 @@ "content_warning": { "type": "string" }, "staleness": { "enum": ["current", "stale", "unknown"] }, "synchronization": { "type": "object" }, + "diagnostics": { "$ref": "#/$defs/diagnostics" }, "error": { "type": "object", "required": ["code", "message", "details"], diff --git a/src/docforge/adapter_contract.py b/src/docforge/adapter_contract.py index afabf43..7dd1445 100644 --- a/src/docforge/adapter_contract.py +++ b/src/docforge/adapter_contract.py @@ -38,6 +38,7 @@ from .models import ( ProposalWriter, RenderConfig, ) +from .telemetry import increment, stage @dataclass(frozen=True) @@ -185,6 +186,21 @@ MAX_IMPLEMENTATION_FILES = 4_096 MAX_IMPLEMENTATION_BYTES = 64_000_000 +def _load_adapter_projection(loader: AdapterLoader) -> AdapterProjection: + increment("adapter_projection_loads") + with stage("adapter.projection"): + return loader.load_projection() + + +def _extract_adapter_source( + loader: IncrementalAdapterLoader, + source: AdapterSource, +) -> AdapterSourceProjection: + increment("adapter_source_extractions") + with stage("adapter.extract"): + return loader.extract_source(source) + + @dataclass(frozen=True) class AdapterImplementation: """One confined implementation boundary that must remain stable for a process.""" @@ -256,7 +272,7 @@ class AdapterProject: allowed_relations = manifest.allowed_relations estimated_nodes = manifest.estimated_nodes else: - initial = loader.load_projection() + initial = _load_adapter_projection(loader) validate_projection(initial) root = initial.root project_id = initial.project_id @@ -370,13 +386,14 @@ class AdapterProject: self._implementation_snapshot = self._capture_implementation(initial=True) def load(self) -> ProjectSnapshot: + increment("project_loads") self.validate_runtime() canonical_sources = self.canonical_source_paths() captured = {path: path.read_bytes() for path in canonical_sources} projection = ( self._load_incremental() if self._incremental_loader is not None - else self.loader.load_projection() + else _load_adapter_projection(self.loader) ) validate_projection(projection) identity = ( @@ -411,6 +428,11 @@ class AdapterProject: def incremental_state(self) -> ProjectState | None: """Return current source identity without reconstructing the complete projection.""" + increment("source_generation_checks") + with stage("source.generation"): + return self._incremental_state() + + def _incremental_state(self) -> ProjectState | None: self.validate_runtime() loader = self._incremental_loader if loader is None: @@ -509,7 +531,7 @@ class AdapterProject: "incremental_disabled", "Adapter does not implement incremental extraction" ) incremental = self._load_incremental() - full = self.loader.load_projection() + full = _load_adapter_projection(self.loader) validate_projection(full) fields = { "project_id": incremental.project_id == full.project_id, @@ -578,7 +600,7 @@ class AdapterProject: hits: list[str] = [] for source in manifest.sources: if source.source_id in invalidated: - contribution = loader.extract_source(source) + contribution = _extract_adapter_source(loader, source) reparsed.append(source.source_id) cache_record = CachedSource( source_id=source.source_id, diff --git a/src/docforge/cli.py b/src/docforge/cli.py index 85a6313..2f35d10 100644 --- a/src/docforge/cli.py +++ b/src/docforge/cli.py @@ -15,12 +15,18 @@ from .index import ProjectIndex from .onboarding import assess_project, scaffold_project from .project import Project, project_root_fingerprint from .rendering import RenderService +from .telemetry import request from .viewer_manager import ViewerManagerClient def _parser() -> argparse.ArgumentParser: parser = argparse.ArgumentParser(prog="docforge") parser.add_argument("--project-root", type=Path, required=True) + parser.add_argument( + "--diagnostics", + action="store_true", + help="Attach bounded request-local stage timings and counters", + ) commands = parser.add_subparsers(dest="command", required=True) onboard = commands.add_parser("onboard") onboard.add_argument("--language", action="append", default=[]) @@ -214,12 +220,20 @@ def _run(arguments: argparse.Namespace) -> dict[str, object]: def main(argv: list[str] | None = None) -> int: parser = _parser() arguments = parser.parse_args(argv) - try: - result = _run(arguments) - code = 0 - except DocForgeError as error: - result = {"status": "error", "error": error.as_dict()} - code = 2 + with request( + f"cli.{arguments.command}", + enabled=arguments.diagnostics, + ) as collector: + try: + result = _run(arguments) + code = 0 + except DocForgeError as error: + result = {"status": "error", "error": error.as_dict()} + code = 2 + if collector is not None: + result["diagnostics"] = collector.as_dict( + outcome="ok" if code == 0 else "error", + ) print(json.dumps(result, sort_keys=True, indent=2)) return code diff --git a/src/docforge/index.py b/src/docforge/index.py index 9afab07..f0cc06c 100644 --- a/src/docforge/index.py +++ b/src/docforge/index.py @@ -33,6 +33,7 @@ from .models import ( ProjectState, ) from .project import project_root_fingerprint +from .telemetry import increment, stage INDEX_SCHEMA_VERSION = 3 APPLICATION_ID = 1_146_683_778 @@ -173,6 +174,11 @@ class ProjectIndex: def synchronize(self) -> dict[str, object]: """Return a current index, rebuilding disposable state when necessary.""" + increment("index_synchronizations") + with stage("index.synchronize"): + return self._synchronize() + + def _synchronize(self) -> dict[str, object]: started = time.perf_counter() try: checked = self.check(verify_rows=False) @@ -223,6 +229,11 @@ class ProjectIndex: return {**checked, "synchronization": synchronization} def _build_locked(self) -> dict[str, object]: + increment("index_builds") + with stage("index.build"): + return self._build_locked_core() + + def _build_locked_core(self) -> dict[str, object]: snapshot = self.project.load() logic = self._logic_projections() status = _status(snapshot, logic) @@ -458,6 +469,11 @@ class ProjectIndex: def _read_snapshot(self) -> Generator[_IndexReadSnapshot, None, None]: """Pin one verified index and source generation for a complete read request.""" + with stage("index.read"), self._read_snapshot_core() as snapshot: + yield snapshot + + @contextmanager + def _read_snapshot_core(self) -> Generator[_IndexReadSnapshot, None, None]: checked = self.check(verify_rows=False) signature = self._verified_index_signature if signature is None or self._index_signature() != signature: @@ -530,6 +546,11 @@ class ProjectIndex: return snapshot.result(**payload) def check(self, *, verify_rows: bool = True) -> dict[str, object]: + increment("index_checks") + with stage("index.check"): + return self._check(verify_rows=verify_rows) + + def _check(self, *, verify_rows: bool = True) -> dict[str, object]: if isinstance(self.project, IncrementalStateProject): state = self.project.incremental_state() if state is not None: diff --git a/src/docforge/mcp_server.py b/src/docforge/mcp_server.py index 2d47c6b..4d80a51 100644 --- a/src/docforge/mcp_server.py +++ b/src/docforge/mcp_server.py @@ -16,9 +16,10 @@ from .changesets import ChangesetStore from .context import compile_context from .errors import DocForgeError from .index import ProjectIndex -from .models import ProjectService, RuntimeValidatedProject +from .models import IncrementalStateProject, ProjectService, RuntimeValidatedProject from .project import Project, project_root_fingerprint from .rendering import RenderService +from .telemetry import request, stage from .viewer_manager import ViewerManagerClient SERVER_VERSION = "1.3.0.dev0" @@ -125,6 +126,7 @@ class DocForgeService: tool_surface: tuple[str, ...] | None = None, binding_metadata: Mapping[str, object] | None = None, no_ast: bool = False, + diagnostics: bool = False, ) -> None: self.project = project self.index = ProjectIndex(self.project, allow_logic=not no_ast) @@ -140,6 +142,7 @@ class DocForgeService: self.context_provider = context_provider self.binding_metadata = dict(binding_metadata or {}) self.no_ast = no_ast + self.diagnostics = diagnostics self.tool_surface = tool_surface or ( *ALL_TOOLS, *(APPLICATION_TOOLS if self.application.enabled else ()), @@ -177,6 +180,29 @@ class DocForgeService: synchronize: bool = True, mutation: _MutationPolicy | None = None, load_error_identity: bool = True, + operation_name: str = "mcp.invoke", + ) -> dict[str, Any]: + with request(operation_name, enabled=self.diagnostics) as collector: + result = self._invoke_core( + operation, + synchronize=synchronize, + mutation=mutation, + load_error_identity=load_error_identity, + ) + if collector is None: + return result + diagnostics = collector.as_dict(outcome="ok" if result.get("status") == "ok" else "error") + with_diagnostics = {**result, "diagnostics": diagnostics} + maximum = self.project.descriptor.limits.max_tool_output_chars + return with_diagnostics if self._encoded_length(with_diagnostics) <= maximum else result + + def _invoke_core( + self, + operation: Callable[[], dict[str, object]], + *, + synchronize: bool = True, + mutation: _MutationPolicy | None = None, + load_error_identity: bool = True, ) -> dict[str, Any]: synchronization: dict[str, object] | None = None maximum = self.project.descriptor.limits.max_tool_output_chars @@ -192,7 +218,8 @@ class DocForgeService: try: try: if isinstance(self.project, RuntimeValidatedProject): - self.project.validate_runtime() + with stage("mcp.runtime_validation"): + self.project.validate_runtime() result: dict[str, Any] = operation() except DocForgeError as error: if not synchronize or error.code not in RECOVERABLE_INDEX_ERROR_CODES: @@ -214,13 +241,26 @@ class DocForgeService: } if load_error_identity: try: - snapshot = self.project.load() - result.update( - { - "revision": snapshot.revision, - "source_hash": snapshot.source_hash, - } + state = ( + self.project.incremental_state() + if isinstance(self.project, IncrementalStateProject) + else None ) + if state is not None: + result.update( + { + "revision": state.revision, + "source_hash": state.source_hash, + } + ) + else: + snapshot = self.project.load() + result.update( + { + "revision": snapshot.revision, + "source_hash": snapshot.source_hash, + } + ) except DocForgeError: result.update({"revision": "unknown", "source_hash": None}) else: @@ -451,7 +491,11 @@ class DocForgeService: return None def synchronize(self) -> dict[str, object]: - return self.invoke(self.index.synchronize, synchronize=False) + return self.invoke( + self.index.synchronize, + synchronize=False, + operation_name="mcp.sync", + ) def bootstrap(self) -> dict[str, object]: def operation() -> dict[str, object]: @@ -506,6 +550,7 @@ class DocForgeService: operation, synchronize=False, load_error_identity=False, + operation_name="mcp.bootstrap", ) def project_info(self) -> dict[str, object]: @@ -533,7 +578,7 @@ class DocForgeService: "index_health": index_health, } - return self.invoke(operation) + return self.invoke(operation, operation_name="mcp.project_info") def contract(self) -> dict[str, object]: def operation() -> dict[str, object]: @@ -602,7 +647,7 @@ class DocForgeService: "project_switching_allowed": False, } - return self.invoke(operation) + return self.invoke(operation, operation_name="mcp.contract") def get_logic(self, owner_node_id: str) -> dict[str, object]: """Return one Logic projection unless the binding preserves a no-AST adapter.""" @@ -618,8 +663,15 @@ class DocForgeService: ), ) - return self.invoke(forbidden, synchronize=False) - return self.invoke(lambda: self.index.get_logic(owner_node_id)) + return self.invoke( + forbidden, + synchronize=False, + operation_name="mcp.get_logic", + ) + return self.invoke( + lambda: self.index.get_logic(owner_node_id), + operation_name="mcp.get_logic", + ) def validate_project(self) -> dict[str, object]: def operation() -> dict[str, object]: @@ -635,7 +687,7 @@ class DocForgeService: "edge_count": len(snapshot.edges), } - return self.invoke(operation) + return self.invoke(operation, operation_name="mcp.validate_project") def render_status( self, @@ -652,10 +704,14 @@ class DocForgeService: operation, synchronize=False, load_error_identity=False, + operation_name="mcp.render_status", ) def context(self, profile: str, budget: int | None = None) -> dict[str, Any]: - return self.invoke(lambda: self.context_provider(self.index, profile, budget)) + return self.invoke( + lambda: self.context_provider(self.index, profile, budget), + operation_name="mcp.context", + ) def visualize( self, @@ -680,13 +736,21 @@ class DocForgeService: "visualization": visualization, } - return self.invoke(operation) + return self.invoke(operation, operation_name="mcp.visualize") def stop_visualization(self) -> dict[str, object]: - return self.invoke(self.visualization.stop) + return self.invoke( + self.visualization.stop, + operation_name="mcp.stop_visualization", + ) def visualization_status(self) -> dict[str, object]: - return self.invoke(self.visualization.status) + return self.invoke( + self.visualization.status, + synchronize=False, + load_error_identity=False, + operation_name="mcp.visualization_status", + ) def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMCP: @@ -752,7 +816,10 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC def get_node(node_id: str) -> dict[str, Any]: """Return one exact stable node from the current validated project index.""" - return service.invoke(lambda: service.index.get_node(node_id)) + return service.invoke( + lambda: service.index.get_node(node_id), + operation_name="mcp.get_node", + ) @server.tool(name="docforge_get_logic") def get_logic(owner_node_id: str) -> dict[str, Any]: @@ -764,7 +831,10 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC def search(query: str, limit: int | None = None) -> dict[str, Any]: """Run bounded lexical search over the current validated project index.""" - return service.invoke(lambda: service.index.search(query, limit=limit)) + return service.invoke( + lambda: service.index.search(query, limit=limit), + operation_name="mcp.search", + ) @server.tool(name="docforge_filter_nodes") def filter_nodes( @@ -783,7 +853,8 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC status=status, tag=tag, limit=limit, - ) + ), + operation_name="mcp.filter", ) @server.tool(name="docforge_backlinks") @@ -795,7 +866,8 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC """Return bounded incoming relationships for one exact stable node.""" return service.invoke( - lambda: service.index.backlinks(node_id, relation=relation, limit=limit) + lambda: service.index.backlinks(node_id, relation=relation, limit=limit), + operation_name="mcp.backlinks", ) @server.tool(name="docforge_dependencies") @@ -806,7 +878,10 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC ) -> dict[str, Any]: """Traverse declared depends_on relationships within the configured depth limit.""" - return service.invoke(lambda: service.index.dependencies(node_id, depth=depth, limit=limit)) + return service.invoke( + lambda: service.index.dependencies(node_id, depth=depth, limit=limit), + operation_name="mcp.dependencies", + ) @server.tool(name="docforge_impact") def impact( @@ -816,7 +891,10 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC ) -> dict[str, Any]: """Traverse bounded incoming relationships and report exact paths.""" - return service.invoke(lambda: service.index.impact(node_id, depth=depth, limit=limit)) + return service.invoke( + lambda: service.index.impact(node_id, depth=depth, limit=limit), + operation_name="mcp.impact", + ) @server.tool(name="docforge_get_context") def get_context(profile: str, budget: int | None = None) -> dict[str, Any]: @@ -890,6 +968,7 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC return service.invoke( lambda: service.changesets.create(changeset_id), synchronize=False, + operation_name="mcp.mutation", mutation=service.mutation( "changeset.create", "changeset", @@ -908,6 +987,7 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC return service.invoke( lambda: service.changesets.register(changeset_id, operations), synchronize=False, + operation_name="mcp.mutation", mutation=service.mutation( "changeset.register", "changeset", @@ -927,14 +1007,18 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC lambda: service.changesets.list_changesets( include_history=include_history, status=status, - ) + ), + operation_name="mcp.changeset", ) @server.tool(name="docforge_get_changeset") def get_changeset(changeset_id: str) -> dict[str, Any]: """Inspect a stored proposal even when its canonical base has become stale.""" - return service.invoke(lambda: service.changesets.inspect(changeset_id)) + return service.invoke( + lambda: service.changesets.inspect(changeset_id), + operation_name="mcp.changeset", + ) @server.tool(name="docforge_rebase_changeset") def rebase_changeset( @@ -949,6 +1033,7 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC expected_changeset_hash, ), synchronize=False, + operation_name="mcp.mutation", mutation=service.mutation( "changeset.rebase", "changeset", @@ -972,6 +1057,7 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC reason, ), synchronize=False, + operation_name="mcp.mutation", mutation=service.mutation( "changeset.abandon", "changeset", @@ -1005,6 +1091,7 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC rationale=rationale, ), synchronize=False, + operation_name="mcp.mutation", mutation=service.mutation( "changeset.append_create", "changeset", @@ -1038,6 +1125,7 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC rationale=rationale, ), synchronize=False, + operation_name="mcp.mutation", mutation=service.mutation( "changeset.append_update", "changeset", @@ -1067,6 +1155,7 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC rationale=rationale, ), synchronize=False, + operation_name="mcp.mutation", mutation=service.mutation( "changeset.append_move", "changeset", @@ -1096,6 +1185,7 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC rationale=rationale, ), synchronize=False, + operation_name="mcp.mutation", mutation=service.mutation( "changeset.append_relationship_update", "changeset", @@ -1125,6 +1215,7 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC rationale=rationale, ), synchronize=False, + operation_name="mcp.mutation", mutation=service.mutation( "changeset.append_delete", "changeset", @@ -1137,13 +1228,19 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC def validate_changeset(changeset_id: str) -> dict[str, Any]: """Validate a proposal against its exact canonical base and other active proposals.""" - return service.invoke(lambda: service.changesets.validate(changeset_id)) + return service.invoke( + lambda: service.changesets.validate(changeset_id), + operation_name="mcp.changeset", + ) @server.tool(name="docforge_get_changeset_diff") def get_changeset_diff(changeset_id: str) -> dict[str, Any]: """Return a deterministic structured and textual diff without applying the proposal.""" - return service.invoke(lambda: service.changesets.diff(changeset_id)) + return service.invoke( + lambda: service.changesets.diff(changeset_id), + operation_name="mcp.changeset", + ) @server.tool(name="docforge_preview_changeset") def preview_changeset(changeset_id: str, view_id: str) -> dict[str, Any]: @@ -1152,6 +1249,7 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC return service.invoke( lambda: service.rendering.preview(changeset_id, view_id), synchronize=False, + operation_name="mcp.mutation", mutation=service.mutation( "render.preview", "preview", @@ -1188,6 +1286,7 @@ def _create_bound_server(service: DocForgeService, *, read_only: bool) -> FastMC return service.invoke( lambda: service.application.apply(changeset_id, expected_changeset_hash), synchronize=False, + operation_name="mcp.mutation", mutation=service.mutation( "changeset.apply", "application", @@ -1206,6 +1305,7 @@ def create_server( *, canonical_applier_id: str | None = None, no_ast: bool = False, + diagnostics: bool = False, ) -> FastMCP: project = Project.open(project_root) return create_project_server( @@ -1220,6 +1320,7 @@ def create_server( "adapter_mode": "generic", }, no_ast=no_ast, + diagnostics=diagnostics, ) @@ -1232,6 +1333,7 @@ def create_project_server( context_provider: ContextProvider = compile_context, binding_metadata: Mapping[str, object] | None = None, no_ast: bool = False, + diagnostics: bool = False, ) -> FastMCP: """Create the full fixed MCP surface for one explicitly configured project service.""" @@ -1243,6 +1345,7 @@ def create_project_server( context_provider=context_provider, binding_metadata=binding_metadata, no_ast=no_ast, + diagnostics=diagnostics, ) return _create_bound_server(service, read_only=False) @@ -1253,6 +1356,7 @@ def create_read_only_server( context_provider: ContextProvider = compile_context, binding_metadata: Mapping[str, object] | None = None, no_ast: bool = False, + diagnostics: bool = False, ) -> FastMCP: """Create an adapter-capable MCP server exposing only the fixed read tool surface.""" @@ -1262,6 +1366,7 @@ def create_read_only_server( tool_surface=READ_TOOLS, binding_metadata=binding_metadata, no_ast=no_ast, + diagnostics=diagnostics, ) return _create_bound_server(service, read_only=True) @@ -1279,12 +1384,18 @@ def main() -> None: "and function-Logic extraction changes" ), ) + parser.add_argument( + "--diagnostics", + action="store_true", + help="Attach bounded request-local stage timings and counters", + ) arguments = parser.parse_args() create_server( arguments.project_root, arguments.proposal_writer, canonical_applier_id=arguments.canonical_applier, no_ast=arguments.no_ast, + diagnostics=arguments.diagnostics, ).run(transport="stdio") diff --git a/src/docforge/project.py b/src/docforge/project.py index 487bc06..9d69b0b 100644 --- a/src/docforge/project.py +++ b/src/docforge/project.py @@ -35,6 +35,7 @@ from .models import ( ProposalWriter, ) from .render_config import load_render_config +from .telemetry import increment, stage SOURCE_GENERATION_SCHEMA_VERSION = 1 GENERIC_SOURCE_CONTRACT = "docforge-core:0.7.1:index:1" @@ -709,6 +710,7 @@ class Project: return cls(_load_descriptor(root)) def load(self) -> ProjectSnapshot: + increment("project_loads") descriptor_bytes = self.descriptor.descriptor_path.read_bytes() if hashlib.sha256(descriptor_bytes).hexdigest() != self.descriptor.descriptor_hash: raise DocForgeError( @@ -730,7 +732,15 @@ class Project: nodes: list[Node] = [] edges: list[Edge] = [] for path in ordered_sources: - source_nodes, source_edges = _load_source_file(self.descriptor, path, captured[path]) + raw = captured[path] + increment("source_files_parsed") + increment("source_bytes_parsed", len(raw)) + with stage("source.parse"): + source_nodes, source_edges = _load_source_file( + self.descriptor, + path, + raw, + ) nodes.extend(source_nodes) edges.extend(source_edges) if len(nodes) > self.descriptor.limits.max_nodes: @@ -804,6 +814,11 @@ class Project: def incremental_state(self) -> ProjectState | None: """Return current source identity without reading or parsing canonical source bytes.""" + increment("source_generation_checks") + with stage("source.generation"): + return self._incremental_state() + + def _incremental_state(self) -> ProjectState | None: path = self.generation_path if not path.is_file() or path.is_symlink(): return None diff --git a/src/docforge/rendering.py b/src/docforge/rendering.py index 1a09879..79e4116 100644 --- a/src/docforge/rendering.py +++ b/src/docforge/rendering.py @@ -27,6 +27,7 @@ from .models import ( ) from .project import project_root_fingerprint from .render_contract import PreparedRender, relative_output, renderer_for +from .telemetry import increment, stage RENDER_RECEIPT_SCHEMA_VERSION = 1 MAX_RENDER_RECEIPT_BYTES = 64_000 @@ -42,6 +43,10 @@ class RenderService: def status(self, view_id: str | None = None) -> dict[str, object]: """Report publication state from bounded receipts without rendering canonical content.""" + with stage("render.status"): + return self._status(view_id) + + def _status(self, view_id: str | None = None) -> dict[str, object]: descriptor = self.project.descriptor config = descriptor.render current_state = self._current_state() @@ -113,7 +118,9 @@ class RenderService: state = "oversized" else: raw = output.read_bytes() - actual_hash = hashlib.sha256(raw).hexdigest() + increment("render_output_bytes_hashed", len(raw)) + with stage("render.output_hash"): + actual_hash = hashlib.sha256(raw).hexdigest() state = "current" if actual_hash == prepared.output_hash else "stale" result = self._view_result( snapshot, @@ -725,13 +732,16 @@ class RenderService: *, changeset_hash: str | None, ) -> tuple[PreparedRender, bytes]: + increment("render_prepare_calls") template = self._template_bytes(snapshot, view) - prepared = renderer_for(view).prepare( - snapshot, - view, - template, - changeset_hash=changeset_hash, - ) + with stage("render.prepare"): + prepared = renderer_for(view).prepare( + snapshot, + view, + template, + changeset_hash=changeset_hash, + ) + increment("render_output_bytes_built", len(prepared.output)) if len(prepared.output) > snapshot.descriptor.limits.max_render_bytes: raise DocForgeError("render_too_large", "Rendered output exceeds the configured limit") return prepared, template diff --git a/src/docforge/telemetry.py b/src/docforge/telemetry.py new file mode 100644 index 0000000..c7e1f8c --- /dev/null +++ b/src/docforge/telemetry.py @@ -0,0 +1,220 @@ +"""Bounded request-local diagnostics for repository gates and explicit profiling.""" + +from __future__ import annotations + +import time +from collections.abc import Generator +from contextlib import contextmanager +from contextvars import ContextVar +from dataclasses import dataclass, field +from typing import Literal + +CounterName = Literal[ + "project_loads", + "source_files_parsed", + "source_bytes_parsed", + "adapter_projection_loads", + "adapter_source_extractions", + "source_generation_checks", + "index_checks", + "index_synchronizations", + "index_builds", + "render_prepare_calls", + "render_output_bytes_built", + "render_output_bytes_hashed", + "viewer_manager_requests", +] +StageName = Literal[ + "source.generation", + "source.parse", + "adapter.projection", + "adapter.extract", + "index.check", + "index.synchronize", + "index.build", + "index.read", + "render.status", + "render.prepare", + "render.output_hash", + "visualization.status", + "viewer.manager", + "mcp.runtime_validation", +] + +COUNTER_NAMES: tuple[CounterName, ...] = ( + "project_loads", + "source_files_parsed", + "source_bytes_parsed", + "adapter_projection_loads", + "adapter_source_extractions", + "source_generation_checks", + "index_checks", + "index_synchronizations", + "index_builds", + "render_prepare_calls", + "render_output_bytes_built", + "render_output_bytes_hashed", + "viewer_manager_requests", +) +STAGE_NAMES: frozenset[StageName] = frozenset( + { + "source.generation", + "source.parse", + "adapter.projection", + "adapter.extract", + "index.check", + "index.synchronize", + "index.build", + "index.read", + "render.status", + "render.prepare", + "render.output_hash", + "visualization.status", + "viewer.manager", + "mcp.runtime_validation", + } +) +OPERATION_NAMES = frozenset( + { + "test", + "benchmark.m1", + "mcp.invoke", + "mcp.bootstrap", + "mcp.sync", + "mcp.project_info", + "mcp.contract", + "mcp.get_node", + "mcp.get_logic", + "mcp.search", + "mcp.filter", + "mcp.backlinks", + "mcp.dependencies", + "mcp.impact", + "mcp.context", + "mcp.validate_project", + "mcp.render_status", + "mcp.visualize", + "mcp.visualization_status", + "mcp.stop_visualization", + "mcp.changeset", + "mcp.mutation", + "cli.onboard", + "cli.info", + "cli.validate", + "cli.build", + "cli.reindex", + "cli.sync", + "cli.check", + "cli.validate-index", + "cli.show", + "cli.search", + "cli.filter", + "cli.backlinks", + "cli.dependencies", + "cli.impact", + "cli.context", + "cli.render", + "cli.render-status", + "cli.preview", + "cli.apply", + "cli.visualize", + "cli.visualization-status", + "cli.visualization-stop", + } +) + + +@dataclass +class _StageAggregate: + calls: int = 0 + elapsed_ns: int = 0 + + +@dataclass +class Collector: + """One bounded aggregate owned by the current request context.""" + + operation: str + counters: dict[CounterName, int] = field( + default_factory=lambda: {name: 0 for name in COUNTER_NAMES} + ) + stages: dict[StageName, _StageAggregate] = field(default_factory=lambda: {}) + elapsed_ns: int = 0 + + def as_dict(self, *, outcome: str) -> dict[str, object]: + if outcome not in {"ok", "error"}: + raise ValueError("Telemetry outcome must be ok or error") + return { + "schema_version": 1, + "operation": self.operation, + "outcome": outcome, + "elapsed_ns": self.elapsed_ns, + "stages": { + name: { + "calls": aggregate.calls, + "elapsed_ns": aggregate.elapsed_ns, + } + for name, aggregate in sorted(self.stages.items()) + }, + "counters": {name: self.counters[name] for name in COUNTER_NAMES}, + } + + +_CURRENT: ContextVar[Collector | None] = ContextVar( + "docforge_telemetry", + default=None, +) + + +@contextmanager +def request( + operation: str, + *, + enabled: bool, +) -> Generator[Collector | None, None, None]: + """Collect one explicit request without affecting the disabled path.""" + + if operation not in OPERATION_NAMES: + raise ValueError("Unknown telemetry operation") + if not enabled: + yield None + return + collector = Collector(operation=operation) + token = _CURRENT.set(collector) + started = time.perf_counter_ns() + try: + yield collector + finally: + collector.elapsed_ns = time.perf_counter_ns() - started + _CURRENT.reset(token) + + +def increment(counter: CounterName | str, amount: int = 1) -> None: + """Increment one fixed counter when a request collector is active.""" + + if counter not in COUNTER_NAMES: + raise ValueError("Unknown telemetry counter") + if type(amount) is not int or amount < 0: + raise ValueError("Telemetry increments must be nonnegative integers") + collector = _CURRENT.get() + if collector is not None: + collector.counters[counter] += amount + + +@contextmanager +def stage(name: StageName | str) -> Generator[None, None, None]: + """Aggregate one fixed stage while avoiding a clock read when disabled.""" + + if name not in STAGE_NAMES: + raise ValueError("Unknown telemetry stage") + collector = _CURRENT.get() + if collector is None: + yield + return + started = time.perf_counter_ns() + try: + yield + finally: + aggregate = collector.stages.setdefault(name, _StageAggregate()) + aggregate.calls += 1 + aggregate.elapsed_ns += time.perf_counter_ns() - started diff --git a/src/docforge/viewer_manager.py b/src/docforge/viewer_manager.py index 7bad944..ae986c3 100644 --- a/src/docforge/viewer_manager.py +++ b/src/docforge/viewer_manager.py @@ -26,6 +26,7 @@ from typing import BinaryIO, cast from .errors import DocForgeError from .index import ProjectIndex from .project import project_root_fingerprint +from .telemetry import increment, stage from .visualization import VISUALIZATION_TEMPLATE, VisualizationIndexSnapshot MANAGER_PROTOCOL = "docforge-viewer-manager@1" @@ -635,7 +636,8 @@ class ViewerManagerClient: return self._lifecycle_request("stop") def status(self) -> dict[str, object]: - return self._lifecycle_request("status") + with stage("visualization.status"): + return self._lifecycle_request("status") def _lifecycle_request(self, action: str) -> dict[str, object]: descriptor = self.index.project.descriptor @@ -654,6 +656,11 @@ class ViewerManagerClient: } def _request(self, request: dict[str, object]) -> dict[str, object]: + increment("viewer_manager_requests") + with stage("viewer.manager"): + return self._request_core(request) + + def _request_core(self, request: dict[str, object]) -> dict[str, object]: state = self._read_state() host = state["host"] port = state["port"] diff --git a/tests/test_adapter_contract.py b/tests/test_adapter_contract.py index 03cc24d..3870a72 100644 --- a/tests/test_adapter_contract.py +++ b/tests/test_adapter_contract.py @@ -47,6 +47,7 @@ from docforge.models import ( RenderConfig, RenderView, ) +from docforge.telemetry import request from docforge.viewer_manager import ViewerManagerClient from docforge.visualization import VisualizationIndexSnapshot @@ -497,6 +498,53 @@ class AdapterContractTests(unittest.TestCase): captured.exception.details["changed"], ) + def test_warm_incremental_adapter_load_remains_visible_to_diagnostics(self) -> None: + with tempfile.TemporaryDirectory() as directory: + root = Path(directory).resolve() + loader = IncrementalLoader(root) + project = AdapterProject(loader, cache_root=root / ".cache" / "incremental") + with request("test", enabled=True) as cold_collector: + project.load() + assert cold_collector is not None + cold_counters = cold_collector.as_dict(outcome="ok")["counters"] + self.assertEqual(1, cold_counters["project_loads"]) + self.assertEqual(0, cold_counters["adapter_projection_loads"]) + self.assertEqual(2, cold_counters["adapter_source_extractions"]) + loader.extract_calls.clear() + + with request("test", enabled=True) as warm_collector: + project.load() + + assert warm_collector is not None + counters = warm_collector.as_dict(outcome="ok")["counters"] + self.assertEqual(1, counters["project_loads"]) + self.assertEqual(0, counters["adapter_projection_loads"]) + self.assertEqual(0, counters["adapter_source_extractions"]) + self.assertEqual([], loader.extract_calls) + + index = ProjectIndex(project) + index.build() + with request("test", enabled=True) as read_collector: + index.get_node("guide.workflow") + assert read_collector is not None + read_counters = read_collector.as_dict(outcome="ok")["counters"] + self.assertEqual(0, read_counters["project_loads"]) + self.assertEqual(0, read_counters["adapter_projection_loads"]) + self.assertEqual(0, read_counters["adapter_source_extractions"]) + self.assertEqual(0, read_counters["index_builds"]) + + legacy = AdapterProject( + Loader(self.projection(root)), + cache_root=root / ".cache" / "legacy", + ) + with request("test", enabled=True) as legacy_collector: + legacy.load() + assert legacy_collector is not None + legacy_counters = legacy_collector.as_dict(outcome="ok")["counters"] + self.assertEqual(1, legacy_counters["project_loads"]) + self.assertEqual(1, legacy_counters["adapter_projection_loads"]) + self.assertEqual(0, legacy_counters["adapter_source_extractions"]) + def test_incremental_adapter_reuses_sources_and_invalidates_reverse_dependencies(self) -> None: with tempfile.TemporaryDirectory() as directory: root = Path(directory).resolve() diff --git a/tests/test_mcp_server.py b/tests/test_mcp_server.py index 632f76e..2dc9ce7 100644 --- a/tests/test_mcp_server.py +++ b/tests/test_mcp_server.py @@ -92,6 +92,24 @@ class DocForgeMcpTests(unittest.IsolatedAsyncioTestCase): ) ) + async def test_factory_diagnostics_are_additive_through_real_mcp(self) -> None: + with tempfile.TemporaryDirectory() as directory: + root = self.copy_fixture("alpha", Path(directory)) + ProjectIndex(Project.open(root)).build() + async with create_connected_server_and_client_session( + create_server(root, diagnostics=True), + raise_exceptions=True, + ) as session: + result = await session.call_tool( + "docforge_get_node", + {"node_id": "guide.workflow"}, + ) + + diagnostics = result.structuredContent["diagnostics"] + self.assertEqual("mcp.get_node", diagnostics["operation"]) + self.assertEqual(0, diagnostics["counters"]["project_loads"]) + self.assertEqual(0, diagnostics["counters"]["source_files_parsed"]) + async def test_no_ast_binding_preserves_adapter_and_blocks_logic(self) -> None: with tempfile.TemporaryDirectory() as directory: root = self.copy_fixture("alpha", Path(directory)) @@ -263,6 +281,7 @@ class DocForgeMcpTests(unittest.IsolatedAsyncioTestCase): root, "alpha-editor", canonical_applier_id="alpha-editor", + diagnostics=True, ), raise_exceptions=True, ) as session: @@ -477,6 +496,7 @@ class DocForgeMcpTests(unittest.IsolatedAsyncioTestCase): self.assertEqual("ok", payload["status"]) self.assertTrue(payload["mutation_committed"]) self.assertEqual("receipt", payload["result_mode"]) + self.assertNotIn("diagnostics", payload) self.assertLessEqual( len(json.dumps(payload, sort_keys=True, separators=(",", ":"))), 1600, @@ -513,7 +533,7 @@ class DocForgeMcpTests(unittest.IsolatedAsyncioTestCase): ProjectIndex(Project.open(root)).build() changeset_id = "must-not-exist-" + ("x" * 100) async with create_connected_server_and_client_session( - create_server(root, "alpha-editor"), + create_server(root, "alpha-editor", diagnostics=True), raise_exceptions=True, ) as session: result = await session.call_tool( @@ -526,6 +546,7 @@ class DocForgeMcpTests(unittest.IsolatedAsyncioTestCase): self.assertEqual("result_too_large", payload["error"]["code"]) self.assertEqual("preflight", payload["error"]["details"]["stage"]) self.assertFalse(payload["error"]["details"]["mutation_committed"]) + self.assertNotIn("diagnostics", payload) self.assertFalse((root / f".docforge/changesets/{changeset_id}.json").exists()) async def test_proposal_tools_use_fixed_writer_and_never_change_canonical_content(self) -> None: diff --git a/tests/test_observability.py b/tests/test_observability.py new file mode 100644 index 0000000..c4cf2c6 --- /dev/null +++ b/tests/test_observability.py @@ -0,0 +1,370 @@ +from __future__ import annotations + +import asyncio +import io +import json +import shutil +import tempfile +import threading +import unittest +from concurrent.futures import ThreadPoolExecutor +from dataclasses import replace +from pathlib import Path +from unittest import mock + +import jsonschema + +from docforge.cli import main as cli_main +from docforge.context import compile_context +from docforge.errors import DocForgeError +from docforge.index import ProjectIndex +from docforge.mcp_server import DocForgeService +from docforge.project import Project +from docforge.rendering import RenderService +from docforge.telemetry import ( + COUNTER_NAMES, + OPERATION_NAMES, + STAGE_NAMES, + increment, + request, + stage, +) +from docforge.viewer_manager import ViewerManagerClient + +ROOT = Path(__file__).resolve().parents[1] +FIXTURES = ROOT / "tests" / "fixtures" +RESULT_SCHEMA = json.loads((ROOT / "schemas" / "result.schema.json").read_text()) +ZERO_WORK_COUNTERS = ( + "project_loads", + "source_files_parsed", + "source_bytes_parsed", + "adapter_projection_loads", + "adapter_source_extractions", + "index_synchronizations", + "index_builds", + "render_prepare_calls", + "render_output_bytes_built", + "render_output_bytes_hashed", +) + + +class TelemetryContractTests(unittest.TestCase): + def copy_fixture(self, destination: Path) -> Path: + root = destination / "alpha" + shutil.copytree(FIXTURES / "alpha", root) + return root + + def test_disabled_collection_reads_no_clock_and_emits_nothing(self) -> None: + with ( + mock.patch( + "docforge.telemetry.time.perf_counter_ns", + side_effect=AssertionError("disabled telemetry read the clock"), + ), + request("test", enabled=False) as collector, + ): + increment("project_loads") + with stage("source.parse"): + pass + self.assertIsNone(collector) + + def test_fixed_names_aggregation_and_exception_cleanup(self) -> None: + with ( + self.assertRaisesRegex(ValueError, "operation"), + request( + "unknown", + enabled=True, + ), + ): + pass + with self.assertRaisesRegex(ValueError, "counter"): + increment("unknown") + with self.assertRaisesRegex(ValueError, "stage"), stage("unknown"): + pass + + with request("test", enabled=True) as collector: + increment("source_files_parsed", 2) + with stage("source.parse"): + pass + with stage("source.parse"): + pass + assert collector is not None + diagnostics = collector.as_dict(outcome="ok") + self.assertEqual(2, diagnostics["counters"]["source_files_parsed"]) + self.assertEqual(2, diagnostics["stages"]["source.parse"]["calls"]) + + with ( + self.assertRaisesRegex(RuntimeError, "failed"), + request( + "test", + enabled=True, + ), + stage("index.read"), + ): + raise RuntimeError("failed") + with request("test", enabled=True) as next_collector: + increment("project_loads") + assert next_collector is not None + self.assertEqual(1, next_collector.as_dict(outcome="ok")["counters"]["project_loads"]) + + with request("test", enabled=True) as outer_collector: + increment("project_loads") + with request("test", enabled=True) as inner_collector: + increment("project_loads", 5) + increment("project_loads") + assert outer_collector is not None + assert inner_collector is not None + self.assertEqual(2, outer_collector.as_dict(outcome="ok")["counters"]["project_loads"]) + self.assertEqual(5, inner_collector.as_dict(outcome="ok")["counters"]["project_loads"]) + + def test_schema_fixed_names_match_the_implementation(self) -> None: + properties = RESULT_SCHEMA["$defs"]["diagnostics"]["properties"] + self.assertEqual( + set(OPERATION_NAMES), + set(properties["operation"]["enum"]), + ) + self.assertEqual( + set(STAGE_NAMES), + set(properties["stages"]["propertyNames"]["enum"]), + ) + self.assertEqual( + set(COUNTER_NAMES), + set(properties["counters"]["required"]), + ) + self.assertEqual( + set(COUNTER_NAMES), + set(properties["counters"]["properties"]), + ) + + def test_thread_and_async_request_contexts_are_isolated(self) -> None: + barrier = threading.Barrier(2) + + def thread_worker(amount: int) -> int: + with request("test", enabled=True) as collector: + increment("project_loads", amount) + barrier.wait() + barrier.wait() + assert collector is not None + return int(collector.as_dict(outcome="ok")["counters"]["project_loads"]) + + with ThreadPoolExecutor(max_workers=2) as executor: + futures = [executor.submit(thread_worker, amount) for amount in (1, 3)] + self.assertEqual([1, 3], [future.result() for future in futures]) + + async def verify_async_isolation() -> list[int]: + ready = [asyncio.Event(), asyncio.Event()] + proceed = asyncio.Event() + + async def async_worker(position: int, amount: int) -> int: + with request("test", enabled=True) as collector: + increment("project_loads", amount) + ready[position].set() + await proceed.wait() + assert collector is not None + return int(collector.as_dict(outcome="ok")["counters"]["project_loads"]) + + tasks = [ + asyncio.create_task(async_worker(position, amount)) + for position, amount in enumerate((2, 5)) + ] + await asyncio.gather(*(event.wait() for event in ready)) + proceed.set() + return list(await asyncio.gather(*tasks)) + + self.assertEqual([2, 5], asyncio.run(verify_async_isolation())) + + def test_generic_positive_controls_and_warm_zero_work_invariants(self) -> None: + with tempfile.TemporaryDirectory() as directory: + root = self.copy_fixture(Path(directory)) + project = Project.open(root) + with request("test", enabled=True) as load_collector: + project.load() + assert load_collector is not None + load_counters = load_collector.as_dict(outcome="ok")["counters"] + self.assertEqual(1, load_counters["project_loads"]) + self.assertGreater(load_counters["source_files_parsed"], 0) + self.assertGreater(load_counters["source_bytes_parsed"], 0) + + index = ProjectIndex(project) + with request("test", enabled=True) as build_collector: + index.build() + assert build_collector is not None + build_counters = build_collector.as_dict(outcome="ok")["counters"] + self.assertEqual(1, build_counters["index_builds"]) + self.assertGreater(build_counters["project_loads"], 0) + + renderer = RenderService(project) + with request("test", enabled=True) as render_collector: + renderer.render("manual") + assert render_collector is not None + render_counters = render_collector.as_dict(outcome="ok")["counters"] + self.assertGreater(render_counters["render_prepare_calls"], 0) + self.assertGreater(render_counters["render_output_bytes_built"], 0) + + with request("test", enabled=True) as deep_collector: + renderer.deep_status("manual") + assert deep_collector is not None + deep_counters = deep_collector.as_dict(outcome="ok")["counters"] + self.assertGreater(deep_counters["render_output_bytes_hashed"], 0) + + service = DocForgeService(project, diagnostics=True) + + warm_operations = { + "sync": service.synchronize, + "node": lambda: service.invoke( + lambda: service.index.get_node("guide.workflow"), + operation_name="mcp.get_node", + ), + "search": lambda: service.invoke( + lambda: service.index.search("workflow", limit=5), + operation_name="mcp.search", + ), + "filter": lambda: service.invoke( + lambda: service.index.filter_nodes(family="guide", limit=5), + operation_name="mcp.filter", + ), + "backlinks": lambda: service.invoke( + lambda: service.index.backlinks("guide.foundation", limit=5), + operation_name="mcp.backlinks", + ), + "dependencies": lambda: service.invoke( + lambda: service.index.dependencies("guide.workflow", depth=2, limit=5), + operation_name="mcp.dependencies", + ), + "impact": lambda: service.invoke( + lambda: service.index.impact("guide.foundation", depth=2, limit=5), + operation_name="mcp.impact", + ), + "context": lambda: service.invoke( + lambda: compile_context(service.index, "active"), + operation_name="mcp.context", + ), + } + warm_results: dict[str, dict[str, object]] = {} + for name, operation in warm_operations.items(): + with self.subTest(operation=name): + result = operation() + warm_results[name] = result + diagnostics = result["diagnostics"] + for counter in ZERO_WORK_COUNTERS: + expected = ( + 1 if name == "sync" and counter == "index_synchronizations" else 0 + ) + self.assertEqual( + expected, + diagnostics["counters"][counter], + counter, + ) + self.assertGreater(diagnostics["counters"]["source_generation_checks"], 0) + + node_result = warm_results["node"] + node_diagnostics = node_result["diagnostics"] + self.assertGreater(node_diagnostics["counters"]["index_checks"], 0) + + missing_result = service.invoke( + lambda: service.index.get_node("missing.node"), + operation_name="mcp.get_node", + ) + self.assertEqual("error", missing_result["status"]) + for counter in ZERO_WORK_COUNTERS: + self.assertEqual( + 0, + missing_result["diagnostics"]["counters"][counter], + counter, + ) + + render_result = service.render_status("manual") + render_diagnostics = render_result["diagnostics"] + for counter in ZERO_WORK_COUNTERS: + self.assertEqual(0, render_diagnostics["counters"][counter], counter) + self.assertEqual(1, render_diagnostics["stages"]["render.status"]["calls"]) + jsonschema.validate(node_result, RESULT_SCHEMA) + jsonschema.validate(render_result, RESULT_SCHEMA) + + def test_structured_errors_include_diagnostics_and_schema_validation(self) -> None: + with tempfile.TemporaryDirectory() as directory: + project = Project.open(self.copy_fixture(Path(directory))) + service = DocForgeService(project, diagnostics=True) + + def fail() -> dict[str, object]: + raise DocForgeError("intentional", "Intentional telemetry error") + + result = service.invoke( + fail, + synchronize=False, + load_error_identity=False, + operation_name="mcp.invoke", + ) + self.assertEqual("error", result["status"]) + self.assertEqual("error", result["diagnostics"]["outcome"]) + jsonschema.validate(result, RESULT_SCHEMA) + + def test_visualization_status_error_has_one_request_and_no_hidden_work(self) -> None: + with tempfile.TemporaryDirectory() as directory: + root = self.copy_fixture(Path(directory)) + project = Project.open(root) + service = DocForgeService(project, diagnostics=True) + service.visualization = ViewerManagerClient( + service.index, + state_path=root / ".docforge" / "missing-viewer-manager.json", + ) + + result = service.visualization_status() + + self.assertEqual("error", result["status"]) + counters = result["diagnostics"]["counters"] + for counter in ZERO_WORK_COUNTERS: + self.assertEqual(0, counters[counter], counter) + self.assertEqual(1, counters["viewer_manager_requests"]) + self.assertEqual( + 1, + result["diagnostics"]["stages"]["visualization.status"]["calls"], + ) + self.assertEqual( + 1, + result["diagnostics"]["stages"]["viewer.manager"]["calls"], + ) + + def test_diagnostics_are_dropped_before_the_primary_result(self) -> None: + with tempfile.TemporaryDirectory() as directory: + original = Project.open(self.copy_fixture(Path(directory))) + limits = replace(original.descriptor.limits, max_tool_output_chars=600) + project = Project(replace(original.descriptor, limits=limits)) + service = DocForgeService(project, diagnostics=True) + result = service.invoke( + lambda: { + "status": "ok", + "project_id": project.descriptor.project_id, + "revision": "unversioned", + "source_hash": "0" * 64, + }, + synchronize=False, + operation_name="mcp.invoke", + ) + self.assertEqual("ok", result["status"]) + self.assertNotIn("diagnostics", result) + + def test_cli_diagnostics_flag_is_additive_and_defaults_off(self) -> None: + base_arguments = ["--project-root", "/unused", "info"] + with mock.patch("docforge.cli._run", return_value={"status": "ok"}): + with mock.patch("sys.stdout", new_callable=io.StringIO) as output: + self.assertEqual(0, cli_main(base_arguments)) + self.assertNotIn("diagnostics", json.loads(output.getvalue())) + + with mock.patch("sys.stdout", new_callable=io.StringIO) as output: + self.assertEqual( + 0, + cli_main( + [ + "--project-root", + "/unused", + "--diagnostics", + "info", + ] + ), + ) + result = json.loads(output.getvalue()) + self.assertEqual("cli.info", result["diagnostics"]["operation"]) + + +if __name__ == "__main__": + unittest.main() diff --git a/tools/milestone0_baseline.py b/tools/milestone0_baseline.py index 1709e4b..f125d8a 100644 --- a/tools/milestone0_baseline.py +++ b/tools/milestone0_baseline.py @@ -144,6 +144,12 @@ This deterministic benchmark content exists only in a disposable temporary direc ) +def write_synthetic_project(root: Path, node_count: int) -> None: + """Create the shared disposable generic benchmark fixture.""" + + _write_project(root, node_count) + + def _json_size(value: object) -> int | None: if value is None: return None @@ -183,6 +189,29 @@ def _measure( return result, last +def measure_operation( + operation: Callable[[], object], + *, + samples: int, + warmups: int = 1, + response_size: bool = True, +) -> tuple[dict[str, object], object]: + """Measure one operation using the shared baseline method.""" + + return _measure( + operation, + samples=samples, + warmups=warmups, + response_size=response_size, + ) + + +def synthetic_node_id(index: int) -> str: + """Return one deterministic node identifier from the shared fixture.""" + + return _node_id(index) + + def _run(command: list[str]) -> str: return subprocess.run( command, diff --git a/tools/milestone1_benchmark.py b/tools/milestone1_benchmark.py new file mode 100644 index 0000000..1c18226 --- /dev/null +++ b/tools/milestone1_benchmark.py @@ -0,0 +1,228 @@ +"""Milestone 1 warm-operation benchmark with algorithmic zero-work gates.""" + +from __future__ import annotations + +import argparse +import json +import platform +import resource +import subprocess +import sys +import tempfile +from collections.abc import Callable, Mapping +from pathlib import Path +from typing import cast + +from milestone0_baseline import ( + measure_operation, + synthetic_node_id, + write_synthetic_project, +) + +from docforge.context import compile_context +from docforge.index import ProjectIndex +from docforge.mcp_server import DocForgeService +from docforge.project import Project +from docforge.rendering import RenderService +from docforge.viewer_manager import ViewerManagerClient + +ROOT = Path(__file__).resolve().parents[1] +ZERO_WORK_COUNTERS = ( + "project_loads", + "source_files_parsed", + "source_bytes_parsed", + "adapter_projection_loads", + "adapter_source_extractions", + "index_builds", + "render_prepare_calls", + "render_output_bytes_built", + "render_output_bytes_hashed", +) + + +def _parser() -> argparse.ArgumentParser: + parser = argparse.ArgumentParser( + description="Gate warm DocForge2 core work on a disposable deterministic project." + ) + parser.add_argument("--nodes", type=int, default=1000) + parser.add_argument("--samples", type=int, default=10) + parser.add_argument("--output", type=Path) + return parser + + +def _git(command: list[str]) -> str: + return subprocess.run( + ["git", *command], + cwd=ROOT, + check=True, + capture_output=True, + text=True, + ).stdout.strip() + + +def _diagnostics(result: object) -> Mapping[str, object]: + if not isinstance(result, Mapping): + raise RuntimeError("Measured operation returned a non-object result") + result_payload = cast(Mapping[str, object], result) + diagnostics_value = result_payload.get("diagnostics") + if not isinstance(diagnostics_value, Mapping): + raise RuntimeError("Measured operation did not return diagnostics") + diagnostics = cast(Mapping[str, object], diagnostics_value) + counters_value = diagnostics.get("counters") + if not isinstance(counters_value, Mapping): + raise RuntimeError("Measured diagnostics did not return counters") + counters = cast(Mapping[str, object], counters_value) + for counter in ZERO_WORK_COUNTERS: + if counters.get(counter) != 0: + raise RuntimeError(f"Warm operation performed forbidden work: {counter}") + return diagnostics + + +def _operation( + operation: Callable[[], dict[str, object]], + *, + samples: int, + p95_limit_ms: float, + expected_status: str = "ok", +) -> dict[str, object]: + measurement, last = measure_operation(operation, samples=samples) + if not isinstance(last, Mapping): + raise RuntimeError(f"Measured operation did not return status={expected_status}") + last_payload = cast(Mapping[str, object], last) + if last_payload.get("status") != expected_status: + raise RuntimeError(f"Measured operation did not return status={expected_status}") + diagnostics = _diagnostics(last_payload) + p95_ms = float(cast(float, measurement["p95_ms"])) + if p95_ms > p95_limit_ms: + raise RuntimeError(f"Warm operation p95 {p95_ms:.3f} ms exceeds {p95_limit_ms:.3f} ms") + return { + **measurement, + "p95_limit_ms": p95_limit_ms, + "diagnostics": diagnostics, + } + + +def _benchmark(root: Path, node_count: int, samples: int) -> dict[str, object]: + project = Project.open(root) + ProjectIndex(project).build() + RenderService(project).render("manual") + service = DocForgeService(project, diagnostics=True) + service.visualization = ViewerManagerClient( + service.index, + state_path=root / ".docforge" / "missing-viewer-manager.json", + ) + target = synthetic_node_id(node_count - 1) + operations = { + "warm_no_change_synchronize": _operation( + service.synchronize, + samples=samples, + p95_limit_ms=100, + ), + "exact_node": _operation( + lambda: service.invoke( + lambda: service.index.get_node(target), + operation_name="mcp.get_node", + ), + samples=samples, + p95_limit_ms=50, + ), + "missing_node_error": _operation( + lambda: service.invoke( + lambda: service.index.get_node("missing.node"), + operation_name="mcp.get_node", + ), + samples=samples, + p95_limit_ms=50, + expected_status="error", + ), + "search_limit_20": _operation( + lambda: service.invoke( + lambda: service.index.search("Synthetic measurement", limit=20), + operation_name="mcp.search", + ), + samples=samples, + p95_limit_ms=100, + ), + "dependencies_depth_8": _operation( + lambda: service.invoke( + lambda: service.index.dependencies(target, depth=8, limit=100), + operation_name="mcp.dependencies", + ), + samples=samples, + p95_limit_ms=100, + ), + "context_32k": _operation( + lambda: service.invoke( + lambda: compile_context(service.index, "active", 32_000), + operation_name="mcp.context", + ), + samples=samples, + p95_limit_ms=250, + ), + "render_receipt_status": _operation( + lambda: service.render_status("manual"), + samples=samples, + p95_limit_ms=50, + ), + "visualization_unavailable_status": _operation( + service.visualization_status, + samples=samples, + p95_limit_ms=50, + expected_status="error", + ), + } + return { + "fixture": { + "kind": "synthetic_generic", + "node_count": node_count, + "edge_count": node_count - 1, + "source_file_count": node_count, + }, + "operations": operations, + "process_peak_rss_kib": int(resource.getrusage(resource.RUSAGE_SELF).ru_maxrss), + } + + +def main() -> int: + arguments = _parser().parse_args() + if arguments.nodes < 2: + raise SystemExit("--nodes must be at least 2") + if arguments.samples < 1: + raise SystemExit("--samples must be positive") + with tempfile.TemporaryDirectory(prefix="docforge-milestone1-") as directory: + root = Path(directory).resolve() + write_synthetic_project(root, arguments.nodes) + measurement = _benchmark(root, arguments.nodes, arguments.samples) + result = { + "schema_version": 1, + "benchmark": "docforge2_milestone1", + "source": { + "revision": _git(["rev-parse", "HEAD"]), + "dirty": bool(_git(["status", "--porcelain"])), + }, + "environment": { + "platform": platform.platform(), + "machine": platform.machine(), + "python": platform.python_version(), + "implementation": platform.python_implementation(), + }, + "method": { + "clock": "time.perf_counter_ns", + "memory": "resource.getrusage(RUSAGE_SELF).ru_maxrss", + "response_size": "UTF-8 bytes of compact sorted JSON", + "samples": arguments.samples, + "zero_work_counters": list(ZERO_WORK_COUNTERS), + }, + **measurement, + } + encoded = json.dumps(result, sort_keys=True, indent=2) + "\n" + if arguments.output is not None: + output = arguments.output.resolve() + output.parent.mkdir(parents=True, exist_ok=True) + output.write_text(encoded, encoding="utf-8") + sys.stdout.write(encoded) + return 0 + + +if __name__ == "__main__": + sys.exit(main())