nginx+hhvm で UNIX Socket接続を試す

その中で、nginx ＋ php-fpm、apache+php-fpm 、apache+mod_php、 nginx+apache+mod_php との接続で、何が一番リクエストを処理できるかをベンチマーク(たしかsiegeを使ってた)を取っていました。

結果を見ると、nginx+php-fpmよりもapache+mod_phpのほうがリクエスト/秒の数値が多い。このとき、nginx+php_fpmはUNIX Socketを使って通信していました。まあ、普通UNIX Socketのほうが早いはずです。が、ここでnginx と php-fpmの接続をTCP(localhost:9000）にすると、順当にnginx+php-fpmのほうがリクエスト/秒が多くなったようです。

ここで疑問。なんでUNIX Socketだとリクエスト数/秒が少なくなるの？
とりあえず仮説を立てました。

UNIX socketだと、File open/closeのオーバーヘッドが高負荷時に大きくなるから遅くなるんじゃね？と仮説を立ててみる #php7casual

— Satoru MIYAZAKI (@s_miyaza) 2016年4月14日

ということで、やってみました。もちろんKUSANAGIで。

まず、hhvm 設定ファイル(/etc/hhvm/php.ini)の以下の部分を修正します。

;hhvm.server.ip = 127.0.0.1
;hhvm.server.port = 9000 
hhvm.server.file_socket = /var/run/php-fpm/sock

次に、nginx設定ファイル(/etc/nginx/conf.d/XXX_html.conf)の以下の部分を修正します。2か所あるので、両方直しましょう。なお、ssl接続の時は、もう一つの設定ファイル/etc/nginx/conf.d/XXX_ssl.conf も同様に修正します。

;#fastcgi_pass 127.0.0.1:9000;
fastcgi_pass unix:/var/run/php-fpm/sock;

/var/run/php-fpm のパーミションは一時的に777にしておきます。ここでサービス再起動。sock ファイルがうまく動くことを確認。

# chmod 777 /var/run/php-fpm
# systemctl restart hhvm nginx
# ls -l /var/run/php-fpm/sock 
srwxrw---- 1 httpd www 0 Apr 17 02:22 /var/run/php-fpm/sock

ここで自分自身に対して ab をかけます（URLは架空のものです）。リクエスト数1000、同時接続数100で実行すると、Requests per secondは130#/s でエラーなしでした。普通に早い何時ものKUSANAGIですね。

# ab -n 1000 -c 100 http://kusanagi70.local/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

　中略

Server Software:        nginx
Server Hostname:        kusanagi70.local
Server Port:            80

Document Path:          /
Document Length:        10445 bytes

Concurrency Level:      100
Time taken for tests:   7.671 seconds
Complete requests:      1000
Failed requests:        0
Write errors:           0
Total transferred:      10727000 bytes
HTML transferred:       10445000 bytes
Requests per second:    130.36 [#/sec] (mean)
Time per request:       767.080 [ms] (mean)
Time per request:       7.671 [ms] (mean, across all concurrent requests)
Transfer rate:          1365.65 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.6      0       2
Processing:    20  724 139.1    715    1158
Waiting:       16  724 139.1    715    1158
Total:         20  724 139.0    715    1158

Percentage of the requests served within a certain time (ms)
  50%    715
  66%    736
  75%    756
  80%    770
  90%    813
  95%    995
  98%   1105
  99%   1124
 100%   1158 (longest request)

もうちょっと負荷を上げて同時接続数を300にしてみましょう。
おやおやエラーが出ましたね。

# ab -n 1000 -c 300 http://kusanagi70.local/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

中略

Server Software:        nginx
Server Hostname:        kusanagi70.local
Server Port:            80

Document Path:          /
Document Length:        10445 bytes

Concurrency Level:      300
Time taken for tests:   6.044 seconds
Complete requests:      1000
Failed requests:        111
   (Connect: 0, Receive: 0, Length: 111, Exceptions: 0)
Write errors:           0
Non-2xx responses:      111
Total transferred:      9572489 bytes
HTML transferred:       9304031 bytes
Requests per second:    165.45 [#/sec] (mean)
Time per request:       1813.214 [ms] (mean)
Time per request:       6.044 [ms] (mean, across all concurrent requests)
Transfer rate:          1546.67 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    3   4.4      0      19
Processing:     4 1523 778.0   1934    2257
Waiting:        0 1523 778.2   1934    2257
Total:         13 1526 774.5   1934    2257

Percentage of the requests served within a certain time (ms)
  50%   1934
  66%   2025
  75%   2139
  80%   2151
  90%   2170
  95%   2177
  98%   2187
  99%   2195
 100%   2257 (longest request)

このときのエラーファイル(/home/kusanagi/XXX/log/nginx/error.log)を見ると、以下のようなエラーが出ていました。一時的にSocketファイルにアクセスできなかったようですね。

2016/04/17 02:30:55 [error] 20252#0: *49100 connect() to unix:/var/run/php-fpm/sock failed (11: Resource temporarily unavailable) while connecting to upstream, client: 127.0.0.1, server: kusanagi70.local, request: "GET / HTTP/1.0", upstream: "fastcgi://unix:/var/run/php-fpm/sock:", host: "kusanagi70.local"

では、どんな動きをするか、strace で nginxのsystem call を追ってみましょう。strace は、-p でプロセスID、-f でfork後のプロセスも追いかけます。nginxのプロセスIDはここではなので、以下のようにstraceを実行後、別端末からab -n 1000 -c 300 で実行します。

# strace -f -p 20251
Process 20251 attached
epoll_wait(13, {{EPOLLIN, {u32=3703730192, u64=139925148299280}}}, 512, -1) = 1
accept4(10, {sa_family=AF_INET, sin_port=htons(39911), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 17
epoll_ctl(13, EPOLL_CTL_ADD, 17, {EPOLLIN|EPOLLRDHUP|EPOLLET, {u32=3703963688, u64=139925148532776}}) = 0
accept4(10, 0x7ffecb6af920, [110], SOCK_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)

中略

epoll_ctl(13, EPOLL_CTL_ADD, 293, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=3703956345, u64=139925148525433}}) = 0
connect(293, {sa_family=AF_LOCAL, sun_path="/var/run/php-fpm/sock"}, 110) = 0
getsockopt(293, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
writev(293, [{"\1\1\0\1\0\10\0\0\0\1\0\0\0\0\0\0\1\4\0\1\2\23\5\0\17*SCRIPT"..., 576}], 1) = 576

中略

epoll_ctl(13, EPOLL_CTL_ADD, 211, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=3703838408, u64=139925148407496}}) = 0
connect(211, {sa_family=AF_LOCAL, sun_path="/var/run/php-fpm/sock"}, 110) = -1 EAGAIN (Resource temporarily unavailable)
write(7, "2016/04/17 01:55:51 [error] 2025"..., 308) = 308
close(211)                              = 0

後略

通常は、connect()でソケットファイルを開き、hhvmとの通信処理を続行するのですが、大量通信時に、connect()がエラー（EAGEIN）を返します。これは一時的にサービスできないというエラーです。やはり同時接続数が多いと socket ではさばききれないようです。

同時接続数が多い場合、socketへの接続エラー発生率が高くなり、その結果秒間リクエストが少なくなる、ということのようです。

ということで、結論から言うと、以下の仮説は間違いでしたね。

UNIX socketだと、File open/closeのオーバーヘッドが高負荷時に大きくなるから遅くなるんじゃね？と仮説を立ててみる #php7casual

— Satoru MIYAZAKI (@s_miyaza) 2016年4月14日

正解は、Socketアクセスエラーが多くなる→正常処理できるリクエストが少なくなる、でした。

ちなみに、同じ環境でnginx+hhvmをtcp/9000で接続した場合、abの結果は以下のようになり、エラーは発生してませんでした。

# ab -n 1000 -c 300 http://kusanagi70.local/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

中略

Server Software:        nginx
Server Hostname:        kusanagi70.local
Server Port:            80

Document Path:          /
Document Length:        10445 bytes

Concurrency Level:      300
Time taken for tests:   6.245 seconds
Complete requests:      1000
Failed requests:        0
Write errors:           0
Total transferred:      10727000 bytes
HTML transferred:       10445000 bytes
Requests per second:    160.13 [#/sec] (mean)
Time per request:       1873.421 [ms] (mean)
Time per request:       6.245 [ms] (mean, across all concurrent requests)
Transfer rate:          1677.51 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    7  11.8      0      29
Processing:    48 1586 580.1   1830    2890
Waiting:       12 1586 580.2   1830    2890
Total:         48 1594 575.8   1830    2915

Percentage of the requests served within a certain time (ms)
  50%   1890
  66%   1936
  75%   2115
  80%   2363
  90%   2786
  95%   2951
  98%   3085
  99%   3135
 100%   7068 (longest request)
  95%   1917
  98%   1921
  99%   1925
 100%   1934 (longest request

もっと過激にリクエスト数5000、同時接続数2000にしてみても、エラーは発生してませんね。リクエスト/秒もあまり変わらないのでエライ。

# ab -n 5000 -c 2000 http://kusanagi70.local/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

中略

Server Software:        nginx
Server Hostname:        kusanagi70.local
Server Port:            80

Document Path:          /
Document Length:        10445 bytes

Concurrency Level:      2000
Time taken for tests:   31.341 seconds
Complete requests:      5000
Failed requests:        0
Write errors:           0
Total transferred:      53635000 bytes
HTML transferred:       52225000 bytes
Requests per second:    159.53 [#/sec] (mean)
Time per request:       12536.570 [ms] (mean)
Time per request:       6.268 [ms] (mean, across all concurrent requests)
Transfer rate:          1671.20 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0   39  48.6      0     118
Processing:   132 10045 3796.8  12311   13817
Waiting:       15 10045 3796.9  12311   13817
Total:        196 10084 3764.5  12312   13927

Percentage of the requests served within a certain time (ms)
  50%  12312
  66%  12567
  75%  12618
  80%  12631
  90%  12653
  95%  12672
  98%  13225
  99%  13607
 100%  13927 (longest request)

Follow me!

@s_miyaza