Bug #22187: High major GCs caused by specific workloads in 3.4

• Status: Open
• Assignee: -
• Target version: -
• ruby -v: 3.4.10
• Backport: 3.3: UNKNOWN, 3.4: UNKNOWN, 4.0: UNKNOWN

[rpeng (Richard Peng)]

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/079ef92b5e59b616d670efe81a33e500f2bf6451).

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:

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

[rpeng (Richard Peng)]

• Description updated (diff)

[rpeng (Richard Peng)]

• Description updated (diff)

[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. It seems like this bug has been addressed in Ruby master thru https://github.com/ruby/ruby/pull/13061 by no longer nilling out objspace->heap_pages.allocatable_slots, which was causing loss of an allocation grant. Would it be possible to backport to 3.4?

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

On 4.0.5
[4.0.5] majors=5 minors=460