Add monotonic timing support for LLM invocation duration calculations

Author: keith-decker

util/opentelemetry-util-genai/src/opentelemetry/util/genai/handler.py

@@ -60,6 +60,7 @@
 
 from __future__ import annotations
 
+import timeit
 from contextlib import contextmanager
 from typing import Iterator
 
@@ -131,6 +132,9 @@ def start_llm(
             name=f"{GenAI.GenAiOperationNameValues.CHAT.value} {invocation.request_model}",
             kind=SpanKind.CLIENT,
         )
+        # Record a monotonic start timestamp (seconds) for duration
+        # calculation using timeit.default_timer.
+        invocation.monotonic_start_s = timeit.default_timer()
         invocation.span = span
         invocation.context_token = otel_context.attach(
             set_span_in_context(span)

util/opentelemetry-util-genai/src/opentelemetry/util/genai/metrics.py

@@ -3,6 +3,7 @@
 from __future__ import annotations
 
 import time
+import timeit
 from numbers import Number
 from typing import Dict, Optional
 
@@ -18,10 +19,6 @@
 _NS_PER_SECOND = 1_000_000_000
 
 
-def _now_ns() -> int:
-    return time.time_ns()
-
-
 def _get_span_start_time_ns(span: Optional[Span]) -> Optional[int]:
     if span is None:
         return None
@@ -32,12 +29,31 @@ def _get_span_start_time_ns(span: Optional[Span]) -> Optional[int]:
     return None
 
 
-def _calculate_duration_seconds(span: Optional[Span]) -> Optional[float]:
-    """Calculate duration in seconds from span start time to now."""
+def _calculate_duration_seconds(
+    span: Optional[Span], invocation: Optional[LLMInvocation] = None
+) -> Optional[float]:
+    """Calculate duration in seconds from a start time to now.
+
+    If `invocation.monotonic_start_ns` is present, use a monotonic
+    clock (`perf_counter_ns`) for elapsed time. Otherwise fall back to the
+    span's wall-clock start time (epoch ns) and `time_ns()` for now.
+
+    Returns None if no usable start time is available.
+    """
+    # Prefer an explicit monotonic start on the invocation (seconds)
+    if invocation is not None and getattr(
+        invocation, "monotonic_start_s", None
+    ):
+        start_s = invocation.monotonic_start_s
+        if isinstance(start_s, (int, float)):
+            elapsed_s = max(timeit.default_timer() - float(start_s), 0.0)
+            return elapsed_s
+
+    # Fall back to span start_time (wall clock epoch ns)
     start_time_ns = _get_span_start_time_ns(span)
     if start_time_ns is None:
         return None
-    elapsed_ns = max(_now_ns() - start_time_ns, 0)
+    elapsed_ns = max(time.time_ns() - start_time_ns, 0)
     return elapsed_ns / _NS_PER_SECOND
 
 
@@ -90,8 +106,8 @@ def record(
                 invocation.response_model_name
             )
 
-        # Calculate duration from span timing
-        duration_seconds = _calculate_duration_seconds(span)
+        # Calculate duration from span timing or invocation monotonic start
+        duration_seconds = _calculate_duration_seconds(span, invocation)
 
         span_context = set_span_in_context(span)
         if error_type:

util/opentelemetry-util-genai/src/opentelemetry/util/genai/types.py

@@ -123,6 +123,10 @@ class LLMInvocation:
     max_tokens: int | None = None
     stop_sequences: list[str] | None = None
     seed: int | None = None
+    # Monotonic start time in seconds (from timeit.default_timer) used
+    # for duration calculations to avoid mixing clock sources. This is
+    # populated by the TelemetryHandler when starting an invocation.
+    monotonic_start_s: float | None = None
 
 
 @dataclass

util/opentelemetry-util-genai/tests/test_handler_metrics.py

@@ -38,15 +38,14 @@ def test_stop_llm_records_duration_and_tokens(self) -> None:
         invocation = LLMInvocation(request_model="model", provider="prov")
         invocation.input_tokens = 5
         invocation.output_tokens = 7
-        handler.start_llm(invocation)
-        span = invocation.span
-        self.assertIsNotNone(span)
-        start_ns = self._get_span_start_time(span)
-        self.assertIsNotNone(start_ns)
+        # Patch default_timer during start to ensure monotonic_start_s
+        with patch("timeit.default_timer", return_value=1000.0):
+            handler.start_llm(invocation)
 
+        # Simulate 2 seconds of elapsed monotonic time (seconds)
         with patch(
-            "time.time_ns",
-            return_value=start_ns + 2_000_000_000,
+            "timeit.default_timer",
+            return_value=1002.0,
         ):
             handler.stop_llm(invocation)
 
@@ -92,16 +91,14 @@ def test_fail_llm_records_error_and_available_tokens(self) -> None:
         )
         invocation = LLMInvocation(request_model="err-model", provider=None)
         invocation.input_tokens = 11
-        handler.start_llm(invocation)
-        span = invocation.span
-        self.assertIsNotNone(span)
-        start_ns = self._get_span_start_time(span)
-        self.assertIsNotNone(start_ns)
+        # Patch default_timer during start to ensure monotonic_start_s
+        with patch("timeit.default_timer", return_value=2000.0):
+            handler.start_llm(invocation)
 
         error = Error(message="boom", type=ValueError)
         with patch(
-            "time.time_ns",
-            return_value=start_ns + 1_000_000_000,
+            "timeit.default_timer",
+            return_value=2001.0,
         ):
             handler.fail_llm(invocation, error)