[ruby-core:125977] [Ruby Bug#22187] High major GCs caused by specific concurrent workloads in 3.4
Issue #22187 has been reported by rpeng (Richard Peng). ---------------------------------------- Bug #22187: High major GCs caused by specific concurrent workloads in 3.4 https://bugs.ruby-lang.org/issues/22187 * Author: rpeng (Richard Peng) * Status: Open * ruby -v: 3.4.10 * Backport: 3.3: UNKNOWN, 3.4: UNKNOWN, 4.0: UNKNOWN ---------------------------------------- Hello, We are running into an issue that's very similar to https://bugs.ruby-lang.org/issues/21838, and believe it has the same root cause of global allocatable slots by running thru git-bisect (https://bugs.ruby-lang.org/projects/ruby-master/repository/git/revisions/079...). For very specific workloads (high concurrency, large-ish file downloads), we are seeing that the amount of major GCs has markedly increased under 3.4. It has occurred in our production workloads and lead to increased tail latencies (almost doubling our p75 / p99s). To reproduce: 1. Save the reproduction script below to a ruby file repro.rb 2. Run it against official ruby images (3.3.11-trixie, and 3.4.10-trixie) 3. See the differences in major GC count ``` docker run --rm --pull always -v "$PWD/repro.rb:/repro.rb:ro" ruby:3.3.11-trixie ruby /repro.rb # output: [3.3.11] threads=9 total=2000 body=4MB majors=8 minors=771 docker run --rm --pull always -v "$PWD/repro.rb:/repro.rb:ro" ruby:3.4.10-trixie ruby /repro.rb # output: [3.4.10] threads=9 total=2000 body=4MB majors=56 minors=752 ``` Reproduction script: ``` ruby # repro.rb require "socket" require "net/http" THREADS = 9 ITERATIONS = 2000 ITERATIONS_PER_THREAD = ITERATIONS / THREADS BODY_MB = 4 BODY = 'x' * (BODY_MB * 1024 * 1024) srv = TCPServer.new("127.0.0.1", 0) PORT = srv.addr[1] Thread.new do loop do begin conn = srv.accept rescue StandardError break end Thread.new(conn) do |c| begin loop do received_line = false while (line = c.gets) received_line = true break if line == "\r\n" end break unless received_line c.write "HTTP/1.1 200 OK\r\nContent-Length: #{BODY.bytesize}\r\n" \ "Connection: keep-alive\r\n\r\n" c.write BODY end ensure c.close end end end end def download Net::HTTP.get("127.0.0.1", "/", PORT).bytesize end # warm up the heap to steady state, then measure only the download loop. 2.times { Array.new(THREADS) { Thread.new { 2.times { download } } }.each(&:join) } Process.warmup before = GC.stat Array.new(THREADS) { Thread.new { ITERATIONS_PER_THREAD.times { download } } }.each(&:join) after = GC.stat puts format("[%s] threads=%d total=%d body=%dMB majors=%d minors=%d", RUBY_VERSION, THREADS, ITERATIONS, BODY_MB, after[:major_gc_count] - before[:major_gc_count], after[:minor_gc_count] - before[:minor_gc_count]) srv.close ``` We _suspect_ that this line change here: https://github.com/ruby/ruby/pull/11562/changes#diff-d23f31a61dfe958dc753964... is causing more aggressive major GCs when the heap should be growing instead, but I am admittedly not well versed in Ruby core code. We made an experiment to add back the check (total_slots < init_slots) in gc/default.c, and it seemed to have remediated the issue, but I'm not sure what trade offs comes with that change. -- https://bugs.ruby-lang.org/
Issue #22187 has been updated by rpeng (Richard Peng). Subject changed from High major GCs caused by specific concurrent workloads in 3.4 to High major GCs caused by specific workloads in 3.4 With some more investigation, added a much shorter reproduction script that does not require a server ```ruby RETAINED = Array.new(25_000) { +"retained" } Process.warmup WINDOW = Array.new(20) before = GC.stat 6_000.times do |i| s = "x" * (4 * 1024 * 1024) WINDOW[i % 20] = Array.new(128) { +"y" } end after = GC.stat puts "[#{RUBY_VERSION}] majors=#{after[:major_gc_count] - before[:major_gc_count]} minors=#{after[:minor_gc_count] - before[:minor_gc_count]}" ``` On 3.3.11 [3.3.10] majors=9 minors=484 On 3.4.10 [3.4.10] majors=161 minors=487 ---------------------------------------- Bug #22187: High major GCs caused by specific workloads in 3.4 https://bugs.ruby-lang.org/issues/22187#change-118036 * Author: rpeng (Richard Peng) * Status: Open * ruby -v: 3.4.10 * Backport: 3.3: UNKNOWN, 3.4: UNKNOWN, 4.0: UNKNOWN ---------------------------------------- Hello, We are running into an issue that's very similar to https://bugs.ruby-lang.org/issues/21838, and believe it has the same root cause of global allocatable slots by running thru git-bisect (https://bugs.ruby-lang.org/projects/ruby-master/repository/git/revisions/079...). For very specific workloads (high concurrency, large-ish file downloads), we are seeing that the amount of major GCs has markedly increased under 3.4. It has occurred in our production workloads and lead to increased tail latencies (almost doubling our p75 / p99s). To reproduce: 1. Save the reproduction script below to a ruby file repro.rb 2. Run it against official ruby images (3.3.11-trixie, and 3.4.10-trixie) 3. See the differences in major GC count ``` docker run --rm --pull always -v "$PWD/repro.rb:/repro.rb:ro" ruby:3.3.11-trixie ruby /repro.rb # output: [3.3.11] threads=9 total=2000 body=4MB majors=8 minors=771 docker run --rm --pull always -v "$PWD/repro.rb:/repro.rb:ro" ruby:3.4.10-trixie ruby /repro.rb # output: [3.4.10] threads=9 total=2000 body=4MB majors=56 minors=752 ``` Reproduction script: ``` ruby # repro.rb require "socket" require "net/http" THREADS = 9 ITERATIONS = 2000 ITERATIONS_PER_THREAD = ITERATIONS / THREADS BODY_MB = 4 BODY = 'x' * (BODY_MB * 1024 * 1024) srv = TCPServer.new("127.0.0.1", 0) PORT = srv.addr[1] Thread.new do loop do begin conn = srv.accept rescue StandardError break end Thread.new(conn) do |c| begin loop do received_line = false while (line = c.gets) received_line = true break if line == "\r\n" end break unless received_line c.write "HTTP/1.1 200 OK\r\nContent-Length: #{BODY.bytesize}\r\n" \ "Connection: keep-alive\r\n\r\n" c.write BODY end ensure c.close end end end end def download Net::HTTP.get("127.0.0.1", "/", PORT).bytesize end # warm up the heap to steady state, then measure only the download loop. 2.times { Array.new(THREADS) { Thread.new { 2.times { download } } }.each(&:join) } Process.warmup before = GC.stat Array.new(THREADS) { Thread.new { ITERATIONS_PER_THREAD.times { download } } }.each(&:join) after = GC.stat puts format("[%s] threads=%d total=%d body=%dMB majors=%d minors=%d", RUBY_VERSION, THREADS, ITERATIONS, BODY_MB, after[:major_gc_count] - before[:major_gc_count], after[:minor_gc_count] - before[:minor_gc_count]) srv.close ``` We _suspect_ that this line change here: https://github.com/ruby/ruby/pull/11562/changes#diff-d23f31a61dfe958dc753964... is causing more aggressive major GCs when the heap should be growing instead, but I am admittedly not well versed in Ruby core code. We made an experiment to add back the check (total_slots < init_slots) in gc/default.c, and it seemed to have remediated the issue, but I'm not sure what trade offs comes with that change. Addendum: With some further investigation, it seems that there's a pathological case in 3.4, where a major GC frees enough slots to allow the workload to continue so it does not actually end up calling malloc. This causes nofree majors to trigger much more often since num slots did not increase, whereas in 3.3, the malloc would eventually right-size the number of slots. I've listed the GC.state for eden 0 slots comparison between the ruby versions (almost all the major GCs were caused by slot 0). 3.3: 29471 slots 3.4: 22922 slots ``` # docker run --rm --pull always -v "$PWD/repro.rb:/repro.rb:ro" ruby:3.3.11-trixie ruby /repro.rb 2>/dev/null [3.3.11] threads=9 total=2000 body=4MB majors=7 minors=766 eden 0 slots: 29471 ``` ``` # docker run --rm --pull always -v "$PWD/repro.rb:/repro.rb:ro" ruby:3.4.10-trixie ruby /repro.rb 2>/dev/null [3.4.10] threads=9 total=2000 body=4MB majors=59 minors=746 eden 0 slots: 22922 ``` -- https://bugs.ruby-lang.org/
participants (1)
-
rpeng (Richard Peng)