Rubyのsleepが引数の時間より数倍かかってしまう
複数スレッドで同時にsleepを行ったとき、
sleepの引数の時間より数倍の時間がかかってしまう事があった。
いろいろと試行錯誤はしてみたけど、イマイチ理由はわからず…。
とりあえずメモだけしておく。
背景
今回のプログラムはとあるネットワーク上のサーバ、以下の4つのスレッドが存在しています。
- 接続待機スレッド（accpet thread）
- データ送信スレッド（send thread）
- データ受信スレッド（recv thread）
- メッセージルーティングスレッド（msg thread）
各スレッドはポーリングをしていて、それ以外の時間はコンテキストスイッチのために
定期的にsleepを入れるようにしています。
今回の問題は、この"定期的なsleep"です。
ruby-profで各スレッドの処理負荷を計測すると以下のとおりとなります。
接続待機スレッド（accpet thread）
1Measure Mode: wall_time 2Thread ID: 70010781717220 3Fiber ID: 70010781716680 4Total: 6.980623 5Sort by: self_time 6 7 %self total self wait child calls name 8 45.84 6.876 3.200 3.677 0.000 52 Kernel#sleep 9 1.44 0.101 0.101 0.000 0.000 1 TCPServer#initialize 10 0.01 0.001 0.001 0.000 0.000 51 <Class::IO>#select
データ送信スレッド（send thread）
データ受信スレッド（recv thread）
1Measure Mode: wall_time 2Thread ID: 70010781622000 3Fiber ID: 70010781619360 4Total: 5.175198 5Sort by: self_time 6 7 %self total self wait child calls name 8 68.86 5.167 3.564 1.604 0.000 52 Kernel#sleep 9 0.02 0.001 0.001 0.000 0.000 69 <Class::IO>#select 10 0.02 5.175 0.001 0.000 5.174 1 NodeRecvTask#run
メッセージルーティングスレッド（msg thread）
1Measure Mode: wall_time 2Thread ID: 70010781621200 3Fiber ID: 70010781619380 4Total: 5.175243 5Sort by: self_time 6 7 %self total self wait child calls name 8 0.02 5.173 0.001 5.172 0.000 52 Kernel#sleep 9 0.01 5.175 0.000 0.000 5.175 1 MessageRouter#run 10 0.00 0.000 0.000 0.000 0.000 16 JSON::Ext::Generator::State#generate
問題点
今回sleepの引数は全て1msに設定しています。
上記のデータのうち、accept threadとrecv threadでsleepの回数に対する
時間がaccpetの場合60倍、recvの場合は70倍近くかかってしまっています。
1msのはずが約60ms。。。
おそらく、コンテキストスイッチの問題で遅くなっているのかなぁとは思っていますが、
それにしても時間がかかりすぎていてあまり納得はできていません。
もう少し調査方法を変えて見ながら探ってみたほうが良いのかも？
Posted at : 2016-01-05 14:40:26 /
Category : none
Comments
まだコメントはありません / No comment.
