Posted at

dropwatchを使ってみた。

More than 3 years have passed since last update.


UDPの処理をするサーバのトラブルシューティング

iptablesのTPROXY機能を使って透過的なパケット処理を行うサーバを開発しているのだが、ある種のトラッフィクに関しては安定的にパケット・ロストが発生する事象が確認された。なお、サーバの環境はLinux(RHEL 7.0)。

netstat -suの出力を見たところ、UDPのpacket receive errorsの増加分が失われたパケットの量に一致していることが判明した。

そこで、dropwatchを用いた原因究明を試みることに。


早速やってみる

手順は以下の通り。

ステップ
ターミナル
実行するコマンド

1
server 1
`# netstat -su

2
server 2
# dropwatch -l kas

3
server 2
dropwatch> start

4
client
# nc -u <dest address> <dest port> < 2MB.txt

5
server 2
ctrl-C

6
server 2
dropwatch> exit

7
server 1
`# netstat -su


結果


server_session_1

# netstat -su|grep packet

120177184 packets received
2008 packets to unknown port received.
132324413 packet receive errors
113599497 packets sent

# netstat -su|grep packet
120177272 packets received # +88
2008 packets to unknown port received.
132324587 packet receive errors # +174
113599585 packets sent # +88



server_session_2

# dropwatch -l kas

Initalizing kallsyms db
dropwatch> start
Enabling monitoring...
Kernel monitoring activated.
Issue Ctrl-C to stop monitoring
2 drops at net_tx_action+0 (0xffffffff814cebe0)
1 drops at ip_rcv_finish+16c (0xffffffff815092ec)
1 drops at tcp_v4_rcv+77 (0xffffffff8152efd7)
1 drops at tcp_rcv_state_process+1b0 (0xffffffff81523c10)
1 drops at sk_stream_kill_queues+50 (0xffffffff814c6e60)
474 drops at net_tx_action+0 (0xffffffff814cebe0)
3 drops at ip_rcv_finish+16c (0xffffffff815092ec)
1 drops at __udp4_lib_mcast_deliver+290 (0xffffffff815391f0)
1 drops at icmp_rcv+11c (0xffffffff8153d60c)
25 drops at inet_frag_destroy+76 (0xffffffff8154f986)
174 drops at udp_queue_rcv_skb+218 (0xffffffff81538c78)
1 drops at tcp_v4_rcv+77 (0xffffffff8152efd7)
6 drops at net_tx_action+0 (0xffffffff814cebe0)
^CGot a stop message
dropwatch> exit
Shutting down ...
#


考察

ぱっと見でわかることとして、netstatにおけるpacket receive errorsの増加分と、dropwatchの次の1行がぴったり対応している。

174 drops at udp_queue_rcv_skb+218 (0xffffffff81538c78)

しかし、それに先立つ

474 drops at net_tx_action+0 (0xffffffff814cebe0)

も気になる。

何度か実験してみたが、udp_queue_rcv_skbでのdropに先立って必ずnet_tx_actionでのdropがレポートされる。

調査はまだまだ続くが、dropwatchを使ってみたことに関しての記事は以上。


参考記事

http://qiita.com/STomohiko/items/ba713543fb02ea2ea5d4