Upgrade to Pro — share decks privately, control downloads, hide ads and more …

DIY::Thread.profile

 DIY::Thread.profile

Whether your application is concurrent or not, there's insight to be gained from Ruby's threading support.

This talk demonstrates building a light-weight sampling profiler in pure Ruby. The techniques are simple enough to integrate into almost any application, and fast enough for even a production environment. If you've ever wondered exactly what your application is doing at any given moment, this will show you how to find out.

Along the way we'll expose gotchas and pitfalls of thread introspection on the many versions and implementations of Ruby. Based on experience implementing thread profiling for New Relic, we'll also touch on how to debug and work around problems when they come up.

Video at http://confreaks.com/videos/2344-mwrc2013-diy-thread-profile-light-weight-profiling-in-pure-ruby

Jason R Clark

April 04, 2013
Tweet

More Decks by Jason R Clark

Other Decks in Programming

Transcript

  1. Where We’re Going • How to Profile • Build Your

    Own Profiler • Show Your Awesome Data • Gotchas Friday, April 5, 13
  2. Where We’re Going • How to Profile • Build Your

    Own Profiler • Show Your Awesome Data • Gotchas Friday, April 5, 13
  3. "Significant effort has been put into reducing ruby-prof’s overhead... Most

    programs will run approximately twice as slow..." https://github.com/rdp/ruby-prof#performance Friday, April 5, 13
  4. Where We’re Going • How to Profile • Build Our

    Own Profiler • Show Your Awesome Data • Gotchas Friday, April 5, 13
  5. Get It Started Thread.new do loop {} # Do more

    maybe? end => #<Thread:0x1036193e8 run> Friday, April 5, 13
  6. Who’s There? Thread.list => [#<Thread:0x10b9c2d70 run>, #<Thread:0x10b9d8198 run>, #<Thread:0x10b9ecc10 run>,

    #<Thread:0x10b9f9d98 run>, #<Thread:0x10ba080c8 run>, #<Thread:0x10b95ddf8 run>] Friday, April 5, 13
  7. Run Profiler, Run! def start Thread.new do while should_run? take_sample

    sleep(@interval) end end end Friday, April 5, 13
  8. Take a Sample def take_sample @sample_count += 1 Thread.list.each do

    |t| next if t.backtrace.nil? t.backtrace.each do |line| count_backtrace_line(line) end end end Friday, April 5, 13
  9. Take a Sample def take_sample @sample_count += 1 Thread.list.each do

    |t| next if t.backtrace.nil? t.backtrace.each do |line| count_backtrace_line(line) end end end Friday, April 5, 13
  10. Take a Sample def take_sample @sample_count += 1 Thread.list.each do

    |t| next if t.backtrace.nil? t.backtrace.each do |line| count_backtrace_line(line) end end end Friday, April 5, 13
  11. Take a Sample def take_sample @sample_count += 1 Thread.list.each do

    |t| next if t.backtrace.nil? t.backtrace.each do |line| count_backtrace_line(line) end end end Friday, April 5, 13
  12. Take a Sample def take_sample @sample_count += 1 Thread.list.each do

    |t| next if t.backtrace.nil? t.backtrace.each do |line| count_backtrace_line(line) end end end Friday, April 5, 13
  13. Making Calls Count def initialize @calls = Hash.new(0) end def

    count_backtrace_line(line) @calls[key(line)] += 1 end Friday, April 5, 13
  14. Making Calls Count def initialize @calls = Hash.new(0) end def

    count_backtrace_line(line) @calls[key(line)] += 1 end Friday, April 5, 13
  15. Where We’re Going • How to Profile • Build Your

    Own Profiler • Show Your Awesome Data • Gotchas Friday, April 5, 13
  16. Sample App class TromplesController < ... # Heavy action def

    tromp fib(30) n_plus_one_much? # Record our tromp ... end Friday, April 5, 13
  17. Sample App # Totally webscale fibonnaci def fib(n) return n

    if (0..1).include? n fib(n-1) + fib(n-2) if n > 1 end Friday, April 5, 13
  18. app.rb 1 call @count=1 Call Tree [ "model.rb:300:in `find'", "controller.rb:20:in

    `index'", "app.rb:1:in `call'" ] Friday, April 5, 13
  19. app.rb 1 call @count=1 Call Tree [ "model.rb:300:in `find'", "controller.rb:20:in

    `index'", "app.rb:1:in `call'" ] controller.rb 20 index @count=1 Friday, April 5, 13
  20. app.rb 1 call @count=1 Call Tree [ "model.rb:300:in `find'", "controller.rb:20:in

    `index'", "app.rb:1:in `call'" ] controller.rb 20 index @count=1 model.rb 300 find @count=1 Friday, April 5, 13
  21. app.rb 1 call @count=2 Call Tree controller.rb 20 index @count=1

    model.rb 300 find @count=1 [ "model.rb:300:in `find'", "controller.rb:42:in `show'", "app.rb:1:in `call'" ] Friday, April 5, 13
  22. app.rb 1 call @count=2 Call Tree controller.rb 20 index @count=1

    model.rb 300 find @count=1 [ "model.rb:300:in `find'", "controller.rb:42:in `show'", "app.rb:1:in `call'" ] Friday, April 5, 13
  23. app.rb 1 call @count=2 Call Tree controller.rb 20 index @count=1

    model.rb 300 find @count=1 controller.rb 42 show @count=1 [ "model.rb:300:in `find'", "controller.rb:42:in `show'", "app.rb:1:in `call'" ] Friday, April 5, 13
  24. model.rb 300 find @count=1 app.rb 1 call @count=2 Call Tree

    controller.rb 20 index @count=1 model.rb 300 find @count=1 controller.rb 42 show @count=1 [ "model.rb:300:in `find'", "controller.rb:42:in `show'", "app.rb:1:in `call'" ] Friday, April 5, 13
  25. Where We’re Going • How to Profile • Build Our

    Own Profiler • Show Your Awesome Data • Gotchas! Friday, April 5, 13
  26. MOAR! https://github.com/jasonrclark/diy_profile class Profiler attr_reader :sample_count, :calls def initialize(interval =

    0.1) @interval = interval @running = false @sample_count = 0 @calls = Hash.new(0) end def count_backtrace_line(line) @calls[key(line)] += 1 end def should_run? @running end def stop @running = false end def start return if @running @running = true Thread.new do while should_run? take_sample sleep(@interval) end end end def take_sample @sample_count += 1 Thread.list.each do |thread| next if thread.backtrace.nil? thread.backtrace.each do |line| count_backtrace_line(line) end end end def count_backtrace_line(line) @calls[key(line)] += 1 end BACKTRACE_LINE_REGEX = /(.*)\:(\d+)\:in `(.*)'/ def key(line) BACKTRACE_LINE_REGEX.match(line).captures end end @jasonrclark Friday, April 5, 13