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
   

   View Slide

2. Thanks for coming.
   Good Morning!
   

   View Slide

3. View Slide

4. Well, lets start with the philosophy at least.
   today’s agenda:
   More Practical,
   Less Philosophical
   

   View Slide

5. User Experience, but also $$$
   Performance
   matters.
   

   View Slide

6. + PERFORMANCE
   

   View Slide

7. Connecting
   Ruby Server
   HTML DL
   CSS DL
   JS DL
   Images
   JS onLoad() Done
   0-10ms
   10-30,000ms
   30ms
   150ms
   100-50,000ms
   

   View Slide

8. Connecting
   Ruby Server
   HTML DL
   CSS DL
   JS DL
   Images
   Sorted by how much
   control we have
   to improve
   

   View Slide

9. Ruby Server
   Ruby/Stdlib
   Rails
   DB/Cache
   YOUR APPLICATION
   

   View Slide

10. So where do we start?
    

    View Slide

11. The Past of RUBY-CORE:
    Developers > Operators
    

    View Slide

12. View Slide

13. THE FUTURE OF RUBY-CORE:
    INTROSPECTABILITY
    

    View Slide

14. Heres to the future cuz we got through the past
    

    View Slide

15. Multitudinous
    The future of ruby
    performance tooling
    

    View Slide

16. There is no BEST tool, either.
    Reminder:
    THERE IS NO ONE TOOL
    

    View Slide

17. Ruby
    PerformancE
    Character
    Profiles
    

    View Slide

18. • Specificity (Sp)
    • Impact (Im)
    • Difficulty of Operator Use (Op)
    • Readability (Rd)
    • Realtimedness (Rl)
    • Special Abilities (SA)
    

    View Slide

19. The Elves
    AS::Notifications + Friends
    

    View Slide

20. ActiveSupport::Notifications.publish("log_action.request_subscriber", data)
    

    View Slide

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
    

    View Slide

22. View Slide

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.
    

    View Slide

24. The Warrior
    RblineproF
    

    View Slide

25. require 'rblineprof'
    def lineprof_block(options = {}, &block)
    profile = lineprof(/app/) do
    ret = yield
    end
    profile_text(profile, options)
    end
    

    View Slide

26. View Slide

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.
    

    View Slide

28. You have obtained a
    special weapon
    

    View Slide

29. Sword of Repeatability
    PPprofiler
    

    View Slide

30. $ ./script/ppprofiler ‘Event.last.as_json(:expand => true)’
    

    View Slide

31. View Slide

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.
    

    View Slide

33. The Mage
    StackProF
    

    View Slide

34. Ruby Process (Unicorn)
    AC::Dispatch
    MyController::Create
    Template::Render
    Ar::Find
    

    View Slide

35. Ruby Process (Unicorn)
    StackProf.start rb_profile_frames() rb_profile_frames() rb_profile_frames() rb_profile_frames()
    StackProf.stop
    StackProf.dump
    

    View Slide

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
    

    View Slide

37. View Slide

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.
    

    View Slide

39. You have obtained a
    special weapon
    

    View Slide

40. Axe of Usability
    StackProF-RemotE
    

    View Slide

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
    

    View Slide

42. View Slide

43. SP::Remote
    +4 Op
    +2 Rd
    +1 Rl
    • Special Abilities:
    Interactive StackProf
    • Good for: Easily
    introspecting a
    production server.
    • Not Good for:
    Development.
    

    View Slide

44. The Giant
    ObjecTSpacE
    

    View Slide

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
    

    View Slide

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"
    

    View Slide

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.
    

    View Slide

48. A WIP Palantir
    ObjspacEViewer
    

    View Slide

49. $ ./scripts/import heap.json
    Time: 00:12:22 |==============================================>> | 93% Progress
    

    View Slide

50. View Slide

51. ObSViewer
    +2 Rd
    • Total WIP
    • The data is there, we
    just need better tools
    to gain analysis
    

    View Slide

52. View Slide

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.
    

    View Slide

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
    

    View Slide