Project

General

Profile

Actions

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]
[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 #1

Updated by cfis (Charlie Savage) about 4 years ago

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

Updated by cfis (Charlie Savage) about 4 years ago

  • Description updated (diff)
Actions #3

Updated by cfis (Charlie Savage) about 4 years ago

  • Description updated (diff)
Actions #4

Updated by cfis (Charlie Savage) about 4 years ago

Actions #5

Updated by cfis (Charlie Savage) about 4 years ago

  • File deleted (uuid.html)
Actions #6

Updated by cfis (Charlie Savage) about 4 years ago

  • File deleted (graph.html)
Actions #7

Updated by cfis (Charlie Savage) about 4 years ago

  • Description updated (diff)
Actions #8

Updated by S_H_ (Shun Hiraoka) about 4 years ago

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?

Actions #10

Updated by jeremyevans0 (Jeremy Evans) about 4 years ago

  • Status changed from Open to Closed

Updated by cfis (Charlie Savage) about 4 years ago

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

Actions

Also available in: Atom PDF

Like0
Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0