The Future of Ruby Performance Tooling

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.

F04bfa14141dca6713f0d9caa763e26b?s=128

Aaron Quint

June 21, 2014
Tweet

Transcript

  1. THE future of ruby performance tooling @aq / GoRuCo 2014

  2. Thanks for coming. Good Morning!

  3. None
  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

  12. None
  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
  22. None
  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
  26. None
  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)’

  31. None
  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
  37. None
  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
  42. None
  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

  50. None
  51. ObSViewer +2 Rd • Total WIP • The data is

    there, we just need better tools to gain analysis
  52. None
  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