Active Record database time logging

rubyonrails-core
1

I've been having a look through the code responsible for printing how much time was spent in Active Record at the end of an action. My reading of the code + experiments suggests that any database time after the render is not counted.

It seems to me that in controller_runtime.rb in Active Record, append_info_to_payload should in fact read

def append_info_to_payload(payload)   super   payload[:db_runtime] = db_runtime + ActiveRecord::LogSubscriber.reset_runtime end

Is this just an oversight?

Fred

2

I've been having a look through the code responsible for printing how much time was spent in Active Record at the end of an action. My reading of the code + experiments suggests that any database time after the render is not counted.

Yeah, my numbers are very confusingly out of whack. This is a good explanation.

It seems to me that in controller_runtime.rb in Active Record, append_info_to_payload should in fact read

def append_info_to_payload(payload) super payload[:db_runtime] = db_runtime + ActiveRecord::LogSubscriber.reset_runtime end

I tried this and got a bunch of test failures with nil in places where it wasn't expected.

Is this just an oversight?

Yeah, I doubt this was deliberate :).

3

> I've been having a look through the code responsible for printing how > much time was spent in Active Record at the end of an action. My > reading of the code + experiments suggests that any database time > after the render is not counted.

Yeah, my numbers are very confusingly out of whack. This is a good explanation.

> It seems to me that in controller_runtime.rb in Active Record, > append_info_to_payload should in fact read

> def append_info_to_payload(payload) > super > payload[:db_runtime] = db_runtime + > ActiveRecord::LogSubscriber.reset_runtime > end

I tried this and got a bunch of test failures with nil in places where it wasn't expected.

I'll have a poke around and see if I can fix this

Fred

4

Yeah, I hadn't quite thought things through - turns out no AR time was being logged at all if there was no render (ie the response was a redirect) and I'd only been looking at the render case while I was messing around. I've stuck a patch up at https://rails.lighthouseapp.com/projects/8994-ruby-on-rails/tickets/6749

Fred