diff options
Diffstat (limited to 'railties')
3 files changed, 101 insertions, 77 deletions
diff --git a/railties/doc/guides/benchmarking_and_profiling/basics.txt b/railties/doc/guides/benchmarking_and_profiling/basics.txt deleted file mode 100644 index 2a34795b08..0000000000 --- a/railties/doc/guides/benchmarking_and_profiling/basics.txt +++ /dev/null @@ -1,55 +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"} - - [4;35;1mProduct Columns (0.003187)[0m [0mSHOW FIELDS FROM `products`[0m - [4;36;1mProduct Load (0.000597)[0m [0;1mSELECT * FROM `products` WHERE (`products`.`name` = 'Escape Plane') LIMIT 1[0m - -Rendering template within layouts/standard - -Rendering media/index - [4;35;1mTrack Load (0.001507)[0m [0mSELECT * FROM `tracks` WHERE (`tracks`.product_id = 1) [0m - [4;36;1mTrack Columns (0.002280)[0m [0;1mSHOW FIELDS FROM `tracks`[0m - -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. - - - - - diff --git a/railties/doc/guides/benchmarking_and_profiling/definitions.txt b/railties/doc/guides/benchmarking_and_profiling/definitions.txt deleted file mode 100644 index 565c301772..0000000000 --- a/railties/doc/guides/benchmarking_and_profiling/definitions.txt +++ /dev/null @@ -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. - diff --git a/railties/doc/guides/benchmarking_and_profiling/index.txt b/railties/doc/guides/benchmarking_and_profiling/index.txt new file mode 100644 index 0000000000..397da2dffb --- /dev/null +++ b/railties/doc/guides/benchmarking_and_profiling/index.txt @@ -0,0 +1,101 @@ +Benchmarking and Profiling Rails +================================ + +This guide covers the benchmarking and profiling tactics/tools of Rails and Ruby in general. By referring to this guide, you will be able to: + +* Understand the various types of benchmarking and profiling metrics +* Generate performance/benchmarking tests +* Use GC patched Ruby binary to measure memory usage and object allocation +* Understand the information provided by Rails inside the log files +* Learn about various tools facilitating benchmarking and profiling + +== Why Benchmark and Profile ? + +Benchmarking and Profiling is an integral part of the development cycle. It is very important that you don't make your end users wait for too long before the page is completely loaded. Ensuring a plesant browsing experience to the end users and cutting cost of unnecessary hardwares is important for any web application. + +=== What is the difference between benchmarking and profiling ? === + +Benchmarking is the process of finding out if a piece of code is slow or not. Whereas profiling is the process of finding out what exactly is slowing down that piece of code. + +== Using and understanding the log files == + +Rails logs files containt basic but very useful information about the time taken to serve every request. A typical log entry looks something like : + +[source, ruby] +---------------------------------------------------------------------------- +Processing ItemsController#index (for 127.0.0.1 at 2008-10-17 00:08:18) [GET] + Session ID: BAh7BiIKZmxhc2hJQzonQWN0aHsABjoKQHVzZWR7AA==--83cff4fe0a897074a65335 + Parameters: {"action"=>"index", "controller"=>"items"} +Rendering template within layouts/items +Rendering items/index +Completed in 5ms (View: 2, DB: 0) | 200 OK [http://localhost/items] +---------------------------------------------------------------------------- + +For this section, we're only interested in the last line from that log entry: + +[source, ruby] +---------------------------------------------------------------------------- +Completed in 5ms (View: 2, DB: 0) | 200 OK [http://localhost/items] +---------------------------------------------------------------------------- + +This data is fairly straight forward to understand. Rails uses millisecond(ms) as the metric to measures the time taken. The complete request spent 5 ms inside Rails, out of which 2 ms were spent rendering views and none was spent communication with the database. It's safe to assume that the remaining 3 ms were spent inside the controller. + +== Helper methods == + +Rails provides various helper methods inside Active Record, Action Controller and Action View to measure the time taken by a specific code. The method is called +benchmark()+ in all three components. + +[source, ruby] +---------------------------------------------------------------------------- +Project.benchmark("Creating project") do + project = Project.create("name" => "stuff") + project.create_manager("name" => "David") + project.milestones << Milestone.find(:all) +end +---------------------------------------------------------------------------- + +The above code benchmarks the multiple statments enclosed inside +Project.benchmark("Creating project") do..end+ block and prints the results inside log files. The statement inside log files will look like: + +[source, ruby] +---------------------------------------------------------------------------- +Creating projectem (185.3ms) +---------------------------------------------------------------------------- + +Please refer to http://api.rubyonrails.com/classes/ActiveRecord/Base.html#M001336[API docs] for optional options to +benchmark()+ + +Similarly, you could use this helper method inside http://api.rubyonrails.com/classes/ActionController/Benchmarking/ClassMethods.html#M000715[controllers] ( Note that it's a class method here ): + +[source, ruby] +---------------------------------------------------------------------------- +def process_projects + self.class.benchmark("Processing projects") do + Project.process(params[:project_ids]) + Project.update_cached_projects + end +end +---------------------------------------------------------------------------- + +and http://api.rubyonrails.com/classes/ActionController/Benchmarking/ClassMethods.html#M000715[views]: + +[source, ruby] +---------------------------------------------------------------------------- +<% benchmark("Showing projects partial") do %> + <%= render :partial => @projects %> +<% end %> +---------------------------------------------------------------------------- + +include::edge_rails_features.txt[] + +include::rubyprof.txt[] + +include::digging_deeper.txt[] + +include::gameplan.txt[] + +include::appendix.txt[] + +== Changelog == + +http://rails.lighthouseapp.com/projects/16213-rails-guides/tickets/4[Lighthouse ticket] + +* October 17, 2008: First revision by Pratik +* September 6, 2008: Initial version by Matthew Bergman <MzbPhoto@gmail.com>
\ No newline at end of file |