-
Notifications
You must be signed in to change notification settings - Fork 58
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Wrong duration for DB transaction event #92
Comments
Digging deeper into this and it seems In Rails version 6, the ActiveSupport::Notifications module used Concurrent.monotonic_time to record times, which effectively reported times in seconds. In Rails 7 and higher they shifted to use Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_millisecond), which provides time measurements in milliseconds for more granular and precise timing of events. https://github.com/rails/rails/blob/6-1-stable/activesupport/lib/active_support/notifications/instrumenter.rb#L129C10-L129C36 This issue is causing any DB related traces to show incorrect durations in the XRay console. |
* Fix issue: Wrong duration for DB transaction event on ROR 7.1 #92 * Added unit tests and restructured the code * Fix unit tests * Update continuous-build.yml (#97) the latest macos-14 supports arm only. This PR using the previous version of macos image to unblock the release. * Worked on the jj22ee's comment and added logic that convert in seconds only for rails 7.1 versions. * Conditionally handle for ruby 7.1 --------- Co-authored-by: Lei Wang <66336933+wangzlei@users.noreply.github.com>
@wangzlei @jj22ee It looks like Rails actually backported a fix to 7.1.4 now https://github.com/rails/rails/releases/tag/v7.1.4
|
[Steps to reproduce the issue]
As a result, the start_time of a subsegment during a DB operation was set to a time in the distant future.
[Investigation]
aws-xray-sdk-ruby subscribes to transaction events and uses the start time of the event as the start_time of the subsegment.
https://github.com/aws/aws-xray-sdk-ruby/blob/master/lib/aws-xray-sdk/facets/rails/active_record.rb
However, while the subsegment start_time is assumed to be in seconds, the event start_time is recorded in milliseconds. In other words, it is 1000 times larger than the assumed value.
https://github.com/rails/rails/blob/0c09ae546fae39333068177b28767abbc6c8726e/activesupport/lib/active_support/notifications/ instrumenter.rb#L106
The text was updated successfully, but these errors were encountered: