TUN/TAPドライバ - パフォーマンス改善までのデバッグ履歴
私はここ数年 Solaris 向けの TUN/TAP ドライバの保守をしているのですが、最近OpenVPNのフォーラムに以下のような書き込みがあるのを見つけました。
http://forums.openvpn.net/topic9542.html
In some sources it was implied that while some performance degradation may be due to OpenSSL operating on small packets, or TCP/UDP flow control mismatches, or MTU and fragmentations, much of the rest can be blamed on the TUN/TAP interface software - which is made differently for different OSes, often by different authors, and performs - well - differently.
投稿した方は Solaris での OpenVPN のパフォーマンスをが出ない事に困っており、TUN/TAPドライバの実装に問題があるのでは無いかと疑って居るようです。実際の投稿の意図としては TUN/TAP ドライバ自体のパフォーマンスの改善では無く、Solaris バンドルの tunnel ドライバを TUN/TAP ドライバの代わりに使えないか?というものでしたが「パフォーマンスが酷く悪い」というのがちょっと気になり調べて見ることにしました。
結論的には調査の結果 Solaris 向け TUN/TAP ドライバにパフォーマンスのボトルネックが見つかり、コードを変更することにより劇的にパフォーマンスを改善できたのですが、そこにいたるまでかなりの道程があったので、後々の備忘録の意味も含めてデバッグ履歴を書き留めておきます。
現在のパフォーマンス測定
パフォーマンスが悪い、といっても遅さの指針となるデータがないと目標も立てられませんし、改善の評価も行えません。
そこで、今回はネットワークパフォーマンス測定ツール netperf を使ってパフォーマンスを測定することにしました。
環境
結果
実ネットワークでの転送速度 | 1 Gbps |
OpenVPN+TAP ドライバ経由での転送 | 20 Mbps |
実際の出力
実ネットワーク
sol11 $ netperf -H oi148 MIGRATED TCP STREAM TEST from ::ffff:0.0.0.0 (0.0.0.0) port 0 AF_INET to oi148 (192.168.1.3) port 0 AF_INET Recv Send Send Socket Socket Message Elapsed Size Size Size Time Throughput bytes bytes bytes secs. 10^6bits/sec 128000 49152 49152 10.00 1028.79
OpenVPN+TAP 経由
sol11 $ netperf -H 192.168.30.1 MIGRATED TCP STREAM TEST from ::ffff:0.0.0.0 (0.0.0.0) port 0 AF_INET to 192.168.30.1 (192.168.30.1) port 0 AF_INET Recv Send Send Socket Socket Message Elapsed Size Size Size Time Throughput bytes bytes bytes secs. 10^6bits/sec 128000 49152 49152 10.32 22.88
なんと実ネットワークと OpenVPN+TAP による仮想ネットワークで46倍ものスループットの差があります。
もちろんソフトウェア的に余計な処理かかなり入っているのである程度がオーバーヘッドがでるのはしょうがないですが、これはあまりにも差が開きすぎています。
というわけで、現状把握とともに目標を
『実ネットワークの10分の1以上(100Mbps以上)まで改善する』
こととしました。
Dtraceによる測定
せっかくSolarisには dtrace(1M) というトレーサーがついているのですから、まずは Dtrace でボトルネック箇所を探してみます。
TAPドライバのトレース。
まずはドライバのボトルネック調査をしてみます。
- TAPドライバ内の関数の呼び出し回数
count_tuntap.d
fbt:tap::entry { @cntproc[probefunc] = count(); } tick-1sec { trunc(@cntproc,10); printa(@cntproc); }
実行結果
sol11 $ sudo dtrace -s count_tuntap.d : 1 68057 :tick-1sec tunwsrv 678 tun_unitdata_ind.clone.0 9334 tunwput 35464 tun_frame 36333
tunwput はTCP/IPから転送されてきたフレームが渡されるエントリポイントで、tun_frame はその先でフレームのルーティング処理を行う関数です。tun_frame の右の数字36,333は転送時間(約10秒)の間に呼び出された回数です。送信するフレームが多くなれば当然呼び出される回数も増えるのでとくにこの結果からは目立ったことはありませんでした。
- TAPドライバ内の関数のトータル実行時間
elapsed_sum_tuntap.d
fbt:tap::entry { self->ts = timestamp; } fbt:tap::return /self->ts > 0/ { @ts[probefunc] = sum(timestamp - self->ts); self->ts = 0; } tick-1sec { trunc(@ts,10); printa(@ts); }
実行結果
sol11 $ sudo dtrace -s elapsed_sum_tuntap.d dtrace: script 'elapsed_sum_tuntap.d' matched 30 probes CPU ID FUNCTION:NAME : 1 68057 :tick-1sec tunwsrv 1081603 tun_unitdata_ind.clone.0 13908076 tunwput 32014047
一番 CPU時間を使った tunwput 関数のトータル実行時間が 32,014,047ns、つまり 0.032秒であったことを示しています。
先ほどの実行回数のところでも tunwput が出てきましたが、結果として10秒あたり 0.032 秒しか使ってないてないということで、TAP ドライバ側で時間がかかっている処理が有るわけでな無いようです。
OpenVPN プロセスのトレース
つづいてユーザプロセスである OpenVPN プロセスをトレースしてます。
- openvpnプロセス内での関数の呼び出し回数
count.d
pid$target:::entry { @cnt[probefunc] = count() } tick-1sec { trunc(@cnt, 30); printa(@cnt); }
実行結果
sol11 $ sudo dtrace -s count.d -p 5511 dtrace: script 'count.d' matched 11218 probes : BF_decrypt 66579 sha1_block_data_order 68652 EVP_CIPHER_CTX_iv_length 75084 po_ctl 75084 proto_is_dgram 81978 memset 223560 memcpy 243961 BF_encrypt 2032723
実行時間10秒の間に BF_encrypt が 2,032,723回呼ばれた事を示しています。2番目には memcpy が 243,961 回呼ばれています。
- openvpn内から呼ばれる関数の実行時間
elapsed_sum.d
pid$target:::entry { self->ts = timestamp; } pid$target:::return /self->ts > 0/ { @ts[probefunc] = sum(timestamp - self->ts); } tick-1sec { trunc(@ts,10); printa(@ts); }
実行結果
sol11 $ sudo dtrace -s elapsed_sum.d -p 5511 dtrace: script 'elapsed_sum.d' matched 22404 probes CPU ID FUNCTION:NAME : 1 68057 :tick-1sec SHA1_Update 142005693 memset 184523613 memmove 189561457 EVP_DigestUpdate 190132463 memcpy 316211424 BF_encrypt 1654880393 __pollsys 3503914650 _pollsys 3538953225 poll 3569561345 po_wait 3600229916
po_wait 関数は openvpn 自身の関数で名前の通り poll を呼び出して待ちます。Stack は以下のとおり。
sol11 $ sudo dtrace -n 'pid$target:::entry/probefunc=="poll"/{ustack(20)}' -p 5511 dtrace: description 'pid$target:::entry' matched 11217 probes CPU ID FUNCTION:NAME 0 77052 poll:entry libc.so.1`poll openvpn`po_wait+0x65 openvpn`io_wait_dowork+0x120 openvpn`main+0x35e openvpn`_start+0x83
これが全体の中で 3,600,229,916ns、つまり3約秒間とっています。
10秒の転送時間の中でトータル3秒間もデータの到着待ちしているとしたら非効率と言わざるを得ません。
snoop コマンドのトレース
上位プロトコルからのデータが届いていないのでは?との推測を受けて、snoop コマンドを使って TAP ドライバに流入するパケットをチェックします。
tap0 インターフェースに流れるパケットをファイル(バイナリフォーマット)に落とすコマンド実行例。
# snoop -d tap0 -o /var/tmp/snoop.out
このように snoop コマンドを実行しながら netperf コマンドを実行します。
取得したパケットキャプチャファイルは snoop コマンドでももちろん読めますが、よりグラフィカルにパケットの送受を確認するために Wireshark というパケットキャプチャの表示・解析ツールを使います。
Wireshark は多機能な解析ツールですが、その機能のなかでもパフォーマンス問題を調査するのにお奨めな機能が「Time-Sequence Graph(tcptrace)」です。この機能はキャプチャファイルオープン後、調査をしたいTCPコネクションのパケットを一つクリックした後、メニューの Statictics -> TCP Stream Graph -> Time-Sequence Graph(tcptrace)から起動することができます。
横軸が経過時間を示し、縦軸がそ転送されたデータ量を示しています。平らなっているように見える部分はデータ転送が無い部分です。
デフォルトでは全体を示しているのでわかりづらいのでマウスの左クリク、もしくは「i」キーでズームインします。
図中の「I」の一つが一つのパケットのデータ転送量を表しています。「I」が重なって上に伸びているのは連続してパケットが送信されたことを示しています。逆に「I」と次の「I」の間が開いてしまっているのは何らかの「待ち」が発生していることになります。
図の左上の方に斜め右上に階段上に登っている先は受信側が「Windowサイズ」として通知してきた受信可能なデータ量を示しています。
つまり、実際に「Windowsサイズ」と書かれた縦の赤線の高さくらいまで連続してデータを送ることができるのに、送信側(=クライアント)が送信を自ら止めているのです。
一方右下の階段上の線は受信側(=サーバ)からのとどいた確認応答(ACK)のデータを示しています。ある時間どのデータ量までACKを受けたかが分かります。
これらからわかることは、クライアントは、サーバからのある一定数のACK、実際には3~4つ前に送信したデータのACKが届くのを見届けてから次のデータを送信しているのが分かります。簡単に言うと以下のような動きを繰り返して、ちょっとずつ時間をロスしています。
- クライアントが4つのパケットを連続して送信。
- サーバからのACKを待つ(1msくらい)
- サーバからACKが到着。
- 次の4つのパケットを送信
TCP というプロトコルの仕組み上、送信側が通知してきた Window サイズ(図の赤い縦線)分だけのデータはACKを受けること無く、連続して送信することができるはずです。
では、なぜクライアントは 4つのパケットだけしか送信せずにACKを待っているのでしょう?
これはおそらくTCPの「輻輳回避アルゴリズム」が働いているため、と考えることができます。
輻輳回避アルゴリズムは、ネットワーク経路に輻輳が発生しているような場合に、ネットワークに負荷を掛けることによってパケットのロスが発生し、パケットの再送信が必要になる、という悪循環を避けるために、自らパケット送信のスロットルを弱める機能になります。
この場合、このパケット以前に、再送信が頻発するなど、TCPが「輻輳が発生している」と判断する事象が発生していたと考えられます。
では、あらためて、このTCP接続の最初の部分を見てみましょう。
これは、TCP接続の最初の部分です。最初「I」が3つならんで縦に伸びて言いますので、3つのパケットが連続してだされているのが分かります。続いては4つのパケットが連続で、次の次の塊では5つのパケットが連続で送られており、7つめ塊では7つのパケットが連続で送られている様子が見て取れます。先ほど書いた通り、本来はWindowサイズ分だけ一気にデータを連続して送れるはずですが、そうはしていません。なぜでしょう? これも輻輳回避の仕組みの一つで「スロースタート」といわれるTCPの機能です。TCPははじめからフルスロットルでデータの転送を開始すること無く文字通り「スロースタート」で様子を探りながらデータがどれくらいなら再転送せずに連続して送信できるかを確認しているのです。
そして、期待通り(?)問題が発生しています。真ん中付近でデータの再送信が発生している様子が見えます。このTime-Sequence 図では再送信がなければ「I」の高さが低くなることは無いはずで、最後の送信時より高さが低い「I」があったらそれは再送信を示しています。
そして、図の右上にあるようにサーバからの ACK が届かずにデータも送れない、という無通信状態が長く続いている様子が伺えます。
snoop の結果からの考察
データの送信状況をみると、Windowサイズが十分なのにもかかわらず、送信側であるクライアントがデータの送信を制御し、サーバからのACKを待っている様子が見える。また、TCP接続開始直後にスロースタートによって連続したデータ送信数を広げようとしている段階でデータの再送信や長期のACK待ちが発生している。これらにより、このTCP接続においてパケットのロスが頻発し、そのせいでパケットの再送信が発生し、その結果としてTCPの輻輳回避アルゴリズムによってデータの流出コントロールが行われたと考えられる。
コード調査
snoop の調査結果からパケットのドロップが起こっていることが推測されましたが、20Mbps程度のデータ量で NIC や Switch でバッファーオーバーフローが起こることは考えられないので、TAPドライバ自身の内部でパケットのドロップが起こっている可能性が出てきました。
実際には snoop のキャプチャにはパケットが記録できているので、疑わしいのは snoop にパケットを渡す部分と、openvpn プロセスにデータを転送する部分の間あたりだと推測できます。TAPのドライバのコードでその様なことを行なっているのは tun_frame という関数です。
/* Route frames */ ### パケットをルーティングする関数 static void tun_frame(queue_t *wq, mblk_t *mp, int q) { : /* Check for the sniffers */ ### snoop 等のパケットキャプチャ向けのルーティング処理 for( tmp=ppa->p_str; tmp; tmp = tmp->p_next ){ : if( !(str->flags & TUN_CONTROL) ){ ### openvpn プロセスにデータパケットをルーティングする処理 /* Data from the Protocol stream send it to * the Control stream */ DBG(CE_CONT,"tun: frame %lu -> control str\n", (ulong_t)msgdsize(mp)); if( canputnext(ppa->rq) ){ ^^^^^^^^^^^^^^^^^ putnext(ppa->rq, mp); ^^^^^^^^^^^^^^^^^^^ } else { if( q == TUN_QUEUE ){ DBG(CE_CONT,"tun: queueing frame %lu\n", (ulong_t)msgdsize(mp)); putbq(wq, mp); ^^^^^^^^^^^^^ } else { DBG(CE_CONT,"tun: dropping frame %lu\n", (ulong_t)msgdsize(mp)); freemsg(mp); ^^^^^^^^^^^ } } } else {
臭う部分がみえて来ました。下線をつけた canputnext(9F)というのは、引数で渡されたキュー(Streams Queue)にパケットが渡せるか?というのを確認するためのカーネルの関数です。ちょっと図で説明します。
今見ているのは図でアプリケーションからTAPドライバをつないでいる赤い矢印の下端部分です。TAPドライバはTCP/IP経由でアプリ(netperf)からのデータを受け取り、それを STREAM HEAD という門を通じて OpenVPN に渡そうかどうしようか、という判断をしている部分になります。
STREAM HEAD はユーザ空間とカーネル空間の間に居る特別なキューです。canputnext(9F) は図のSTREAMS HEAD にデータが渡せるかどうか(キューががいっぱいでないか)を確認するために使われています。
ここで、TAPではちょっと自分でも輻輳制御を行なっています。STREAM HEADのキューが一杯だとしても即座に、freemsg(9F)でパケットをドロップせず、一旦 putbp(9F) で自分自身のキューに保存し、2度めのチャレンジでもSTREAM HEADが一杯だったら初めて freemsg(9F) で破棄する、という動きをとっています。
・・・輻輳制御の仕組みがあるとは言え、非常に疑わしいコードです。デバッグプリントのコードを有効にして再度テストしてみましょう。
: Jul 16 22:19:15 sol11 tap: [ID 852863 kern.notice] tun: queueing frame 1389 Jul 16 22:19:15 sol11 tap: [ID 279187 kern.notice] tun: dropping frame 1389 Jul 16 22:19:15 sol11 tap: [ID 852863 kern.notice] tun: queueing frame 1389 Jul 16 22:19:15 sol11 tap: [ID 279187 kern.notice] tun: dropping frame 1389 Jul 16 22:19:15 sol11 tap: [ID 852863 kern.notice] tun: queueing frame 1389 Jul 16 22:19:15 sol11 tap: [ID 279187 kern.notice] tun: dropping frame 1389 Jul 16 22:19:15 sol11 tap: [ID 852863 kern.notice] tun: queueing frame 1389 Jul 16 22:19:15 sol11 tap: [ID 279187 kern.notice] tun: dropping frame 1389 :
案の定、ドロップの嵐です(笑)
なぜ、こんなにドロップしてしまうんでしょう? そもそも STREAM HEAD のキューのサイズってどれくらいなんでしょう?
チェックしてみましょう。
確認にはデバッガである mdb を使います。mdb に -k オプションを指定してカーネルデバッガとして起動します。(もちろんroot権限が必要です)
sol11 $ sudo mdb -k Loading modules: [ unix genunix specfs dtrace mac cpu.generic uppc pcplusmp scsi_vhci zfs mpt sd ip hook neti arp usba sockfs fctl kssl random idm fcip cpc crypto lofs ufs logindmux ptm sppp nfs ] >
ストリームの一覧を表示して TAP ドライバのストリームを探します。
> ::walk stream_head_cache|::stream : +-----------------------+-----------------------+ | 0xffffff015a80f6b8 | 0xffffff015a80f5c0 | | strwhead | strrhead | | | | | cnt = 0t0 | cnt = 0t0 | | flg = 0x00004022 | flg = 0x00044030 | +-----------------------+-----------------------+ | ^ v | +-----------------------+-----------------------+ | 0xffffff014d4988d0 | 0xffffff014d4987d8 | | tap | tap | | | | | cnt = 0t0 | cnt = 0t0 | | flg = 0x00248822 | flg = 0x00208832 | +-----------------------+-----------------------+
::walk stream_head_cache コマンドは全ての STREAMSをリストし、パイプで ::stream コマンドに渡すことで STREAMSの構造を見やすく図示してくれます。
右上の strrhead (STREAM HEAD の Read サイドキュー)のアドレスから queue のサイズ(q_hiwat)を見てみます。
ここでは queue_t 構造体の q_hiwat メンバを見てみます。
> 0xffffff015a80f5c0::print queue_t q_hiwat q_hiwat = 0x1400 ^^^^^^
::print コマンドは指定した与えられたアドレスをを構造体に当てはめて、指定したメンバを表示してくれるコマンドです。
なるほど、分かりました。キューのサイズは 0x1400=5,120byteです。TCPのペイロード(データ)が1,460byteだとすると、3パケット分しかキャッシュできない計算になります。これでは溢れるのも必至です。
コードの変更による対策
これまでの調査から、OpenVPN プロセスがオープンしている STREAM の STREAM HEADのキューのサイズ(q_hiwat)が小さいためにパケットのドロップが起きているのがわかっています。対策は単純で、このキューのサイズを大きくします。
具体的には OpenVPN が STREAM をオープンした際に呼ばれるコードに STREAM HEADのキューのサイズを大きするコードを追加します。
/* Handle IOCTLs */ static void tun_ioctl(queue_t *wq, mblk_t *mp) { : /* Set High Water Mark of Stream head */ if( !(mopt = allocb(sizeof(struct stroptions), BPRI_LO)) ){ tuniocack(wq, mp, M_IOCNAK, 0, ENOMEM); return; } mopt->b_datap->db_type = M_SETOPTS; mopt->b_wptr += sizeof(struct stroptions); sop = (struct stroptions *)(void *)mopt->b_rptr; sop->so_flags = SO_HIWAT; sop->so_hiwat = TUN_SO_HIWAT; putnext(ppa->rq, mopt);
so_hiwat に設定している TUN_SO_HIWAT は if_tun.h で以下のように宣言してあります。
#define TUN_SO_HIWAT 1024*1024
1024*1024byte。つまり1Mです。約720個のTCPデータを保持できます。これくらいあれば大丈夫でしょう。
コード変更後のパフォーマンス測定
結果
実ネットワークでの転送速度 | 1 Gbps |
OpenVPN+TAP ドライバ経由での転送 | 214 Mbps |
実際の出力
OpenVPN+TAP 経由
sol11 $ netperf -H 192.168.30.1 MIGRATED TCP STREAM TEST from ::ffff:0.0.0.0 (0.0.0.0) port 0 AF_INET to 192.168.30.1 (192.168.30.1) port 0 AF_INET Recv Send Send Socket Socket Message Elapsed Size Size Size Time Throughput bytes bytes bytes secs. 10^6bits/sec 128000 49152 49152 10.04 214.29
どうでしょう? 変更前は 22Mbps 程度だったので約10倍ちかくスループットが向上しています。
実ネットワークとの差も 4.8 倍差と、目標としていた10分の1より縮まっています!!
というわけで、TUN/TAP ドライバのパフォーマンス改善までのデバッグ履歴は以上です。
なお、もし STREAM についてもう少し知りたいと言う方は拙作でありますが以下のページもご参照ください。