2013年10月7日月曜日

データ・ロギング・システムの検討(Etherによるデータ転送能力の調査)

さて、snappyの実力に関する実験データは取れたので、いよいよ検討してるデータ収集(ロギング)の検討に入ります。まずデータをEtherで転送するときの、実際の転送時間や、HDDへの記録にかかる時間、タイミングなんかを調べます。

まず、いま検討しているシステムは以下の様なものです。

PC1PCxはリアルタイムでデータを収集します。そのため自前でデータを記録していると、リアルタイムでのデータ収集のタイミングが乱される可能性があるので、収集したデータをEhterでどんどんPC0に送ります。(TCP/IPのSocket通信を想定しています)PC0では、送られたデータをどんどんHDDにログしていく。(ここは特にリアルタイムである必要はないが、PC1PCxより送られてくるデータを受信・ログが間に合う必要はある。)

本システムでタイミング的にボトルネックになりそうなのは以下の2点です。

PC1→PC0で収集データを送るときのEtherの通信時間。(データ長が長いと、それだけ通信時間が長くなる)
PC0によるHDDへの書き込み時間。(システムはLinuxで動かすのを想定しているので、PC0では強烈なファイルキャッシュが働くはずですが、それでも結局はHDDへの書き込み時間が問題になる)

結局、2か所でデータ長が問題になり、収集データを圧縮したいという要求がでてきます。それも高速に。(リアルタイム処理が乱されないように)
考えた、システムでの動作シーケンスの概要を以下に示します。
話を簡単にするために、データ収集としてPC1だけにします。

PC1PC0のSocketを接続
PC1で収集したデータをsnappy等で圧縮(今回の実験では、まだこの部分は未実装で計測)
PC1からPC0のEhterでデータを送信
PC0では受信したデータをHDDにログ
PC0からログ処理が終了し、次のデータを送ってもいいことを知らせるためにAckをPC1へ送る

まず基本的なデータを取るために、圧縮なしで100KBのデータをPC1は全速で送り、1回のloop処理時間を計測してみました。(10回loopを、3回実施)

1回目開始からの時間[sec]loopの時間[sec]2回目開始からの時間[sec]loopの時間[sec]3回目開始からの時間[sec]loopの時間[sec]
00.0094580700.0093951200.00931001
10.0188470.0093889310.0186870.0092918810.01864890.00933889
20.0281250.00927820.0280430.00935620.02789090.009242
30.0374820.00935730.03741910.009376130.0371830.0092921
40.0467150.00923340.04685210.00943340.04670190.0095189
50.05598310.009268150.05619910.00934750.05608110.0093792
60.06527520.009292160.0654850.009285960.06545310.009372
70.07459810.009322970.07483820.009353270.0748780.0094249
80.08389210.00929480.08408310.009244980.0841250.009247
90.0931940.009301990.09342410.00934190.09344390.0093189

約9msちょっとかかるようですね。なお、各loop処理時間の計測結果は毎回coutしてしまうと、コンソール出力処理の待ちにかなり時間を喰われてしまい、正確なloopの処理時間が計測できません。(このコンソール処理ってすごい時間がかかるんですよ。HDDへの出力はファイルキャッシュがあるので高速なんですが。)なので、プログラム中に計測した時間をメモリに記憶し、loop処理終了後にcoutするようにしています。

さて9ms/回はわかりましたが、ボトルネックとなる①、②はこのうちどれだけ時間がかかっているんでしょう?PC1にてWireSharkを起動し、パケットが何時送られたか時間を計測してみました。(PC0はHDDにログをしているのでファイルキャッシュがかなりきつい状態になっているはずです。そんな高負荷な状態でWireShark動かしてしまうと時間計測に影響を与えるといけないので、PC1で行います)
大体、以下の様な結果を得ました。(動作説明:PC1では「データ送信」の時に100KB分を1回だけsend( )関数をCallしています。それが35個のパケットに分解され、全部で2msかかったのがWireSharkのログで判明しました。また、PC0では1回のrecv( )関数では100KB分を受信できず、2,3回にわけて受信していました。つまりTCP/IPの実装部で35個のパケットを受信バッファにどんどん取り込んでいますが、アプリに制御が渡るのはまとめて2,3回になっていました。ただし、個々のパケット受信に対してはパケット受領のackがデータ送信の1ms後から始まり、8msの間続いたのがWireSharkのログで判明しました。PC0側で100KB分のデータをHDDにfwrite( )してプログラムに制御が返ってきたところで、PC1にAckの信号を送っています。それらの時間関係を示したのが、下の図です。)


PC0は受信において8msの間に35個のackパケットを250~300usにてほぼ等間隔にPC1に返していました。(例外もあります。時々50usのときもありましたし、1回300msもかかったことがありました。)

ところで上記の実験では10回loopでしたが、これだとログ・サイズは1MBにしかなりません。OSはLinuxでやっているので、余裕でファイルキャッシュに吸収されてしまい、実際のHDDへの書き込み時間(処理)の影響を測定できていません。試しにloopを30,000回にして2GB以上のログファイルを転送するときの時間を計測してみました。(PC0は32bit Linuxでメモリ2GB搭載です。これだけのログファイルをHDDへ書き込もうとすれば、オンメモリ上のファイルキャッシュは一杯になるでしょう。)
結果はやはり9ms/回でした。HDDの書き込み速度がそこそこ速く、処理が間に合ったのでしょう。(しかしファイルキャッシュの効果は偉大だ)

ただそれにしても送信処理より受信処理が4倍かかるのはちょっと予想外に時間がかかりすぎです。これだと高速な圧縮処理使うより、(snappy使うより)多少時間かかってもデータサイズを小さく圧縮(高圧縮率)した方がトータルで性能が出るんでない?
試しにHDDへの書き込みだけコメントアウトして、socketの受信処理だけに絞って計測してみました。

結果は、変わらないでした。ちょっとびっくりしましたが、受信時のackパケットを250us毎に返していたのはTC/IPの受信スタックの処理時間が優勢のようです。TCP/IPの処理は重いとは聞いていましたが、これほどとは・・・ データの圧縮どうこう言う前に、socket通信を少しでも早くするために、socketのパケットサイズを調整しないといけません。

今回実験してみて感じたことをまとめてみます。


  • Linuxのファイルキャッシュはかなり強力だった。(テストプログラムを終了したあとも、しばらくHDDが動きっぱなしでした。実際に2GB強のデータをHDDに書き込まれたのはテストプログラム終了後しばらくしてからでしょう。)
  • TCP/IPの処理はかなり時間がかかる。今回、1回のloopで100KBをまとめてsend( )しましたが、パケットとしては35個に分割されていました。他に何台のPCがPC0に接続されるかによりますが、システムの利用状況に応じてパケットサイズを調整しないといけない。(あるいはこんなくらいの時間がかかると思ってシステムの設計を行うかのどちらか)
  • 結局、snappyの有効性確認ができる状況が作れませんでしたが、ある程度の圧縮率が見込める運用状況ならやった方がいいでしょう。(圧縮率200%が見込めるなら、単純にパケット長が半分になるので、上図の送信・受信処理時間も半分になってくれるはず。)
  • 収集データをHDDにロギングまでする必要があるというのはかなり特殊な用途ですが、1回のシステムの動作で10GBくらいのデータを収集するなら64bit OSマシンでオンメモリに保持した方がいい。今回2GB強のログサイズだったので、ファイルキャッシュがなんとかもったが、10GBくらいだとたぶんHDDの状態にも影響されるでしょう。(テストプログラム終了後のdisk I/Oがすごかったので、ちょっと怖くなった)


まあ、snappy使って送信データを圧縮・伸長しようなんてのは、たいていはクラウド系のシステムでの利用がほとんどでしょうから、今回の検討が特殊な状況だとは思います。

PS:
結論として高速にEtherで通信したいと思ったら、snappy等でデータを圧縮し、パケットのサイズを減らし(なんとか1パケットに抑えれるのがベスト!)、受信側の負荷を下げてやるのが一番いいということになると思います。



0 件のコメント:

コメントを投稿