From e0f60cb29efac005cec7d65b23934173c72451af Mon Sep 17 00:00:00 2001 From: MSP-Greg Date: Tue, 6 Apr 2021 19:30:56 -0500 Subject: [PATCH 1/4] Add test and benchmark files --- benchmarks/local/chunked_string_times.sh | 155 ++++++ benchmarks/local/socket_times.rb | 49 ++ benchmarks/request_reponse_time_benchmarks.md | 62 +++ benchmarks/wrk/chunked_string_wrk.sh | 103 ++++ benchmarks/wrk/ci_length.sh | 21 + test/helpers/sockets.rb | 462 ++++++++++++++++++ test/rackup/chunked_encoding_csv.ru | 24 + test/rackup/ci_array.ru | 30 ++ test/rackup/ci_chunked.ru | 24 + test/rackup/ci_string.ru | 28 ++ 10 files changed, 958 insertions(+) create mode 100644 benchmarks/local/chunked_string_times.sh create mode 100644 benchmarks/local/socket_times.rb create mode 100644 benchmarks/request_reponse_time_benchmarks.md create mode 100644 benchmarks/wrk/chunked_string_wrk.sh create mode 100644 benchmarks/wrk/ci_length.sh create mode 100644 test/helpers/sockets.rb create mode 100644 test/rackup/chunked_encoding_csv.ru create mode 100644 test/rackup/ci_array.ru create mode 100644 test/rackup/ci_chunked.ru create mode 100644 test/rackup/ci_string.ru diff --git a/benchmarks/local/chunked_string_times.sh b/benchmarks/local/chunked_string_times.sh new file mode 100644 index 0000000000..b31014b6ff --- /dev/null +++ b/benchmarks/local/chunked_string_times.sh @@ -0,0 +1,155 @@ +#!/bin/sh + +# run from Puma directory + +# -l client threads (loops) +# -c connections per client thread +# -r requests per client +# Total connections = l * c * r +# +# -s Puma bind socket type, default ssl, also tcp or unix +# -t Puma threads, default 5:5 +# -w Puma workers, default 2 +# +# example +# benchmarks/local/chunked_string_times.sh -l10 -c100 -r10 -s tcp -t5:5 -w2 +# + +while getopts l:c:r:s:b:t:w: option +do +case "${option}" +in +l) loops=${OPTARG};; +c) connections=${OPTARG};; +r) req_per_client=${OPTARG};; +s) skt_type=${OPTARG};; +b) body_kb=${OPTARG};; +t) threads=${OPTARG};; +w) workers=${OPTARG};; +esac +done + +if test -z "$loops" ; then + loops=10 +fi + +if test -z "$connections"; then + connections=200 +fi + +if test -z "$req_per_client"; then + req_per_client=1 +fi + +if test -z "$skt_type"; then + skt_type=ssl +fi + +if test -z "$threads"; then + threads=5:5 +fi + +if test -z "$workers"; then + workers=2 +fi + +case $skt_type in + ssl) + bind="ssl://127.0.0.1:40010?cert=examples/puma/cert_puma.pem&key=examples/puma/puma_keypair.pem&verify_mode=none" + curl_str=https://127.0.0.1:40010 + ;; + tcp) + bind=tcp://127.0.0.1:40010 + curl_str=http://127.0.0.1:40010 + ;; + unix) + bind=unix://$HOME/skt.unix + curl_str="--unix-socket $HOME/skt.unix http:/n" + ;; +esac + +conf="" + +bundle exec ruby -Ilib bin/puma -q -b $bind -t$threads -w$workers $conf --control-url=tcp://127.0.0.1:40001 --control-token=test test/rackup/ci_chunked.ru & +sleep 5s + +echo "\n══════════════════════════════════════════════════════════════════════════ Chunked Body" +printf "%7d 1kB Body ── curl test\n" $(curl -kso /dev/null -w '%{size_download}' -H 'Len: 1' $curl_str) +printf "%7d 10kB Body\n" $(curl -kso /dev/null -w '%{size_download}' -H 'Len: 10' $curl_str) +printf "%7d 100kB Body\n" $(curl -kso /dev/null -w '%{size_download}' -H 'Len: 100' $curl_str) +printf "%7d 2050kB Body\n" $(curl -kso /dev/null -w '%{size_download}' -H 'Len: 2050' $curl_str) + +# show headers +# curl -kvo /dev/null -H 'Len: 1' $curl_str + +echo "\n──────────────────────────────────────────────────────────────────────────── 1kB Body" +ruby ./benchmarks/local/socket_times.rb $loops $connections $req_per_client $skt_type 1 + +echo "\n──────────────────────────────────────────────────────────────────────────── 10kB Body" +ruby benchmarks/local/socket_times.rb $loops $connections $req_per_client $skt_type 10 + +echo "\n──────────────────────────────────────────────────────────────────────────── 100kB Body" +ruby benchmarks/local/socket_times.rb $loops $connections $req_per_client $skt_type 100 + +echo "\n─────────────────────────────────────────────────────────────────────────── 2050kB Body" +ruby benchmarks/local/socket_times.rb 10 15 2 $skt_type 2050 + +echo "\n" +bundle exec ruby -Ilib bin/pumactl -C tcp://127.0.0.1:40001 -T test stop +sleep 3s + +echo "\n" + +bundle exec ruby -Ilib bin/puma -q -b $bind -t$threads -w$workers $conf --control-url=tcp://127.0.0.1:40001 --control-token=test test/rackup/ci_array.ru & +sleep 5s +echo "\n══════════════════════════════════════════════════════════════════════════ Array Body" +printf "%7d 1kB Body ── curl test\n" $(curl -kso /dev/null -w '%{size_download}' -H 'Len: 1' $curl_str) +printf "%7d 10kB Body\n" $(curl -kso /dev/null -w '%{size_download}' -H 'Len: 10' $curl_str) +printf "%7d 100kB Body\n" $(curl -kso /dev/null -w '%{size_download}' -H 'Len: 100' $curl_str) +printf "%7d 2050kB Body\n" $(curl -kso /dev/null -w '%{size_download}' -H 'Len: 2050' $curl_str) + +# show headers +# curl -kvo /dev/null -H 'Len: 1' $curl_str + +echo "\n──────────────────────────────────────────────────────────────────────────── 1kB Body" +ruby ./benchmarks/local/socket_times.rb $loops $connections $req_per_client $skt_type 1 + +echo "\n──────────────────────────────────────────────────────────────────────────── 10kB Body" +ruby benchmarks/local/socket_times.rb $loops $connections $req_per_client $skt_type 10 + +echo "\n──────────────────────────────────────────────────────────────────────────── 100kB Body" +ruby benchmarks/local/socket_times.rb $loops $connections $req_per_client $skt_type 100 + +echo "\n─────────────────────────────────────────────────────────────────────────── 2050kB Body" +ruby benchmarks/local/socket_times.rb 10 15 2 $skt_type 2050 + +echo "\n" +bundle exec ruby -Ilib bin/pumactl -C tcp://127.0.0.1:40001 -T test stop +sleep 3s + +echo "\n" + +bundle exec ruby -Ilib bin/puma -q -b $bind -t$threads -w$workers $conf --control-url=tcp://127.0.0.1:40001 --control-token=test test/rackup/ci_string.ru & +sleep 5s + +echo "\n═══════════════════════════════════════════════════════════════════════════ String Body" +printf "%7d 1kB Body ── curl test\n" $(curl -kso /dev/null -w '%{size_download}' -H 'Len: 1' $curl_str) +printf "%7d 10kB Body\n" $(curl -kso /dev/null -w '%{size_download}' -H 'Len: 10' $curl_str) +printf "%7d 100kB Body\n" $(curl -kso /dev/null -w '%{size_download}' -H 'Len: 100' $curl_str) +printf "%7d 2050kB Body\n" $(curl -kso /dev/null -w '%{size_download}' -H 'Len: 2050' $curl_str) + +echo "\n──────────────────────────────────────────────────────────────────────────── 1kB Body" +ruby benchmarks/local/socket_times.rb $loops $connections $req_per_client $skt_type 1 + +echo "\n──────────────────────────────────────────────────────────────────────────── 10kB Body" +ruby benchmarks/local/socket_times.rb $loops $connections $req_per_client $skt_type 10 + +echo "\n──────────────────────────────────────────────────────────────────────────── 100kB Body" +ruby benchmarks/local/socket_times.rb $loops $connections $req_per_client $skt_type 100 + +echo "\n─────────────────────────────────────────────────────────────────────────── 2050kB Body" +ruby benchmarks/local/socket_times.rb 10 15 2 $skt_type 2050 + +echo "\n" +bundle exec ruby -Ilib bin/pumactl -C tcp://127.0.0.1:40001 -T test stop +sleep 3 diff --git a/benchmarks/local/socket_times.rb b/benchmarks/local/socket_times.rb new file mode 100644 index 0000000000..fd20812ece --- /dev/null +++ b/benchmarks/local/socket_times.rb @@ -0,0 +1,49 @@ +# frozen_string_literal: true + +require_relative '../../test/helpers/sockets' + +module TestPuma + class TestClients + + include TestPuma::Sockets + + def run + thread_loops = ARGV[0].to_i + thread_connections = ARGV[1].to_i + req_per_client = ARGV[2].to_i + @bind_type = ARGV[3].to_sym + body_kb = ARGV[4].to_i + + @ios_to_close = [] + + case @bind_type + when :ssl, :tcp + @bind_port = 40010 + when :unix + @bind_path = "#{Dir.home}/skt.unix" + else + exit 1 + end + + client_dly = 0.000_01 + thread_dly = client_dly/thread_loops.to_f + + replies = {} + t_st = Process.clock_gettime Process::CLOCK_MONOTONIC + client_threads = create_clients replies, thread_loops, thread_connections, + dly_thread: thread_dly, dly_client: client_dly, body_kb: body_kb, req_per_client: req_per_client + + client_threads.each(&:join) + ttl_time = Process.clock_gettime(Process::CLOCK_MONOTONIC) - t_st + + rps = replies[:times].length/ttl_time + info = format("%4dkB Response Body, Total Time %5.2f, RPS %d", body_kb, ttl_time, rps) + puts info, time_info(thread_loops, thread_connections, replies[:times], req_per_client) + + unless replies[:times].length == thread_loops * thread_connections * req_per_client + puts '', msg_from_replies(replies) + end + end + end +end +TestPuma::TestClients.new.run diff --git a/benchmarks/request_reponse_time_benchmarks.md b/benchmarks/request_reponse_time_benchmarks.md new file mode 100644 index 0000000000..7ca2b1cdff --- /dev/null +++ b/benchmarks/request_reponse_time_benchmarks.md @@ -0,0 +1,62 @@ +## Request and Response Metrics - Response Size, Requests per Second, Client Response Time + +Files included in Puma allow benchmarking request/response time or 'requests per seconds'. This explains some tests that can be done with varied body size, along with chunked and string bodies. + +Two rackup files are included that allow changes to the response from test scripts. They are `test/rackup/ci_string.ru` and `test/rackup/ci_chunked.ru`. Both include 25 headers that total approx 1.6kB. Their bodies can be varied in 1kB increments. Both bodies start with the PID of the worker/process on the first line, the next line is 'Hello World'. `ci_string.ru` adds another line if a 'DLY' header is set in the request. + +After that, both files allow the additional body string to be set by either `ENV['CI_TEST_KB']` or a 'LEN' request header. The value adds 1KB increments. `ci_string.ru` adds the bytes to the single body string, `ci_chunked.ru` uses 'LEN' for the enumeration counter that returns a 1kB string for each loop. + +Two script are provided, both can be set to test tcp, ssl, or unix sockets (no unix sockets with wrk): + +1. `benchmarks/wrk/chunked_string_wrk.sh` - this script starts Puma using `ci_chunked.ru`, then runs three set of wrk measurements using 1kB, 10kB, and 100kb bodies. It then stops Puma, starts another instance using `ci_string.ru`, and runs the same measurements. Both allow setting the Puma server worker and thread arguments. Each wrk run is set for 20 seconds. An example for use on a quad core system and an OS that supports `fork` is: +``` +benchmarks/wrk/chunked_string_wrk.sh -s tcp -t5:5 -w2 +``` + +2. `benchmarks/local/chunked_string_times.sh` - this script send a predetermined number of client sockets to the server, and summarized the time from client write to the client receiving all of the response body. It makes use of `test/helpers/sockets.rb`, see below for more info on that. It performs a similar set of tests as the above wrk script. An example for use on a quad core system and an OS that supports `fork` is the following, generating 2,000 requests: +``` +benchmarks/local/chunked_string_times.sh -l10 -c100 -r10 -s tcp -t5:5 -w2 +``` + +## `test/helpers/sockets.rb` + +`test/helpers/create_clients` is a CI test helper file, designed to make it simple to set up client connections to Puma. It works with two other files that create Puma servers, using either IO.popen or an in-process `Puma::Server`. Some of the code is used to create individual clients. The main method used in `chunked_string_times.sh` is the `create_clients` method, which creates a large number of client connections and reports timing and error information. Simplified code for it is as follows: + +```ruby +client_threads = [] + +threads.times do |thread| + client_threads << Thread.new do + < adjustable delay > + clients_per_thread.times do + req_per_client.times do |req_idx| + begin + < create socket > if req_idx.zero? + < socket write request > + rescue # multiple + < collect open/write error data > + end + begin + < socket read response > + < log timing > + rescue # multiple + < collect read error data > + end + < adjustable delay > + end + end + end +end + +< optional server action - restart, shutdown > + +client_threads.each(&:join) +``` + +## General (~ off topic) + +`create_clients` can generate enough clients to see 10,000 requests per second in a two worker server (using a response body of 10kB or less). One can also set the counts high enough to check memory leaks, etc. + +Note that there is some 'warm-up' time, so it's best to generate enough connections for the run to last at least one second. Normally, increasing the 'clients per thread' (or `-c`) is best. + +On a good day (uninterrupted), good, experienced coders can identify race, deadlock, threading, and other issues by inspection. On bad days, having a test/benchmark system that can generate a high volume of client requests is helpful. `sockets.rb`, along with its companion server files, makes it easy to reconfigure bind protocols, puma server/cli setup, client request setup, etc. \ No newline at end of file diff --git a/benchmarks/wrk/chunked_string_wrk.sh b/benchmarks/wrk/chunked_string_wrk.sh new file mode 100644 index 0000000000..fb87362c7a --- /dev/null +++ b/benchmarks/wrk/chunked_string_wrk.sh @@ -0,0 +1,103 @@ +#!/bin/sh + +# run from Puma directory + +# -s Puma bind socket type, default ssl, also tcp or unix +# -t Puma threads, default 5:5 +# -w Puma workers, default 2 +# +# Test uses 4 curl connections for workers 0 or 1, and 8 curl connections for +# workers two or more. + +# example +# benchmarks/wrk/chunked_string_wrk.sh -s tcp -t5:5 -w2 +# + +while getopts s:t:w: option +do +case "${option}" +in +s) skt_type=${OPTARG};; +t) threads=${OPTARG};; +w) workers=${OPTARG};; +esac +done + +if test -z "$skt_type"; then + skt_type=ssl +fi + +if test -z "$threads"; then + threads=5:5 +fi + +if test -z "$workers"; then + workers=2 +fi + +if [ $workers -gt 1 ]; then + wrk_c=8 +else + wrk_c=4 +fi + +wrk_t=2 + +case $skt_type in + ssl) + bind="ssl://127.0.0.1:40010?cert=examples/puma/cert_puma.pem&key=examples/puma/puma_keypair.pem&verify_mode=none" + wrk_url=https://127.0.0.1:40010 + ;; + tcp) + bind=tcp://127.0.0.1:40010 + wrk_url=http://127.0.0.1:40010 + ;; + unix) + bind=unix://$HOME/skt.unix + echo UNIXSockets unvailable with wrk + exit + ;; +esac + +conf="" +echo bundle exec ruby -Ilib bin/puma -q -b $bind -t$threads -w$workers $conf --control-url=tcp://127.0.0.1:40001 --control-token=test test/rackup/ci_chunked.ru +bundle exec ruby -Ilib bin/puma -q -b $bind -t$threads -w$workers $conf --control-url=tcp://127.0.0.1:40001 --control-token=test test/rackup/ci_chunked.ru & +sleep 5s + +echo "\n══════════════════════════════════════════════════════════════════════════ Chunked Body" + +echo "\n──────────────────────────────────────────────────────────────────────────── 1kB Body" +wrk -c $wrk_c -t $wrk_t -d 20 --latency -H 'Len: 1' $wrk_url + +echo "\n──────────────────────────────────────────────────────────────────────────── 10kB Body" +wrk -c $wrk_c -t $wrk_t -d 20 --latency -H 'Len: 10' $wrk_url + +echo "\n──────────────────────────────────────────────────────────────────────────── 100kB Body" +wrk -c $wrk_c -t $wrk_t -d 20 --latency -H 'Len: 100' $wrk_url + +echo "\n" +bundle exec ruby -Ilib bin/pumactl -C tcp://127.0.0.1:40001 -T test stop +sleep 3s + +echo "\n" +bundle exec ruby -Ilib bin/puma -q -b $bind -t$threads -w$workers $conf --control-url=tcp://127.0.0.1:40001 --control-token=test test/rackup/ci_string.ru & + +sleep 5s + +echo "\n═══════════════════════════════════════════════════════════════════════════ String Body" + +echo "\n──────────────────────────────────────────────────────────────────────────── 1kB Body" +wrk -c $wrk_c -t $wrk_t -d 20 --latency $wr_url -H 'Len: 1' $wrk_url + +echo "\n──────────────────────────────────────────────────────────────────────────── 10kB Body" +wrk -c $wrk_c -t $wrk_t -d 20 --latency $wr_url -H 'Len: 10' $wrk_url + +echo "\n──────────────────────────────────────────────────────────────────────────── 100kB Body" +wrk -c $wrk_c -t $wrk_t -d 20 --latency $wr_url -H 'Len: 100' $wrk_url + +echo "\n" +bundle exec ruby -Ilib bin/pumactl -C tcp://127.0.0.1:40001 -T test stop +sleep 3 + +# echo "\n──────────────────────────────────────────────────────────────────────────── netstat -ant" +# netstat -ant diff --git a/benchmarks/wrk/ci_length.sh b/benchmarks/wrk/ci_length.sh new file mode 100644 index 0000000000..9c35c69c39 --- /dev/null +++ b/benchmarks/wrk/ci_length.sh @@ -0,0 +1,21 @@ +# You are encouraged to use @ioquatix's wrk fork, +# located here: https://github.com/ioquatix/wrk + +# two args, 1st is ru file, 2nd is length when used with ci_chunked.ru or +# ci_string.ru, defaults to 10 in the ru files +# Examples +# benchmarks/wrk/ci_length.sh ci_chunked.ru 100 chunked 100 kb body +# benchmarks/wrk/ci_length.sh ci_string.ru 10 string 10 kb body + +ru="test/rackup/$1" + +if [ -n "$2" ]; then +export CI_TEST_KB="$2" +fi + +bundle exec bin/puma -t 4 $ru & +PID1=$! +sleep 5 +wrk -c 4 -d 30 --latency http://localhost:9292 + +kill $PID1 diff --git a/test/helpers/sockets.rb b/test/helpers/sockets.rb new file mode 100644 index 0000000000..878b3788f0 --- /dev/null +++ b/test/helpers/sockets.rb @@ -0,0 +1,462 @@ +# frozen_string_literal: true + +require 'socket' +require 'timeout' + +module TestPuma + + READ_TIMEOUT = 10 + + module SktPrepend + attr_reader :close_connection + + def get_body(path = nil, dly: nil, len: nil, timeout: 10) + fast_write get_req(path, dly: dly, len: len) + read_body timeout + end + + def get_response(path = nil, dly: nil, len: nil, timeout: 10) + fast_write get_req(path, dly: dly, len: len) + read_response timeout + end + + def read_body(timeout = 10) + response = read_response timeout + hdrs, body = response.split "\r\n\r\n" + @close_connection = hdrs.include? "\nConnection: close" + body + end + + def read_response(timeout = 10) + content_length = nil + chunked = nil + read_len = 65_536 + response = ''.dup + t_st = Process.clock_gettime(Process::CLOCK_MONOTONIC) + loop do + begin + chunk = read_nonblock(read_len, exception: false) + case chunk + when String + unless content_length + chunked ||= chunk.include? "\r\nTransfer-Encoding: chunked\r\n" + content_length = (t = chunk[/Content-Length: (\d+)/i , 1]) ? t.to_i : nil + end + + response << chunk + ary = response.split("\r\n\r\n", 2) + if content_length + if ary.last.bytesize == content_length + # STDOUT.puts "#{ary.last.bytesize} content length" + return response + end + elsif chunked + # STDOUT.puts "#{ary.last.bytesize} chunked" + if ary.last.end_with? "\r\n0\r\n\r\n" + # STDOUT.puts "#{ary.last.bytesize} chunked" + return response + end + elsif ary.length == 2 + return response + end + when :wait_readable, :wait_writable # :wait_writable for ssl + when nil + raise EOFError + end + sleep 0.0002 + if timeout < Process.clock_gettime(Process::CLOCK_MONOTONIC) - t_st + raise Timeout::Error, 'Client Read Timeout' + end + end + end + end + + def get(path = nil, dly: nil, len: nil) + fast_write get_req(path, dly: dly, len: len) + end + + def write(str) + fast_write str + end + + def <<(str) + fast_write str + end + + def fast_write(str) + n = 0 + + while true + begin + n = syswrite str + rescue Errno::EAGAIN, Errno::EWOULDBLOCK => e + raise e unless IO.select(nil, [io], nil, 5) + retry + rescue Errno::EPIPE, SystemCallError, IOError => e + raise e + end + + return if n == str.bytesize + str = str.byteslice(n..-1) + end + end + + private + + def get_req(path = nil, dly: nil, len: nil) + req = "GET /#{path} HTTP/1.1\r\n".dup + req << "Dly: #{dly}\r\n" if dly + req << "Len: #{len}\r\n" if len + req << "\r\n" + end + end + + class SktTCP < ::TCPSocket + prepend SktPrepend + end + + if Object.const_defined? :UNIXSocket + class SktUnix < ::UNIXSocket + prepend SktPrepend + end + end + + if !Object.const_defined?(:Puma) || Puma.ssl? + require 'openssl' + class SktSSL < ::OpenSSL::SSL::SSLSocket + prepend SktPrepend + end + end + + module Sockets + + IS_JRUBY = Object.const_defined? :JRUBY_VERSION + + IS_OSX = RUBY_PLATFORM.include? 'darwin' + + IS_WINDOWS = !!(RUBY_PLATFORM =~ /mswin|ming|cygwin/ || + IS_JRUBY && RUBY_DESCRIPTION.include?('mswin')) + + IS_MRI = (RUBY_ENGINE == 'ruby' || RUBY_ENGINE.nil?) + + HOST = TestPuma.const_defined?(:SvrBase) ? SvrBase::HOST : '127.0.0.1' + + # OpenSSL::SSL::SSLError is intermittently raised on SSL connect? + # IOError is intermittent on all platforms (except maybe Windows), seems + # to be only be raised on SSL connect? + # macOS sometimes raises Errno::EBADF for socket init error + # + OPEN_WRITE_ERRORS = begin + ary = [Errno::ECONNREFUSED, Errno::ECONNRESET, Errno::ENOENT, + Errno::EPIPE, Errno::EBADF, IOError] + ary << Errno::ENOTCONN if IS_OSX + ary << OpenSSL::SSL::SSLError if Object.const_defined?(:OpenSSL) + + ary.freeze + end + + + def fast_connect_get_body(path = nil, dly: nil, len: nil, timeout: READ_TIMEOUT) + fast_connect_get(path, dly: dly, len: len).read_body timeout + end + + def fast_connect_get_response(path = nil, dly: nil, len: nil, timeout: READ_TIMEOUT) + fast_connect_get(path, dly: dly, len: len).read_response timeout + end + + # use only if all socket writes are fast + # does not wait for a read + def fast_connect_get(path = nil, dly: nil, len: nil) + req = "GET /#{path} HTTP/1.1\r\n".dup + req << "Dly: #{dly}\r\n" if dly + req << "Len: #{len}\r\n" if len + req << "\r\n" + fast_connect_raw req + end + + # Use to send a raw string, keyword parameters are the same as `fast_connect`. + # + def fast_connect_raw(str = nil, type: nil, p: nil) + s = fast_connect type: type, p: p + s.fast_write str + s + end + + # Used to open a socket. Normally, the connection info is supplied by calling `bind_type`, + # but that can be set manually if needed for control sockets, etc. + # @param type: [Symbol] the type of connection, eg, :tcp, :ssl, :aunix, :unix + # @param p: [String, Integer] the port or path of the connection + # + def fast_connect(type: nil, p: nil) + _bind_type = type || @bind_type + _bind_port = p || @bind_port + + skt = + case _bind_type + when :ssl + ctx = ::OpenSSL::SSL::SSLContext.new.tap { |c| + c.verify_mode = ::OpenSSL::SSL::VERIFY_NONE + c.session_cache_mode = ::OpenSSL::SSL::SSLContext::SESSION_CACHE_OFF + } + if RUBY_VERSION < '2.3' + old_verbose, $VERBOSE = $VERBOSE, nil + end + temp = SktSSL.new(SktTCP.new(HOST, _bind_port), ctx).tap { |s| + s.sync_close = true + s.connect + } + $VERBOSE = old_verbose if RUBY_VERSION < '2.3' + temp + when :tcp + SktTCP.new HOST, _bind_port + when :aunix, :unix + path = p || @bind_path + SktUnix.new path.sub(/\A@/, "\0") + end + @ios_to_close << skt + skt + end + + # Creates a stream of client sockets + # + # The response body must contain 'Hello World' on a line. + # + # ### Write Errors + # * Ubuntu & macOS + # * tcp: Errno::ECONNREFUSED + # * unix: Errno::EPIPE, Errno::ENOENT + # + # rubocop:disable Metrics/ParameterLists + def create_clients(replies, threads, clients_per_thread, + dly_thread: 0.005, dly_client: 0.005, dly_app: nil, + body_kb: 10, keep_alive: false, req_per_client: 1, resp_timeout: 10) + + # set all the replies keys + %i[refused_write refused reset restart restart_count + success timeout bad_response].each { |k| replies[k] = 0 } + + replies[:pids] = Hash.new 0 + replies[:pids_first] = Hash.new + replies[:refused_errs_write] = Hash.new 0 + replies[:refused_errs_read] = Hash.new 0 + replies[:times] = [] + + use_reqs = false + if req_per_client > 1 + replies[:reqs_good_wr] = Array.new req_per_client, 0 + replies[:reqs_good_rd] = Array.new req_per_client, 0 + use_reqs = true + end + + client_threads = [] + refused_errors = thread_run_refused + + mutex_w = Mutex.new + mutex_r_ok = Mutex.new + mutex_r_bad = Mutex.new + + threads.times do |thread| + client_threads << Thread.new do + sleep(dly_thread * thread) if dly_thread + clients_per_thread.times do + socket = nil + open_write_err = false + req_per_client.times do |req_idx| + time_st = Process.clock_gettime Process::CLOCK_MONOTONIC + begin + if req_idx.zero? + socket = fast_connect_get dly: dly_app, len: body_kb + else + socket.get dly: dly_app, len: body_kb + end + replies[:reqs_good_wr][req_idx] += 1 if use_reqs + rescue *OPEN_WRITE_ERRORS => e + # unix Errno::ENOENT, darwin - Errno::ECONNRESET + mutex_w.synchronize { + replies[:refused_errs_write][e.class.to_s] += 1 + replies[:refused_write] += 1 + } + open_write_err = true if req_per_client > 1 + else + begin + body = socket.read_body resp_timeout + time_end = Process.clock_gettime Process::CLOCK_MONOTONIC + if body =~ /^Hello World$/ + mutex_r_ok.synchronize { + body_pid = body[/\A\d+/].to_i + replies[:success] += 1 + replies[:pids][body_pid] += 1 + replies[:times] << 1000 * (time_end - time_st) + unless replies[:pids_first].key? body_pid + replies[:pids_first][body_pid] = replies[:success] + end + if replies[:phase0_pids] + replies[:restart] += 1 unless replies[:phase0_pids].include?(body_pid) + else + replies[:restart] += 1 if replies[:restart_count] > 0 + end + replies[:reqs_good_rd][req_idx] += 1 if use_reqs + } + break if socket.close_connection + else + mutex_r_bad.synchronize { replies[:bad_response] += 1 } + end + rescue Errno::ECONNRESET + # connection was accepted but then closed + # client would see an empty response + mutex_r_bad.synchronize { replies[:reset] += 1 } + rescue *refused_errors, IOError => e + if e.is_a?(IOError) && Thread.current.respond_to?(:purge_interrupt_queue) + Thread.current.purge_interrupt_queue + end + mutex_r_bad.synchronize { + replies[:refused_errs_read][e.class.to_s] += 1 + replies[:refused] += 1 + } + rescue ::Timeout::Error + mutex_r_bad.synchronize { replies[:timeout] += 1 } + end + ensure + # SSLSocket is not an IO + if !keep_alive && (req_idx + 1 == req_per_client) && + socket && socket.to_io.is_a?(IO) && !socket.closed? + begin + if @bind_type == :ssl + socket.sysclose + else + socket.close + end + rescue Errno::EBADF + end + end + end + sleep dly_client if dly_client + break if open_write_err + end + end + end + end + client_threads + end + + def msg_from_replies(replies) + colors = { + red: "\e[31;1m", + green: "\e[32;1m", + yellow: "\e[33;1m", + blue: "\e[34;1m", + magenta: "\e[35;1m", + cyan: "\e[36;1m" + } + reset = "\e[0m" + + msg = ''.dup + + c = -> (str, key, clr) { + t = replies.fetch(key,0) + unless t.zero? + msg << "#{colors[clr]} %4d #{str}#{reset}\n" % t + end + } + + c.call('read bad response', :bad_response , :red) + c.call('read refused*' , :refused , :red) + c.call('read reset' , :reset , :red) + c.call('read timeout' , :timeout , :red) + c.call('write refused*' , :refused_write, :yellow) + c.call('success' , :success , :green) + + if replies[:restart_count] > 0 + msg << " %4d success after restart\n" % replies.fetch(:restart,0) + msg << " %4d restart count\n" % replies[:restart_count] + if replies[:pids].keys.length > 1 + pid_idx = replies[:pids_first].to_a.sort_by { |a| -a[1] } + msg << " %4d response pids\n" % replies[:pids].keys.length + msg << " %4d index of first request in last 'pid'\n" % pid_idx.first[1] + end + end + + unless replies[:refused_errs_write].empty? + msg << ' write refused errors - ' + msg << replies[:refused_errs_write].map { |k,v| + format "%2d %s", v, k }.join(', ') + msg << "\n" + end + + unless replies[:refused_errs_read].empty? + msg << ' read refused errors - ' + msg << replies[:refused_errs_read].map { |k,v| + format "%2d %s", v, k }.join(', ') + msg << "\n" + end + + if replies[:reqs_good_wr] + msg << "\nRequests by Number\n Total" + replies[:reqs_good_wr].length.times { |idx| msg << " \u2500\u2500 #{idx + 1}".rjust(6) } + msg << "\nwrite %4d" % replies[:reqs_good_wr].reduce(:+) + replies[:reqs_good_wr].each { |i| msg << " %4d" % i } + msg << "\n read %4d" % replies[:reqs_good_rd].reduce(:+) + replies[:reqs_good_rd].each { |i| msg << " %4d" % i } + msg << "\n\n" + end + msg + end + + # Generates the request/response time distribution string + # + def time_info(threads, clients_per_thread, time_ary, req_per_client = 1) + good_requests = time_ary.length + total_requests = threads * clients_per_thread * req_per_client + + rpc = req_per_client == 1 ? '1 request per client' : + "#{req_per_client} requests per client" + + str = "(#{threads} loops of #{clients_per_thread} clients * #{rpc})" + + ret = ''.dup + + if total_requests == good_requests + ret << "#{time_ary.length} successful requests #{str} - total request time\n" + else + ret << "#{time_ary.length} successful requests #{str} - total request time, BAD REQUESTS #{total_requests - good_requests}\n" + end + + return "#{ret}\nNeed at least 20 good requests for timing, only have #{good_requests}" if good_requests < 20 + + idxs = [] + fmt_vals = '%2s'.dup + hdr = ' '.dup + v = [' mS'] + + time_ary.sort! + + time_max = time_ary.last + digits = time_max < 100 ? 3 : (time_max < 1000 ? 2 : 1) + + [0.05, 0.1, 0.2, 0.4, 0.5, 0.6, 0.8, 0.9, 0.95].each { |n| + idxs << (good_requests * n).ceil + + fmt_vals << " %6.#{digits}f" + hdr << format(' %6s', "#{(100*n).to_i}% ") + } + hdr << "\n" + + idxs.each { |i| v << ((time_ary[i] + time_ary[i-1])/2).round(digits) } + + ret << "#{hdr}#{format fmt_vals, *v}\n" + ret + end + + # used to define correct 'refused' errors + def thread_run_refused + if @bind_type == :unix + ary = [Errno::EBADF, Errno::ENOENT] + else + ary = IS_OSX ? [Errno::EBADF, Errno::ECONNREFUSED, Errno::EPIPE, EOFError] : + [Errno::EBADF, Errno::ECONNREFUSED] # intermittent Errno::EBADF with ssl? + end + ary << Errno::ECONNABORTED if IS_WINDOWS + ary.freeze + end + end +end diff --git a/test/rackup/chunked_encoding_csv.ru b/test/rackup/chunked_encoding_csv.ru new file mode 100644 index 0000000000..f66ed86f22 --- /dev/null +++ b/test/rackup/chunked_encoding_csv.ru @@ -0,0 +1,24 @@ +# this can used to test from a browser +# bundle exec bin/puma -t 4 test/rackup/chunked_encoding_csv.ru +# open localhost:9292 in browser, with Edge & Excel on Windows, the file opens + +require 'csv' + +BYTE_ORDER_MARK = "\377\376".force_encoding Encoding::UTF_16LE +CSV_OPTIONS = { col_sep: "\t", force_quotes: false }.freeze + +run lambda { |env| + hdrs = {} + hdrs['Content-Type'] = 'text/csv; charset=utf-16le' + hdrs['Content-Disposition'] = 'attachment; filename="file.csv"' + + csv_body = Enumerator.new do |yielder| + yielder << BYTE_ORDER_MARK + ['A,B,C,D', "1,2,3,иї_テスト"].each do |entry| + yielder << CSV.generate_line(entry.split(','), **CSV_OPTIONS).encode(Encoding::UTF_16LE) + end + yielder << "\nHello World\n".encode(Encoding::UTF_16LE) + end + + [200, hdrs, csv_body] +} diff --git a/test/rackup/ci_array.ru b/test/rackup/ci_array.ru new file mode 100644 index 0000000000..3c1c71212a --- /dev/null +++ b/test/rackup/ci_array.ru @@ -0,0 +1,30 @@ +require 'securerandom' + +# ~10k response is default + +env_len = ENV['CI_TEST_KB'] ? ENV['CI_TEST_KB'].to_i : nil + +long_header_hash = {} + +25.times { |i| long_header_hash["X-My-Header-#{i}"] = SecureRandom.hex(25) } +long_header_hash['Content-Type'] = 'text/plain; charset=utf-8' + +run lambda { |env| + resp = "#{Process.pid}\nHello World\n".dup + + if (dly = env['HTTP_DLY']) + sleep dly.to_f + resp << "Slept #{dly}\n" + end + + # length = 1018 bytesize = 1024 + str_1kb = "──#{SecureRandom.hex 507}─\n" + + len = (env['HTTP_LEN'] || env_len || 10).to_i + + ary = Array.new len+1, str_1kb + ary[0] = resp + + long_header_hash['Content-Length'] = (resp.bytesize + 1024*len).to_s + [200, long_header_hash.dup, ary] +} diff --git a/test/rackup/ci_chunked.ru b/test/rackup/ci_chunked.ru new file mode 100644 index 0000000000..c95901394a --- /dev/null +++ b/test/rackup/ci_chunked.ru @@ -0,0 +1,24 @@ +require 'securerandom' + +env_len = ENV['CI_TEST_KB'] ? ENV['CI_TEST_KB'].to_i : nil + +long_header_hash = {} +long_header_hash['Content-Type'] = 'text; charset=utf-8' + +25.times { |i| long_header_hash["X-My-Header-#{i}"] = SecureRandom.hex(25) } + +run lambda { |env| + # length = 1018 bytesize = 1024 + str_1kb = "──#{SecureRandom.hex 507}─\n" + + len = (env['HTTP_LEN'] || env_len || 10).to_i + + body = Enumerator.new do |yielder| + yielder << "#{Process.pid}\nHello World\n" + len.times do |entry| + yielder << str_1kb + end + end + + [200, long_header_hash.dup, body] +} diff --git a/test/rackup/ci_string.ru b/test/rackup/ci_string.ru new file mode 100644 index 0000000000..a97ffc5df4 --- /dev/null +++ b/test/rackup/ci_string.ru @@ -0,0 +1,28 @@ +require 'securerandom' + +# ~10k response is default + +env_len = ENV['CI_TEST_KB'] ? ENV['CI_TEST_KB'].to_i : nil + +long_header_hash = {} + +25.times { |i| long_header_hash["X-My-Header-#{i}"] = SecureRandom.hex(25) } +long_header_hash['Content-Type'] = 'text/plain; charset=utf-8' + +run lambda { |env| + resp = "#{Process.pid}\nHello World\n".dup + + if (dly = env['HTTP_DLY']) + sleep dly.to_f + resp << "Slept #{dly}\n" + end + + # length = 1018 bytesize = 1024 + str_1kb = "──#{SecureRandom.hex 507}─\n" + + len = (env['HTTP_LEN'] || env_len || 10).to_i + + resp << (str_1kb * len) + long_header_hash['Content-Length'] = resp.bytesize.to_s + [200, long_header_hash.dup, [resp]] +} From 67bbaa70034a4706ad4377975be4455965aa7019 Mon Sep 17 00:00:00 2001 From: MSP-Greg Date: Thu, 8 Apr 2021 22:22:49 -0500 Subject: [PATCH 2/4] request.rb - update fast_writes for chunked and/or enum bodies, use write_nonblock Co-authored-by: Calvin Xiao --- lib/puma/request.rb | 115 +++++++++++++++++++++++++++----------------- 1 file changed, 71 insertions(+), 44 deletions(-) diff --git a/lib/puma/request.rb b/lib/puma/request.rb index 66c9884cca..fbcf975fa2 100644 --- a/lib/puma/request.rb +++ b/lib/puma/request.rb @@ -1,5 +1,7 @@ # frozen_string_literal: true +require 'stringio' + module Puma # The methods here are included in Server, but are separated into this file. @@ -12,6 +14,8 @@ module Puma # module Request + BUFFER_LENGTH = 128 * 1024 + include Puma::Const # Takes the request contained in +client+, invokes the Rack application to construct @@ -50,7 +54,7 @@ def handle_request(client, lines) head = env[REQUEST_METHOD] == HEAD env[RACK_INPUT] = body - env[RACK_URL_SCHEME] = default_server_port(env) == PORT_443 ? HTTPS : HTTP + env[RACK_URL_SCHEME] ||= default_server_port(env) == PORT_443 ? HTTPS : HTTP if @early_hints env[EARLY_HINTS] = lambda { |headers| @@ -108,7 +112,7 @@ def handle_request(client, lines) nil end - cork_socket io +# cork_socket io str_headers(env, status, headers, res_info, lines) @@ -123,7 +127,7 @@ def handle_request(client, lines) end lines << LINE_END - fast_write io, lines.to_s + fast_write io, lines.read return res_info[:keep_alive] end @@ -137,36 +141,17 @@ def handle_request(client, lines) lines << line_ending - fast_write io, lines.to_s - if response_hijack + fast_write io, lines.read response_hijack.call io return :async end - begin - res_body.each do |part| - next if part.bytesize.zero? - if chunked - fast_write io, (part.bytesize.to_s(16) << line_ending) - fast_write io, part # part may have different encoding - fast_write io, line_ending - else - fast_write io, part - end - io.flush - end - - if chunked - fast_write io, CLOSE_CHUNKED - io.flush - end - rescue SystemCallError, IOError - raise ConnectionError, "Connection error detected during write" - end + fast_write_body io, res_body, lines, chunked ensure - uncork_socket io +# uncork_socket io + io.flush body.close client.tempfile.unlink if client.tempfile @@ -189,39 +174,73 @@ def default_server_port(env) end end - # Writes to an io (normally Client#io) using #syswrite - # @param io [#syswrite] the io to write to + # Used to write 'early hints', 'no body' responses, 'hijacked' responses, + # and body segments (called by `fast_write_ary`). + # Writes a string to an io (normally `Client#io`) using `write_nonblock`. + # Large strings may not be written in one pass, especially if `io` is a + # `MiniSSL::Socket`. + # @param io [#write_nonblock] the io to write to # @param str [String] the string written to the io # @raise [ConnectionError] # def fast_write(io, str) n = 0 - while true + byte_size = str.bytesize + while n < byte_size begin - n = io.syswrite str - rescue Errno::EAGAIN, Errno::EWOULDBLOCK - if !IO.select(nil, [io], nil, WRITE_TIMEOUT) + n += io.write_nonblock(n == 0 ? str : str.byteslice(n..-1)) + rescue IO::WaitWritable, Errno::EINTR + unless IO.select(nil, [io], nil, WRITE_TIMEOUT) raise ConnectionError, "Socket timeout writing data" end - retry rescue Errno::EPIPE, SystemCallError, IOError raise ConnectionError, "Socket timeout writing data" end - - return if n == str.bytesize - str = str.byteslice(n..-1) end end - private :fast_write - # @param status [Integer] status from the app - # @return [String] the text description from Puma::HTTP_STATUS_CODES + # Used to write headers and body. + # Writes to an io (normally `Client#io`) using `#fast_write`. + # Accumulates `body` items into `strm`, then writes anytime `strm` is 128kB + # or larger. + # @param io [#write] the io to write to + # @param body [Enumerable, File] the body object + # @param strm [Puma::IOBuffer] strm to write body body into + # @param chunk [Boolean] + # @raise [ConnectionError] # - def fetch_status_code(status) - HTTP_STATUS_CODES.fetch(status) { 'CUSTOM' } + def fast_write_body(io, body, strm, chunked) + running_len = 0 + if body.is_a? ::File + while part = body.read(BUFFER_LENGTH) + if chunked + strm.append part.bytesize.to_s(16), LINE_END, part, LINE_END + fast_write io, strm.read + else + fast_write io, part + end + end + fast_write(io, CLOSE_CHUNKED) if chunked + else + body.each do |part| + next if (byte_size = part.bytesize).zero? + running_len += byte_size + if running_len > BUFFER_LENGTH && byte_size != running_len + fast_write io, strm.read + running_len = 0 + end + if chunked + strm.append byte_size.to_s(16), LINE_END, part, LINE_END + else + strm.append part + end + end + fast_write io, (chunked ? (strm << CLOSE_CHUNKED).read : strm.read) + end end - private :fetch_status_code + + private :fast_write, :fast_write_body # Given a Hash +env+ for the request read from +client+, add # and fixup keys to comply with Rack's env guidelines. @@ -357,6 +376,14 @@ def str_early_hints(headers) end private :str_early_hints + # @param status [Integer] status from the app + # @return [String] the text description from Puma::HTTP_STATUS_CODES + # + def fetch_status_code(status) + HTTP_STATUS_CODES.fetch status, 'CUSTOM' + end + private :fetch_status_code + # Processes and write headers to the IOBuffer. # @param env [Hash] see Puma::Client#env, from request # @param status [Integer] the status returned by the Rack application @@ -372,7 +399,7 @@ def str_headers(env, status, headers, res_info, lines) http_11 = env[HTTP_VERSION] == HTTP_11 if http_11 res_info[:allow_chunked] = true - res_info[:keep_alive] = env.fetch(HTTP_CONNECTION, "").downcase != CLOSE + res_info[:keep_alive] = env.fetch(HTTP_CONNECTION, '').downcase != CLOSE # An optimization. The most common response is 200, so we can # reply with the proper 200 status without having to compute @@ -388,7 +415,7 @@ def str_headers(env, status, headers, res_info, lines) end else res_info[:allow_chunked] = false - res_info[:keep_alive] = env.fetch(HTTP_CONNECTION, "").downcase == KEEP_ALIVE + res_info[:keep_alive] = env.fetch(HTTP_CONNECTION, '').downcase == KEEP_ALIVE # Same optimization as above for HTTP/1.1 # From 7dd2d76fee1cd22105cb412dd3c431acb6b93101 Mon Sep 17 00:00:00 2001 From: MSP-Greg Date: Thu, 8 Apr 2021 22:23:14 -0500 Subject: [PATCH 3/4] io_buffer.rb - use StringIO instead of String --- lib/puma/io_buffer.rb | 34 ++++++++++++++++++++++++++++++---- 1 file changed, 30 insertions(+), 4 deletions(-) diff --git a/lib/puma/io_buffer.rb b/lib/puma/io_buffer.rb index 48146719c3..4b150e5999 100644 --- a/lib/puma/io_buffer.rb +++ b/lib/puma/io_buffer.rb @@ -1,11 +1,37 @@ # frozen_string_literal: true +require 'stringio' + module Puma - class IOBuffer < String - def append(*args) - args.each { |a| concat(a) } + class IOBuffer < StringIO + def initialize + super.binmode + end + + def empty? + length.zero? + end + + def reset + truncate 0 + rewind end - alias reset clear + def read + rewind + super.tap { |s| truncate 0; rewind } + end + + # don't use, added just for existing CI tests + alias_method :to_s, :string + + # before Ruby 2.5, `write` would only take one argument + if RUBY_VERSION >= '2.5' && RUBY_ENGINE != 'truffleruby' + alias_method :append, :write + else + def append(*strs) + strs.each { |str| write str } + end + end end end From 58664f849d6e9404cca69cf3dd4f28a6442955f4 Mon Sep 17 00:00:00 2001 From: MSP-Greg Date: Thu, 8 Apr 2021 22:23:39 -0500 Subject: [PATCH 4/4] minissl.rb - allow chaining with '<<', improve/simplify write --- lib/puma/minissl.rb | 46 +++++++++++++++++++++++++++------------------ 1 file changed, 28 insertions(+), 18 deletions(-) diff --git a/lib/puma/minissl.rb b/lib/puma/minissl.rb index 64534872fb..fc93ce8582 100644 --- a/lib/puma/minissl.rb +++ b/lib/puma/minissl.rb @@ -21,6 +21,7 @@ class Socket def initialize(socket, engine) @socket = socket @engine = engine + @buffer = Puma::IOBuffer.new @peercert = nil end @@ -114,31 +115,40 @@ def read_nonblock(size, *_) end end + # When returning a large response body (2MB), Ubuntu works fine with + # `syswrite`, but macOS & Windows have OpenSSL errors on the client. + # def write(data) return 0 if data.empty? - - data_size = data.bytesize - need = data_size - - while true - wrote = @engine.write data - - enc_wr = ''.dup - while (enc = @engine.extract) - enc_wr << enc + write_size = 128 * 1024 + ttl = 0 + running = 0 + byte_size = data.bytesize + enc_wr = @buffer + enc = nil + + while ttl < byte_size + inc = @engine.write(ttl.zero? ? data : data.byteslice(ttl..-1)) + running += inc + ttl += inc + enc_wr.write(enc) while (enc = @engine.extract) + + if running > write_size + @socket.write enc_wr.read + running = 0 end - @socket.write enc_wr unless enc_wr.empty? - - need -= wrote - - return data_size if need == 0 - - data = data.byteslice(wrote..-1) end + @socket.write(enc_wr.read) unless enc_wr.empty? + enc.clear unless enc.nil? + byte_size end alias_method :syswrite, :write - alias_method :<<, :write + + def <<(data) + write data + self + end # This is a temporary fix to deal with websockets code using # write_nonblock.