TCP_DEFER_ACCEPTは、LinuxでサポートされているTCPのオプションで、サーバ側で使用した場合にはaccept(2)からのブロック解除をTCP接続が完了したタイミングではなく最初のデータが到着したタイミングで行ってくれるオプションです。
Webサーバ・アプリケーションサーバではリクエストが到着してからaccept(2)のブロックを解除するので、リクエストの到着をWebサーバ・アプリケーションサーバで待つ必要がなくなり、特にprefork型のサーバでは効率的にプロセスを使えるようになるという利点があります。PerlではStarletがこの機能を有効にしています
ところが、某サービスでTCP_DEFER_ACCEPTが有効にも関わらず、accept後のreadでデータが読めず、最悪の場合、デフォルトのtimeoutである5分間プロセスがストールすることがありました。straceで捕まえられたのが以下。
21:13:28.727597 accept(4, {sa_family=AF_INET, sin_port=htons(50776), sin_addr=inet_addr("127.0.0.1")}, [6396800329316302864]) = 5
21:13:28.727749 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff39d54050) = -1 EINVAL (Invalid argument)
21:13:28.727834 lseek(5, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
21:13:28.727905 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff39d54050) = -1 EINVAL (Invalid argument)
21:13:28.727982 lseek(5, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
21:13:28.728051 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
21:13:28.728148 fcntl(5, F_GETFL) = 0x2 (flags O_RDWR)
21:13:28.728226 fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0
21:13:28.728311 setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
21:13:28.728451 read(5, 0x123dacc0, 131072) = -1 EAGAIN (Resource temporarily unavailable)
21:13:28.728557 gettimeofday({1398946408, 728589}, NULL) = 0
21:13:28.728649 select(8, [5], NULL, [5], {300, 0}) = 0 (Timeout)
21:18:28.732551 gettimeofday({1398946708, 732602}, NULL) = 0
21:18:28.732952 close(5) = 0
21:13:28.728451にread(2)を試みてますが、データがまだ到着せずEAGAINとなり、select(2)でソケットが読めるようになるまで待ちますが、5分後タイムアウトとなり接続を切っていることがわかります。他にも数十秒まってからリクエストが届いたりするパターンもあり、レスポンスがかなり不安定な状況になっていました。
調べても、なかなか同じような事例はでてこなかったのですが、ひとつだけ中国語のサイトでみつけました。
http://bbs.csdn.net/topics/380151037
google翻訳して読むと、somaxconn(backlog)が溢れるとEAGAINが返り、somaxconnを増やして解決したそうです。
なるほどと思い、某サービスの当時の状況を振り返ると、Starletのworker数は10とかなり少なめ、backlogは標準の128で起動されており、ゴールデンウィーク前のキャンペーンでアクセスがかなり増加しているところで、アプリケーションから呼び出している外部のAPIの遅延が目立ってきている状態。workerプロセスは全てbusyとなりbacklogが不足してしまっていたと容易に考えられます。
現在はこのサーバはアプリケーションの改善を行うとともに、worker数、backlogともに増やして再発しにくいよう設定しています。
再現実験
CentOS6のサーバに、Starletを起動し、abにて負荷をかけることで再現させてみます。
サーバのsomaxconnは大きめに設定しています
$ sysctl net.core.somaxconn
net.core.somaxconn = 32768
念のためtcpmaxsyn_backlogも確認
$ sysctl net.ipv4.tcp_max_syn_backlog
net.ipv4.tcp_max_syn_backlog = 2048
syncookieはoffです。onでも同じ状況が再現しています。
$ sysctl -a|grep cookie
net.ipv4.tcp_syncookies = 1
Perlは5.18.2。StarletやServer::Starterのバージョンは以下。
- Starlet 0.23
- Server::Starter 0.17
アプリケーションは、1msecほどsleepしてレスポンスするようにしました。
$ cat app.psgi
my $body = "Hello World\n";
sub {
my $env = shift;
select undef, undef, undef, 0.001;
[200,["Content-Type"=>"text/html"],[$body]];
};
まず、workerを3つ、backlogを10にて起動します。start_serverコマンドは—backlogオプションでbacklogが指定できます。
$ start_server --port 5432 --backlog 10 -- carton exec -- plackup -s Starlet --workers=3 --max-reqs-per-child 50000 --min-reqs-per-child 40000 --E production -a app.psgi
別ターミナルからab
$ ab -c 1000 -n 10000 http://127.0.0.1:5432/
さらに、別ターミナルで適当なプロセスにstraceでattachしてEAGAINがでるか観察します
$ strace -tt -p $pid 2>&1 | tee /tmp/trace.txt | grep EAGAIN
10:48:28.188696 read(5, 0x7fcd284a9010, 131072) = -1 EAGAIN (Resource temporarily unavailable)
10:48:33.201731 read(5, 0x7fcd284a9010, 131072) = -1 EAGAIN (Resource temporarily unavailable)
10:48:35.391262 read(5, 0x7fcd284a9010, 131072) = -1 EAGAIN (Resource temporarily unavailable)
10:48:36.000677 read(5, 0x7fcd284a9010, 131072) = -1 EAGAIN (Resource temporarily unavailable)
何回かでました。前後をみると、
10:48:36.000442 accept(4, {sa_family=AF_INET, sin_port=htons(23509), sin_addr=inet_addr("127.0.0.1")}, [16]) = 5
10:48:36.000469 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff5c142940) = -1 EINVAL (Invalid argument)
10:48:36.000501 lseek(5, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
10:48:36.000522 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff5c142940) = -1 EINVAL (Invalid argument)
10:48:36.000544 lseek(5, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
10:48:36.000566 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
10:48:36.000602 fcntl(5, F_GETFL) = 0x2 (flags O_RDWR)
10:48:36.000623 fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0
10:48:36.000645 setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
10:48:36.000677 read(5, 0x7fcd284a9010, 131072) = -1 EAGAIN (Resource temporarily unavailable)
10:48:36.000709 select(8, [5], NULL, [5], {300, 0}) = 1 (in [5], left {294, 901422})
10:48:41.099372 read(5, "GET / HTTP/1.0\r\nHost: 127.0.0.1:"..., 131072) = 82
10:48:41.099448 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout)
10:48:41.100603 write(5, "HTTP/1.1 200 OK\r\nDate: Thu, 08 M"..., 145) = 145
10:48:41.100678 close(5) = 0
EAGAINのあと、selectで5秒ほど待ちました。
abの結果のレスポンス時間をみると、一部のアクセスがかなり遅いようです。7秒と言えばTCPの再送？
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 30 341.9 0 7001
Processing: 1 18 153.7 8 6364
Waiting: 1 18 153.7 8 6364
Total: 4 48 406.6 8 10077
Percentage of the requests served within a certain time (ms)
50% 8
66% 13
75% 13
80% 13
90% 17
95% 18
98% 32
99% 1014
100% 10077 (longest request)
次に、backlogを十分に大きな8192にて起動します。worker数はそのまま。
$ start_server --port 5432 --backlog 8192 -- carton exec -- plackup -s Starlet --workers=3 --max-reqs-per-child 50000 --min-reqs-per-child 40000 --E production -a app.psgi
再びabしながら別ターミナルで適当なプロセスにstraceでattachしてEAGAINがでるか観察しましたが、
$ strace -tt -p $pid 2>&1 | tee /tmp/trace.txt | grep EAGAIN
何回か試行した中ではEAGAINがでませんでした。
abの結果は以下。遅いですが、安定してレスポンスができています。
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 1 2.8 0 10
Processing: 8 384 70.9 401 416
Waiting: 8 384 70.9 401 416
Total: 18 385 68.5 401 416
Percentage of the requests served within a certain time (ms)
50% 401
66% 402
75% 407
80% 412
90% 414
95% 414
98% 415
99% 415
100% 416 (longest request)
まとめると
backlogが不十分な場合TCP_DEFER_ACCEPTが有効でも、accept(2)後の最初のreadでリクエストが読めないことがある。最悪のケース、長い時間プロセスが占有され、サービスに影響がでることがある。対策としては十分なbacklogを確保することと、prefork型のサーバでは十分なworker数を起動するのも対策となるでしょう。
イベントドリブンなサーバはTCP_DEFER_ACCEPTを使わないのも一つの手ですが、prefork型のサーバではプロセスを占有してリクエストを待つコストが大きく、解決にはならないと思われます。
データが来ないままacceptのブロックが解除されてしまう理由はkernelのソースを読めばわかるのかなぁ。。
