hrpECのTimeoverでRTCのインスタンス名などを併記して表示する

[snozawa]

hrpECのTimeoverで、RTCのインスタンス名などを併記して表示することは可能でしょうか。
https://github.com/fkanehiro/hrpsys-base/blob/master/ec/hrpEC/hrpEC-common.cpp#L119
例えばinvoke_worker iwからRTCのインスタンス名などを取得するにはどのようにしたら良いでしょうか。

よろしくお願いします。

[fkanehiro]

はい、実はそれがわからなくて今のようなわかりにくい表示になっています。

[snozawa]

ありがとうございます。
さらに初歩的な質問となりますが、rtm.pyなど外からで良いので、
invoke_worker iwに相当するものをinvoke_worker iwの実行順序と同じ順序で
リストを取得する方法はございますでしょうか。

[fkanehiro]

方法がわかりました。
#812
でテスト中です。

[snozawa]

大変ありがとうございます、こちらでもインスタンス名がでるのを確認しました。
ちなみにこちらの処理は(ref, narrowあたり)時間のかかる処理だったりしますでしょうか？

[fkanehiro]

refが指しているコンポーネントが同一プロセス内にあればほとんど時間は食わないと思いますが、確認はしていないです。

2015年9月16日 13:37 Shunichi Nozawa notifications@github.com:

大変ありがとうございます、こちらでもインスタンス名がでるのを確認しました。
ちなみにこちらの処理は(ref, narrowあたり)時間のかかる処理だったりしますでしょうか？

—
Reply to this email directly or view it on GitHub
#806 (comment)
.

[snozawa]

承知しました。
このあたり挙動をみながらなにかありましたらreopenいたします

ありがとうございました

[snozawa]

refが指しているコンポーネントが同一プロセス内にあればほとんど時間は食わないと思いますが、確認はしていないです。

実機で確認してみると、やはりこの部分で遅くなっているようです。

[fkanehiro]

どの程度遅くなりますか？

2015-09-17 22:29 GMT+09:00 Shunichi Nozawa notifications@github.com:

Reopened #806 #806.

—
Reply to this email directly or view it on GitHub
#806 (comment).

[snozawa]

すいません、timeoverがでるタイミングも関わるので、まだデータが取得できておりません。
データをとり次第ご報告させていただきます。
（まだ、動作中関節駆動がガクっと目に見えて止まり、体感で遅くなっているように感じたという段階となっております）

[fkanehiro]

遅くなるといってもタイムオーバーした時だけなわけですが、タイムオーバーした上にここで更に時間がかかると不連続が大きくなる、という感じでしょうか。

2015年9月17日 22:53 Shunichi Nozawa notifications@github.com:

すいません、timeoverがでるタイミングも関わるので、まだデータが取得できておりません。
データをとり次第ご報告させていただきます。

—
Reply to this email directly or view it on GitHub
#806 (comment)
.

[snozawa]

遅くなるといってもタイムオーバーした時だけなわけですが、タイムオーバーした上にここで更に時間がかかると不連続が大きくなる、という感じでしょうか。

はい、おっしゃるとおりです。
そもそもtimeover時に関節駆動をしていると、動作中ガクっとみえる挙動となります。
「ガクっ」の停止時間は元々timeover時にはあったものですが、最新ではより長く感じます。

[mmurooka]

実機で時間を測りましたのでご報告させていただきます．

master...mmurooka:check-get-rtc-name-time の変更を加えて時間を測ってみました．
以下のログを見る限り，
RTC::RTObject::_narrow や rtc->get_component_profile()->instance_name を
呼んでいるところ自体で時間がかかっている訳ではなさそうなのですが，
実機の挙動は@snozawa さん指摘の通り「ガクッ」の時間が長くなっているようでした．

[1442551794.248458] Timeover: processing time = 4.03[ms]
RobotHardware0(0.19)[0.00 : 0.02], seq(0.01)[0.00 : 0.01], sh(0.17)[0.00 : 0.02], fk(0.04)[0.00 : 0.00], kf(0.05)[0.00 : 0.01], rmfo(0.09)[0.00 : 0.01], es(0.03)[0.00 : 0.00], ic(0.03)[0.00 : 0.00], abc(0.57)[0.00 : 0.01], st(0.44)[0.00 : 0.02], co(0.64)[0.00 : 0.00], te(0.03)[0.00 : 0.00], tl(0.05)[0.00 : 0.00], hes(0.02)[0.00 : 0.00], el(0.96)[0.00 : 0.00], log(0.10)[0.00 : 0.03], hc(0.60)[0.00 : 0.00],
[1442551796.560309] Timeover: processing time = 4.18[ms]
RobotHardware0(0.19)[0.00 : 0.02], seq(0.02)[0.00 : 0.01], sh(0.17)[0.00 : 0.02], fk(0.03)[0.00 : 0.00], kf(0.05)[0.00 : 0.00], rmfo(0.09)[0.00 : 0.01], es(0.03)[0.00 : 0.00], ic(0.03)[0.00 : 0.00], abc(0.56)[0.00 : 0.01], st(0.44)[0.00 : 0.02], co(0.62)[0.00 : 0.00], te(0.03)[0.00 : 0.00], tl(0.05)[0.00 : 0.00], hes(0.02)[0.00 : 0.00], el(0.96)[0.00 : 0.00], log(0.10)[0.00 : 0.02], hc(0.78)[0.00 : 0.00],
[1442551797.064302] Timeover: processing time = 4.23[ms]
RobotHardware0(0.19)[0.00 : 0.02], seq(0.02)[0.00 : 0.01], sh(0.17)[0.00 : 0.02], fk(0.03)[0.00 : 0.00], kf(0.05)[0.00 : 0.00], rmfo(0.09)[0.00 : 0.01], es(0.03)[0.00 : 0.00], ic(0.03)[0.00 : 0.00], abc(0.57)[0.00 : 0.01], st(0.44)[0.00 : 0.02], co(0.64)[0.00 : 0.00], te(0.04)[0.00 : 0.00], tl(0.05)[0.00 : 0.00], hes(0.02)[0.00 : 0.00], el(0.96)[0.00 : 0.00], log(0.10)[0.00 : 0.03], hc(0.81)[0.00 : 0.00],
[hrpEC]: processing time = 0.185[ms], 0.013[ms], 0.162[ms], 0.034[ms], 0.044[ms], 0.087[ms], 0.027[ms], 0.033[ms], 0.556[ms], 0.436[ms], 0.624[ms], 0.034[ms], 0.050[ms], 0.021[ms], 0.077[ms], 0.103[ms], 0.618[ms], [ms]
[hrpEC] : waitForNextPeriod 0.858000[ms], warker (onExecute) 3.142000[ms], ExecutionProfile 0.030000[ms], time from prev cicle 0.000000[ms]
[1442551798.463965] Timeover: processing time = 4.09[ms]
RobotHardware0(0.18)[0.00 : 0.03], seq(0.02)[0.00 : 0.01], sh(0.16)[0.00 : 0.02], fk(0.03)[0.00 : 0.00], kf(0.05)[0.00 : 0.00], rmfo(0.09)[0.00 : 0.01], es(0.06)[0.00 : 0.00], ic(0.03)[0.00 : 0.00], abc(0.57)[0.00 : 0.01], st(0.45)[0.00 : 0.03], co(0.62)[0.00 : 0.00], te(0.03)[0.00 : 0.00], tl(0.05)[0.00 : 0.00], hes(0.02)[0.00 : 0.00], el(0.07)[0.00 : 0.00], log(0.10)[0.00 : 0.03], hc(1.54)[0.00 : 0.00],
[1442551798.660128] Timeover: processing time = 4.26[ms]
RobotHardware0(0.19)[0.00 : 0.02], seq(0.02)[0.00 : 0.01], sh(0.17)[0.00 : 0.02], fk(0.04)[0.00 : 0.00], kf(0.05)[0.00 : 0.01], rmfo(0.09)[0.00 : 0.01], es(0.07)[0.00 : 0.00], ic(0.03)[0.00 : 0.00], abc(0.57)[0.00 : 0.01], st(0.78)[0.00 : 0.03], co(0.32)[0.00 : 0.00], te(0.03)[0.00 : 0.00], tl(0.05)[0.00 : 0.00], hes(0.02)[0.00 : 0.00], el(0.07)[0.00 : 0.00], log(0.10)[0.00 : 0.03], hc(1.66)[0.00 : 0.00],

[fkanehiro]

DELTA_SEC2の単位はなんですか？

2015年9月18日 15:38 Masaki Murooka notifications@github.com:

実機で時間を測りましたのでご報告させていただきます．

master...mmurooka:check-get-rtc-name-time
master...mmurooka:check-get-rtc-name-time
の変更を加えて時間を測ってみました．
以下のログを見る限り，
RTC::RTObject::_narrow や rtc->get_component_profile()->instance_name を
呼んでいるところ自体で時間がかかっている訳ではなさそうなのですが，
実機の挙動は@snozawa https://github.com/snozawa さん指摘の通り「ガクッ」の時間が長くなっているようでした．

[1442551794.248458] Timeover: processing time = 4.03[ms]
RobotHardware0(0.19)[0.00 : 0.02], seq(0.01)[0.00 : 0.01], sh(0.17)[0.00 : 0.02], fk(0.04)[0.00 : 0.00], kf(0.05)[0.00 : 0.01], rmfo(0.09)[0.00 : 0.01], es(0.03)[0.00 : 0.00], ic(0.03)[0.00 : 0.00], abc(0.57)[0.00 : 0.01], st(0.44)[0.00 : 0.02], co(0.64)[0.00 : 0.00], te(0.03)[0.00 : 0.00], tl(0.05)[0.00 : 0.00], hes(0.02)[0.00 : 0.00], el(0.96)[0.00 : 0.00], log(0.10)[0.00 : 0.03], hc(0.60)[0.00 : 0.00],
[1442551796.560309] Timeover: processing time = 4.18[ms]
RobotHardware0(0.19)[0.00 : 0.02], seq(0.02)[0.00 : 0.01], sh(0.17)[0.00 : 0.02], fk(0.03)[0.00 : 0.00], kf(0.05)[0.00 : 0.00], rmfo(0.09)[0.00 : 0.01], es(0.03)[0.00 : 0.00], ic(0.03)[0.00 : 0.00], abc(0.56)[0.00 : 0.01], st(0.44)[0.00 : 0.02], co(0.62)[0.00 : 0.00], te(0.03)[0.00 : 0.00], tl(0.05)[0.00 : 0.00], hes(0.02)[0.00 : 0.00], el(0.96)[0.00 : 0.00], log(0.10)[0.00 : 0.02], hc(0.78)[0.00 : 0.00],
[1442551797.064302] Timeover: processing time = 4.23[ms]
RobotHardware0(0.19)[0.00 : 0.02], seq(0.02)[0.00 : 0.01], sh(0.17)[0.00 : 0.02], fk(0.03)[0.00 : 0.00], kf(0.05)[0.00 : 0.00], rmfo(0.09)[0.00 : 0.01], es(0.03)[0.00 : 0.00], ic(0.03)[0.00 : 0.00], abc(0.57)[0.00 : 0.01], st(0.44)[0.00 : 0.02], co(0.64)[0.00 : 0.00], te(0.04)[0.00 : 0.00], tl(0.05)[0.00 : 0.00], hes(0.02)[0.00 : 0.00], el(0.96)[0.00 : 0.00], log(0.10)[0.00 : 0.03], hc(0.81)[0.00 : 0.00],
[hrpEC]: processing time = 0.185[ms], 0.013[ms], 0.162[ms], 0.034[ms], 0.044[ms], 0.087[ms], 0.027[ms], 0.033[ms], 0.556[ms], 0.436[ms], 0.624[ms], 0.034[ms], 0.050[ms], 0.021[ms], 0.077[ms], 0.103[ms], 0.618[ms], [ms]
[hrpEC] : waitForNextPeriod 0.858000[ms], warker (onExecute) 3.142000[ms], ExecutionProfile 0.030000[ms], time from prev cicle 0.000000[ms]
[1442551798.463965] Timeover: processing time = 4.09[ms]
RobotHardware0(0.18)[0.00 : 0.03], seq(0.02)[0.00 : 0.01], sh(0.16)[0.00 : 0.02], fk(0.03)[0.00 : 0.00], kf(0.05)[0.00 : 0.00], rmfo(0.09)[0.00 : 0.01], es(0.06)[0.00 : 0.00], ic(0.03)[0.00 : 0.00], abc(0.57)[0.00 : 0.01], st(0.45)[0.00 : 0.03], co(0.62)[0.00 : 0.00], te(0.03)[0.00 : 0.00], tl(0.05)[0.00 : 0.00], hes(0.02)[0.00 : 0.00], el(0.07)[0.00 : 0.00], log(0.10)[0.00 : 0.03], hc(1.54)[0.00 : 0.00],
[1442551798.660128] Timeover: processing time = 4.26[ms]
RobotHardware0(0.19)[0.00 : 0.02], seq(0.02)[0.00 : 0.01], sh(0.17)[0.00 : 0.02], fk(0.04)[0.00 : 0.00], kf(0.05)[0.00 : 0.01], rmfo(0.09)[0.00 : 0.01], es(0.07)[0.00 : 0.00], ic(0.03)[0.00 : 0.00], abc(0.57)[0.00 : 0.01], st(0.78)[0.00 : 0.03], co(0.32)[0.00 : 0.00], te(0.03)[0.00 : 0.00], tl(0.05)[0.00 : 0.00], hes(0.02)[0.00 : 0.00], el(0.07)[0.00 : 0.00], log(0.10)[0.00 : 0.03], hc(1.66)[0.00 : 0.00],

—
Reply to this email directly or view it on GitHub
#806 (comment)
.

[mmurooka]

すみません，定義は以下の通りで単位はmsecです． secです．

#define DELTA_SEC2(start, end) (end.tv_sec - start.tv_sec + (end.tv_usec - start.tv_usec)/1e6)

[garaemon]

#define DELTA_SEC2(start, end) (end.tv_sec - start.tv_sec + (end.tv_usec - start.tv_usec)/1e6)

この定義おかしく有りません?

tv_secってミリ秒なんでしたっけ?

[snozawa]

すいません、秒でした。
ですので、例えば0.02[sec]=>20[msec]かかってることになり、やはり時間はかかっているのであっていそうです。
また、各RTCごとに10-30[msec]かかっているようにみえます。

[garaemon]

rtc->get_component_profile()->instance_name

が遅いんですね。

[mmurooka]

はい，みなさんおっしゃる通りでした．

[snozawa]

#818
で一度様子見とさせていただければと思います。
一旦closeします。