From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.2 (2018-09-13) on dcvr.yhbt.net X-Spam-Level: X-Spam-Status: No, score=-3.8 required=3.0 tests=AWL,BAYES_00, HEADER_FROM_DIFFERENT_DOMAINS,MAILING_LIST_MULTI,RCVD_IN_DNSWL_MED, SPF_HELO_NONE,SPF_PASS,UNPARSEABLE_RELAY shortcircuit=no autolearn=ham autolearn_force=no version=3.4.2 Received: from neon.ruby-lang.org (neon.ruby-lang.org [221.186.184.75]) by dcvr.yhbt.net (Postfix) with ESMTP id 2CDFC1F66E for ; Fri, 21 Aug 2020 18:01:40 +0000 (UTC) Received: from neon.ruby-lang.org (localhost [IPv6:::1]) by neon.ruby-lang.org (Postfix) with ESMTP id D7824120AA9; Sat, 22 Aug 2020 03:01:05 +0900 (JST) Received: from xtrwkhkc.outbound-mail.sendgrid.net (xtrwkhkc.outbound-mail.sendgrid.net [167.89.16.28]) by neon.ruby-lang.org (Postfix) with ESMTPS id CD843120A50 for ; Sat, 22 Aug 2020 03:01:03 +0900 (JST) Received: by filterdrecv-p3las1-7c6d97d9cb-tjd4v with SMTP id filterdrecv-p3las1-7c6d97d9cb-tjd4v-17-5F400BFC-5A 2020-08-21 18:01:32.472180713 +0000 UTC m=+86308.870109083 Received: from herokuapp.com (unknown) by geopod-ismtpd-4-1 (SG) with ESMTP id ZB47d5UzRnGKM-aqaPMWtA for ; Fri, 21 Aug 2020 18:01:32.302 +0000 (UTC) Date: Fri, 21 Aug 2020 18:01:32 +0000 (UTC) From: merch-redmine@jeremyevans.net Message-ID: References: Mime-Version: 1.0 X-Redmine-MailingListIntegration-Message-Ids: 75497 X-Redmine-Project: ruby-master X-Redmine-Issue-Tracker: Bug X-Redmine-Issue-Id: 17031 X-Redmine-Issue-Author: marcandre X-Redmine-Sender: jeremyevans0 X-Mailer: Redmine X-Redmine-Host: bugs.ruby-lang.org X-Redmine-Site: Ruby Issue Tracking System X-Auto-Response-Suppress: All Auto-Submitted: auto-generated X-SG-EID: =?us-ascii?Q?RVE3t853K5scBhbmJHUzZTFFeVC=2FZSUmHZ0Dc+26wcEi2CTgsF1oz0wTSSxGGN?= =?us-ascii?Q?BIBJSavcJEJ8eV1jPeBEmWGxDY1po7emUSL9WEc?= =?us-ascii?Q?=2FEEdbpHq+v+rrswhUd0fGSuWpxNEClONOGvAEUF?= =?us-ascii?Q?06kPiDVJRcWN8dybmlWtQXeMYagDRAquqipbBl6?= =?us-ascii?Q?3HAApNnkWg+HtFUxXWk+SFLCMM1cw87xWiH+ZaK?= =?us-ascii?Q?bESmdXNQlawM503JA=3D?= To: ruby-core@ruby-lang.org X-ML-Name: ruby-core X-Mail-Count: 99667 Subject: [ruby-core:99667] [Ruby master Bug#17031] `Kernel#caller_locations(m, n)` should be optimized X-BeenThere: ruby-core@ruby-lang.org X-Mailman-Version: 2.1.15 Precedence: list Reply-To: Ruby developers List-Id: Ruby developers List-Unsubscribe: , List-Post: List-Help: List-Subscribe: , Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Errors-To: ruby-core-bounces@ruby-lang.org Sender: "ruby-core" 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/