Wrong duration for DB transaction event

[wangzlei]

[Steps to reproduce the issue]

• Create a Ruby on rails application with the X-Ray SDK for Ruby middleware [3] to send requests to the Database.
  • Create a Model and a corresponding Controller.
  • Define routing URL pattern corresponding to the Controller.
• Start the X-Ray daemon.
• Send a request to the created application.
• Confirm the the time duration for the trace in the X-Ray console.

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

[duckworth]

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
vs
https://github.com/rails/rails/blob/f12ae4448477a57c6fdac39039ac9fd60ba878bf/activesupport/lib/active_support/notifications/instrumenter.rb#L154

This issue is causing any DB related traces to show incorrect durations in the XRay console.

[duckworth]

@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

Fix ActiveSupport::Notifications.publish_eventto preserve units.
This solves the incorrect reporting of time spent running Active Record
asynchronous queries (by a factor 1000).
Jean Boussier