[ruby-core:99169] [Ruby master Bug#17031] `Kernel#caller_locations(m, n)` should be optimized

[ruby-core:99169] [Ruby master Bug#17031] `Kernel#caller_locations(m, n)` should be optimized

[marcandre-ruby-core]

Issue #17031 has been reported by marcandre (Marc-Andre Lafortune).

----------------------------------------
Bug #17031: `Kernel#caller_locations(m, n)` should be optimized
https://bugs.ruby-lang.org/issues/17031

* Author: marcandre (Marc-Andre Lafortune)
* Status: Open
* Priority: Normal
* Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN
----------------------------------------
`Kernel#caller_locations(1, 1)` currently appears to needlessly allocate memory for the whole backtrace.

It allocates ~20kB for a 800-deep stacktrace, vs 1.6 kB for a shallow backtrace.
It is also much slower for long stacktraces: about 7x slower for a 800-deep backtrace than for a shallow one.

Test used:
```ruby
def do_something
  location = caller_locations(1, 1).first
end

def test(depth, trigger)
  do_something if depth == trigger

  test(depth - 1, trigger) unless depth == 0
end

require 'benchmark/ips'

Benchmark.ips do |x|
  x.report (:short_backtrace    )    {test(800,800)}
  x.report (:long_backtrace     )    {test(800,  0)}
  x.report (:no_caller_locations)    {test(800, -1)}
end

require 'memory_profiler'

MemoryProfiler.report { test(800,800) }.pretty_print(scale_bytes: true, detailed_report: false)
MemoryProfiler.report { test(800,  0) }.pretty_print(scale_bytes: true, detailed_report: false)
```

Found when checking memory usage on RuboCop.




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

[ruby-core:99176] [Ruby master Bug#17031] `Kernel#caller_locations(m, n)` should be optimized

[eregontp]

Issue #17031 has been updated by Eregon (Benoit Daloze).


Could you post the results of running that on your computer?
Then it's easier to see your point without needing to reproduce.

----------------------------------------
Bug #17031: `Kernel#caller_locations(m, n)` should be optimized
https://bugs.ruby-lang.org/issues/17031#change-86555

* Author: marcandre (Marc-Andre Lafortune)
* Status: Open
* Priority: Normal
* Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN
----------------------------------------
`Kernel#caller_locations(1, 1)` currently appears to needlessly allocate memory for the whole backtrace.

It allocates ~20kB for a 800-deep stacktrace, vs 1.6 kB for a shallow backtrace.
It is also much slower for long stacktraces: about 7x slower for a 800-deep backtrace than for a shallow one.

Test used:
```ruby
def do_something
  location = caller_locations(1, 1).first
end

def test(depth, trigger)
  do_something if depth == trigger

  test(depth - 1, trigger) unless depth == 0
end

require 'benchmark/ips'

Benchmark.ips do |x|
  x.report (:short_backtrace    )    {test(800,800)}
  x.report (:long_backtrace     )    {test(800,  0)}
  x.report (:no_caller_locations)    {test(800, -1)}
end

require 'memory_profiler'

MemoryProfiler.report { test(800,800) }.pretty_print(scale_bytes: true, detailed_report: false)
MemoryProfiler.report { test(800,  0) }.pretty_print(scale_bytes: true, detailed_report: false)
```

Found when checking memory usage on RuboCop.




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

[ruby-core:99180] [Ruby master Bug#17031] `Kernel#caller_locations(m, n)` should be optimized

[marcandre-ruby-core]

Issue #17031 has been updated by marcandre (Marc-Andre Lafortune).


Sure

```
Calculating -------------------------------------
     short_backtrace     28.315k (± 7.1%) i/s -    141.984k in   5.044733s
      long_backtrace     24.168k (± 8.7%) i/s -    120.900k in   5.050243s
 no_caller_locations     29.288k (± 2.5%) i/s -    148.359k in   5.068723s
Total allocated: 1.58 kB (3 objects)
Total retained:  0 B (0 objects)

Total allocated: 19.58 kB (3 objects)
Total retained:  0 B (0 objects)
```

I got a factor 6.2 this time: (1/24.168-1/29.288)/(1/28.315-1/29.288)
 
 


----------------------------------------
Bug #17031: `Kernel#caller_locations(m, n)` should be optimized
https://bugs.ruby-lang.org/issues/17031#change-86559

* Author: marcandre (Marc-Andre Lafortune)
* Status: Open
* Priority: Normal
* Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN
----------------------------------------
`Kernel#caller_locations(1, 1)` currently appears to needlessly allocate memory for the whole backtrace.

It allocates ~20kB for a 800-deep stacktrace, vs 1.6 kB for a shallow backtrace.
It is also much slower for long stacktraces: about 7x slower for a 800-deep backtrace than for a shallow one.

Test used:
```ruby
def do_something
  location = caller_locations(1, 1).first
end

def test(depth, trigger)
  do_something if depth == trigger

  test(depth - 1, trigger) unless depth == 0
end

require 'benchmark/ips'

Benchmark.ips do |x|
  x.report (:short_backtrace    )    {test(800,800)}
  x.report (:long_backtrace     )    {test(800,  0)}
  x.report (:no_caller_locations)    {test(800, -1)}
end

require 'memory_profiler'

MemoryProfiler.report { test(800,800) }.pretty_print(scale_bytes: true, detailed_report: false)
MemoryProfiler.report { test(800,  0) }.pretty_print(scale_bytes: true, detailed_report: false)
```

Found when checking memory usage on RuboCop.




-- 
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>

[ruby-core:99209] [Ruby master Bug#17031] `Kernel#caller_locations(m, n)` should be optimized

[merch-redmine]

Issue #17031 has been updated by jeremyevans0 (Jeremy Evans).


Reviewing the related code in vm_backtrace.c, you are correct.  This occurs both for `caller` and `caller_locations`.  The entire internal backtrace object is generated by `rb_ec_backtrace_object`, and then passed to a function that looks at specific parts of it to generate the strings or Thread::Backtrace::Location objects.  To fix this would require changing the logic so that `rb_ec_backtrace_object` was passed the starting level and number of frames.

----------------------------------------
Bug #17031: `Kernel#caller_locations(m, n)` should be optimized
https://bugs.ruby-lang.org/issues/17031#change-86589

* Author: marcandre (Marc-Andre Lafortune)
* Status: Open
* Priority: Normal
* Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN
----------------------------------------
`Kernel#caller_locations(1, 1)` currently appears to needlessly allocate memory for the whole backtrace.

It allocates ~20kB for a 800-deep stacktrace, vs 1.6 kB for a shallow backtrace.
It is also much slower for long stacktraces: about 7x slower for a 800-deep backtrace than for a shallow one.

Test used:
```ruby
def do_something
  location = caller_locations(1, 1).first
end

def test(depth, trigger)
  do_something if depth == trigger

  test(depth - 1, trigger) unless depth == 0
end

require 'benchmark/ips'

Benchmark.ips do |x|
  x.report (:short_backtrace    )    {test(800,800)}
  x.report (:long_backtrace     )    {test(800,  0)}
  x.report (:no_caller_locations)    {test(800, -1)}
end

require 'memory_profiler'

MemoryProfiler.report { test(800,800) }.pretty_print(scale_bytes: true, detailed_report: false)
MemoryProfiler.report { test(800,  0) }.pretty_print(scale_bytes: true, detailed_report: false)
```

Found when checking memory usage on RuboCop.




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

[ruby-core:99309] [Ruby master Bug#17031] `Kernel#caller_locations(m, n)` should be optimized

[merch-redmine]

Issue #17031 has been updated by jeremyevans0 (Jeremy Evans).


I've added a pull request that addresses this issue: https://github.com/ruby/ruby/pull/3357

----------------------------------------
Bug #17031: `Kernel#caller_locations(m, n)` should be optimized
https://bugs.ruby-lang.org/issues/17031#change-86697

* Author: marcandre (Marc-Andre Lafortune)
* Status: Open
* Priority: Normal
* Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN
----------------------------------------
`Kernel#caller_locations(1, 1)` currently appears to needlessly allocate memory for the whole backtrace.

It allocates ~20kB for a 800-deep stacktrace, vs 1.6 kB for a shallow backtrace.
It is also much slower for long stacktraces: about 7x slower for a 800-deep backtrace than for a shallow one.

Test used:
```ruby
def do_something
  location = caller_locations(1, 1).first
end

def test(depth, trigger)
  do_something if depth == trigger

  test(depth - 1, trigger) unless depth == 0
end

require 'benchmark/ips'

Benchmark.ips do |x|
  x.report (:short_backtrace    )    {test(800,800)}
  x.report (:long_backtrace     )    {test(800,  0)}
  x.report (:no_caller_locations)    {test(800, -1)}
end

require 'memory_profiler'

MemoryProfiler.report { test(800,800) }.pretty_print(scale_bytes: true, detailed_report: false)
MemoryProfiler.report { test(800,  0) }.pretty_print(scale_bytes: true, detailed_report: false)
```

Found when checking memory usage on RuboCop.




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

[ruby-core:99565] [Ruby master Bug#17031] `Kernel#caller_locations(m, n)` should be optimized

[ko1]

Issue #17031 has been updated by ko1 (Koichi Sasada).


Thank you Jeremy!
Great patch!

----------------------------------------
Bug #17031: `Kernel#caller_locations(m, n)` should be optimized
https://bugs.ruby-lang.org/issues/17031#change-87031

* Author: marcandre (Marc-Andre Lafortune)
* Status: Open
* Priority: Normal
* Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN
----------------------------------------
`Kernel#caller_locations(1, 1)` currently appears to needlessly allocate memory for the whole backtrace.

It allocates ~20kB for a 800-deep stacktrace, vs 1.6 kB for a shallow backtrace.
It is also much slower for long stacktraces: about 7x slower for a 800-deep backtrace than for a shallow one.

Test used:
```ruby
def do_something
  location = caller_locations(1, 1).first
end

def test(depth, trigger)
  do_something if depth == trigger

  test(depth - 1, trigger) unless depth == 0
end

require 'benchmark/ips'

Benchmark.ips do |x|
  x.report (:short_backtrace    )    {test(800,800)}
  x.report (:long_backtrace     )    {test(800,  0)}
  x.report (:no_caller_locations)    {test(800, -1)}
end

require 'memory_profiler'

MemoryProfiler.report { test(800,800) }.pretty_print(scale_bytes: true, detailed_report: false)
MemoryProfiler.report { test(800,  0) }.pretty_print(scale_bytes: true, detailed_report: false)
```

Found when checking memory usage on RuboCop.




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

[ruby-core:99572] [Ruby master Bug#17031] `Kernel#caller_locations(m, n)` should be optimized

[merch-redmine]

Issue #17031 has been updated by jeremyevans0 (Jeremy Evans).

Status changed from Closed to Open

Reopening this as the commit had to be reverted as CI showed issues in `backtrace_mark`.  I can't work on debugging this right away, so someone is welcome to look into fixing this in the meantime.

----------------------------------------
Bug #17031: `Kernel#caller_locations(m, n)` should be optimized
https://bugs.ruby-lang.org/issues/17031#change-87040

* Author: marcandre (Marc-Andre Lafortune)
* Status: Open
* Priority: Normal
* Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN
----------------------------------------
`Kernel#caller_locations(1, 1)` currently appears to needlessly allocate memory for the whole backtrace.

It allocates ~20kB for a 800-deep stacktrace, vs 1.6 kB for a shallow backtrace.
It is also much slower for long stacktraces: about 7x slower for a 800-deep backtrace than for a shallow one.

Test used:
```ruby
def do_something
  location = caller_locations(1, 1).first
end

def test(depth, trigger)
  do_something if depth == trigger

  test(depth - 1, trigger) unless depth == 0
end

require 'benchmark/ips'

Benchmark.ips do |x|
  x.report (:short_backtrace    )    {test(800,800)}
  x.report (:long_backtrace     )    {test(800,  0)}
  x.report (:no_caller_locations)    {test(800, -1)}
end

require 'memory_profiler'

MemoryProfiler.report { test(800,800) }.pretty_print(scale_bytes: true, detailed_report: false)
MemoryProfiler.report { test(800,  0) }.pretty_print(scale_bytes: true, detailed_report: false)
```

Found when checking memory usage on RuboCop.




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

[ruby-core:99667] [Ruby master Bug#17031] `Kernel#caller_locations(m, n)` should be optimized

[merch-redmine]

Issue #17031 has been updated by jeremyevans0 (Jeremy Evans).


Most of the CI issues were when running with asserts, so I compiled with asserts enabled and ran tests.  It took quite a while, and no problems were noted:

```
Finished tests in 82924.634324s, 0.2518 tests/s, 67.0770 assertions/s.
20884 tests, 5562336 assertions, 0 failures, 0 errors, 79 skips
```

Here are some backtraces for the crashed CI processes before the commit was reverted:

```
/tmp/ruby/v3/build/trunk-test/libruby.so.2.8.0(rb_bug+0xe4) [0x7fd5f7149c73] /tmp/ruby/v3/src/trunk-test/error.c:660
/tmp/ruby/v3/build/trunk-test/libruby.so.2.8.0(gc_mark_ptr+0xee) [0x7fd5f7202a3e] /tmp/ruby/v3/src/trunk-test/gc.c:5301
/tmp/ruby/v3/build/trunk-test/libruby.so.2.8.0(backtrace_mark+0x89) [0x7fd5f73b7859] /tmp/ruby/v3/src/trunk-test/vm_backtrace.c:129
/tmp/ruby/v3/build/trunk-test/libruby.so.2.8.0(gc_mark_children+0x5d7) [0x7fd5f7203447] /tmp/ruby/v3/src/trunk-test/gc.c:5544

/tmp/ruby/v3/build/trunk-gc-asserts/libruby.so.2.8.0(sigsegv+0x4b) [0x7f998c3acc8b] /tmp/ruby/v3/src/trunk-gc-asserts/signal.c:959
/lib/x86_64-linux-gnu/libc.so.6(0x7f998bdecf20) [0x7f998bdecf20]
/tmp/ruby/v3/build/trunk-gc-asserts/libruby.so.2.8.0(backtrace_mark+0x27) [0x7f998c441167] /tmp/ruby/v3/src/trunk-gc-asserts/vm_backtrace.c:425
/tmp/ruby/v3/build/trunk-gc-asserts/libruby.so.2.8.0(gc_mark_children+0x5e7) [0x7f998c28d607] /tmp/ruby/v3/src/trunk-gc-asserts/gc.c:5544

/tmp/ruby/v3/build/trunk-asserts/libruby.so.2.8.0(check_rvalue_consistency_force+0x5c) [0x7f939d46ecac] /tmp/ruby/v3/src/trunk-asserts/gc.c:1291
/tmp/ruby/v3/build/trunk-asserts/libruby.so.2.8.0(gc_mark+0x2c) [0x7f939d4730ec] /tmp/ruby/v3/src/trunk-asserts/gc.c:1307
/tmp/ruby/v3/build/trunk-asserts/libruby.so.2.8.0(backtrace_mark+0x89) [0x7f939d62a309] /tmp/ruby/v3/src/trunk-asserts/vm_backtrace.c:129
/tmp/ruby/v3/build/trunk-asserts/libruby.so.2.8.0(gc_mark_children+0x74f) [0x7f939d4738bf] /tmp/ruby/v3/src/trunk-asserts/gc.c:5544
```

Unfortunately, not being able to recreate the issue or get a backtrace with debugging information, I'm not sure what the root cause is.  My best guess at this point is it may be caused by this chunk:

```diff
@@ -126,6 +129,10 @@ location_mark_entry(rb_backtrace_location_t *fi)
        rb_gc_mark_movable((VALUE)fi->body.iseq.iseq);
        break;
       case LOCATION_TYPE_CFUNC:
+        if (fi->body.cfunc.prev_loc) {
+            location_mark_entry(fi->body.cfunc.prev_loc);
+        }
+        break;
       case LOCATION_TYPE_IFUNC:
       default:
        break;
@@ -484,22 +491,47 @@ backtrace_alloc(VALUE klass)
     return obj;
 }
```

I originally thought that was necessary to handle the location for a cfunc where the previous iseq frame was not part of the backtrace, but on reflection it should not be, because that iseq frame should be separately marked as it is the last entry in rb_backtrace_t.backtrace.  I'm not sure why it would cause problems, but since it is new and shouldn't be necessary, it might be best to eliminate it.  I submitted this change as a pull request (https://github.com/ruby/ruby/pull/3441).

----------------------------------------
Bug #17031: `Kernel#caller_locations(m, n)` should be optimized
https://bugs.ruby-lang.org/issues/17031#change-87152

* Author: marcandre (Marc-Andre Lafortune)
* Status: Open
* Priority: Normal
* Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN
----------------------------------------
`Kernel#caller_locations(1, 1)` currently appears to needlessly allocate memory for the whole backtrace.

It allocates ~20kB for a 800-deep stacktrace, vs 1.6 kB for a shallow backtrace.
It is also much slower for long stacktraces: about 7x slower for a 800-deep backtrace than for a shallow one.

Test used:
```ruby
def do_something
  location = caller_locations(1, 1).first
end

def test(depth, trigger)
  do_something if depth == trigger

  test(depth - 1, trigger) unless depth == 0
end

require 'benchmark/ips'

Benchmark.ips do |x|
  x.report (:short_backtrace    )    {test(800,800)}
  x.report (:long_backtrace     )    {test(800,  0)}
  x.report (:no_caller_locations)    {test(800, -1)}
end

require 'memory_profiler'

MemoryProfiler.report { test(800,800) }.pretty_print(scale_bytes: true, detailed_report: false)
MemoryProfiler.report { test(800,  0) }.pretty_print(scale_bytes: true, detailed_report: false)
```

Found when checking memory usage on RuboCop.




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