getting strange loading time reports while trying to speed up rails app

Question

i am using newrelic (developer mode) for monitoring my rails application. strangely, loading the same page gives different loading results with one random part constantly overweighing the rest.

as an example (all results from same page, "messages/1", just doing a refresh)

                                             Exclusive         Total
Administration#find_by_sql                269 ms  35%   276 ms    36%
messages/show.html.erb Template           113 ms    15%     183 ms    24%
MessagesController#show                   90 ms     12%     760 ms    99%
events/_events_box.html.erb Template         24 ms  3%   24 ms     3%
SQL/show                                     19 ms  2%   19 ms    2%
User#find                                    19 ms  2%   19 ms    2%
Remainder                                    234 ms 31%  234 ms    31%

-------
subscriptions/_subscribe.html.erb Template   266 ms    44%   272 ms   45%
MessagesController#show                      61 ms  10%      606 ms   99%
messages/show.html.erb Template              61 ms  10%   365 ms   60%
SQL/other                                 24 ms     4%     24 ms  4%
layouts/_header.html.erb Template         20 ms     3%     28 ms  5%
events/_events_box.html.erb Template      19 ms     3%     19 ms  3%
Remainder                                 160 ms    26%     160 ms  26%

-------
drafts/_js_and_sbox.html.erb Template      265 ms   44%       269 ms  45%
MessagesController#show                    72 ms    12%       595 ms  100%
messages/show.html.erb Template               57 ms    9%  356 ms  59%
events/_events_box.html.erb Template          19 ms    3%     19 ms   3%
layouts/_header.html.erb Template             18 ms    3%        28 ms   5%
SQL/other                                  15 ms    2%     15 ms   2%
Remainder                                  153 ms   26%     153 ms  26%

does anyone know the reason why could a random part of the code (which is usually insignificant and load fast) always take almost half of the loading time? Maybe it's because i perform queries in some of the templates?

Answer 1

This is a bit late, but maybe it'll be helpful to other people... I think it's because garbage collecting hits at random and inflates your page load times by ~150 ms, See this article for more discussion:

ruby-prof attributes full cost of garbage collection to the method where GC gets triggered, not the methods that allocate the memory. That's like blaming the last straw for breaking the camel's back.

Answer 2

The other option sis that your db could be a bit overloaded at some times - causing slow db-queries/wait-times. NewRelic isn't very specific sometimes.

If you really want to tune your actions, I'd take NewRelic's pronouncements as guidelines for where you want to test with a better tool (eg ruby-prof).

I did a talk on using these tools: http://skillsmatter.com/podcast/ajax-ria/making-your-rails-app-kick-ass-with-ruby-prof-and-kcachegrind