Perftools Text Output 34
2 1.6% 72.0% 10 8.0% ActionDispatch::Routing::RouteSet::Generator#initialize
Number of times execution was in
this method when the sample was taken
That sample count as a percentage
of all samples taken
Friday, February 3, 12
Slide 35
Slide 35 text
Perftools Text Output 35
2 1.6% 72.0% 10 8.0% ActionDispatch::Routing::RouteSet::Generator#initialize
Percentage of samples already printed
before this line
Number of samples in this method and
methods it calls
Percentage of samples in this method and
methods it calls
Friday, February 3, 12
Slide 36
Slide 36 text
PDF Output
36
Friday, February 3, 12
Slide 37
Slide 37 text
Perftools PDF Output 37
Samples recorded in this
method
Calling Methods
Methods It Calls
Samples in this method
and methods it calls
Friday, February 3, 12
Slide 38
Slide 38 text
/Users/jcasimir/.rvm/rubies/ruby-1.9.2-p290/bin/ruby
Total samples: 131
Focusing on: 131
Dropped nodes with <= 0 abs(samples)
Dropped edges with <= 0 samples
ActionDispatch
BestStandardsSupport#call
0 (0.0%)
of 80 (61.1%)
Bullet
Rack#call
0 (0.0%)
of 80 (61.1%)
80
Rack
PerftoolsProfiler
ProfilerMiddleware#call
0 (0.0%)
of 80 (61.1%)
80
Rack
PerftoolsProfiler
ProfileOnce#act
0 (0.0%)
of 80 (61.1%)
Rack
PerftoolsProfiler
Profiler#profile
0 (0.0%)
of 80 (61.1%)
80
80
Friday, February 3, 12
Slide 39
Slide 39 text
ActionView
AbstractRenderer#wrap_formats
0 (0.0%)
of 78 (59.5%)
ActionView
TemplateRenderer#render_template
0 (0.0%)
of 77 (58.8%)
77
ActionView
Renderer#render_template
0 (0.0%)
of 78 (59.5%)
78
ActionView
TemplateRenderer#render
0 (0.0%)
of 78 (59.5%)
78
78
ActionView
AbstractRenderer#instrument
0 (0.0%)
of 77 (58.8%)
ActionView
TemplateRenderer#render_with_layout
0 (0.0%)
of 77 (58.8%)
77
77
Friday, February 3, 12
Slide 40
Slide 40 text
Perftools CPU:
What to Watch For
■ Text-mode can find methods
that are computationally expensive
■ PDF can show you both:
■ Big Boxes (computationally expensive)
■ Call Paths (delegation complexity)
40
Friday, February 3, 12
Slide 41
Slide 41 text
Example: Blog Dashboard
■ https://github.com/jumpstartlab/jsblogger_advanced
■ Setup 1000 sample articles with comments and tags
■ Access the dashboard
■ 5 most recent articles
■ 5 most recent comments
■ Request-time computed statistics about the site
41
Rendered dashboard/show.html.erb within layouts/application (473.9ms)
Completed 200 OK in 2371ms (Views: 436.2ms | ActiveRecord: 926.3ms)
Friday, February 3, 12
/Users/jcasimir/.rvm/rubies/ruby-1.9.2-p290/bin/ruby
Total samples: 217
Focusing on: 217
Dropped nodes with <= 1 abs(samples)
Dropped edges with <= 0 samples
ActionDispatch
BestStandardsSupport#call
0 (0.0%)
of 174 (80.2%)
Bullet
Rack#call
0 (0.0%)
of 174 (80.2%)
174
Rack
PerftoolsProfiler
ProfilerMiddleware#call
0 (0.0%)
of 174 (80.2%)
174
Rack
PerftoolsProfiler
ProfileOnce#act
0 (0.0%)
of 174 (80.2%)
Rack
PerftoolsProfiler
174
174
Friday, February 3, 12
Slide 44
Slide 44 text
ActionDispatch
Head#call
0 (0.0%)
of 174 (80.2%)
ActionController
ImplicitRender#send_action
0 (0.0%)
of 173 (79.7%)
173
DashboardController#show
0 (0.0%)
of 144 (66.4%)
144
Rack
Session
Abstract
ID#call
0 (0.0%)
of 173 (79.7%)
173
ActionDispatch
Flash#call
0 (0.0%)
of 173 (79.7%)
ActionDispatch
ParamsParser#call
0 (0.0%)
of 173 (79.7%)
173
173
50
Rack
Session
Abstract
ID#context
0 (0.0%)
of 173 (79.7%)
173
173
Class#most_popular
0 (0.0%)
of 130 (59.9%)
130
Enumerable#sort_by
0 (0.0%)
of 128 (59.0%)
128
ActiveRecord
Associations
CollectionProxy#count
0 (0.0%)
of 122 (56.2%)
122
Friday, February 3, 12
Slide 45
Slide 45 text
45
Perftools.rb PDF
■ That’s a method I wrote
■ It’s making 128 method calls
■ Those calls consume 59.9%
of the total runtime
Friday, February 3, 12
Slide 46
Slide 46 text
Blog Dashboard Changes
■ Original
46
Rendered dashboard/show.html.erb within layouts/application (473.9ms)
Completed 200 OK in 2371ms (Views: 436.2ms | ActiveRecord: 926.3ms)
Rendered dashboard/show.html.erb within layouts/application (425.8ms)
Completed 200 OK in 696ms (Views: 343.5ms | ActiveRecord: 117.6ms)
70% Performance Improvement
■ Stub out .most_popular and re-run
Friday, February 3, 12
Slide 47
Slide 47 text
More Digging
■ In the Rails Console
■ From the Terminal
47
> PerfTools::CpuProfiler.start("/tmp/article_most_popular") do
> Article.most_popular
> end
$ pprof.rb --text /tmp/article_most_popular
$ pprof.rb --pdf /tmp/article_most_popular > /tmp/most_popular.pdf
$ open most_popular.pdf
Friday, February 3, 12
Slide 48
Slide 48 text
Conclusions 48
Total: 177 samples
110 62.1% 62.1% 110 62.1% SQLite3::Statement#step
24 13.6% 75.7% 24 13.6% NilClass#raise_nil_warning_f
11 6.2% 81.9% 11 6.2% garbage_collector
All the time is
spent in the DB
Friday, February 3, 12
Slide 49
Slide 49 text
Memory Profiling 49
Friday, February 3, 12
Slide 50
Slide 50 text
MemProf by Joe Damato
50
Friday, February 3, 12
Slide 51
Slide 51 text
Perftools.rb for Memory
51
Friday, February 3, 12
Slide 52
Slide 52 text
Perftools.rb for
Memory/Objects 52
■ Use the rack middleware like before
■ Append mode=objects to the URL:
http://localhost:3000/articles/2?
profile=true&printer=text&mode=objects
Friday, February 3, 12
Memory Profiling in 1.9 54
?
Friday, February 3, 12
Slide 55
Slide 55 text
Database Abuse 55
Friday, February 3, 12
Slide 56
Slide 56 text
Bullet helps find N+1 Queries
56
Friday, February 3, 12
Slide 57
Slide 57 text
Setup 57
Gemfile
gem 'bullet'
Initializer
YourAppName::Application.config.after_initialize do
Bullet.enable = true
Bullet.alert = true
Bullet.disable_browser_cache = true
Bullet.rails_logger = true
end
Friday, February 3, 12
Slide 58
Slide 58 text
Warning from Bullet about N+1
58
Friday, February 3, 12
Slide 59
Slide 59 text
In the Log File 59
localhost:3000http://localhost:3000/articles
N+1 Query detected
Tag => [:articles]
Add to your finder: :include => [:articles]
N+1 Query method call stack
/Users/jcasimir/Dropbox/Projects/jsblogger_advanced/app/helpers/
tags_helper.rb:30:in `block in tag_links_with_count'
/Users/jcasimir/Dropbox/Projects/jsblogger_advanced/app/helpers/
tags_helper.rb:29:in `tag_links_with_count'
/Users/jcasimir/Dropbox/Projects/jsblogger_advanced/app/views/articles/
index.html.erb:13:in `block in
_app_views_articles_index_html_erb___186389655085943572_70332291225800'
/Users/jcasimir/Dropbox/Projects/jsblogger_advanced/app/views/articles/
index.html.erb:10:in
`_app_views_articles_index_html_erb___186389655085943572_70332291225800'
Friday, February 3, 12
Slide 60
Slide 60 text
That Helper Method 60
def tag_links_with_count(tags)
tags.collect do |tag|
link_to ("#{tag.name} (#{tag.articles.length})"),
articles_path(:tag => tag.name)
end.join(",").html_safe
end
Friday, February 3, 12
Slide 61
Slide 61 text
Link Helper Changes
■ Original with .length
61
Rendered articles/index.html.erb within layouts/application (409.4ms)
Completed 200 OK in 418ms (Views: 349.9ms | ActiveRecord: 67.5ms)
Rendered articles/index.html.erb within layouts/application (377.0ms)
Completed 200 OK in 387ms (Views: 337.2ms | ActiveRecord: 49.7ms)
10% Performance Improvement
■ Switched to .count
Friday, February 3, 12
Slide 62
Slide 62 text
Slowjam finds Slow Queries
62
Friday, February 3, 12
Logfile Results 64
[1m[35mComment Load (8.0ms)[0m SELECT "comments".* FROM
"comments" ORDER BY created_at DESC LIMIT 5
SLOW QUERY
Comment Load (8.0ms) SELECT "comments".* FROM "comments"
ORDER BY created_at DESC LIMIT 5
app/models/comment.rb:7 |
app/controllers/dashboard_controller.rb:8
Reveals need for an index
Friday, February 3, 12
67
■ Performance matters!
■ Profile the CPU with Perftools.rb
■ Profile Memory with Memprof (1.8.7) or Perftools.rb
■ Watch your Database
■ N+1 Queries with Bullet
■ Slow Queries with Slowjam / Auto-EXPLAIN
■ Links and more resources at:
http://jumpstartlab.com/performance
Jeff Casimir / @j3
Metrics-Driven Rails Performance
Friday, February 3, 12