本記事の検証は環境によって異なる結果になる場合がありますので、本記事の検証結果をそのまま鵜呑みにしないでください。実運用環境と同等の環境で検証されることをお勧めします。
はじめに
スローHTTPアタックは、サーバーのリソースを枯渇させ、サービスを停止させるDoS攻撃の一種です。本記事では、Docker環境に構築したWebサーバー、アプリケーションサーバーに対してスローHTTPアタックを行い、サーバーリソースがどのように変化するのかを検証します。また、各サーバーのタイムアウト値などの設定も検証します。
スローHTTPアタックの概要
まずはスローHTTPアタックの仕組みを簡単に説明します。スローHTTPアタックはアプリケーション層（L7）のDoS攻撃です。
良く知られているICMP FloodやSYN Floodは大量のパケットやトラフィックを送りつけてサーバーをパンクさせるL3/L4のDoS攻撃ですが、スローHTTPアタックはHTTPプロトコルの正常な挙動を悪用してより少ない総帯域幅で攻撃を行いサーバーのリソースを枯渇させます。
よくある攻撃手法として以下の３つが挙げられます。
1. Slowloris攻撃
攻撃者はHTTPリクエストヘッダーの送信を開始しますが、故意に改行コードを送信せず、リクエストを未完了の状態に保ちます。
そして、サーバーが接続を切断しないよう、数秒おきに不要なヘッダーを送信し続けます。
これによりサーバーは接続を維持するためのスレッドやプロセスを解放することができなくなり、攻撃者が多数の接続を同時に確立するとサーバーのリソースは枯渇し、新しい接続を受け付けられなくなります。
2. Slow HTTP POST攻撃 / RUDY (R-U-Dead-Yet?)攻撃
攻撃者は有効なリクエストヘッダーを送信し、リクエストボディの送信を開始しますが、非常に小さなチャンクに分割し、ゆっくりと送信します。
リクエストボディの送信が完了するまでサーバーは接続を維持するためのスレッドやプロセスを解放することができなくなり、攻撃者が多数の接続を同時に確立するとサーバーのリソースは枯渇し、新しい接続を受け付けられなくなります。
3. Slow Read攻撃
攻撃者はサーバーに通常のHTTPリクエストを送信し、サーバーはリクエストを正常に処理してレスポンスを生成します。
サーバーがレスポンスをクライアントに送信し始めると攻撃者はTCPの受信ウィンドウサイズを非常に小さく保ち、かつレスポンスを少しずつしか読み取らないようにします。
サーバーはレスポンスの送信を完了するまで接続を維持し、送信バッファにレスポンスを保持し続けます。これにより、サーバープロセスやメモリリソースが解放されず、他の正規の接続を処理できなくなります。
スローHTTPアタックの検証
今回は以下のWebサーバー、APサーバーに対してSlow HTTP POST攻撃を行い、サーバーのリソースの変化を観察します。
- Apache HTTP Server 2.4.65 (httpd:2.4.65-alpine3.22)
- nginx 1.29.1 (nginx:1.29.1-alpine3.22-slim)
- Caddy 2.10.2 (caddy:2.10.2-alpine)
- Apache Tomcat 11.0.11 (tomcat:jdk21-temurin-noble)
- Node.js 24.8.0 (node:24.8.0-alpine3.22)
- Gunicorn 23.0.0 (python:3.11-slim)
- Puma 7.1.0 (ruby:3.4-alpine)
筆者はPythonとRubyをWeb開発で使用した経験がないためGunicornとPumaは全く詳しくありません。軽く触れる程度なので予めご了承ください。
クラウドサーバー上に構築したDocker環境に上記サーバーをデプロイして検証を行います。クラウドサーバーの情報は以下の通りです。
- Service Provider: Hetzner Cloud
- Location: Hillsboro, Oregon (USA)
- CPU: 3vCPU・AMD
- RAM: 4GB
- OS: Ubuntu 24.04.3 LTS
- Kernel: 6.8.0-86-generic
- Docker: 27.5.1, build 9f9e405（Hetzner Cloud Appsで提供されているDocker CEを使用）
スローHTTPリクエストのシミュレーションは以下のようなcurlコマンドでContent-Lengthヘッダーにリクエストボディより大きいサイズを設定する方法で行います。厳密にはスローHTTPリクエストではありませんが、簡易的な検証には使い勝手が良いため今回は専用のツールは使いません。必要に応じてSlowHTTPTestなどをご利用ください。
# リクエストボディ5バイトに対してContent-Lengthヘッダーを1バイト多いバイト数に設定し、同時並行でリクエストを送信する
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
Apache HTTP Server
以下の構成で検証を行います。
クライアント 
Apache HTTP Server PHP-FPM（PHP/8.4.13）
検証には以下のスクリプトを使用します。
<?php
$data = file_get_contents("php://input");
// コンテナログを出力
error_log("Length:" . ($data === false ? "false" : strlen($data)));
echo "Hello, {$data}!";
今回PHP-FPMの設定はワーカープロセスの最大数を5に設定しています。
[www]
pm = dynamic
pm.max_children = 5
pm.start_servers = 2
pm.min_spare_servers = 1
pm.max_spare_servers = 3
まずは通常のリクエストを送信してみます。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 200 OK
Date: Fri, 26 Sep 2025 02:27:24 GMT
Server: Apache/2.4.65 (Unix)
X-Powered-By: PHP/8.4.13
Transfer-Encoding: chunked
Content-Type: text/html; charset=UTF-8
Hello, qiita!
real 0m0.341s
user 0m0.004s
sys 0m0.012s
続いてスローHTTPリクエストを送信すると20秒ほどでリクエストがタイムアウトし、408 Request Timeoutのエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 408 Request Timeout
Date: Fri, 26 Sep 2025 02:26:17 GMT
Server: Apache/2.4.65 (Unix)
Content-Length: 221
Connection: close
Content-Type: text/html; charset=iso-8859-1
[...]
real 0m20.379s
user 0m0.006s
sys 0m0.018s
PHP-FPMコンテナのログを確認するとスローHTTPリクエストは入力ストリームが空になっています。
# 通常のリクエストのログ
NOTICE: PHP message: Length:5
# スローHTTPリクエストのログ
NOTICE: PHP message: Length:0
リクエスト時にPHP-FPMコンテナ上でtcpdumpを実行して通信を確認してみると、POSTデータは受信しているのですが入力ストリームから読み込む際に空になっているようです（POSTデータのサイズが16KB未満だと空で、16KB以上のサイズだと出力されるので何らかのバッファサイズが関係しているのかもしれません）。
$ tcpdump -A port 9000
[...]
06:48:07.159587 IP apache-container.qiita-slow-http_default.55270 > 947ab23e960f.9000: Flags [P.], seq 759:772, ack 1, win 502, options [nop,nop,TS val 1031774595 ecr 224236284], length 13
E..AR @.@..k..........#(. ...q.~....X_.....
=....]..........qiita
[...]
06:48:27.678237 IP 947ab23e960f.9000 > apache-container.qiita-slow-http_default.55270: Flags [P.], seq 1:105, ack 773, win 504, options [nop,nop,TS val 224256802 ecr 1031795113], length 104
E....:@.@...........#(...q.~. ."....X......
.]."=........L..X-Powered-By: PHP/8.4.13
Content-type: text/html; charset=UTF-8
Hello, !.................-st
[...]
20秒ほどでタイムアウトしましたが、この秒数はRequestReadTimeoutのデフォルト値の20秒が適用されています。
RequestReadTimeout handshake=0 header=20-40,MinRate=500 body=20,MinRate=500
bodyの秒数を20秒から30秒に変更して試してみます。
RequestReadTimeout handshake=0 header=20-40,MinRate=500 body=30,MinRate=500
タイムアウトの時間が30秒に変化しました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" http://***.***.***.***/
[...]
real 0m30.397s
user 0m0.004s
sys 0m0.017s
リクエストボディのサイズを少し大きくして200バイトで送信してみます。タイムアウト時間に変化はありません。
$ time curl -X POST -H "Content-Length: 201" -d @200b.txt http://***.***.***.***/
[...]
real 0m30.771s
user 0m0.005s
sys 0m0.024s
今度はボディのMinRateを500バイトから10バイトに変更して試してみます。
RequestReadTimeout handshake=0 header=20-40,MinRate=500 body=30,MinRate=10
10バイト受信するごとにタイムアウト時間が1秒増加するため、200バイトの受信でタイムアウト時間が20秒増加して50秒になりました。
$ time curl -X POST -H "Content-Length: 201" -d @200b.txt http://***.***.***.***/
[...]
real 0m50.372s
user 0m0.006s
sys 0m0.017s
TimeOutをデフォルトの60秒から30秒に変更して同様に送信してみます。
TimeOut 30
RequestReadTimeout handshake=0 header=20-40,MinRate=500 body=30,MinRate=10
TimeOutの設定が優先され50秒から30秒に変化しました。
$ time curl -X POST -H "Content-Length: 201" -d @200b.txt http://***.***.***.***/
[...]
real 0m30.371s
user 0m0.001s
sys 0m0.020s
先のテストでは短時間で一気に送信していましたが、以下のスクリプトを使用して小さいチャンクに分割してゆっくり送信してみます。
#!/bin/bash
HOST="***.***.***.***"
PORT="80"
BODY_SIZE=$1
CHUNK_SIZE=$2
REQUEST_HEADER="POST / HTTP/1.1\r\nHost: $HOST\r\nConnection: close\r\nContent-Type: text/plain\r\nContent-Length: $BODY_SIZE\r\n\r\n"
BODY=$(yes 'a' | tr -d '\n' | head -c $BODY_SIZE)
{
# ヘッダを送信
echo -ne "$REQUEST_HEADER"
# ボディをチャンクに分割して1秒おきに送信
for ((i=0; i<${#BODY}; i+=CHUNK_SIZE)); do
CHUNK="${BODY:$i:$CHUNK_SIZE}"
echo -n "$CHUNK"
sleep 1
done
} | nc $HOST $PORT
先ほどの設定のままでボディサイズ2000バイト、チャンクサイズ20バイトで送信してみます。
TimeOut 30
RequestReadTimeout handshake=0 header=20-40,MinRate=500 body=30,MinRate=10
MinRateを上回る転送量でデータを受信するためタイムアウトせずに2000 ÷ 20 = 100秒で送信が完了しました。
$ time ./slow_http_post.sh 2000 20
HTTP/1.1 200 OK
[...]
7d8
Hello, aaaaaaaaaaaa[...]aaaaaaaa!
0
real 1m42.613s
user 0m0.118s
sys 0m0.333s
RequestReadTimeoutの設定をデフォルトに戻して試してみます。
TimeOut 30
RequestReadTimeout handshake=0 header=20-40,MinRate=500 body=20,MinRate=500
転送量がMinRateの500バイトに達しないためタイムアウト時間が20秒から増加せず、20秒でタイムアウトしました。
$ time ./slow_http_post.sh 2000 20
HTTP/1.1 408 Request Timeout
[...]
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>408 Request Timeout</title>
</head><body>
<h1>Request Timeout</h1>
<p>Server timeout waiting for the HTTP request from the client.</p>
</body></html>
real 0m22.137s
user 0m0.051s
sys 0m0.099s
多重度を上げてサーバーリソースの変化を確認します。まずは小さいサイズのスローHTTPリクエストを多重度300で送信します。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
real 0m24.415s
user 0m0.109s
sys 0m0.285s
ビジー状態のワーカースレッドの数が300近くに上昇し、タイムアウトが発生すると0に戻りました。ビジー状態のワーカースレッドの減少とともにアイドル状態のワーカースレッドが上昇し、250付近で一定になりました。
リクエスト前は3個のワーカープロセスが起動しており、MinSpareThreadsのデフォルト値25 × 3 = 75のワーカースレッドが待機していましたが、リクエストの負荷増加により計10個のワーカープロセスが起動し、10 * 25 = 250のワーカースレッドが待機しているためこのような変化になっています。
リクエストの前後でオープン中のネットワークソケットを確認すると600ほど増加しました（クライアント接続300 + アップストリーム接続300）。
# リクエスト前
$ lsof | grep httpd | grep socket | wc -l
22
# リクエスト直後
$ lsof | grep httpd | grep socket | wc -l
628
スローHTTPリクエスト送信中に通常のPOSTリクエストを送信すると、スローHTTPリクエストによりPHP-FPMのワーカープロセスが占有されているため20秒近くかかりました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" http://***.***.***.***/
Hello, qiita!
real 0m19.136s
user 0m0.005s
sys 0m0.009s
静的なHTMLページの方はPHP-FPMへのアップストリーム接続がないため、遅延せずにレスポンスが返ってきます。
$ time curl -X GET http://***.***.***.***/hello.html
Hello!
real 0m0.338s
user 0m0.007s
sys 0m0.010s
ApacheコンテナのFDの上限を256に変更し、ワーカープロセス数の上限を2、プロセスあたりのスレッド数の上限を200に設定して、多重度300で送信してみます。
$ ulimit -n
256
<IfModule mpm_event_module>
ServerLimit 2
ThreadLimit 200
ThreadsPerChild 200
</IfModule>
スローHTTPリクエストを送信すると直後に503 Service Unavailableや500 Proxy Errorのエラーレスポンスが複数返ってきて、その後タイムアウトのエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 --dump-header - http://***.***.***.***/?[1-300]
HTTP/1.1 503 Service Unavailable
[...]
HTTP/1.1 500 Proxy Error
[...]
HTTP/1.1 408 Request Timeout
[...]
real 0m42.200s
user 0m0.089s
sys 0m0.216s
スローHTTPリクエスト送信中に静的なHTMLページにアクセスすると20秒ほど掛かりました。
$ time curl -X GET http://***.***.***.***/hello.html
Hello!
real 0m20.669s
user 0m0.005s
sys 0m0.024s
リクエスト直後のオープン中のネットワークソケットを確認すると、変更前は600ほどありましたが400にまで減少しています（一つのワーカープロセスがオープンできるファイル数が256に制限されたため）。Apacheの受信キュー（backlog）を確認すると複数の接続がaccept待ちで滞留しています。
$ lsof | grep httpd | grep socket | wc -l
404
$ ss -t state listening
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 4096 127.0.0.11:45861 0.0.0.0:*
30 511 *:http *:*
Apacheが起動できるワーカースレッドの最大数（MaxRequestWorkers）を300にまで減らしてスローHTTPリクエストを多重度300で送信してみます。
<IfModule mpm_event_module>
StartServers 4
MinSpareThreads 25
MaxSpareThreads 50
ThreadsPerChild 50
MaxRequestWorkers 300
MaxConnectionsPerChild 0
</IfModule>
スローHTTPリクエスト送信中に静的なHTMLページにアクセスすると20秒ほど掛かりました。スローHTTPリクエストでApacheのワーカースレッドが占有されてしまい、処理の遅延が発生していることが確認できます。Apacheの受信キューを確認すると1件の接続がaccept待ちで滞留しています。
$ time curl -X GET http://***.***.***.***/hello.html
Hello!
real 0m19.158s
user 0m0.004s
sys 0m0.013s
$ ss -t state listening
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 4096 127.0.0.11:45861 0.0.0.0:*
1 511 *:http *:*
多重度を300からPHP-FPMのワーカープロセスの最大数と同じ5に減らしてスローHTTPリクエストを送信してみます。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 5 http://***.***.***.***/?[1-5]
[...]
real 0m20.035s
user 0m0.000s
sys 0m0.007s
スローHTTPリクエスト送信中に通常のPOSTリクエストを送信してみます。スローHTTPリクエストによってPHP-FPMのワーカープロセスが占有されているため処理が20秒ほどかかりました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" http://***.***.***.***/
Hello, qiita!
real 0m19.266s
user 0m0.004s
sys 0m0.012s
Apacheの受信キューに滞留している接続はありません。
$ ss -t state listening
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 4096 127.0.0.11:45861 0.0.0.0:*
0 511 *:http *:*
PHP-FPMの受信キュー（backlog）を確認すると1件の接続がaccept待ちで滞留しています（公式ドキュメントではデフォルト値は511と記載されていますが、明示的に設定しない場合はnet.core.somaxconnが適用されるようです）。
$ ss -t state listening
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 4096 127.0.0.11:43755 0.0.0.0:*
1 4096 *:9000 *:*
サイズを1MBに変えて多重度5で送信してみます。
$ time curl -X POST -H "Content-Length: 1048577" -d @1mb.txt --parallel --parallel-immediate --parallel-max 5 http://***.***.***.***/?[1-5]
[...]
real 1m4.773s
user 0m0.009s
sys 0m0.091s
スローHTTPリクエスト送信中に通常のPOSTリクエストを送信してみます。RequestReadTimeoutの20秒でタイムアウトすることはありませんが、504 Gateway Timeoutのエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 504 Gateway Timeout
[...]
real 1m0.416s
user 0m0.009s
sys 0m0.010s
PHP-FPMコンテナのログを確認するとデータは受信していることが分かります。
NOTICE: PHP message: Length:5
ProxyTimeoutをデフォルトの60秒から90秒に変更して試すと今度は1分ほどで正常なレスポンスが返ってきました。
ProxyTimeout 90
# ProxyPassやProxyPassMatchのパラメーターとしても指定可能
ProxyPassMatch ^/(.*\.php(/.*)?)$ fcgi://php-fpm:9000/var/www/html/$1 timeout=90
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
[...]
Hello, qiita!
real 1m4.025s
user 0m0.008s
sys 0m0.021s
ProxyTimeoutをデフォルトの60秒に戻して、多重度5の１MBのスローHTTPリクエスト送信中に1MBの通常のリクエストを送信すると小さいサイズと同様に504 Gateway Timeoutのエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 1048576" -d @1mb.txt --dump-header - http://***.***.***.***/
HTTP/1.1 504 Gateway Timeout
[...]
real 1m2.936s
user 0m0.004s
sys 0m0.027s
PHP-FPMコンテナのログを確認するとデータは受信していますがサイズが160KBまでしか受信できていないようです。
NOTICE: PHP message: Length:163840
ログにワーカープロセスのプロセスIDを出力するようにプログラムを修正して再度送信します。
error_log("Length:" . ($data === false ? "false" : strlen($data)) . ' / PID:' . getmypid());
送信中のApacheのコンテナのネットワークソケットの状態を確認してみます。クライアントからの接続のうち受信バッファに未読データが残っている接続が1件確認できます。また、PHP-FPMへの接続のうち送信バッファに確認応答を受信していないデータが残っている接続が1件確認できます。クライアント接続6件、アップストリーム接続6件が確認できます。
$ ss -pt state established
Recv-Q Send-Q Local Address:Port Peer Address:Port Process
0 0 172.18.0.5:43920 172.18.0.2:9000 users:(("httpd",pid=129,fd=12))
0 0 172.18.0.5:43898 172.18.0.2:9000 users:(("httpd",pid=16,fd=15))
0 0 172.18.0.5:43894 172.18.0.2:9000 users:(("httpd",pid=20,fd=12))
0 56200 172.18.0.5:43926 172.18.0.2:9000 users:(("httpd",pid=20,fd=14))
0 0 172.18.0.5:43914 172.18.0.2:9000 users:(("httpd",pid=16,fd=16))
0 0 172.18.0.5:43882 172.18.0.2:9000 users:(("httpd",pid=16,fd=12))
0 0 [::ffff:172.18.0.5]:http [::ffff:***.***.***.***]:58570 users:(("httpd",pid=16,fd=13))
0 0 [::ffff:172.18.0.5]:http [::ffff:***.***.***.***]:58550 users:(("httpd",pid=20,fd=11))
0 0 [::ffff:172.18.0.5]:http [::ffff:***.***.***.***]:58560 users:(("httpd",pid=16,fd=14))
0 0 [::ffff:172.18.0.5]:http [::ffff:***.***.***.***]:58580 users:(("httpd",pid=16,fd=11))
451728 0 [::ffff:172.18.0.5]:http [::ffff:***.***.***.***]:58490 users:(("httpd",pid=20,fd=13))
0 0 [::ffff:172.18.0.5]:http [::ffff:***.***.***.***]:58484 users:(("httpd",pid=129,fd=11))
送信中のPHP-FPMのコンテナのネットワークソケットの状態を確認してみます。Apacheからの接続のうち受信バッファに未読データが残っている接続が1件確認できます。スローHTTPリクエストによってワーカープロセスが占有されているためにacceptされず、受信キューに滞留している接続が1件確認できます。
$ ss -pt state established
Recv-Q Send-Q Local Address:Port Peer Address:Port Process
0 0 [::ffff:172.18.0.2]:9000 [::ffff:172.18.0.5]:43920 users:(("php-fpm",pid=79049,fd=5))
0 0 [::ffff:172.18.0.2]:9000 [::ffff:172.18.0.5]:43898 users:(("php-fpm",pid=79048,fd=5))
0 0 [::ffff:172.18.0.2]:9000 [::ffff:172.18.0.5]:43894 users:(("php-fpm",pid=137,fd=5))
122285 0 [::ffff:172.18.0.2]:9000 [::ffff:172.18.0.5]:43926
0 0 [::ffff:172.18.0.2]:9000 [::ffff:172.18.0.5]:43882 users:(("php-fpm",pid=85,fd=5))
0 0 [::ffff:172.18.0.2]:9000 [::ffff:172.18.0.5]:43914 users:(("php-fpm",pid=136,fd=5))
$ ss -t state listening
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 4096 127.0.0.11:43755 0.0.0.0:*
1 4096 *:9000 *:*
504 Gateway Timeoutが発生した直後のApacheのコンテナのネットワークソケットの状態を確認してみます。受信バッファと送信バッファにデータが残っていた接続が消えました。クライアント接続5件、アップストリーム接続5件が確認できます。
$ ss -pt state established
Recv-Q Send-Q Local Address:Port Peer Address:Port Process
0 0 172.18.0.5:43920 172.18.0.2:9000 users:(("httpd",pid=129,fd=12))
0 0 172.18.0.5:43898 172.18.0.2:9000 users:(("httpd",pid=16,fd=15))
0 0 172.18.0.5:43894 172.18.0.2:9000 users:(("httpd",pid=20,fd=12))
0 0 172.18.0.5:43914 172.18.0.2:9000 users:(("httpd",pid=16,fd=16))
0 0 172.18.0.5:43882 172.18.0.2:9000 users:(("httpd",pid=16,fd=12))
0 0 [::ffff:172.18.0.5]:http [::ffff:***.***.***.***]:58570 users:(("httpd",pid=16,fd=13))
0 0 [::ffff:172.18.0.5]:http [::ffff:***.***.***.***]:58550 users:(("httpd",pid=20,fd=11))
0 0 [::ffff:172.18.0.5]:http [::ffff:***.***.***.***]:58560 users:(("httpd",pid=16,fd=14))
0 0 [::ffff:172.18.0.5]:http [::ffff:***.***.***.***]:58580 users:(("httpd",pid=16,fd=11))
0 0 [::ffff:172.18.0.5]:http [::ffff:***.***.***.***]:58484 users:(("httpd",pid=129,fd=11))
PHP-FPMのコンテナの方は変化がありません。
$ ss -pt state established
Recv-Q Send-Q Local Address:Port Peer Address:Port Process
0 0 [::ffff:172.18.0.2]:9000 [::ffff:172.18.0.5]:43920 users:(("php-fpm",pid=79049,fd=5))
0 0 [::ffff:172.18.0.2]:9000 [::ffff:172.18.0.5]:43898 users:(("php-fpm",pid=79048,fd=5))
0 0 [::ffff:172.18.0.2]:9000 [::ffff:172.18.0.5]:43894 users:(("php-fpm",pid=137,fd=5))
122285 0 [::ffff:172.18.0.2]:9000 [::ffff:172.18.0.5]:43926
0 0 [::ffff:172.18.0.2]:9000 [::ffff:172.18.0.5]:43882 users:(("php-fpm",pid=85,fd=5))
0 0 [::ffff:172.18.0.2]:9000 [::ffff:172.18.0.5]:43914 users:(("php-fpm",pid=136,fd=5))
60秒のタイムアウトの後にPHP-FPMコンテナのログを確認すると以下のようなログが出力されています。プロセスIDが85のワーカープロセスでスローHTTPリクエストが処理された後に、滞留していたリクエストが処理されているようです。
NOTICE: PHP message: Length:1048576 / PID:85
NOTICE: PHP message: Length:163840 / PID:85
NOTICE: PHP message: Length:1048576 / PID:136
NOTICE: PHP message: Length:1048576 / PID:137
NOTICE: PHP message: Length:1048576 / PID:79049
NOTICE: PHP message: Length:1048576 / PID:79048
ApacheのTimeOut（60秒）よりProxyTimeout（60秒）の方がわずかに早く発動したために、PHP-FPMの受信キューに残っていたリクエストがワーカープロセスに処理される時には、Apache側で滞留していたデータがすでに破棄されており、受信していた一部のデータのみ処理されたのではないかと考えられます。
ProxyTimeoutがどのように発動するのか、タイムアウトを30秒に変更して検証してみます。
ProxyTimeout 30
１番目にPHPスクリプトに60秒のsleep処理を追加して通常のPOSTリクエストを送信してみます。30秒で504 Gateway Timeoutのエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 504 Gateway Timeout
[...]
real 0m30.366s
user 0m0.006s
sys 0m0.020s
２番目に1MBのスローリクエストを送信してみます。60秒で408 Request Timeoutのエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 1048577" -d @1mb.txt --dump-header - http://***.***.***.***/
HTTP/1.1 408 Request Timeout
[...]
real 1m2.023s
user 0m0.001s
sys 0m0.033s
３番目にスローHTTPリクエストを多重度5で送信してワーカープロセスを占有した上で、1MBの通常のPOSTリクエストを送信してみます。30秒で504 Gateway Timeoutのエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 1048576" -d @1mb.txt --dump-header - http://***.***.***.***/
HTTP/1.1 504 Gateway Timeout
[...]
real 0m33.502s
user 0m0.010s
sys 0m0.019s
PHP-FPMコンテナのログを確認すると176KBだけ受信しています。
NOTICE: PHP message: Length:180224
４番目にスローHTTPリクエストを多重度5で送信してワーカープロセスを占有した上で、1MBのスローHTTPリクエストを送信してみます。1分半ほどで408 Request Timeoutのエラーレスポンスが返ってきました。加えて504 Gateway Timeoutも発生しているようです。
$ time curl -X POST -H "Content-Length: 1048577" -d @1mb.txt --dump-header - http://***.***.***.***/
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>408 Request Timeout</title>
</head><body>
<h1>Request Timeout</h1>
<p>Server timeout waiting for the HTTP request from the client.</p>
<p>Additionally, a 504 Gateway Timeout
error was encountered while trying to use an ErrorDocument to handle the request.</p>
</body></html>
real 1m32.830s
user 0m0.005s
sys 0m0.043s
PHP-FPMコンテナのログを確認すると160KBだけ受信しています。
NOTICE: PHP message: Length:163840
５番目にスローHTTPリクエストを多重度5で送信してワーカープロセスを占有した上で、10MBを1秒おきに100KBずつ送信してみます。2分半ほどで送信が完了しましたが504 Gateway Timeoutのエラーレスポンスが返ってきました。
$ time ./slow_http_post.sh 10485760 102400
HTTP/1.1 504 Gateway Timeout
[...]
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>504 Gateway Timeout</title>
</head><body>
<h1>Gateway Timeout</h1>
<p>The gateway did not receive a timely response
from the upstream server or application.</p>
</body></html>
real 2m38.596s
user 0m23.206s
sys 0m7.608s
PHP-FPMコンテナのログを確認すると160KBだけ受信しています。
NOTICE: PHP message: Length:163840
１番目はApacheがPHP-FPMからの応答を待っている状態、２番目はApacheがクライアントからの送信を待っている状態、３～５番目はApacheがPHP-FPMへの送信を待っている状態になり、ProxyTimeoutはアップストリーム接続のI/O待ちに対して発動していると考えられます。先のテストで1MBを送信した時にTimeOutとProxyTimeoutが同じ60秒に設定されていてもProxyTimeoutが早く発動したのは、クライアントからのデータを受信している最中にアップストリーム接続の方が若干早くI/O待ちが発生したために、TimeOutよりも先にProxyTimeoutが発動したのではないかと考えられます。
設定を元に戻してリクエストボディのサイズを10MBにしたスローHTTPリクエストをワーカープロセスの最大数と同じ5にして送信してみます（TimeOutの60秒を40秒ほど超過していますが、サーバーが海外にありクライアントからサーバーへの送信に時間が掛かっているためです）。
$ time curl -X POST -H "Content-Length: 10485761" -d @10mb.txt --parallel --parallel-immediate --parallel-max 5 http://***.***.***.***/?[1-5]
[...]
real 1m41.035s
user 0m0.073s
sys 0m0.122s
まずはApacheのメモリ使用量を確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセス（マスター＋ワーカー）のメモリ使用量（RSS）の合計を表しています。受信データをバッファリングせずにPHP-FPMに転送しているためほとんど変化がありません。
PHP-FPMの方も確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセス（マスター＋ワーカー）のメモリ使用量（PSS）の合計を表しています。コンテナのメモリ使用量は受信したデータ量相応の増加が見られます。一方でプロセスのメモリ使用量はほとんど変化がありません。
送信前と送信中でPHP-FPMコンテナのメモリ使用量の詳細を比較してみます。メモリ使用量の詳細はdocker statsのAPIエンドポイントから取得します。
$ curl -s --unix-socket /var/run/docker.sock http://<APIバージョン>/containers/<コンテナのID>/stats?stream=false | jq '.memory_stats'
docker statsのAPIエンドポイントから取得したメモリ使用量の詳細の差分を確認すると、リクエストボディの総量（10MB×5=50MB）とページキャッシュの増加量が一致しています。
$ jq -s '
{
"USAGE (Total)": ((.[1].usage - .[0].usage) / 1048576),
"ANON (Heap/Stack)": ((.[1].stats.anon - .[0].stats.anon) / 1048576),
"FILE (Cache)": ((.[1].stats.file - .[0].stats.file) / 1048576),
"INACTIVE_FILE": ((.[1].stats.inactive_file - .[0].stats.inactive_file) / 1048576),
"FILE_DIRTY": ((.[1].stats.file_dirty - .[0].stats.file_dirty) / 1048576),
"SLAB": ((.[1].stats.slab - .[0].stats.slab) / 1048576)
}
' before.json after.json
{
"USAGE (Total)": 52.671875,
"ANON (Heap/Stack)": 0.609375,
"FILE (Cache)": 50,
"INACTIVE_FILE": 50,
"FILE_DIRTY": 0,
"SLAB": 1.7280654907226562
}
ワーカープロセスがオープンしているファイルを確認すると、tmpディレクトリにリクエストボディをバッファリングしたファイルが作成されています。
$ ls -al /proc/<ワーカープロセスのPID>/fd
total 0
dr-x------ 2 root root 9 Nov 1 06:59 .
dr-xr-xr-x 9 www-data www-data 0 Nov 1 06:57 ..
lrwx------ 1 root root 64 Nov 1 06:59 0 -> /dev/null
l-wx------ 1 root root 64 Nov 1 06:59 1 -> 'pipe:[1842911]'
lrwx------ 1 root root 64 Nov 1 06:59 14 -> 'socket:[1839743]'
l-wx------ 1 root root 64 Nov 1 06:59 2 -> 'pipe:[1842912]'
lrwx------ 1 root root 64 Nov 1 06:59 3 -> '/memfd:opcache_lock (deleted)'
l-wx------ 1 root root 64 Nov 1 06:59 4 -> 'pipe:[1836219]'
lrwx------ 1 root root 64 Nov 1 07:00 5 -> 'socket:[1845853]'
l-wx------ 1 root root 64 Nov 1 06:59 6 -> /dev/null
lrwx------ 1 root root 64 Nov 1 07:00 7 -> /tmp/phpv971h819cts3dthmLk5
$ cut -b 1-100 /tmp/phpv971h819cts3dthmLk5
aaaaaaaaaaaaaaaaaa[...]aaaaaaaaaaaaaaaaa
プロセスのメモリ使用量にほとんど変化がありませんでしたが、ページキャッシュからデータを読み込み$_POSTに展開 ⇒ スクリプトの処理を実行 ⇒ 処理終了後にメモリを解放、というサイクルが一瞬で終わってしまい計測できなかったためです。PHPスクリプトの最後にsleep処理を入れてスクリプト実行中にメモリ使用量の詳細を取得して差分を確認すると、ヒープメモリの使用量が大幅に増加していることが分かります。
$ jq -s '
{
"USAGE (Total)": ((.[1].usage - .[0].usage) / 1048576),
"ANON (Heap/Stack)": ((.[1].stats.anon - .[0].stats.anon) / 1048576),
"FILE (Cache)": ((.[1].stats.file - .[0].stats.file) / 1048576),
"INACTIVE_FILE": ((.[1].stats.inactive_file - .[0].stats.inactive_file) / 1048576),
"FILE_DIRTY": ((.[1].stats.file_dirty - .[0].stats.file_dirty) / 1048576),
"SLAB": ((.[1].stats.slab - .[0].stats.slab) / 1048576)
}
' before.json after.json
{
"USAGE (Total)": 216.46484375,
"ANON (Heap/Stack)": 163.9921875,
"FILE (Cache)": 50,
"INACTIVE_FILE": 50,
"FILE_DIRTY": 0,
"SLAB": 1.7347030639648438
}
php.iniにはenable_post_data_readingというオプションがあり、以下のように記載されています。
このオプションを無効にすると、
$_POSTや$_FILESに値が入らなくなります。 この場合、投稿されたデータを読むには、ストリームラッパー php://input を使う以外の方法はなくなります。 これは、リクエストをプロキシしたり POST データを処理する際のメモリ消費量を抑えたりする際に有用です。
そこで、このオプションを無効にして試してみます。下図の緑色がPHP-FPMコンテナのメモリ使用量、黄色がプロセス（マスター＋ワーカー）のメモリ使用量（PSS）の合計を表しています。無効にする前はプロセスのメモリ使用量の増加は軽微でしたが、今度は大幅に増加しました。
送信中のメモリ使用量の詳細を取得して差分を確認すると、ヒープメモリの使用量が増加しています。オプションが有効になっている時はタイムアウトによる接続の切断をトリガーにPOSTデータがヒープメモリに展開されていましたが、無効にしたことでタイムアウトを待たずに逐次ヒープメモリに展開され、このように計測できる状態として表れています。
$ jq -s '
{
"USAGE (Total)": ((.[1].usage - .[0].usage) / 1048576),
"ANON (Heap/Stack)": ((.[1].stats.anon - .[0].stats.anon) / 1048576),
"FILE (Cache)": ((.[1].stats.file - .[0].stats.file) / 1048576),
"INACTIVE_FILE": ((.[1].stats.inactive_file - .[0].stats.inactive_file) / 1048576),
"FILE_DIRTY": ((.[1].stats.file_dirty - .[0].stats.file_dirty) / 1048576),
"SLAB": ((.[1].stats.slab - .[0].stats.slab) / 1048576)
}
' before.json after.json
{
"USAGE (Total)": 121.734375,
"ANON (Heap/Stack)": 69.2109375,
"FILE (Cache)": 50.00390625,
"INACTIVE_FILE": 50,
"FILE_DIRTY": 0,
"SLAB": 1.8478240966796875
}
設定を元に戻して今度はリクエストボディのサイズを1MBにしたスローHTTPリクエストを多重度50で送信してみます。全ての接続がタイムアウトで完了するまでに２分半ほど掛かりました。
$ time curl -X POST -H "Content-Length: 1048577" -d @1mb.txt --parallel --parallel-immediate --parallel-max 50 http://***.***.***.***/?[1-50]
[...]
real 2m33.284s
user 0m0.254s
sys 0m0.545s
まずはApacheのメモリ使用量を確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセス（マスター＋ワーカー）のメモリ使用量（RSS）の合計を表しています。10MBを多重度5で送信した時はほとんど変化がありませんでしたが、今回は増加が見られます。
送信中のApacheコンテナのネットワークソケットを確認するとキューにデータが残ったままの接続が多数確認できます。
$ ss -nt state established '( dport = 9000 or sport = 80 )'
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 58368 172.18.0.6:42432 172.18.0.2:9000
0 56276 172.18.0.6:50306 172.18.0.2:9000
0 56492 172.18.0.6:41678 172.18.0.2:9000
[...]
94812 0 [::ffff:172.18.0.6]:80 [::ffff:***.***.***.***]:64828
95068 0 [::ffff:172.18.0.6]:80 [::ffff:***.***.***.***]:64271
95968 0 [::ffff:172.18.0.6]:80 [::ffff:***.***.***.***]:64885
[...]
送信前と送信中でApacheコンテナのメモリ使用量の詳細を取得して差分を確認すると、ソケットバッファが増加しています。PHP-FPMのワーカープロセスが5つのため、多重度5の時は受信したデータをすぐに転送できていましたが、多重度50では転送できずに一時的にバッファに滞留していることが分かります。
$ jq -s '
{
"USAGE (Total)": ((.[1].usage - .[0].usage) / 1048576),
"ANON (Heap/Stack)": ((.[1].stats.anon - .[0].stats.anon) / 1048576),
"FILE (Cache)": ((.[1].stats.file - .[0].stats.file) / 1048576),
"INACTIVE_FILE": ((.[1].stats.inactive_file - .[0].stats.inactive_file) / 1048576),
"FILE_DIRTY": ((.[1].stats.file_dirty - .[0].stats.file_dirty) / 1048576),
"SLAB": ((.[1].stats.slab - .[0].stats.slab) / 1048576),
"SOCK": ((.[1].stats.sock - .[0].stats.sock) / 1048576),
}
' before.json after.json
{
"USAGE (Total)": 19.65625,
"ANON (Heap/Stack)": 5.546875,
"FILE (Cache)": 0,
"INACTIVE_FILE": 0,
"FILE_DIRTY": 0,
"SLAB": 1.3747177124023438,
"SOCK": 11.2109375
}
PHP-FPMの方も確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセス（マスター＋ワーカー）のメモリ使用量（PSS）の合計を表しています。メモリ使用量が多少増加していますが、10MBの時と比較すると1件あたりのデータ量が少なくなった関係で増加量も小さくなっています。
10MBを多重度5で送信した時より時間が長く掛かりました。tcpdumpを使ってクライアント・Apache間でどのような通信が行われたのか確認してみます。
接続確立時のパケットを見ると、クライアントが接続した直後からWebサーバーのTCPスタックはクライアントへの受信ウィンドウサイズを500バイト前後まで急激に縮小しています。
08:33:38.860038 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [S], seq 607155229, win 65280, options [...], length 0
08:33:38.860043 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [S.], seq 3394184153, ack 607155230, win 65160, options [...], length 0
08:33:39.021037 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [.], ack 1, win 510, options [...], length 0
08:33:39.021144 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [P.], seq 1:185, ack 1, win 510, options [...], length 184: HTTP: POST /?31 HTTP/1.1
08:33:39.021174 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 185, win 508, options [...], length 0
08:33:39.188411 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [.], seq 185:1413, ack 26, win 510, options [...], length 1228: HTTP
08:33:39.189737 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [P.], seq 1413:2641, ack 26, win 510, options [...], length 1228: HTTP
08:33:39.189843 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 2641, win 489, options [...], length 0
08:33:39.213305 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [P.], seq 2641:5097, ack 26, win 510, options [...], length 2456: HTTP
その後も受信ウィンドウサイズをどんどん縮小していき、ゼロウィンドウでクライアントからの送信が一時的に保留されています。
08:33:53.353058 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 495465, win 35, options [...], length 0
08:33:53.381249 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [P.], seq 495465:497921, ack 26, win 510, options [...], length 2456: HTTP
08:33:53.419481 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [.], seq 497921:499149, ack 26, win 510, options [...], length 1228: HTTP
08:33:53.420461 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [P.], seq 499149:499833, ack 26, win 510, options [...], length 684: HTTP
08:33:53.504052 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 499833, win 1, options [...], length 0
08:33:54.132740 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [P.], seq 499833:499961, ack 26, win 510, options [...], length 128: HTTP
08:33:54.132748 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 499961, win 0, options [...], length 0
08:33:54.736950 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [.], ack 26, win 510, options [...], length 0
08:33:54.736975 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 499961, win 0, options [...], length 0
08:33:55.759228 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [.], ack 26, win 510, options [...], length 0
08:33:55.759243 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 499961, win 0, options [...], length 0
08:33:57.671841 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [.], ack 26, win 510, options [...], length 0
08:33:57.671876 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 499961, win 0, options [...], length 0
08:34:01.423958 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [.], ack 26, win 510, options [...], length 0
08:34:01.423981 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 499961, win 0, options [...], length 0
08:34:08.590809 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [.], ack 26, win 510, options [...], length 0
08:34:08.590876 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 499961, win 0, options [...], length 0
08:34:22.414146 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [.], ack 26, win 510, options [...], length 0
08:34:22.414171 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 499961, win 0, options [...], length 0
08:34:48.922619 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 499961, win 133, options [...], length 0
08:34:48.922801 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 499961, win 345, options [...], length 0
08:34:48.922929 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 499961, win 771, options [...], length 0
ゼロウィンドウから徐々にサイズを拡大していきますが、送信が完了するまでに1分半ほど掛かり、その1分後にタイムアウトが発動して2分半ほど掛かっています。
08:35:06.885173 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 1045213, win 11205, options [...], length 0
08:35:06.928351 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [P.], seq 1045213:1046441, ack 26, win 510, options [...], length 1228: HTTP
08:35:06.928372 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 1046441, win 11227, options [...], length 0
08:35:06.961298 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [.], seq 1046441:1047669, ack 26, win 510, options [...], length 1228: HTTP
08:35:06.961313 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 1047669, win 11250, options [...], length 0
08:35:07.002709 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [P.], seq 1047669:1048761, ack 26, win 510, options [...], length 1092: HTTP
08:35:07.002736 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 1048761, win 11272, options [...], length 0
08:36:07.056601 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [P.], seq 26:535, ack 1048761, win 11272, options [...], length 509: HTTP: HTTP/1.1 408 Request Timeout
08:36:07.056707 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [F.], seq 535, ack 1048761, win 11272, options [...], length 0
08:36:07.218733 IP ***.***.***.***.*****.jp.53780 > d3c1dcbcf40b.80: Flags [F.], seq 1048761, ack 536, win 507, options [...], length 0
08:36:07.218782 IP d3c1dcbcf40b.80 > ***.***.***.***.*****.jp.53780: Flags [.], ack 1048762, win 11272, options [...], length 0
netstatのTCPFromZeroWindowAdvを確認するとゼロウィンドウが発生していたことがカウントされています。
$ cat /proc/net/netstat | \
awk '/^TcpExt:/{
for(i=1; i<=NF; i++) {
if ($i == "TCPFromZeroWindowAdv") {
target_col = i;
getline;
print $target_col;
exit;
}
}
}'
45
nginx
以下の構成で検証を行います。検証スクリプトはApacheの時と同じものを使用します。
クライアント nginx PHP-FPM（PHP/8.4.13）
まずは通常のリクエストを送信してみます。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 200 OK
Server: nginx/1.29.1
Date: Sun, 02 Nov 2025 01:50:03 GMT
Content-Type: text/html; charset=UTF-8
Transfer-Encoding: chunked
Connection: keep-alive
X-Powered-By: PHP/8.4.13
Hello, qiita!
real 0m0.366s
user 0m0.004s
sys 0m0.014s
続いてスローHTTPリクエストを送信すると60秒ほどでリクエストがタイムアウトし、接続がクローズされました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
curl: (52) Empty reply from server
real 1m0.389s
user 0m0.005s
sys 0m0.018s
nginxはリクエストボディをバッファリングし、すべてのデータの受信が完了してからPHP-FPMに転送するため、PHP-FPMコンテナのログを確認してもログは出力されていません。
リクエスト時のネットワークソケットを確認してもPHP-FPMコンテナ（9000番ポート）への接続は確認できません。
$ ss -ntH state established 'dport = 9000' | wc -l
0
60秒ほどでタイムアウトしましたが、この秒数はclient_body_timeoutのデフォルト値の60秒が適用されています。
タイムアウトの秒数を60秒から30秒に変更して試してみます。
client_body_timeout 30s;
タイムアウトの時間が30秒に変化しました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" http://***.***.***.***/
curl: (52) Empty reply from server
real 0m30.370s
user 0m0.004s
sys 0m0.014s
アップストリーム接続のタイムアウト（fastcgi_send_timeout）を30秒に設定して試してみます。
location ~ \.php$ {
fastcgi_send_timeout 30;
fastcgi_pass php-fpm:9000;
[...]
}
PHP-FPMへの転送が発生しないため設定した30秒では接続はクローズされずに、client_body_timeoutの60秒でクローズされました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" http://***.***.***.***/
curl: (52) Empty reply from server
real 1m0.379s
user 0m0.004s
sys 0m0.017s
小さいチャンクに分割してゆっくり送信してみます。300バイトのデータを1秒おきに1バイトずつ送信すると、タイムアウトが発生することなくリクエストが完了しました。
$ time ./slow_http_post.sh 300 1
HTTP/1.1 200 OK
[...]
134
Hello, aaaaaaaaaaaaaaaaaaaa[...]aaaaaaaaaaaaaaaaaaaaaa!
0
real 5m2.460s
user 0m0.411s
sys 0m0.910s
多重度を上げてサーバーリソースの変化を確認します。
nginxのworker_processesはデフォルトの1、worker_connectionsはデフォルトの512の状態で、小さいサイズのスローHTTPリクエストを多重度300で送信します。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
real 1m1.674s
user 0m0.175s
sys 0m0.453s
アクティブ接続数が300近くに上昇し、タイムアウトが発生すると0に戻りました。
リクエストの前後でオープン中のネットワークソケットを確認すると300増加しました（クライアント接続300、アップストリーム接続はなし）。
# リクエスト前
$ su - nginx -s /bin/bash -c "lsof | grep nginx | grep socket | wc -l"
3
# リクエスト直後
$ su - nginx -s /bin/bash -c "lsof | grep nginx | grep socket | wc -l"
303
スローHTTPリクエスト送信中に通常のPOSTリクエストをPHPに送信しても、スローHTTPリクエストはPHP-FPMに転送されておらず、PHP-FPMのワーカープロセスが空いているため遅延せずにレスポンスが返ってきます。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" http://***.***.***.***/
Hello, qiita!
real 0m0.336s
user 0m0.005s
sys 0m0.009s
nginxコンテナのFDの上限を256に変更し、多重度300で送信してみます。
$ ulimit -n
256
スローHTTPリクエストを送信すると1分後に複数の接続がクローズされ、2分後に残りの接続がクローズされました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
[...]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
real 2m0.624s
user 0m0.143s
sys 0m0.372s
スローHTTPリクエスト送信中に通常のPOSTリクエストを送信すると1分ほど掛かりました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" http://***.***.***.***/
Hello, qiita!
real 0m59.493s
user 0m0.008s
sys 0m0.017s
リクエスト直後のオープン中のネットワークソケットを確認すると変更前の300から250に減少しています（一つのワーカープロセスがオープンできるファイル数が256に制限されたため）。nginxの受信キューを確認すると複数の接続がaccept待ちで滞留しています。
$ su - nginx -s /bin/bash -c "lsof | grep nginx | grep socket | wc -l"
248
$ ss -t state listening
Recv-Q Send-Q Local Address:Port Peer Address:Port
56 511 0.0.0.0:http 0.0.0.0:*
0 4096 127.0.0.11:37995 0.0.0.0:*
FDではなくworker_connectionsの数を300に減らしてスローHTTPリクエストを送信してみます。
events {
worker_connections 300;
}
リクエスト直後に複数の接続がクローズされました。worker_connectionsにはネットワーク接続 (ソケット)以外にもログのFDやイベント処理（epoll）で使用されるFDなども含まれ、今回のクライアント接続数が300だったために上限を超過したクライアント接続がクローズされています。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (56) Recv failure: Connection reset by peer
curl: (52) Empty reply from server
curl: (52) Empty reply from server
[...]
スローHTTPリクエスト送信直後に通常のPOSTリクエストを多重度10で送信すると、ほとんどのクライアント接続がリセットされました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --parallel --parallel-immediate --parallel-max 10 http://***.***.***.***/?[1-10]
Hello, qiita!
curl: (52) Empty reply from server
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
Hello, qiita!
real 0m0.365s
user 0m0.011s
sys 0m0.011s
worker_connections以外に接続数を制限する設定としてlimit_conn / limit_conn_zoneがありますのでこちらを試してみます。
PHP-FPMへの接続に対して同時接続数を100に制限します。
http {
[...]
limit_conn_zone $server_name zone=per_server_proxy:1m;
limit_conn_log_level warn;
limit_conn_status 429;
server {
[...]
location / {
limit_conn per_server_proxy 100;
fastcgi_pass php-fpm:9000;
[...]
}
}
}
多重度300で送信するとリクエスト直後に429 Too Many Requestsのエラーレスポンスが多数返ってきました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 --dump-header - http://***.***.***.***/?[1-300]
HTTP/1.1 429 Too Many Requests
Server: nginx/1.29.1
Date: Sun, 12 Oct 2025 11:56:12 GMT
Content-Type: text/html
Content-Length: 169
Connection: keep-alive
[...]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
real 1m0.612s
user 0m0.088s
sys 0m0.312s
アクティブ接続数を確認すると瞬間的に300に上昇しましたが、その後100で一定になりました。
スローHTTPリクエスト送信中に通常のPOSTリクエストを送信すると429 Too Many Requestsのエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 429 Too Many Requests
[...]
real 0m0.343s
user 0m0.006s
sys 0m0.006s
静的なHTMLページにアクセスすると遅延せずにレスポンスが返ってきました（アップストリーム接続が発生しないため影響なし）。
$ time curl -X GET http://***.***.***.***/hello.html
Hello!
real 0m0.343s
user 0m0.001s
sys 0m0.012s
次にリクエストボディのサイズを10MBにしたスローHTTPリクエストをワーカープロセスの最大数と同じ5にして送信してみます。
$ time curl -X POST -H "Content-Length: 10485761" -d @10mb.txt --parallel --parallel-immediate --parallel-max 5 http://***.***.***.***/?[1-5]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
real 1m41.195s
user 0m0.072s
sys 0m0.221s
まずはnginxのメモリ使用量を確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセス（マスター＋ワーカー）のメモリ使用量（RSS）の合計を表しています。コンテナのメモリ使用量は受信したデータ量相応の増加が見られます。一方でプロセスのメモリ使用量はほとんど変化がありません。
docker statsのAPIエンドポイントから取得したメモリ使用量の詳細の差分を確認すると、リクエストボディの総量（10MB×5=50MB）とページキャッシュの増加量が一致しています。
$ jq -s '
{
"USAGE (Total)": ((.[1].usage - .[0].usage) / 1048576),
"ANON (Heap/Stack)": ((.[1].stats.anon - .[0].stats.anon) / 1048576),
"FILE (Cache)": ((.[1].stats.file - .[0].stats.file) / 1048576),
"INACTIVE_FILE": ((.[1].stats.inactive_file - .[0].stats.inactive_file) / 1048576),
"FILE_DIRTY": ((.[1].stats.file_dirty - .[0].stats.file_dirty) / 1048576),
"SLAB": ((.[1].stats.slab - .[0].stats.slab) / 1048576)
}
' before.json after.json
{
"USAGE (Total)": 51.6953125,
"ANON (Heap/Stack)": 0.1953125,
"FILE (Cache)": 50,
"INACTIVE_FILE": 50,
"FILE_DIRTY": 0,
"SLAB": 1.5029830932617188
}
nginxはclient_body_temp_pathに設定されたパスにリクエストボディを一時ファイルとして保存しますので確認してみます。
$ ls /var/cache/nginx/client_temp
ファイルは存在していません。そこで現在nginxのワーカープロセスがオープンしているファイルを確認してみると、一時ファイルはアンリンクされていることが分かります。
$ su - nginx -s /bin/bash -c "ls -al /proc/<ワーカープロセスのPID>/fd"
total 0
dr-x------ 2 nginx nginx 21 Nov 2 12:01 .
dr-xr-xr-x 9 nginx nginx 0 Nov 2 11:41 ..
lrwx------ 1 nginx nginx 64 Nov 2 12:01 0 -> /dev/null
l-wx------ 1 nginx nginx 64 Nov 2 12:01 1 -> pipe:[2921049]
lrwx------ 1 nginx nginx 64 Nov 2 12:01 10 -> anon_inode:[eventfd]
lrwx------ 1 nginx nginx 64 Nov 2 12:01 11 -> socket:[2939537]
lrwx------ 1 nginx nginx 64 Nov 2 12:01 12 -> socket:[2939538]
lrwx------ 1 nginx nginx 64 Nov 2 12:01 13 -> socket:[2939539]
lrwx------ 1 nginx nginx 64 Nov 2 12:01 14 -> socket:[2939540]
lrwx------ 1 nginx nginx 64 Nov 2 12:01 15 -> socket:[2939541]
lrwx------ 1 nginx nginx 64 Nov 2 12:01 16 -> /var/cache/nginx/client_temp/0000000001 (deleted)
lrwx------ 1 nginx nginx 64 Nov 2 12:01 17 -> /var/cache/nginx/client_temp/0000000002 (deleted)
lrwx------ 1 nginx nginx 64 Nov 2 12:01 18 -> /var/cache/nginx/client_temp/0000000003 (deleted)
lrwx------ 1 nginx nginx 64 Nov 2 12:01 19 -> /var/cache/nginx/client_temp/0000000004 (deleted)
l-wx------ 1 nginx nginx 64 Nov 2 12:01 2 -> pipe:[2921050]
lrwx------ 1 nginx nginx 64 Nov 2 12:01 20 -> /var/cache/nginx/client_temp/0000000005 (deleted)
lrwx------ 1 nginx nginx 64 Nov 2 12:01 3 -> socket:[2921307]
[...]
PHP-FPMの方はデータを受信していないため変化はありません。
nginxの設定でfastcgi_request_bufferingをoffにして、データ全体のバッファリングを無効にした状態で同様に10MBのスローHTTPリクエストを送信してみます。
location ~ \.php$ {
fastcgi_request_buffering off;
fastcgi_pass php-fpm:9000;
[...]
}
$ time curl -X POST -H "Content-Length: 10485761" -d @10mb.txt --parallel --parallel-immediate --parallel-max 5 http://***.***.***.***/?[1-5]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
real 1m41.041s
user 0m0.086s
sys 0m0.144s
まずはnginxのメモリ使用量を確認してみます。受信データ全体をバッファリングせずにPHP-FPMに転送しているためほとんど変化はありません。
PHP-FPMの方も確認してみます。下図の緑色がコンテナのメモリ使用量、黄色が黄色がプロセス（マスター＋ワーカー）のメモリ使用量（PSS）の合計を表しています。Apacheの時と同様にコンテナのメモリ使用量は受信したデータ量相応の増加が見られます。
PHP-FPMコンテナのログを確認すると10MBのデータを受信したことが出力されています。
NOTICE: PHP message: Length:10485760
NOTICE: PHP message: Length:10485760
NOTICE: PHP message: Length:10485760
NOTICE: PHP message: Length:10485760
NOTICE: PHP message: Length:10485760
バッファリングを無効にした状態でリクエストボディのサイズを1MBにしたスローHTTPリクエストを多重度50で送信してみます。リクエストからおよそ１分後に多数の接続で504 Gateway Time-outのエラーレスポンスが返ってきて、その後しばらくして残りの接続がクローズされました。
$ time curl -X POST -H "Content-Length: 1048577" -d @1mb.txt --parallel --parallel-immediate --parallel-max 50 --dump-header - http://***.***.***.***/?[1-50]
[...]
HTTP/1.1 504 Gateway Time-out
[...]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
real 2m17.737s
user 0m0.182s
sys 0m0.258s
nginxのメモリ使用量を確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセス（マスター＋ワーカー）のメモリ使用量（RSS）の合計を表しています。プロセスのメモリ使用量はほとんど変化はありませんが、コンテナのメモリ使用量が増加しています。
docker statsのAPIエンドポイントから取得したメモリ使用量の詳細の差分を確認するとソケットバッファが増加しており、PHP-FPMに転送できないために一時的にバッファに滞留していることが分かります。
$ jq -s '
{
"USAGE (Total)": ((.[1].usage - .[0].usage) / 1048576),
"ANON (Heap/Stack)": ((.[1].stats.anon - .[0].stats.anon) / 1048576),
"FILE (Cache)": ((.[1].stats.file - .[0].stats.file) / 1048576),
"INACTIVE_FILE": ((.[1].stats.inactive_file - .[0].stats.inactive_file) / 1048576),
"FILE_DIRTY": ((.[1].stats.file_dirty - .[0].stats.file_dirty) / 1048576),
"SLAB": ((.[1].stats.slab - .[0].stats.slab) / 1048576),
"SOCK": ((.[1].stats.sock - .[0].stats.sock) / 1048576),
}
' before.json after.json
{
"USAGE (Total)": 16.55078125,
"ANON (Heap/Stack)": 1.2890625,
"FILE (Cache)": 0,
"INACTIVE_FILE": 0,
"FILE_DIRTY": 0,
"SLAB": 0.290130615234375,
"SOCK": 14.953125
}
$ ss -nt state established '( dport = 9000 or sport = 80 )'
Recv-Q Send-Q Local Address:Port Peer Address:Port
94192 0 172.18.0.6:80 ***.***.***.***:54769
93708 0 172.18.0.6:80 ***.***.***.***:54792
96980 0 172.18.0.6:80 ***.***.***.***:54600
[...]
0 91392 172.18.0.6:58982 172.18.0.3:9000
0 107600 172.18.0.6:57726 172.18.0.3:9000
0 115968 172.18.0.6:58824 172.18.0.3:9000
0 121296 172.18.0.6:58216 172.18.0.3:9000
PHP-FPMの方はApacheの時とほぼ同じようなメモリ使用量の変化となっています。
PHP-FPMコンテナのログを確認するとApacheの時と同様に一部のデータしか受信できていない接続が多数確認できます。
NOTICE: PHP message: Length:1048576
NOTICE: PHP message: Length:217240
NOTICE: PHP message: Length:247040
NOTICE: PHP message: Length:229376
NOTICE: PHP message: Length:229376
[...]
Apacheと同様に10MBを多重度5で送信した時より時間が長く掛かりました。tcpdumpを使用してクライアント・nginx間でどのような通信が行われたのか確認してみます。
接続確立時のパケットを見ると、クライアントが接続した直後からWebサーバーのTCPスタックはクライアントへの受信ウィンドウサイズを500バイト前後まで急激に縮小しています。これはApacheの時の同様の挙動です。
00:35:08.588957 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [S], seq 602158, win 65280, options [...], length 0
00:35:08.588981 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [S.], seq 2605355932, ack 602159, win 65160, options [...], length 0
00:35:08.775851 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [.], ack 1, win 510, options [...], length 0
00:35:08.775852 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [P.], seq 1:186, ack 1, win 510, options [...], length 185: HTTP: POST /index.php?276 HTTP/1.1
00:35:08.775868 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 186, win 508, options [...], length 0
00:35:09.224525 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [P.], seq 186:2642, ack 26, win 510, options [...], length 2456: HTTP
00:35:09.224546 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 2642, win 547, options [...], length 0
その後も受信ウィンドウサイズをどんどん縮小していき、ゼロウィンドウでクライアントからの送信が一時的に保留されています。ここまではApacheと同様の挙動ですが、クライアントからの送信が停止してから60秒後（fastcgi_send_timeoutのデフォルト値）に504 Gateway Time-outが発動してクライアントにFIN/ACKを送信しています。ApacheではProxyTimeoutが発動した後も、Timeoutが発動するまではクライアントにFIN/ACKを送信しませんでしたが、nginxでは発動と同時に送信するようです。
00:36:00.896071 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 331746, win 11, options [...], length 0
00:36:01.192225 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [.], seq 331746:332974, ack 26, win 510, options [...], length 1228: HTTP
00:36:01.328040 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 332974, win 2, options [...], length 0
00:36:02.478114 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [P.], seq 332974:333230, ack 26, win 510, options [...], length 256: HTTP
00:36:02.478124 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 333230, win 0, options [...], length 0
00:36:03.507246 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [.], ack 26, win 510, options [...], length 0
00:36:03.507255 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 333230, win 0, options [...], length 0
00:36:05.231861 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [.], ack 26, win 510, options [...], length 0
00:36:05.231875 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 333230, win 0, options [...], length 0
00:36:08.595291 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [.], ack 26, win 510, options [...], length 0
00:36:08.595309 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 333230, win 0, options [...], length 0
00:36:14.567237 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [.], ack 26, win 510, options [...], length 0
00:36:14.567255 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 333230, win 0, options [...], length 0
00:36:26.081729 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [.], ack 26, win 510, options [...], length 0
00:36:26.081733 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 333230, win 0, options [...], length 0
00:36:49.120369 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [.], ack 26, win 510, options [...], length 0
00:36:49.120394 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 333230, win 0, options [...], length 0
00:37:02.479160 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [P.], seq 26:355, ack 333230, win 0, options [...], length 329: HTTP: HTTP/1.1 504 Gateway Time-out
00:37:02.479245 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [F.], seq 355, ack 333230, win 0, options [...], length 0
00:37:02.479300 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 333230, win 126, options [...], length 0
00:37:02.479397 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 333230, win 363, options [...], length 0
00:37:02.648254 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [.], ack 355, win 508, options [...], length 0
00:37:02.648330 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [P.], seq 333230:334202, ack 356, win 508, options [...], length 972: HTTP
[...]
00:37:03.823970 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [P.], seq 367358:369814, ack 356, win 508, options [...], length 2456: HTTP
00:37:03.823988 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 369814, win 1110, options [...], length 0
00:37:03.825841 IP ***.***.***.***.*****.jp.57783 > 0896acbe9b4d.80: Flags [FP.], seq 369814:371042, ack 356, win 508, options [...], length 1228: HTTP
00:37:03.825854 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.57783: Flags [.], ack 371043, win 1132, options [...], length 0
バッファリングが有効だった時には発動しなかったfastcgi_send_timeoutを30秒に設定して送信してみます。
location ~ \.php$ {
fastcgi_send_timeout 30s;
fastcgi_request_buffering off;
fastcgi_pass php-fpm:9000;
[...]
}
掛かった時間が１分ほど短くなりました。
$ time curl -X POST -H "Content-Length: 1048577" -d @1mb.txt --parallel --parallel-immediate --parallel-max 50 --dump-header - http://***.***.***.***/?[1-50]
[...]
HTTP/1.1 504 Gateway Time-out
[...]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
real 1m19.323s
user 0m0.134s
sys 0m0.290s
変更前はPHP-FPMのワーカープロセスを占有していた接続がタイムアウトして、待機していた接続が続けて処理されたためにプラス1分掛かっていました。しかし、今回は待機していた接続が全て先にタイムアウトしたために短くなったと考えられます。tcpdumpで確認するとゼロウィンドウで送信が一時的に保留されてから30秒後に504 Gateway Time-outが発動しています。
02:59:04.920037 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.58326: Flags [.], ack 329290, win 11, options [...], length 0
02:59:05.050134 IP ***.***.***.***.*****.jp.58326 > 0896acbe9b4d.80: Flags [.], seq 329290:330518, ack 26, win 510, options [...], length 1228: HTTP
02:59:05.051032 IP ***.***.***.***.*****.jp.58326 > 0896acbe9b4d.80: Flags [P.], seq 330518:330674, ack 26, win 510, options [...], length 156: HTTP
02:59:05.144042 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.58326: Flags [.], ack 330674, win 1, options [...], length 0
02:59:06.126968 IP ***.***.***.***.*****.jp.58326 > 0896acbe9b4d.80: Flags [P.], seq 330674:330802, ack 26, win 510, options [...], length 128: HTTP
02:59:06.312068 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.58326: Flags [.], ack 330802, win 0, options [...], length 0
02:59:07.254508 IP ***.***.***.***.*****.jp.58326 > 0896acbe9b4d.80: Flags [.], ack 26, win 510, options [...], length 0
02:59:07.254520 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.58326: Flags [.], ack 330802, win 0, options [...], length 0
02:59:08.911726 IP ***.***.***.***.*****.jp.58326 > 0896acbe9b4d.80: Flags [.], ack 26, win 510, options [...], length 0
02:59:08.911760 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.58326: Flags [.], ack 330802, win 0, options [...], length 0
02:59:12.111648 IP ***.***.***.***.*****.jp.58326 > 0896acbe9b4d.80: Flags [.], ack 26, win 510, options [...], length 0
02:59:12.111677 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.58326: Flags [.], ack 330802, win 0, options [...], length 0
02:59:18.255948 IP ***.***.***.***.*****.jp.58326 > 0896acbe9b4d.80: Flags [.], ack 26, win 510, options [...], length 0
02:59:18.256015 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.58326: Flags [.], ack 330802, win 0, options [...], length 0
02:59:30.541438 IP ***.***.***.***.*****.jp.58326 > 0896acbe9b4d.80: Flags [.], ack 26, win 510, options [...], length 0
02:59:30.541465 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.58326: Flags [.], ack 330802, win 0, options [...], length 0
02:59:36.126476 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.58326: Flags [P.], seq 26:355, ack 330802, win 0, options [...], length 329: HTTP: HTTP/1.1 504 Gateway Time-out
02:59:36.126506 IP 0896acbe9b4d.80 > ***.***.***.***.*****.jp.58326: Flags [F.], seq 355, ack 330802, win 0, options [...], length 0
Caddy
以下の構成で検証を行います。検証スクリプトはApacheの時と同じものを使用します。
クライアント Caddy PHP-FPM（PHP/8.4.13）
まずは通常のリクエストを送信してみます。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 200 OK
Content-Type: text/html; charset=UTF-8
Via: 0.0 Caddy
X-Powered-By: PHP/8.4.13
Date: Mon, 03 Nov 2025 06:15:43 GMT
Content-Length: 13
Hello, qiita!
real 0m0.340s
user 0m0.001s
sys 0m0.015s
続いてスローHTTPリクエストを送信すると、クライアントから接続をクローズしない限り接続されたままになりました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
^C
real 30m11.159s
user 0m0.035s
sys 0m0.063s
Caddyは明示的にタイムアウトを設定しない限りタイムアウトが発生しません。read_bodyを60秒に設定して再度リクエストを送信してみます。
{
servers {
timeouts {
read_body 60s
read_header 5s
write 30s
idle 10m
}
}
}
60秒でリクエストがタイムアウトし接続がクローズされました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
curl: (52) Empty reply from server
real 1m0.361s
user 0m0.011s
sys 0m0.034s
PHP-FPMコンテナのログを確認してもログは出力されていません。
リクエスト時のネットワークソケットを確認してもPHP-FPMとのアップストリーム接続は確認できません。
$ ss -ntH state established 'dport = 9000' | wc -l
0
ただし、リクエストボディのサイズが4KB以上になるとPHP-FPMとのアップストリーム接続が確立されました。
$ time curl -X POST -H "Content-Length: 4097" -d @4kb.txt --dump-header - http://***.***.***.***/
curl: (52) Empty reply from server
real 1m0.359s
user 0m0.015s
sys 0m0.015s
$ ss -ntH state established 'dport = 9000' | wc -l
1
request_buffersを5バイトに設定して試すと、設定前は確立されなかったアップストリーム接続が今度は確立されました。
@phpFiles path *.php
reverse_proxy @phpFiles php-fpm:9000 {
request_buffers 5B
transport fastcgi {
[...]
}
}
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
[...]
$ ss -ntH state established 'dport = 9000' | wc -l
1
FastCGIの場合にrequest_buffersのデフォルト値が4KBに設定されるように変更されたのがこのような挙動として表れているのではないかと思います（関連PR）。ただし、接続は確立されてもリクエストボディのサイズが65500バイトより大きくないと転送されず、タイムアウト時に破棄されてしまうようです。
$ time curl -X POST -H "Content-Length: 65501" -d @65500b.txt --dump-header - http://***.***.***.***/
[...]
# PHP-FPMのコンテナのログ
NOTICE: PHP message: Length:0
$ time curl -X POST -H "Content-Length: 65502" -d @65501b.txt --dump-header - http://***.***.***.***/
[...]
# PHP-FPMのコンテナのログ（48KBまでしか送信されていない理由は未調査）
NOTICE: PHP message: Length:49152
なお、read_bodyを29秒以下に設定すると、4KB以上と4KB未満で異なるエラーレスポンスが返ってきました（理由は未調査）。
# 4KB以上
$ time curl -X POST -H "Content-Length: 4097" -d @4kb.txt --dump-header - http://***.***.***.***/
HTTP/1.1 504 Gateway Timeout
Server: Caddy
Date: Mon, 03 Nov 2025 09:14:00 GMT
Content-Length: 0
Connection: close
real 0m29.341s
user 0m0.000s
sys 0m0.021s
# 4KB未満
$ time curl -X POST -H "Content-Length: 4096" -d @4095b.txt --dump-header - http://***.***.***.***/
HTTP/1.1 499 status code 499
Server: Caddy
Date: Mon, 03 Nov 2025 09:14:33 GMT
Content-Length: 0
Connection: close
real 0m29.339s
user 0m0.010s
sys 0m0.011s
read_bodyをデフォルトの状態（未設定）に戻して、4KBのスローHTTPリクエストをPHP-FPMのワーカープロセスの数と同じ多重度5で送信してみます。
$ time curl -X POST -H "Content-Length: 4097" -d @4kb.txt --parallel --parallel-immediate --parallel-max 5 http://***.***.***.***/?[1-5]
[...]
この状態で通常のPOSTリクエストを送信すると、PHP-FPMのワーカープロセスがスローHTTPリクエストに無期限で占有されてしまうため、クライアントから接続をクローズしない限り接続されたままの状態となりました。今回のケースのようなネットワークI/O待ちの場合、PHPのmax_execution_timeやmax_input_timeを設定しても効果はありません（一部の実行環境を除きITIMER_PROFが使用される）。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
^C
real 11m5.734s
user 0m0.030s
sys 0m0.081s
そこでPHP-FPMのrequest_terminate_timeoutを30秒に設定して同様に送信してみます。
[www]
pm = dynamic
pm.max_children = 5
pm.start_servers = 2
pm.min_spare_servers = 1
pm.max_spare_servers = 3
request_terminate_timeout=30
多重度5で送信すると接続された状態が続きます。
$ time curl -X POST -H "Content-Length: 4097" -d @4kb.txt --parallel --parallel-immediate --parallel-max 5 http://***.***.***.***/?[1-5]
[...]
ただし、PHP-FPMコンテナのログを見るとワーカープロセスが強制終了して新しいワーカープロセスが起動しています（プロセスが強制終了するためPHPの処理は続行されません）。
[16-Nov-2025 06:42:40] WARNING: [pool www] child 810, script '/var/www/html/index.php' (request: "POST /index.php?4") execution timed out (33.591544 sec), terminating
[16-Nov-2025 06:42:40] WARNING: [pool www] child 784, script '/var/www/html/index.php' (request: "POST /index.php?3") execution timed out (34.593629 sec), terminating
[16-Nov-2025 06:42:40] WARNING: [pool www] child 783, script '/var/www/html/index.php' (request: "POST /index.php?1") execution timed out (35.593978 sec), terminating
[16-Nov-2025 06:42:40] WARNING: [pool www] child 22, script '/var/www/html/index.php' (request: "POST /index.php?5") execution timed out (36.217745 sec), terminating
[16-Nov-2025 06:42:40] WARNING: [pool www] child 21, script '/var/www/html/index.php' (request: "POST /index.php?2") execution timed out (36.225584 sec), terminating
[16-Nov-2025 06:42:40] WARNING: [pool www] child 22 exited on signal 15 (SIGTERM) after 500.069319 seconds from start
[16-Nov-2025 06:42:40] NOTICE: [pool www] child 861 started
[16-Nov-2025 06:42:40] WARNING: [pool www] child 784 exited on signal 15 (SIGTERM) after 34.596156 seconds from start
[16-Nov-2025 06:42:40] NOTICE: [pool www] child 862 started
[16-Nov-2025 06:42:40] WARNING: [pool www] child 783 exited on signal 15 (SIGTERM) after 35.597734 seconds from start
[16-Nov-2025 06:42:40] NOTICE: [pool www] child 863 started
[16-Nov-2025 06:42:40] WARNING: [pool www] child 21 exited on signal 15 (SIGTERM) after 500.073255 seconds from start
[16-Nov-2025 06:42:40] NOTICE: [pool www] child 864 started
[16-Nov-2025 06:42:40] WARNING: [pool www] child 810 exited on signal 15 (SIGTERM) after 33.597351 seconds from start
[16-Nov-2025 06:42:40] NOTICE: [pool www] child 865 started
スローHTTPリクエスト送信中に通常のリクエストを送信すると、スローHTTPリクエストがタイムアウトして新しく起動したワーカープロセスによって処理されました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 200 OK
[...]
Hello, qiita!
real 0m35.671s
user 0m0.008s
sys 0m0.013s
PHP-FPMのタイムアウト発生直後のCaddyコンテナのネットワークソケットを確認すると、アップストリーム接続がCLOSE-WAITになっています。そして1分程度経過した後にアップストリーム接続がクローズされました（クライアント接続は残ったままです）。
$ ss -nt '( dport = 9000 or sport = 80 )'
State Recv-Q Send-Q Local Address:Port Peer Address:Port
CLOSE-WAIT 1 0 172.18.0.7:45198 172.18.0.3:9000
CLOSE-WAIT 1 0 172.18.0.7:45220 172.18.0.3:9000
CLOSE-WAIT 1 0 172.18.0.7:45200 172.18.0.3:9000
CLOSE-WAIT 1 0 172.18.0.7:45208 172.18.0.3:9000
CLOSE-WAIT 1 0 172.18.0.7:45188 172.18.0.3:9000
ESTAB 0 0 [::ffff:172.18.0.7]:80 [::ffff:***.***.***.***]:54276
ESTAB 0 0 [::ffff:172.18.0.7]:80 [::ffff:***.***.***.***]:54286
ESTAB 0 0 [::ffff:172.18.0.7]:80 [::ffff:***.***.***.***]:54302
ESTAB 0 0 [::ffff:172.18.0.7]:80 [::ffff:***.***.***.***]:54218
ESTAB 0 0 [::ffff:172.18.0.7]:80 [::ffff:***.***.***.***]:54310
$ ss -nt '( dport = 9000 or sport = 80 )'
ESTAB 0 0 [::ffff:172.18.0.7]:80 [::ffff:***.***.***.***]:54276
ESTAB 0 0 [::ffff:172.18.0.7]:80 [::ffff:***.***.***.***]:54286
ESTAB 0 0 [::ffff:172.18.0.7]:80 [::ffff:***.***.***.***]:54302
ESTAB 0 0 [::ffff:172.18.0.7]:80 [::ffff:***.***.***.***]:54218
ESTAB 0 0 [::ffff:172.18.0.7]:80 [::ffff:***.***.***.***]:54310
アップストリーム接続のタイムアウト（write_timeout）を60秒に設定してread_bodyの代わりに効果があるかどうか試してみます（PHP-FPMの設定は元に戻しています）。
@phpFiles path *.php
reverse_proxy @phpFiles php-fpm:9000 {
transport fastcgi {
root /var/www/html
split .php
write_timeout 60s
}
}
4KBのスローHTTPリクエストを送信してもタイムアウトは発生しません。
$ time curl -X POST -H "Content-Length: 4097" -d @4kb.txt --dump-header - http://***.***.***.***/
^C
real 3m11.000s
user 0m0.016s
sys 0m0.033s
多重度5で送信してPHP-FPMのワーカープロセスを占有した状態で、通常のPOSTリクエストを送信してみます。
$ time curl -X POST -H "Content-Length: 4097" -d @4kb.txt --parallel --parallel-immediate --parallel-max 5 http://***.***.***.***/?[1-5]
[...]
5バイトの送信ではタイムアウトは発生しませんが、1MBの送信では60秒で504 Gateway Timeoutのエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
^C
real 5m58.985s
user 0m0.025s
sys 0m0.027s
$ time curl -X POST -H "Content-Length: 1048576" -d @1mb.txt --dump-header - http://***.***.***.***/
HTTP/1.1 504 Gateway Timeout
[...]
real 1m0.486s
user 0m0.009s
sys 0m0.018s
1MB送信直後のネットワークソケットを確認すると、1MBの接続でソケットバッファに滞留があります。ApacheのProxyTimeoutと同じように、アップストリーム接続に対する書き込み処理の待ちに対してwrite_timeoutは発動するようです。
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 0 172.18.0.6:43192 172.18.0.3:9000
0 0 172.18.0.6:43186 172.18.0.3:9000
0 0 172.18.0.6:43204 172.18.0.3:9000
0 0 172.18.0.6:43208 172.18.0.3:9000
0 0 172.18.0.6:43206 172.18.0.3:9000
0 695040 172.18.0.6:43222 172.18.0.3:9000
0 0 [::ffff:172.18.0.6]:http [::ffff:***.***.***.***]:53144
0 0 [::ffff:172.18.0.6]:http [::ffff:***.***.***.***]:53160
193888 0 [::ffff:172.18.0.6]:http [::ffff:***.***.***.***]:53162
0 0 [::ffff:172.18.0.6]:2019 [::ffff:172.18.0.2]:49136
0 0 [::ffff:172.18.0.6]:http [::ffff:***.***.***.***]:53138
0 0 [::ffff:172.18.0.6]:http [::ffff:***.***.***.***]:53158
0 0 [::ffff:172.18.0.6]:http [::ffff:***.***.***.***]:53132
read_bodyを60秒の設定に戻して、小さいチャンクに分割してゆっくり送信してみます。300バイトのデータを1秒おきに1バイトずつ送信すると、read_bodyに設定した60秒でタイムアウトし接続がクローズされました。また、チャンクのサイズを大きくしても同じ結果となりました。
$ time ./slow_http_post.sh 300 1
real 1m2.358s
user 0m0.075s
sys 0m0.346s
$ time ./slow_http_post.sh 10485760 102400
real 1m2.163s
user 0m13.512s
sys 0m5.316s
多重度を上げてサーバーリソースの変化を確認します。まずは4KBのスローHTTPリクエストを多重度300で送信します。
$ time curl -X POST -H "Content-Length: 4097" -d @4kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
real 1m1.699s
user 0m0.215s
sys 0m0.680s
処理中のリクエストの数が300に上昇し、タイムアウトが発生すると0に戻りました。同様にgoroutine（軽量スレッド）の数も300増加しました。
リクエストの前後でオープン中のネットワークソケットを確認すると600増加しました（クライアント接続300 + アップストリーム接続300）。
# リクエスト前
$ lsof | grep caddy | grep socket | wc -l
3
# リクエスト直後
$ lsof | grep caddy | grep socket | wc -l
603
スローHTTPリクエスト送信後に少し間を開けて通常のPOSTリクエストをPHPに送信すると、PHP-FPMのワーカープロセスが占有されているため遅延が発生し、タイムアウト時間とは関係なくスローHTTPリクエストがタイムアウトしたタイミングで接続がクローズされました（タイムアウト時間と関係なくクローズされる理由は未調査）。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
curl: (52) Empty reply from server
real 0m43.632s
user 0m0.000s
sys 0m0.019s
# PHP-FPMにデータは転送されているためコンテナのログは出力されている
NOTICE: PHP message: Length:5
CaddyコンテナのFDの上限を512に変更し、多重度300で送信してみます。
$ ulimit -n
512
リクエスト直後に複数の接続で502 Bad Gatewayのエラーレスポンスが返ってきて、その後のタイムアウトで残りの接続がクローズされました。
$ time curl -X POST -H "Content-Length: 4097" -d @4kb.txt --parallel --parallel-immediate --parallel-max 300 --dump-header - http://***.***.***.***/?[1-300]
HTTP/1.1 502 Bad Gateway
[...]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
real 1m1.807s
user 0m0.190s
sys 0m0.503s
リクエスト直後のオープン中のネットワークソケットを確認すると、変更前の603から505に減少しました。
$ lsof | grep caddy | grep socket | wc -l
505
アップストリーム接続の最大数を設定するmax_requestsを試してみます（Caddyfile形式の設定方法が見つからなかったためJSON形式で設定しています）。
{
"handle": [
{
"handler": "reverse_proxy",
"transport": {
"protocol": "fastcgi",
"root": "/var/www/html",
"split_path": [
".php"
]
},
"upstreams": [
{
"dial": "php-fpm:9000",
"max_requests": 100
}
]
}
],
[...]
}
HTTPスローHTTPリクエストを多重度300で送信するとリクエスト直後に複数の接続で503 Service Unavailableのエラーレスポンスが返ってきて、その後のタイムアウトで残りの接続がクローズされました。
$ time curl -X POST -H "Content-Length: 4097" -d @4kb.txt --parallel --parallel-immediate --parallel-max 300 --dump-header - http://***.***.***.***/?[1-300]
HTTP/1.1 503 Service Unavailable
[...]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
real 1m1.097s
user 0m0.197s
sys 0m0.493s
処理中のリクエストの数を確認すると瞬間的に250くらいまで上昇していますが、その後100まで下がって一定になりました。
スローHTTPリクエスト送信中に通常のPOSTリクエストを送信すると503 Service Unavailableのエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 503 Service Unavailable
[...]
real 0m0.335s
user 0m0.011s
sys 0m0.007s
静的なHTMLにリクエストを送信すると、こちらはアップストリーム接続がないため遅延せずにレスポンスが返ってきました。
$ time curl -X GET http://***.***.***.***/hello.html
Hello!
real 0m0.329s
user 0m0.004s
sys 0m0.012s
設定を元に戻してリクエストボディのサイズを10MBにしたスローHTTPリクエストを、PHP-FPMのワーカープロセスの数と同じ多重度5で送信してみます。Apacheやnginxはデータを受信している最中はタイムアウトのタイマーがリセットされるため1分40秒ほど掛かっていましたが、Caddyはアイムアウトに設定した60秒で接続がクローズされました。
$ time curl -X POST -H "Content-Length: 10485761" -d @10mb.txt --parallel --parallel-immediate --parallel-max 5 http://***.***.***.***/?[1-5]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
real 1m0.422s
user 0m0.059s
sys 0m0.265s
まずはCaddyのメモリ使用量を確認してみます。下図の緑色がCaddyコンテナのメモリ使用量、黄色がプロセスのメモリ使用量（RSS）の合計、青色が割り当てられたヒープメモリのサイズを表しています。バッファリングせずに転送しているので目立った変化はありません。
PHP-FPMの方も確認してみます。下図の緑色がPHP-FPMコンテナのメモリ使用量、黄色がプロセスのメモリ使用量（PSS）の合計を表しています。Apacheの時と同様にコンテナのメモリ使用量は受信したデータ量相応の増加が見られます。
PHP-FPMコンテナのログを確認すると、先のテストと同様に受信したデータサイズが送信したデータサイズより少なくなっています（16KB不足）。
NOTICE: PHP message: Length:10469376
NOTICE: PHP message: Length:10469376
NOTICE: PHP message: Length:10469376
NOTICE: PHP message: Length:10469376
NOTICE: PHP message: Length:10469376
request_buffersに10MBを設定してバッファリングを有効にした状態で送信してみます。
@phpFiles path *.php
reverse_proxy @phpFiles php-fpm:9000 {
request_buffers 10MB
transport fastcgi {
root /var/www/html
split .php
}
}
$ time curl -X POST -H "Content-Length: 10485761" -d @10mb.txt --parallel --parallel-immediate --parallel-max 5 http://***.***.***.***/?[1-5]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (52) Empty reply from server
real 1m0.403s
user 0m0.062s
sys 0m0.134s
まずはCaddyのメモリ使用量を確認してみます。下図の緑色がCaddyコンテナのメモリ使用量、黄色がプロセスのメモリ使用量（RSS）の合計、青色が割り当てられたヒープメモリのサイズを表しています。いずれもほぼ同じような増加を示しています。ヒープメモリ上のオブジェクトが解放されてもメモリアロケーターがすぐにはOSにメモリを返さないため、しばらくはプロセスのメモリ使用量が増加したままの状態が続いています。
docker statsのAPIエンドポイントから取得したメモリ使用量の詳細の差分を確認すると、nginxではページキャッシュが増加していましたが、Caddyはヒープメモリの割り当てで増加していることが分かります。
$ jq -s '
{
"USAGE (Total)": ((.[1].usage - .[0].usage) / 1048576),
"ANON (Heap/Stack)": ((.[1].stats.anon - .[0].stats.anon) / 1048576),
"FILE (Cache)": ((.[1].stats.file - .[0].stats.file) / 1048576),
"INACTIVE_FILE": ((.[1].stats.inactive_file - .[0].stats.inactive_file) / 1048576),
"FILE_DIRTY": ((.[1].stats.file_dirty - .[0].stats.file_dirty) / 1048576),
"SLAB": ((.[1].stats.slab - .[0].stats.slab) / 1048576)
}
' before.json after.json
{
"USAGE (Total)": 114.94140625,
"ANON (Heap/Stack)": 114.72265625,
"FILE (Cache)": 0,
"INACTIVE_FILE": 0,
"FILE_DIRTY": 0,
"SLAB": 0.00064849853515625
}
Caddyにはプロファイリングの機能があるので送信中にプロファイルを取得してバッファリングの有無でdiffをとってみるとバッファにコピーしていることが確認できます。
$ go tool pprof -diff_base=no_buffering_allocs.prof buffering_allocs.prof
[...]
(pprof) top
Showing nodes accounting for 71781.09kB, 481.80% of 14898.67kB total
Dropped 2 nodes (cum <= 74.49kB)
Showing top 10 nodes out of 178
flat flat% sum% cum cum%
67185.71kB 450.95% 450.95% 67185.71kB 450.95% bytes.growSlice
1805.17kB 12.12% 463.07% 1805.17kB 12.12% compress/flate.NewWriter
1246.04kB 8.36% 471.43% 1246.04kB 8.36% os.readFileContents
[...]
(pprof) traces
File: caddy
Build ID: 8a32851908a303960579c849e7121ac8eb2325d5
Type: alloc_space
Time: Oct 8, 2025 at 11:31am (JST)
-----------+-------------------------------------------------------
bytes: 8MB
24MB bytes.growSlice
bytes.(*Buffer).grow
bytes.(*Buffer).ReadFrom
io.copyBuffer
io.Copy (inline)
io.CopyN
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.Handler.bufferedBody
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.Handler.prepareRequest
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.(*Handler).ServeHTTP
[...]
-----------+-------------------------------------------------------
bytes: 4MB
20.01MB bytes.growSlice
bytes.(*Buffer).grow
bytes.(*Buffer).ReadFrom
io.copyBuffer
io.Copy (inline)
io.CopyN
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.Handler.bufferedBody
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.Handler.prepareRequest
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.(*Handler).ServeHTTP
[...]
-----------+-------------------------------------------------------
bytes: 2MB
10.19MB bytes.growSlice
bytes.(*Buffer).grow
bytes.(*Buffer).ReadFrom
io.copyBuffer
io.Copy (inline)
io.CopyN
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.Handler.bufferedBody
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.Handler.prepareRequest
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.(*Handler).ServeHTTP
[...]
PHP-FPMの方はCaddyからバッファリングされたデータがまとめて転送される時にコンテナのメモリ使用量が瞬間的に増加しますが、それ以外では目立った変化はありません。
なお、CaddyからPHP-FPMに転送されるタイミングは、受信したデータがrequest_buffersに設定したサイズに到達したか、もしくは全データを受信したタイミング（Content-Lengthとの一致や終端チャンクの受信）です。したがって以下のように10MBより1B大きいサイズを設定してスローHTTPリクエストを送信すると、PHP-FPMには転送されずにタイムアウト時に受信したデータが破棄されます。
@phpFiles path *.php
reverse_proxy @phpFiles php-fpm:9000 {
request_buffers 10485761B
transport fastcgi {
root /var/www/html
split .php
}
}
逆に10MBより小さいサイズを設定した場合、設定したサイズまでバッファリングして転送した後は逐次転送を行います（設定したサイズごとにバッファリングを繰り返す訳ではありません）。
@phpFiles path *.php
reverse_proxy @phpFiles php-fpm:9000 {
request_buffers 3MB
transport fastcgi {
root /var/www/html
split .php
}
}
バッファリングの設定を元に戻してリクエストボディのサイズを1MBにしたスローHTTPリクエストを多重度50で送信してみます。送信中でもタイムアウトで強制的に接続が切断されるため、PHP-FPMのワーカープロセスで処理中の接続以外の全ての接続が送信途中でリセットされています。
$ time curl -X POST -H "Content-Length: 1048577" -d @1mb.txt --parallel --parallel-immediate --parallel-max 50 http://***.***.***.***/?[1-50]
[...]
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
real 1m0.512s
user 0m0.129s
sys 0m0.356s
Caddyのメモリ使用量を確認してみます。下図の緑色がCaddyコンテナのメモリ使用量、黄色がプロセスのメモリ使用量（RSS）の合計、青色が割り当てられたヒープメモリのサイズを表しています。データ送信中に切断された接続が大多数のため増加量が少なくなっています。バッファリングはしていませんがヒープメモリの割り当てが増加しています（通常のPOSTリクエストでも同様なのでスローHTTPリクエスト特有の挙動ではありません）。
docker statsのAPIエンドポイントから取得したメモリ使用量の詳細の差分を確認すると、ヒープメモリの割り当てとソケットバッファが増加していることが分かります。
$ jq -s '
{
"USAGE (Total)": ((.[1].usage - .[0].usage) / 1048576),
"ANON (Heap/Stack)": ((.[1].stats.anon - .[0].stats.anon) / 1048576),
"FILE (Cache)": ((.[1].stats.file - .[0].stats.file) / 1048576),
"INACTIVE_FILE": ((.[1].stats.inactive_file - .[0].stats.inactive_file) / 1048576),
"FILE_DIRTY": ((.[1].stats.file_dirty - .[0].stats.file_dirty) / 1048576),
"SLAB": ((.[1].stats.slab - .[0].stats.slab) / 1048576),
"SOCK": ((.[1].stats.sock - .[0].stats.sock) / 1048576),
}
' before.json after.json
{
"USAGE (Total)": 23.6484375,
"ANON (Heap/Stack)": 8.94921875,
"FILE (Cache)": 0,
"INACTIVE_FILE": 0,
"FILE_DIRTY": 0,
"SLAB": 0.27939605712890625,
"SOCK": 14.3984375
}
プロファイルを取得して確認してみると、リクエストボディを一時的にバッファにコピーする際のメモリアロケーションのようです。
go tool pprof -diff_base=before.prof after.prof
[...]
(pprof) sample_index=alloc_space
(pprof) top
Showing nodes accounting for 11224.36kB, 73.25% of 15323.91kB total
Showing top 10 nodes out of 86
flat flat% sum% cum cum%
4686.26kB 30.58% 30.58% 4686.26kB 30.58% bytes.growSlice
1805.17kB 11.78% 42.36% 2932.84kB 19.14% compress/flate.NewWriter
1127.67kB 7.36% 49.72% 1127.67kB 7.36% compress/flate.newDeflateFast (inline)
528.17kB 3.45% 53.17% 4702.37kB 30.69% io.copyBuffer
[...]
(pprof) traces growSlice
File: caddy
Build ID: 8a32851908a303960579c849e7121ac8eb2325d5
Type: alloc_space
Time: Nov 6, 2025 at 7:47am (JST)
-----------+-------------------------------------------------------
bytes: 20kB
1.02MB bytes.growSlice
bytes.(*Buffer).grow
bytes.(*Buffer).Write
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy/fastcgi.(*streamWriter).Write
io.copyBuffer
io.Copy (inline)
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy/fastcgi.(*client).Do
[...]
-----------+-------------------------------------------------------
bytes: 9.50kB
1.01MB bytes.growSlice
bytes.(*Buffer).grow
bytes.(*Buffer).Write
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy/fastcgi.(*streamWriter).Write
io.copyBuffer
io.Copy (inline)
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy/fastcgi.(*client).Do
[...]
-----------+-------------------------------------------------------
bytes: 40kB
1.04MB bytes.growSlice
bytes.(*Buffer).grow
bytes.(*Buffer).Write
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy/fastcgi.(*streamWriter).Write
io.copyBuffer
io.Copy (inline)
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy/fastcgi.(*client).Do
[...]
tcpdumpを使用してクライアント・Caddy間でどのような通信が行われたのか確認してみます。Apacheやnginxと同じように受信ウィンドウサイズが500バイト前後まで急激に縮小し、その後セロウィンドウが発生して60秒後にサーバーからクライアントにRST/ACKが送信されています。
23:28:37.233958 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [S], seq 906386748, win 65280, options [...], length 0
23:28:37.233976 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59448: Flags [S.], seq 249011578, ack 906386749, win 65160, options [...], length 0
23:28:37.407901 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [.], ack 1, win 510, options [...], length 0
23:28:37.409802 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [P.], seq 1:185, ack 1, win 510, options [...], length 184: HTTP: POST /?14 HTTP/1.1
23:28:37.409806 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59448: Flags [.], ack 185, win 508, options [...], length 0
23:28:37.634852 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [.], seq 185:1413, ack 26, win 510, options [...], length 1228: HTTP
23:28:37.635808 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [P.], seq 1413:2641, ack 26, win 510, options [...], length 1228: HTTP
23:28:37.635913 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59448: Flags [.], ack 2641, win 489, options [...], length 0
23:28:37.838031 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [P.], seq 12465:14921, ack 26, win 510, options [...], length 2456: HTTP
[...]
23:28:55.780450 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59448: Flags [.], ack 442065, win 0, options [...], length 0
23:28:56.962231 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [.], ack 26, win 510, options [...], length 0
23:28:56.962241 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59448: Flags [.], ack 442065, win 0, options [...], length 0
23:28:59.138885 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [.], ack 26, win 510, options [...], length 0
23:28:59.138912 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59448: Flags [.], ack 442065, win 0, options [...], length 0
23:29:03.457872 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [.], ack 26, win 510, options [...], length 0
23:29:03.457901 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59448: Flags [.], ack 442065, win 0, options [...], length 0
23:29:10.152060 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59448: Flags [.], ack 442065, win 0, options [...], length 0
23:29:10.324592 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [.], ack 26, win 510, options [...], length 0
23:29:11.647897 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [.], ack 26, win 510, options [...], length 0
23:29:11.647906 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59448: Flags [.], ack 442065, win 0, options [...], length 0
23:29:25.576107 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59448: Flags [.], ack 442065, win 0, options [...], length 0
23:29:25.748989 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [.], ack 26, win 510, options [...], length 0
23:29:27.774622 IP ***.***.***.***.*****.jp.59448 > ac3031d28bf9.80: Flags [.], ack 26, win 510, options [...], length 0
23:29:27.774651 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59448: Flags [.], ack 442065, win 0, options [...], length 0
23:29:37.473517 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59448: Flags [R.], seq 26, ack 442065, win 826, options [...], length 0
PHP-FPMの方はApacheやnginxの時と同じような変化をしています。
write_timeoutを30秒に設定して同様にtcpdumpを確認すると、30秒で接続がリセットされていることが分かります。
@phpFiles path *.php
reverse_proxy @phpFiles php-fpm:9000 {
transport fastcgi {
root /var/www/html
split .php
write_timeout 30s
}
}
00:09:59.673796 IP ***.***.***.***.*****.jp.59486 > ac3031d28bf9.80: Flags [S], seq 2201833493, win 65280, options [...], length 0
00:09:59.673803 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59486: Flags [S.], seq 649443551, ack 2201833494, win 65160, options [...], length 0
00:09:59.849414 IP ***.***.***.***.*****.jp.59486 > ac3031d28bf9.80: Flags [.], ack 1, win 510, options [...], length 0
00:09:59.849440 IP ***.***.***.***.*****.jp.59486 > ac3031d28bf9.80: Flags [P.], seq 1:185, ack 1, win 510, options [...], length 184: HTTP: POST /index.php?38 HTTP/1.1
00:09:59.849445 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59486: Flags [.], ack 185, win 508, options [...], length 0
[...]
00:10:21.794751 IP ***.***.***.***.*****.jp.59486 > ac3031d28bf9.80: Flags [.], ack 26, win 510, options [...], length 0
00:10:21.794775 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59486: Flags [.], ack 417377, win 0, options [...], length 0
00:10:27.168933 IP ***.***.***.***.*****.jp.59486 > ac3031d28bf9.80: Flags [.], ack 26, win 510, options [...], length 0
00:10:27.168966 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59486: Flags [.], ack 417377, win 0, options [...], length 0
00:10:30.541827 IP ac3031d28bf9.80 > ***.***.***.***.*****.jp.59486: Flags [R.], seq 26, ack 417377, win 715, options [...], length 0
read_bodyを設定せずにwrite_timeoutを設定した場合は504 Gateway Timeoutのステータスコードが送信されてくるのですが、両方設定しているとステータスコードは送信されてこないようです。
Node.js
Node.jsで簡易的なリバースプロキシサーバーを実装して、バックエンドのNode.jsへのリクエストを中継するBFFのような構成で検証します。なお、BFFサーバーとバックエンドサーバーはそれぞれ異なるコンテナで実行します。
クライアント Node.js（BFF） Node.js（バックエンド）
検証には以下のコードを使用します。
const http = require('http');
// BFFサーバー
http.createServer((clientReq, clientRes) => {
const options = {
host: 'backend',
port: 9000,
path: clientReq.url,
method: clientReq.method,
headers: clientReq.headers,
};
const proxyReq = http.request(options, (backendRes) => {
clientRes.writeHead(backendRes.statusCode, backendRes.headers);
backendRes.pipe(clientRes);
});
clientReq.pipe(proxyReq);
proxyReq.on('error', (err) => {
if (!clientRes.headersSent) {
clientRes.writeHead(500, { 'Content-Type': 'text/plain' });
clientRes.end('Could not connect to backend server.\n');
}
});
// 検証用にあえてコメントアウトしています
// clientReq.on('error', (err) => {
// console.log(`Request error: ${err.message}`);
// proxyReq.destroy();
// });
}).listen(80);
const http = require('http');
// バックエンドサーバー
http.createServer((req, res) => {
let body = '';
let totalBytes = 0;
req.on('data', chunk => {
body += chunk.toString();
totalBytes += chunk.length;
});
req.on('end', () => {
console.log(`Length: ${totalBytes}`);
res.writeHead(200, { 'Content-Type': 'text/plain' });
res.end(`Hello, ${body}!`);
});
req.on('error', (err) => {
console.log(`Request error: ${err.message}`);
console.log(`Length: ${totalBytes}`);
});
}).listen(9000);
まずは通常のリクエストを送信してみます。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 200 OK
content-type: text/plain
date: Thu, 06 Nov 2025 07:11:13 GMT
connection: keep-alive
keep-alive: timeout=5
transfer-encoding: chunked
Hello, qiita!
real 0m0.493s
user 0m0.001s
sys 0m0.081s
続いてスローHTTPリクエストを送信すると、5分ほどでリクエストがタイムアウトし、408 Request Timeoutのエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 408 Request Timeout
connection: close
Date: Thu, 06 Nov 2025 07:22:00 GMT
Transfer-Encoding: chunked
real 5m15.817s
user 0m0.019s
sys 0m0.035s
リクエスト時のBFFサーバーコンテナのネットワークソケットを確認するとバックエンドサーバーとの接続が確立していることが確認できます。
$ ss -ntH state established 'dport = 9000' | wc -l
1
バックエンドサーバーのコンテナのログにはerrorイベント時のログが出力されています。
Request error: aborted
Length: 5
タイムアウトに5分ほど掛かっていますが、この時間はserver.requestTimeoutのデフォルト値が300秒が適用されています。
BFFサーバーのタイムアウトを60秒に変更して試してみます。
const http = require('http');
http.createServer({
requestTimeout: 60000
}, (clientReq, clientRes) =>
[...]
タイムアウトの時間が変化しましたが、設定した60秒を20秒ほど超過しました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 408 Request Timeout
Connection: close
real 1m22.426s
user 0m0.005s
sys 0m0.016s
connectionsCheckingIntervalをデフォルトの30秒から1秒に変更して短い間隔で接続をチェックするようにしてみます。
const http = require('http');
http.createServer({
requestTimeout: 60000,
connectionsCheckingInterval: 1000
}, (clientReq, clientRes) =>
[...]
タイムアウトの時間がほぼ60秒になりました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 408 Request Timeout
Connection: close
real 1m0.460s
user 0m0.005s
sys 0m0.024s
タイムアウトはしましたが、BFFサーバーコンテナのネットワークソケットを確認するとバックエンドサーバーとの接続が残ったままになっています。
$ ss -ntH state established 'dport = 9000' | wc -l
1
BFFサーバーのコメントアウトしていた個所を戻して試すと、今度はタイムアウトと同時にバックエンドサーバーとの接続がリセットされました。
http.createServer({
[...]
clientReq.on('error', (err) => {
console.log(`Request error: ${err.message}`);
proxyReq.destroy();
});
}).listen(80);
$ ss -ntH state established 'dport = 9000' | wc -l
0
なお、以下のようにstream.pipelineを使用することでエラー発生時に接続の後始末を自動的に行うこともできます。
http.createServer({
requestTimeout: 60000
},
async (clientReq, clientRes) => {
const options = {
host: 'backend',
port: 9000,
path: clientReq.url,
method: clientReq.method,
headers: clientReq.headers,
};
const proxyReq = http.request(options, (targetRes) => {
clientRes.writeHead(targetRes.statusCode, targetRes.headers);
pipeline(
targetRes,
clientRes,
(err) => {
if (err) {
if (!clientRes.headersSent) {
clientRes.writeHead(500, { 'Content-Type': 'text/plain' });
clientRes.end('Proxy Error: Response transfer failed.');
}
}
}
);
});
pipeline(
clientReq,
proxyReq,
(err) => {
if (err) {
if (!clientRes.headersSent) {
clientRes.writeHead(500, { 'Content-Type': 'text/plain' });
clientRes.end('Proxy Error: Request transfer failed.');
}
}
}
);
proxyReq.on('error', (err) => {
if (!clientRes.headersSent) {
clientRes.writeHead(503, { 'Content-Type': 'text/plain' });
clientRes.end('Service Unavailable: Could not reach target server.');
}
});
}).listen(80);
小さいチャンクに分割してゆっくり送信してみます。300バイトのデータを1秒おきに1バイトずつ送信すると、60秒でタイムアウトが発生しました。
$ time ./slow_http_post.sh 300 1
HTTP/1.1 408 Request Timeout
Connection: close
real 1m3.281s
user 0m0.077s
sys 0m0.202s
多重度を上げてサーバーリソースの変化を確認します。まずはスローHTTPリクエストを多重度300で送信します。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
real 1m2.423s
user 0m0.118s
sys 0m0.288s
BFFサーバーはアクティブ接続数が600に上昇、バックエンドサーバーは300に上昇し、タイムアウトが発生すると元に戻りました。
リクエスト直後のオープン中のネットワークソケットを確認すると同様の増加が確認できます。
# BFFサーバー
# リクエスト前
$ lsof | grep node | grep socket | wc -l
2
# リクエスト直後
$ lsof | grep node | grep socket | wc -l
602
# バックエンドサーバー
# リクエスト前
$ lsof | grep node | grep socket | wc -l
2
# リクエスト直後
$ lsof | grep node | grep socket | wc -l
302
BFFサーバーコンテナのFDの上限を512に変更し、多重度300で送信してみます。
$ ulimit -n
512
送信直後にクライアント接続およびアップストリーム接続で複数の接続が失敗しました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
curl: (52) Empty reply from server
curl: (52) Empty reply from server
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
Could not connect to backend server.
Could not connect to backend server.
Could not connect to backend server.
Could not connect to backend server.
[...]
real 1m0.753s
user 0m0.110s
sys 0m0.342s
変更前と比較するとアクティブ接続数が減少しています（FDの枯渇でメトリクスを収集できなくなったため一部グラフが途切れています）。
BFFサーバーの接続上限数maxConnectionsを100に設定して試してます。
const server = http.createServer({
requestTimeout: 60000
}, (clientReq, clientRes) => {
[...]
}).listen(80);
server.maxConnections = 100;
多重度300で送信すると多数の接続が送信直後にリセットされました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
[...]
real 1m1.105s
user 0m0.122s
sys 0m0.263s
BFFサーバーのネットワークソケットを確認すると、バックエンドサーバーへの接続が100件となっています。
$ ss -ntH state established 'dport = 9000' | wc -l
100
スローHTTPリクエスト送信中に通常のPOSTリクエストを送信しても、送信直後に接続がリセットされます。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" http://***.***.***.***/
curl: (56) Recv failure: Connection reset by peer
real 0m0.356s
user 0m0.012s
sys 0m0.006s
今度はBFFサーバーではなくバックエンドサーバーの方にmaxConnectionsの設定を行い試してみます。
const server = http.createServer((req, res) => {
[...]
}).listen(9000);
server.maxConnections = 100;
多重度300で送信すると多数の接続で送信直後にエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 --dump-header - http://***.***.***.***/?[1-300]
HTTP/1.1 500 Internal Server Error
[...]
real 1m1.447s
user 0m0.135s
sys 0m0.275s
BFFサーバーのネットワークソケットを確認すると、バックエンドサーバーへの接続が100件となっています。
$ ss -ntH state established 'dport = 9000' | wc -l
100
BBFサーバーをクラスター化し、3つのワーカープロセスで動かした状態でmaxConnectionsを設定して試してみます。
if (cluster.isPrimary) {
for (let i = 0; i < 3; i++) {
cluster.fork();
}
cluster.on('exit', (worker, code, signal) => {
console.log(`worker ${worker.process.pid} died`);
});
} else {
const server = http.createServer({
requestTimeout: 60000
}, (clientReq, clientRes) => {
[...]
}).listen(80);
server.maxConnections = 50;
}
maxConnectionsを50に設定して多重度300で送信すると2分で完了しました。クラスター化しない場合はmaxConnectionsを超えるリクエストは送信直後にエラーレスポンスが返ってきましたが、今回は1分後と最初のタイムアウトが発生してエラーレスポンスが返り、その１分後に２回目のタイムアウトが発生してエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 --dump-header - http://***.***.***.***/?[1-300]
HTTP/1.1 408 Request Timeout
Connection: close
[...]
HTTP/1.1 408 Request Timeout
Connection: close
real 2m11.118s
user 0m0.186s
sys 0m0.411s
リクエスト直後のBFFサーバーのネットワークソケットを確認すると、クライアントからの接続は300、バックエンドサーバーへの接続は150になっています。150のリクエストがバックエンドサーバに転送され、残りの150リクエストがソケットバッファに滞留しています。
$ ss -ntH state established 'sport = 80' | wc -l
300
$ ss -ntH state established 'dport = 9000' | wc -l
150
$ ss -nt state established 'sport = 80'
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 0 [::ffff:172.18.0.4]:http [::ffff:***.***.***.***]:57274
0 0 [::ffff:172.18.0.4]:http [::ffff:***.***.***.***]:56395
153 0 [::ffff:172.18.0.4]:http [::ffff:***.***.***.***]:57347
153 0 [::ffff:172.18.0.4]:http [::ffff:***.***.***.***]:57705
153 0 [::ffff:172.18.0.4]:http [::ffff:***.***.***.***]:57650
153 0 [::ffff:172.18.0.4]:http [::ffff:***.***.***.***]:57321
153 0 [::ffff:172.18.0.4]:http [::ffff:***.***.***.***]:57337
[...]
$ ss -ntH state established 'sport = 80' | awk '{ if ($1 != 0) print }' | wc -l
150
そして１分後にはクライアントからの接続は150に減少しています。
$ ss -ntH state established 'sport = 80' | wc -l
150
スローHTTPリクエスト送信中に通常のPOSTリクエストを送信すると1分後にレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" http://***.***.***.***/
HTTP/1.1 200 OK
[...]
Hello, qiita!
real 0m57.834s
user 0m0.004s
sys 0m0.018s
今度はdropMaxConnectionをtrueに設定して試してみます。
if (cluster.isPrimary) {
[...]
} else {
const server = http.createServer({
requestTimeout: 60000
}, (clientReq, clientRes) => {
[...]
}).listen(80);
server.maxConnections = 50;
server.dropMaxConnection = true;
}
多重度300で送信すると150件の接続が送信直後にリセットされ、1分後に残りの接続がタイムアウトになりました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 --dump-header - http://***.***.***.***/?[1-300]
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
[...]
HTTP/1.1 408 Request Timeout
Connection: close
real 1m1.822s
user 0m0.103s
sys 0m0.321s
BFFサーバーのネットワークソケットを確認すると、クライアントからの接続、バックエンドサーバーへの接続はともに150件となっています。
$ ss -ntH state established 'sport = 80' | wc -l
150
$ ss -ntH state established 'dport = 9000' | wc -l
150
スローHTTPリクエスト送信中に通常のPOSTリクエストを送信しても送信直後に接続がリセットされます。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" http://***.***.***.***/
curl: (56) Recv failure: Connection reset by peer
real 0m0.366s
user 0m0.011s
sys 0m0.016s
バックエンドサーバーに転送を行うエージェントのmaxSocketsも試してみます。
const agent = new http.Agent({
maxSockets: 100,
keepAlive: true,
});
http.createServer({
requestTimeout: 60000
}, (clientReq, clientRes) => {
const options = {
host: 'backend',
port: 9000,
path: clientReq.url,
method: clientReq.method,
headers: clientReq.headers,
agent
};
const proxyReq = http.request(options, (backendRes) => {
clientRes.writeHead(backendRes.statusCode, backendRes.headers);
backendRes.pipe(clientRes);
});
clientReq.pipe(proxyReq);
// タイムアウト時に接続を破棄する
proxyReq.on('timeout', () => {
proxyReq.destroy();
if (!clientRes.headersSent) {
clientRes.writeHead(408, { 'Content-Type': 'text/plain' });
clientRes.end('Request Timeout.\n');
}
});
[...]
}).listen(80);
maxSocketsを100に設定して多重度300で送信すると１分後に全ての接続がタイムアウトしました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 --dump-header - http://***.***.***.***/?[1-300]
[...]
HTTP/1.1 408 Request Timeout
Connection: close
real 1m0.423s
user 0m0.066s
sys 0m0.086s
リクエスト直後のBFFサーバーのネットワークソケットを確認すると、クライアントからBFFサーバーへの接続は300、BFFサーバーからバックエンドサーバーへの接続は100になっています。ソケットバッファにデータが残っている接続は見当たりません。
$ ss -ntH state established 'sport = 80' | wc -l
300
$ ss -ntH state established 'dport = 9000' | wc -l
100
$ ss -nt state established 'sport = 80'
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 0 [::ffff:172.18.0.3]:http [::ffff:***.***.***.***]:62169
0 0 [::ffff:172.18.0.3]:http [::ffff:***.***.***.***]:62207
0 0 [::ffff:172.18.0.3]:http [::ffff:***.***.***.***]:63185
0 0 [::ffff:172.18.0.3]:http [::ffff:***.***.***.***]:62189
0 0 [::ffff:172.18.0.3]:http [::ffff:***.***.***.***]:62154
[...]
$ ss -ntH state established 'sport = 80' | awk '{ if ($1 != 0) print }' | wc -l
0
スローHTTPリクエスト送信中に通常のリクエストを送信すると1分ほどの遅延が発生しました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" http://***.***.***.***/
Hello, qiita!
real 0m57.354s
user 0m0.000s
sys 0m0.010s
エージェントのtimeoutを20秒に設定してHTTPスローリクエストを多重度300で送信してみます。
const agent = new http.Agent({
maxSockets: 100,
keepAlive: true,
timeout: 20000
});
[...]
20秒おきに408 Request Timeoutのエラーレスポンスが返ってきました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 --dump-header - http://***.***.***.***/?[1-300]
HTTP/1.1 408 Request Timeout
[...]
HTTP/1.1 408 Request Timeout
[...]
real 1m0.735s
user 0m0.105s
sys 0m0.324s
リクエスト直後のBFFサーバーのネットワークソケットを確認すると、リクエスト直後は300件あった接続が20秒のタイムアウト発生ごとに100件ずつ減っていることが確認できます。maxSocketsを100に設定しており、最初の100件がバックエンドサーバーに接続して20秒後にタイムアウトイベントで接続が終了し、次の100件がバックエンドサーバーに接続、そしてタイムアウト後にまた次の100件という形で接続が行われるためこのような挙動になっています（接続が終了するのはタイムアウトイベント発生時に接続を破棄する処理を入れているためであり、破棄する処理を入れなければ接続は維持されます。タイムアウトが発生したから自動的に接続が破棄されるという訳ではありません。）。
# リクエスト直後
$ ss -ntH state established 'sport = 80' | wc -l
300
# 20秒後
$ ss -ntH state established 'sport = 80' | wc -l
200
# 40秒後
$ ss -ntH state established 'sport = 80' | wc -l
100
HTTPクライアントリクエストでエージェントを指定しない場合、globalAgentが使用され、デフォルトのタイムアウト秒数は5秒になります。エージェントを指定せずに多重度300で送信すると5秒でタイムアウトイベントが発生し、エラーレスポンスが返ってきます。
http.createServer({
requestTimeout: 60000
}, (clientReq, clientRes) => {
const options = {
host: 'backend',
port: 9000,
path: clientReq.url,
method: clientReq.method,
headers: clientReq.headers
};
const proxyReq = http.request(options, (backendRes) => {
clientRes.writeHead(backendRes.statusCode, backendRes.headers);
backendRes.pipe(clientRes);
});
clientReq.pipe(proxyReq);
proxyReq.on('timeout', () => {
proxyReq.destroy();
if (!clientRes.headersSent) {
clientRes.writeHead(408, { 'Content-Type': 'text/plain' });
clientRes.end('Request Timeout.\n');
}
});
[...]
}).listen(80);
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
Request Timeout.
Request Timeout.
Request Timeout.
real 0m6.488s
user 0m0.089s
sys 0m0.260s
なお、このタイムアウトの秒数は最後にデータを受信してからの経過秒数になり、データを受信するとリセットされます。以下のスクリプトで間隔を開けて１バイトずつ送信してみます。
#!/bin/bash
HOST="***.***.***.***"
PORT="80"
INTERVAL=$1
{
echo -ne "POST / HTTP/1.1\r\nHost: $HOST\r\nConnection: close\r\nContent-Type: text/plain\r\nContent-Length: 10\r\n\r\n"
for ((i=0; i<10; i+=1)); do
echo -n "a"
sleep $INTERVAL
done
} | nc $HOST $PORT
4秒間隔で送信するとタイムアウトが発生せず完了しました。
$ time ./slow_http_post.sh 4
HTTP/1.1 200 OK
[...]
real 0m40.053s
user 0m0.023s
sys 0m0.031s
5秒間隔で送信するとタイムアウトが発生しました。
$ time ./slow_http_post.sh 5
HTTP/1.1 408 Request Timeout
[...]
real 0m15.011s
user 0m0.013s
sys 0m0.007s
http.requestのオプションのtimeoutを20秒に設定してHTTPスローリクエストを多重度300で送信してみます。
http.createServer({
requestTimeout: 60000
}, (clientReq, clientRes) => {
const options = {
host: 'backend',
port: 9000,
path: clientReq.url,
method: clientReq.method,
headers: clientReq.headers,
timeout: 20000
};
const proxyReq = http.request(options, (backendRes) => {
clientRes.writeHead(backendRes.statusCode, backendRes.headers);
backendRes.pipe(clientRes);
});
clientReq.pipe(proxyReq);
proxyReq.on('timeout', () => {
proxyReq.destroy();
if (!clientRes.headersSent) {
clientRes.writeHead(408, { 'Content-Type': 'text/plain' });
clientRes.end('Request Timeout.\n');
}
});
[...]
}).listen(80);
20秒後に全ての接続でタイムアウトイベントが発生してレスポンスが返ってきました。エージェントのtimeoutはバックエンドサーバーに接続するとカウントされましたが、こちらはバックエンドサーバーに接続しているかどうかに関わらずカウントされるようです。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 --dump-header - http://***.***.***.***/?[1-300]
HTTP/1.1 408 Request Timeout
Content-Type: text/plain
Date: Sat, 08 Nov 2025 08:39:38 GMT
Connection: keep-alive
Keep-Alive: timeout=5
Transfer-Encoding: chunked
Request Timeout.
[...]
real 0m21.199s
user 0m0.084s
sys 0m0.302s
リクエストボディのサイズを256KBにしたスローHTTPリクエストを多重度300で送信してメモリ使用量の変化を確認します。まずは接続数の制限を行わずに送信します。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
real 1m4.731s
user 0m1.372s
sys 0m3.206s
BFFサーバーのメモリ使用量を確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセスのメモリ使用量（PSS）、青色がヒープメモリの使用量、オレンジ色がV8ヒープ外に確保されたメモリ使用量を表しています。バッファリングせずに転送しているため大きな変化はありません。
バックエンドサーバーのメモリ使用量を確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセスのメモリ使用量（PSS）、青色がヒープメモリの使用量、オレンジ色がV8ヒープ外に確保されたメモリ使用量を表しています。受信したデータ量相応の増加が見られます。
エージェントのmaxSocketsを100に設定してバックエンドへの接続数を制限した状態で同様に送信してみます。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
real 1m4.164s
user 0m1.246s
sys 0m3.301s
BFFサーバーのメモリ使用量を確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセスのメモリ使用量（PSS）、青色がヒープメモリの使用量、オレンジ色がV8ヒープ外に確保されたメモリ使用量を表しています。バックエンドに転送される接続数が制限されているため、それを超過する接続によってメモリ使用量が増加しています。
docker statsのAPIエンドポイントから取得したメモリ使用量の詳細の差分を確認すると、ヒープメモリの割り当てとソケットバッファが増加していることが分かります。
$ jq -s '
{
"USAGE (Total)": ((.[1].usage - .[0].usage) / 1048576),
"ANON (Heap/Stack)": ((.[1].stats.anon - .[0].stats.anon) / 1048576),
"FILE (Cache)": ((.[1].stats.file - .[0].stats.file) / 1048576),
"INACTIVE_FILE": ((.[1].stats.inactive_file - .[0].stats.inactive_file) / 1048576),
"FILE_DIRTY": ((.[1].stats.file_dirty - .[0].stats.file_dirty) / 1048576),
"SLAB": ((.[1].stats.slab - .[0].stats.slab) / 1048576),
"SOCK": ((.[1].stats.sock - .[0].stats.sock) / 1048576),
}
' before.json after.json
{
"USAGE (Total)": 61.7421875,
"ANON (Heap/Stack)": 39.26171875,
"FILE (Cache)": 0,
"INACTIVE_FILE": 0,
"FILE_DIRTY": 0,
"SLAB": 0.8085098266601562,
"SOCK": 21.265625
}
Chrome DevToolsで送信前後のヒープメモリのダンプを比較すると、外部メモリ領域（external）のC++バッファが増加していることが分かります。転送待ちとなっている接続のPOSTデータの一部をバッファリングしていると考えられます。
バックエンドサーバーのメモリ使用量を確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセスのメモリ使用量（PSS）、青色がヒープメモリの使用量、オレンジ色がV8ヒープ外に確保されたメモリ使用量を表しています。転送される接続数が100に制限されているため、制限なしの時と比較すると増加量は少なくなっていますが、受信したデータ量相応の増加が見られます。
Apache Tomcat
以下の構成で検証を行います。
クライアント Tomcat
検証には以下のJavaサーブレットを使用します。
package com.example;
import jakarta.servlet.ServletException;
import jakarta.servlet.annotation.WebServlet;
import jakarta.servlet.http.HttpServlet;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.InputStream;
import java.net.SocketTimeoutException;
import java.util.logging.Logger;
@WebServlet("/hello")
public class HelloServlet extends HttpServlet {
Logger log = Logger.getLogger(HelloServlet.class.getName());
protected void doPost(HttpServletRequest request, HttpServletResponse response)
throws ServletException, IOException {
int totalBytesRead = 0;
String name;
try (InputStream is = request.getInputStream();
ByteArrayOutputStream bos = new ByteArrayOutputStream()) {
final int BUFFER_SIZE = 4096;
byte[] buffer = new byte[BUFFER_SIZE];
int bytesRead;
while ((bytesRead = is.read(buffer)) != -1) {
totalBytesRead += bytesRead;
bos.write(buffer, 0, bytesRead);
}
name = bos.toString();
} catch (IOException e) {
log.info("Length: " + totalBytesRead);
if (e.getCause() instanceof SocketTimeoutException) {
response.setStatus(HttpServletResponse.SC_REQUEST_TIMEOUT);
} else {
response.setStatus(HttpServletResponse.SC_INTERNAL_SERVER_ERROR);
}
return;
}
log.info("Length: " + totalBytesRead);
response.setContentType("text/plain");
response.setCharacterEncoding("utf-8");
response.getWriter().println("Hello, " + name + "!");
}
}
まずは通常のリクエストを送信してみます。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/my-app/hello
HTTP/1.1 200
Content-Type: text/plain;charset=utf-8
Content-Length: 14
Date: Sun, 09 Nov 2025 07:14:21 GMT
Hello, qiita!
real 0m0.524s
user 0m0.045s
sys 0m0.045s
続いてスローHTTPリクエストを送信すると、20秒ほどでステータスコードの408が返ってきました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/my-app/hello
HTTP/1.1 408
Connection: close
Content-Length: 0
Date: Sun, 09 Nov 2025 08:27:32 GMT
real 0m20.356s
user 0m0.000s
sys 0m0.017s
Tomcatコンテナのログで受信したデータのバイト数を確認すると送信したバイト数と一致しています。
com.example.HelloServlet.doPost Length: 5
20秒ほどでタイムアウトしましたが、この秒数はTomcatの設定ファイルのserver.xmlで設定するHTTP ConnectorのconnectionTimeoutのデフォルト値の20秒が適用されています。
<Connector port="8080" protocol="HTTP/1.1"
connectionTimeout="20000"
redirectPort="8443" />
タイムアウトの秒数を60秒に変更して試してみます。
<Connector port="8080" protocol="HTTP/1.1"
connectionTimeout="60000"
redirectPort="8443" />
タイムアウトの時間が60秒に変化しました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/my-app/hello
HTTP/1.1 408
Connection: close
Content-Length: 0
Date: Sun, 09 Nov 2025 08:35:31 GMT
real 1m0.405s
user 0m0.005s
sys 0m0.020s
下図はconnectionTimeoutが20秒の時のビジー状態のスレッドの数（アクティブにタスクを実行しているスレッドのおよその数）です。スローHTTPリクエストで数が１つ増加していますが、タイムアウト後にさらに１つ上昇しています。
以下はサーブレット内で意図的に例外を発生させた場合のtcpdumpの結果です。クライアントにエラーレスポンスを返した後、FIN/ACKを送信しています。
3:34:42.855002 IP ***.***.***.***.*****.jp.63702 > cd76ad6dcde2.http-alt: Flags [S], seq 757311234, win 65280, options [...], length 0
03:34:42.855033 IP cd76ad6dcde2.http-alt > ***.***.***.***.*****.jp.63702: Flags [S.], seq 1376205678, ack 757311235, win 65160, options [...], length 0
03:34:43.030899 IP ***.***.***.***.*****.jp.63702 > cd76ad6dcde2.http-alt: Flags [.], ack 1, win 510, options [...], length 0
03:34:43.030902 IP ***.***.***.***.*****.jp.63702 > cd76ad6dcde2.http-alt: Flags [P.], seq 1:170, ack 1, win 510, options [...], length 161: HTTP: POST /my-app/hello HTTP/1.1
03:34:43.030954 IP cd76ad6dcde2.http-alt > ***.***.***.***.*****.jp.63702: Flags [.], ack 170, win 508, options [...], length 0
03:34:43.033262 IP cd76ad6dcde2.http-alt > ***.***.***.***.*****.jp.63702: Flags [P.], seq 1:93, ack 170, win 508, options [...], length 92: HTTP: HTTP/1.1 500
03:34:43.033699 IP cd76ad6dcde2.http-alt > ***.***.***.***.*****.jp.63702: Flags [F.], seq 93, ack 170, win 508, options [...], length 0
03:34:43.202349 IP ***.***.***.***.*****.jp.63702 > cd76ad6dcde2.http-alt: Flags [.], ack 93, win 510, options [...], length 0
03:34:43.202352 IP ***.***.***.***.*****.jp.63702 > cd76ad6dcde2.http-alt: Flags [F.], seq 170, ack 94, win 510, options [...], length 0
03:34:43.202387 IP cd76ad6dcde2.http-alt > ***.***.***.***.*****.jp.63702: Flags [.], ack 171, win 508, options [...], length 0
以下はスローHTTPリクエストでタイムアウトが発生した時のtcpdumpの結果です。クライアントにエラーレスポンスを返した後、さらに20秒経過してからクライアントにFIN/ACKを送信しています。
03:37:51.064649 IP ***.***.***.***.*****.jp.63642 > cd76ad6dcde2.http-alt: Flags [S], seq 642819272, win 65280, options [...], length 0
03:37:51.064688 IP cd76ad6dcde2.http-alt > ***.***.***.***.*****.jp.63642: Flags [S.], seq 2400472122, ack 642819273, win 65160, options [...], length 0
03:37:51.225481 IP ***.***.***.***.*****.jp.63642 > cd76ad6dcde2.http-alt: Flags [.], ack 1, win 510, options [...], length 0
03:37:51.225483 IP ***.***.***.***.*****.jp.63642 > cd76ad6dcde2.http-alt: Flags [P.], seq 1:170, ack 1, win 510, options [...], length 161: HTTP: POST /my-app/hello HTTP/1.1
03:37:51.225539 IP cd76ad6dcde2.http-alt > ***.***.***.***.*****.jp.63642: Flags [.], ack 170, win 508, options [...], length 0
03:38:11.228652 IP cd76ad6dcde2.http-alt > ***.***.***.***.*****.jp.63642: Flags [P.], seq 1:93, ack 170, win 508, options [...], length 92: HTTP: HTTP/1.1 408
03:38:11.390499 IP ***.***.***.***.*****.jp.63642 > cd76ad6dcde2.http-alt: Flags [.], ack 93, win 510, options [...], length 0
03:38:11.392823 IP ***.***.***.***.*****.jp.63642 > cd76ad6dcde2.http-alt: Flags [F.], seq 170, ack 93, win 510, options [...], length 0
03:38:11.433038 IP cd76ad6dcde2.http-alt > ***.***.***.***.*****.jp.63642: Flags [.], ack 171, win 508, options [...], length 0
03:38:31.229795 IP cd76ad6dcde2.http-alt > ***.***.***.***.*****.jp.63642: Flags [F.], seq 93, ack 171, win 508, options [...], length 0
03:38:31.392261 IP ***.***.***.***.*****.jp.63642 > cd76ad6dcde2.http-alt: Flags [.], ack 94, win 510, options [...], length 0
詳細なログを出力して比較してみます。以下はサーブレット内で意図的に例外を発生させた場合のログです。ソケットからデータを読み込んで、サーブレットが終了したらソケットをクローズしていることが分かります。
11-Nov-2025 03:34:43.031 FINER [http-nio-8080-Acceptor] org.apache.tomcat.util.threads.LimitLatch.countUpOrAwait Counting up[http-nio-8080-Acceptor] latch=1
11-Nov-2025 03:34:43.031 FINER [http-nio-8080-exec-7] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Processing socket [org.apache.tomcat.util.net.NioChannel@2f40e6e2:java.nio.channels.SocketChannel[connected local=/172.18.0.3:8080 remote=/***.***.***.***:63702]] with status [OPEN_READ]
[...]
11-Nov-2025 03:34:43.031 FINER [http-nio-8080-exec-7] org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@21870d7a:org.apache.tomcat.util.net.NioChannel@2f40e6e2:java.nio.channels.SocketChannel[connected local=/172.18.0.3:8080 remote=/***.***.***.***:63702]], Read direct from socket: [161]
11-Nov-2025 03:34:43.031 FINER [http-nio-8080-exec-7] org.apache.coyote.http11.Http11InputBuffer.fill Received [POST /my-app/hello HTTP/1.1
Host: ***.***.***.***
User-Agent: curl/7.68.0
Accept: */*
Content-Length: 5
Content-Type: application/x-www-form-urlencoded
qiita]
[...]
11-Nov-2025 03:34:43.033 FINER [http-nio-8080-exec-7] org.apache.coyote.AbstractProcessorLight.process Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@21870d7a:org.apache.tomcat.util.net.NioChannel@2f40e6e2:java.nio.channels.SocketChannel[connected local=/172.18.0.3:8080 remote=/***.***.***.***:63702]], Status in: [OPEN_READ], State out: [CLOSED]
11-Nov-2025 03:34:43.033 FINER [http-nio-8080-exec-7] org.apache.coyote.AbstractProtocol$ConnectionHandler.release Pushed Processor [org.apache.coyote.http11.Http11Processor@499964b5]
11-Nov-2025 03:34:43.033 FINER [http-nio-8080-exec-7] org.apache.tomcat.util.threads.LimitLatch.countDown Counting down[http-nio-8080-exec-7] latch=1
11-Nov-2025 03:34:43.033 FINER [http-nio-8080-exec-7] org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doClose Calling
以下はスローHTTPリクエストでタイムアウトが発生した時のログです。ソケットからデータを読み込んで20秒後のタイムアウト発生時にバッファからの最終読み込みのような処理が行われ、そこからさらに20秒後にSocketTimeoutExceptionが発生してソケットがクローズされています。
11-Nov-2025 03:37:51.225 FINER [http-nio-8080-Acceptor] org.apache.tomcat.util.threads.LimitLatch.countUpOrAwait Counting up[http-nio-8080-Acceptor] latch=1
11-Nov-2025 03:37:51.226 FINER [http-nio-8080-exec-8] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Processing socket [org.apache.tomcat.util.net.NioChannel@2a7acd9d:java.nio.channels.SocketChannel[connected local=/172.18.0.3:8080 remote=/***.***.***.***:63642]] with status [OPEN_READ]
[...]
11-Nov-2025 03:37:51.226 FINER [http-nio-8080-exec-8] org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@24bd36a2:org.apache.tomcat.util.net.NioChannel@2a7acd9d:java.nio.channels.SocketChannel[connected local=/172.18.0.3:8080 remote=/***.***.***.***:63642]], Read direct from socket: [161]
11-Nov-2025 03:37:51.226 FINER [http-nio-8080-exec-8] org.apache.coyote.http11.Http11InputBuffer.fill Received [POST /my-app/hello HTTP/1.1
Host: ***.***.***.***
User-Agent: curl/7.68.0
Accept: */*
Content-Length: 6
Content-Type: application/x-www-form-urlencoded
qiita]
[...]
11-Nov-2025 03:38:11.229 FINER [http-nio-8080-exec-8] org.apache.coyote.http11.Http11InputBuffer.fill Before fill(): parsingHeader: [false], parsingRequestLine: [false], parsingRequestLinePhase: [0], parsingRequestLineStart: [0], byteBuffer.position(): [164], byteBuffer.limit(): [164], end: [164]
11-Nov-2025 03:38:11.229 FINER [http-nio-8080-exec-8] org.apache.tomcat.util.net.SocketWrapperBase.populateReadBuffer Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@24bd36a2:org.apache.tomcat.util.net.NioChannel@2a7acd9d:java.nio.channels.SocketChannel[connected local=/172.18.0.3:8080 remote=/***.***.***.***:63642]], Read from buffer: [0]
[...]
11-Nov-2025 03:38:31.229 FINE [http-nio-8080-exec-8] org.apache.coyote.AbstractProcessor.setErrorState Error state [CLOSE_CONNECTION_NOW] reported while processing request
java.net.SocketTimeoutException
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.fillReadBuffer(NioEndpoint.java:1306)
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read(NioEndpoint.java:1223)
at org.apache.coyote.http11.Http11InputBuffer.fill(Http11InputBuffer.java:776)
at org.apache.coyote.http11.Http11InputBuffer$SocketInputBuffer.doRead(Http11InputBuffer.java:829)
at org.apache.coyote.http11.filters.IdentityInputFilter.end(IdentityInputFilter.java:146)
at org.apache.coyote.http11.Http11InputBuffer.endRequest(Http11InputBuffer.java:622)
at org.apache.coyote.http11.Http11Processor.endRequest(Http11Processor.java:1197)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:437)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:903)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1778)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:946)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:480)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:57)
at java.base/java.lang.Thread.run(Thread.java:1583)
11-Nov-2025 03:38:31.229 FINER [http-nio-8080-exec-8] org.apache.coyote.AbstractProcessorLight.process Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@24bd36a2:org.apache.tomcat.util.net.NioChannel@2a7acd9d:java.nio.channels.SocketChannel[connected local=/172.18.0.3:8080 remote=/***.***.***.***:63642]], Status in: [OPEN_READ], State out: [CLOSED]
11-Nov-2025 03:38:31.229 FINER [http-nio-8080-exec-8] org.apache.coyote.AbstractProtocol$ConnectionHandler.release Pushed Processor [org.apache.coyote.http11.Http11Processor@499964b5]
11-Nov-2025 03:38:31.229 FINER [http-nio-8080-exec-8] org.apache.tomcat.util.threads.LimitLatch.countDown Counting down[http-nio-8080-exec-8] latch=1
11-Nov-2025 03:38:31.229 FINER [http-nio-8080-exec-8] org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doClose Calling
netcatでcurlと同じリクエストを送信してみるとタイムアウトの20秒でレスポンスヘッダーを受け取った後も接続はクローズされず、2倍の40秒で接続がクローズされることが確認できます。
#!/bin/bash
HOST="***.***.***.***"
PORT="80"
{
echo -ne "POST /my-app/hello HTTP/1.1\r\nHost: $HOST\r\nConnection: close\r\nContent-Type: text/plain\r\nContent-Length: 6\r\n\r\n"
echo -n "hello"
} | nc $HOST $PORT
$ time ./slow_http_post.sh
HTTP/1.1 408
Connection: close
Content-Length: 0
Date: Tue, 11 Nov 2025 04:11:20 GMT
real 0m40.364s
user 0m0.017s
sys 0m0.019s
ただし、WSLのDocker環境で同様のスローHTTPリクエストを送信すると、20秒後のタイムアウト発生時にバッファからの最終読み込みのような処理が行われるところまでは同じなのですが、その後すぐにEOFExceptionが発生してソケットがクローズされます。
14-Nov-2025 09:23:55.812 FINER [http-nio-8080-exec-2] org.apache.tomcat.util.net.SocketWrapperBase.populateReadBuffer Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@24948d79:org.apache.tomcat.util.net.NioChannel@2a536643:java.nio.channels.SocketChannel[connected local=/172.18.0.2:8080 remote=/172.18.0.1:55018]], Read from buffer: [0]
14-Nov-2025 09:23:55.812 FINE [http-nio-8080-exec-2] org.apache.coyote.AbstractProcessor.setErrorState Error state [CLOSE_CONNECTION_NOW] reported while processing request
java.io.EOFException
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.fillReadBuffer(NioEndpoint.java:1312)
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read(NioEndpoint.java:1223)
at org.apache.coyote.http11.Http11InputBuffer.fill(Http11InputBuffer.java:776)
at org.apache.coyote.http11.Http11InputBuffer$SocketInputBuffer.doRead(Http11InputBuffer.java:829)
at org.apache.coyote.http11.filters.IdentityInputFilter.end(IdentityInputFilter.java:146)
at org.apache.coyote.http11.Http11InputBuffer.endRequest(Http11InputBuffer.java:622)
at org.apache.coyote.http11.Http11Processor.endRequest(Http11Processor.java:1197)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:437)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:903)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1778)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:946)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:480)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:57)
at java.base/java.lang.Thread.run(Thread.java:1583)
14-Nov-2025 09:23:55.812 FINER [http-nio-8080-exec-2] org.apache.coyote.AbstractProcessorLight.process Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@24948d79:org.apache.tomcat.util.net.NioChannel@2a536643:java.nio.channels.SocketChannel[connected local=/172.18.0.2:8080 remote=/172.18.0.1:55018]], Status in: [OPEN_READ], State out: [CLOSED]
14-Nov-2025 09:23:55.812 FINER [http-nio-8080-exec-2] org.apache.coyote.AbstractProtocol$ConnectionHandler.release Pushed Processor [org.apache.coyote.http11.Http11Processor@2a7ccabd]
14-Nov-2025 09:23:55.813 FINER [http-nio-8080-exec-2] org.apache.tomcat.util.threads.LimitLatch.countDown Counting down[http-nio-8080-exec-2] latch=1
14-Nov-2025 09:23:55.813 FINER [http-nio-8080-exec-2] org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doClose Calling [org.apache.tomcat.util.net.NioEndpoint@773cbf4f].closeSocket([org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@24948d79:org.apache.tomcat.util.net.NioChannel@2a536643:java.nio.channels.SocketChannel[connected local=/172.18.0.2:8080 remote=/172.18.0.1:55018]])
クラウドサーバーとWSLでreadのシステムコールをトレースしてみるとクラウドサーバーの方ではセグメンテーション違反 (SIGSEGV) が発生しています。カーネルのバージョンなど環境依存の現象かもしれません。
# クラウドサーバー
$ strace -f -e trace=read -p <TomcatのPID>
[pid 51] read(60, "POST /my-app/hello HTTP/"..., 8192) = 161
[pid 51] read(60, 0x707b6805eaf0, 8192) = -1 EAGAIN (Resource temporarily unavailable)
[pid 51] --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0x8} ---
[pid 51] read(60, 0x707b6805eaf0, 8192) = -1 EAGAIN (Resource temporarily unavailable)
# WSL
$ strace -f -e trace=read -p <TomcatのPID>
[pid 55] read(16, "POST /my-app/hello HTTP/"..., 8192) = 161
[pid 55] read(16, 0x79b0e0000ff0, 8192) = -1 EAGAIN (Resource temporarily unavailable)
[pid 55] read(16, "", 8192) = 0
リクエストボディのサイズを大きくしてスローHTTPリクエストを送信してみます。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --dump-header - http://***.***.***.***/my-app/hello
HTTP/1.1 408
[...]
real 0m21.281s
user 0m0.006s
sys 0m0.015s
tcpdumpで確認すると、小さいサイズの時とは異なりエラーレスポンスを返した後にすぐにクライアントにFIN/ACKを送信しています。
[...]
02:14:46.359276 IP ***.***.***.***.*****.jp.62222 > a6cc30288fe7.http-alt: Flags [P.], seq 261756:262336, ack 18, win 510, options [...], length 580: HTTP
02:14:46.359297 IP a6cc30288fe7.http-alt > ***.***.***.***.*****.jp.62222: Flags [.], ack 262336, win 4106, options [...], length 0
02:15:06.361349 IP a6cc30288fe7.http-alt > ***.***.***.***.*****.jp.62222: Flags [P.], seq 18:110, ack 262336, win 4106, options [...], length 92: HTTP: HTTP/1.1 408
02:15:06.361962 IP a6cc30288fe7.http-alt > ***.***.***.***.*****.jp.62222: Flags [F.], seq 110, ack 262336, win 4106, options [...], length 0
02:15:06.534066 IP ***.***.***.***.*****.jp.62222 > a6cc30288fe7.http-alt: Flags [F.], seq 262336, ack 110, win 510, options [...], length 0
02:15:06.534099 IP a6cc30288fe7.http-alt > ***.***.***.***.*****.jp.62222: Flags [.], ack 262337, win 4106, options [...], length 0
ログを確認するとタイムアウト時にソケットがクローズされています。
12-Nov-2025 02:15:06.361 FINER [http-nio-8080-exec-2] org.apache.coyote.AbstractProcessorLight.process Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@396e48db:org.apache.tomcat.util.net.NioChannel@37a9a05e:java.nio.channels.SocketChannel[connected local=/172.18.0.2:8080 remote=/***.***.***.***:62222]], Status in: [OPEN_READ], State out: [CLOSED]
12-Nov-2025 02:15:06.361 FINER [http-nio-8080-exec-2] org.apache.coyote.AbstractProtocol$ConnectionHandler.release Pushed Processor [org.apache.coyote.http11.Http11Processor@499964b5]
12-Nov-2025 02:15:06.361 FINER [http-nio-8080-exec-2] org.apache.tomcat.util.threads.LimitLatch.countDown Counting down[http-nio-8080-exec-2] latch=1
12-Nov-2025 02:15:06.361 FINER [http-nio-8080-exec-2] org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doClose Calling [org.apache.tomcat.util.net.NioEndpoint@a5b0b86].closeSocket([org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@396e48db:org.apache.tomcat.util.net.NioChannel@37a9a05e:java.nio.channels.SocketChannel[connected local=/172.18.0.2:8080 remote=/***.***.***.***:62222]])
curlのバージョンによっては大きいサイズをPOSTする時に自動的にExpect: 100-continueヘッダーを送信します。このヘッダーを送信しないようにして試してみます。
$ time curl -X POST -H "Expect:" -H "Content-Length: 262145" -d @256kb.txt --dump-header - http://***.***.***.***/my-app/hello
HTTP/1.1 408
[...]
real 0m21.172s
user 0m0.015s
sys 0m0.010s
今度は小さいサイズの時と同じようにソケットのクローズに遅延が発生しました。Expect: 100-continueヘッダーの有無によって接続のクローズの処理が変わるようです。
12:00:34.608067 IP 04321ba3604c.http-alt > ***.***.***.***.*****.jp.56206: Flags [P.], seq 1:93, ack 262314, win 4120, options [...], length 92: HTTP: HTTP/1.1 408
12:00:34.790757 IP ***.***.***.***.*****.jp.56206 > 04321ba3604c.http-alt: Flags [.], ack 93, win 510, options [...], length 0
12:00:34.790774 IP ***.***.***.***.*****.jp.56206 > 04321ba3604c.http-alt: Flags [F.], seq 262314, ack 93, win 510, options [...], length 0
12:00:34.831075 IP 04321ba3604c.http-alt > ***.***.***.***.*****.jp.56206: Flags [.], ack 262315, win 4120, options [...], length 0
12:00:54.609334 IP 04321ba3604c.http-alt > ***.***.***.***.*****.jp.56206: Flags [F.], seq 93, ack 262315, win 4120, options [...], length 0
12:00:54.782209 IP ***.***.***.***.*****.jp.56206 > 04321ba3604c.http-alt: Flags [.], ack 94, win 510, options [...], length 0
小さいチャンクに分割してゆっくり送信してみます。300バイトのデータを1秒おきに1バイトずつ送信すると、タイムアウトが発生することなくリクエストが完了しました。
$ time ./slow_http_post.sh 300 1
HTTP/1.1 200
Content-Type: text/plain;charset=utf-8
Content-Length: 309
Date: Sun, 09 Nov 2025 08:42:16 GMT
Connection: close
Hello, aaaaaaaaaaaaaaaaaaaa[...]aaaaaaaaaaaaaaaaaaaaaa!
real 5m1.316s
user 0m0.391s
sys 0m0.929s
多重度を上げてサーバーリソースの変化を確認します。まずはスローHTTPリクエストを多重度300で送信します。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 --dump-header - http://***.***.***.***/my-app/hello?[1-300]
[...]
HTTP/1.1 408
Connection: close
Content-Length: 0
Date: Sun, 09 Nov 2025 09:05:50 GMT
real 1m0.536s
user 0m0.124s
sys 0m0.309s
ビジー状態のスレッドが200まで増加し、その後130ほどに減少した後に0に戻りました。
スローHTTPリクエスト送信中に通常のリクエストを送信すると、スレッドに空きがないため遅延が発生して40秒ほど掛かりました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/my-app/hello
HTTP/1.1 200
Content-Type: text/plain;charset=utf-8
Content-Length: 0
Date: Tue, 11 Nov 2025 07:08:49 GMT
Hello, qiita!
real 0m39.542s
user 0m0.000s
sys 0m0.028s
スレッド数が200までしか増加しなかったのはHTTP ConnectorのmaxThreadsのデフォルト値200が適用されているためです。
最大スレッド数を350に変更して送信してみます。
<Connector port="8080" protocol="HTTP/1.1"
connectionTimeout="20000"
maxThreads="350"
redirectPort="8443" />
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/my-app/hello?[1-300]
[...]
real 0m21.527s
user 0m0.112s
sys 0m0.316s
ビジー状態のスレッドが300まで増加し、全ての接続が完了するまでの時間も短くなりました。スレッド数が一気に0に戻らずに一旦60ほどになっているのは先のテストで確認したソケットのクローズの遅延によるものと考えられます。
maxConnectionsとacceptCount（backlog）も設定してみます。
<Connector port="8080" protocol="HTTP/1.1"
connectionTimeout="20000"
maxThreads="350"
maxConnections="100"
acceptCount="50"
redirectPort="8443" />
多重度300で送信すると複数の接続がサーバーからリセットされました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/my-app/hello?[1-300]
[...]
real 2m18.813s
user 0m0.159s
sys 0m0.368s
リクエスト直後のTomcatコンテナのネットワークソケットの状態を確認すると、accept待ちの接続がacceptCountで設定したの50に達しています。TCP接続数はmaxConnectionsの100とacceptCountを足した150になっています。そのうち、ソケットバッファに滞留している接続が50確認できます。
$ ss -t state listening
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 4096 127.0.0.11:40783 0.0.0.0:*
50 50 *:http-alt *:*
$ ss -ntH state established 'sport = 8080' | wc -l
150
$ ss -ntH state established 'sport = 8080' | awk '{ if ($1 != 0) print }' | wc -l
50
クライアント側のネットワークソケットの状態を確認すると、300のリクエストのうち接続要求を送信した接続が4、確立した接続が296、確立した接続のうちソケットバッファに滞留している接続が146となっています。
$ ss -ntH state syn-sent 'dport = 80' | wc -l
4
$ ss -ntH state established 'dport = 80' | wc -l
296
$ ss -ntH state established 'dport = 80' | awk '{ if ($2 != 0) print }' | wc -l
146
ビジー状態のスレッドを確認すると、200に到達する山が2回発生しています。ビジースレッドの山に合わせてWAITINGのスレッドも増加しています。
送信直後にTIMED_WAITINGが増加した時のスレッドダンプを確認すると入力ストリームを読み込むところで待機していることが分かります。
$ jstack -l <TomcaのPID>
[...]
"http-nio-8080-exec-546" #581 [3534] daemon prio=5 os_prio=0 cpu=0.41ms elapsed=24.70s tid=0x00007fa40810e030 nid=3534 in Object.wait() [0x00007fa3774fd000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait0(java.base@21.0.9/Native Method)
- waiting on <no object reference available>
at java.lang.Object.wait(java.base@21.0.9/Object.java:366)
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.fillReadBuffer(NioEndpoint.java:1322)
- locked <0x00000000c6820ce8> (a java.util.concurrent.Semaphore)
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read(NioEndpoint.java:1223)
at org.apache.coyote.http11.Http11InputBuffer.fill(Http11InputBuffer.java:776)
at org.apache.coyote.http11.Http11InputBuffer$SocketInputBuffer.doRead(Http11InputBuffer.java:829)
at org.apache.coyote.http11.filters.IdentityInputFilter.doRead(IdentityInputFilter.java:94)
at org.apache.coyote.http11.Http11InputBuffer.doRead(Http11InputBuffer.java:229)
at org.apache.coyote.Request.doRead(Request.java:681)
at org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:294)
at org.apache.catalina.connector.InputBuffer.checkByteBufferEof(InputBuffer.java:590)
at org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:348)
at org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:81)
at org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:74)
at com.example.HelloServlet.doPost(HelloServlet.java:28)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:649)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:710)
[...]
その後のWAITINGが増加した時のスレッドダンプを確認してみます。TIMED_WAITINGのスレッドを確認するとソケットのリードで待機していますが、入力ストリームの読み込みではないようです。WAITINGのスレッドを確認するとTomcatのSocketProcessorがソケットを処理しようとしてロック競合が発生しているようです。
$ jstack -l <TomcaのPID>
[...]
"http-nio-8080-exec-274" #309 [6690] daemon prio=5 os_prio=0 cpu=0.99ms elapsed=36.74s tid=0x00007696840b9660 nid=6690 in Object.wait() [0x0000769638efd000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait0(java.base@21.0.9/Native Method)
- waiting on <no object reference available>
at java.lang.Object.wait(java.base@21.0.9/Object.java:366)
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.fillReadBuffer(NioEndpoint.java:1322)
- locked <0x00000000c62d95e8> (a java.util.concurrent.Semaphore)
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read(NioEndpoint.java:1223)
at org.apache.coyote.http11.Http11InputBuffer.fill(Http11InputBuffer.java:776)
at org.apache.coyote.http11.Http11InputBuffer$SocketInputBuffer.doRead(Http11InputBuffer.java:829)
at org.apache.coyote.http11.filters.IdentityInputFilter.end(IdentityInputFilter.java:146)
at org.apache.coyote.http11.Http11InputBuffer.endRequest(Http11InputBuffer.java:622)
at org.apache.coyote.http11.Http11Processor.endRequest(Http11Processor.java:1197)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:437)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:903)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1778)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:946)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:480)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:57)
at java.lang.Thread.runWith(java.base@21.0.9/Thread.java:1596)
at java.lang.Thread.run(java.base@21.0.9/Thread.java:1583)
[...]
"http-nio-8080-exec-389" #424 [6830] daemon prio=5 os_prio=0 cpu=0.06ms elapsed=16.65s tid=0x0000769684127d40 nid=6830 waiting on condition [0x00007695ef2fe000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@21.0.9/Native Method)
- parking to wait for <0x00000000c6006e10> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(java.base@21.0.9/LockSupport.java:221)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@21.0.9/AbstractQueuedSynchronizer.java:788)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@21.0.9/AbstractQueuedSynchronizer.java:1024)
at java.util.concurrent.locks.ReentrantLock$Sync.lock(java.base@21.0.9/ReentrantLock.java:153)
at java.util.concurrent.locks.ReentrantLock.lock(java.base@21.0.9/ReentrantLock.java:322)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:42)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:946)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:480)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:57)
at java.lang.Thread.runWith(java.base@21.0.9/Thread.java:1596)
at java.lang.Thread.run(java.base@21.0.9/Thread.java:1583)
[...]
はっきりしたことは分かりませんが、タイムアウト発生でエラーレスポンスは返したもののソケットはクローズされずにロックされたままでTIMED_WAITINGになり（この時点でmaxConnectionsのカウントは-1される）、待機していた別の接続がそのソケットのロックを取得しようとしてWAITINGになっているのかもしれません。
設定を以下の状態に戻してリクエストボディのサイズを256KBにしたスローHTTPリクエストを多重度300で送信してみます。
<Connector port="8080" protocol="HTTP/1.1"
connectionTimeout="20000"
maxThreads="350"
redirectPort="8443" />
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/my-app/hello?[1-300]
[...]
real 1m23.333s
user 0m1.226s
sys 0m3.089s
メモリ使用量を確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセスのメモリ使用量（RSS）、青色がヒープメモリの使用量を表しています。ヒープメモリの使用量の増加に合わせてコンテナやプロセスのメモリ使用量も同じように増加しています。
メモリプールを確認してみます。下図の緑色がEden領域、黄色がOld領域を表しています。リクエスト直後から短時間でOld領域が増加しています。
GCのログを確認するとEden領域の圧迫によるOld領域への早期昇格が起こっていることが分かります。ただ、最終的にはコンカレントGCでOld領域は回収されており、通常のリクエストを多重度300で送信した時と比較して目立った変化は確認できません。
[...]
[444.290s][info ][gc,heap] GC(24) Eden regions: 84->0(51)
[444.290s][trace][gc,heap] GC(24) Used: 0K, Waste: 0K
[444.290s][info ][gc,heap] GC(24) Survivor regions: 3->11(11)
[444.290s][trace][gc,heap] GC(24) Used: 11264K, Waste: 0K
[444.290s][info ][gc,heap] GC(24) Old regions: 47->76
[444.290s][trace][gc,heap] GC(24) Used: 77312K, Waste: 512K
[444.290s][info ][gc,heap] GC(24) Humongous regions: 0->0
[444.290s][trace][gc,heap] GC(24) Used: 0K, Waste: 0K
[...]
[444.384s][info ][gc,heap] GC(25) Eden regions: 51->0(54)
[444.384s][trace][gc,heap] GC(25) Used: 0K, Waste: 0K
[444.384s][info ][gc,heap] GC(25) Survivor regions: 11->2(8)
[444.384s][trace][gc,heap] GC(25) Used: 1581K, Waste: 466K
[444.384s][info ][gc,heap] GC(25) Old regions: 76->88
[444.384s][trace][gc,heap] GC(25) Used: 89164K, Waste: 947K
[444.384s][info ][gc,heap] GC(25) Humongous regions: 0->0
[444.384s][trace][gc,heap] GC(25) Used: 0K, Waste: 0K
[...]
[469.322s][info ][gc,heap] GC(31) Eden regions: 39->0(16)
[469.322s][trace][gc,heap] GC(31) Used: 0K, Waste: 0K
[469.322s][info ][gc,heap] GC(31) Survivor regions: 6->6(6)
[469.322s][trace][gc,heap] GC(31) Used: 6144K, Waste: 0K
[469.322s][info ][gc,heap] GC(31) Old regions: 124->161
[469.322s][trace][gc,heap] GC(31) Used: 164607K, Waste: 256K
[469.322s][info ][gc,heap] GC(31) Humongous regions: 0->0
[469.322s][trace][gc,heap] GC(31) Used: 0K, Waste: 0K
[...]
[472.744s][info ][gc,heap] GC(33) Eden regions: 16->0(34)
[472.744s][trace][gc,heap] GC(33) Used: 0K, Waste: 0K
[472.744s][info ][gc,heap] GC(33) Survivor regions: 6->3(3)
[472.744s][trace][gc,heap] GC(33) Used: 3072K, Waste: 0K
[472.744s][info ][gc,heap] GC(33) Old regions: 156->174
[472.744s][trace][gc,heap] GC(33) Used: 178073K, Waste: 102K
[472.744s][info ][gc,heap] GC(33) Humongous regions: 0->0
[472.744s][trace][gc,heap] GC(33) Used: 0K, Waste: 0K
[...]
[624.284s][info ][gc,heap] GC(43) Eden regions: 149->0(161)
[624.284s][trace][gc,heap] GC(43) Used: 0K, Waste: 0K
[624.284s][info ][gc,heap] GC(43) Survivor regions: 1->1(19)
[624.284s][trace][gc,heap] GC(43) Used: 474K, Waste: 549K
[624.284s][info ][gc,heap] GC(43) Old regions: 82->58
[624.284s][trace][gc,heap] GC(43) Used: 59337K, Waste: 54K
[624.284s][info ][gc,heap] GC(43) Humongous regions: 0->0
[624.284s][trace][gc,heap] GC(43) Used: 0K, Waste: 0K
[...]
小さいチャンクに分割してゆっくり送信してみます。256KBのデータを1KBずつ多重度300で送信します。
$ time seq 300 | xargs -I{} echo "1024" | parallel -j 300 './slow_http_post.sh 262144 {}'
[...]
real 6m14.474s
user 22m43.204s
sys 9m1.329s
メモリ使用量を確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセスのメモリ使用量（RSS）、青色がヒープメモリの使用量を表しています。ゆっくり送信したので増加はなだらかですが、一気に送信した時と比較して目立った変化は確認できません。
メモリプールを確認してみます。下図の緑色がEden領域、黄色がOld領域を表しています。こちらもOld領域の増加がなだらかになっていますが目立った変化は確認できません。
プログラムを少し変更して試してみます。最初のプログラムではgetInputStreamから読み込んでいましたが、今度はgetParameterを使用してパラメーターから直接読み込むようにします。
@WebServlet("/hello")
public class HelloServlet extends HttpServlet {
Logger log = Logger.getLogger(HelloServlet.class.getName());
protected void doPost(HttpServletRequest request, HttpServletResponse response)
throws ServletException, IOException {
String name = request.getParameter("name");
log.info("Length: " + name.length());
response.setContentType("text/plain");
response.setCharacterEncoding("utf-8");
response.getWriter().println("Hello, " + name + "!");
}
}
まずは256KBのスローHTTPリクエストを多重度300で送信してみます。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/my-app/hello?[1-300]
[...]
real 1m24.430s
user 0m1.309s
sys 0m3.274s
メモリ使用量を確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセスのメモリ使用量（RSS）、青色がヒープメモリの使用量を表しています。ヒープメモリの使用量の増加に合わせてコンテナやプロセスのメモリ使用量も同じように増加しています。getInputStreamを使用した場合よりも短時間で増加しているように見えます。
メモリプールを確認してみます。下図の緑色がEden領域、黄色がOld領域を表しています。リクエスト直後から短時間でOld領域が増加しています。こちらも同様にgetInputStreamを使用した場合よりも短時間で増加しているように見えます。
小さいチャンクに分割してゆっくり送信してみます。256KBのデータを1KBずつ多重度300で送信します。
$ time seq 300 | xargs -I{} echo "1024" | parallel -j 300 './slow_http_post.sh 262144 {}'
[...]
real 5m40.933s
user 20m34.145s
sys 7m33.784s
メモリ使用量を確認してみます。下図の緑色がコンテナのメモリ使用量、黄色がプロセスのメモリ使用量（RSS）、青色がヒープメモリの使用量を表しています。getInputStreamを使用した場合よりも短時間で増加していることがはっきりと表れています。
メモリプールを確認してみます。下図の緑色がEden領域、黄色がOld領域を表しています。こちらも同様に短時間で増加していることがはっきりと表れています。加えてOld領域が回収されないままの状態が続いていることも確認できます。
メモリ使用量が短時間で増加する可能性としてまず思いつくのは、頻繁なメモリアロケーションを避けるなどの目的で入力ストリームを格納するバッファの初期サイズをContent-Lengthヘッダーのサイズで作成しているということではないかと思います。そこで実際に送信するリクエストボディのサイズを大幅に超えるサイズをContent-Lengthヘッダーに設定して送信してみます。
$ time curl -X POST -H "Content-Length: 1048576" -d "name=qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/my-app/hello?[1-300]
[...]
real 0m21.598s
user 0m0.135s
sys 0m0.458s
下図の緑色がgetParameterを使用した場合のOld領域の使用量、黄色がgetInputStreamを使用した場合のOld領域の使用量を表しています。getParameterを使用した方が一時的に大幅に増加していることが分かります。
ヒープ領域の最大サイズを1GBに設定してContent-Lengthヘッダーを5MB、多重度300の計1500MBで送信してみます。
CATALINA_OPTS="-Xms1g -Xmx1g ...."
$ time curl -X POST -H "Content-Length: 5242880" -d "name=qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/my-app/hello?[1-300]
[...]
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
OutOfMemoryErrorが発生してTomcatが応答しなくなりました。
13-Nov-2025 02:55:05.368 SEVERE [http-nio-8080-exec-162] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Failed to complete processing of a request
java.lang.OutOfMemoryError: Java heap space
at org.apache.catalina.connector.Request.doParseParameters(Request.java:2966)
at org.apache.catalina.connector.Request.parseParameters(Request.java:2864)
at org.apache.catalina.connector.Request.getParameter(Request.java:1095)
at org.apache.catalina.connector.RequestFacade.getParameter(RequestFacade.java:149)
at com.example.HelloNewServlet.doPost(HelloNewServlet.java:20)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:649)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:710)
[...]
小さいチャンクに分割して送信した時にOld領域が回収されないままの状態が続きましたが、これはスローHTTPリクエストが影響している訳ではなく、processorCacheがデフォルトで有効になっているからです。Tomcatはパフォーマンス最適化のために様々なオブジェクトをリクエストのたびに生成せずにキャッシュして再利用します。
送信が完了して10分くらい経過した状態でヒープメモリのダンプを取得してEclipse Memory Analyzer Toolで確認してみます。
$ jcmd <TomcaのPID> GC.heap_dump heap_dump.hprof
OQLを実行してorg.apache.coyote.Requestを検索すると200件のリクエストがキャッシュされていることが確認できます（processorCacheのデフォルト値が200）。
SELECT * FROM INSTANCEOF org.apache.coyote.Request
Class Name | Shallow Heap | Retained Heap
---------------------------------------------------------------------
org.apache.coyote.Request @ 0xc4e45a20| 208 | 265,320
org.apache.coyote.Request @ 0xc4ea0440| 208 | 265,320
org.apache.coyote.Request @ 0xc4ee7748| 208 | 265,320
org.apache.coyote.Request @ 0xc4ef0c50| 208 | 265,320
org.apache.coyote.Request @ 0xc4f50478| 208 | 265,320
org.apache.coyote.Request @ 0xc4f734e0| 208 | 265,320
org.apache.coyote.Request @ 0xc4f737a8| 208 | 265,320
org.apache.coyote.Request @ 0xc4fd4620| 208 | 265,320
[...]
org.apache.coyote.Request @ 0xff1a8018| 208 | 265,320
org.apache.coyote.Request @ 0xff1af430| 208 | 265,320
Total: 200 entries | |
---------------------------------------------------------------------
org.apache.coyote.Requestの中身をparameters ⇒ tmpValueの順で辿っていくとバッファにリクエスト内容がキャッシュされていることが確認できます。
SELECT * FROM OBJECTS 217072
Class Name | Shallow Heap | Retained Heap
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
byte[262144] @ 0xc6eb6850 name=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa...| 262,160 | 262,160
Total: 1 entry | |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Tomcatのソースコードを確認した訳ではないため確証はありませんが、POSTパラメーターなどストリームから取り出してバッファに格納したデータは、次のリクエストでキャッシュが再利用されるまではクリアされずにメモリ上に残ったままになるようです（チャンクに分割せずに送信した時はタイムアウトエラーでバッファに格納する前に処理が終了したため、Old領域が回収されているように見えたのではないかと思います）。
キャッシュを無効にして試してみます。
<Connector port="8080" protocol="HTTP/1.1"
processorCache="0"
connectionTimeout="20000"
maxThreads="350"
redirectPort="8443" />
OQLを実行してorg.apache.coyote.Requestを検索すると0件になりました。
SELECT * FROM INSTANCEOF org.apache.coyote.Request
Your Query did not yield any result.
TomcatはExecutorが管理するスレッド上でリクエストを処理します。Executorが使用するスレッドのデフォルトはプラットフォーム・スレッドですが仮想スレッドも使用できますので仮想スレッドも検証してみます。
<Executor name="tomcatThreadPool"
className="org.apache.catalina.core.StandardVirtualThreadExecutor"/>
<Connector port="8080" protocol="HTTP/1.1"
executor="tomcatThreadPool"
connectionTimeout="20000"
maxThreads="350"
redirectPort="8443" />
256KBのスローHTTPリクエストを多重度300で送信してみます。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/my-app/hello?[1-300]
[...]
real 1m33.441s
user 0m1.314s
sys 0m3.443s
仮想スレッドはTomcatのThread Pools Metricsでは計測できないためビジー状態のスレッドは確認できませんが、スレッド数が250ほど増加しています。スレッドプールのスレッド数の最大値のデフォルトが256になっていますので、仮想スレッドが上限値まで起動したと考えられます（StandardVirtualThreadExecutorにはmaxThreadsの設定がないため、ConnectorのmaxThreadsの設定は無視されます）。
メモリ使用量も確認してみます。こちらはプラットフォーム・スレッドと比較して目立った変化は確認できません。
使用しているJavaのバージョンを Java 21 から Java 25 に変更して試してみます。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/my-app/hello?[1-300]
[...]
real 1m21.692s
user 0m1.440s
sys 0m3.212s
スレッド数がほとんど変化していません。これはJava24で仮想スレッドの改良が行われた効果によるものです（JEP 491: Synchronize Virtual Threads without Pinning）。従来はsynchronizedやReentrantLockを使うと仮想スレッドがプラットフォームスレッドを占有してしまうピン止め（pinning）の問題がありましたが、Java24からはこのピン止めが避けられるようになり、同期コードでもスケールしやすくなっています。
メモリ使用量も確認してみます。こちらはJava21と比較して目立った変化は確認できません。
以下のようにプログラムを修正して非同期I/Oを使用した場合も検証してみます。
package com.example;
import jakarta.servlet.AsyncContext;
import jakarta.servlet.AsyncEvent;
import jakarta.servlet.AsyncListener;
import jakarta.servlet.ReadListener;
import jakarta.servlet.ServletException;
import jakarta.servlet.ServletInputStream;
import jakarta.servlet.annotation.WebServlet;
import jakarta.servlet.http.HttpServlet;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.PrintWriter;
import java.util.logging.Logger;
@WebServlet(urlPatterns = "/hello", asyncSupported = true)
public class HelloServlet extends HttpServlet {
Logger log = Logger.getLogger(HelloServlet.class.getName());
@Override
protected void doPost(HttpServletRequest request, HttpServletResponse response)
throws ServletException, IOException {
final AsyncContext asyncContext = request.startAsync(request, response);
asyncContext.addListener(new AsyncListener() {
@Override
public void onComplete(AsyncEvent event) throws IOException {
log.info("Async complete");
}
@Override
public void onTimeout(AsyncEvent event) throws IOException {
log.info("Timeout");
HttpServletResponse res = (HttpServletResponse) event.getAsyncContext().getResponse();
res.sendError(HttpServletResponse.SC_REQUEST_TIMEOUT);
}
@Override
public void onError(AsyncEvent event) throws IOException {
log.info("Error: " + event.getThrowable());
}
@Override
public void onStartAsync(AsyncEvent event) throws IOException {
log.info("Async started");
}
});
ServletInputStream is = request.getInputStream();
ReadListener readListener = new ReadListener() {
final int BUFFER_SIZE = 1024 * 4;
private final byte[] buffer = new byte[BUFFER_SIZE];
int totalBytesRead = 0;
ByteArrayOutputStream bos = new ByteArrayOutputStream();
@Override
public void onDataAvailable() throws IOException {
int bytesRead;
while (is.isReady() && (bytesRead = is.read(buffer)) != -1) {
totalBytesRead += bytesRead;
bos.write(buffer, 0, bytesRead);
}
}
@Override
public void onAllDataRead() throws IOException {
HttpServletResponse res = (HttpServletResponse) asyncContext.getResponse();
res.setContentType("text/plain");
res.setCharacterEncoding("UTF-8");
try (PrintWriter writer = res.getWriter()) {
writer.write("Hello, " + bos.toString() + "!");
}
log.info("Length: " + totalBytesRead);
asyncContext.complete();
}
@Override
public void onError(Throwable t) {
log.info("Length: " + totalBytesRead);
log.info("Error: " + t.getMessage());
asyncContext.complete();
}
};
is.setReadListener(readListener);
}
}
スローHTTPリクエストを送信すると20秒でタイムアウトしました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/my-app/hello
curl: (52) Empty reply from server
real 0m20.433s
user 0m0.000s
sys 0m0.022s
小さいチャンクに分割してゆっくり送信してみます。300バイトのデータを1秒おきに1バイトずつ送信すると、同期I/Oの実装ではタイムアウトしませんでしたが、非同期I/Oの実装だと30秒でタイムアウトしました。
$ time ./slow_http_post.sh 300 1
HTTP/1.1 408
Connection: close
Content-Length: 0
Date: Fri, 14 Nov 2025 02:15:21 GMT
real 0m32.159s
user 0m0.035s
sys 0m0.133s
asyncTimeoutをデフォルトの30秒から60秒に変更してみます。
<Connector port="8080" protocol="HTTP/1.1"
connectionTimeout="20000"
asyncTimeout="60000"
maxThreads="350"
redirectPort="8443" />
タイムアウトに掛かる時間が60秒に変化しました。
$ time ./slow_http_post.sh 300 1
HTTP/1.1 408
Connection: close
Content-Length: 0
Date: Fri, 14 Nov 2025 02:18:41 GMT
real 1m2.289s
user 0m0.081s
sys 0m0.218s
リクエストボディのサイズを256KBにしたスローHTTPリクエストを多重度300で送信してみます（送信に時間が掛かるためタイムアウトは120秒に変更しています）。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/my-app/hello?[1-300]
[...]
real 1m20.390s
user 0m1.257s
sys 0m3.141s
送信中のスレッドを確認するとスレッド数が30ほど増加していますがビジー状態のスレッドはありません。リクエストは細切れのソケットイベントの連続で構成され、TomcatのPollerがそのソケットイベントをFIFOキューに入れてワーカースレッドが処理します。非同期I/Oの場合はスレッドとリクエストが固定されず、その時空いているワーカースレッドが逐次処理するためこのような変化となって表れています。
メモリ使用量は同期I/Oと比較して目立った変化は確認できません。
小さいチャンクに分割してゆっくり送信してみます。
$ time seq 300 | xargs -I{} echo "4096" | parallel -j 300 './slow_http_post.sh 262144 {}'
[...]
real 1m37.549s
user 5m29.432s
sys 2m26.940s
1秒間隔で送信しているためワーカースレッドの余裕があり、スレッド数はほとんど変化がありません。
メモリ使用量は同期I/Oと比較して目立った変化は確認できません。
Gunicorn
以下の構成で検証を行います。
クライアント Gunicorn
検証には以下のスクリプトを使用します。
import sys
def app(environ, start_response):
try:
content_length = int(environ.get('CONTENT_LENGTH', 0))
except ValueError:
content_length = 0
if content_length > 0:
request_body = environ['wsgi.input'].read(content_length)
else:
request_body = b''
log_message = f"Length: {len(request_body)}"
print(log_message, file=sys.stderr)
response_body = 'Hello, %s!' % request_body.decode('utf-8')
start_response('200 OK', [('Content-type', 'text/plain')])
return [response_body.encode('utf-8')]
検証するGunicornのワーカーは以下の4種類です。
-
sync（同期ワーカー） -
eventlet（コルーチンワーカー） -
gevent（コルーチンワーカー） -
gthread（スレッドワーカー）
まずは通常のリクエストを送信してみます。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 200 OK
Server: gunicorn
Date: Sun, 16 Nov 2025 03:40:22 GMT
Connection: close
Transfer-Encoding: chunked
Content-type: text/plain
Hello, qiita!
real 0m0.353s
user 0m0.004s
sys 0m0.016s
次にそれぞれのワーカーに対してスローHTTPリクエストを送信してみます。
< syncワーカー >
syncワーカーでは30秒ほどでタイムアウトが発生し、500 Internal Server Errorが返ってきました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 500 Internal Server Error
[...]
real 0m30.823s
user 0m0.006s
sys 0m0.028s
コンテナのログを確認すると、ワーカープロセスがkillされて新しいワーカープロセスが起動していることが確認できます。
[2025-11-16 03:45:46 +0000] [9] [CRITICAL] WORKER TIMEOUT (pid:1982)
[...]
[2025-11-16 03:45:46 +0000] [1982] [INFO] Worker exiting (pid: 1982)
[2025-11-16 03:45:46 +0000] [2608] [INFO] Booting worker with pid: 2608
タイムアウトに30秒ほど掛かっていますが、この秒数はtimeoutのデフォルト値の30秒が適用されています。
60秒に変更して試してみます。
worker_class = "sync"
timeout = 60
タイムアウトに掛かる時間が60秒に変化しました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 500 Internal Server Error
[...]
real 1m0.998s
user 0m0.015s
sys 0m0.012s
< eventlet、gevent、gthreadワーカー >
eventlet、gevent、gthreadワーカーではタイムアウトが発生せず、クライアントから接続をクローズしない限り接続されたままになりました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
^C
real 5m20.534s
user 0m0.008s
sys 0m0.021s
< syncワーカー >
syncワーカーに対して小さいチャンクに分割してゆっくり送信すると30秒ほどでタイムアウトが発生しました。
$ time ./slow_http_post.sh 300 1
[...]
real 0m34.114s
user 0m0.053s
sys 0m0.071s
syncワーカーのワーカー数（workers）を4に設定してスローHTTPリクエストを多重度4で送信します。
worker_class = "sync"
workers = 4
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 4 http://***.***.***.***/?[1-4]
HTTP/1.1 500 Internal Server Error
[...]
real 0m31.253s
user 0m0.008s
sys 0m0.019s
送信中に通常のリクエストを送信するとワーカーに空きが出るまで遅延が発生しました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 200 OK
[...]
Hello, qiita!
real 0m30.743s
user 0m0.008s
sys 0m0.015s
< eventlet、geventワーカー >
eventletワーカーおよびgeventワーカーのワーカー数を1、ワーカー接続数（worker_connections）を100にしてスローHTTPリクエストを多重度100で送信します。
worker_class = "eventlet"
workers = 1
worker_connections = 100
worker_class = "gevent"
workers = 1
worker_connections = 100
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 100 http://***.***.***.***/?[1-100]
送信中に通常のリクエストを送信すると同時接続数が上限に達しているため待機状態となり、クライアントから接続をクローズしない限り接続されたままになりました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
^C
real 5m35.129s
user 0m0.004s
sys 0m0.017s
< gthreadワーカー >
gthreadワーカーのワーカー数を1、スレッド数（threads）を100にしてスローHTTPリクエストを多重度100で送信します。
worker_class = "gthread"
workers = 1
threads = 100
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 100 http://***.***.***.***/?[1-100]
スレッドの数が100増加していることが確認できます。
# 送信前
$ cat /proc/<ワーカーのPID>/status | grep Threads
Threads: 1
# 送信中
$ cat /proc/<ワーカーのPID>/status | grep Threads
Threads: 101
送信中に通常のリクエストを送信すると同時接続数が上限に達しているため待機状態となり、クライアントから接続をクローズしない限り接続されたままになりました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
^C
real 5m38.248s
user 0m0.008s
sys 0m0.006s
多重度を上げてサーバーリソースの変化を確認します。
< syncワーカー >
syncワーカーに対して256KBのスローHTTPリクエストを多重度300で送信します（ワーカー数1）。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
リクエスト直後のGunicornの受信キューを確認すると、ワーカーで処理中の1件を除く299件の接続がaccept待ちで滞留しています。
$ ss -t state listening
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 4096 127.0.0.11:35123 0.0.0.0:*
299 2048 0.0.0.0:8000 0.0.0.0:*
$ ss -nt state established
Recv-Q Send-Q Local Address:Port Peer Address:Port
94859 0 172.18.0.3:8000 ***.***.***.***:57050
91558 0 172.18.0.3:8000 ***.***.***.***:56565
94015 0 172.18.0.3:8000 ***.***.***.***:57157
94014 0 172.18.0.3:8000 ***.***.***.***:56589
[...]
メモリ使用量は変化がありません。
accept前のソケットバッファはcgroupには集計されませんが、カーネルのソケットバッファを確認すると約37MBのデータが滞留していることが分かります。（9531 × 4KB ≒ 37MB）
$ cat /proc/net/sockstat
sockets: used 224
TCP: inuse 7 orphan 0 tw 0 alloc 329 mem 9531
UDP: inuse 3 mem 0
UDPLITE: inuse 0
RAW: inuse 0
FRAG: inuse 0 memory 0
< eventlet、geventワーカー >
eventletワーカーおよびgeventワーカーに対して256KBのスローHTTPリクエストを多重度300で送信します（ワーカー数1、ワーカー接続数100）。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
リクエスト直後のGunicornの受信キューを確認すると、199件の接続がaccept待ちで滞留しています。
$ ss -t state listening
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 4096 127.0.0.11:35123 0.0.0.0:*
199 2048 0.0.0.0:8000 0.0.0.0:*
$ ss -nt state established
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 0 172.18.0.3:8000 ***.***.***.***:64698
0 0 172.18.0.3:8000 ***.***.***.***:64731
93351 0 172.18.0.3:8000 ***.***.***.***:64797
96727 0 172.18.0.3:8000 ***.***.***.***:64861
[...]
メモリ使用量を確認すると40MBほど増加しています。
docker statsのAPIエンドポイントから取得したメモリ使用量の詳細の差分を確認すると、ヒープメモリの割り当て増加していることが分かります。
$ jq -s '
{
"USAGE (Total)": ((.[1].usage - .[0].usage) / 1048576),
"ANON (Heap/Stack)": ((.[1].stats.anon - .[0].stats.anon) / 1048576),
"FILE (Cache)": ((.[1].stats.file - .[0].stats.file) / 1048576),
"INACTIVE_FILE": ((.[1].stats.inactive_file - .[0].stats.inactive_file) / 1048576),
"FILE_DIRTY": ((.[1].stats.file_dirty - .[0].stats.file_dirty) / 1048576),
"SLAB": ((.[1].stats.slab - .[0].stats.slab) / 1048576),
"SOCK": ((.[1].stats.sock - .[0].stats.sock) / 1048576),
}
' before.json after.json
{
"USAGE (Total)": 37.17578125,
"ANON (Heap/Stack)": 36.83203125,
"FILE (Cache)": 0,
"INACTIVE_FILE": 0,
"FILE_DIRTY": 0,
"SLAB": 0.14862823486328125,
"SOCK": 0.125
}
< gthreadワーカー >
gthreadワーカーに対して256KBのスローHTTPリクエストを多重度300で送信します（ワーカー数1、スレッド数100）。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
リクエスト直後のGunicornの受信キューを確認すると、accept待ちはありません。
$ ss -t state listening
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 4096 127.0.0.11:35123 0.0.0.0:*
0 2048 0.0.0.0:8000 0.0.0.0:*
$ ss -nt state established
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 0 172.18.0.3:8000 ***.***.***.***:49493
95627 0 172.18.0.3:8000 ***.***.***.***:49828
0 0 172.18.0.3:8000 ***.***.***.***:49749
94427 0 172.18.0.3:8000 ***.***.***.***:49461
[...]
メモリ使用量を確認するとコンテナの方がプロセスより増加量が大きくなっています。
docker statsのAPIエンドポイントから取得したメモリ使用量の詳細の差分を確認すると、ヒープメモリの割り当てとソケットバッファで増加していることが分かります。
$ jq -s '
{
"USAGE (Total)": ((.[1].usage - .[0].usage) / 1048576),
"ANON (Heap/Stack)": ((.[1].stats.anon - .[0].stats.anon) / 1048576),
"FILE (Cache)": ((.[1].stats.file - .[0].stats.file) / 1048576),
"INACTIVE_FILE": ((.[1].stats.inactive_file - .[0].stats.inactive_file) / 1048576),
"FILE_DIRTY": ((.[1].stats.file_dirty - .[0].stats.file_dirty) / 1048576),
"SLAB": ((.[1].stats.slab - .[0].stats.slab) / 1048576),
"SOCK": ((.[1].stats.sock - .[0].stats.sock) / 1048576),
}
' before.json after.json
{
"USAGE (Total)": 81.4296875,
"ANON (Heap/Stack)": 53.04296875,
"FILE (Cache)": 0,
"INACTIVE_FILE": 0,
"FILE_DIRTY": 0,
"SLAB": 1.4849319458007812,
"SOCK": 24.828125
}
Puma
以下の構成で検証を行います。
クライアント Puma
検証には以下のスクリプトを使用します。
run lambda { |env|
input = env["rack.input"]
buffer = ""
while chunk = input.read(1024)
buffer << chunk
STDERR.puts "Chunk Length: #{chunk.size}"
end
STDERR.puts "Length: #{buffer.size}"
response_body = "Hello, #{buffer}!"
[200, { 'Content-Type' => 'text/plain' }, [response_body]]
}
まずは通常のリクエストを送信してみます。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 200 OK
content-type: text/plain
content-length: 13
Hello, qiita!
real 0m0.453s
user 0m0.073s
sys 0m0.044s
続いてスローHTTPリクエストを送信すると30秒ほどでリクエストがタイムアウトし、408 Request Timeoutが返ってきました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 408 Request Timeout
connection: close
real 0m30.438s
user 0m0.009s
sys 0m0.017s
入力ストリームから1024バイトずつ読み込んでログを出力するようにしたのですが、コンテナのログを確認してもログは出力されていません。サイズを大きくして送信してもログは出力されません。受信したデータをストリームとして渡すのではなく、リクエストボディをバッファリングして全てのデータの受信が完了してから渡すようです。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --dump-header - http://***.***.***.***/
HTTP/1.1 408 Request Timeout
connection: close
real 0m31.267s
user 0m0.004s
sys 0m0.017s
念のためTransfer-Encoding: chunkedで試しましたが、終了の0バイトのチャンクを送信するまでバッファリングされました。
#!/bin/bash
HOST="***.***.***.***"
PORT="80"
REQUEST_HEADER="POST / HTTP/1.1\r\nHost: $HOST\r\nConnection: close\r\nContent-Type: text/plain\r\nTransfer-Encoding: chunked\r\n\r\n"
BODY=$(yes 'a' | tr -d '\n' | head -c 2048)
{
echo -ne "$REQUEST_HEADER"
printf "%x\r\n%s\r\n" ${#BODY} "$BODY"
# echo -ne "0\r\n\r\n"
} | nc $HOST $PORT
タイムアウトに30秒ほど掛かっていますが、この秒数はfirst_data_timeoutのデフォルト値の30秒が適用されています。60秒に変更して試してみます。
first_data_timeout 60
タイムアウトに掛かる時間が60秒に変化しました。
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --dump-header - http://***.***.***.***/
HTTP/1.1 408 Request Timeout
connection: close
real 1m0.388s
user 0m0.014s
sys 0m0.010s
次に小さいチャンクに分割してゆっくり送信してみます。300バイトのデータを1秒おきに1バイトずつ送信すると、タイムアウトが発生することなくリクエストが完了しました。
$ time ./slow_http_post.sh 300 1
HTTP/1.1 200 OK
content-type: text/plain
connection: close
content-length: 308
Hello, aaaaaaaaaaaaaaaaaaaa[...]aaaaaaaaaaaaaaaaaaaaaa!
real 5m1.373s
user 0m0.407s
sys 0m0.996s
多重度を上げてサーバーリソースの変化を確認します。
ワーカープロセスの数（workers）を0にしてマスタープロセスのみでスローHTTPリクエストを多重度300で送信します。
workers 0
threads 5, 5
$ time curl -X POST -H "Content-Length: 6" -d "qiita" --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
real 0m31.616s
user 0m0.092s
sys 0m0.333s
リクエスト直後のオープン中のネットワークソケットを確認すると300増加しています。
$ lsof | grep ruby | grep socket | wc -l
3
$ lsof | grep ruby | grep socket | wc -l
303
受信キューにaccept待ちの接続はありません。
$ ss -t state listening
Recv-Q Send-Q Local Address:Port Peer Address:Port
0 4096 127.0.0.11:40607 0.0.0.0:*
0 1024 0.0.0.0:9292 0.0.0.0:*
リクエスト直後のマスタープロセスのスレッド数を確認しても送信前と変化はありません。
# 送信前
$ cat /proc/<マスタープロセスのPID>/status | grep Threads
15
# 送信直後
$ cat /proc/<マスタープロセスのPID>/status | grep Threads
15
スローHTTPリクエスト送信中に通常のリクエストを送信すると遅延なくレスポンスが返ってきました。一つのスローHTTPリクエストが一つのスレッドを占有し続ける訳ではなく、I/O待ちの間は別のリクエストを処理しているようです（ノン・ブロッキングI/O）。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" http://***.***.***.***/
Hello, qiita!
real 0m0.354s
user 0m0.009s
sys 0m0.009s
サイズを256KBに変更して多重度300で送信してみます。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
real 1m32.237s
user 0m1.185s
sys 0m3.188s
メモリ使用量を確認するとコンテナのメモリ使用量がプロセスよりも大きく増加しています。
docker statsのAPIエンドポイントから取得したメモリ使用量の詳細の差分を確認すると、ヒープメモリの割り当てとページキャッシュが増加していることが分かります。
$ jq -s '
{
"USAGE (Total)": ((.[1].usage - .[0].usage) / 1048576),
"ANON (Heap/Stack)": ((.[1].stats.anon - .[0].stats.anon) / 1048576),
"FILE (Cache)": ((.[1].stats.file - .[0].stats.file) / 1048576),
"INACTIVE_FILE": ((.[1].stats.inactive_file - .[0].stats.inactive_file) / 1048576),
"FILE_DIRTY": ((.[1].stats.file_dirty - .[0].stats.file_dirty) / 1048576),
"SLAB": ((.[1].stats.slab - .[0].stats.slab) / 1048576),
"SOCK": ((.[1].stats.sock - .[0].stats.sock) / 1048576),
}
' before.json after.json
{
"USAGE (Total)": 106.69140625,
"ANON (Heap/Stack)": 28.640625,
"FILE (Cache)": 74.1484375,
"INACTIVE_FILE": 74.1484375,
"FILE_DIRTY": 0.47265625,
"SLAB": 3.6141586303710938,
"SOCK": 0
}
リクエスト送信中にマスタープロセスがオープンしているファイルを確認すると、tmpディレクトリにリクエストボディをバッファリングした一時ファイルが作成され、アンリンクされていることが分かります。
$ ls -al /proc/<マスタープロセスのPID>/fd
[...]
lrwx------ 1 root root 64 Nov 18 02:26 111 -> /tmp/puma20251118-8-72g01p (deleted)
lrwx------ 1 root root 64 Nov 18 02:26 112 -> /tmp/puma20251118-8-vcfad3 (deleted)
lrwx------ 1 root root 64 Nov 18 02:26 113 -> /tmp/puma20251118-8-50tyxa (deleted)
lrwx------ 1 root root 64 Nov 18 02:26 114 -> /tmp/puma20251118-8-4gmpd6 (deleted)
lrwx------ 1 root root 64 Nov 18 02:26 115 -> /tmp/puma20251118-8-w2c8ca (deleted)
[...]
PumaコンテナのFDの上限を512に変更して多重度300で送信してみます。
$ ulimit -n
512
ソケットファイルと一時ファイルの作成で上限の512を超過したために複数の接続でエラーが発生しました。
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
/usr/local/lib/ruby/3.4.0/tempfile.rb:572:in 'File#initialize'
/usr/local/lib/ruby/3.4.0/tempfile.rb:572:in 'IO.open'
/usr/local/lib/ruby/3.4.0/tempfile.rb:572:in 'block in Tempfile.create_with_filename'
/usr/local/lib/ruby/3.4.0/tmpdir.rb:179:in 'Dir::Tmpname.create'
/usr/local/lib/ruby/3.4.0/tempfile.rb:569:in 'Tempfile.create_with_filename'
/usr/local/lib/ruby/3.4.0/tempfile.rb:562:in 'Tempfile.create'
/usr/local/bundle/gems/puma-7.1.0/lib/puma/client.rb:477:in 'Puma::Client#setup_body'
/usr/local/bundle/gems/puma-7.1.0/lib/puma/client.rb:280:in 'Puma::Client#try_to_finish'
/usr/local/bundle/gems/puma-7.1.0/lib/puma/server.rb:321:in 'Puma::Server#reactor_wakeup'
/usr/local/bundle/gems/puma-7.1.0/lib/puma/server.rb:268:in 'block in Puma::Server#run'
/usr/local/bundle/gems/puma-7.1.0/lib/puma/reactor.rb:133:in 'Puma::Reactor#wakeup!'
/usr/local/bundle/gems/puma-7.1.0/lib/puma/reactor.rb:87:in 'block in Puma::Reactor#select_loop'
/usr/local/bundle/gems/puma-7.1.0/lib/puma/reactor.rb:85:in 'NIO::Selector#select'
/usr/local/bundle/gems/puma-7.1.0/lib/puma/reactor.rb:85:in 'Puma::Reactor#select_loop'
/usr/local/bundle/gems/puma-7.1.0/lib/puma/reactor.rb:47:in 'block in Puma::Reactor#run'
real 1m27.691s
user 0m0.958s
sys 0m2.437s
コンテナのログにも大量のエラーが出力されています。
[...]
2025-11-18 02:40:07 +0000 Listen loop: #<Errno::EMFILE: No file descriptors available - accept(2)>
2025-11-18 02:40:07 +0000 Listen loop: #<Errno::EMFILE: No file descriptors available - accept(2)>
2025-11-18 02:40:07 +0000 Listen loop: #<Errno::EMFILE: No file descriptors available - accept(2)>
2025-11-18 02:40:07 +0000 Listen loop: #<Errno::EMFILE: No file descriptors available - accept(2)>
[...]
送信中に通常のリクエストを送信すると遅延が発生しました。
$ time curl -X POST -H "Content-Length: 5" -d "qiita" http://***.***.***.***/
Hello, qiita!
real 1m16.365s
user 0m0.006s
sys 0m0.021s
クラスターモードに変更して送信してみます。
workers 2
threads 5, 5
$ time curl -X POST -H "Content-Length: 262145" -d @256kb.txt --parallel --parallel-immediate --parallel-max 300 http://***.***.***.***/?[1-300]
[...]
real 1m32.237s
user 0m1.185s
sys 0m3.188s
マスタープロセスのみの時と比較してメモリ使用量に目立った変化はありません。
最後に
接続数やタイムアウト値などの設定は実際にどのように働くのか把握しづらいですが、今回のようなcurlコマンドを使用した簡易的な方法で把握しやすくなります。普段何となく設定しているという方は、その設定値が本当に実運用環境に適しているのか検証してみると良いでしょう。また、APサーバーの前にWebサーバーを配置する必要があるかどうかなど、サーバー構成を検討する材料の一つとして、運用で何を監視すべきかなど監視項目の一つとして、今回のスローHTTPも考慮に加えて頂けると良いかなと思います。本記事が少しでもお役に立てれば幸いです。