At the Forge - Profiling Rails Applications
The production log profiler shows which actions require attention, but it doesn't tell why a particular action might be giving you trouble. For that, you need to dive into the application a bit more, profiling not a set of actions, but one particular action.
This is possible thanks to a built-in script that comes with Rails, script/performance/request. This script follows a set of instructions written in a (presumably short) Ruby program, using a similar set of commands and subroutines that are available for integration tests.
In other words, you use integration-test syntax to describe a short sequence of one or more actions and run this program via the request profiler. Then, the request profiler produces two output files that describe what was going on behind the scenes as those requests were serviced. This information can help you improve the performance of this particular action.
In order for this script to work, first install the ruby-prof gem:
gem install --remote ruby-prof
Once that is installed, you need to create a simple integration test script. This script doesn't need to be wrapped in the same object that the integration tests themselves use. Instead, simply create a file named test.rb, and put it somewhere on the filesystem. I created a directory named test/performance and put it there, with the one-line contents as follows:
Notice that I'm using URLs here, rather than names of controllers and actions. Finally, with this in place, invoke the profiler:
script/performance/request -n 10 test/performance/test.rb
Now you should see the program telling you that it's warming up and then reporting as it goes through each of the iterations you specified. In the above example, the -n 10 option indicates the number of times the script should be invoked; by default, it's 100.
Note that the output files are put in the test directory (to which you might not have write access by default). And, indeed, the output files are quite useful, but they can be confusing the first time you look at them.
The first output file, profile-output.txt, is (as the suffix implies) a text file that shows how much time was spent in each method, both as a time measure and as a percentage of the total run time. Consider the following:
%self total self wait child calls name 13.74 58.35 38.13 0.00 20.22 608720 Buffer#read
This means there were 608,720 calls to Buffer#read during the test, which took a total of 38.13 seconds, or 13.75% of the execution time. Because this is a built-in method, you can't optimize it. However, you can try to reduce the number of times it is called, so that it will take even less time.
The question is, how do we know which functions are calling Buffer#read? Perhaps reading from buffers is an inevitable part of a Web application, and we just need to realize that?
If you look at the second file, profile-graph.html, you see a nicely linked description of which methods called which other methods, and how long it took. Each box represents the analysis of one method, and the method being analyzed is printed in bold.
All of the methods above the boldfaced method name are parent methods (that is, methods that called the one in question); whereas, methods below the current one are child methods (that is, methods that are called by the method being analyzed). By looking at who called Buffer#read, you can see which methods (if any) need optimizing or a smaller number of invocations. By going back and forth between methods, their parents and the source code, you can cut down on a great deal of waste, making your sites more efficient than before.
This month, we looked at two basic profiling tools that programmers can use to identify performance problems in Rails-based Web sites. There are, of course, other tools we can use, but the fact that these are so nicely integrated into Rails makes us all the more likely to use them. With constant monitoring and tweaking, we can make our sites run faster without having to resort to buying additional servers.
The Rails Way, by Obie Fernandez, has become my favorite, because it includes so much useful information, as well as code examples. It doesn't try to teach you Rails, but it does provide a great deal of information that is useful for advanced users as well as newcomers.
Advanced Rails, by Brad Ediger, gives some greater depth to several topics, such as performance optimization, ActiveRecord features, RESTful sites and internationalization, among others.
Rails Analyzer Tools: this is a collection of tools that can help you better understand your Rails-based site. The production log profiler is part of the Rails Analysis Tools set; see rails-analyzer.rubyforge.org for more information.
Reuven M. Lerner, a longtime Web/database developer and consultant, is a PhD candidate in learning sciences at Northwestern University, studying on-line learning communities. He recently returned (with his wife and three children) to their home in Modi'in, Israel, after four years in the Chicago area.