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)

 1Measure Mode: wall_time
 2Thread ID: 70010781712700
 3Fiber ID: 70010781619120
 4Total: 5.175139
 5Sort by: self_time
 6
 7 %self      total      self      wait     child     calls  name
 8  1.94      5.174     0.100     5.073     0.000       52   Kernel#sleep
 9  0.01      0.001     0.001     0.000     0.000       17   IO#write
10  0.01      5.175     0.000     0.000     5.175        1   NodeSendTask#run

データ受信スレッド(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

コメント

まだコメントはありません

コメントを投稿


お名前


メールアドレス(返信を通知する場合のみ記入)


認証コード(201031 と記入してください)