feat: expose privacy and intake stage timings

src/staylong/services/taskmaster.py

@@ -1,9 +1,11 @@
 """Consent-governed orchestration for StayLong's single Taskmaster workflow."""
 
-from collections.abc import Mapping
+import logging
+from collections.abc import Callable, Mapping
 from dataclasses import dataclass, replace
 from datetime import datetime, timedelta
 from enum import StrEnum
+from time import perf_counter
 from typing import Any, Protocol
 from uuid import uuid4
 
@@ -31,6 +33,13 @@
 )
 from staylong.services.reminders import Reminder, ReminderService, ReminderStatus
 
+logger = logging.getLogger(__name__)
+
+
+def _milliseconds(duration_seconds: float) -> int:
+    """Round a monotonic duration for compact, content-free operational logs."""
+    return round(duration_seconds * 1_000)
+
 
 class PrivacyGuard(Protocol):
     """Sanitizes user text before it enters persisted workflow state."""
@@ -194,6 +203,7 @@ def __init__(
         contact_drafts: ContactDraftDemoAdapter | None = None,
         reminders: ReminderService | None = None,
         privacy_guard: PrivacyGuard | None = None,
+        monotonic_clock: Callable[[], float] = perf_counter,
     ) -> None:
         self._intake_agent = intake_agent
         self._repository = repository
@@ -203,6 +213,7 @@ def __init__(
         self.integration_mode = calendar.integration_mode
         self._reminders = reminders or ReminderService()
         self._privacy_guard = privacy_guard
+        self._monotonic_clock = monotonic_clock
 
     @property
     def repository(self) -> WorkflowRepository:
@@ -217,10 +228,12 @@ def event_repository(self) -> EventRepository:
     def start(self, *, concern: str, now: datetime) -> WorkflowSnapshot:
         """Route danger before model use, otherwise begin the facts-only intake."""
         case_id = uuid4().hex
+        started_at = self._monotonic_clock()
         # Emergency detection must remain deterministic and must never wait for a model.
         protected_concern = concern
         if self._privacy_guard is not None and route_concern(concern) != EMERGENCY_ROUTE:
             protected_concern = self._privacy_guard.redact(concern).redacted_text
+        privacy_finished_at = self._monotonic_clock()
         try:
             candidate_pack = self._intake_agent.prepare_assessment_pack(protected_concern)
         except EmergencyRouteRequired:
@@ -230,6 +243,7 @@ def start(self, *, concern: str, now: datetime) -> WorkflowSnapshot:
                 stage=WorkflowStage.EMERGENCY,
             )
             return self._save(snapshot)
+        intake_finished_at = self._monotonic_clock()
 
         snapshot = WorkflowSnapshot(
             case_id=case_id,
@@ -238,12 +252,21 @@ def start(self, *, concern: str, now: datetime) -> WorkflowSnapshot:
             questions=candidate_pack.information_to_confirm,
             _candidate_pack=candidate_pack,
         )
-        return self._save_with_event(
+        saved = self._save_with_event(
             snapshot,
             event_type="concern.created",
             now=now,
             details={"source": "older-person"},
         )
+        persistence_finished_at = self._monotonic_clock()
+        logger.info(
+            "workflow.start.timing privacy_ms=%d intake_ms=%d persistence_ms=%d total_ms=%d",
+            _milliseconds(privacy_finished_at - started_at),
+            _milliseconds(intake_finished_at - privacy_finished_at),
+            _milliseconds(persistence_finished_at - intake_finished_at),
+            _milliseconds(persistence_finished_at - started_at),
+        )
+        return saved
 
     def answer_intake(
         self, *, case_id: str, answers: Mapping[str, str], now: datetime

tests/services/test_taskmaster.py

@@ -1,5 +1,6 @@
 """Behaviour-first tests for the consent-governed StayLong Taskmaster flow."""
 
+import logging
 from datetime import UTC, datetime
 
 import pytest
@@ -132,6 +133,33 @@ def test_workflow_redacts_concern_before_model_and_persistence() -> None:
     assert "[PHONE REDACTED]" in started.concern
 
 
+def test_start_logs_only_stage_timings_without_concern_content(
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    from staylong.services.taskmaster import InMemoryWorkflowRepository, TaskmasterWorkflow
+
+    ticks = iter((10.0, 10.11, 10.33, 10.66))
+    workflow = TaskmasterWorkflow(
+        intake_agent=IntakeAgent(provider=StaticProvider()),
+        repository=InMemoryWorkflowRepository(),
+        event_repository=InMemoryEventRepository(),
+        calendar=CalendarDemoAdapter(),
+        privacy_guard=StaticPrivacyGuard(),
+        monotonic_clock=lambda: next(ticks),
+    )
+
+    with caplog.at_level(logging.INFO, logger="staylong.services.taskmaster"):
+        workflow.start(
+            concern="Call 0412 345 678 about the dark hallway.",
+            now=NOW,
+        )
+
+    assert caplog.messages == [
+        "workflow.start.timing privacy_ms=110 intake_ms=220 persistence_ms=330 total_ms=660"
+    ]
+    assert "0412 345 678" not in caplog.text
+
+
 def test_emergency_route_skips_gemma_privacy_call() -> None:
     from staylong.services.taskmaster import (
         InMemoryWorkflowRepository,