Project

General

Profile

Actions
Copy link

Bug #17152

closed

Missing TracePoint return event for String#unpack

Added by cfis (Charlie Savage) about 4 years ago. Updated about 4 years ago.

Status:
Closed
Assignee:
-
Target version:
-
ruby -v:
ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x64-mingw32]
Backport:
2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN
[ruby-core:99927]

Description

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

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?

Files

trace.txt (1.31 KB) trace.txt cfis (Charlie Savage), 09/04/2020 07:28 PM
Actions
Copy link

Also available in: Atom PDF

Like0
Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0