Bug #18907: rb_profile_frames output includes dummy main Thread frame

• Status: Closed
• Assignee: -
• Target version: -
• ruby -v: ruby 3.2.0dev (2022-07-11T06:58:19Z master fae568edbe) [x86_64-darwin20]
• Backport: 2.7: UNKNOWN, 3.0: UNKNOWN, 3.1: UNKNOWN

[ivoanjo (Ivo Anjo)]

Howdy! I'm working at Datadog on the ddtrace gem, and we're starting to make use of the rb_profile_frames API for our continuous profiler.

While comparing the output of rb_profile_frames for Thread.main with the regular Thread.main.backtrace_locations I noticed we get one more frame at the base of the stack.

This is the dummy frame that gets skipped on backtrace_each (https://github.com/ruby/ruby/blob/2733c049674298cbc2130689a0a40013f3458755/vm_backtrace.c#L890) and rb_ec_parcial_backtrace_object (https://github.com/ruby/ruby/blob/2733c049674298cbc2130689a0a40013f3458755/vm_backtrace.c#L605) but is not skipped by rb_profile_frames.

For instance, adding the following test code to test/-ext-/debug/test_profile_frames.rb:

  def test_compare_apis
    backtrace_locations, profile_frames = [Thread.current.backtrace_locations, Bug::Debug.profile_frames(0, 100)]

    puts '---'
    puts backtrace_locations.size
    puts backtrace_locations
    puts '---'
    puts profile_frames.size
    profile_frames.each { puts _1.to_s }
    puts '---'
  end

and then running it with make test/-ext-/debug/test_profile_frames.rb yields:

[3/4] TestProfileFrames#test_compare_apis---
27
ruby-master/test/-ext-/debug/test_profile_frames.rb:141:in `backtrace_locations'
ruby-master/test/-ext-/debug/test_profile_frames.rb:141:in `test_compare_apis'
ruby-master/tool/lib/test/unit/testcase.rb:200:in `run_test'
ruby-master/tool/lib/test/unit/testcase.rb:168:in `run'
ruby-master/tool/lib/test/unit.rb:1563:in `block in _run_suite'
ruby-master/tool/lib/test/unit.rb:1550:in `map'
ruby-master/tool/lib/test/unit.rb:1550:in `_run_suite'
ruby-master/tool/lib/test/unit.rb:1343:in `_run_suite'
ruby-master/tool/lib/test/unit.rb:812:in `block in _run_suites'
ruby-master/tool/lib/test/unit.rb:810:in `each'
ruby-master/tool/lib/test/unit.rb:810:in `_run_suites'
ruby-master/tool/lib/test/unit.rb:847:in `_run_suites'
ruby-master/tool/lib/test/unit.rb:1496:in `_run_anything'
ruby-master/tool/lib/test/unit.rb:1280:in `_run_anything'
ruby-master/tool/lib/test/unit.rb:1671:in `run_tests'
ruby-master/tool/lib/test/unit.rb:1658:in `block in _run'
ruby-master/tool/lib/test/unit.rb:1657:in `each'
ruby-master/tool/lib/test/unit.rb:1657:in `_run'
ruby-master/tool/lib/test/unit.rb:1700:in `run'
ruby-master/tool/lib/test/unit.rb:1032:in `run'
ruby-master/tool/lib/test/unit.rb:880:in `run'
ruby-master/tool/lib/test/unit.rb:154:in `run'
ruby-master/tool/lib/test/unit.rb:1779:in `run'
ruby-master/tool/lib/test/unit.rb:1783:in `run'
ruby-master/tool/test/runner.rb:23:in `<top (required)>'
./test/runner.rb:14:in `require_relative'
./test/runner.rb:14:in `<main>' # <--- FRAME IN MAIN
---
28
[nil, "<cfunc>", nil, nil, "Bug::Debug.profile_frames", nil, "Bug::Debug", true, "profile_frames", "Bug::Debug.profile_frames", 0]
["ruby-master/test/-ext-/debug/test_profile_frames.rb", "ruby-master/test/-ext-/debug/test_profile_frames.rb", "test_compare_apis", "test_compare_apis", "TestProfileFrames#test_compare_apis", 140, "TestProfileFrames", false, "test_compare_apis", "TestProfileFrames#test_compare_apis", 141]
["ruby-master/tool/lib/test/unit/testcase.rb", "ruby-master/tool/lib/test/unit/testcase.rb", "run_test", "run_test", "Test::Unit::TestCase#run_test", 198, "Test::Unit::TestCase", false, "run_test", "Test::Unit::TestCase#run_test", 200]
["ruby-master/tool/lib/test/unit/testcase.rb", "ruby-master/tool/lib/test/unit/testcase.rb", "run", "run", "Test::Unit::TestCase#run", 146, "Test::Unit::TestCase", false, "run", "Test::Unit::TestCase#run", 168]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "_run_suite", "_run_suite", "Test::Unit::Runner#_run_suite", 1530, "Test::Unit::Runner", false, "_run_suite", "Test::Unit::Runner#_run_suite", 1563]
[nil, "<cfunc>", nil, nil, "Array#map", nil, "Array", false, "map", "Array#map", 0]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "_run_suite", "_run_suite", "Test::Unit::Runner#_run_suite", 1530, "Test::Unit::Runner", false, "_run_suite", "Test::Unit::Runner#_run_suite", 1550]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "_run_suite", "_run_suite", "Test::Unit::ExcludesOption#_run_suite", 1339, "Test::Unit::ExcludesOption", false, "_run_suite", "Test::Unit::ExcludesOption#_run_suite", 1343]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "_run_suites", "_run_suites", "Test::Unit::Parallel#_run_suites", 802, "Test::Unit::Parallel", false, "_run_suites", "Test::Unit::Parallel#_run_suites", 812]
[nil, "<cfunc>", nil, nil, "Array#each", nil, "Array", false, "each", "Array#each", 0]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "_run_suites", "_run_suites", "Test::Unit::Parallel#_run_suites", 802, "Test::Unit::Parallel", false, "_run_suites", "Test::Unit::Parallel#_run_suites", 810]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "_run_suites", "_run_suites", "Test::Unit::Skipping#_run_suites", 846, "Test::Unit::Skipping", false, "_run_suites", "Test::Unit::Skipping#_run_suites", 847]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "_run_anything", "_run_anything", "Test::Unit::Runner#_run_anything", 1477, "Test::Unit::Runner", false, "_run_anything", "Test::Unit::Runner#_run_anything", 1496]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "_run_anything", "_run_anything", "Test::Unit::RepeatOption#_run_anything", 1278, "Test::Unit::RepeatOption", false, "_run_anything", "Test::Unit::RepeatOption#_run_anything", 1280]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "run_tests", "run_tests", "Test::Unit::Runner#run_tests", 1670, "Test::Unit::Runner", false, "run_tests", "Test::Unit::Runner#run_tests", 1671]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "_run", "_run", "Test::Unit::Runner#_run", 1651, "Test::Unit::Runner", false, "_run", "Test::Unit::Runner#_run", 1658]
[nil, "<cfunc>", nil, nil, "Array#each", nil, "Array", false, "each", "Array#each", 0]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "_run", "_run", "Test::Unit::Runner#_run", 1651, "Test::Unit::Runner", false, "_run", "Test::Unit::Runner#_run", 1657]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "run", "run", "Test::Unit::Runner#run", 1699, "Test::Unit::Runner", false, "run", "Test::Unit::Runner#run", 1700]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "run", "run", "Test::Unit::StatusLine#run", 1031, "Test::Unit::StatusLine", false, "run", "Test::Unit::StatusLine#run", 1032]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "run", "run", "Test::Unit::Statistics#run", 879, "Test::Unit::Statistics", false, "run", "Test::Unit::Statistics#run", 880]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "run", "run", "Test::Unit::RunCount#run", 152, "Test::Unit::RunCount", false, "run", "Test::Unit::RunCount#run", 154]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "run", "run", "Test::Unit::AutoRunner#run", 1775, "Test::Unit::AutoRunner", false, "run", "Test::Unit::AutoRunner#run", 1779]
["ruby-master/tool/lib/test/unit.rb", "ruby-master/tool/lib/test/unit.rb", "run", "run", "Test::Unit::AutoRunner.run", 1782, "Test::Unit::AutoRunner", true, "run", "Test::Unit::AutoRunner.run", 1783]
["ruby-master/tool/test/runner.rb", "ruby-master/tool/test/runner.rb", "<top (required)>", "<top (required)>", "<top (required)>", 0, nil, false, nil, nil, 23]
[nil, "<cfunc>", nil, nil, "Kernel#require_relative", nil, "Kernel", false, "require_relative", "Kernel#require_relative", 0]
["./test/runner.rb", "ruby-master/test/runner.rb", "<main>", "<main>", "<main>", 0, nil, false, nil, nil, 14] # <--- FRAME IN MAIN
["./test/runner.rb", nil, "<main>", "<main>", "<main>", 0, nil, false, nil, nil, 0] # <--- DUMMY FRAME
---

PR with fix: https://github.com/ruby/ruby/pull/6114

[ivoanjo (Ivo Anjo)]

• Description updated (diff)

[ivoanjo (Ivo Anjo)]

Update: I've rebased the PR to fix a conflict caused by the tabs-vs-spaces fix :)

[ivoanjo (Ivo Anjo)]

• Status changed from Open to Closed

Applied in changeset git|649bfbe00d8032fa2c0536e596a284f69926e87f.

---

Fix rb_profile_frames output includes dummy main thread frame

The rb_profile_frames API did not skip the two dummy frames that
each thread has at its beginning. This was unlike backtrace_each and
rb_ec_parcial_backtrace_object, which do skip them.

This does not seem to be a problem for non-main thread frames,
because both VM_FRAME_RUBYFRAME_P(cfp) and
rb_vm_frame_method_entry(cfp) are NULL for them.

BUT, on the main thread VM_FRAME_RUBYFRAME_P(cfp) was true
and thus the dummy thread was still included in the output of
rb_profile_frames.

I've now made rb_profile_frames skip this extra frame (like
backtrace_each and friends), as well as add a test that asserts
the size and contents of rb_profile_frames.

Fixes [Bug #18907] (https://bugs.ruby-lang.org/issues/18907)

[mame (Yusuke Endoh)]

I talked with @ko1 (Koichi Sasada) about this issue. It seems to be fine, so I have merged it, thanks!

[ivoanjo (Ivo Anjo)]

Awesome, thank you! :)