feat: Add per-backend execution timing instrumentation (issue #56) (#57)

* feat: Add per-backend execution timing instrumentation (issue #56)

This change adds execution timing to backend results to improve visibility
into backend performance. This makes it easier to identify slow backends,
diagnose performance regressions, and validate caching optimizations.

Changes:
- Added execution_time_ms field to BackendResult model
- Implemented timing tracking at dispatcher level using perf_counter
- Display timing in verbose CLI output (e.g., "1567.84ms")
- Timing included in JSON output format
- All existing tests pass (239 tests)

Part of epic #52 - Performance: Optimize caching to eliminate redundant API calls

[AI-assisted]

* fix: Use actual backend response_time instead of wall-clock time

The previous implementation measured wall-clock time from task start to
finish, which showed similar times for all backends (~1.3s) because they
run concurrently. This was not useful for identifying slow backends.

Now using the existing response_time field (which each backend already
tracks internally) and converting it to milliseconds. This shows the
actual work time for each backend:
- Fast cached backends: 0-85ms
- Slow backends with API calls: 275-1641ms

This correctly identifies which backends are actually slow vs fast.

[AI-assisted]

---------

Co-authored-by: florath-ai-assistant[bot] <Andreas.Florath@telekom.de>

Author: coding-ai-assistant[bot]

src/aletheia_probe/cli.py

@@ -393,8 +393,11 @@ async def _async_assess_publication(
                         )
                     )
                     cache_indicator = " [cached]" if backend_result.cached else ""
+                    timing_info = ""
+                    if backend_result.execution_time_ms is not None:
+                        timing_info = f" ({backend_result.execution_time_ms:.2f}ms)"
                     print(
-                        f"  {status_emoji} {backend_result.backend_name}: {backend_result.status}{cache_indicator}"
+                        f"  {status_emoji} {backend_result.backend_name}: {backend_result.status}{cache_indicator}{timing_info}"
                     )
                     if backend_result.assessment:
                         print(

src/aletheia_probe/dispatcher.py

@@ -173,9 +173,9 @@ async def _query_backends(
             backend_config = self.config_manager.get_backend_config(backend_name)
             timeout = backend_config.timeout if backend_config else 15
 
-            # Create task with timeout
+            # Create task with timeout and timing wrapper
             task = asyncio.create_task(
-                backend.query_with_timeout(query_input, timeout),
+                self._query_backend_with_timing(backend, query_input, timeout),
                 name=f"backend_{backend_name}",
             )
             tasks.append((backend_name, task))
@@ -232,6 +232,27 @@ async def _query_backends(
 
         return backend_results
 
+    async def _query_backend_with_timing(
+        self, backend: Backend, query_input: QueryInput, timeout: int
+    ) -> BackendResult:
+        """Query a backend and add execution timing information.
+
+        Args:
+            backend: The backend to query
+            query_input: The query input
+            timeout: Timeout in seconds
+
+        Returns:
+            BackendResult with execution_time_ms populated
+        """
+        result = await backend.query_with_timeout(query_input, timeout)
+
+        # Convert response_time (seconds) to execution_time_ms (milliseconds)
+        # response_time already contains the actual backend execution time
+        result_dict = result.model_dump()
+        result_dict["execution_time_ms"] = result.response_time * 1000
+        return BackendResult(**result_dict)
+
     def _calculate_assessment(
         self,
         query_input: QueryInput,

src/aletheia_probe/models.py

@@ -52,6 +52,9 @@ class BackendResult(BaseModel):
     )
     response_time: float = Field(..., description="Query response time in seconds")
     cached: bool = Field(False, description="Whether result was retrieved from cache")
+    execution_time_ms: float | None = Field(
+        None, description="Backend execution time in milliseconds"
+    )
 
 
 class JournalMetadata(BaseModel):