2014年4月28日月曜日

mod_info: 設定のダンプ(DUMP_CONFIG)

httpd-2.4では、mod_infoモジュールの機能で、起動時に設定内容のダンプが行えるようになっている。
使い方は簡単で、mod_infoモジュールを読み込むようにしておいて、起動時のオプションに -DDUMP_CONFIG を指定すればよい。

http://httpd.apache.org/docs/2.4/en/mod/mod_info.html#startup

-DDUMP_CONFIG実行例

(httpd.conf)
-------------------------------------------------
LoadModule info_module modules/mod_info.so
-------------------------------------------------

(コマンド実行例)
$ ./httpd -t -DDUMP_CONFIG
# In file: /usr/local/apache249/conf/httpd.conf
#   6:
ServerName www.example.com
#   9:
Listen 80
#  19:
StartServers 1
#  20:
MaxRequestWorkers 3
#  21:
MinSpareThreads 3
#  22:
MaxSpareThreads 3
#  23:
ThreadsPerChild 3
#  24:
MaxConnectionsPerChild 0
#  25:
AsyncRequestWorkerFactor 2
#  41:
KeepAlive on
#  42:
KeepAliveTimeout 5
#  43:
MaxKeepAliveRequests 100
#  50:
LogFormat "%h %l %u %t \"%r\" %>s %b" common
#  51:
CustomLog logs/access_log common
#  60:
LogLevel warn mpm_event:trace6
#  66:
Listen 443
#  71:
SSLRandomSeed startup file:/dev/urandom  256
#  72:
SSLRandomSeed connect builtin
#  74:
SSLSessionCache shmcb:logs/scache(1024000)
#  77:
SSLCryptoDevice builtin
#  81:
SSLFIPS off
#  84:
SSLPassPhraseDialog builtin
#  86:
LogFormat "%t %h %{SSL_PROTOCOL}x %{SSL_CIPHER}x \"%r\" %b" ssl_log
#  88:
<VirtualHost _default_:443>
  #  89:
  ErrorLog logs/ssl_error_log
  #  90:
  CustomLog logs/ssl_access_log ssl_log
  #  92:
  SSLEngine on
  #  95:
  SSLSessionCacheTimeout 300
  #  97:
  SSLCertificateFile conf/server.crt
  #  98:
  SSLCertificateKeyFile conf/server.key
  # 102:
  SSLProtocol all
  # 105:
  SSLCipherSuite HIGH:MEDIUM
  # 108:
  SSLCompression off
  # 111:
  SSLHonorCipherOrder off
  # 114:
  SSLInsecureRenegotiation off
</VirtualHost>
# 153:
ExtendedStatus on
# 155:
<Location /server-status>
  # 156:
  SetHandler server-status
</Location>
# 164:
Alias /cgi-bin /usr/local/apache249/cgi-bin
# 166:
<Directory /usr/local/apache249/cgi-bin>
  # 167:
  SetHandler cgi-script
  # 168:
  Options ExecCGI
</Directory>
Syntax OK

ただし、この出力では、既にIfModuleやIncludeは処理済みなので、出力されない。
.htaccessの内容も出力されない。
ServerRootも出力されないが、これは -DDUMP_RUN_CFG オプションを指定すれば出力される。
LoadModuleも出力されないが、これは -M オプションを指定すれば分かる。

-DDUMP_RUN_CFGの出力例

$ ./httpd -t -DDUMP_RUN_CFG
ServerRoot: "/usr/local/apache249"
Main DocumentRoot: "/usr/local/apache249/htdocs"
Main ErrorLog: "/usr/local/apache249/logs/error_log"
Mutex ssl-stapling: using_defaults
Mutex ssl-cache: using_defaults
Mutex default: dir="/usr/local/apache249/logs/" mechanism=default
PidFile: "/usr/local/apache249/logs/httpd.pid"
Define: DUMP_RUN_CFG
User: name="#-1" id=4294967295 not_used
Group: name="#-1" id=4294967295 not_used

-Mオプションの出力例

$ ./httpd -M
Loaded Modules:
 core_module (static)
 so_module (static)
 http_module (static)
 mpm_event_module (shared)
 unixd_module (shared)
 authz_core_module (shared)
 log_config_module (shared)
 mime_module (shared)
 ssl_module (shared)
 socache_shmcb_module (shared)
 status_module (shared)
 alias_module (shared)
 cgid_module (shared)
 info_module (shared)

ときどき、読み込まれた設定を確認したいことがあり、mod_infoで ?config クエリを使っていたりしたが、 mod_infoのステータス画面の出力設定を残すのが嫌な場合もあった。
これなら起動時に確認され、infoページへのアクセスの設定もないので、都合がよさそうだ。
ただし、今、実行中のプロセスの設定内容を出力させるには、mod_infoの情報ページにアクセスしなくてはならないようだ。

注意点

-DDUMP_CONFIGは読み込んだ設定情報を出力しているだけで、有効な設定だけを出力しているわけではない。
たとえば、設定ファイルに重複した設定があった場合、

StartServers         1
StartServers         10

その内容がそのまま出力される。
$ ./httpd -t -DDUMP_CONFIG
# In file: /usr/local/apache249/conf/httpd.conf
#   6:
PidFile conf/httpd.pid
#   9:
ServerName www.example.com
#  12:
Listen 80
#  22:
StartServers 1
#  23:
StartServers 10
 :


2014年4月21日月曜日

event MPMのタイムアウトキュー

event MPMには4つのタイムアウトキューが存在する。

タイムアウトまでの経過時間別にキューが用意されているため、タイムアウトイベントの登録は、末尾に行われる。登録された順に、タイムアウト時間が経過することになる。キューという呼び名の通り、タイムアウト時刻が経過しているかどうかは先頭から確認される。
タイムアウトの発生前に、待っているイベント(ソケットの受信や送信)が発生すれば、各タイムアウトキューからその情報は除去される。


(1) write_completion_q

  • レスポンスの送信が未完了な場合に利用される。 
  • TimeOut でのタイムアウト待ちキュー。 
  • TimeOut 経過前に書き込み可能になったら、書き込み処理がworkerスレッドで実行される。 
  • TimeOut 経過した場合、ソケットのwrite側をshutdownし、linger_qでクローズ待ちする。 

(2) keepalive_q

  • レスポンス送信完了後の次リクエスト受信待ちに利用される。 
  • KeepAliveTimeOut でのタイムアウト待ちキュー。 
  • KeepAliveTimeOut 経過前に読込可能になったら、リクエスト処理がworkerスレッドで実行される。 
  • KeepAliveTimeOut 経過した場合、ソケットのwrite側をshutdownし、linger_qでクローズ待ちする。 

(3) linger_q

  • ソケットのwrite側のshutdown後の、FIN待ちに利用される。 
  • MAX_SECS_TO_LINGER(30秒) でのタイムアウト待ちキュー 
  • MAX_SECS_TO_LINGER 経過前に読込可能になったら、読み捨て処理を行い、ソケットをクローズする 
  • MAX_SECS_TO_LINGER 経過した場合、ソケットをクローズする 

(4) short_linger_q

  • ソケットのwrite側のshutdown後の、FIN待ちに利用される。 
  • SECONDS_TO_LINGER(2秒) でのタイムアウト待ちキュー 
    • notesに"short-lingering-close"は存在した場合に、linger_qではなく、こちらを使用する。 
    • mod_reqtimeoutで受信タイムアウト時に指定されていた。他は見当たらない。 
  • SECONDS_TO_LINGER 経過前に読込可能になったら、読み捨て処理を行い、ソケットをクローズする 
  • SECONDS_TO_LINGER 経過した場合、ソケットをクローズする


これらのタイムアウト待ちもworker MPMでは、workerスレッド内で待っていたが、event MPMでは、タイムアウトキューに登録し、また、対応するソケットを (centos5では)epollの監視対象に追加し、listenerスレッドで待ち受けを行うようになった。
これにより、workerスレッドの無駄な待ち時間が削減され、結果的に処理効率が改善したと考えられる。
KeepAliveTimeOutの待ち時間以外の改善個所もあることから、KeepAliveを利用していない場合にも性能改善が見られたのはこの効果ではないかと考えている。

ちなみに、KeepAlive Onで実行していると、レスポンスを返した後、ソケットはkeepalive_qに入るが、もしクライアントが直ちにソケットを閉じた場合、listenerスレッドはソケットが読込可能になったことを検知し、workerスレッドに引き渡す。その後、workerスレッドが読み込むと、EOFが検知されることになる。

2014年4月14日月曜日

apr_skiplist とmod_dialupモジュール

httpd-2.4.7で行われている変更:
Changes with Apache 2.4.7

  *) APR 1.5.0 or later is now required for the event MPM.
これがなぜだろう、というblogを見かけた。

同じblogの記事内に、以下のconfig.logのメッセージが紹介されている。
configure:25866: result: no - APR skiplist is not available

したがって、これは、以下の関係だろうと想像された。
Changes for APR 1.5.0
 :

  *) Add apr_skiplist family. [Jim Jagielski]

blogを書かれた方の意図はともかく、少し調べてみるとこれに関連した 2.4系branch の修正は、次のcommitで行われていた。
http://svn.apache.org/viewvc?view=revision&revision=1542560

http://svn.apache.org/viewvc?view=revision&revision=1543475
ここにある、Jeffのアイデアというのはこれだろう。
http://mail-archives.apache.org/mod_mbox/httpd-dev/201311.mbox/%3CCAKUrXK5n7havg2-6MR6JAt0dQecbH6je6K9ySY8iHNQfN6mv8g%40mail.gmail.com%3E


ちなみに、もともとhttpd側で実装していたのを、APRに引っ越させたらしい。
http://svn.apache.org/viewvc?view=revision&revision=1528438
http://svn.apache.org/viewvc?view=revision&revision=1527536
これはどうでもいいか。

2014年4月7日月曜日

event MPM と worker MPM の比較 追加: httperf

Keep-Alive無効の場合も、CPU使用率が worker MPM < event MPM となっていた。
その分、毎秒のリクエスト処理件数も増えているのだと考えられるが、念のため、httperfで固定レートでリクエスト負荷を加えた場合のCPU使用率を比較した。
結果的には、両者のCPU使用率の差は些少だった。
負荷をかけている期間(約100秒)中のCPU使用率の平均は以下の通り。


event MPM worker MPM
%user 13.23 13.09
%nice 0.00 0.00
%system 19.10 18.91
%iowait 0.09 0.09
%steal 0.00 0.00
%idle 67.59 67.92


基本的にリクエスト処理によるCPU負荷は event MPM と worker MPM では大差はない。
event MPM の処理効率が上がっているため、abによる性能検証で、リクエスト処理件数が上がり、処理件数が増えた分、CPU使用率が増大した、ということでよいだろう。

以下 httperfコマンド実行結果をコピペし、投稿末尾に、CPU使用率のグラフをつけた。
特に深い考えはないが、いずれもhttperf は2プロセスで実行した。

(1) event MPM


(1.1) httperf #1

$ ./httperf --server centos5 --port 8080 --uri /hello.html --num-conns 200000 --rate 2000
httperf --client=0/1 --server=centos5 --port=8080 --uri=/hello.html --rate=2000 --send-buffer=4096 --recv-buffer=16384 --num-conns=200000 --num-calls=1
httperf: warning: open file limit > FD_SETSIZE; limiting max. # of open files to FD_SETSIZE
Maximum connect burst length: 3

Total: connections 200000 requests 200000 replies 200000 test-duration 99.993 s

Connection rate: 2000.1 conn/s (0.5 ms/conn, <=10 concurrent connections)
Connection time [ms]: min 0.4 avg 0.7 max 4.8 median 0.5 stddev 0.1
Connection time [ms]: connect 0.2
Connection length [replies/conn]: 1.000

Request rate: 2000.1 req/s (0.5 ms/req)
Request size [B]: 71.0

Reply rate [replies/s]: min 1999.9 avg 2000.1 max 2000.1 stddev 0.1 (19 samples)
Reply time [ms]: response 0.4 transfer 0.0
Reply size [B]: header 224.0 content 31.0 footer 0.0 (total 255.0)
Reply status: 1xx=0 2xx=200000 3xx=0 4xx=0 5xx=0

CPU time [s]: user 23.85 system 76.08 (user 23.8% system 76.1% total 99.9%)
Net I/O: 636.8 KB/s (5.2*10^6 bps)

Errors: total 0 client-timo 0 socket-timo 0 connrefused 0 connreset 0
Errors: fd-unavail 0 addrunavail 0 ftab-full 0 other 0

(1.2) httperf #2

#  ./httperf --server centos5 --port 8080 --uri /hello.html --num-conns 200000 --rate 2000
httperf --client=0/1 --server=centos5 --port=8080 --uri=/hello.html --rate=2000 --send-buffer=4096 --recv-buffer=16384 --num-conns=200000 --num-calls=1
httperf: warning: open file limit > FD_SETSIZE; limiting max. # of open files to FD_SETSIZE
Maximum connect burst length: 4

Total: connections 200000 requests 200000 replies 200000 test-duration 99.993 s

Connection rate: 2000.1 conn/s (0.5 ms/conn, <=10 concurrent connections)
Connection time [ms]: min 0.1 avg 0.7 max 4.8 median 0.5 stddev 0.1
Connection time [ms]: connect 0.3
Connection length [replies/conn]: 1.000

Request rate: 2000.1 req/s (0.5 ms/req)
Request size [B]: 71.0

Reply rate [replies/s]: min 1999.9 avg 2000.1 max 2000.1 stddev 0.1 (19 samples)
Reply time [ms]: response 0.4 transfer 0.0
Reply size [B]: header 224.0 content 31.0 footer 0.0 (total 255.0)
Reply status: 1xx=0 2xx=200000 3xx=0 4xx=0 5xx=0

CPU time [s]: user 21.87 system 78.04 (user 21.9% system 78.0% total 99.9%)
Net I/O: 636.8 KB/s (5.2*10^6 bps)

Errors: total 0 client-timo 0 socket-timo 0 connrefused 0 connreset 0
Errors: fd-unavail 0 addrunavail 0 ftab-full 0 other 0


(2) worker MPM


(2.1) httperf #1

$ ./httperf --server centos5 --port 8080 --uri /hello.html --num-conns 200000 --rate 2000
httperf --client=0/1 --server=centos5 --port=8080 --uri=/hello.html --rate=2000 --send-buffer=4096 --recv-buffer=16384 --num-conns=200000 --num-calls=1
httperf: warning: open file limit > FD_SETSIZE; limiting max. # of open files to FD_SETSIZE
Maximum connect burst length: 3

Total: connections 200000 requests 200000 replies 200000 test-duration 99.993 s

Connection rate: 2000.1 conn/s (0.5 ms/conn, <=10 concurrent connections)
Connection time [ms]: min 0.4 avg 0.7 max 4.7 median 0.5 stddev 0.1
Connection time [ms]: connect 0.3
Connection length [replies/conn]: 1.000

Request rate: 2000.1 req/s (0.5 ms/req)
Request size [B]: 71.0

Reply rate [replies/s]: min 1999.9 avg 2000.1 max 2000.1 stddev 0.1 (19 samples)
Reply time [ms]: response 0.4 transfer 0.0
Reply size [B]: header 224.0 content 31.0 footer 0.0 (total 255.0)
Reply status: 1xx=0 2xx=200000 3xx=0 4xx=0 5xx=0

CPU time [s]: user 23.74 system 76.18 (user 23.7% system 76.2% total 99.9%)
Net I/O: 636.8 KB/s (5.2*10^6 bps)

Errors: total 0 client-timo 0 socket-timo 0 connrefused 0 connreset 0
Errors: fd-unavail 0 addrunavail 0 ftab-full 0 other 0

(2.2) httperf #2

#  ./httperf --server centos5 --port 8080 --uri /hello.html --num-conns 200000 --rate 2000
httperf --client=0/1 --server=centos5 --port=8080 --uri=/hello.html --rate=2000 --send-buffer=4096 --recv-buffer=16384 --num-conns=200000 --num-calls=1
httperf: warning: open file limit > FD_SETSIZE; limiting max. # of open files to FD_SETSIZE
Maximum connect burst length: 4

Total: connections 200000 requests 200000 replies 200000 test-duration 99.993 s

Connection rate: 2000.1 conn/s (0.5 ms/conn, <=10 concurrent connections)
Connection time [ms]: min 0.2 avg 0.7 max 4.8 median 0.5 stddev 0.1
Connection time [ms]: connect 0.3
Connection length [replies/conn]: 1.000

Request rate: 2000.1 req/s (0.5 ms/req)
Request size [B]: 71.0

Reply rate [replies/s]: min 1999.9 avg 2000.1 max 2000.1 stddev 0.1 (19 samples)
Reply time [ms]: response 0.4 transfer 0.0
Reply size [B]: header 224.0 content 31.0 footer 0.0 (total 255.0)
Reply status: 1xx=0 2xx=200000 3xx=0 4xx=0 5xx=0

CPU time [s]: user 22.19 system 77.72 (user 22.2% system 77.7% total 99.9%)
Net I/O: 636.8 KB/s (5.2*10^6 bps)

Errors: total 0 client-timo 0 socket-timo 0 connrefused 0 connreset 0
Errors: fd-unavail 0 addrunavail 0 ftab-full 0 other 0

(3)CPU使用率比較


(3.1) event MPM


(3.2) worker MPM


2014年4月1日火曜日

event MPM と worker MPM の比較まとめ

(1) CPU使用率の比較

event MPM > worekr MPM
event MPMではsystem + user で90%以上の値になっている(Keep-Alive有効の方がやや高い)。
worker MPMの場合は、Keep-Alive無効で60%程度、KeepAlive有効だと更に低く50%程度になる。
リクエストの処理件数の違いが現われているんだろう。


Keep-Alive無効 Keep-Alive有効
event MPM worker MPM event MPM worker MPM
%user 36.56 24.19 42.74 23.42
%nice 0.00 0.00 0.00 0.00
%system 53.04 37.66 51.03 25.28
%iowait 0.34 0.27 0.14 0.15
%steal 0.00 0.00 0.00 0.00
%idle 10.06 37.88 6.09 51.14

メモ

そもそも、Keep-Alive有効な状態で、worker MPMがリクエストをどう処理したのか。
今回の設定では、MaxKeepAliveRequestsは指定していない。
したがってデフォルトの100になっている。
100リクエストの処理が終わると、接続が切られ、次のコネクションがworkerスレッドを割り当てられるといった順序で処理が行われていったのだろう。
アクセスログに %k (この接続でのKeep-Aliveなリクエスト処理数) を追加して、値を確認してみると、確かに、100より大きな値は見られなかった。


(2) リクエスト処理数の比較

abでの1秒あたりのリクエストの処理数はKeep-Alive有効、無効いずれの場合もevent MPMの方が優位だった。


(<table>タグがなぜかうまく使えなかったので、絵にした)

ただし、event MPM(Keep-Alive有効)の場合は、リクエストエラーが発生した。
また、残念ながらネットワーク(100Mbps)的にもこのあたりが限界だった。

Keep-Aliveが無効なら、worker MPMとevent MPMで処理に違いがあるとは思わなかったが、実際には差が生じている。workerスレッド数以上に接続を保持できる構成や、ソケットのシャットダウン処理の非同期化が効果を上げているのだろうか。


念のため httperfを用いて固定レートでの負荷をかけてCPU使用率の比較を行った。
これは次回。


(2014/4/3) CPU使用率の比較に表を追加