vendor/rails/railties/doc/guides/source/benchmarking_and_profiling/digging_deeper.txt

   1 == Real Life Example ==
   2 === The setup ===
   3
   4 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.
   5
   6
   7 [source, ruby]
   8 ----------------------------------------------------------------------------
   9 class HomepageTest < ActionController::PerformanceTest
  10   # Replace this with your real tests.
  11   def test_homepage
  12     get '/'
  13   end
  14 end
  15 ----------------------------------------------------------------------------
  16
  17 .Output
  18 ----------------------------------------------------------------------------
  19 HomepageTest#test_homepage (115 ms warmup)
  20         process_time: 591 ms
  21         memory: 3052.90 KB
  22         objects: 59471
  23 ----------------------------------------------------------------------------
  24
  25
  26
  27 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.
  28
  29 .Default
  30 ----------------------------------------------------------------------------
  31 HomepageTest#test_homepage (19 ms warmup)
  32         process_time: 26 ms
  33               memory: 298.79 KB
  34              objects: 1917
  35 ----------------------------------------------------------------------------
  36
  37 that over a factor of ten difference. Lets look at our flat process time file to see if anything pops out at us.
  38
  39 .Process time
  40 ----------------------------------------------------------------------------
  41 20.73      0.39     0.12     0.00     0.27      420  Pathname#cleanpath_aggressive
  42 17.07      0.14     0.10     0.00     0.04     3186  Pathname#chop_basename
  43  6.47      0.06     0.04     0.00     0.02     6571  Kernel#===
  44  5.04      0.06     0.03     0.00     0.03      840  Pathname#initialize
  45  5.03      0.05     0.03     0.00     0.02        4  ERB::Compiler::ExplicitScanner#scan
  46  4.51      0.03     0.03     0.00     0.00     9504  String#==
  47  2.94      0.46     0.02     0.00     0.44     1393  String#gsub
  48  2.66      0.09     0.02     0.00     0.07      480  Array#each
  49  2.46      0.01     0.01     0.00     0.00     3606  Regexp#to_s
  50 ----------------------------------------------------------------------------
  51
  52 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*.
  53
  54 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.
  55
  56 .Objects Created
  57 ----------------------------------------------------------------------------
  58 20.74  34800.00 12324.00     0.00 22476.00      420  Pathname#cleanpath_aggressive
  59 16.79  18696.00  9978.00     0.00  8718.00     3186  Pathname#chop_basename
  60 11.47  13197.00  6813.00     0.00  6384.00      480  Array#each
  61  8.51  41964.00  5059.00     0.00 36905.00     1386  String#gsub
  62  6.07   3606.00  3606.00     0.00     0.00     3606  Regexp#to_s
  63 ----------------------------------------------------------------------------
  64
  65 nope nothing new here. Lets look at memory usage
  66
  67 .Memory Consuption
  68 ----------------------------------------------------------------------------
  69  40.17   1706.80  1223.70     0.00   483.10     3186  Pathname#chop_basename
  70  14.92    454.47   454.47     0.00     0.00     3606  Regexp#to_s
  71   7.09   2381.36   215.99     0.00  2165.37     1386  String#gsub
  72   5.08    231.19   154.73     0.00    76.46      420  Pathname#prepend_prefix
  73   2.34     71.35    71.35     0.00     0.00     1265  String#initialize_copy
  74 ----------------------------------------------------------------------------
  75
  76 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.
  77
  78
  79 [source, html]
  80 ----------------------------------------------------------------------------
  81 <%if request.env["HTTP_USER_AGENT"].match(/Opera/)%>
  82 <%= stylesheet_link_tag "opera" %>
  83 <% end %>
  84 ----------------------------------------------------------------------------
  85
  86 That's wrong. I mistakenly am using a search function for a simple compare function. Lets fix that.
  87
  88
  89 [source, html]
  90 ----------------------------------------------------------------------------
  91 <%if request.env["HTTP_USER_AGENT"] =~ /Opera/%>
  92 <%= stylesheet_link_tag "opera" %>
  93 <% end %>
  94 ----------------------------------------------------------------------------
  95
  96 I'll now try my test again.
  97
  98 ----------------------------------------------------------------------------
  99 process_time: 75 ms
 100               memory: 519.95 KB
 101              objects: 6537
 102 ----------------------------------------------------------------------------
 103
 104 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.
 105