In this second part of a six-part article series on optimizing the performance of a Ruby-on-Rails application, you will learn how to use the Rails Analyzer tool set. This article is excerpted from chapter 13 of the book Practical Rails Projects, written by Eldon Alameda (Apress; ISBN: 1590597818).


Using Rails Analyzer


The Robot Co-op, the creators of the popular 43things.com, 43places.com, and 43people.com, has released an impressive set of tools for analyzing the performance of a Rails application. The tool set is called Rails Analyzer and can be found at http://rails-analyzer.rubyforge.org/.


Rails Analyzer consists of four independent parts:




  1. The Production Log Analyzer can be used to analyze Rails log files. It produces a report that tells which actions are the most popular and which take the most time to render. It is an invaluable tool for measuring the performance of those actions that are used most often in the production setting.



  2. The Action Profiler is used to profile individual actions. Run it as the next step after using the Production Log Analyzer to find the slow actions. With the Action Profiler, you can drill down to the action and see where it is taking its time.



  3. Rails Analyzer Tools is a collection of tools for monitoring and benchmarking a Rails

    application. The tools included arebenchfor benchmarking a particular page,crawlerfor crawling a page and requesting all the local linked files on that page, andrails_statfor pinging the load status of a live production Rails application.



  4. SQL Dependency Grapher can be used to visualize the frequency of table dependencies in a Rails application. (We won’t cover this part of the tool set in this chapter.)



Let’s see how Rails Analyzer can help us. First, log on to the production server and install the needed gems:


$ sudo gem install rails_analyzer_tools production_log_analyzer action_profiler


Now we can get started by setting up for the Production Log Analyzer and then running it.


The Production Log Analyzer can’t use the standard Rails log format because it needs a log line to be able to be clearly identified with a single action. So, we need to substitute the logger withSyslogLogger, a class provided by the Rails Analyzer Tools gem. Note that this works only on Linux and FreeBSD. If you use some other production environment, consult the Rails Analyzer homepage for more information.


Add the following lines toconfig/environments/production.rb:


require 'analyzer_tools/syslog_logger' RAILS_DEFAULT_LOGGER = SyslogLogger.new


This tells Rails to use the replacement logger when in production.


Next, add the following lines to/etc/sysconf.log:


!rails

*.*              /var/log/production.log


This tellssyslogto log all Rails-related entries to your own production log file.


Now create the file and restart thesyslogdaemon:


sudo touch /var/log/production.log

sudo killall -HUP syslogd


Restart the Rails application, and it should be logging to/var/log/production.log. Confirm this by tailing the log file (withtail -f, for example) and loading a page on the site. You should see something like the following show up at the end of the output:


--------------------------------------------

Sep 28 00:46:22 emporium rails[6975]: Rendered cart/_cart (0.09150)

Sep 28 00:46:22 emporium rails[6975]: Completed in 0.53988

(1 reqs/sec) | Rendering: 0.37126 (68%) | DB: 0.05668 (10%) | 200

OK [http://emporium.com/catalog/show/17]

--------------------------------------------


Now you know that the logging is working in the way it needs to for the Production Log Analyzer.


Let’s wait overnight and see how much traffic George gathers on the site. (If you are eager to get going, write a little script that loads the pages randomly, or go the manual route by browsing around the site a few times.)


Woke up already? Good, not bad for a hacker. Let’s get back to work. Run the Production Log Analyzer to see what happened while we were asleep:


$ sudo pl_analyze /var/log/production.log


 




















































Request Times Summary: Count Avg Std Dev Min Max
ALL REQUESTS: 266 0.115 0.344 0.000 2.066
Unknown: 197 0.000 0.000 0.000 0.000
CatalogController#index: 28 1.047 0.378 0.550 2.066
CatalogController#show: 21 0.034 0.113 0.005 0.540
AboutController#index: 20 0.023 0.016 0.013 0.077

 


 


 


 


 


 


Slowest Request Times:

CatalogController#index took 2.066s

CatalogController#index took 1.750s

CatalogController#index took 1.654s

CatalogController#index took 1.504s

CatalogController#index took 1.476s

CatalogController#index took 1.392s

CatalogController#index took 1.388s

CatalogController#index took 1.237s

CatalogController#index took 1.222s

CatalogController#index took 1.219s


----------------------------------------------



 




















































DB Times Summary: 


 


 Count 


 


 Avg 


 


 Std Dev Min 


 


 Max 


 
ALL REQUESTS: 


 


 266 


 


 0.006 


 


 0.019 


 


 0.000 


 


 0.165 


 
Unknown: 


 


 197 


 


 0.000 


 


 0.000 


 


 0.000 


 


 0.000 


 
CatalogController#index: 


 


 28 


 


 0.052 


 


 0.032 


 


 0.024 


 


 0.165 


 
CatalogController#show: 


 


 21 


 


 0.003 


 


 0.012 


 


 0.000 


 


 0.057 


 
AboutController#index: 


 


 20 


 


 0.000 


 


 0.000 


 


 0.000 


 


 0.00 


 

Slowest Total DB Times:

CatalogController#index took 0.165s

CatalogController#index took 0.156s

CatalogController#index took 0.077s

CatalogController#index took 0.063s

CatalogController#index took 0.062s

CatalogController#index took 0.058s

CatalogController#index took 0.057s

CatalogController#show took 0.057s

CatalogController#index took 0.054s

CatalogController#index took 0.054s


----------------------------------------------




 




















































Render Times Summary: 


 


 Count 


 


 Avg 


 


 Std Dev Min 


 


 Max 


 
ALL REQUESTS: 


 


 266 


 


 0.099 


 


 0.306 


 


 0.000 


 


 1.934 


 
Unknown: 


 


 197 


 


 0.000 


 


 0.000 


 


 0.000 


 


 0.000 


 
CatalogController#index: 


 


 28 


 


 0.915 


 


 0.377 


 


 0.429 


 


 1.934 


 
CatalogController#show: 


 


 21 


 


 0.018 


 


 0.079 


 


 0.000 


 


 0.371 


 
AboutController#index: 


 


 20 


 


 0.020 


 


 0.010 


 


 0.013 


 


 0.055 


 


Slowest Total Render Times:

CatalogController#index took 1.934s

CatalogController#index took 1.554s

CatalogController#index took 1.524s

CatalogController#index took 1.403s

CatalogController#index took 1.396s

CatalogController#index took 1.266s

CatalogController#index took 1.208s

CatalogController#index took 1.122s

CatalogController#index took 1.102s

CatalogController#index took 1.100s


The first listing in the output is a summary of the complete request times. After that are similar summaries for the times needed in the database and for the rendering. A summary lists the different requested actions, the count of times they were requested, and the statistics of their performance (including average, minimum, and maximum times and the standard deviation). From this listing, it is pretty easy to see which actions tend to be the slowest. If a slow action is also a very popular action, it is a good candidate for being optimized in one way or another.


Following the statistical analysis is a list of the slowest individual action loads in each category. An astute reader can see that the slowest request time should match theMax field value in theALL REQUESTSrow in the statistical analysis.


From the analysis, you can see that the three actions that had been requested are pretty much equally popular. However, the index page inCatalogController is clearly the slowest, and its request times are more than one second on average.


Next, take a look at what happens in the action by using theaction_grepcommand included in the Production Log Analyzer package:


$ sudo action_grep CatalogController#index /var/log/production.log


--------------------------------------------Sep 28 12:17:50 emporium rails[10500]: Processing CatalogController#index

(for 81.193.72.157 at 2006-09-28 12:17:50) [GET]

Sep 28 12:17:50 emporium rails[10500]: Session ID:

ba0a2e9b205ed0da9390dc08ea00d114

Sep 28 12:17:50 emporium rails[10500]: Parameters: {"action"=>"index",

"controller"=>"catalog"}

Sep 28 12:17:50 emporium rails[10500]: Globalize::Language Columns

(0.002259)   SHOW FIELDS FROM globalize_languages

Sep 28 12:17:50 emporium rails[10500]: Globalize::Language Load (0.000155)

 SELECT * FROM globalize_languages WHERE (globalize_languages.`iso_639_1`

 = 'en' ) LIMIT 1

Sep 28 12:17:50 emporium rails[10500]: Cart Load (0.000108)    SELECT * FROM

carts WHERE (carts.id = 107) LIMIT 1

Sep 28 12:17:50 emporium rails[10500]: Book Count (0.000156)   SELECT

COUNT(DISTINCT books.id) FROM books LEFT OUTER JOIN authors_books

ON authors_books.book_id = books.id LEFT OUTER JOIN authors

ON authors.id =authors_books.author_id LEFT OUTER JOIN publishers

ON publishers.id = books.publisher_id

Sep 28 12:17:50 emporium rails[10500]: Globalize::Language Load (0.000650)

SELECT * FROM globalize_languages WHERE (globalize_languages.`rfc_3066` =

'en-US' ) LIMIT 1

Sep 28 12:17:50 emporium rails[10500]: Globalize::Language Load (0.000140)

SELECT * FROM globalize_languages WHERE (globalize_languages.`iso_639_1` =

'en' ) LIMIT 1

Sep 28 12:17:50 emporium rails[10500]: Book Columns (0.002050)   SHOW FIELDS

FROM books

Sep 28 12:17:50 emporium rails[10500]: Author Columns (0.001774)   SHOW FIELDS

FROM authors

Sep 28 12:17:50 emporium rails[10500]: Publisher Columns (0.001681)   SHOW

FIELDS FROM publishers

Sep 28 12:17:50 emporium rails[10500]: Book Load IDs For Limited Eager

Loading (0.000133)   SELECT id FROM books ORDER BY books.id desc LIMIT 0, 10

--------------------------------------------


The command gives a lot of output about what has been happening in theindexactions inCatalogController. You can see that most of the database traffic is related to the Globalize plugin. However, if you take a closer look at the Production Log Analyzer output, you will see that most of the time is not spent in the database, but in rendering the page (0.052 second vs. 0.915 second). We should find out what is taking so much time in rendering the page. And that’s where Action Profiler comes in.


Please check back for the third part of the series.


 


In this second part of a six-part article series on optimizing the performance of a Ruby-on-Rails application, you will learn how to use the Rails Analyzer tool set. This article is excerpted from chapter 13 of the book Practical Rails Projects, written by Eldon Alameda (Apress; ISBN: 1590597818).