Skip to content
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

Improve duration counting using monotonic clock #424

Merged
merged 4 commits into from Sep 17, 2020

Conversation

soulcutter
Copy link
Contributor

@soulcutter soulcutter commented May 10, 2018

When measuring durations, it's preferable to use the system monotonic
clock rather than Time.now in order to avoid problems with the wall
clock potentially moving forwards or backwards for corrections that
would throw off calculation of elapsed time.

https://blog.dnsimple.com/2018/03/elapsed-time-with-ruby-the-right-way/

This was written in order to preserve the existing behavior in cases where the start time or end time were manually set.

NEW BEHAVIOR

  • If a span has start and finish called in-order, with no explicit start_time or finish_time given it will use the monotonic clock to measure duration.

Existing (preserved) behavior

  • If a span has finish called without first having called start the duration will be 0
  • If a span has start called with an explicit start_time, and finish called with no explicit finish_time then duration uses the wall clock for the end time
  • If a span has start with no start_time, and finish called with an explicit finish_time, duration uses the wall clock for the start time

TODO

  • Needs tests for the above behavior. Existing behavior may already be tested - I am unsure, need to verify.
  • Figure out problem with appraisal rake test:grape

When measuring durations, it's preferable to use the system monotonic
clock rather than `Time.now` in order to avoid problems with the wall
clock potentially moving forwards or backwards for corrections that
would throw off calculation of elapsed time.

https://blog.dnsimple.com/2018/03/elapsed-time-with-ruby-the-right-way/
This extracts the stateful duration attributes from the Span class into
a Duration class that is able to calculate duration for itself using the
wall clock if times are explicitly set, or a monotonic clock if no times
are explicitly set.

This was extracted partially because the logic in Span was getting
messy, and partly because Rubocop was complaining that the Span class
was too long.
@delner delner added core Involves Datadog core libraries community Was opened by a community member labels May 10, 2018
@delner
Copy link
Contributor

delner commented May 23, 2018

@soulcutter You mentioned that this one might need to be shelved for a bit. If that's the case, would it make sense to close it now, and perhaps re-open it when you'd like to resubmit for consideration?

@soulcutter
Copy link
Contributor Author

Before working further on this, is this a change that you would consider merging when complete?

@delner
Copy link
Contributor

delner commented May 31, 2018

If it improves the accuracy of our traces, I would certainly consider it. But before I make a promise about merging this, could you maybe share a summary list of benefits/drawbacks to sell me on this?

@soulcutter
Copy link
Contributor Author

I think the link in the description illustrates the problems with using "wall time" when measuring time - wall time doesn't always move forwards - there are cases where the wall time is inaccurate for measuring duration

@delner delner self-requested a review November 2, 2018 20:33
@delner delner mentioned this pull request Feb 6, 2020
@soulcutter
Copy link
Contributor Author

soulcutter commented Sep 6, 2020

Related to: #625 (comment)

Hey @delner / @mikhailov - I might be able to get this restarted (at this point I'd probably start fresh, though). I can easily-enough remove the ruby-concurrent dependency (although it's a solid lib used by Rails and many other professional apps & gems). Are there any other changes beyond that you'd look for, though - I saw would take minimal changes - I think this IS minimal for the purposes of maintaining existing behavior - is there something that sticks out as being non-minimal (other than the dependency)?

@soulcutter
Copy link
Contributor Author

thinkin about it, I'd be even MORE happy if y'all would pick it up. Seems like it would make it more likely to actually get merged if you were driving it. Also... like.. you're getting paid to do it, and it has been raised independently by 3 different people, one of which (me) put some time in to offer an approach. Like... can you prioritize it? It's not a big thing, but it's an important thing for timing accuracy which I think it important to your business.

@brettlangdon brettlangdon requested a review from a team September 9, 2020 16:09
Copy link
Member

@marcotc marcotc left a comment

Choose a reason for hiding this comment

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

Thank you for all the work so far, @soulcutter.
We are scheduling ourselves to finish this work, we'll pick it up soon!

I left a few comments as a reminder to ourselves on a few changes we need to do.

@@ -11,6 +13,8 @@ module Datadog
# within a larger operation. Spans can be nested within each other, and in those instances
# will have a parent-child relationship.
class Span
extend Forwardable
Copy link
Member

Choose a reason for hiding this comment

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

Forwardable has some performance that we'd like to avoid. It allocates a new object on every method call, which is not desirable. It is also slower, but I'm more concerned with the memory allocation for each call to the delegated methods:

require 'benchmark/ips'
require 'benchmark/memory'

require 'forwardable'

class Foo
  extend Forwardable

  def initialize
    @delegate = Bar.new
  end

  def_delegators :@delegate, :perform

  def def_perform
    @delegate.perform
  end
end

class Bar
  def perform; end
end

instance = Foo.new

Benchmark.memory do |x|
  x.report('forwardable') { instance.perform }
  x.report('def perform') { instance.def_perform }

  x.compare!
end

Benchmark.ips do |x|
  x.report('forwardable') { instance.perform }
  x.report('def perform') { instance.def_perform }

  x.compare!
end
Calculating -------------------------------------
         forwardable    40.000  memsize (     0.000  retained)
                         1.000  objects (     0.000  retained)
                         0.000  strings (     0.000  retained)
         def perform     0.000  memsize (     0.000  retained)
                         0.000  objects (     0.000  retained)
                         0.000  strings (     0.000  retained)

Comparison:
         def perform:          0 allocated
         forwardable:         40 allocated - Infx more
Warming up --------------------------------------
         forwardable   831.919k i/100ms
         def perform     1.807M i/100ms
Calculating -------------------------------------
         forwardable      7.722M (± 6.1%) i/s -     39.100M in   5.082914s
         def perform     18.442M (± 2.6%) i/s -     92.146M in   5.000256s

Comparison:
         def perform: 18441718.1 i/s
         forwardable:  7722268.6 i/s - 2.39x  (± 0.00) slower

end

def duration_marker
Concurrent.monotonic_time
Copy link
Member

Choose a reason for hiding this comment

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

We can use the existing Datadog::Utils::Time.get_time monotonic time method.
With this, we can remove the dependency on concurrent-ruby.

@ericmustin ericmustin mentioned this pull request Sep 14, 2020
@ericmustin ericmustin merged commit f9b295d into DataDog:master Sep 17, 2020
@ericmustin ericmustin added this to the 0.41.0 milestone Sep 30, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
community Was opened by a community member core Involves Datadog core libraries
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants