Linuxのサーバーで，sshやsudoが非常に遅い場合の解決メモ

症状

こんにちは，タイトルに有るようにあるサーバーでパッケージ更新作業かなにかを行って以降，以上にsshやsudoが遅くなってしまいました．(sudo付けるのと付けないのでvimの起動時間が10秒以上変わる程度)
zfs on linuxで動いているのでそのあたりのパフォーマンスがおかしくなるような不整合でも起こってるのかと思いましたがfs系のエラーは拾えず，ただ以上に遅い以外は不具合が無かったので置いてたのですが，zabbix_agentで実行するUserParameterのスクリプトがTimeOutする為動かなくなり，お客さんの要望に答えられない問題が出てきたため対応することに

よくある例

sudoはhostの名前解決を実行時にするため，/etc/hostsが変になっているとその分遅くなるというのがグーグル先生に聞くとたくさん出てきますが，今回はそこではありませんでした．

今回の事例

結論を書くと，/etc/nsswitch.confの中身が不適切だったためでした．
修正前

passwd: compat winbind
group: compat winbind
shadow: compat winbind
...

passwd,group,shadowの確認にwinbindを使う設定になっていますが，そのルートの認証はそもそも想定していないので無効にします．
修正後

passwd: compat
group: compat
shadow: compat
...

これであっさり治りました．

原因究明

原因を突き止めるアプローチについて書いておきます

解析

straceを使ってどの命令にどれくらい時間がかかるかログを取ります．

$sudo strace -o trace.log -r su -

その際に取れたログ(一部文言変更等加工済)が以下です．

0.000060 close(3) = 0
0.000097 mprotect(0x7fb7e6ec4000, 4096, PROT_READ) = 0
0.000053 munmap(0x7fb7e82f3000, 32831) = 0
0.000119 getpid() = 30017
0.000074 lstat("/tmp/.winbindd", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
0.000090 lstat("/tmp/.winbindd/pipe", {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
0.000069 socket(PF_FILE, SOCK_STREAM, 0) = 3
0.000056 fcntl(3, F_GETFL) = 0x2 (flags O_RDWR)
0.000045 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
0.000044 fcntl(3, F_GETFD) = 0
0.000047 fcntl(3, F_SETFD, FD_CLOEXEC) = 0
0.000043 connect(3, {sa_family=AF_FILE, path="/tmp/.winbindd/pipe"}, 110) = 0
0.000088 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 0) = 0 (Timeout)
0.000054 write(3, "0\10\0\0\0\0\0\0\0\0\0\0Au\0\0\0\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2096) = 2096
0.000085 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
4.730378 read(3, "\250\r\0\0\2\0\0\0\33\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 3496) = 3496
0.000042 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 0) = 0 (Timeout)
0.000042 write(3, "0\10\0\0/\0\0\0\0\0\0\0Au\0\0\0\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2096) = 2096
0.000036 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
0.000070 read(3, "\313\r\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 3496) = 3496
0.000031 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
0.000025 read(3, "/var/run/samba/winbindd_privileg"..., 35) = 35

勿論上にも下にもまだまだ続きますが，この最初の数字の所が以上に突出している部分が，時間がかかっている箇所になります．
この場合は

read(3, "\250\r\0\0\2\0\0\0\33\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 3496) = 3496

の部分になります．

調べる

ログには他にも時間がかかっている場所がありましたが，そこにも3496という数値が出てきていたのでこれらのキーワードで調べます，そしたらあっさりbindについての話が引っかかりました．

suやsudo等をする時にbindが関係してくるということは，認証の参照設定にwinbindが設定されているという事ですのでnsswitch.confが怪しいと考えられるので確認し，予想通りの設定があったので修正したら治りました．