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

Transcript

1. Jason Clark @jasonrclark Ruby Agent Engineer DIY::Thread.profile Light-Weight Profiling in Pure Ruby Friday, April 5, 13
2. THREADS! Friday, April 5, 13
3. Where We’re Going • How to Profile • Build Your Own Profiler • Show Your Awesome Data • Gotchas Friday, April 5, 13
4. Where We’re Going • How to Profile • Build Your Own Profiler • Show Your Awesome Data • Gotchas Friday, April 5, 13
5. Instrumenting Friday, April 5, 13
6. Friday, April 5, 13
7. "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
8. Friday, April 5, 13
9. Sometimes, Maybe? SQL Model Controller Routing Middleware Server Friday, April 5, 13
10. Application Code Friday, April 5, 13
11. Samples Anyone? Friday, April 5, 13
12. Our Stack SQL Model Controller Routing Middleware Server Friday, April 5, 13
13. Sampling Time Friday, April 5, 13
14. Sampling Time Friday, April 5, 13
15. Sampling Time Friday, April 5, 13
16. Sampling Time Friday, April 5, 13
17. Where We’re Going • How to Profile • Build Our Own Profiler • Show Your Awesome Data • Gotchas Friday, April 5, 13
18. ::Thread Friday, April 5, 13
19. Get It Started Thread.new do loop {} # Do more maybe? end => #<Thread:0x1036193e8 run> Friday, April 5, 13
20. 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
21. =>[ "model.rb:300:in `find'", "controller.rb:20:in `index'", "app.rb:1:in `call'" ] Backtracin’ Thread.current.backtrace Friday, April 5, 13
22. Friday, April 5, 13
23. Let’s Build It! Friday, April 5, 13
24. Run Profiler, Run! def start Thread.new do while should_run? take_sample sleep(@interval) end end end Friday, April 5, 13
25. def start Thread.new do while should_run? take_sample sleep(@interval) end end end Run Profiler, Run! Friday, April 5, 13
26. def start Thread.new do while should_run? take_sample sleep(@interval) end end end Run Profiler, Run! Friday, April 5, 13
27. def start Thread.new do while should_run? take_sample sleep(@interval) end end end Run Profiler, Run! Friday, April 5, 13
28. 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
29. 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
30. 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
31. 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
32. Take a Sample [ "model.rb:300:in `find'", "controller.rb:20:in `index'", "app.rb:1:in `call'" ] Friday, April 5, 13
33. 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
34. Making Calls Count def initialize @calls = Hash.new(0) end def count_backtrace_line(line) @calls[key(line)] += 1 end Friday, April 5, 13
35. Making Calls Count def initialize @calls = Hash.new(0) end def count_backtrace_line(line) @calls[key(line)] += 1 end Friday, April 5, 13
36. Breaking in Line BACKTRACE_LINE_REGEX = /(.*)\:(\d+)\:in `(.*)'/ def key(line) BACKTRACE_LINE_REGEX. match(line). captures end Friday, April 5, 13
37. Breaking in Line "app.rb:5:in `call'" => [ "app.rb", "5", "call" ] Friday, April 5, 13
38. @calls => { ["app.rb","5","call"] => 1, ... } Breaking in Line Key Count Friday, April 5, 13
39. Where We’re Going • How to Profile • Build Your Own Profiler • Show Your Awesome Data • Gotchas Friday, April 5, 13
40. Friday, April 5, 13
41. Sample App class TromplesController < ... # Heavy action def tromp fib(30) n_plus_one_much? # Record our tromp ... end Friday, April 5, 13
42. 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
43. Sample App def n_plus_one_much? Trompler.all.each do |t| Trompler.find(t.id) end end Friday, April 5, 13
44. Friday, April 5, 13
45. Friday, April 5, 13
46. Friday, April 5, 13
47. Friday, April 5, 13
48. Friday, April 5, 13
49. Friday, April 5, 13
50. Friday, April 5, 13
51. Friday, April 5, 13
52. Another View Friday, April 5, 13
53. Call Trees Friday, April 5, 13
54. Call Tree [ "model.rb:300:in `find'", "controller.rb:20:in `index'", "app.rb:1:in `call'" ] Friday, April 5, 13
55. 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
56. 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
57. 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
58. Another! [ "model.rb:300:in `find'", "controller.rb:42:in `show'", "app.rb:1:in `call'" ] Friday, April 5, 13
59. 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
60. 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
61. 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
62. 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
63. Call Trees Friday, April 5, 13
64. Where We’re Going • How to Profile • Build Our Own Profiler • Show Your Awesome Data • Gotchas! Friday, April 5, 13
65. How Often? • Traffic • Task Size Friday, April 5, 13
66. Overhead? • Average 1.7 milliseconds • Memory for calls hash/tree Friday, April 5, 13
67. Thread#backtrace only on >= 1.9.x Friday, April 5, 13
68. 1.9.1 flakiness Friday, April 5, 13
69. JRuby Oddities http://jira.codehaus.org/browse/JRUBY-7054 http://jira.codehaus.org/browse/JRUBY-7056 Friday, April 5, 13
70. 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