[ruby-core:116045] [Ruby master Bug#20157] Regression in GC.measure_total_time

newer
[ruby-core:116103] [Ruby master...

older
[ruby-core:116015] [Ruby master...

rianmcguire (Rian McGuire)

6 Jan 2024 6 Jan '24

4:14 a.m.

Issue #20157 has been reported by rianmcguire (Rian McGuire). ---------------------------------------- Bug #20157: Regression in GC.measure_total_time https://bugs.ruby-lang.org/issues/20157 * Author: rianmcguire (Rian McGuire) * Status: Open * Priority: Normal * ruby -v: ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux] * Backport: 3.0: UNKNOWN, 3.1: UNKNOWN, 3.2: UNKNOWN, 3.3: UNKNOWN ---------------------------------------- Setting `GC.measure_total_time = false` is no longer disabling GC time measurement in Ruby 3.3.0. Reproduction script: ``` ruby puts RUBY_DESCRIPTION GC.measure_total_time = false puts "measure_total_time is now false" puts "GC.stat(:time) = #{GC.stat(:time)}" puts "There should be no further clock_gettime syscalls" # Generate some garbage Random.new.bytes(100 * 1024 * 1024) GC.start puts "GC.stat(:time) = #{GC.stat(:time)}. This should be unchanged from above" ``` Ruby 3.2.2 (expected behaviour): ``` $ strace --trace=clock_gettime --signal=none ruby --disable-gems bug.rb clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=45735959}) = 0 ruby 3.2.2 (2023-03-30 revision e51014f9c0) [x86_64-linux] measure_total_time is now false GC.stat(:time) = 0 There should be no further clock_gettime syscalls GC.stat(:time) = 0. This should be unchanged from above +++ exited with 0 +++ ``` Ruby 3.3.0: ``` $ strace --trace=clock_gettime --signal=none ruby --disable-gems bug.rb clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=31784505}) = 0 ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux] measure_total_time is now false GC.stat(:time) = 0 There should be no further clock_gettime syscalls clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47132055}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47576566}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47586656}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47852906}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=180726043}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=181242023}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=181248873}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=191276005}) = 0 GC.stat(:time) = 11. This should be unchanged from above +++ exited with 0 +++ ``` It appears that this was caused by commit https://github.com/ruby/ruby/commit/93ac7405b80cc61930d73da04441fa09af1851e1 -- the test for `MEASURE_GC` inside in `gc_enter_event_measure_p` was lost in the refactoring. -- https://bugs.ruby-lang.org/

Show replies by date

rianmcguire (Rian McGuire)

6 Jan 6 Jan

4:16 a.m.

New subject: [ruby-core:116046] [Ruby master Bug#20157] Regression in GC.measure_total_time

Issue #20157 has been updated by rianmcguire (Rian McGuire). I've created a PR for this: https://github.com/ruby/ruby/pull/9427 ---------------------------------------- Bug #20157: Regression in GC.measure_total_time https://bugs.ruby-lang.org/issues/20157#change-106042 * Author: rianmcguire (Rian McGuire) * Status: Open * Priority: Normal * ruby -v: ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux] * Backport: 3.0: UNKNOWN, 3.1: UNKNOWN, 3.2: UNKNOWN, 3.3: UNKNOWN ---------------------------------------- Setting `GC.measure_total_time = false` is no longer disabling GC time measurement in Ruby 3.3.0. Reproduction script: ``` ruby puts RUBY_DESCRIPTION GC.measure_total_time = false puts "measure_total_time is now false" puts "GC.stat(:time) = #{GC.stat(:time)}" puts "There should be no further clock_gettime syscalls" # Generate some garbage Random.new.bytes(100 * 1024 * 1024) GC.start puts "GC.stat(:time) = #{GC.stat(:time)}. This should be unchanged from above" ``` Ruby 3.2.2 (expected behaviour): ``` $ strace --trace=clock_gettime --signal=none ruby --disable-gems bug.rb clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=45735959}) = 0 ruby 3.2.2 (2023-03-30 revision e51014f9c0) [x86_64-linux] measure_total_time is now false GC.stat(:time) = 0 There should be no further clock_gettime syscalls GC.stat(:time) = 0. This should be unchanged from above +++ exited with 0 +++ ``` Ruby 3.3.0: ``` $ strace --trace=clock_gettime --signal=none ruby --disable-gems bug.rb clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=31784505}) = 0 ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux] measure_total_time is now false GC.stat(:time) = 0 There should be no further clock_gettime syscalls clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47132055}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47576566}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47586656}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47852906}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=180726043}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=181242023}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=181248873}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=191276005}) = 0 GC.stat(:time) = 11. This should be unchanged from above +++ exited with 0 +++ ``` It appears that this was caused by commit https://github.com/ruby/ruby/commit/93ac7405b80cc61930d73da04441fa09af1851e1 -- the test for `MEASURE_GC` inside in `gc_enter_event_measure_p` was lost in the refactoring. -- https://bugs.ruby-lang.org/

rianmcguire (Rian McGuire)

4:27 a.m.

New subject: [ruby-core:116047] [Ruby master Bug#20157] Regression in GC.measure_total_time

Issue #20157 has been updated by rianmcguire (Rian McGuire). I've proposed a fix here: https://github.com/ruby/ruby/pull/9427 ---------------------------------------- Bug #20157: Regression in GC.measure_total_time https://bugs.ruby-lang.org/issues/20157#change-106043 * Author: rianmcguire (Rian McGuire) * Status: Open * Priority: Normal * ruby -v: ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux] * Backport: 3.0: UNKNOWN, 3.1: UNKNOWN, 3.2: UNKNOWN, 3.3: UNKNOWN ---------------------------------------- Setting `GC.measure_total_time = false` is no longer disabling GC time measurement in Ruby 3.3.0. Reproduction script: ``` ruby puts RUBY_DESCRIPTION GC.measure_total_time = false puts "measure_total_time is now false" puts "GC.stat(:time) = #{GC.stat(:time)}" puts "There should be no further clock_gettime syscalls" # Generate some garbage Random.new.bytes(100 * 1024 * 1024) GC.start puts "GC.stat(:time) = #{GC.stat(:time)}. This should be unchanged from above" ``` Ruby 3.2.2 (expected behaviour): ``` $ strace --trace=clock_gettime --signal=none ruby --disable-gems bug.rb clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=45735959}) = 0 ruby 3.2.2 (2023-03-30 revision e51014f9c0) [x86_64-linux] measure_total_time is now false GC.stat(:time) = 0 There should be no further clock_gettime syscalls GC.stat(:time) = 0. This should be unchanged from above +++ exited with 0 +++ ``` Ruby 3.3.0: ``` $ strace --trace=clock_gettime --signal=none ruby --disable-gems bug.rb clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=31784505}) = 0 ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux] measure_total_time is now false GC.stat(:time) = 0 There should be no further clock_gettime syscalls clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47132055}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47576566}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47586656}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47852906}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=180726043}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=181242023}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=181248873}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=191276005}) = 0 GC.stat(:time) = 11. This should be unchanged from above +++ exited with 0 +++ ``` It appears that this was caused by commit https://github.com/ruby/ruby/commit/93ac7405b80cc61930d73da04441fa09af1851e1 -- the test for `MEASURE_GC` inside in `gc_enter_event_measure_p` was lost in the refactoring. -- https://bugs.ruby-lang.org/

kjtsanaktsidis (KJ Tsanaktsidis)

6:39 a.m.

New subject: [ruby-core:116049] [Ruby master Bug#20157] Regression in GC.measure_total_time

Issue #20157 has been updated by kjtsanaktsidis (KJ Tsanaktsidis). Status changed from Open to Closed Backport changed from 3.0: UNKNOWN, 3.1: UNKNOWN, 3.2: UNKNOWN, 3.3: UNKNOWN to 3.0: DONTNEED, 3.1: DONTNEED, 3.2: DONTNEED, 3.3: REQUIRED PR above has been merged - thank you again. ---------------------------------------- Bug #20157: Regression in GC.measure_total_time https://bugs.ruby-lang.org/issues/20157#change-106045 * Author: rianmcguire (Rian McGuire) * Status: Closed * Priority: Normal * ruby -v: ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux] * Backport: 3.0: DONTNEED, 3.1: DONTNEED, 3.2: DONTNEED, 3.3: REQUIRED ---------------------------------------- Setting `GC.measure_total_time = false` is no longer disabling GC time measurement in Ruby 3.3.0. Reproduction script: ``` ruby puts RUBY_DESCRIPTION GC.measure_total_time = false puts "measure_total_time is now false" puts "GC.stat(:time) = #{GC.stat(:time)}" puts "There should be no further clock_gettime syscalls" # Generate some garbage Random.new.bytes(100 * 1024 * 1024) GC.start puts "GC.stat(:time) = #{GC.stat(:time)}. This should be unchanged from above" ``` Ruby 3.2.2 (expected behaviour): ``` $ strace --trace=clock_gettime --signal=none ruby --disable-gems bug.rb clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=45735959}) = 0 ruby 3.2.2 (2023-03-30 revision e51014f9c0) [x86_64-linux] measure_total_time is now false GC.stat(:time) = 0 There should be no further clock_gettime syscalls GC.stat(:time) = 0. This should be unchanged from above +++ exited with 0 +++ ``` Ruby 3.3.0: ``` $ strace --trace=clock_gettime --signal=none ruby --disable-gems bug.rb clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=31784505}) = 0 ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux] measure_total_time is now false GC.stat(:time) = 0 There should be no further clock_gettime syscalls clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47132055}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47576566}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47586656}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47852906}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=180726043}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=181242023}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=181248873}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=191276005}) = 0 GC.stat(:time) = 11. This should be unchanged from above +++ exited with 0 +++ ``` It appears that this was caused by commit https://github.com/ruby/ruby/commit/93ac7405b80cc61930d73da04441fa09af1851e1 -- the test for `MEASURE_GC` inside in `gc_enter_event_measure_p` was lost in the refactoring. -- https://bugs.ruby-lang.org/

kjtsanaktsidis (KJ Tsanaktsidis)

6:49 a.m.

New subject: [ruby-core:116050] [Ruby master Bug#20157] Regression in GC.measure_total_time

Issue #20157 has been updated by kjtsanaktsidis (KJ Tsanaktsidis). Backport PR: https://github.com/ruby/ruby/pull/9428 ---------------------------------------- Bug #20157: Regression in GC.measure_total_time https://bugs.ruby-lang.org/issues/20157#change-106046 * Author: rianmcguire (Rian McGuire) * Status: Closed * Priority: Normal * ruby -v: ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux] * Backport: 3.0: DONTNEED, 3.1: DONTNEED, 3.2: DONTNEED, 3.3: REQUIRED ---------------------------------------- Setting `GC.measure_total_time = false` is no longer disabling GC time measurement in Ruby 3.3.0. Reproduction script: ``` ruby puts RUBY_DESCRIPTION GC.measure_total_time = false puts "measure_total_time is now false" puts "GC.stat(:time) = #{GC.stat(:time)}" puts "There should be no further clock_gettime syscalls" # Generate some garbage Random.new.bytes(100 * 1024 * 1024) GC.start puts "GC.stat(:time) = #{GC.stat(:time)}. This should be unchanged from above" ``` Ruby 3.2.2 (expected behaviour): ``` $ strace --trace=clock_gettime --signal=none ruby --disable-gems bug.rb clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=45735959}) = 0 ruby 3.2.2 (2023-03-30 revision e51014f9c0) [x86_64-linux] measure_total_time is now false GC.stat(:time) = 0 There should be no further clock_gettime syscalls GC.stat(:time) = 0. This should be unchanged from above +++ exited with 0 +++ ``` Ruby 3.3.0: ``` $ strace --trace=clock_gettime --signal=none ruby --disable-gems bug.rb clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=31784505}) = 0 ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux] measure_total_time is now false GC.stat(:time) = 0 There should be no further clock_gettime syscalls clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47132055}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47576566}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47586656}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47852906}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=180726043}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=181242023}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=181248873}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=191276005}) = 0 GC.stat(:time) = 11. This should be unchanged from above +++ exited with 0 +++ ``` It appears that this was caused by commit https://github.com/ruby/ruby/commit/93ac7405b80cc61930d73da04441fa09af1851e1 -- the test for `MEASURE_GC` inside in `gc_enter_event_measure_p` was lost in the refactoring. -- https://bugs.ruby-lang.org/

naruse (Yui NARUSE)

1 Feb 1 Feb

4:40 a.m.

New subject: [ruby-core:116540] [Ruby master Bug#20157] Regression in GC.measure_total_time

Issue #20157 has been updated by naruse (Yui NARUSE). Backport changed from 3.0: DONTNEED, 3.1: DONTNEED, 3.2: DONTNEED, 3.3: REQUIRED to 3.0: DONTNEED, 3.1: DONTNEED, 3.2: DONTNEED, 3.3: DONE ruby_3_3 920c17dc94239baae05b513046b27967f11a3569. ---------------------------------------- Bug #20157: Regression in GC.measure_total_time https://bugs.ruby-lang.org/issues/20157#change-106558 * Author: rianmcguire (Rian McGuire) * Status: Closed * Priority: Normal * ruby -v: ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux] * Backport: 3.0: DONTNEED, 3.1: DONTNEED, 3.2: DONTNEED, 3.3: DONE ---------------------------------------- Setting `GC.measure_total_time = false` is no longer disabling GC time measurement in Ruby 3.3.0. Reproduction script: ``` ruby puts RUBY_DESCRIPTION GC.measure_total_time = false puts "measure_total_time is now false" puts "GC.stat(:time) = #{GC.stat(:time)}" puts "There should be no further clock_gettime syscalls" # Generate some garbage Random.new.bytes(100 * 1024 * 1024) GC.start puts "GC.stat(:time) = #{GC.stat(:time)}. This should be unchanged from above" ``` Ruby 3.2.2 (expected behaviour): ``` $ strace --trace=clock_gettime --signal=none ruby --disable-gems bug.rb clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=45735959}) = 0 ruby 3.2.2 (2023-03-30 revision e51014f9c0) [x86_64-linux] measure_total_time is now false GC.stat(:time) = 0 There should be no further clock_gettime syscalls GC.stat(:time) = 0. This should be unchanged from above +++ exited with 0 +++ ``` Ruby 3.3.0: ``` $ strace --trace=clock_gettime --signal=none ruby --disable-gems bug.rb clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=31784505}) = 0 ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux] measure_total_time is now false GC.stat(:time) = 0 There should be no further clock_gettime syscalls clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47132055}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47576566}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47586656}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=47852906}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=180726043}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=181242023}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=181248873}) = 0 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=191276005}) = 0 GC.stat(:time) = 11. This should be unchanged from above +++ exited with 0 +++ ``` It appears that this was caused by commit https://github.com/ruby/ruby/commit/93ac7405b80cc61930d73da04441fa09af1851e1 -- the test for `MEASURE_GC` inside in `gc_enter_event_measure_p` was lost in the refactoring. -- https://bugs.ruby-lang.org/

549

Age (days ago)

575

Last active (days ago)

List overview

Download

5 comments

3 participants

participants (3)

kjtsanaktsidis (KJ Tsanaktsidis)
naruse (Yui NARUSE)
rianmcguire (Rian McGuire)