[Bug 864] New: OCL Timercomponent with multiple timers fires sometimes with wrong timerIds

Submitted by Steven Bellens on Thu, 2011-05-26 09:40

http://bugs.orocos.org/show_bug.cgi?id=864

Summary: OCL Timercomponent with multiple timers fires
sometimes with wrong timerIds
Product: Toolchain
Version: unspecified
Platform: All
OS/Version: All
Status: NEW
Severity: enhancement
Priority: P3
Component: OCL
AssignedTo: orocos-dev [..] ...
ReportedBy: steven [dot] bellens [..] ...
CC: orocos-dev [..] ...
Estimated Hours: 0.0

I'm using the OCL::TimerComponent, connected to a Controller component, which
triggers (eventPort) a custom method (watchdog). I had no problem using the
Timer component with only one timer (Timercomponent gets configured and started
properly, and the actual timer is started with Timer.startTimer (id, period)).
When I start a second timer in the same component (with a different timerId of
course), that timer triggers my component _sometimes_ more then once in a
single period and at the same time, the other one didn't trigger at all?! See
for example the deployer output below, where timer 0 and timer 1 both run at
0.5 seconds. Timer 0 does not trigger the method at e.g. 3.974seconds, while
timer 1 triggers it twice:

0.974 [ Info ][Logger] Controller - watchdog method started for timer 1
1.474 [ Info ][Logger] Controller - watchdog method started for timer 0
1.474 [ Info ][Logger] Controller - watchdog method started for timer 1
1.974 [ Info ][Logger] Controller - watchdog method started for timer 0
1.974 [ Info ][Logger] Controller - watchdog method started for timer 1
2.474 [ Info ][Logger] Controller - watchdog method started for timer 0
2.474 [ Info ][Logger] Controller - watchdog method started for timer 1
2.974 [ Info ][Logger] Controller - watchdog method started for timer 0
2.974 [ Info ][Logger] Controller - watchdog method started for timer 1
3.474 [ Info ][Logger] Controller - watchdog method started for timer 0
3.474 [ Info ][Logger] Controller - watchdog method started for timer 1
3.974 [ Info ][Logger] Controller - watchdog method started for timer 1
3.974 [ Info ][Logger] Controller - watchdog method started for timer 1
4.474 [ Info ][Logger] Controller - watchdog method started for timer 0
4.474 [ Info ][Logger] Controller - watchdog method started for timer 1
4.974 [ Info ][Logger] Controller - watchdog method started for timer 1
4.974 [ Info ][Logger] Controller - watchdog method started for timer 1
5.474 [ Info ][Logger] Controller - watchdog method started for timer 0
5.474 [ Info ][Logger] Controller - watchdog method started for timer 1
5.974 [ Info ][Logger] Controller - watchdog method started for timer 0
5.974 [ Info ][Logger] Controller - watchdog method started for timer 1
6.474 [ Info ][Logger] Controller - watchdog method started for timer 0
6.474 [ Info ][Logger] Controller - watchdog method started for timer 1
6.974 [ Info ][Logger] Controller - watchdog method started for timer 0
6.974 [ Info ][Logger] Controller - watchdog method started for timer 1
7.474 [ Info ][Logger] Controller - watchdog method started for timer 0
7.474 [ Info ][Logger] Controller - watchdog method started for timer 1
7.974 [ Info ][Logger] Controller - watchdog method started for timer 0
7.974 [ Info ][Logger] Controller - watchdog method started for timer 1
8.474 [ Info ][Logger] Controller - watchdog method started for timer 1
8.474 [ Info ][Logger] Controller - watchdog method started for timer 1
8.974 [ Info ][Logger] Controller - watchdog method started for timer 0

Similar behaviour is noticed when they run at different periods, the triggering
times are always correct, but the timerId is sometimes wrong, e.g. for timer 0
at 0.5 seconds and timer 1 at 1.0 seconds:

1.469 [ Info ][Logger] Controller - watchdog method started for timer 1
1.470 [ Info ][Logger] Controller - watchdog method started for timer 1
1.969 [ Info ][Logger] Controller - watchdog method started for timer 0
2.469 [ Info ][Logger] Controller - watchdog method started for timer 0
2.469 [ Info ][Logger] Controller - watchdog method started for timer 1
2.969 [ Info ][Logger] Controller - watchdog method started for timer 0
3.469 [ Info ][Logger] Controller - watchdog method started for timer 0
3.469 [ Info ][Logger] Controller - watchdog method started for timer 1
3.969 [ Info ][Logger] Controller - watchdog method started for timer 0
4.469 [ Info ][Logger] Controller - watchdog method started for timer 0
4.469 [ Info ][Logger] Controller - watchdog method started for timer 1
4.969 [ Info ][Logger] Controller - watchdog method started for timer 0
5.469 [ Info ][Logger] Controller - watchdog method started for timer 0
5.469 [ Info ][Logger] Controller - watchdog method started for timer 1
5.969 [ Info ][Logger] Controller - watchdog method started for timer 0
6.469 [ Info ][Logger] Controller - watchdog method started for timer 0
6.469 [ Info ][Logger] Controller - watchdog method started for timer 1
6.969 [ Info ][Logger] Controller - watchdog method started for timer 0
7.469 [ Info ][Logger] Controller - watchdog method started for timer 0
7.469 [ Info ][Logger] Controller - watchdog method started for timer 1
7.969 [ Info ][Logger] Controller - watchdog method started for timer 0
8.469 [ Info ][Logger] Controller - watchdog method started for timer 1
8.470 [ Info ][Logger] Controller - watchdog method started for timer 1
8.969 [ Info ][Logger] Controller - watchdog method started for timer 0

‹ typegen: /type names error starting deployer-xenomai on (master) ›
»
Ruben Smits's picture

[Bug 864] OCL Timercomponent with multiple timers fires sometime

Submitted by Ruben Smits on Fri, 2011-05-27 08:40.

http://bugs.orocos.org/show_bug.cgi?id=864

Ruben Smits <ruben [dot] smits [..] ...> changed:

What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |RESOLVED
CC| |ruben [dot] smits [..] ...en.b
| |e
Resolution| |FIXED

--- Comment #2 from Ruben Smits <ruben [dot] smits [..] ...> 2011-05-27 10:37:59 CEST ---
We have found our problem:

The component which was connected with TimerComponent, using addEventPort was
executed by a PeriodicActivity, secondly the connection was not buffered.

So by the time the updateHook was executed, (in this case not the write on the
eventport, but because of its periodicity) the timerid in the port was already
overwritten due to the fact that the signal times were so close together.

Creating a buffer already resolved the issue. We could/should probably also
remove the periodicity of the activity.

Another case were addEventPort and PeriodicActivity do not match ...

»

[Bug 864] OCL Timercomponent with multiple timers fires sometime

Submitted by Steven Bellens on Fri, 2011-05-27 08:08.

http://bugs.orocos.org/show_bug.cgi?id=864

--- Comment #1 from Steven Bellens <steven [dot] bellens [..] ...> 2011-05-27 10:07:30 CEST ---
We narrowed down the problem to only appear when two timers have to be
triggered at (nearly) the same time. In that case, it's always the timer id of
the timer started as second that appears instead of the id from the timer
started first, e.g. for 3 timers with period 0.1seconds, started in sequence 1
- 2 - 3 in the deploy script:

0.687 [ Info ][Logger] Controller - watchdog started for id 1
0.687 [ Info ][Logger] Controller - watchdog started for id 2
0.688 [ Info ][Logger] Controller - watchdog started for id 3
0.787 [ Info ][Logger] Controller - watchdog started for id 2
0.787 [ Info ][Logger] Controller - watchdog started for id 2
0.788 [ Info ][Logger] Controller - watchdog started for id 3
0.887 [ Info ][Logger] Controller - watchdog started for id 1
0.887 [ Info ][Logger] Controller - watchdog started for id 2
0.888 [ Info ][Logger] Controller - watchdog started for id 3
0.987 [ Info ][Logger] Controller - watchdog started for id 1
0.987 [ Info ][Logger] Controller - watchdog started for id 2
0.988 [ Info ][Logger] Controller - watchdog started for id 3
1.087 [ Info ][Logger] Controller - watchdog started for id 1
1.087 [ Info ][Logger] Controller - watchdog started for id 2
1.088 [ Info ][Logger] Controller - watchdog started for id 3
1.187 [ Info ][Logger] Controller - watchdog started for id 1
1.187 [ Info ][Logger] Controller - watchdog started for id 2
1.188 [ Info ][Logger] Controller - watchdog started for id 3
1.287 [ Info ][Logger] Controller - watchdog started for id 2
1.287 [ Info ][Logger] Controller - watchdog started for id 2
1.288 [ Info ][Logger] Controller - watchdog started for id 3

»

[Bug 864] New: OCL Timercomponent with multiple timers fires som

Submitted by snrkiwi on Thu, 2011-05-26 12:00.

On May 26, 2011, at 05:39 , Steven Bellens wrote:

>
> http://bugs.orocos.org/show_bug.cgi?id=864
>
> Summary: OCL Timercomponent with multiple timers fires
> sometimes with wrong timerIds
> Product: Toolchain
> Version: unspecified
> Platform: All
> OS/Version: All
> Status: NEW
> Severity: enhancement
> Priority: P3
> Component: OCL
> AssignedTo: orocos-dev [..] ...
> ReportedBy: steven [dot] bellens [..] ...
> CC: orocos-dev [..] ...
> Estimated Hours: 0.0
>
>
> I'm using the OCL::TimerComponent, connected to a Controller component, which
> triggers (eventPort) a custom method (watchdog). I had no problem using the
> Timer component with only one timer (Timercomponent gets configured and started
> properly, and the actual timer is started with Timer.startTimer (id, period)).
> When I start a second timer in the same component (with a different timerId of
> course), that timer triggers my component _sometimes_ more then once in a
> single period and at the same time, the other one didn't trigger at all?! See
> for example the deployer output below, where timer 0 and timer 1 both run at
> 0.5 seconds. Timer 0 does not trigger the method at e.g. 3.974seconds, while
> timer 1 triggers it twice:

<sni

The TimerComponent has had this problem for a while (search the ML). We use it like this in state machines:

...
		handle
		{
			// wait for N seconds
			do Timer.wait(ID_WAIT, 2.0)
		}
		exit
		{
			// in case still running
			try Timer.killTimer(ID_WAIT)
		}
		transition Timer.timeout(timerID) 
			if timerID == ID_WAIT then select OTHER_STATE
    		transition nonTimerRelated() select ANOTHER_STATE
	}

Where we explicitly wait for the timer ID of interest. Otherwise you run into your problem :-(
S

»