Ruby

Bug #17152

Updated by cfis (Charlie Savage) over 4 years ago

A user reported an incorrect call graph for profiled code from ruby prof. See https://github.com/ruby-prof/ruby-prof/issues/279. 

 After investigation, this is a bug in Ruby 2.7.1 (it works in Ruby 2.6.*, not sure about Ruby 2.7.0). 

 Take this simple code: 

 ``` 
 str = "AABBCC" 
 profile = RubyProf::Profile.profile do 
   5.times do 
     str.unpack("c*") 
   end 
 end 

 File.open('uuid.html', 'w') do |f| 
   RubyProf::CallStackPrinter.new(profile).print(f) 
 end 

 File.open('graph.html', 'w') do |f| 
   RubyProf::GraphHtmlPrinter.new(profile).print(f) 
 end 
 ``` 

 If you look at fired trace point events (you can do that by setting the environmental variable RUBY_PROF_TRACE=trace.txt before running ruby-prof), you get: 

 ``` 
 60031140:209717.574422 line       #      D:/src/ruby-prof/test/stack_test.rb:10 
 60031140:209717.574646 c-call     Integer#times      D:/src/ruby-prof/test/stack_test.rb:10 
 60031140:209717.574683 line       #      D:/src/ruby-prof/test/stack_test.rb:11 
 60031140:209717.574704 call       String#unpack      <internal:pack>:256 
 60031140:209717.574721 line       String#unpack      <internal:pack>:257 
 60031140:209717.574937 line       #      D:/src/ruby-prof/test/stack_test.rb:11 
 60031140:209717.574959 call       String#unpack      <internal:pack>:256 
 60031140:209717.574976 line       String#unpack      <internal:pack>:257 
 60031140:209717.574991 line       #      D:/src/ruby-prof/test/stack_test.rb:11 
 60031140:209717.575004 call       String#unpack      <internal:pack>:256 
 60031140:209717.575020 line       String#unpack      <internal:pack>:257 
 60031140:209717.575034 line       #      D:/src/ruby-prof/test/stack_test.rb:11 
 60031140:209717.575047 call       String#unpack      <internal:pack>:256 
 60031140:209717.575060 line       String#unpack      <internal:pack>:257 
 60031140:209717.575074 line       #      D:/src/ruby-prof/test/stack_test.rb:11 
 60031140:209717.575086 call       String#unpack      <internal:pack>:256 
 60031140:209717.575106 line       String#unpack      <internal:pack>:257 
 60031140:209717.575121 c-return Integer#times      D:/src/ruby-prof/test/stack_test.rb:10 
 ``` 

 Notice the return tracepoints are not fired. If you use some other method, like string.downcase, they are correctly fired. Perhaps something unique about unpack?

Back