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.
|
