From 3ca3ae75ba5a1ac71a7ceab529567c689fbebb5f Mon Sep 17 00:00:00 2001 From: MikeD <5084545+devmonkey22@users.noreply.github.com> Date: Fri, 9 May 2025 12:15:28 -0400 Subject: [PATCH 1/5] Fix `opentelemetry-instrumentation-tornado` server (request) duration metric calculation (#3486) --- CHANGELOG.md | 2 ++ .../opentelemetry/instrumentation/tornado/__init__.py | 10 ++++++++-- 2 files changed, 10 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 1f252e8290..50084bc665 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -139,6 +139,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ([#3447](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/3447)) - `opentelemetry-instrumentation-botocore` Capture server attributes for botocore API calls ([#3448](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/3448)) +- `opentelemetry-instrumentation-tornado` Fix server (request) duration metric calculation + ([#3486](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/3486)) ## Version 1.32.0/0.53b0 (2025-04-10) diff --git a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py index e396558076..385f2f17ba 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py @@ -211,6 +211,7 @@ def client_response_hook(span, future): _logger = getLogger(__name__) _TraceContext = namedtuple("TraceContext", ["activation", "span", "token"]) +_HANDLER_STATE_KEY = "_otel_state_key" _HANDLER_CONTEXT_KEY = "_otel_trace_context_key" _OTEL_PATCHED_KEY = "_otel_patched_key" @@ -402,7 +403,10 @@ def _wrap(cls, method_name, wrapper): def _prepare( tracer, server_histograms, request_hook, func, handler, args, kwargs ): - server_histograms[_START_TIME] = default_timer() + otel_handler_state = { + _START_TIME: default_timer() + } + setattr(handler, _HANDLER_STATE_KEY, otel_handler_state) request = handler.request if _excluded_urls.url_disabled(request.uri): @@ -622,8 +626,10 @@ def _record_prepare_metrics(server_histograms, handler): def _record_on_finish_metrics(server_histograms, handler, error=None): + otel_handler_state = getattr(handler, _HANDLER_STATE_KEY, None) or {} + start_time = otel_handler_state.get(_START_TIME, None) or default_timer() elapsed_time = round( - (default_timer() - server_histograms[_START_TIME]) * 1000 + (default_timer() - start_time) * 1000 ) response_size = int(handler._headers.get("Content-Length", 0)) From 0d23c861b5f5c7e2e1062a16fc676daa96036982 Mon Sep 17 00:00:00 2001 From: MikeD <5084545+devmonkey22@users.noreply.github.com> Date: Tue, 5 Aug 2025 16:40:16 -0400 Subject: [PATCH 2/5] Update changelog --- CHANGELOG.md | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 50084bc665..e8080aa58c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,6 +11,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## Unreleased +### Fixed + +- `opentelemetry-instrumentation-tornado` Fix server (request) duration metric calculation + ([#3679](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/3679)) + ## Version 1.36.0/0.57b0 (2025-07-29) ### Fixed @@ -139,8 +144,6 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ([#3447](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/3447)) - `opentelemetry-instrumentation-botocore` Capture server attributes for botocore API calls ([#3448](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/3448)) -- `opentelemetry-instrumentation-tornado` Fix server (request) duration metric calculation - ([#3486](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/3486)) ## Version 1.32.0/0.53b0 (2025-04-10) From 1761813a5d4cd634d97fd53b10350a0fc3a98742 Mon Sep 17 00:00:00 2001 From: MikeD <5084545+devmonkey22@users.noreply.github.com> Date: Tue, 5 Aug 2025 17:53:32 -0400 Subject: [PATCH 3/5] Linting --- .../src/opentelemetry/instrumentation/tornado/__init__.py | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py index 385f2f17ba..e79117a8d0 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py @@ -403,9 +403,7 @@ def _wrap(cls, method_name, wrapper): def _prepare( tracer, server_histograms, request_hook, func, handler, args, kwargs ): - otel_handler_state = { - _START_TIME: default_timer() - } + otel_handler_state = {_START_TIME: default_timer()} setattr(handler, _HANDLER_STATE_KEY, otel_handler_state) request = handler.request @@ -628,9 +626,7 @@ def _record_prepare_metrics(server_histograms, handler): def _record_on_finish_metrics(server_histograms, handler, error=None): otel_handler_state = getattr(handler, _HANDLER_STATE_KEY, None) or {} start_time = otel_handler_state.get(_START_TIME, None) or default_timer() - elapsed_time = round( - (default_timer() - start_time) * 1000 - ) + elapsed_time = round((default_timer() - start_time) * 1000) response_size = int(handler._headers.get("Content-Length", 0)) metric_attributes = _create_metric_attributes(handler) From a45d6176b892dddbdcac63f38c26b9f90f5b524a Mon Sep 17 00:00:00 2001 From: MikeD <5084545+devmonkey22@users.noreply.github.com> Date: Fri, 8 Aug 2025 12:53:03 -0400 Subject: [PATCH 4/5] Add tornado metrics test_metrics_concurrent_requests test --- .../tests/test_metrics_instrumentation.py | 75 +++++++++++++++++++ .../tests/tornado_test_app.py | 9 +++ 2 files changed, 84 insertions(+) diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py index ea601ce8e9..5dd0f87b12 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py @@ -13,8 +13,11 @@ # limitations under the License. +import asyncio from timeit import default_timer +import tornado.testing + from opentelemetry.instrumentation.tornado import TornadoInstrumentor from opentelemetry.sdk.metrics.export import HistogramDataPoint @@ -165,6 +168,78 @@ def test_basic_metrics(self): ), ) + @tornado.testing.gen_test + async def test_metrics_concurrent_requests(self): + """ + Test that metrics can handle concurrent requests and calculate in an async-safe way. + """ + req1 = self.http_client.fetch(self.get_url("/slow?duration=1.0")) + req2 = self.http_client.fetch(self.get_url("/async")) + await asyncio.gather(req1, req2) + + metrics = self.get_sorted_metrics() + self.assertEqual(len(metrics), 7) + + client_duration = metrics[0] + server_duration = metrics[4] + self.assertEqual(client_duration.name, "http.client.duration") + self.assertEqual(server_duration.name, "http.server.duration") + + # Calculating duration requires tracking state via `_HANDLER_STATE_KEY`, so we want to make sure + # duration is calculated properly per request, and doesn't affect concurrent requests. + req1_client_duration_data_point = next( + dp + for dp in client_duration.data.data_points + if "/slow" in dp.attributes.get("http.url") + ) + req1_server_duration_data_point = next( + dp + for dp in server_duration.data.data_points + if "/slow" in dp.attributes.get("http.target") + ) + req2_client_duration_data_point = next( + dp + for dp in client_duration.data.data_points + if "/async" in dp.attributes.get("http.url") + ) + req2_server_duration_data_point = next( + dp + for dp in server_duration.data.data_points + if "/async" in dp.attributes.get("http.target") + ) + + # Server and client durations should be similar (adjusting for msecs vs secs) + self.assertAlmostEqual( + abs( + req1_server_duration_data_point.sum / 1000.0 + - req1_client_duration_data_point.sum + ), + 0.0, + delta=0.01, + ) + self.assertAlmostEqual( + abs( + req2_server_duration_data_point.sum / 1000.0 + - req2_client_duration_data_point.sum + ), + 0.0, + delta=0.01, + ) + + # Make sure duration is roughly equivalent to expected (req1/slow) should be around 1 second + self.assertAlmostEqual( + req1_server_duration_data_point.sum / 1000.0, + 1.0, + delta=0.1, + msg="Should have been about 1 second", + ) + self.assertAlmostEqual( + req2_server_duration_data_point.sum, + 0.0, + delta=0.1, + msg="Should have been really short", + ) + def test_metric_uninstrument(self): self.fetch("/") TornadoInstrumentor().uninstrument() diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/tornado_test_app.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/tornado_test_app.py index 1523375212..4adac0ae3f 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/tornado_test_app.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/tornado_test_app.py @@ -1,4 +1,5 @@ # pylint: disable=W0223,R0201 +import asyncio import time import tornado.web @@ -106,6 +107,13 @@ def get(self): self.set_status(200) +class SlowHandler(tornado.web.RequestHandler): + async def get(self): + with self.application.tracer.start_as_current_span("slow"): + duration = float(self.get_argument("duration", "1.0")) + await asyncio.sleep(duration) + + class RaiseHTTPErrorHandler(tornado.web.RequestHandler): def get(self): raise tornado.web.HTTPError(403) @@ -133,6 +141,7 @@ def make_app(tracer): (r"/ping", HealthCheckHandler), (r"/test_custom_response_headers", CustomResponseHeaderHandler), (r"/raise_403", RaiseHTTPErrorHandler), + (r"/slow", SlowHandler), (r"/echo_socket", EchoWebSocketHandler), ] ) From 97b99a33dc4da19408267c57df9c694ddb489767 Mon Sep 17 00:00:00 2001 From: MikeD <5084545+devmonkey22@users.noreply.github.com> Date: Fri, 8 Aug 2025 13:06:48 -0400 Subject: [PATCH 5/5] Fix tornado test ms to sec conversion --- .../tests/test_metrics_instrumentation.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py index 5dd0f87b12..2afa05a20a 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py @@ -234,7 +234,7 @@ async def test_metrics_concurrent_requests(self): msg="Should have been about 1 second", ) self.assertAlmostEqual( - req2_server_duration_data_point.sum, + req2_server_duration_data_point.sum / 1000.0, 0.0, delta=0.1, msg="Should have been really short",