プログラマ 福重 伸太朗 〜基本へ帰ろう〜 このページをアンテナに追加 RSSフィード

2009-04-21

qmail送信パフォーマンス改善のテスト

前回のテストの中で、もうひとつ実験をしていました。

それは、qmailの配信速度改善です。

実験方法は単純で、concurrencylocal の数を 倍にすると、単純にローカル配送速度は倍になるのか?というものでした。

前回のテストの1回目(syslogの時)の concurrencylocal は 120 です。それを、240 にしたら配送時間は倍になるのでしょうか。qmailインストール時に big-concurrency.patch を適用していますので、120以上に上げることができます。

同じ、syslogの状態のときに(multilogになる前に)、やってみました。

送信もしますが、受信もしますので、tcpserverの同時起動可能プロセス数(-c)は 480 に上げます。(ちなみに変更前は 240 です)



  • 設定の確認
# /var/qmail/bin/qmail-showctl | grep concurrencylocal
concurrencylocal: Local concurrency is 240.
# ps aux | grep tcpserver
qmaild   14158  0.0  0.0   1716   512 ttyp0    S    17:09   0:00 tcpserver -qv -l0 -HR -u 503 -g 502 -c 480 -x /etc/tcp.smtp.cdb 0 smtp qmail-smtpd dev_pv_web /bin/checkpassword /bin/true

では、同じように、rootからadminへ1万通送信してみましょう。何分かかるでしょうか。単純計算すると10分の半分 5 分程度で終わるような気がします。



実験結果

# sh mass_mail_test.sh
start : Tue Apr 21 17:13:40 JST 2009
end : Tue Apr 21 17:26:17 JST 2009

なんと、12分以上かかりました。送信処理の最大並列数を倍にしたのに、倍にする前より多くの時間がかかってしまいました。なぜでしょう。まず、sarの結果をみてみましょう。

ちなみに、OS自体のプロセス数上限は、 6144 ですので、問題ないと思います。

# ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
max nice                        (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 6144
max locked memory       (kbytes, -l) 32
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1024
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
max rt priority                 (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 6144
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

時間は、17:13:40〜17:26:17の部分です。(16:45前後のものはconcurrencylocal は 120のときのものです)

f:id:japanrock_pg:20090421235311p:image

f:id:japanrock_pg:20090421235310p:image

f:id:japanrock_pg:20090421235313p:image

f:id:japanrock_pg:20090421235312p:image

f:id:japanrock_pg:20090421235308p:image

f:id:japanrock_pg:20090421235309p:image


I/O負荷やプロセス数が下がっています・・・。送信処理の最大並列数を上げると、プロセス数は上がるような気はするが・・・なぜだ・・・・。

つっこみ大歓迎です><







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

what

no title

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



実験方法

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



実験環境

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

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

f:id:japanrock_pg:20090421221729p:image



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の部分です)

f:id:japanrock_pg:20090421221733p:image

f:id:japanrock_pg:20090421221732p:image

f:id:japanrock_pg:20090421221735p:image

f:id:japanrock_pg:20090421223006p:image

f:id:japanrock_pg:20090421221730p:image

f:id:japanrock_pg:20090421221731p:image



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

mailログを multilogへ移行後、10000通送信してみました。

multilogへの移行はsyslog は I/O 負荷が高い → daemontool に移行しよう! - drk7jpを参考にしました。


#!/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 にログが流れ込んできます。

f:id:japanrock_pg:20090421224634p:image



  • 結果
# 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の部分です)

f:id:japanrock_pg:20090421223003p:image

f:id:japanrock_pg:20090421223002p:image

f:id:japanrock_pg:20090421223005p:image

f:id:japanrock_pg:20090421223004p:image

f:id:japanrock_pg:20090421223000p:image

f:id:japanrock_pg:20090421223001p:image

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



今回のテストのまとめ

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

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



おまけ( qmailmrtg7 )

multilogにしていると、qmailmrtg7 というソフトが使え、qmailのログの状況をグラフ化して見れます。やってみます。

ツールを使った効率的なログ分析術:実用qmailサーバ運用・管理術(10) - @ITを参考にやりました。

グラフで見れるのはよいですね。


f:id:japanrock_pg:20090421233230p:image