From: cfis@...
Date: 2020-09-04T19:25:07+00:00
Subject: [ruby-core:99927] [Ruby master Bug#17152] Missing TracePoint return event for String#unpack

Issue #17152 has been reported by cfis (Charlie Savage).

----------------------------------------
Bug #17152: Missing TracePoint return event for String#unpack
https://bugs.ruby-lang.org/issues/17152

* Author: cfis (Charlie Savage)
* Status: Open
* Priority: Normal
* Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN
----------------------------------------
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?



-- 
https://bugs.ruby-lang.org/

Unsubscribe: <mailto:ruby-core-request@ruby-lang.org?subject=unsubscribe>
<http://lists.ruby-lang.org/cgi-bin/mailman/options/ruby-core>