Topic: Slow Ruby Application

Hello

I have been working with a RoR application that was created by another developer.  The application runs very very slowly ie one of the pages takes 30 seconds to load at most 12 records.

Running a profile test using ruby-prof on that page makes the following flat file:

Thread ID: -605077288
Total: 29.650000

%self     total     self     wait    child    calls  name
  5.90      3.37     1.75     0.00     1.62    77200  OCI8::Util#do_ocicall
  2.56      1.92     0.76     0.00     1.16     2990  Array#each-1
  1.79     10.38     0.53     0.00     9.85        1  RubyProf::Test#run_profile
  1.55      0.46     0.46     0.00     0.00   274120  Array#[]
  1.52      3.49     0.45     0.00     3.04    12500  OCI8::Cursor#define_a_column_pre_ar
  1.38      0.85     0.41     0.00     0.44    12500  OCI8::Cursor#bind_or_define
  1.25      0.37     0.37     0.00     0.00      360  OCIStmt#execute
  1.21      0.57     0.36     0.00     0.21   105350  Kernel#===
  0.84      4.99     0.25     0.00     4.74      720  Integer#upto
  0.74      0.22     0.22     0.00     0.00   179580  Array#[]=
  0.74      4.59     0.22     0.00     4.37    12590  OCI8::Cursor#define_a_column
  0.71      0.21     0.21     0.00     0.00    75450  OCIDescriptor#attrGet
  0.71      0.21     0.21     0.00     0.00   127100  Fixnum#==
  0.64      0.19     0.19     0.00     0.00    12590  OCIStmt#defineByPos
  0.61      1.06     0.18     0.00     0.88     1360  Array#collect
  0.61      0.18     0.18     0.00     0.00    77200  Mutex#lock
  0.51      0.15     0.15     0.00     0.00    77200  Mutex#unlock
  0.47      0.17     0.14     0.00     0.03    91890  Hash#[]
  0.40      0.26     0.12     0.00     0.14       80  Array#collect-1
  0.40      0.12     0.12     0.00     0.00    11100  String#gsub
  0.37      0.11     0.11     0.00     0.00    87870  Module#===
  0.37      7.59     0.11     0.00     7.48     3740  Array#each
  0.37      0.11     0.11     0.00     0.00    77380  <Class::Thread>#current
  0.34      0.11     0.10     0.00     0.01     8000  <Object::Object>#fix_type
  0.30      0.09     0.09     0.00     0.00    82580  Hash#[]=
  0.30      0.09     0.09     0.00     0.00    13310  String#downcase
  0.30      0.13     0.09     0.00     0.04     2560  Hash#each
  0.27      0.08     0.08     0.00     0.00    33850  Kernel#nil?
  0.24      0.07     0.07     0.00     0.00    67250  Kernel#respond_to?
  0.24      0.16     0.07     0.00     0.09    12820  ActiveRecord::ConnectionAdapters::OracleAdapter#oracle_downcase
  0.24      0.07     0.07     0.00     0.00    49090  String#==
  0.20      0.12     0.06     0.00     0.06    47010  Fixnum#-
  0.20      0.06     0.06     0.00     0.00     1210  OCIStmt#fetch
  0.20      0.24     0.06     0.00     0.18      930  Array#map
  0.20      0.06     0.06     0.00     0.00    39150  OCIDefine#get
  0.20      0.06     0.06     0.00     0.00    32330  Symbol#===
  0.17      7.99     0.05     0.00     7.94      360  ActiveRecord::ConnectionAdapters::OracleAdapter#select
  0.17      0.05     0.05     0.00     0.00    28170  NilClass#nil?
  0.17      0.05     0.05     0.00     0.00    12950  OCIHandle#free
  0.17      0.10     0.05     0.00     0.05     8940  <Class::ActiveRecord::Base>#connection
  0.13      0.04     0.04     0.00     0.00     9320  Fixnum#to_s
  0.13      0.04     0.04     0.00     0.00    12590  OCIStmt#paramGet
  0.13      0.04     0.04     0.00     0.00     7620  ActiveRecord::ConnectionAdapters::OracleAdapter#quote_column_name
  0.10      0.05     0.03     0.00     0.02      750  <Class::Date>#jd_to_civil
  0.10      0.03     0.03     0.00     0.00     1600  ERB::Util#html_escape
  0.10      0.03     0.03     0.00     0.00      240  Kernel#method_missing
  0.10      0.03     0.03     0.00     0.00     2140  Hash#initialize_copy
  0.10      0.03     0.03     0.00     0.00    12500  OCIDefine#set_handle
  0.10      5.04     0.03     0.00     5.01      360  OCI8::Cursor#define_columns
  0.10      0.06     0.03     0.00     0.03     2810  ActiveRecord::Base#column_for_attribute
  0.10      0.18     0.03     0.00     0.15     1990  ActiveRecord::Base#read_attribute
  0.10      0.04     0.03     0.00     0.01      320  <Class::File>#mtime
  0.10      0.03     0.03     0.00     0.00    14530  Hash#default
  0.10      0.49     0.03     0.00     0.46     1210  OCI8::Cursor#fetch_a_row
  0.07      0.19     0.02     0.00     0.17     3950  Class#new
  0.07      0.02     0.02     0.00     0.00     4530  Float#/
  0.07      4.31     0.02     0.00     4.29       70  ActionView::Base#render
  0.07      0.21     0.02     0.00     0.19      630  ActionView::Helpers::TagHelper#tag_options
  0.07      0.02     0.02     0.00     0.00     3360  <Class::ActiveRecord::Base>#columns_hash
  0.07      0.02     0.02     0.00     0.00     6380  Kernel#kind_of?
  0.07      0.02     0.02     0.00     0.00     3470  Array#include?
  0.07      0.02     0.02     0.00     0.00      140  Hash#replace
  0.07      0.02     0.02     0.00     0.00      360  OCI8::Cursor#initialize
  0.07      0.02     0.02     0.00     0.00    12350  String#to_s
  0.07      0.03     0.02     0.00     0.01     1110  Logger#debug
  0.07      0.02     0.02     0.00     0.00     8970  <Class::ActiveRecord::Base>#active_connections
  0.07      0.02     0.02     0.00     0.00     1890  Hash#keys
  0.07      0.02     0.02     0.00     0.00     9650  Kernel#==
  0.07      0.51     0.02     0.00     0.49     1210  OCI8::Cursor#fetch


Is there any current tutorials or documentation about profiling and speeding up a RoR application?

Re: Slow Ruby Application

How much time spent in DB when rendering the page? This profiling tool you used is kinda useless.

Re: Slow Ruby Application

Thanks for the reply.  I am a little unsure where to find out that information.  The default output says:

[12 06 2009: 09:30:16] (INFO) {} Completed in 18.91651 (0 reqs/sec) | Rendering: 9.45213 (49%) | DB: 0.00000 (0%) | 200 OK [http://127.0.0.1/select]
(INFO) {} Completed in 18.91651 (0 reqs/sec) | Rendering: 9.45213 (49%) | DB: 0.00000 (0%) | 200 OK [http://127.0.0.1/select]

That output does not seem to want to tell me how long it spent in the database.  Looking through the code, I noticed that very often Ruby is being used to carry out functions that could be done in the database ie calculating averages.  Is there some advantage to carrying this out in Ruby?

Re: Slow Ruby Application

Scaling Rails screen casts done by Greg Pollack of Rails Envy fame, highly recommended.

Re: Slow Ruby Application

I know this might be a stupid question, but is the app running in "production" or "development"?

Just a thought.

Re: Slow Ruby Application

It is running in production mode.  Those screencasts that cherring suggested are excellent.  I discovered that none of the javascripts or css files are cached, and that was just the first screencast!

Also one of the methods in the program works out the average of a column by iterating over an array.  Guess I need to refactor the original programmer's source.