Home arrow Ruby-on-Rails arrow Page 2 - Using Rails Analyzer for Performance Optimization
RUBY-ON-RAILS

Using Rails Analyzer for Performance Optimization


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

Author Info:
By: Apress Publishing
Rating: 5 stars5 stars5 stars5 stars5 stars / 2
December 07, 2010
TABLE OF CONTENTS:
  1. · Using Rails Analyzer for Performance Optimization
  2. · Using the Production Log Analyzer

print this article
SEARCH DEVARTICLES

Using Rails Analyzer for Performance Optimization - Using the Production Log Analyzer
(Page 2 of 2 )

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 AvgStd Dev Min Max
ALL REQUESTS:266 0.115 0.3440.000 2.066
Unknown: 197 0.000 0.0000.000 0.000
CatalogController#index: 281.047 0.3780.550 2.066
CatalogController#show:210.034 0.1130.005 0.540
AboutController#index: 200.023 0.0160.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.001

 

 

 

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.


DISCLAIMER: The content provided in this article is not warranted or guaranteed by Developer Shed, Inc. The content provided is intended for entertainment and/or educational purposes in order to introduce to the reader key ideas, concepts, and/or product reviews. As such it is incumbent upon the reader to employ real-world tactics for security and implementation of best practices. We are not liable for any negative consequences that may result from implementing any information covered in our articles or tutorials. If this is a hardware review, it is not recommended to open and/or modify your hardware.

blog comments powered by Disqus
RUBY-ON-RAILS ARTICLES

- Ruby-on-Rails Faces Second Security Flaw in ...
- Ruby 2.0 Prepped for February 2013 Release
- Why LinkedIn Switched from Ruby on Rails
- Adding Style with Action Pack
- Handling HTML in Templates with Action Pack
- Filters, Controllers and Helpers in Action P...
- Action Pack and Controller Filters
- Action Pack Categories and Events
- Logging Out, Events and Templates with Actio...
- Action Pack Sessions and Architecture
- More on Action Pack Partial Templates
- Action Pack Partial Templates
- Displaying Error Messages with the Action Pa...
- Action Pack Request Parameters
- Creating an Action Pack Registration Form

Watch our Tech Videos 
Dev Articles Forums 
 RSS  Articles
 RSS  Forums
 RSS  All Feeds
Write For Us 
Weekly Newsletter
 
Developer Updates  
Free Website Content 
Contact Us 
Site Map 
Privacy Policy 
Support 

Developer Shed Affiliates

 




© 2003-2018 by Developer Shed. All rights reserved. DS Cluster - Follow our Sitemap
Popular Web Development Topics
All Web Development Tutorials