Fix asyncio to_thread instrumentation to measure actual function execution

.changelog/4901.fixed

@@ -0,0 +1 @@
+`opentelemetry-instrumentation-asyncio`: fix `to_thread` instrumentation so spans and duration metrics measure the actual function execution instead of ending immediately, and record the `exception` state when the function raises

instrumentation/opentelemetry-instrumentation-asyncio/src/opentelemetry/instrumentation/asyncio/__init__.py

@@ -224,30 +224,37 @@ def wrap_taskgroup_create_task(method, instance, args, kwargs) -> None:
 
     def trace_to_thread(self, func: callable):
         """
-        Trace a function, but if already instrumented, skip double-wrapping.
+        Wrap a function so that its execution in the worker thread is
+        measured and, if enabled, traced.
         """
-        if _is_instrumented(func):
-            return func
-
-        start = default_timer()
         func_name = getattr(func, "__name__", None)
         if func_name is None and isinstance(func, functools.partial):
             func_name = func.func.__name__
-        span = (
-            self._tracer.start_span(f"{ASYNCIO_PREFIX} to_thread-" + func_name)
-            if func_name in self._to_thread_name_to_trace
-            else None
-        )
-        attr = {"type": "to_thread", "name": func_name}
-        exception = None
-        try:
-            attr["state"] = "finished"
-            return func
-        except Exception:
-            attr["state"] = "exception"
-            raise
-        finally:
-            self.record_process(start, attr, span, exception)
+
+        @functools.wraps(func)
+        def wrapper(*args, **kwargs):
+            start = default_timer()
+            span = (
+                self._tracer.start_span(
+                    f"{ASYNCIO_PREFIX} to_thread-" + func_name
+                )
+                if func_name in self._to_thread_name_to_trace
+                else None
+            )
+            attr = {"type": "to_thread", "name": func_name}
+            exception = None
+            try:
+                result = func(*args, **kwargs)
+                attr["state"] = "finished"
+                return result
+            except Exception as exc:
+                exception = exc
+                attr["state"] = "exception"
+                raise
+            finally:
+                self.record_process(start, attr, span, exception)
+
+        return wrapper
 
     def trace_item(self, coro_or_future):
         """Trace a coroutine or future item."""

instrumentation/opentelemetry-instrumentation-asyncio/tests/test_asyncio_to_thread.py

@@ -2,6 +2,7 @@
 # SPDX-License-Identifier: Apache-2.0
 import asyncio
 import functools
+import time
 from unittest.mock import patch
 
 # pylint: disable=no-name-in-module
@@ -10,7 +11,7 @@
     OTEL_PYTHON_ASYNCIO_TO_THREAD_FUNCTION_NAMES_TO_TRACE,
 )
 from opentelemetry.test.test_base import TestBase
-from opentelemetry.trace import get_tracer
+from opentelemetry.trace import StatusCode, get_tracer
 
 
 class TestAsyncioToThread(TestBase):
@@ -58,6 +59,83 @@ async def to_thread():
                     self.assertEqual(point.attributes["type"], "to_thread")
                     self.assertEqual(point.attributes["name"], "multiply")
 
+    def test_to_thread_duration_covers_execution(self):
+        def multiply(x, y):
+            time.sleep(0.1)
+            return x * y
+
+        async def to_thread():
+            result = await asyncio.to_thread(multiply, 2, 3)
+            assert result == 6
+
+        asyncio.run(to_thread())
+
+        spans = self.memory_exporter.get_finished_spans()
+        self.assertEqual(len(spans), 1)
+        span = spans[0]
+        self.assertGreaterEqual(span.end_time - span.start_time, 0.1 * 10**9)
+
+        for metric in (
+            self.memory_metrics_reader.get_metrics_data()
+            .resource_metrics[0]
+            .scope_metrics[0]
+            .metrics
+        ):
+            if metric.name == "asyncio.process.duration":
+                for point in metric.data.data_points:
+                    self.assertGreaterEqual(point.sum, 0.1)
+
+    def test_to_thread_exception(self):
+        def multiply(x, y):
+            raise ValueError("fail")
+
+        async def to_thread():
+            await asyncio.to_thread(multiply, 2, 3)
+
+        with self.assertRaises(ValueError):
+            asyncio.run(to_thread())
+
+        spans = self.memory_exporter.get_finished_spans()
+        self.assertEqual(len(spans), 1)
+        span = spans[0]
+        self.assertEqual(span.name, "asyncio to_thread-multiply")
+        self.assertEqual(span.status.status_code, StatusCode.ERROR)
+        self.assertEqual(len(span.events), 1)
+        self.assertEqual(span.events[0].name, "exception")
+
+        for metric in (
+            self.memory_metrics_reader.get_metrics_data()
+            .resource_metrics[0]
+            .scope_metrics[0]
+            .metrics
+        ):
+            if metric.name == "asyncio.process.duration":
+                for point in metric.data.data_points:
+                    self.assertEqual(point.attributes["state"], "exception")
+
+    def test_to_thread_repeated_calls(self):
+        def multiply(x, y):
+            return x * y
+
+        async def to_thread():
+            assert await asyncio.to_thread(multiply, 2, 3) == 6
+            assert await asyncio.to_thread(multiply, 4, 5) == 20
+
+        asyncio.run(to_thread())
+
+        spans = self.memory_exporter.get_finished_spans()
+        self.assertEqual(len(spans), 2)
+
+        for metric in (
+            self.memory_metrics_reader.get_metrics_data()
+            .resource_metrics[0]
+            .scope_metrics[0]
+            .metrics
+        ):
+            if metric.name == "asyncio.process.created":
+                for point in metric.data.data_points:
+                    self.assertEqual(point.value, 2)
+
     def test_to_thread_partial_func(self):
         def multiply(x, y):
             return x * y