Active Record database time logging

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

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 :).

> 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

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