Site performance improvement

betame342 · December 14, 2007, 6:23pm

Hi,

I have a question, on how to further improve the site. I attached the
profiler of the site.

Currently, It take about 1.8 seconds to load.

At first I have question on

“Mysql#get_length” which take the longest to run. What this means? is
the query time to get data from database? or the time to process data
from database?
“Integer#times” => what this one mean

Thank you in advance,
Beta

Processing SiteController#index (for at 2007-12-14 17:17:30) [GET]
Session ID: 37ae3e35922944de02a29c40080bd5aa
Parameters: {“action”=>“index”, “controller”=>“site”}
Rendering within layouts/site
Rendering site/index
Completed in 1.86557 (0 reqs/sec) | Rendering: 0.02519 (1%) | DB:
0.97598 (52%) | 200 OK [http://www.domainname.com/]
[http://www.domainname.com/]

Thread ID: 47637799080480
Total: 0.96

%self total self wait child calls name

Thread ID: 47637798421720
Total: 1.79

%self total self wait child calls name
14.53 0.47 0.26 0.00 0.21 15822 Mysql#get_length
9.50 0.84 0.17 0.00 0.67 625 Integer#times
7.82 0.14 0.14 0.00 0.00 29018 String#slice!
7.82 0.21 0.14 0.00 0.07 391 Array#each_index
4.47 0.08 0.08 0.00 0.00 18146 Array#<<
3.91 0.07 0.07 0.00 0.00 5631 IO#write
3.91 0.07 0.07 0.00 0.00 18944 Hash#[]=
3.35 0.06 0.06 0.00 0.00 17305 Kernel#==
2.79 0.15 0.05 0.00 0.10 3329
ActiveRecord::Base#==
2.79 0.06 0.05 0.00 0.01 16425 Hash#[]
2.23 0.04 0.04 0.00 0.00 32530 Array#[]
2.23 0.04 0.04 0.00 0.00 7274 String#to_i
1.68 0.42 0.03 0.00 0.39 344 Array#each-1
1.68 0.05 0.03 0.00 0.02 524 Array#each-2
1.68 0.09 0.03 0.00 0.06 36750 Fixnum#==
1.68 0.09 0.03 0.00 0.06 6658 Asset#id
1.68 0.03 0.03 0.00 0.00 2390 Symbol#to_s
1.68 0.54 0.03 0.00 0.51 78 Array#each
1.68 0.07 0.03 0.00 0.04 673 Mysql::Net#read
1.12 0.95 0.02 0.00 0.93 657 Mysql#read_one_row
1.12 0.02 0.02 0.00 0.00 16286 String#length
1.12 0.05 0.02 0.00 0.03 282 Article#vote
1.12 0.17 0.02 0.00 0.15 535 Array#include?
1.12 0.05 0.02 0.00 0.03 282 Article#asset

betame342 · December 14, 2007, 10:23pm

On Dec 14, 5:23 pm, Beta B. [email protected]
wrote:

from database?
http://railsmanual.com/class/Mysql/get_length
2. “Integer#times” => what this one mean

It’s the times method on Integer. 3.times { puts “Ho”} will output
Ho
Ho
Ho
Do you have the native mysql gem installed? it looks like you’re not;
that will hurt you.

Fred

betame342 · December 15, 2007, 1:51am

Frederick C. wrote:

Do you have the native mysql gem installed? it looks like you’re not;
that will hurt you.

Fred

Excellent idea. Now the speed improve from 2 second to .5 seconds.

My next step is to even optimize it. This time, I don’t have slowdown in
mysql access anymore

Processing SiteController#index (for at 2007-12-15 00:46:33) [GET]
Session ID: 7258ae45fb0596b232e18603eca096ea
Parameters: {“action”=>“index”, “controller”=>“site”}
Rendering within layouts/site
Rendering site/index
Completed in 0.52546 (1 reqs/sec) | Rendering: 0.01480 (2%) | DB:
0.00223 (0%) | 200 OK [http://www.domainname.com/]
[http://www.domainname.com/]

Thread ID: 47273109057680
Total: 0.52

%self total self wait child calls name
11.54 0.10 0.06 0.00 0.04 6658 Asset#id
11.54 0.21 0.06 0.00 0.15 3329
ActiveRecord::Base#==
7.69 0.05 0.04 0.00 0.01 16425 Hash#[]
5.77 0.03 0.03 0.00 0.00 524 Array#each-2
3.85 0.02 0.02 0.00 0.00 1159 String#to_s
3.85 0.23 0.02 0.00 0.21 535 Array#include?
3.85 0.02 0.02 0.00 0.00 16
Mysql::Result#each_hash
3.85 0.02 0.02 0.00 0.00 3607 Kernel#class
1.92 0.01 0.01 0.00 0.00 26
ActiveRecord::Base#interpolate_sql
1.92 0.02 0.01 0.00 0.01 1
ActionView::Base::CompiledTemplates#_run_rhtml_47app47views47layouts47site46rhtml
1.92 0.42 0.01 0.00 0.41 344 Array#each-1
1.92 0.01 0.01 0.00 0.00 3348 Fixnum#==
1.92 0.01 0.01 0.00 0.00 1744
ActiveRecord::Reflection::MacroReflection#name
1.92 0.45 0.01 0.00 0.44 62 Array#each
1.92 0.01 0.01 0.00 0.00 1154 String#==
1.92 0.03 0.01 0.00 0.02 1388
ActiveRecord::Associations::ClassMethods::JoinDependency::JoinBase#record_id
1.92 0.01 0.01 0.00 0.00 139
ActiveRecord::ConnectionAdapters::Quoting#quote
1.92 0.38 0.01 0.00 0.37 564
ActiveRecord::Associations::ClassMethods::JoinDependency#construct_association
1.92 0.03 0.01 0.00 0.02 383
ActiveRecord::Callbacks::ClassMethods#instantiate
1.92 0.01 0.01 0.00 0.00 1952
ActiveRecord::Associations::ClassMethods::JoinDependency::JoinBase#aliased_primary_key
1.92 0.01 0.01 0.00 0.00 3329 Kernel#equal?
1.92 0.04 0.01 0.00 0.03 332 Enumerable#inject
1.92 0.01 0.01 0.00 0.00 7274 String#to_i
1.92 0.01 0.01 0.00 0.00 1180 Hash#default
1.92 0.05 0.01 0.00 0.04 566 Kernel#send-1
1.92 0.01 0.01 0.00 0.00 8
ActiveRecord::Associations::ClassMethods::JoinDependency::JoinAssociation#association_join
1.92 0.01 0.01 0.00 0.00 54 String#empty?
1.92 0.01 0.01 0.00 0.00 97
ActiveRecord::ConnectionAdapters::MysqlAdapter#quote_column_name
1.92 0.01 0.01 0.00 0.00 3329
Kernel#instance_of?
1.92 0.01 0.01 0.00 0.00 2390 Symbol#to_s
1.92 0.01 0.01 0.00 0.00 1612 Symbol#===
1.92 0.03 0.01 0.00 0.02 282 Article#vote
1.92 0.01 0.01 0.00 0.00 808
ActiveRecord::Associations::AssociationProxy#target

betame342 · December 15, 2007, 5:14am

Frederick C. wrote:

On Dec 15, 12:51 am, Beta B. [email protected]
wrote:

Well it’s hard to guess without seeing any code, but the fact that
AR::Base#== is being called so many times is suspicious.
I’d guess that you’re eager-loading multiple associations. I’d cut
back on those a bit - eager loading is handy but it can sometimes hurt
more than it helps (especially multiple has_manys - you end up getting
a full cartesian product back from the db that rails has to chomp
through).

Fred

Yap. You are right again. I am eager loading the multiple associations
and did not put the “unless read_fragment”.

unless read_fragment(“views-layout-site”)
@main_articles = Article.find(:all, :include => [:asset, :vote],
:conditions=>“assets.parent_id is null”,
:order=>“stat_final_ranking desc”, :limit=>20)
end

I am still reading some tips from
http://darwinweb.net/articles/66-optimizing_and_simplifying_limited_eager_loading_in_activerecord

betame342 · December 15, 2007, 2:07am

On Dec 15, 12:51 am, Beta B. [email protected]
wrote:

Well it’s hard to guess without seeing any code, but the fact that
AR::Base#== is being called so many times is suspicious.
I’d guess that you’re eager-loading multiple associations. I’d cut
back on those a bit - eager loading is handy but it can sometimes hurt
more than it helps (especially multiple has_manys - you end up getting
a full cartesian product back from the db that rails has to chomp
through).

Fred

betame342 · December 15, 2007, 5:21am

Frederick C. wrote:

On Dec 15, 12:51 am, Beta B. [email protected]
wrote:

Well it’s hard to guess without seeing any code, but the fact that
AR::Base#== is being called so many times is suspicious.
I’d guess that you’re eager-loading multiple associations. I’d cut
back on those a bit - eager loading is handy but it can sometimes hurt
more than it helps (especially multiple has_manys - you end up getting
a full cartesian product back from the db that rails has to chomp
through).

Fred

now I am happy. :)…

It’s able to handle 16 request per seconds.

Processing SiteController#index (for at 2007-12-15 04:08:12) [GET]
Session ID: 1d7c866bd0a1c1f744c51e5b64f336e5
Parameters: {“action”=>“index”, “controller”=>“site”}
Rendering within layouts/site
Rendering site/index
Completed in 0.06147 (16 reqs/sec) | Rendering: 0.05765 (93%) | DB:
0.00150 (2%) | 200 OK [http://www.domainname.com/]
[http://www.domainname.com/]

Thread ID: 47300583503400
Total: 0.07

%self total self wait child calls name
28.57 0.02 0.02 0.00 0.00 1686 String#==
14.29 0.04 0.01 0.00 0.03 4
ActionView::Base#compile_template
14.29 0.01 0.01 0.00 0.00 1
Class::ActionController::Base#hidden_actions
14.29 0.01 0.01 0.00 0.00 286 Symbol#===
14.29 0.03 0.01 0.00 0.02 4
ERB::Compiler::ExplicitScanner#scan
14.29 0.01 0.01 0.00 0.00 26 Kernel#sprintf