hagio.org - 日記

Index

今月のアルバム U.S. Beers! [ 投稿 | 編集 ]

編集

May 2012

May 9 (Wed)

23:42

[root@courier tmp]# cat ns.1 Ip: 155562324 total packets received ... [root@courier tmp]#

こういうコマンド実行で、return から出力までに時間がかかったので、 sshd の strace を見てみた。 FD 8, 10 がおそらく bash との通信用、FD 3 が ssh クライアントとの通信用と思われる。

23:06:25.567415 write(8, "\r", 1) = 1 <0.000027> ★return を bash へ 23:06:25.567503 select(11, [3 6 10], [], NULL, NULL) = 1 (in [10]) <0.692257> ★★ここが遅い 23:06:26.259851 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000086> 23:06:26.260035 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000024> 23:06:26.260142 read(10, "\r\nIp:\r\n 155562324 total packe"..., 16384) = 2550 <0.000048> ★cat 結果 read 23:06:26.260408 select(11, [3 6 10], [3], NULL, NULL) = 2 (in [10], out [3]) <0.000043> 23:06:26.260536 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000021> 23:06:26.260623 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000020> 23:06:26.260715 read(10, "\33[50;1H\33[K\33[7m0 root@cou \33[m\33[1"..., 16384) = 571 <0.000024> ★プロンプト文字列 read 23:06:26.260808 write(3, "\243\33\342[\237\371\254Wd\fT\201\360\263\375\204\203\241\212\302\207\231\226\311\345\270=\353A\271\317\212"..., 2592) = 2592 <0.000041> ★ssh クライアントへ送信

もちろんコンソールでは遅延は発生しないので、select() が遅延してる？んなまさか。。

22:59

ssh 接続先のホストで、通信しているインタフェースに対して tcpdump -i bond0 などと実行すると、ふつうはターミナルにザーッとパケット情報が流れるわけだが、遅延発生中はなんと、1 秒に 1 パケットしか送信されない場合もあることがわかった。

[root@courier tmp]# tcpdump -nni bond0 tcpdump: verbose output suppressed, use -v or -vv for full protocol decode listening on bond0, link-type EN10MB (Ethernet), capture size 65535 bytes 22:51:56.602799 IP 192.168.1.2.22 > 192.168.1.10.50520: Flags [P.], seq 1591198633:1591198825, ack 717422957, win 211, options [nop,nop,TS val 3280868678 ecr 933335924], length 192 22:51:56.603145 IP 192.168.1.10.50520 > 192.168.1.2.22: Flags [.], ack 192, win 65535, options [nop,nop,TS val 933337518 ecr 3280868678], length 0 22:51:56.610777 IP 192.168.1.2.22 > 192.168.1.10.50520: Flags [P.], seq 192:560, ack 1, win 211, options [nop,nop,TS val 3280868686 ecr 933337518], length 368 22:51:56.610955 IP 192.168.1.10.50520 > 192.168.1.2.22: Flags [.], ack 560, win 65535, options [nop,nop,TS val 933337525 ecr 3280868686], length 0 22:51:56.619938 IP 192.168.1.2.22 > 192.168.1.10.50520: Flags [P.], seq 560:912, ack 1, win 211, options [nop,nop,TS val 3280868695 ecr 933337525], length 352 22:51:56.620148 IP 192.168.1.10.50520 > 192.168.1.2.22: Flags [.], ack 912, win 65535, options [nop,nop,TS val 933337534 ecr 3280868695], length 0 22:51:57.876752 IP 192.168.1.2.22 > 192.168.1.10.50520: Flags [P.], seq 912:1264, ack 1, win 211, options [nop,nop,TS val 3280869952 ecr 933337534], length 352 22:51:57.877011 IP 192.168.1.10.50520 > 192.168.1.2.22: Flags [.], ack 1264, win 65535, options [nop,nop,TS val 933338790 ecr 3280869952], length 0 22:51:58.002698 IP 192.168.1.2.22 > 192.168.1.10.50520: Flags [P.], seq 1264:1616, ack 1, win 211, options [nop,nop,TS val 3280870078 ecr 933338790], length 352 22:51:58.002928 IP 192.168.1.10.50520 > 192.168.1.2.22: Flags [.], ack 1616, win 65535, options [nop,nop,TS val 933338915 ecr 3280870078], length 0 22:51:58.004748 IP 192.168.1.2.22 > 192.168.1.10.50520: Flags [P.], seq 1616:1968, ack 1, win 211, options [nop,nop,TS val 3280870080 ecr 933338915], length 352 22:51:58.004901 IP 192.168.1.10.50520 > 192.168.1.2.22: Flags [.], ack 1968, win 65535, options [nop,nop,TS val 933338917 ecr 3280870080], length 0

つまりこれは、ack の遅延ではなさそうだ。じゃあ、送信遅延？あるいは、sshd の処理遅延？次はどう切り分けるか。

May 8 (Tue)

22:58

うちのサーバの ssh で遅延する件をいまだに解決できていないが、そろそろ日頃の作業に限界を感じるようになってきたので、少し調べてみる。
地道に解決するのは正直面倒なので、ひとまずやってみたこと：

NIC の変更 (bonding 組みたくて買ったが、内蔵と同じチップだった…)
某 offload などの on/off
某 coalesce などの on/off
ack 関連のカーネルパラメータの on/off

これらは効かなかった。遅延時の tcpdump を見ると ack が遅延しているし、 netstat -s でも delayed ack が増加していたのでこれを疑ったが、

#define TCP_DELACK_MAX ((unsigned)(HZ/5)) /* maximal time to delay before sending an ACK */ "include/net/tcp.h"

となっていて、最大でも 200ms と思われる。 tcpdump を見るに 300ms ほど遅れている場合もあるので、該当しなさそうである。

んーむ、詳細に情報を取り直して、怪しいところ洗い出すしかないか…。メンド

4 月(2) へ

↑戻る