Skip to content

Fix tornado server (request) duration metric calculation#3679

Merged
xrmx merged 6 commits intoopen-telemetry:mainfrom
devmonkey22:3486-tornado-server-duration2
Aug 22, 2025
Merged

Fix tornado server (request) duration metric calculation#3679
xrmx merged 6 commits intoopen-telemetry:mainfrom
devmonkey22:3486-tornado-server-duration2

Conversation

@devmonkey22
Copy link
Copy Markdown
Contributor

@devmonkey22 devmonkey22 commented Aug 5, 2025 •
edited
Loading

Description

Fix the tornado instrumenter to track a request's elapsed time in an async-safe way so concurrent requests calculate their own elapsed time for the HTTP_SERVER_DURATION metric properly. This changes the tornado instrumentation to track state (like request start time used to calculate request duration) on the per-request handler instance and not on the more global server_histogram object that is shared between requests.

Fixes #3486

Type of change

Please delete options that are not relevant.

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Breaking change (fix or feature that would cause existing functionality to not work as expected)
  • This change requires a documentation update

How Has This Been Tested?

  • Added tornado metrics test_metrics_concurrent_requests test

Without the fix, the test run errors with:
image

Does This PR Require a Core Repo Change?

  • Yes. - Link to PR:
  • No.

Checklist:

See contributing.md for styleguide, changelog guidelines, and more.

  • Followed the style guidelines of this project
  • Changelogs have been updated
  • Unit tests have been added
  • Documentation has been updated

@devmonkey22 devmonkey22 requested a review from a team as a code owner August 5, 2025 20:51
@github-actions github-actions Bot requested a review from shalevr August 5, 2025 20:51
This was referenced Aug 5, 2025
Closed
Merged
@devmonkey22 devmonkey22 changed the title [WIP] Fix tornado server (request) duration metric calculation Fix tornado server (request) duration metric calculation Aug 5, 2025
@tammy-baylis-swi
Copy link
Copy Markdown
Contributor

tammy-baylis-swi commented Aug 7, 2025

Thank you for this fix. Please could you also add/update the tests?: https://github.com/open-telemetry/opentelemetry-python-contrib/blob/74536f1a92a357c9a25fccba057ce5766d5a8f27/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py

@devmonkey22
Copy link
Copy Markdown
Contributor Author

devmonkey22 commented Aug 7, 2025

Thank you for this fix. Please could you also add/update the tests?: https://github.com/open-telemetry/opentelemetry-python-contrib/blob/74536f1a92a357c9a25fccba057ce5766d5a8f27/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py

@tammy-baylis-swi Can you think of a good way to test this race condition? I think we'd have to be able start two concurrent fetches, where one hits prepare, stays running in a (maybe 1 second sleep), the 2nd request hits (updates start_time), then both requests can complete. Then we could test that the duration for the 1st request is similar to client duration (ie: not super short like 2nd request should be). Do you know of an example already? Otherwise, I was just going to rely on the existing tests to make sure duration is still calculated and similar to client duration (just can't check race condition is fully fixed).

@tammy-baylis-swi
Copy link
Copy Markdown
Contributor

tammy-baylis-swi commented Aug 7, 2025

@tammy-baylis-swi Can you think of a good way to test this race condition? I think we'd have to be able start two concurrent fetches, where one hits prepare, stays running in a (maybe 1 second sleep), the 2nd request hits (updates start_time), then both requests can complete. Then we could test that the duration for the 1st request is similar to client duration (ie: not super short like 2nd request should be). Do you know of an example already? Otherwise, I was just going to rely on the existing tests to make sure duration is still calculated and similar to client duration (just can't check race condition is fully fixed).

I'm not actually familiar with Tornado but generally the checks for values resulting from concurrent fetches with predictable times would be helpful, if it's possible. Hmm. Would it make sense to make_app with any new routes as needed, then also use tornado.httpclient.AsyncHTTPClient to do two concurrent fetches and check resulting metrics in memory?

@devmonkey22
Copy link
Copy Markdown
Contributor Author

devmonkey22 commented Aug 8, 2025

@tammy-baylis-swi Can you think of a good way to test this race condition? I think we'd have to be able start two concurrent fetches, where one hits prepare, stays running in a (maybe 1 second sleep), the 2nd request hits (updates start_time), then both requests can complete. Then we could test that the duration for the 1st request is similar to client duration (ie: not super short like 2nd request should be). Do you know of an example already? Otherwise, I was just going to rely on the existing tests to make sure duration is still calculated and similar to client duration (just can't check race condition is fully fixed).

I'm not actually familiar with Tornado but generally the checks for values resulting from concurrent fetches with predictable times would be helpful, if it's possible. Hmm. Would it make sense to make_app with any new routes as needed, then also use tornado.httpclient.AsyncHTTPClient to do two concurrent fetches and check resulting metrics in memory?

Thanks @tammy-baylis-swi I think I found the test approach. Just need to iron out CI test failures that didn't happen locally.

@devmonkey22
Copy link
Copy Markdown
Contributor Author

devmonkey22 commented Aug 8, 2025

Should be ready for review again. Tests are passing.

tammy-baylis-swi
tammy-baylis-swi approved these changes Aug 9, 2025
View reviewed changes
Copy link
Copy Markdown
Contributor

@tammy-baylis-swi tammy-baylis-swi left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice, thank you for the commented new tests and updated OP. This lgtm; the Maintainers will also have to have a look.

@tammy-baylis-swi tammy-baylis-swi moved this to Ready for review in Python PR digest Aug 13, 2025
@xrmx xrmx enabled auto-merge (squash) August 22, 2025 15:09
@xrmx xrmx merged commit 3567a03 into open-telemetry:main Aug 22, 2025
632 checks passed
@github-project-automation github-project-automation Bot moved this from Ready for review to Done in Python PR digest Aug 22, 2025
sightseeker added a commit to sightseeker/opentelemetry-python-contrib that referenced this pull request Mar 11, 2026
@sightseeker @xrmx
Fix tornado server (request) duration metric calculation (open-teleme…
d410454 
…try#3679)

* Fix `opentelemetry-instrumentation-tornado` server (request) duration metric calculation (open-telemetry#3486)

* Update changelog

* Linting

* Add tornado metrics test_metrics_concurrent_requests test

* Fix tornado test ms to sec conversion

---------

Co-authored-by: Riccardo Magliocchetti <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@xrmx xrmx xrmx approved these changes

@tammy-baylis-swi tammy-baylis-swi tammy-baylis-swi approved these changes

@shalevr shalevr Awaiting requested review from shalevr

Assignees

@shalevr shalevr

Labels

None yet

Projects

Python PR digest
Status: Done

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

Tornado instrumentation HTTP_SERVER_DURATION metric is inaccurate and not async-safe

4 participants

@devmonkey22 @tammy-baylis-swi @xrmx @shalevr