syslog と multilog の I/O負荷の差を調査

サーバー qmail パフォーマンス

what

http://neta.ywcafe.net/000582.html
現在、大量メール配信サーバの I/O 負荷が高い問題があり、上記の記事をきっかけに、実際に syslog と multilog で I/O 負荷が違うのか見てみた。I/O負荷が高いのは、おそらく /var/log/maillogへの書き込みに負荷がかかっているものと思われる。


実験方法

MTAはqmail を利用します。qmailでユーザrootからユーザadmin へローカル配送を1万通行い、それのメールログ書き込みに伴う I/O負荷を sar の結果で比較します。


実験環境

coLinux on CentOS 5.1（セットアップ方法はこちら） に qmail をインストールして、ユーザ admin を作成します。絵で見ると以下のような構成です。

OS Windows XP Professional Version 2002 Service Pack 3
CPU ADM Athlon(tm) 64 X2 Dual Core Proccessor 3600+ 190 GHz
メモリ 2.00 GB RAM
coLinuxに割り当てたメモリ 768 MB
qmailバージョン 1.03


qmail の設定
# /var/qmail/bin/qmail-showctl
qmail home directory: /var/qmail.
user-ext delimiter: -.
paternalism (in decimal): 2.
silent concurrency limit: 509.
subdirectory split: 23.
user ids: 502, 503, 504, 0, 505, 506, 507, 508.
group ids: 502, 503.
badmailfrom: (Default.) Any MAIL FROM is allowed.
bouncefrom: (Default.) Bounce user name is MAILER-DAEMON.
bouncehost: (Default.) Bounce host name is dev_pv_web.
concurrencylocal: Local concurrency is 120.
concurrencyremote: Remote concurrency is 120.
databytes: (Default.) SMTP DATA limit is 0 bytes.
defaultdomain: Default domain name is dev_pv_web.
defaulthost: (Default.) Default host name is dev_pv_web.
doublebouncehost: (Default.) 2B recipient host: dev_pv_web.
doublebounceto: (Default.) 2B recipient user: postmaster.
envnoathost: (Default.) Presumed domain name is dev_pv_web.
helohost: (Default.) SMTP client HELO host name is dev_pv_web.
idhost: (Default.) Message-ID host name is dev_pv_web.
localiphost: (Default.) Local IP address becomes dev_pv_web.
locals:
Messages for dev_pv_web are delivered locally.
me: My name is dev_pv_web.
percenthack: (Default.) The percent hack is not allowed.
plusdomain: Plus domain name is dev_pv_web.
qmqpservers: (Default.) No QMQP servers.
queuelifetime: (Default.) Message lifetime in the queue is 604800 seconds.
rcpthosts:
SMTP clients may send messages to recipients at dev_pv_web.
morercpthosts: (Default.) No effect.
morercpthosts.cdb: (Default.) No effect.
smtpgreeting: (Default.) SMTP greeting: 220 dev_pv_web.
smtproutes: (Default.) No artificial SMTP routes.
timeoutconnect: SMTP client connection timeout is 20 seconds.
timeoutremote: SMTP client data timeout is 20 seconds.
timeoutsmtpd: (Default.) SMTP server data timeout is 1200 seconds.
virtualdomains: (Default.) No virtual domains.

qmailインストール時に以下のパッチをあてています。

  • patch < qmail-date-localtime.patch
  • patch < auth.patch
  • patch < qmail-smtpd-relay-reject
  • patch -p1 < big-concurrency.patch
tcpserverの同時接続数

240 に設定しました。基準は、メール配信同時プロセス（concurrencylocal）が 120 であるためです。余裕をもって設定しました。

# ps aux | grep tcp
qmaild    1439  0.0  0.0   1716   512 ttyp0    S    15:59   0:00 tcpserver -qv -l0 -HR -u 503 -g 502 -c 240 -x /etc/tcp.smtp.cdb 0 smtp qmail-smtpd dev_pv_web /bin/checkpassword /bin/true
sysstat(sar)のcronの設定状況

1分ごとに sar の結果を出力するように設定しました。

# cat /etc/cron.d/sysstat
# Run system activity accounting tool every 10 minutes
*/1 * * * * root /usr/local/lib/sa/sa1 -d 1 1
# 0 * * * * root /usr/local/lib/sa/sa1 -d 600 6 &
# Generate a daily summary of process accounting at 23:53
53 23 * * * root /usr/local/lib/sa/sa2 -A
coLinux on CentOS5.1の状況
# df
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/cobd0             6047492   2093996   3646296  37% /
none                    387980         0    387980   0% /dev/shm

# free
             total       used       free     shared    buffers     cached
Mem:        775964     166268     609696          0       7696     130700
-/+ buffers/cache:      27872     748092
Swap:       102392          0     102392
coLinux on CentOS5.1 に割り当てたドメインとMXレコード

coLinux on CentOS5.1 のIP 10.20.138.175 に dev.fukushige.live-revolution.co.jp というドメインを向け、MXレコードを向けます。社内DNSに設定しました。

# dig dev.fukushige.live-revolution.co.jp MX

; <<>> DiG 9.3.3rc2 <<>> dev.fukushige.live-revolution.co.jp MX
;; global options:  printcmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 47218
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 1, ADDITIONAL: 2

;; QUESTION SECTION:
;dev.fukushige.live-revolution.co.jp. IN        MX

;; ANSWER SECTION:
dev.fukushige.live-revolution.co.jp. 86400 IN MX 10 dev.fukushige.live-revolution.co.jp.

;; AUTHORITY SECTION:
dev.fukushige.live-revolution.co.jp. 86400 IN NS ns.live-revolution.co.jp.

;; ADDITIONAL SECTION:
dev.fukushige.live-revolution.co.jp. 86400 IN A 10.20.138.175
ns.live-revolution.co.jp. 86400 IN      A       10.20.138.9

;; Query time: 49 msec
;; SERVER: 10.20.138.1#53(10.20.138.1)
;; WHEN: Tue Apr 21 15:29:14 2009
;; MSG SIZE  rcvd: 118

配送テスト

root から admin へ配送

# echo to:admin@dev.fukushige.live-revolution.co.jp | /var/qmail/bin/qmail-inject

/var/log/maillog の内容

Apr 21 15:33:21 dev_pv_web qmail: 1240295601.900032 new msg 703526
Apr 21 15:33:21 dev_pv_web qmail: 1240295601.900115 info msg 703526: bytes 270 from <root@dev.fukushige.live-revolution.co.jp> qp 1298 uid 0
Apr 21 15:33:21 dev_pv_web qmail: 1240295601.932297 starting delivery 1: msg 703526 to local admin@dev.fukushige.live-revolution.co.jp
Apr 21 15:33:21 dev_pv_web qmail: 1240295601.932377 status: local 1/120 remote 0/120
Apr 21 15:33:21 dev_pv_web qmail: 1240295601.954598 delivery 1: success: did_1+0+0/
Apr 21 15:33:21 dev_pv_web qmail: 1240295601.954682 status: local 0/120 remote 0/120
Apr 21 15:33:21 dev_pv_web qmail: 1240295601.954726 end msg 703526

ちゃんと、 success している。


メールボックス確認

$ find /home/admin/Maildir/new/ -type f | wc -l
5
$ ls -la /home/admin/Maildir/new/
total 12
drwx------ 2 admin admin 4096 Apr 21 15:33 .
drwx------ 5 admin admin 4096 Apr 21 14:52 ..
-rw------- 1 admin admin  382 Apr 21 15:33 1240295601.1301.dev_pv_web

ちゃんと届いている。


実験に用いたスクリプトのテスト

  • mass_mail_test.sh
#!/bin/bash

CNT=0
while [ ${CNT} -lt 4 ]
do
   echo to:admin@dev.fukushige.live-revolution.co.jp | /var/qmail/bin/qmail-inject
   CNT=$(expr ${CNT} + 1)
done

ためしに、4通送ってみる。rootで実行（ # sh mass_mail_test.sh ）。


メールボックスを確認

$ find /home/admin/Maildir/new/ -type f | wc -l
5
$ ls -la /home/admin/Maildir/new/
total 28
drwx------ 2 admin admin 4096 Apr 21 16:11 .
drwx------ 5 admin admin 4096 Apr 21 14:52 ..
-rw------- 1 admin admin  382 Apr 21 15:33 1240295601.1301.dev_pv_web
-rw------- 1 admin admin  382 Apr 21 16:11 1240297869.1515.dev_pv_web
-rw------- 1 admin admin  382 Apr 21 16:11 1240297869.1522.dev_pv_web
-rw------- 1 admin admin  382 Apr 21 16:11 1240297869.1529.dev_pv_web
-rw------- 1 admin admin  382 Apr 21 16:11 1240297869.1533.dev_pv_web

先ほどの、1通のテストをあわせて、5通ちゃんと届いている。

他にも、5通ほどテストしましたので、受信メールは合計 10 通になりました。

$ find /home/admin/Maildir/new/ -type f | wc -l
10

1000通テストで送ってみます

こんどは、1000通送ってみます。スタート時間と終了時間も取得してみます。

  • mass_mail_test.sh
#!/bin/bash

echo "start : `date`"

CNT=0
while [ ${CNT} -lt 1000 ]
do
   echo to:admin@dev.fukushige.live-revolution.co.jp | /var/qmail/bin/qmail-inject
   CNT=$(expr ${CNT} + 1)
done

echo "end : `date`"


1000通送るのに、ぴったり 1分かかりました。

# sh mass_mail_test.sh
start : Tue Apr 21 16:35:59 JST 2009
end : Tue Apr 21 16:36:59 JST 2009

受信ボックスにも 1000 通ちゃんと追加されています。

$ find /home/admin/Maildir/new/ -type f | wc -l
1010

特に問題がないようです。


1万通送ってみる

そろそろ負荷テストっぽくなってきました。今度は、1万通送ってみましょう。1000通で 1分ほどでしたので、10分程度で終わるのかと思います。やってみます。

  • mass_mail_test.sh
#!/bin/bash

echo "start : `date`"

CNT=0
while [ ${CNT} -lt 10000 ]
do
   echo to:admin@dev.fukushige.live-revolution.co.jp | /var/qmail/bin/qmail-inject
   CNT=$(expr ${CNT} + 1)
done

echo "end : `date`"


途中で ps aux を見てみると、qmail-local がプロセスにいくつも存在しており、ローカル配送しているのがわかります。

Last login: Tue Apr 21 16:43:25 2009 from 10.20.138.71
[admin@dev_pv_web ~]$ ps aux | grep local
pgsql      807  0.0  0.5  48060  3904 ?        S    14:14   0:00 /usr/local/pgsql/bin/postgres -D /usr/local/pgsql/data
admin    20822  0.0  0.0   1544   336 ttyp0    S    16:44   0:00 bin/qmail-local -- admin /home/admin admin   dev.fukushige.live-revolution.co.jp root@dev.fukushige.live-revolution.co.jp ./Maildir/
admin    20824  0.0  0.0   1544   344 ttyp0    R    16:44   0:00 bin/qmail-local -- admin /home/admin admin   dev.fukushige.live-revolution.co.jp root@dev.fukushige.live-revolution.co.jp ./Maildir/
admin    20829  0.0  0.0   3912   712 ttyp3    S+   16:44   0:00 grep local


結果

# sh mass_mail_test.sh
start : Tue Apr 21 16:42:51 JST 2009
end : Tue Apr 21 16:52:59 JST 2009

予想通り、10分程度かかりました。 tail -f /var/log/maillog で眺めていましたが、ずっと success でした。失敗はなさそうです。

admin の受信ボックスを見てみると、

$ find /home/admin/Maildir/new/ -type f | wc -l
11010

しっかりと、1万通プラスされています。


ここで、その 10 分間の負荷状況を見てみましょう。（時間は16:42:51〜16:52:59の部分です）







multilogを採用して、I/O負荷を見てみる

mailログを multilogへ移行後、10000通送信してみました。
multilogへの移行はsyslog は I/O 負荷が高い → daemontool に移行しよう！ - drk7jpを参考にしました。

  • 送信プログラム( mass_mail_test.sh )
#!/bin/bash

echo "start : `date`"

CNT=0
while [ ${CNT} -lt 10000 ]
do
   echo to:admin@dev.fukushige.live-revolution.co.jp | /var/qmail/bin/qmail-inject
   CNT=$(expr ${CNT} + 1)
done

echo "end : `date`"


わさわさと、 /var/log/qmail/current にログが流れ込んできます。


  • 結果
# sh mass_mail_test.sh
start : Tue Apr 21 21:42:27 JST 2009
end : Tue Apr 21 21:52:37 JST 2009

時間は変わりませんでした。10分です。もちろん、メールボックスにはしっかり届いていました。


その 10 分間の負荷状況を見てみましょう。（時間は21:42:27~21 21:52:37の部分です）






・・・あまり変化がない・・・・orz


今回のテストのまとめ

syslog と multilog の差があまり変化が見られない・・・。ローカル配送で1万通送った程度では、あまり変化がないのでしょうか・・・。それとも、何かやりかたを間違えているのでしょうか・・・。

今回のテストについて、つっこみ大歓迎です＞＜


おまけ（ qmailmrtg7 ）

multilogにしていると、qmailmrtg7 というソフトが使え、qmailのログの状況をグラフ化して見れます。やってみます。
ツールを使った効率的なログ分析術 (2/2)：実用qmailサーバ運用・管理術（10） - ＠ITを参考にやりました。
グラフで見れるのはよいですね。