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

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 fo开发者_JS百科und 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

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!)

If these times are observed in the development environment, the additional time is probably because the application classes are not being cached. The application files are being reloaded on every request.

As suggested in this answer, try setting config.cache_classes = true in environment/development.rb and restarting your server to see what effect this has on your response times. Be sure to change this back to config.cache_classes = false and restart your server once you're done.