[ruby-core:112878] [Ruby master Bug#19412] Socket starts queueing and not responding after a certain amount of requests
From:
"brodock (Gabriel Mazetto) via ruby-core" <ruby-core@...>
Date:
2023-03-14 18:33:44 UTC
List:
ruby-core #112878
Issue #19412 has been updated by brodock (Gabriel Mazetto).
ruby -v set to ruby 3.2.1 (2023-02-08 revision 31819e82c8) [arm64-darwin22]
@jeremyevans0
running apache benchmark with `-c1` does show some of the behavior. It will go from 0 to somethign around 16000 in 4 seconds and get stuck there, see a 3x run log:
```
ab -n 20000 -c 1 http://127.0.0.1:8080/
This is ApacheBench, Version 2.3 <$Revision: 1901567 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking 127.0.0.1 (be patient)
Completed 2000 requests
Completed 4000 requests
Completed 6000 requests
Completed 8000 requests
Completed 10000 requests
Completed 12000 requests
Completed 14000 requests
Completed 16000 requests
apr_socket_recv: Operation timed out (60)
Total of 16346 requests completed
```
```
ab -n 20000 -c 1 http://127.0.0.1:8080/
This is ApacheBench, Version 2.3 <$Revision: 1901567 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking 127.0.0.1 (be patient)
Completed 2000 requests
Completed 4000 requests
Completed 6000 requests
Completed 8000 requests
Completed 10000 requests
Completed 12000 requests
Completed 14000 requests
Completed 16000 requests
apr_socket_recv: Operation timed out (60)
Total of 16347 requests completed
```
```
ab -n 20000 -c 1 http://127.0.0.1:8080/
This is ApacheBench, Version 2.3 <$Revision: 1901567 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking 127.0.0.1 (be patient)
Completed 2000 requests
Completed 4000 requests
Completed 6000 requests
Completed 8000 requests
Completed 10000 requests
Completed 12000 requests
Completed 14000 requests
Completed 16000 requests
apr_socket_recv: Operation timed out (60)
Total of 16349 requests completed
```
I've also run a version of your client and got to reproduce the error (with similar output):
```ruby
require 'socket'
PORT = 8080
LISTEN = '127.0.0.1'
NTIMES = 20000
NTIMES.times do |t|
socket = TCPSocket.new(LISTEN, PORT)
socket.write("HTTP/1.1 GET /\n")
socket.shutdown(Socket::SHUT_WR)
socket.read
puts "Completed #{t} requests" if t > 0 && t % (NTIMES / 10) == 0
rescue Exception => e
puts "Total of #{t-1} requests completed"
raise e
ensure
socket&.close
end
```
```
ruby --version
Could not locate Gemfile or .bundle/ directory
ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [arm64-darwin21]
ruby client.rb
Could not locate Gemfile or .bundle/ directory
Completed 2000 requests
Completed 4000 requests
Completed 6000 requests
Completed 8000 requests
Completed 10000 requests
Completed 12000 requests
Completed 14000 requests
Completed 16000 requests
Total of 16344 requests completed
client.rb:8:in `initialize': Operation timed out - connect(2) for "127.0.0.1" port 8080 (Errno::ETIMEDOUT)
from client.rb:8:in `new'
from client.rb:8:in `block in <main>'
from client.rb:7:in `times'
from client.rb:7:in `<main>'
```
and with ruby 3.2.1:
```
rvm use 3.2.1
Using /Users/brodock/.rvm/gems/ruby-3.2.1
ruby --version
Could not locate Gemfile or .bundle/ directory
ruby 3.2.1 (2023-02-08 revision 31819e82c8) [arm64-darwin22]
ruby client.rb
Could not locate Gemfile or .bundle/ directory
Completed 2000 requests
Completed 4000 requests
Completed 6000 requests
Completed 8000 requests
Completed 10000 requests
Completed 12000 requests
Completed 14000 requests
Completed 16000 requests
Total of 16342 requests completed
client.rb:8:in `initialize': connect(2) for "127.0.0.1" port 8080 (IO::TimeoutError)
from client.rb:8:in `new'
from client.rb:8:in `block in <main>'
from client.rb:7:in `times'
from client.rb:7:in `<main>'
```
----------------------------------------
Bug #19412: Socket starts queueing and not responding after a certain amount of requests
https://bugs.ruby-lang.org/issues/19412#change-102394
* Author: brodock (Gabriel Mazetto)
* Status: Open
* Priority: Normal
* ruby -v: ruby 3.2.1 (2023-02-08 revision 31819e82c8) [arm64-darwin22]
* Backport: 2.7: UNKNOWN, 3.0: UNKNOWN, 3.1: UNKNOWN, 3.2: UNKNOWN
----------------------------------------
Here is a an example code:
```
require 'socket'
PORT = 8080
BACKLOG = 50
LISTEN = '127.0.0.1'
def handle_connection(connection, _addrinfo)
request = connection.gets
puts request
connection.write "HTTP/1.1 200\r\n"
connection.write "Content-Type: text/html\r\n"
connection.write "\r\n"
connection.write "Hello world! Current time is #{Time.now}"
ensure
connection.close
end
begin
socket = Socket.new(:INET, :STREAM)
socket.bind(Addrinfo.tcp(LISTEN, PORT))
socket.listen(BACKLOG)
puts "Requested queue size: #{BACKLOG} bigger then limit: #{Socket::SOMAXCONN}" if BACKLOG > Socket::SOMAXCONN
loop do
listening, = IO.select([socket])
io, = listening
connection, addrinfo = io.accept
handle_connection(connection, addrinfo)
end
ensure
socket.close
end
```
This tries to simulate a TCP server that responds as if it was an HTTP server.
The amount of requests it can sustain seems to depend on the OS. On a Linux machine running ubuntu 20.04 I get something around 7.6K to 7.8K until it stops responding.
```
$ uname -a
Linux ... 5.17.5-x86_64-linode154 #1 SMP PREEMPT Mon May 2 15:07:22 EDT 2022 x86_64 x86_64 x86_64 GNU/Linux
$ ab -n 20000 -c 50 http://127.0.0.1:8080/
This is ApacheBench, Version 2.3 <$Revision: 1843412 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking 127.0.0.1 (be patient)
Completed 2000 requests
Completed 4000 requests
Completed 6000 requests
apr_pollset_poll: The timeout specified has expired (70007)
Total of 7883 requests completed
```
on MacOS Ventura I get around 16K:
```
$ uname -a
Darwin ... 22.2.0 Darwin Kernel Version 22.2.0: Fri Nov 11 02:04:44 PST 2022; root:xnu-8792.61.2~4/RELEASE_ARM64_T8103 arm64
$ ab -n 20000 -c 50 http://127.0.0.1:8080/
This is ApacheBench, Version 2.3 <$Revision: 1901567 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking 127.0.0.1 (be patient)
Completed 2000 requests
Completed 4000 requests
Completed 6000 requests
Completed 8000 requests
Completed 10000 requests
Completed 12000 requests
Completed 14000 requests
Completed 16000 requests
apr_socket_recv: Operation timed out (60)
Total of 16375 requests completed
```
in both cases when that limit reaches, if I abort the program (CTRL-C) and try to run it again it takes a while until the port is released:
```
...
GET / HTTP/1.0
GET / HTTP/1.0
GET / HTTP/1.0
^Csocketserver.rb:29:in `select': Interrupt
from socketserver.rb:29:in `block in <main>'
from socketserver.rb:28:in `loop'
from socketserver.rb:28:in `<main>'
$ ruby socketserver.rb
socketserver.rb:23:in `bind': Address already in use - bind(2) for 127.0.0.1:8080 (Errno::EADDRINUSE)
from socketserver.rb:23:in `<main>'
```
After killing the process it seems no process is holding the port:
```
lsof -wni tcp:8080
```
Running the command above does not return anything (it does when the program is still running).
I think we may be failing to release something when interacting with the Socket on syscalls/kernel level and we endup filling up some queue/buffer that eventually gets freed.
--
https://bugs.ruby-lang.org/
______________________________________________
ruby-core mailing list -- ruby-core@ml.ruby-lang.org
To unsubscribe send an email to ruby-core-leave@ml.ruby-lang.org
ruby-core info -- https://ml.ruby-lang.org/mailman3/postorius/lists/ruby-core.ml.ruby-lang.org/