Apache2.4をMPM_workerで動かしてKeepAlive有無によるログとパケットの差異を観察する

やったこと

ApacheのチューニングとしてHTTP Keep-Aliveの設定をよく見かけます。
このKeep-Alive、仕組みをわかってるつもりではいるんですが、挙動をじっくり見たことがありませんでした。
そこで今回は、Keep-Aliveの有無によって

• パケットキャプチャ
• アクセスログ

がどう変わるのかを観察してみます。

環境

# cat /etc/centos-release
CentOS Linux release 7.1.1503 (Core)

# httpd -v
Server version: Apache/2.4.6 (CentOS)
Server built:   Apr  2 2020 13:13:23

事前準備

今回はスレッドの動きも見たいので、ApacheをMPM workerで動かします。
設定は以下のファイルで実施します。

/etc/httpd/conf.modules.d/00-mpm.conf

LoadModule mpm_worker_module modules/mod_mpm_worker.so

アクセスログでプロセスID（PID）、スレッドID（TID）とリクエストを対応付けたいので、下記の通りログ設定を編集します。
\"%{pid}P\" \"%{tid}P\"の記載が当該箇所です。

/etc/httpd/conf/httpd.conf

LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{pid}P\" \"%{tid}P\" " combined

通信は、下記のtcpdumpコマンドでキャプチャします。pcapファイルに出力して、あとでWiresharkで確認します。

# tcpdump port 80 -i enp0s8 -w /home/vagrant/$(date "+%Y%m%d%H%M%S").pcap

Keep-Alive offの通信を観察する

Keep-Aliveをオフにします。
下記の下記の通り設定します。

/etc/httpd/conf/httpd.conf

KeepAlive Off

後でアクセスログを見てPIDとリクエストを対応付けたいので、ApacheのPIDを確認します。ユーザーがapacheと記載されているのがサーバープロセスです。一つのコントローラープロセス、4つのサーバープロセスが生成されていることがわかります。
Apacheのコントローラープロセス、サーバープロセス、スレッドの関係については以下の記事をご覧ください。
Apache2.4のMPM prefork/worker/eventの違いを理解する

# ps aux | grep httpd
root      4257  0.0  0.4 211268  4964 ?        Ss   23:00   0:00 /usr/sbin/httpd -DFOREGROUND
apache    4258  0.0  0.2 211016  2828 ?        S    23:00   0:00 /usr/sbin/httpd -DFOREGROUND
apache    4259  0.0  0.5 500232  5400 ?        Sl   23:00   0:00 /usr/sbin/httpd -DFOREGROUND
apache    4260  0.0  0.5 500232  5400 ?        Sl   23:00   0:00 /usr/sbin/httpd -DFOREGROUND
apache    4261  0.0  0.5 500232  5404 ?        Sl   23:00   0:00 /usr/sbin/httpd -DFOREGROUND

リソースにアクセスしてみます。今回は1ページにつき3枚の画像を含むページを/var/www/html/index.htmlに配置し、ブラウザからアクセスしてみました。
この時、先ほどのtcpdumpコマンドで通信をキャプチャします。

アクセスログを確認してみます。
右から2列目の4桁がPID、右端の列がTIDです。4リクエストの全てが異なるスレッドによって処理されたことがわかります。

# less /var/log/httpd/access_log
192.168.33.1 - - [12/May/2020:23:02:11 +0900] "GET /index.html HTTP/1.1" 200 356 "-" "4259" "140456360896256"
192.168.33.1 - - [12/May/2020:23:02:12 +0900] "GET /20200422_142825101_iOS.jpg HTTP/1.1" 200 128575 "http://192.168.33.10/index.html" "4260" "140456268576512"
192.168.33.1 - - [12/May/2020:23:02:12 +0900] "GET /20200422_144339615_iOS.jpg HTTP/1.1" 200 69018 "http://192.168.33.10/index.html" "4259" "140456344110848"
192.168.33.1 - - [12/May/2020:23:02:12 +0900] "GET /20200422_143625154_iOS.jpg HTTP/1.1" 200 180936 "http://192.168.33.10/index.html" "4261" "140456529565440"

tcpdumpコマンドでキャプチャしたpcapをwiresharkで確認します。
下の図は、index.htmlへのGETリクエストを選択して、当該リクエストが含まれるTCPセッションを表示したところです。
一つのTCPセッションにHTTPリクエスト・レスポンスが一往復のみしか含まれていませんね。

Keep-Alive onの通信を観察する

Keep-Alive onを有効にします。
下記の通り設定します。タイムアウト値は今回Apacheデフォルトの5秒にしています。

/etc/httpd/conf/httpd.conf

KeepAlive On
KeepAliveTimeout 5

PID、TIDを確認します。

# ps aux | grep httpd
root      4053  0.0  0.4 211268  4964 ?        Ss   21:47   0:00 /usr/sbin/httpd -DFOREGROUND
apache    4054  0.0  0.2 211016  2828 ?        S    21:47   0:00 /usr/sbin/httpd -DFOREGROUND
apache    4055  0.0  0.5 631304  5936 ?        Sl   21:47   0:00 /usr/sbin/httpd -DFOREGROUND
apache    4056  0.0  0.5 631304  5940 ?        Sl   21:47   0:00 /usr/sbin/httpd -DFOREGROUND
apache    4057  0.0  0.5 631304  5944 ?        Sl   21:47   0:00 /usr/sbin/httpd -DFOREGROUND
apache    4142  0.0  0.5 500232  5408 ?        Sl   21:49   0:00 /usr/sbin/httpd -DFOREGROUND

先ほどと同じようにtcpdumpコマンドを流しつつリソースにブラウザアクセスしてから、アクセスログを確認します。
KeepAliveがoffのときは各リクエストが異なるプロセス、スレッドで処理されていましたが、今回は4リクエスト中3リクエストが同一プロセス、同一スレッドで処理されたことがわかります。
なんか1リクエストPIDは異なるのにTIDは同じやつがいますがこれはよくわかりません。

192.168.33.1 - - [12/May/2020:21:56:03 +0900] "GET /index.html HTTP/1.1" 200 356 "-" "4055" "139884928952064"
192.168.33.1 - - [12/May/2020:21:56:03 +0900] "GET /20200422_142825101_iOS.jpg HTTP/1.1" 200 128575 "http://192.168.33.10/index.html" "4055" "139884928952064"
192.168.33.1 - - [12/May/2020:21:56:03 +0900] "GET /20200422_143625154_iOS.jpg HTTP/1.1" 200 180936 "http://192.168.33.10/index.html" "4055" "139884928952064"
192.168.33.1 - - [12/May/2020:21:56:03 +0900] "GET /20200422_144339615_iOS.jpg HTTP/1.1" 200 69018 "http://192.168.33.10/index.html" "4056" "139884928952064"

ネットワークキャプチャも確認します。
先ほどと同じく、/index.htmlへのGETリクエストを選択して、当該リクエストが含まれるTCPセッションを表示します。
今回は一つのTCPセッションにHTTPリクエスト・レスポンスが三往復含まれています。

なるほど有益な設定だった

Keep-Aliveを有効にすることで、一つのTCPセッション、スレッドで複数のHTTP通信をさばく様子を目で見て確認できて満足です。
リクエストがたくさん来た時でも、Keep-Aliveが有効ならApacheがスレッド数を使い切ってしまうのを防ぐことができそうです。
ただし、Keep-Aliveを設定した場合、Keep-Aliveタイムアウト（一つのTCPセッションが次のHTTP通信を待つ時間の上限）がくるまでスレッドが占有されることになります。
Keep-Aliveを設定したうえで性能が頭打ちを迎えてしまったら、Keep-Aliveタイムアウト値やスレッド数などを見直す必要があるかもしれません。