Vernier: A next generation CRuby profiler - RubyKaigi 2024

Transcript

1. Vernier A next-generation Ruby pro fi ler
2. John Hawthorn Sta ff Engineer @ GitHub Ruby Committer Rails Core @jhawthorn @john@hawthorn.pub john.hawthorn.website
4. bundle update $ vernier run -- Fetching gem metadata from https://rubygems.org/... Resolving dependencies... Bundle updated! #<Vernier::Result 0.6187 seconds, 1086 samples> written to ./bundle_update.vernier.json.gz
8. Firefox CRuby • C++ • Javascript • JIT compilers • multithreaded • C • Ruby • JIT compiler • multithreaded
18. 890 000 allocations
19. name, _, checksum = line.split(" ", 3) checksums[name] = checksum
20. name, _, checksum = line.split(" ", 3) checksums[name] = checksum
21. name = line[0, line.index(" ")] checksum = line[line.rindex(" "), line.size] name, _, checksum = line.split(" ", 3) checksums[name] = checksum # name, _, checksum = line.split(" ", 3)
22. $ time bundle update 0.618s $ time bundle update 0.497s Before After ~100ms faster!
23. Original idea: Retained memory pro fi ler
24. ObjectSpace.trace_object_allocations_start require "./config/environment" # Your program ObjectSpace.dump_all(...) {"address":"0x109598a30", "type":"OBJECT", "file":"msgpack-1.7.2/lib/msgpack.rb", "line":32, "method":"full_unpack",
25. {"address":"0x109598a30", "type":"OBJECT", "file":"msgpack-1.7.2/lib/msgpack.rb", "line":32, "method":"full_unpack", ????
26. $stack_table = Vernier::StackTable.new def bar = $stack_table.current_stack def foo = bar p foo() #=> 2 p 3.times.map { foo() } #=> [5, 5, 5] puts $stack_table.backtrace(2) # test.rb:3:in 'Object#bar' # test.rb:4:in 'Object#foo' # test.rb:5:in '<main>'
27. $stack_table = Vernier::StackTable.new def bar = $stack_table.current_stack def foo = bar p foo() #=> 2 p 3.times.map { foo() } #=> [5, 5, 5] Never allocates Ruby objects
28. Frames Stacks Integer#times <main> Object#bar Object#foo Object#bar Object#foo Integer#times <main> Object#bar Object#foo
29. Frames Stacks 3 0 2 1 5 4 Integer#times <main> Object#bar Object#foo
33. Vernier: Time pro fi ling
34. Tracing pro fi ler times = [] TracePoint.new(:call) do |tp| times << Time.now end TracePoint.new(:return) do |tp| puts "#{tp.method} took #{times.pop - Time.now}" end
35. $ time ruby fib.rb 0.107s $ time ruby -rprofile fib.rb 52.105s $ time ruby-prof fib.rb 2.888s 28x slower 500x slower
36. Ruby Native code Idle
37. Ruby Native code Idle with 30x overhead
38. Tracing: User timings
39. GC instrumentation
40. Thread.new do loop do sleep 0.001 end end Sampling pro fi ler $samples = [] [ ["test.rb:2:in `foo'", "test.rb:8:in `<main>'"], ["test.rb:5:in `bar'", "test.rb:9:in `<main>'"], ... $samples << Thread.main.backtrace
41. sleep(1)
42. running program (idle) sleep(1)
43. running program (idle) sleep(1) pure-Ruby pro fi ler thread
44. record sample record sample running program (idle) sleep(0.001) sleep(0 sleep(0.001) sleep(1) pure-Ruby pro fi ler thread
45. running program (idle) sleep(0.001) sleep(0 sleep(0.001) start = Time.now while Time.now < start + 1 # loop for 1s end record sample record sample pure-Ruby pro fi ler thread
46. stalled sleep(0.001) running program (Ruby GVL) GVL contention start = Time.now while Time.now < start + 1 # loop for 1s end
47. Ruby 3.2+
48. rb_internal_thread_add_event_hook( internal_thread_event_cb, event_mask, userdata); RUBY_INTERNAL_THREAD_EVENT_STARTED RUBY_INTERNAL_THREAD_EVENT_READY RUBY_INTERNAL_THREAD_EVENT_RESUMED RUBY_INTERNAL_THREAD_EVENT_SUSPENDED RUBY_INTERNAL_THREAD_EVENT_EXITED
51. #define native_thread_yield() ((void)0) #endif /* 100ms. 10ms is too small for user level * thread scheduling on recent Linux * (tested on 2.6.35) */ #define TIME_QUANTUM_MSEC (100) #define TIME_QUANTUM_USEC (TIME_QUANTUM_MSEC * 100 #define TIME_QUANTUM_NSEC (TIME_QUANTUM_USEC * 100 static void native_thread_dedicated_inc(rb_vm_t *v struct rb_native_thread *nt);
52. Thread GVL states • Running - Holding the GVL. Executing Ruby code • Stalled - Blocked acquiring the GVL • Suspended - GVL released (I/O, sleep, network, etc.) Records backtrace!
56. rb_pro fi le_frames save sample UNIX Signal queue job "safepoint" running program (Ruby GVL) Stackprof (< 0.2.18) RUBY_VM_CHECK_INTS
57. def empty_method end def slow_method x = "h" + "e" + "l" + "l" + "o" + "," x += "w" + "o" + "r" + "l" + "d" empty_method end 1000.times do slow_method end
58. def empty_method end def slow_method x = "h" + "e" + "l" + "l" + "o" + "," x += "w" + "o" + "r" + "l" + "d" empty_method end 1000.times do slow_method end
59. TOTAL (pct) SAMPLES (pct) FRAME 56 (100.0%) 56 (100.0%) empty_method 56 (100.0%) 0 (0.0%) slow_method 56 (100.0%) 0 (0.0%) Integer#times 56 (100.0%) 0 (0.0%) <main> def empty_method end def slow_method x = "h" + "e" + "l" + "l" + "o" + "," x += "w" + "o" + "r" + "l" + "d" empty_method end 1000.times do slow_method end 100%
60. rb_pro fi le_frames save sample UNIX Signal queue job running program (Ruby GVL) Stackprof (>= 0.2.18) "safepoint" RUBY_VM_CHECK_INTS
61. rb_pro fi le_frames save sample UNIX Signal queue job running program (Ruby GVL) Stackprof (>= 0.2.18) "safepoint" RUBY_VM_CHECK_INTS
62. async-signal-safe? Is rb_profile_frames Of fi cially? No. In the VM? Since Ruby 3.0.0 On YJIT? Since Ruby 3.2.1
63. $ time \ ruby --yjit test.rb 2.149 total $ stackprof run -- \ ruby --yjit test.rb 7.902 total $ time vernier run -- \ ruby --yjit test.rb 2.351 total def test(n) while n > 0 n -= 1 end end test(100_000_000)
64. rb_pro fi le_frames save sample UNIX Signal queue job running program (Ruby GVL) Stackprof (>= 0.2.18) "safepoint" RUBY_VM_CHECK_INTS
65. rb_pro fi le_frames UNIX Signal queue job Stackprof (>= 0.2.18) running program (C GVL) GVLTest.sleep_holding_gvl(1)
66. rb_pro fi le_frames UNIX Signal queue job running program (C GVL) rb_pro fi le_frames UNIX Signal queue job "Missed sample" GVLTest.sleep_holding_gvl(1)
67. Vernier rb_pro fi le_frames save sample Vernier thread running program (C GVL) 📏 Less overhead! More accurate! GVLTest.sleep_holding_gvl(1)
68. main thread puma worker thread Stackprof + threads
69. main thread puma worker thread Stackprof + threads
70. Vernier thread 📏 puma worker thread puma worker thread Vernier + threads
71. Vernier thread 📏 puma worker thread puma worker thread (idle) Vernier + threads
72. Vernier thread 📏 puma worker thread puma worker thread (idle) Ractor thread
73. puma worker thread puma worker thread (idle) Ractor thread Vernier thread 📏
74. $ bundle exec \ vernier run \ --hooks=rails \ --output /tmp/puma.profile.json \ --signal CONT --start-paused -- \ bin/rails s -p 3000 $ pkill -CONT -f puma Toggle pro fi ling
77. • Option 1: Use separate processes • Option 2: Make "running" section faster • Option 3: Short lived Ractor
79. Use Ractor or make faster
80. Vernier • GVL aware pro fi ling • Pro fi les all Ractors and Threads (M:N supported) • Low overhead, no postponed jobs • GC tracing, GVL tracing, user tracing, allocation tracing • Retained memory tracing (bonus feature)
81. Thank you! ͋Γ͕ͱ͏͍͟͝·͢
82. Vernier https://vernier.prof