Rails - Completed time for a request significantly higher than View and DB times

Question

I have a controller that returns JSON or XML from a fairly complex relational query with some controller logic as well.

I've tuned on the DB side by refining my query and making sure my indexes are correct for my query.

In my log I see items like this:

Completed in 740ms (View: 1, DB: 50)

So if I understand correctly this means the view took 1 second to render and the DB query was 50ms. Is all the remaining time in the controller? I've tried bypassing my controller logic and just leaving my to_json and to_xml in there and it is just as slow. As a point of reference my average returned JSON result set is 168k.

Are there other steps that go into the Completed in time? Does it include time until last byte for the network transfer?

Update: I wrapped various parts of my controller in benchmarking blocks:

self.class.benchmark("Active Record Find") do
  #my query here
end

What I found was that even though the log line says DB: 50 my active record find is taking almost all of the remaining time. So now I'm confused as to what that DB number means and why the benchmark line will say ~ 600ms but the DB: time will be ~50.

Thanks

Answer 1

Your DB number is time actually spent in the database, but not loading ActiveRecord objects.

So if you're loading 168,000 ruby active_record objects to render then as JSON, this would explain your 550 ms (or more!)