Bug #22187
Updated by rpeng (Richard Peng) 3 months ago
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:
``` 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-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
```