Rails / Performance

From WhyNotWiki

Jump to: navigation, search

See also: Ruby / Performance, http://en.wikipedia.org/wiki/Computer_performance

[1]

[2]


Contents

[edit] Rails' default performance logging

Processing SlowController#action (for 192.168.254.118 at 2007-03-30 15:58:29) [GET]
  Session ID: a24d159162c90a77b6e19b0864d88fb1
  Parameters: {"action"=>"action", "controller"=>"slow"}
Rendering slow/default
Completed in 0.00480 (208 reqs/sec) | Rendering: 0.00291 (60%) | 200 OK [http://riblet/slow/action]

If you have queries on the page, it will also give you a benchmark for the DB part (running queries) of the request.

Processing SlowController#db (for 192.168.254.118 at 2007-03-30 15:57:31) [GET]
  Session ID: a24d159162c90a77b6e19b0864d88fb1
  Parameters: {"action"=>"db", "controller"=>"slow"}
  ^[[4;36;1mUser Load (0.001329)^[[0m   ^[[0;1mSELECT * FROM users WHERE (users."name" = 'Bench') LIMIT 1^[[0m
  ^[[4;35;1mUser Update (0.001852)^[[0m   ^[[0mUPDATE users SET "name" = 'Bench' WHERE "id" = 1^[[0m
Rendering slow/default
Completed in 0.23593 (4 reqs/sec) | Rendering: 0.00296 (1%) | DB: 0.00318 (1%) | 200 OK [http://riblet/slow/db]

[edit] Question: How come the percentages don't add up to 100%?

Because the 100% is the time taken for the entire action. Rendering and DB are components of that time, yes, but there can be code in the controller action itself that also take up time. That time (apparently) is what takes the balance.

See Rails / Performance / Dissection of performance-/benchmarking-related code for details.

[edit] Top Rails Performance Problems

[2]

  • slow helper methods
  • complicated routes
  • associations
  • retrieving too much from DB
  • slow session storage (see Rails / Sessions)
  • DB performance is usually not a bottleneck! Instantiating ActiveRecord objects is more expensive.

[edit] Benchmarking

[edit] star_full.gif star_full.gif star_full.gif RailsBench

Homepage: http://railsbench.rubyforge.org/ blog


Project/Development: http://rubyforge.org/projects/railsbench/


Description: Railsbench is a small collection of ruby and shell scripts which make measuring raw performance of rails apps a snap. All tests are run from the command prompt making performance regression testing easy.

Railsbench measures the raw performance of Rails request processing, ignoring the time spent passing the request from the web server to the Rails application.
License: GNU General Public License (GPL) version 2


Readiness: 4 - Beta, Registered: 2005-08-22 01:13, railsbench-0.9.1 January 14, 2007


[2]

Measures raw performance of Rails request processing configured through:

  • benchmark definitions
    • $RAILS_ROOT/config/benchmarks.yml
    • defines which urls you want to visit in yaml
  • benchmark class configuration
    • $RAILS_ROOT/config/benchmarks.rb
    • creates a benchmarking instance with an ActiveRecordStore
    • Can also define user locking etc.
  • stores benchmark data in $RAILS_PERF_DATA
  • indexed by date and benchmark time
  • uses additional Rails environment benchmarking

[edit] Installation

Run in your app's root directory:

railsbench install

This will create: config/benchmarks.yml, config/benchmarks.rb

Modify config/benchmarks.yml. List the actions/URLs you want to be benchmarked.

[edit] Example run

config/benchmarks.yml:
slow_action:
    uri: /slow/slow_action


> time railsbench perf_run 2 '-bm=slow_action'
benchmarking 3 runs with options 2 -bm=slow_action

perf data file: /home/tyler/perf_run.slow_action.txt
    requests=2, options=-bm=slow_action

loading environment                 3.54289

page request                          total  stddev%     r/s    ms/r
/slow_action                        0.03123   0.4270   64.04   15.62

all requests                        0.03123   0.4270   64.04   15.62

real    0m11.786s

> cat /home/tyler/perf_run.slow_action.txt
ruby /usr/lib/ruby/gems/1.8/gems/railsbench-0.9.1/script/perf_bench 2 -bm=slow_action
                                      user     system      total        real
loading environment               2.970000   0.580000   3.550000 (  3.552244)
/slow_action                      0.030000   0.000000   0.030000 (  0.031213)
                                      user     system      total        real
loading environment               2.930000   0.590000   3.520000 (  3.823915)
/slow_action                      0.030000   0.000000   0.030000 (  0.031141)
                                      user     system      total        real
loading environment               2.970000   0.570000   3.540000 (  3.540627)
/slow_action                      0.030000   0.000000   0.030000 (  0.042731)

[edit] Caveats

[4]

  • Only GET requests are supported.

[edit] Dissection

Calling railsbench perf_run will cause the following files to be executed...

/usr/lib/ruby/gems/1.8/gems/railsbench-0.9.1/bin/railsbench
/usr/lib/ruby/gems/1.8/gems/railsbench-0.9.1/script/perf_run
/usr/lib/ruby/gems/1.8/gems/railsbench-0.9.1/lib/railsbench/perf_utils.rb
/usr/lib/ruby/gems/1.8/gems/railsbench-0.9.1/script/perf_bench

Basically all bin/railsbench does is set ENV['RAILS_ROOT'] and load the subcommand given as the argument to railsbench (for instance, perf_run):

  ...
    if File.exists? 'config/environment.rb'
      ENV['RAILS_ROOT'] = File.expand_path '.'
  ...
  load "#{RAILSBENCH_BASE}/script/#{real_cmd}"

lib/railsbench/perf_utils.rb

def perf_run(script, iterations, options, raw_data_file)
  perf_runs = (ENV['RAILS_PERF_RUNS'] ||= "3").to_i

  disable_gc_stats
  set_gc_variables([iterations, options])

  perf_options = "#{iterations} #{options}"
  null = (RUBY_PLATFORM =~ /win32/i) ? 'nul' : '/dev/null'

  perf_cmd = "ruby #{RAILSBENCH_BINDIR}/perf_bench #{perf_options}"
  print_cmd = "ruby #{RAILSBENCH_BINDIR}/perf_times #{raw_data_file}"

  puts "benchmarking #{perf_runs} runs with options #{perf_options}"

  File.open(raw_data_file, "w"){ |f| f.puts perf_cmd }
  perf_runs.times do
    puts perf_cmd      # for debugging
    system("#{perf_cmd} >#{null}") || die("#{script}: #{perf_cmd} returned #{$?}")
  end
  File.open(raw_data_file, "a" ){|f| f.puts }

  unset_gc_variables
  system(print_cmd) || die("#{script}: #{print_cmd} returned #{$?}")
end

You can see that all perf_run does is build and call the perf_bench command to do all the dirty work (storing the results in a file such as /home/tyler/perf_run.slow_action.txt), iterating the required number of times. It then calls perf_times to actually display the results generated by perf_bench.

> railsbench perf_run 2 '-bm=slow_action'
benchmarking 3 runs with options 2 -bm=slow_action
ruby /usr/lib/ruby/gems/1.8/gems/railsbench-0.9.1/script/perf_bench 2 -bm=slow_action
ruby /usr/lib/ruby/gems/1.8/gems/railsbench-0.9.1/script/perf_bench 2 -bm=slow_action
ruby /usr/lib/ruby/gems/1.8/gems/railsbench-0.9.1/script/perf_bench 2 -bm=slow_action

script/perf_bench

bm(32) do |test|
  test.report("loading environment") do
    require 'railsbench/railsbenchmark'
    require ENV['RAILS_ROOT'] + '/config/benchmarks'
  end
  ...

  RAILS_BENCHMARKER.iterations = ARGV[0].to_i
  RAILS_BENCHMARKER.url_spec = benchmarks
  RAILS_BENCHMARKER.setup_test_urls(benchmark_name)
  RAILS_BENCHMARKER.establish_test_session
  RAILS_BENCHMARKER.warmup
  RAILS_BENCHMARKER.run_urls(test)
end

Benchmark::OUTPUT.close unless Benchmark::OUTPUT.nil? || !ENV['RAILS_BENCHMARK_FILE']

lib/railsbench/railsbenchmark.rb

  def run_urls(test)
    setup_initial_env
    if gc_frequency>0
      run_urls_with_gc_control(test, @urls, iterations, gc_frequency)
    else
      run_urls_without_gc_control(test, @urls, iterations)
    end
    delete_test_session
    delete_new_test_sessions
  end

Now I'll run the perf_bench script directly so I can actually see its output...

> export RAILS_ROOT=`pwd`
> ruby /usr/lib/ruby/gems/1.8/gems/railsbench-0.9.1/script/perf_bench 2 -bm=slow_action

                                      user     system      total        real
loading environment               3.050000   0.580000   3.630000 (  4.021684)
Content-Type: text/html; charset=utf-8
Set-Cookie: _session_id=0cd12525d44c01d40c86cf80a23e5d09; path=/
Status: 200 OK
Cache-Control: no-cache
Content-Length: 10

It looks like most of the work is actually done by Benchmarker#bm . The only thing that RailsBenchmark really takes care of is setting up and fake web request / session / environment, etc., much like a Rails functional test would do.

[edit] Built-in benchmarker script

http://wiki.rubyonrails.org/rails/pages/BenchmarkerScript

$ ruby script/performance/benchmarker 50 'Keyword.popular_keywords' 'Keyword.popular_keywords(10)'
            user     system      total        real
#1      0.060000   0.010000   0.070000 (  0.699459)
#2      0.070000   0.020000   0.090000 (  0.498171)


[edit] Other Rails Libraries/Plugins

[edit] Rails Analyzer project

Homepage: http://rails-analyzer.rubyforge.org/


Project/Development: http://rubyforge.org/projects/rails-analyzer/


Description: The Rails Analyzer project contains a collection of tools for Rails that let you discover biggest slow spots in your applications allowing you to best focus optimization efforts.





[edit] Rails Analyzer Tools

Part of: #Rails_Analyzer_project

Categories/Tags: RailsStat is a [Rails log file analyzer (category)]
Documentation: http://rails-analyzer.rubyforge.org/tools/
Source code: gem install rails_analyzer_tools



Description: Rails Analyzer Tools contains Bench, Crawler, RailsStat, IOTail and SyslogLogger libraries, and the programs bench, crawl and rails_stat based on these libraries.





http://rails-analyzer.rubyforge.org/tools/

Bench

Bench lets you benchmark the performance of a particular page. Simply give the URL, the number of requests to run and the number of threads to run in parallel.

You really, really, really don’t want to run bench against a live website.

  $ bench -u http://coop.robotcoop.com/ -r 50 -c 2
  50....45....40....35....30....25....20....15....10....5....
  Total time: 10.7073893547058
  Average time: 0.214147787094116

RailsStat

RailsStat displays the approximate number of requests, queries, and lines logged per second in 10 (or whatever) second intervals. Simply give it the path to your production log for a live Rails site and you’re done:

 $ rails_stat /var/log/production.log
 ~ 2.1 req/sec, 23.0 queries/sec, 32.8 lines/sec

SyslogLogger

SyslogLogger is a Logger replacement that logs to syslog. It is almost drop-in with a few caveats.

[edit] star_full.gif star_full.gif star_empty.gif SQLDependencyGrapher

Part of: #Rails_Analyzer_project

Categories/Tags: [Rails log file analyzer (category)]
Documentation: http://rails-analyzer.rubyforge.org/sql_dep_graph/
Source code: gem install sql_dep_graph



Description: SQLDependencyGrapher allows you to visualize the query dependencies between your database tables to better understand how they actually get used. It generates a graph of the connections between tables based on joins found in a SQL query log.
Depends on: creates a dot file that you can render with Graphviz or OmniGraffle





http://rails-analyzer.rubyforge.org/sql_dep_graph/

Usage:

  sql_dep_graph log/production.log > sql_deps.dot

  dot -Tpng sql_deps.dot > sql_deps.png


[edit] star_full.gif star_full.gif star_empty.gif Production Log Analyzer

Part of: #Rails_Analyzer_project

Categories/Tags: [Rails log file analyzer (category)]
Documentation: http://rails-analyzer.rubyforge.org/pl_analyze/
Source code: gem install production_log_analyzer



Description: The Production Log Analyzer lets you find out which pages on your site are dragging you down.
Depends on: The PL Analyzer requires the use of SyslogLogger from rails_analyzer_tools because the default Logger doesn’t give any way to associate lines logged to a request.





http://rails-analyzer.rubyforge.org/pl_analyze/

 pl_analyze /var/log/production.log
 /usr/bin/gzip -dc /var/log/production.log.0.gz | /usr/local/bin/pl_analyze /dev/stdin

Sample output

  Request Times Summary:          Count   Avg     Std Dev Min     Max
  ALL REQUESTS:                   11      0.576   0.508   0.000   1.470

  ThingsController#view:          3       0.716   0.387   0.396   1.260
  TeamsController#progress:       2       0.841   0.629   0.212   1.470
  RssController#uber:             2       0.035   0.000   0.035   0.035
  ...

  Average Request Time: 0.634
  Request Time Std Dev: 0.498

  Slowest Request Times:
          TeamsController#progress took 1.470s
          ThingsController#view took 1.260s
          PeopleController#view took 1.102s
          ...

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

  DB Times Summary:               Count   Avg     Std Dev Min     Max
  ALL REQUESTS:                   11      0.366   0.393   0.000   1.144
  ...

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

  Render Times Summary:           Count   Avg     Std Dev Min     Max
  ALL REQUESTS:                   11      0.219   0.253   0.000   0.695
  ...

The PL Analyzer also includes action_grep which lets you grab lines from a log that only match a single action.

 action_grep RssController#uber /var/log/production.log


[edit] Query Analyzer

Homepage: http://nfectio.us/articles/2006/09/20/mysql-query-analyzer-rails-plugin
Source code: http://svn.nfectio.us/plugins/query_analyzer


As listed in other directories: http://rubyfurnace.com/plugins/query_analyzer
Description: Provides query analysis using the MySQL query execution plan





http://svn.umesd.k12.or.us/plugins/query_analyzer/README [5]

The Query Analyzer plugin will expand the usability of your log files by providing query analysis using the MySQL query execution plan. Each SQL select query will be ‘EXPLAIN’ed and added to the log files right below the original query.

Using this plugin and a good understanding of the results, you will be able to analyze and optimize the queries your application is making.

Refer to http://www.mysql.org/doc/refman/5.0/en/explain.html for more information on understanding the results.

Here is a real life usage of the plugin that detected the omission of indexes on a table. In this case, it was a join table and the keys didn’t have indexes (silly me!) [I've done that! — Tyler (]. Names have been changed to protect the innocent (and make it fit 80 columns).

P Load (0.008669)
 => SELECT p.* FROM p INNER JOIN d ON p.id = d.p_id WHERE (d.p_id = 2 AND ((d.type = 'P'))) 

Analyzing P Load
   
select_type | key_len | type   | Extra       | id | possible_keys | rows | table  | ref    | key    
----------------------------------------------------------------------------------------------------
SIMPLE      |         | ALL    | Using where | 1  |               | 74   |    d   |        |        
SIMPLE      | 4       | eq_ref | Using where | 1  | PRIMARY       | 1    |    p   | d.p_id | PRIMARY


[edit] Profiling/Profilers

http://en.wikipedia.org/wiki/Performance_analysis#Use_of_profilers

A profiler is a performance analysis tool that measures the behavior of a program as it runs, particularly the frequency and duration of function calls. The output is a stream of recorded events (a trace) or a statistical summary of the events observed (a profile).

[edit] star_full.gif star_empty.gif star_empty.gif ActionProfiler

Part of: #Rails Analyzer project

Homepage: http://rails-analyzer.rubyforge.org/action_profiler/
Documentation: http://rails-analyzer.rubyforge.org/action_profiler/
Source code: gem install action_profiler



Description: Action Profiler allows you to profile a single Rails action to determine what to optimize. You can use the Production Log Analyzer and action_grep to determine which actions you should profile and what arguments to use.



Environment: Command-line, for Rails apps 




class SlowController < ApplicationController
  def index
    sloow
  end
  def sloow
    sleep 1
  end
end

> action_profiler SlowController#index
Warmup...
Profiling...
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 44.44     0.16      0.16        5    32.00    34.00  MonitorMixin.mon_check_owner
 11.11     0.20      0.04        9     4.44     4.44  String#split
  2.78     0.21      0.01       21     0.48     0.48  String#[]
  2.78     0.22      0.01        3     3.33     3.33  Kernel.hash
  2.78     0.23      0.01        1    10.00    10.00  ActionController::Base#assign_default_content_type_and_charset
...
  0.00     0.36      0.00        1     0.00     0.00  SlowController#index
...
  0.00     0.36      0.00        1     0.00     0.00  SlowController#sloow
...
  0.00     0.36      0.00        1     0.00     0.00  Kernel.sleep
...
  • Why doesn't it show sloow at the top of the list? Did it not take 1 whole s??
    • Apparently sleep does a system call and the time that it has to wait for the system call to complete doesn't count as part of its time? That seems kind of weak.
  • What is MonitorMixin and why is it taking 44% of the time??


class SlowController < ApplicationController
  def index
    10000.times do
      ' aoeusnt oensuth onue ouents'.split
    end
  end
end

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 70.30     1.87      1.87        2   935.00  2480.00  Integer#times
 16.17     2.30      0.43    10009     0.04     0.04  String#split
  6.39     2.47      0.17        5    34.00    38.00  Logger#add
  1.13     2.50      0.03       31     0.97     0.97  String#gsub

That's more like it.

Problems:

Had to patch a line in /usr/lib/ruby/gems/1.8/gems/action_profiler-1.0.0/lib/action_profiler/profiled_processor.rb

    #require__ "action_profiler/#{name.downcase}_processor"
    require "action_profiler/#{name.downcase}_processor"

It seg-faulted when I tried running it with ZenProfiler or with RubyProf (0.3 apparently) (which they recommend instead of the default profiler because the default is apparently "slow")...

> action_profiler SlowController#index
ZenProfilerProcessor
/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:32: [BUG] Segmentation fault
ruby 1.8.5 (2007-03-13) [i386-linux]
Aborted

> action_profiler SlowController#index
ProfProcessor
Warmup...
Profiling...
/usr/lib/ruby/gems/1.8/gems/actionpack-1.13.3/lib/action_controller/routing.rb:5: [BUG] Segmentation fault
ruby 1.8.5 (2007-03-13) [i386-linux]
Aborted

[edit] star_full.gif star_empty.gif star_empty.gif BrowserProfiler

Project/Development: http://rubyforge.org/projects/browser-prof/


Description: This is a rails plugin. This plugin provides an instant full performance profiling report for the request made. The result gets appended to the end of the request in HTML table format.





http://revolutiononrails.blogspot.com/2007/01/plugin-release-browser-profiler.html

Simple usage: http://localhost:3000/some/action?browser_profile!

If you add the browser_profile! param to any URL, it will append the profiling output to the bottom of the html file.

[edit] Built-in profiler script

http://wiki.rubyonrails.org/rails/pages/ProfilerScript

script/performance/profiler : to profile a single statement from within the environment.

  profiler 'Person.expensive_method(10)' [times]

[edit] conductor/lib/request_profiler.rb

http://svn.rubyonrails.org/rails/tools/conductor/lib/request_profiler.rb

module ActionController
  class Base
    # Profile each request and append the results to the response body.
    # Requires the ruby-prof C extension by Shugo Maeda [...]
    def self.profile_requests(timing_mode = :clock)
      if ProfilerFilter.available?
        ProfilerFilter.timing_mode = timing_mode
        around_filter ProfilerFilter
      end
    end
  end
end

class ProfilerFilter
    ...

    # Begin profiling.  Ignore if profiling has already begun.
    def before(controller)
      GC.disable
      Prof.start rescue true
    end

    # Finish profiling.  Append results to response body.
    def after(controller)
      results = Prof.stop
      GC.enable
      GC.start
      str = render_results(results)
      controller.response.body.gsub!(%r(</html>\s*$)m, "#{str}</html>")
    end


[edit] Template-level Caching

[2]

Cacheable Elements

  • Pages
    • Fastest. Complete pages are stored on the file system. Web server bypasses app for rendering. Scales through NFS or NAS. Problematic if app requires login.
  • Actions
    • Second fastest. Caches the result of invoking actions on controllers. User login id can be used as part of the storage key.
  • Fragments
    • Very useful for caching small fragments (hence the name) of HTML produced during request processing. Can be made user aware.
  • Action caching is just a special case of fragment caching.
  • Several storage containers are available for fragment caching.

Storage Options for Fragment Caching

  • In Memory
    • Very very fast. If your app is running fast enough with 1 app server process, go for it!
  • File System
    • Reasonably fast.
  • DrbStore
  • memcached


[edit] Data caching

http://www.rubyinside.com/railstips/posts/show/6 Caching unchanging / configuration data at application startup

If you have data that doesn't change between application restarts, cache it in a constant somewhere. For example, you might have a YAML or XML file in /config that stores application configuration data, and you could load it into a constant in environment.rb, making lookups quick and easy application-wide.

Here's how Snippets does it:

SNIPPETS_CONFIG = YAML::load(File.open("#{RAILS_ROOT}/config/snippets.yml"))

[edit] Baseline data

http://blog.kovyrin.net/2006/08/28/ruby-performance-results/ Looking For Optimal Solution: Benchmark Results Summary and Findings

Compares apache, nginix, lighttpd; mongrel, fastcghi

[edit] References

http://www.rubyinside.com/railstips/user/peter/tag/performance

http://railsexpress.de/blog/ RailsExpress.blog "How to make your rails app run reeeeeally fast!" (Stefan Kaes)

http://www.rubyinside.com/railstips/tag/performance

http://wiki.rubyonrails.org/rails/pages/BenchmarkingRails

  1. ↑ Ezra Zygmuntowicz. "Exploring the Request/Response Life-Cycle through the Mongrel and Rails Source Code", view slides
  2. ↑ 2.0 2.1 2.2 2.3 Stefen Kaes. "Rails Application Optimization Techniques & Tools", presented at RailsConf 2006 blog entry download slides, notes: [1] [2] [3]
Facts about Rails / PerformanceRDF feed
Depends on Creates a dot file that you can render with Graphviz or OmniGraffle  +, and The PL Analyzer requires the use of SyslogLogger from rails analyzer tools because the default Logger doesn’t give any way to associate lines logged to a request.  +
Licensed under GNU General Public License (GPL) version 2  +
Description [Oops! No type defined for attribute]
Retrieved from "http://whynotwiki.com/Rails_/_Performance"
Personal tools