The Future of Ruby Performance Tooling

A presentation I gave at Gotham Ruby Conf 2014 (http://goruco.com) about Ruby Performance Tooling and what we've been doing at Paperless Post. There were a couple videos in the slides so unfortunately those are not included here. Video should be up soon though.

Transcript

1. THE future of ruby performance tooling @aq / GoRuCo 2014
2. Thanks for coming. Good Morning!
4. Well, lets start with the philosophy at least. today’s agenda: More Practical, Less Philosophical
5. User Experience, but also $$$ Performance matters.
6. + PERFORMANCE
7. Connecting Ruby Server HTML DL CSS DL JS DL Images JS onLoad() Done 0-10ms 10-30,000ms 30ms 150ms 100-50,000ms
8. Connecting Ruby Server HTML DL CSS DL JS DL Images Sorted by how much control we have to improve
9. Ruby Server Ruby/Stdlib Rails DB/Cache YOUR APPLICATION
10. So where do we start?
11. The Past of RUBY-CORE: Developers > Operators
13. THE FUTURE OF RUBY-CORE: INTROSPECTABILITY
14. Heres to the future cuz we got through the past
15. Multitudinous The future of ruby performance tooling
16. There is no BEST tool, either. Reminder: THERE IS NO ONE TOOL
17. Ruby PerformancE Character Profiles
18. • Specificity (Sp) • Impact (Im) • Difficulty of Operator Use (Op) • Readability (Rd) • Realtimedness (Rl) • Special Abilities (SA)
19. The Elves AS::Notifications + Friends
20. ActiveSupport::Notifications.publish("log_action.request_subscriber", data)
21. class StatsdSubscriber < ActiveSupport::LogSubscriber attr_reader :event ! def log_action(event) payload = event.payload[:controller_data] prefix = “controller.#{payload[:method]}.#{payload[:controller].to_s.gsub(‘::’,'_')}." %w{view db total}.each do |metric| value = payload["#{metric}_runtime".to_sym] Paperless::Statsd.timing("#{prefix}.#{metric}", value) if value Paperless::Statsd.timing("controller.#{metric}", value) if value end end ! end
23. AS:Notify Sp: 5-10 Im: 5-10 Op: 7 Rd: 2-10 Rl: 9 • Special Abilities: Graphs! • Good for: p90s, what _layers_ are slow? Trending data. • Not Good for: Giving you details about anything. Easy to misinterpret data.
24. The Warrior RblineproF
25. require 'rblineprof' def lineprof_block(options = {}, &block) profile = lineprof(/app/) do ret = yield end profile_text(profile, options) end
27. RblineproF Sp: 9 Im: 9 Op: 8 Rd: 7 Rl: 3 • Special Abilities: Amazing visibility into dev hotspots • Good for: Diving deep into slow actions. • Not Good for: Discovery or fixing of systematic issues. Real world numbers.
28. You have obtained a special weapon
29. Sword of Repeatability PPprofiler
30. $ ./script/ppprofiler ‘Event.last.as_json(:expand => true)’
32. PPprofiler +2 Op +2 Rd • Special Abilities: Tracks local improvements. • Good for: Golf. Sharing improvements with team. • Not Good for: Production. This is about local.
33. The Mage StackProF
34. Ruby Process (Unicorn) AC::Dispatch MyController::Create Template::Render Ar::Find
35. Ruby Process (Unicorn) StackProf.start rb_profile_frames() rb_profile_frames() rb_profile_frames() rb_profile_frames() StackProf.stop StackProf.dump
36. $ stackprof ~/Downloads/stackprof-cpu-1402024056.dump ================================== Mode: cpu(1000) Samples: 562 (0.35% miss rate) GC: 71 (12.63%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 33 (5.9%) 33 (5.9%) ActiveRecord::Base.scoped_methods 30 (5.3%) 30 (5.3%) ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#… 26 (4.6%) 26 (4.6%) ActiveSupport::CoreExtensions::Hash::Keys#assert_valid_keys 24 (4.3%) 24 (4.3%) block in ActiveRecord::ConnectionAdapters::..#execute 14 (2.5%) 14 (2.5%) block in ActiveSupport::Inflector#singularize 13 (2.3%) 12 (2.1%) block in ActiveSupport::Notifications::Fanout#listeners_for 12 (2.1%) 12 (2.1%) ActiveRecord::Reflection::AssociationReflection#klass 19 (3.4%) 12 (2.1%) ActiveRecord::ConnectionAdapters::ConnectionHandler#… 11 (2.0%) 11 (2.0%) block in ActiveRecord::Base.with_scope 797 (141.8%) 11 (2.0%) ActiveRecord::Base.with_scope 18 (3.2%) 8 (1.4%) ActiveRecord::Base.quote_bound_value 7 (1.2%) 7 (1.2%) Haml::Helpers#preserve 79 (14.1%) 7 (1.2%) block in ActiveRecord::Base.with_scope 6 (1.1%) 6 (1.1%) block (2 levels) in ActiveRecord::Base.connection_handler= 72 (12.8%) 6 (1.1%) block (2 levels) in ActiveRecord::Base.with_scope
38. StackProF Sp: 4 Im: 2 Op: 3 Rd: 4-6 Rl: 9 • Special Abilities: FLAMEGRAPHS • Good for: Finding systemic issues in production. • Not Good for: Detailed info about whats slow in YOUR code.
39. You have obtained a special weapon
40. Axe of Usability StackProF-RemotE
41. require 'stackprof/remote/middleware' ! enabled = proc do |env| magic_method || Rails.env.development? end ActionController::Dispatcher.middleware.use StackProf::Remote::Middleware, enabled: enabled, logger: Rails.logger
43. SP::Remote +4 Op +2 Rd +1 Rl • Special Abilities: Interactive StackProf • Good for: Easily introspecting a production server. • Not Good for: Development.
44. The Giant ObjecTSpacE
45. $ ./bin/rbtrace -p 8963 -e 'GC.start(full_mark: true); require “objspace”;\ ObjectSpace.dump_all(output: File.open(“heap.json","w"))' ! $ ls -lh heap.json -rw-r--r-- 1 aaronquint staff 87M Jun 16 21:52 heap.json
46. {"address":"0xf583b8", "type":"STRING", "class":"0xf11620", "frozen":true, "embedded":true, "bytesize":13, "value":"output_format", "encoding":"UTF-8", "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf583e0", "type":"OBJECT", "class":"0x2471268", "frozen":true, "ivars":3, "references":["0xf58480"], "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf58458", "type":"STRING", "class":"0xf11620", "frozen":true, "embedded":true, "bytesize":10, "value":"transforms", "encoding":"UTF-8", "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf58480", "type":"STRING", "class":"0xf11620", "embedded":true, "bytesize":1, "value":"/", "encoding":"UTF-8", "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf584d0", "type":"STRING", "class":"0xf11620", "frozen":true, "embedded":true, "bytesize":6, "value":"output", "encoding":"UTF-8", "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf58570", "type":"STRING", "class":"0xf11620", "frozen":true, "embedded":true, "bytesize":11, "value":"progressive", "encoding":"UTF-8", "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf58598", "type":"OBJECT", "class":"0x2470b10", "frozen":true, "ivars":3, "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf58610", "type":"OBJECT", "class":"0x24714e8", "frozen":true, "ivars":3, "references":["0xf58638"], "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf58638", "type":"STRING", "class":"0xf11620", "embedded":true, "bytesize":3, "value":"api", "encoding":"UTF-8", "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf58700", "type":"OBJECT", "class":"0x24714e8", "frozen":true, "ivars":3, "references":["0xf58750"], "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf58728", "type":"STRING", "class":"0xf11620", "frozen":true, "embedded":true, "fstring":true, "bytesize" 8, "value":"ASTERISK", "encoding":"US-ASCII", "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf58750", "type":"STRING", "class":"0xf11620", "shared":true, "encoding":"UTF-8", "references": ["0xf5f1b8"], "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf587a0", "type":"STRING", "class":"0xf11620", "frozen":true, "bytesize":24, "capacity":48, "value":"ActionController::CgiExt", "encoding":"US-ASCII", "memsize":49, "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf587c8", "type":"STRING", "class":"0xf11620", "frozen":true, "embedded":true, "bytesize":5, "value":"strip", "encoding":"UTF-8", "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf587f0", "type":"STRING", "class":"0xf11620", "frozen":true, "embedded":true, "fstring":true, "bytesize" 9, "value":"SEV_LABEL", "encoding":"US-ASCII", "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf58840", "type":"OBJECT", "class":"0x2471268", "frozen":true, "ivars":3, "references":["0xf588e0"], "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf588b8", "type":"STRING", "class":"0xf11620", "frozen":true, "embedded":true, "fstring":true, "bytesize" 6, "value":"DOLLAR", "encoding":"US-ASCII", "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf588e0", "type":"STRING", "class":"0xf11620", "embedded":true, "bytesize":1, "value":"/", "encoding":"UTF-8", "flags":{"wb_protected":true, "old":true, "marked":true}} {"address":"0xf58930", "type":"STRING", "class":"0xf11620", "frozen":true, "embedded":true, "bytesize":12, "value":"version_name", "encoding":"UTF-8", "flags"
47. ObjecTSpacE Sp: 10 Im: 10 Op: 3 Rd:3 Rl: 2 • Special Abilities: Every. Object. • Good for: Potential for diagnosing memory issues. • Not Good for: Hard to fetch from running systems.
48. A WIP Palantir ObjspacEViewer
49. $ ./scripts/import heap.json Time: 00:12:22 |==============================================>> | 93% Progress
51. ObSViewer +2 Rd • Total WIP • The data is there, we just need better tools to gain analysis
53. — The Strategy Use low impact tools to collect data from production and high impact tools to measure the relative improvements of iterative changes in development and staging.
54. THANKS! ! twitter: @aq code: github.com/quirkey ! rblineprof: github.com/tmm1/rblineprof stackprof: github.com/tmm1/stackprof ppprofiler: dev.paperlesspost.com stackprof-remote: github.com/quirkey/stackprof-remote objspace_viewer: github.com/quirkey/objspace_viewer