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

Add cpu time, idle time, and allocations features to log subscriber events #33449

Merged
merged 1 commit into from
Jul 26, 2018

Conversation

eileencodes
Copy link
Member

This PR does a few things

  1. It changes the event subscriber from using Time.now to use process clock. This avoids issues with the machine changing time and reduces allocations by 2 for each event
  2. Adds start! and finish! methods to Event so we can record more information
  3. Adds cpu time, idle time, and allocations count to Event

cc/ @tenderlove

@eileencodes eileencodes added this to the 6.0.0 milestone Jul 26, 2018
@eileencodes eileencodes force-pushed the use-process-clock-instead-of-time branch from 4d3a37f to d587445 Compare July 26, 2018 17:57
* Use process clock instead of Time.now

This fixes any issues with the system clock changing and also eliminates
2 object allocations per event.

* Add start! and finish! methods to the event object so we can record
more information

* Adds cpu time, idle time, and allocation count for a particular event.

Co-authored-by: Aaron Patterson <aaron.patterson@gmail.com>
@yahonda
Copy link
Member

yahonda commented Jul 27, 2018

Hi, I am maintaining Oracle enhanced adapter which supports both CRuby and JRuby.

Looks like JRuby jruby 9.2.0.0 (2.5.0) 2018-05-24 81156a8 Java HotSpot(TM) 64-Bit Server VM 25.171-b11 on 1.8.0_171-b11 [linux-x86_64] raises uninitialized constant Process::CLOCK_PROCESS_CPUTIME_ID as reported rsim/oracle-enhanced#1735

Let me report it to JRuby. cc @enebo @headius

yahonda added a commit to yahonda/rails that referenced this pull request Jul 30, 2018
According to rails#33449 and rails#33468, cpu_time and allocations are 0 when
JRuby is used.

```ruby
$ ruby -v
jruby 9.2.1.0-SNAPSHOT (2.5.0) 2018-07-27 13b2df5 Java HotSpot(TM) 64-Bit Server VM 25.181-b13 on 1.8.0_181-b13 [linux-x86_64]
$ bundle exec ruby -w -Itest test/log_subscriber_test.rb -n test_event_attributes
Run options: -n test_event_attributes --seed 6231

F

Failure:
SyncLogSubscriberTest#test_event_attributes [test/log_subscriber_test.rb:84]:
Expected 0 to be > 0.

rails test test/log_subscriber_test.rb:78

Finished in 0.018983s, 52.6791 runs/s, 105.3582 assertions/s.
1 runs, 2 assertions, 1 failures, 0 errors, 0 skips
```
kamipo added a commit that referenced this pull request Nov 20, 2018
Since #33449, `event.end = Time.now` is not used anymore and should use
`event.finish!`.

We can't use `deprecate :end=` in definition time in this module due to
circular require in `active_support/deprecation/behaviors`.
@maxim
Copy link
Contributor

maxim commented Mar 25, 2019

Love this change, yet I gotta second the question asked by @bdmac in #34271. It looks like events no longer carry wall time, and we cannot reasonably get those from monotonic/cpu times. Would it perhaps make sense to add wall times to the event objects in addition to the changes here?

As far as calling Time.now in a subscriber - I'm guessing it's vulnerable to how many subscribers there are, and their own run time: it could take a while before it gets to the time-recording subscriber.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants