aboutsummaryrefslogblamecommitdiffstats
path: root/railties/doc/guides/benchmarking_and_profiling/digging_deeper.txt
blob: fe22fba078845d9c657075daa4dab08dcbe1805d (plain) (tree)








































































































                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
== Real Life Example ==
=== The setup ===

So I have been building this application for the last month and feel pretty good about the ruby code. I'm readying it for beta testers when I discover to my shock that with less then twenty people it starts to crash. It's a pretty simple Ecommerce site so I'm very confused by what I'm seeing. On running looking through my log files I find to my shock that the lowest time for a page run is running around 240 ms. My database finds aren't the problems so I'm lost as to what is happening to cause all this. Lets run a benchmark. 


[source, ruby]
----------------------------------------------------------------------------
class HomepageTest < ActionController::PerformanceTest
  # Replace this with your real tests.
  def test_homepage
    get '/'
  end
end
----------------------------------------------------------------------------

.Output
----------------------------------------------------------------------------
HomepageTest#test_homepage (115 ms warmup)
        process_time: 591 ms
        memory: 3052.90 KB
        objects: 59471
----------------------------------------------------------------------------



Obviously something is very very wrong here. 3052.90 Kb to load my minimal homepage. For Comparison for another site running well I get this for my homepage test. 

.Default
----------------------------------------------------------------------------
HomepageTest#test_homepage (19 ms warmup)
        process_time: 26 ms
              memory: 298.79 KB
             objects: 1917
----------------------------------------------------------------------------

that over a factor of ten difference. Lets look at our flat process time file to see if anything pops out at us. 

.Process time
----------------------------------------------------------------------------
20.73      0.39     0.12     0.00     0.27      420  Pathname#cleanpath_aggressive
17.07      0.14     0.10     0.00     0.04     3186  Pathname#chop_basename
 6.47      0.06     0.04     0.00     0.02     6571  Kernel#===
 5.04      0.06     0.03     0.00     0.03      840  Pathname#initialize
 5.03      0.05     0.03     0.00     0.02        4  ERB::Compiler::ExplicitScanner#scan
 4.51      0.03     0.03     0.00     0.00     9504  String#==
 2.94      0.46     0.02     0.00     0.44     1393  String#gsub
 2.66      0.09     0.02     0.00     0.07      480  Array#each
 2.46      0.01     0.01     0.00     0.00     3606  Regexp#to_s
----------------------------------------------------------------------------

Yes indeed we seem to have found the problem. Pathname#cleanpath_aggressive is taking nearly a quarter our process time and  Pathname#chop_basename another 17%. From here I do a few more benchmarks to make sure that these processes are slowing down the other pages. They are so now I know what I must do. *If we can get rid of or shorten these processes we can make our pages run much quicker*. 

Now both of these are main ruby processes so are goal right now is to find out what other process is calling them. Glancing at our Graph file I see that #cleanpath is calling #cleanpath_aggressive. #cleanpath is being called by String#gsub and from there some html template errors. But my page seems to be rendering fine. why would it be calling template errors. I'm decide to check my object flat file to see if I can find any more information. 

.Objects Created
----------------------------------------------------------------------------
20.74  34800.00 12324.00     0.00 22476.00      420  Pathname#cleanpath_aggressive
16.79  18696.00  9978.00     0.00  8718.00     3186  Pathname#chop_basename
11.47  13197.00  6813.00     0.00  6384.00      480  Array#each
 8.51  41964.00  5059.00     0.00 36905.00     1386  String#gsub
 6.07   3606.00  3606.00     0.00     0.00     3606  Regexp#to_s
----------------------------------------------------------------------------

nope nothing new here. Lets look at memory usage

.Memory Consuption
----------------------------------------------------------------------------
 40.17   1706.80  1223.70     0.00   483.10     3186  Pathname#chop_basename
 14.92    454.47   454.47     0.00     0.00     3606  Regexp#to_s
  7.09   2381.36   215.99     0.00  2165.37     1386  String#gsub
  5.08    231.19   154.73     0.00    76.46      420  Pathname#prepend_prefix
  2.34     71.35    71.35     0.00     0.00     1265  String#initialize_copy
----------------------------------------------------------------------------

Ok so it seems Regexp#to_s is the second costliest process. At this point I try to figure out what could be calling a regular expression cause I very rarely use them. Going over my standard layout I discover at the top. 


[source, html]
----------------------------------------------------------------------------
<%if request.env["HTTP_USER_AGENT"].match(/Opera/)%>
<%= stylesheet_link_tag "opera" %>
<% end %>
----------------------------------------------------------------------------

That's wrong. I mistakenly am using a search function for a simple compare function. Lets fix that. 


[source, html]
----------------------------------------------------------------------------
<%if request.env["HTTP_USER_AGENT"] =~ /Opera/%>
<%= stylesheet_link_tag "opera" %>
<% end %>
----------------------------------------------------------------------------

I'll now try my test again. 

----------------------------------------------------------------------------
process_time: 75 ms
              memory: 519.95 KB
             objects: 6537
----------------------------------------------------------------------------

Much better. The problem has been solved. Now I should have realized earlier due to the String#gsub that my problem had to be with reqexp serch function but such knowledge comes with time. Looking through the mass output data is a skill.