I have an application running 3.0.9 and I'm trying to make sense of
the request benchmark numbers. For example, this line:
Completed 200 OK in 17800ms (Views: 46.6ms | ActiveRecord: 334.6ms)
My understanding from the past is that the difference between the
total time and the combination of Views and ActiveRecord would be
filter and controller processing. But in this case there is no
processing like that. The only thing that would be slow should be
various ActiveRecord calls. So are there cases where ActiveRecord
calls are not being added to the ActiveRecord time in the logs?
Then I've got entries like this, where the total time is less than
Views + ActiveRecord:
Completed 200 OK in 215ms (Views: 212.6ms | ActiveRecord: 1597.9ms)
So what's up with this? I checked the rails issues on github but
couldn't find anything so I thought I'd see if anyone else is getting
similar numbers or has more information.
Just watched the log scroll by and picked up a few more:
Completed 200 OK in 748ms (Views: 41.8ms | ActiveRecord: 26017.3ms)
Completed 200 OK in 230ms (Views: 82.8ms | ActiveRecord: 21721.1ms)
Completed 200 OK in 11493ms (Views: 3147.8ms | ActiveRecord:
70157.3ms)
Completed 200 OK in 1841ms (Views: 54.8ms | ActiveRecord: 45339.3ms)
Completed 200 OK in 5313ms (Views: 782.0ms | ActiveRecord: 1856.8ms)
Completed 200 OK in 12608ms (Views: 5874.5ms | ActiveRecord: 2090.9ms)
Completed 200 OK in 11143ms (Views: 1149.9ms | ActiveRecord: 3978.0ms)
Completed 200 OK in 1421ms (Views: 40.0ms | ActiveRecord: 88.5ms)
These are all from the same action, there is action caching but these
are all when either no fragment exists, or when an expired fragment
exists, which may account for some of these numbers. A fragment hit
is fast. I'll be migrating the database to a fast machine soon.
Still I'd like to know why these numbers are so off.
