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 を使ってパフォーマンスを測定することにしました。

環境

  • VMWare ESXi 5.0 内の2つの Solaris ゲストOS間の通信。
    • 実H/W: HP Proliant ML110 G5
    • サーバ側(nerserver 実行): OpenIndiana b148
    • クライアント側(netperf実行): Oracle Solaris 11 (11/11)
    • ゲスト間のネットワーク帯域: 1Gbps
    • netperf バージョン: 2.5.0

結果

実ネットワークでの転送速度 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秒間もデータの到着待ちしているとしたら非効率と言わざるを得ません。

Dtraceのトレース結果からの考察

openvpn プロセスは転送時間の10秒中3秒はTAPドライバからのデータ待ちをしている。これに対して TAPドライバはロック待ちや負荷の高い処理は行なっておらず、余裕がある。
つまり、プロセスに渡すべきデータが上位プロトコル(TCP/IP)から届いていないと思われる。

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)から起動することができます。

f:id:kaizawa2:20120716200740p:plain

横軸が経過時間を示し、縦軸がそ転送されたデータ量を示しています。平らなっているように見える部分はデータ転送が無い部分です。
デフォルトでは全体を示しているのでわかりづらいのでマウスの左クリク、もしくは「i」キーでズームインします。

f:id:kaizawa2:20120716203423p:plain

図中の「I」の一つが一つのパケットのデータ転送量を表しています。「I」が重なって上に伸びているのは連続してパケットが送信されたことを示しています。逆に「I」と次の「I」の間が開いてしまっているのは何らかの「待ち」が発生していることになります。
図の左上の方に斜め右上に階段上に登っている先は受信側が「Windowサイズ」として通知してきた受信可能なデータ量を示しています。
つまり、実際に「Windowsサイズ」と書かれた縦の赤線の高さくらいまで連続してデータを送ることができるのに、送信側(=クライアント)が送信を自ら止めているのです。
一方右下の階段上の線は受信側(=サーバ)からのとどいた確認応答(ACK)のデータを示しています。ある時間どのデータ量までACKを受けたかが分かります。
これらからわかることは、クライアントは、サーバからのある一定数のACK、実際には3~4つ前に送信したデータのACKが届くのを見届けてから次のデータを送信しているのが分かります。簡単に言うと以下のような動きを繰り返して、ちょっとずつ時間をロスしています。

  1. クライアントが4つのパケットを連続して送信。
  2. サーバからのACKを待つ(1msくらい)
  3. サーバからACKが到着。
  4. 次の4つのパケットを送信

TCP というプロトコルの仕組み上、送信側が通知してきた Window サイズ(図の赤い縦線)分だけのデータはACKを受けること無く、連続して送信することができるはずです。
では、なぜクライアントは 4つのパケットだけしか送信せずにACKを待っているのでしょう?

これはおそらくTCPの「輻輳回避アルゴリズム」が働いているため、と考えることができます。
輻輳回避アルゴリズムは、ネットワーク経路に輻輳が発生しているような場合に、ネットワークに負荷を掛けることによってパケットのロスが発生し、パケットの再送信が必要になる、という悪循環を避けるために、自らパケット送信のスロットルを弱める機能になります。
この場合、このパケット以前に、再送信が頻発するなど、TCPが「輻輳が発生している」と判断する事象が発生していたと考えられます。

では、あらためて、このTCP接続の最初の部分を見てみましょう。

f:id:kaizawa2:20120716211947p:plain

これは、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)にパケットが渡せるか?というのを確認するためのカーネルの関数です。ちょっと図で説明します。

f:id:kaizawa2:20120716220720g:plain

今見ているのは図でアプリケーションから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パケット分しかキャッシュできない計算になります。これでは溢れるのも必至です。

mdb によるカーネルデバッグ結果の考察

TAP ドライバが openvpn に渡すための橋渡しとなる STREAM HEAD のキューのサイズが5,120バイトしかなく、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 についてもう少し知りたいと言う方は拙作でありますが以下のページもご参照ください。

http://www.whiteboard.ne.jp/~admin2/index.php