Postfixがきりの良い時間にアクセスすると遅い
Postfixがきりの良い時間にアクセスすると遅い
背景
ユーザから「cronがキックするスクリプトがメールを送るとPostfixからの応答が遅くタイムアウトが起きている」と報告された。
結論
nslcdのレスポンスが遅いことが原因だった。 きりの良い時間はLDAPのアクセスが多く、負荷が高まるためレスポンスが遅くなっている。 対象のPostfixは動作上LDAPが必要なく、nslcdがLDAPの応答がない場合にさっさとタイムアウトするようにすることで改善した。
調査
最初はmilter、saslauthdを疑っていたのだが、両者を外した状態で検証しても改善しない。 master.cf, main.cfのパラメタも変えてみたが改善しない。 回りくどいことはやめて、straceでプロセスを追ってみた。
$ ps auxww | grep master root 12984 0.0 0.0 107452 948 pts/1 S+ 16:07 0:00 grep master $ sudo strace -tt -s 2048 -f -p 12984 -t > strace.20151105 2>&1
1:35:01 clone(Process 9798 attached [pid 12984] 21:35:01 clone(Process 9799 attached
9799と9788はmasterがcloneを実行して作成したプロセス。
[pid 9799] 21:35:01 open("/lib64/libnss_ldap.so.2", O_RDONLY) = 1
ldapライブラリを読み込んでいる
[pid 9799] 21:35:01 execve("/usr/libexec/postfix/smtpd", ["smtpd", "-n", "465", "-t", "inet", "-u", "-o", "stress=", "-s", "2", "-o", "smtpd_sasl_auth_enable=yes", "-o", "smtpd_sasl_security_options=noanonymous"], [/* 4 vars */] <unfinished ...>
9799はmasterからsmtpdに転身する。
9799だけに関して見ると以下のように1秒から14秒まで飛んでいる。
[pid 9799] 21:35:01 munmap(0x7fc9a8b3b000, 34862) = 0 [pid 9799] 21:35:01 socket(PF_FILE, SOCK_STREAM, 0) = 10 [pid 9799] 21:35:01 connect(10, {sa_family=AF_FILE, path="/var/run/nslcd/socket"}, 110) = 0 [pid 9799] 21:35:01 select(1024, NULL, [10], NULL, {9, 999999}) = 1 (out [10], left {9, 999995}) [pid 9799] 21:35:01 sendto(10, "\1\0\0\0\213\23\0\0\7\0\0\0postfix", 19, MSG_NOSIGNAL, NULL, 0) = 19 [pid 9799] 21:35:01 select(1024, [10], NULL, NULL, {59, 999999} <unfinished ...> [pid 9799] 21:35:14 <... select resumed> ) = 1 (in [10], left {46, 803711}) [pid 9799] 21:35:14 read(10, "\1\0\0\0\213\23\0\0\3\0\0\0", 1024) = 12 [pid 9799] 21:35:14 close(10) = 0
/var/run/nslcd/socketにデータを送りつけるところで止まっているように見える。 nslcdはLDAPでユーザ情報を引くときに通信するデーモンらしい。 http://arthurdejong.org/nss-pam-ldapd/nslcd.conf.5
Postfixという名前のユーザはローカルに存在するので、LDAPに聞きに行く必要は無いはずだがよくわからない。 /etc/nsswitch.conf上もfilesが優先されていた。
とりあえず、以下のようにnslcdのタイムアウト値を減らしたところ、レスポンスが改善した。
bind_timelimit 2 timelimit 3
ちょっと釈然としないが、よいとしよう。