Bug #17152: Missing TracePoint return event for String#unpack

• 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

[cfis (Charlie Savage)]

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?

[cfis (Charlie Savage)]

• Description updated (diff)
• ruby -v set to ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x64-mingw32]

[cfis (Charlie Savage)]

• Description updated (diff)

[cfis (Charlie Savage)]

• Description updated (diff)

[cfis (Charlie Savage)]

• File graph.html added
• File trace.txt trace.txt added
• File uuid.html added

[cfis (Charlie Savage)]

• File deleted (uuid.html)

[cfis (Charlie Savage)]

• File deleted (graph.html)

[cfis (Charlie Savage)]

• Description updated (diff)

[S_H_ (Shun Hiraoka)]

Hi, cfis (Charlie Savage) .

you expected return like this?

47435362097880:112480.769196 line     #    bug.rb: 5
47435362097880:112480.769280 c-call   Integer#times    bug.rb: 5
47435362097880:112480.769290 line     #    bug.rb: 6
47435362097880:112480.769296 call     String#unpack    <internal:pack>:256
47435362097880:112480.769301 line     String#unpack    <internal:pack>:257
47435362097880:112480.769306 return   String#unpack    <internal:pack>:258
47435362097880:112480.769313 line     #    bug.rb: 6
47435362097880:112480.769316 call     String#unpack    <internal:pack>:256
47435362097880:112480.769319 line     String#unpack    <internal:pack>:257
47435362097880:112480.769322 return   String#unpack    <internal:pack>:258
47435362097880:112480.769325 line     #    bug.rb: 6
47435362097880:112480.769328 call     String#unpack    <internal:pack>:256
47435362097880:112480.769331 line     String#unpack    <internal:pack>:257
47435362097880:112480.769334 return   String#unpack    <internal:pack>:258
47435362097880:112480.769337 line     #    bug.rb: 6
47435362097880:112480.769340 call     String#unpack    <internal:pack>:256
47435362097880:112480.769342 line     String#unpack    <internal:pack>:257
47435362097880:112480.769346 return   String#unpack    <internal:pack>:258
47435362097880:112480.769348 line     #    bug.rb: 6
47435362097880:112480.769351 call     String#unpack    <internal:pack>:256
47435362097880:112480.769354 line     String#unpack    <internal:pack>:257
47435362097880:112480.769357 return   String#unpack    <internal:pack>:258
47435362097880:112480.769360 c-return Integer#times    bug.rb: 5

Some method is implimented by Ruby code since Ruby 2.7.
It behavior semms to be caused builtin code(that is implemented by Ruby code).

But, this behavior was fixed in master:ruby 3.0.0dev (2020-09-03T21:41:58Z master d4585e7470) [x86_64-linux] with this commit.
https://github.com/ruby/ruby/commit/3e02cd518fbe4d91c2aca7fbc3c5aafa387d3cb7

Anyone backport this commit? Shall I try it?

[S_H_ (Shun Hiraoka)]

This behavior is fixed(alredy backported).

ref: https://bugs.ruby-lang.org/issues/17149
ref: https://github.com/ruby/ruby/commit/3fef159f81fad6ffb9af5b60f4c8ec867fdb2391

[jeremyevans0 (Jeremy Evans)]

• Status changed from Open to Closed

[cfis (Charlie Savage)]

Yes Shun, I expect the return calls.
Thanks for the help!