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を使ってみたことに関しての記事は以上。