Linux
udp
netstat
dropwatch
tproxy

dropwatchを使ってみた。

More than 1 year has 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