Issue 106 in rtm-ros-robotics: iob::overrunが多く出る

[rtm-ros-...@googlecode.com]

Status: Accepted
Owner: you...@jsk.imi.i.u-tokyo.ac.jp
Labels: Type-Defect Priority-Medium

New issue 106 by you...@jsk.imi.i.u-tokyo.ac.jp: iob::overrunが多く出る
http://code.google.com/p/rtm-ros-robotics/issues/detail?id=106

hrpsys_gazeboのiob.cppでr4159の変更からだと思うのですが、
iob::overrunがかなり大量に出ています。

これに対して、Timeover: processing time = ... の表示は、
全く出ないわけではないですがごく少ないです。

ということは、plugin(rtcd)の部分は5msで計算できている。
iobの中ではoverrunだと理解されているという事でしょうか？
この場合の5msが実時間か、シミュレーション時間かというのは少し問題になるとは
思います。

現状の仕様は、iob.cppの中のwait_for_iog_signal()で5ms(200Hz,シミュレーション
時間)待つようになっていると思いますが、
overrunは10msを超える値や、しばしば100msを超える値も出ます。
これは、シミュレーション時間の100msの間処理がなされなかったのだろうか？
これと、Timeover::processing time との関係も理解できていないんだけど、
rtcdの部分は5ms(多分実時間)で回っているけれども、ループ全体はかなり遅れた時
間で回っているという事かな？

あと、遅いコンピュータで実行している人は、どんな感じのiob::overrunが出ている
でしょうか？

--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[rtm-ros-...@googlecode.com]

Comment #1 on issue 106 by nakaokat: iob::overrunが多く出る
http://code.google.com/p/rtm-ros-robotics/issues/detail?id=106

このコミット以前はros::Time::sleepUntilを使っていましたが、
これだと標準カーネルのタイマの粒度が4msなので、待つときは最低4ms止まっていた
はずです。
このため、sleepを入れずにros::Time::now()を監視し続ける実装に変更しました。

変更した当初はZ800レベルのマシンで問題なく回っていたように思います。
ros::Time::now()が遅くて待たされていると、iob::overrunが大量発生しそうです。


これとは別ですが、たまにiob::overrunで負の表示が出てくるのが気になります。
表示を出す前のifの条件から、負の表示は出るはずがないと思うのですが・・・

hrpECというのがこちらで使われているかわかりませんが、
もしかしたら2回初期化されているという話が関係あるかもしれません。
https://code.google.com/p/hrpsys-base/issues/detail?id=105

[rtm-ros-...@googlecode.com]

Comment #2 on issue 106 by you...@jsk.imi.i.u-tokyo.ac.jp: iob::overrunが多
く出る
http://code.google.com/p/rtm-ros-robotics/issues/detail?id=106

それと、以下のように1つの要素しか無い、timeoverと
Timeover: processing time = 3.2[ms]
3.2,
12個の要素のtimeoverが出るんだけど、
Timeover: processing time = 7.7[ms]
6.6, 0.0, 0.4, 0.1, 0.2, 0.0, 0.1, 0.1, 0.1, 0.0, 0.0, 0.1,

12個の方は正解なんだと思うのだけど、1つの要素のtimeoverは何が起こっているの
だろうか？
これはiob::overrunとは直接は関係ないと思うのだけど、いつごろから出ているだろ
うか？

[rtm-ros-...@googlecode.com]

Comment #3 on issue 106 by you...@jsk.imi.i.u-tokyo.ac.jp: iob::overrunが多
く出る
http://code.google.com/p/rtm-ros-robotics/issues/detail?id=106

r4368 : wait_for_iob_signal でのwaitにsleepを入れた。
r4369 : HrpSeqStateROSBridgeのclock subscribeを初期化時に判定することにした
(こちらはこのチケットの原因と直接は関係ない)

次のフレームのwaitをしている部分にsleepを入れるとよく動いているように見え
る。
はっきりと原因が分かったわけではないが、ros::Timeはclockを読んでいるため、
メインループでの負荷が上がるとclockをちゃんと読めないのではないかと思われ
る。

overrunの出ている原因で多そうなのが、clockが一度に5ms以上進むことがあるこ
と。
通信のレイテンシの問題だろうと思う。

[rtm-ros-...@googlecode.com]

Comment #4 on issue 106 by nakaokat: iob::overrunが多く出る
http://code.google.com/p/rtm-ros-robotics/issues/detail?id=106

12個のtimeoverはserializeされているコンポーネントの実行時間で、
1個のtimeoverは1回のループのtimeoverだと思います。
たしか一つのコンポーネントが5msを越えるとコンポーネントごとの時間が出力され
（12個の方）、
全体の時間を合計して5msを越えると1つの数字しか出ないと聞いたことがあります。

[rtm-ros-...@googlecode.com]

Comment #5 on issue 106 by nakaokat: iob::overrunが多く出る
http://code.google.com/p/rtm-ros-robotics/issues/detail?id=106

r4368 で使われているros::WallDurationも、内部の実装ではnanosleep()を使ってい
るため、
一度sleepしたスレッドが復帰するまでには最低でもカーネルのタイマ割り込みの周
期だけかかります。
普通のカーネルだと4ms周期だと思うのですが、これでうまく動いているとなると
5msのうち4msはsleepして1msでループが回っているということでしょうか。

[rtm-ros-...@googlecode.com]

Comment #6 on issue 106 by you...@jsk.imi.i.u-tokyo.ac.jp: iob::overrunが多
く出る
http://code.google.com/p/rtm-ros-robotics/issues/detail?id=106

原因らしきものはわかりました。

mensaが変です、/clockが順調に出ていません。
怪しいのは、localhostへのpingが遅いです。
何もしないときは、0.1msほど（この段階で、他のマシンの10倍ほど時間がかかって
いる）
drcsimを立ち上げるなどして、負荷が高まると20msほどかかる。
（他のマシンはあまり負荷と関係なくpingの時間は一定）

なんだか、localhostへのpingが一度外に出て行っているように感じる。設定は他と
の違いは見当たらない。(vpnを止めるために再起動しても同じ症状）

> 一度sleepしたスレッドが復帰するまでには最低でもカーネルのタイマ割り込みの
> 周期だけかかります。
> 普通のカーネルだと4ms周期だと思うのですが、これでうまく動いているとなると
こちらの方は、カーネル内部の実装まではわからないけど、実際は4msもかかってい
るように見えない。そこそこ正確にスリープしてそうに見える。他のスレッドに制御
が渡っていないのかもしれない。

[rtm-ros-...@googlecode.com]

Comment #7 on issue 106 by nakaokat: iob::overrunが多く出る
http://code.google.com/p/rtm-ros-robotics/issues/detail?id=106

帯域制限用にshaperdをインストールしてあったので、削除しました。
pingは0.01-3程度です。

[rtm-ros-...@googlecode.com]

Updates:
Status: Fixed

Comment #8 on issue 106 by you...@jsk.imi.i.u-tokyo.ac.jp: iob::overrunが多
く出る
http://code.google.com/p/rtm-ros-robotics/issues/detail?id=106

これで、修正されているようです。