ujunのブログ

　本ブログ、いつか書こう書こうと思っていて去年くらいにアカウントだけ作ったはいいけど、結局、初投稿がYAPC::Asia 2014のネタとなりました。

　一応会社ではインフラ担当という位置づけにいる自分ですが、仕事ではEnterprise臭のするプロダクトばっかり使うので、せめてプライベートではちょっと試してみたい技術は積極的に触ってここに書いてくようにしようとおもいます。

　YAPCに行くのは今年が初めてで、そもそも技術系の勉強会に出るように動き出したのも去年の終わりくらいから。きっかけのようなものは特になくて、上に書いたように、せめてプライベートでは、という思いが高まったからだったと思う。。。

　YAPC、なんというか、すごい、会場の雰囲気が。初参加のじぶんには、こんなに熱意があってちょっと普通じゃない雰囲気とか、明日からなにか変わるような感じとか、冗談じゃなくそういうのを感じました。むしろ自宅から程近い日吉なんて場所で、こんなにも胸熱なイベントが開催されていることが信じられない感すらありました。

　いろいろ貴重な話を聞けたのですが(特にRebuild.fmのリスナーとしては@miyagawaさんや@lestrratさんがラフに話してたPerlあるあるはすごい高まりました)、2014/08/30(土)の2日目のほうのid:zentooさんのトークについて、すぐに試せて有用そうな話題だったので、自分でも簡単に試してみました。

Perl Mongersのためのstrace入門

Perl Mongersのためのstrace入門 - YAPC::Asia Tokyo 2014

　スライドは以下です。

strace for Perl Mongers from Naosuke Yokoe

　帰ってからすごい簡単にですが触ってみたりしました。サンプルではPlackを使ったアプリケーションでしたが、自分はPlackを触ったことがないので、、、単純にApacheのプロセスで試してみました。ちなみに、インフラ担当でありながら、straceをまともに使ったことなかった。。

やったこと
- vagrantで立てたVirtual Box上のcentosで、apacheを起動する。
- 何回かapacheにリクエストしてみて、httpdプロセスのプロセスの発行するシステムコールを見る。
わかったこと
- KeepAliveのOn/Offでのリクエストの捌き方の違いを実感。

　まず、MPMはpreforkで、設定はデフォルトから変えていなくて、以下のよう。また、KeepAliveはOffの設定。

<IfModule prefork.c>
StartServers       8
MinSpareServers    5
MaxSpareServers   20
ServerLimit      256
MaxClients       256
MaxRequestsPerChild  4000
</IfModule>

StartServersが8なので、起動直後は8個のプロセスがリクエストを待ち受ける。

$ ps aux | grep httpd | grep -v grep
root      2312  0.0  0.6 177792  3888 ?        Ss   06:27   0:00 /usr/sbin/httpd
apache    2318  0.0  0.5 177928  3080 ?        S    06:27   0:00 /usr/sbin/httpd
apache    2319  0.0  0.5 177928  3080 ?        S    06:27   0:00 /usr/sbin/httpd
apache    2320  0.0  0.5 177928  3084 ?        S    06:27   0:00 /usr/sbin/httpd
apache    2321  0.0  0.5 177928  3080 ?        S    06:27   0:00 /usr/sbin/httpd
apache    2322  0.0  0.5 177928  3084 ?        S    06:27   0:00 /usr/sbin/httpd
apache    2323  0.0  0.5 177928  3088 ?        S    06:27   0:00 /usr/sbin/httpd
apache    2324  0.0  0.5 177928  3080 ?        S    06:27   0:00 /usr/sbin/httpd
apache    2325  0.0  0.5 177928  3080 ?        S    06:27   0:00 /usr/sbin/httpd

次に、tmuxで8個仮想端末を作って、それぞれで上記のhttpdプロセスにstraceでアタッチ。

$ sudo strace -p 2318
～
$ sudo strace -p 2325

サンプルとして、以下のコンテンツにブラウザから1回リクエストしてみます。

$ cat /var/www/html/index.html 
<html>
  <head>
  </head>

  <body>
    <img src="http://127.0.0.1:8080/sample1.png" />
    <img src="http://127.0.0.1:8080/sample2.jpg" />
  </body>
</html>

すると、PID:2318、PID:2319、PID:2320のstraceの出力にそれぞれ以下の結果を確認。

PID:2318
accept4(4, {sa_family=AF_INET6, sin6_port=htons(45800), inet_pton(AF_INET6, "::ffff:10.0.2.2", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 10
getsockname(10, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::ffff:10.0.2.15", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
fcntl(10, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(10, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
read(10, "GET / HTTP/1.1\r\nHost: localhost:"..., 8000) = 418
stat("/var/www/html/", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
stat("/var/www/html/index.html", {st_mode=S_IFREG|0644, st_size=158, ...}) = 0
open("/var/www/html/index.html", O_RDONLY|O_CLOEXEC) = 11
fcntl(11, F_GETFD)                      = 0x1 (flags FD_CLOEXEC)
fcntl(11, F_SETFD, FD_CLOEXEC)          = 0
close(11)                               = 0
brk(0x7ffac326e000)                     = 0x7ffac326e000
writev(10, [{"HTTP/1.1 304 Not Modified\r\nDate:"..., 149}], 1) = 149
write(7, "10.0.2.2 - - [01/Sep/2014:07:26:"..., 148) = 148
shutdown(10, 1 /* send */)              = 0
poll([{fd=10, events=POLLIN}], 1, 2000) = 1 ([{fd=10, revents=POLLIN|POLLHUP}])
read(10, "", 512)                       = 0
close(10)                               = 0
read(5, 0x7fff4f57657f, 1)              = -1 EAGAIN (Resource temporarily unavailable)
accept4(4,

PID:2319
accept4(4, {sa_family=AF_INET6, sin6_port=htons(45804), inet_pton(AF_INET6, "::ffff:10.0.2.2", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 10
getsockname(10, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::ffff:10.0.2.15", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
fcntl(10, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(10, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
read(10, "GET /sample1.png HTTP/1.1\r\nHost:"..., 8000) = 435
stat("/var/www/html/sample1.png", {st_mode=S_IFREG|0644, st_size=342085, ...}) = 0
open("/var/www/html/sample1.png", O_RDONLY|O_CLOEXEC) = 11
fcntl(11, F_GETFD)                      = 0x1 (flags FD_CLOEXEC)
fcntl(11, F_SETFD, FD_CLOEXEC)          = 0
close(11)                               = 0
brk(0x7ffac326e000)                     = 0x7ffac326e000
writev(10, [{"HTTP/1.1 304 Not Modified\r\nDate:"..., 152}], 1) = 152
write(7, "10.0.2.2 - - [01/Sep/2014:07:26:"..., 180) = 180
shutdown(10, 1 /* send */)              = 0
poll([{fd=10, events=POLLIN}], 1, 2000) = 1 ([{fd=10, revents=POLLIN|POLLHUP}])
read(10, "", 512)                       = 0
close(10)                               = 0
read(5, 0x7fff4f57657f, 1)              = -1 EAGAIN (Resource temporarily unavailable)
accept4(4,

PID:2320
accept4(4, {sa_family=AF_INET6, sin6_port=htons(45799), inet_pton(AF_INET6, "::ffff:10.0.2.2", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 10
getsockname(10, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::ffff:10.0.2.15", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
fcntl(10, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(10, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
read(10, "GET /sample2.jpg HTTP/1.1\r\nHost:"..., 8000) = 435
stat("/var/www/html/sample2.jpg", {st_mode=S_IFREG|0644, st_size=77451, ...}) = 0
open("/var/www/html/sample2.jpg", O_RDONLY|O_CLOEXEC) = 11
fcntl(11, F_GETFD)                      = 0x1 (flags FD_CLOEXEC)
fcntl(11, F_SETFD, FD_CLOEXEC)          = 0
close(11)                               = 0
brk(0x7ffac326e000)                     = 0x7ffac326e000
writev(10, [{"HTTP/1.1 304 Not Modified\r\nDate:"..., 152}], 1) = 152
write(7, "10.0.2.2 - - [01/Sep/2014:07:26:"..., 180) = 180
shutdown(10, 1 /* send */)              = 0
poll([{fd=10, events=POLLIN}], 1, 2000) = 1 ([{fd=10, revents=POLLIN|POLLHUP}])
read(10, "", 512)                       = 0
close(10)                               = 0
read(5, 0x7fff4f57657f, 1)              = -1 EAGAIN (Resource temporarily unavailable)
accept4(4,

なるほど、3つのTCPリクエスト(index.htmlへとsample1.pngへとsampl2.jpgへ)が来て別々のプロセスがレスポンスしているのですね。トークでは、acceptで返ってきたファイルディスクリプタ(上だと10。以下、fd)を追うのが定石とのことでした。ざっくり見ると、fd10をreadしてGETリクエストを読み込んでから、リクエストされたリソースをfd11でオープンして、内容をfd10に書き込んでいるということでしょうか。最後にfd10をクローズしてからacceptで次回のリクエストを待機しています。

次に画面をリロードすると、今度はPID:2321、PID:2322、PID:2323のstraceに同じような挙動が。リクエストがくる度に、ラウンドロビンで応答するプロセスを回しているんですね。

　ここで、KeepAliveをOnにしてみました。

　同じようにブラウザからアクセスすると、

PID:2586
accept4(4, {sa_family=AF_INET6, sin6_port=htons(45931), inet_pton(AF_INET6, "::ffff:10.0.2.2", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 10
getsockname(10, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::ffff:10.0.2.15", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
fcntl(10, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(10, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
read(10, "GET / HTTP/1.1\r\nHost: localhost:"..., 8000) = 418
stat("/var/www/html/", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
stat("/var/www/html/index.html", {st_mode=S_IFREG|0644, st_size=158, ...}) = 0
open("/var/www/html/index.html", O_RDONLY|O_CLOEXEC) = 11
fcntl(11, F_GETFD)                      = 0x1 (flags FD_CLOEXEC)
fcntl(11, F_SETFD, FD_CLOEXEC)          = 0
close(11)                               = 0
writev(10, [{"HTTP/1.1 304 Not Modified\r\nDate:"..., 187}], 1) = 187
read(10, 0x7f3dfa150768, 8000)          = -1 EAGAIN (Resource temporarily unavailable)
write(7, "10.0.2.2 - - [01/Sep/2014:07:41:"..., 148) = 148
poll([{fd=10, events=POLLIN}], 1, 15000) = 1 ([{fd=10, revents=POLLIN}])

PID:2587
accept4(4, {sa_family=AF_INET6, sin6_port=htons(45932), inet_pton(AF_INET6, "::ffff:10.0.2.2", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 10
getsockname(10, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::ffff:10.0.2.15", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
fcntl(10, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(10, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
read(10, "GET /sample1.png HTTP/1.1\r\nHost:"..., 8000) = 435
stat("/var/www/html/sample1.png", {st_mode=S_IFREG|0644, st_size=342085, ...}) = 0
open("/var/www/html/sample1.png", O_RDONLY|O_CLOEXEC) = 11
fcntl(11, F_GETFD)                      = 0x1 (flags FD_CLOEXEC)
fcntl(11, F_SETFD, FD_CLOEXEC)          = 0
close(11)                               = 0
writev(10, [{"HTTP/1.1 304 Not Modified\r\nDate:"..., 190}], 1) = 190
read(10, 0x7f3dfa150768, 8000)          = -1 EAGAIN (Resource temporarily unavailable)
write(7, "10.0.2.2 - - [01/Sep/2014:07:41:"..., 180) = 180
poll([{fd=10, events=POLLIN}], 1, 15000) = 1 ([{fd=10, revents=POLLIN}])

PID:2588
accept4(4, {sa_family=AF_INET6, sin6_port=htons(45933), inet_pton(AF_INET6, "::ffff:10.0.2.2", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 10
getsockname(10, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::ffff:10.0.2.15", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
fcntl(10, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(10, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
read(10, "GET /sample2.jpg HTTP/1.1\r\nHost:"..., 8000) = 435
stat("/var/www/html/sample2.jpg", {st_mode=S_IFREG|0644, st_size=77451, ...}) = 0
open("/var/www/html/sample2.jpg", O_RDONLY|O_CLOEXEC) = 11
fcntl(11, F_GETFD)                      = 0x1 (flags FD_CLOEXEC)
fcntl(11, F_SETFD, FD_CLOEXEC)          = 0
close(11)                               = 0
writev(10, [{"HTTP/1.1 304 Not Modified\r\nDate:"..., 190}], 1) = 190
read(10, 0x7f3dfa14c748, 8000)          = -1 EAGAIN (Resource temporarily unavailable)
write(7, "10.0.2.2 - - [01/Sep/2014:07:41:"..., 180) = 180
poll([{fd=10, events=POLLIN}], 1, 15000) = 1 ([{fd=10, revents=POLLIN}])

PID:2586、PID:2587、PID:2588に対してさっきと同じような出力を確認(ただし、fd10をクローズしていないな)。

で、画面をリロード。

すると、またもやPID:2586、PID:2587、PID:2588が反応。1回1回のリクエストごとに接続をクローズしないで、使いまわしているのがわかりました。KeepAliveTimeoutが15(上記の最後の出力で、pollのタイムアウト値が15000msとなっているのがわかる)なので、15秒以上空けてからリクエストすると、応答するプロセスがスイッチして、PID:2589以降のプロセスが処理します。また、MaxKeepAliveRequestが100なので、100回リロード後には、やはりPID:2589以降のプロセスが処理します。

　個々の細かいシステムコールとかあんまり理解していませんが、今回はこんなところまでわかりました。

　これがKeepAliveの設定の違いなのか。。今まで全然実感なくほいほい設定していたけど。こんなことも分かっていなかったのは自分だけなのかもしれませんが、実感を持ってミドルのチューニングするのは重要だと思うので、よい経験になりました。

　Perlと全然関係ない内容になってしまいましたが、これもYAPC::Asiaに参加しなければ得られなかった知見です。発表者の方には本当に感謝です。すばらしい時間を過ごせました。

　せっかくだし、これを機にいろんな勉強会に足を運んでみたいと強く感じました。

ujunのブログ

plenvな環境でのif_perl

YAPC::Asia 2014(2日目)に行ってきて、straceを触ってみた。

Perl Mongersのためのstrace入門