Permalink
Browse files

fixed up benchmarking file names, fixed commits, truncated statistics…

… section. Add real life example
  • Loading branch information...
1 parent ea1eb57 commit d64c9eaebeee2c8611c70d1be8964f28c2ae60b1 @FotoVerite FotoVerite committed Sep 22, 2008
Showing with 132 additions and 47,473 deletions.
  1. BIN railties/doc/guides/bechmarking_and_profiling/.DS_Store
  2. +0 −104 railties/doc/guides/bechmarking_and_profiling/appendix.txt
  3. +0 −54 railties/doc/guides/bechmarking_and_profiling/basics.txt
  4. +0 −22 railties/doc/guides/bechmarking_and_profiling/definitions.txt
  5. +0 −105 railties/doc/guides/bechmarking_and_profiling/digging_deeper.txt
  6. +0 −194 railties/doc/guides/bechmarking_and_profiling/edge_rails_features.txt
  7. BIN railties/doc/guides/bechmarking_and_profiling/examples/.DS_Store
  8. +0 −45,478 railties/doc/guides/bechmarking_and_profiling/examples/graph.html
  9. +0 −27 railties/doc/guides/bechmarking_and_profiling/gameplan.txt
  10. BIN railties/doc/guides/bechmarking_and_profiling/images/kgraph.png
  11. BIN railties/doc/guides/bechmarking_and_profiling/images/klist.png
  12. +0 −44 railties/doc/guides/bechmarking_and_profiling/preamble.txt
  13. +0 −180 railties/doc/guides/bechmarking_and_profiling/rubyprof.txt
  14. +0 −54 railties/doc/guides/bechmarking_and_profiling/statistics.txt
  15. +0 −271 railties/doc/guides/benchmarking_and_profiling/Basics.html
  16. +2 −2 railties/doc/guides/benchmarking_and_profiling/appendix.txt
  17. +3 −3 railties/doc/guides/benchmarking_and_profiling/basics.txt
  18. +6 −8 railties/doc/guides/benchmarking_and_profiling/definitions.txt
  19. +105 −1 railties/doc/guides/benchmarking_and_profiling/digging_deeper.txt
  20. +0 −187 railties/doc/guides/benchmarking_and_profiling/edge rails features.txt
  21. +1 −1 railties/doc/guides/benchmarking_and_profiling/gameplan.txt
  22. +0 −656 railties/doc/guides/benchmarking_and_profiling/preamble.html
  23. +3 −5 railties/doc/guides/benchmarking_and_profiling/preamble.txt
  24. +2 −2 railties/doc/guides/benchmarking_and_profiling/rubyprof.txt
  25. +10 −73 railties/doc/guides/benchmarking_and_profiling/statistics.txt
  26. +0 −2 railties/doc/guides/untitled.rb
Binary file not shown.
@@ -1,104 +0,0 @@
-== Other Profiling Tools ==
-
-There are a lot of great profiling tools out there. Some free, some not so free. This is a sort list detailing some of them.
-
-=== httperf ===
-http://www.hpl.hp.com/research/linux/httperf/[http://www.hpl.hp.com/research/linux/httperf/]
-
-A necessary tool in your arsenal. Very useful for load testing your website.
-
-#TODO write and link to a short article on how to use httperf. Anybody have a good tutorial availble.
-
-
-=== Rails Analyzer ===
-
-The Rails Analyzer project contains a collection of tools for Rails. It's open source and pretty speedy. It's not being actively worked on but is still contains some very useful tools.
-
-* The Production Log Analyzer examines Rails log files and gives back a report. It also includes action_grep which will give you all log results for a particular action.
-
-* The Action Profiler similar to Ruby-Prof profiler.
-
-* rails_stat which gives a live counter of requests per second of a running Rails app.
-
-* The SQL Dependency Grapher allows you to visualize the frequency of table dependencies in a Rails application.
-
-Their project homepage can be found at http://rails-analyzer.rubyforge.org/[http://rails-analyzer.rubyforge.org/]
-
-The one major caveat is that it needs your log to be in a different format from how rails sets it up specifically SyslogLogger.
-
-
-==== SyslogLogger ====
-
-SyslogLogger is a Logger work-alike that logs via syslog instead of to a file. You can add SyslogLogger to your Rails production environment to aggregate logs between multiple machines.
-
-More information can be found out at http://rails-analyzer.rubyforge.org/hacks/classes/SyslogLogger.html[http://rails-analyzer.rubyforge.org/hacks/classes/SyslogLogger.html]
-
-If you don't have access to your machines root system or just want something a bit easier to implement there is also a module developed by Geoffrey Grosenbach
-
-==== A Hodel 3000 Compliant Logger for the Rest of Us ====
-
-Directions taken from
-http://topfunky.net/svn/plugins/hodel_3000_compliant_logger/lib/hodel_3000_compliant_logger.rb[link to module file]
-
-Just put the module in your lib directory and add this to your environment.rb in it's config portion.
-
-------------------------------------------------------------
-require 'hodel_3000_compliant_logger'
-config.logger = Hodel3000CompliantLogger.new(config.log_path)
--------------------------------------------------------------
-
-It's that simple. Your log output on restart should look like this.
-
-.Hodel 3000 Example
-----------------------------------------------------------------------------
-Jul 15 11:45:43 matthew-bergmans-macbook-pro-15 rails[16207]:
-Parameters: {"action"=>"shipping", "controller"=>"checkout"}
-Jul 15 11:45:43 matthew-bergmans-macbook-pro-15 rails[16207]: 
-[4;36;1mBook Columns (0.003155) SHOW FIELDS FROM `books`
-Jul 15 11:45:43 matthew-bergmans-macbook-pro-15 rails[16207]: 
-[4;35;1mBook Load (0.000881) SELECT * FROM `books` WHERE (`books`.`id` = 1 AND (`books`.`sold` = 1)) 
-Jul 15 11:45:43 matthew-bergmans-macbook-pro-15 rails[16207]: 
-[4;36;1mShippingAddress Columns (0.002683) SHOW FIELDS FROM `shipping_addresses`
-Jul 15 11:45:43 matthew-bergmans-macbook-pro-15 rails[16207]: 
-[4;35;1mBook Load (0.000362) SELECT ounces FROM `books` WHERE (`books`.`id` = 1) 
-Jul 15 11:45:43 matthew-bergmans-macbook-pro-15 rails[16207]:
-Rendering template within layouts/application
-Jul 15 11:45:43 matthew-bergmans-macbook-pro-15 rails[16207]:
-Rendering checkout/shipping
-Jul 15 11:45:43 matthew-bergmans-macbook-pro-15 rails[16207]: 
-[4;36;1mBook Load (0.000548) SELECT * FROM `books`
-WHERE (sold = 0) LIMIT 3
-Jul 15 11:45:43 matthew-bergmans-macbook-pro-15 rails[16207]: 
-[4;35;1mAuthor Columns (0.002571) SHOW FIELDS FROM `authors`
-Jul 15 11:45:43 matthew-bergmans-macbook-pro-15 rails[16207]:
-Author Load (0.000811) SELECT * FROM `authors` WHERE (`authors`.`id` = 1) 
-Jul 15 11:45:43 matthew-bergmans-macbook-pro-15 rails[16207]:
-Rendered store/_new_books (0.01358)
-Jul 15 11:45:43 matthew-bergmans-macbook-pro-15 rails[16207]:
-Completed in 0.37297 (2 reqs/sec) | Rendering: 0.02971 (7%) | DB: 0.01697 (4%) | 200 OK [https://secure.jeffbooks/checkout/shipping]
-----------------------------------------------------------------------------
-
-=== Palmist ===
-An open source mysql query analyzer. Full featured and easy to work with. Also requires Hodel 3000
-http://www.flyingmachinestudios.com/projects/[http://www.flyingmachinestudios.com/projects/]
-
-=== New Relic ===
-http://www.newrelic.com/[http://www.newrelic.com/]
-
-Pretty nifty performance tools, pricey though. They do have a basic free
-service both for when in development and when you put your application into production. Very simple installation and signup.
-
-#TODO more in-depth without being like an advertisement.
-
-=== FiveRuns ===
-http://www.fiveruns.com/[http://www.fiveruns.com/]
-
-#TODO give a bit more detail
-
-==== TuneUp ====
-
-In their words "a new socially networked application profiling tool for Ruby on Rails developers. Designed for rapid application performance analysis in development, both privately or collaboratively with input from the community, FiveRuns TuneUp gives developers visibility into performance trouble spots and bottlenecks before they reach production."
-
-==== Manage ====
-
-Like new relic a production monitoring tool.
@@ -1,54 +0,0 @@
-== On The Road to Optimization ==
-=== Looking at the log file in regards to optimization ===
-
- You actually have been gathering data for benchmarking throughout your development cycle. Your log files are not just for error detection they also contain very useful information on how speedy your action is behaving.
-
-.Regular Log Output
-============================================================================
-Processing MediaController#index (for 127.0.0.1 at 2008-07-17 21:30:21) [GET]
-
- Session ID: BAh7BiIKZmxhc2hJQzonQWN0aW9uQ29udHJvbGxlcjo6Rmxhc2g6OkZsYXNo
-SGFzaHsABjoKQHVzZWR7AA==--cb57dad9c5e4704f0e1eddb3d498fef544faaf46
-
- Parameters: {"action"=>"index", "controller"=>"media"}
-
- Product Columns (0.003187) SHOW FIELDS FROM `products`
- Product Load (0.000597) SELECT * FROM `products` WHERE (`products`.`name` = 'Escape Plane') LIMIT 1
-
-Rendering template within layouts/standard
-
-Rendering media/index
- Track Load (0.001507) SELECT * FROM `tracks` WHERE (`tracks`.product_id = 1) 
- Track Columns (0.002280) SHOW FIELDS FROM `tracks`
-
-Rendered layouts/_header (0.00051)
-
-*Completed in 0.04310 (23 reqs/sec) | Rendering: 0.00819 (19%) | DB: 0.00757 (17%) | 200 OK [http://localhost/media]*
-============================================================================
-
-What concerns us here is the last line of the action.
-
-Completed in 0.04310 (23 reqs/sec) gives us the amount of requests this specific action can handle. 0.04310 is the total amount of time the process to complete and 23 reqs/sec is an estimation from this. As we will see this number is not strictly valid since is a single instance of the process. But it does give you a general feel as to how the action is performing.
-
-Rendering: 0.00819 (19%) is the amount in milliseconds and the percentage of total time needed to complete the action for rendering the view
-
-DB: 0.00757 (17%) is the amount in milliseconds and the percentage of total time needed to complete the action for querying the database
-
-Pretty easy right. But wait 17+19 equals 36. 36%! where is the rest of the time going? The rest of the time is being spent processing the controller. It is not shown but it is easy to calculate. Usually there is where most of your time ends on well functions actions.
-
-=== Why the Log File on it's Own is not Helpful ===
-
-So why can't we just use this to test our rails application. Technically that could work, but would be very stressful and slow. You don't have time to view your log after every request to see if your code is running quickly. Also a request that runs 100 reqs/sec might simply be an outlier and really usually runs at 20 reqs/sec. It's simply not enough information to do everything we need it to do but it's a start.
-
-But there is something else we must consider.
-
-=== A Simple Question, a Complicated Answer ===
-
-Is Completed in 0.04310 (23 reqs/sec) a good time. Seems like it doesn't it. 43 ms does not outrageous time for a dynamic page load. But is this a dynamic page load. Maybe it was all cached. In which case this is very slow. Or maybe I'm running on five year old equipment and this is actually blazing fast for my G3. The truth is that we can't answer the question given the data. This is part of benchmarking. We need a baseline. Through comparative analysis of all your pages in your app, and an simple dynamic page for a control we can determine how fast your pages are actually running and if any of them need to be optimized.
-
-And now for something completely different a short statistic lesson.
-
-
-
-
-
@@ -1,22 +0,0 @@
-== Terminology ==
-
-=== What We Mean by Benchmarking and Profiling ===
-
-Benchmarking: If you are new to programing you probably have heard the term mostly in comparative reviews of computer and graphic card specs. If you done a bit of coding you've probably seen in mostly in terms of comparing one language to another or iterations of the same language.
-
-Benchmarking in rails is more fine grained. It entails comparing and contrasting various parts and pages of an application against one another. Mostly one is looking for how long a page requires to render, but memory consumption is also an area of concern.
-
-While benchmarking two different sets of problems can emerge. Either you find that a few pages are performing worse then the rest of your app unexpectedly or that your whole entire application is slower then it reasonably should be. From there you start to profile to find the problem.
-
-Profiling: When a page or process is seen to be problematic due to speed or memory consumption we profile it. Meaning we measures the behavior as the page or process runs, particularly the frequency and duration of function calls. The goal of profiling is not to find bugs, but to eliminate bottlenecks and establish a baseline for future regression testing. It must be engaged in a carefully controlled process of measurement and analysis.
-
-==== What does that actually mean? ====
-
-You have to have a clear goal for when you benchmark and profile. It's very comparable to BDD where you are taking small steps towards a solution instead of trying to do it all in one large all encompassing step. A clearly defined set of expectations is essential for meaningful performance testing. We will talk more about this later.
-
-==== Where Does this Leave Us ====
-
-Numbers and data. You benchmark to compare, your profile to fix. It's all about gaining data to analyze and using that information to better your application. The most important thing you should take away at the moment that this must be done in a systematic way.
-
-So the next logical question is how do we get this data.
-
@@ -1,105 +0,0 @@
-== 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.
-
Oops, something went wrong.

0 comments on commit d64c9ea

Please sign in to comment.