R: sptest SP06 strange behaviour

Wed Mar 25 13:04:17 UTC 2020

Hello Sebastian

I'm using version 4.11.3 and started the BSP for Microsemi SmartFusion2
FPGA-based CortexM3 from the NXP 176x BSP.

I don’t believe it's an interrupt priority problem. 
For example I'm executing SP11 and have another problem which seem related
to a synchronization issue; this is the console output:

*** BEGIN OF TEST SP 11 ***
TA1 - rtems_event_send - send RTEMS_EVENT_16 to TA2
TA1 - rtems_event_receive - waiting forever on RTEMS_EVENT_14 and
RTEMS_EVENT_15
TA2 - rtems_event_receive - waiting forever on RTEMS_EVENT_16
TA2 - RTEMS_EVENT_16 received - eventout => 00010000
TA2 - rtems_event_send - send RTEMS_EVENT_14 and RTEMS_EVENT_15 to TA1
TA2 - rtems_event_receive - RTEMS_EVENT_17 or RTEMS_EVENT_18 - forever and
ANY
TA1 - RTEMS_EVENT_14 and RTEMS_EVENT_15 received - eventout => 0000c000
TA1 - rtems_event_send - send RTEMS_EVENT_18 to TA2
TA1 - rtems_event_receive - waiting with 10 second timeout on RTEMS_EVENT_14
TA2 - RTEMS_EVENT_17 or RTEMS_EVENT_18 received - eventout => 00040000
TA2 - rtems_event_send - send RTEMS_EVENT_14 to TA1
TA2 - rtems_clock_set - TA1 - RTEMS_EVENT_14 received - eventout =>
0000084000:
15
TA1 - rtems_event_send - send RTEMS_EVENT_19 to TA2:
0
0
rtems_clock_get_tod    FAILED -- expected (0RTEMS_SUCCESSFUL2) got
(/RTEMS_NOT_DEFINED12)

>From this dump it seems that 'rtems_clock_set' on TA2 is called before
'rtems_clock_get_tod' on TA1. Actually (I set break points to be sure)
'rtems_clock_get_tod' is called before 'rtems_clock_set' and hence the
RTEMS_NOT_DEFINED error.

By studying the task1 and task2 I see that:

	- on TA2, when event RTEMS_EVENT_17 or RTEMS_EVENT_18 are received,
the RTEMS_EVENT_14 will be send; then the rtems_clock_set is called to
initialize RTC.
	- on TA1, when RTEMS_EVENT_14 is received, RTEMS_EVENT_19 will be
sent and then 'rtems_clock_get_tod' is called.

It could happen than TA1 will resume (as per RTEMS_EVENT_14) just before TA2
has the chance to initialize the RTC (by calling rtems_clock_set); I don't
believe a different interrupt priority for the (at the moment) only
interrupt source (the systick used to handle the task switching on timeout
policy) could modify this behavoiur, but I admit to don't know the inner
implementations of RTEMS kernel.

I've tried a small modification: on TA2 the initialization of RTC
(rtems_clock_set) is executed before sending RTEMS_EVENT_14; the resulting
console dump is the following:

*** BEGIN OF TEST SP 11 ***
TA1 - rtems_event_send - send RTEMS_EVENT_16 to TA2
TA1 - rtems_event_receive - waiting forever on RTEMS_EVENT_14 and
RTEMS_EVENT_15
TA2 - rtems_event_receive - waiting forever on RTEMS_EVENT_16
TA2 - RTEMS_EVENT_16 received - eventout => 00010000
TA2 - rtems_event_send - send RTEMS_EVENT_14 and RTEMS_EVENT_15 to TA1
TA2 - rtems_event_receive - RTEMS_EVENT_17 or RTEMS_EVENT_18 - forever and
ANYTA1 - RTEMS_EVENT_14 and RTEMS_EVENT_15 received - eventout => 
0000c000
TA1 - rtems_event_send - send RTEMS_EVENT_18 to TA2
TA1 - rtems_event_receive - waiting with 10 second timeout on
RTEMS_EVENT_14TA2 - RTEMS_EVENT_17 or RTEMS_EVENT_18 received - eventout => 
00040000
TA2 - rtems_event_send - send RTEMS_EVENT_14 to TA1
TA2 - rtems_clock_set - TA1 - RTEMS_EVENT_14 received - eventout =>
0000084000:
15TA1 - rtems_event_send - send RTEMS_EVENT_19 to TA2:
0TA1 - waiting 100 ms0
   02/12/1988
TA2 - rtems_event_send - sending RTEMS_EVENT_10 to self after 4 seconds
TA2 - rtems_event_receive - waiting forever on RTEMS_EVENT_10TA1 -
rtems_clock_get_tod - 
08:15:00   02/12/1988
<pause>TA2 - RTEMS_EVENT_10 received - eventout => 00000400
TA2 - rtems_clock_get_tod - k0
8k:k15k:k0k4k   k0k2k/k12k/k1988k

TA2 - rtems_event_receive - RTEMS_PENDING_EVENTS

TA1 - rtems_event_send - send RTEMS_EVENT_18 to self after 5 secondsTA2 -
eventout => 
000TA1 - rtems_event_receive - waiting forever on RTEMS_EVENT_1880000

TA2 - rtems_event_receive - RTEMS_EVENT_19 - RTEMS_NO_WAIT
TA2 - RTEMS_EVENT_19 received - eventout => 00080000
TA2 - rtems_task_delete - deletes self
TA1 - RTEMS_EVENT_18 received - eventout => 00040000
TA1 - rtems_clock_get_tod - 08:15:09   02/12/1988
TA1 - rtems_event_send - send RTEMS_EVENT_3 to self
TA1 - rtems_event_receive - RTEMS_EVENT_3 or RTEMS_EVENT_22 - NO_WAIT and
ANY
TA1 - RTEMS_EVENT_3 received - eventout => 00000008
TA1 - rtems_event_send - send RTEMS_EVENT_4 to self
TA1 - rtems_event_receive - RTEMS_EVENT_4 or RTEMS_EVENT_5 - forever and ANY
TA1 - RTEMS_EVENT_4 received - eventout => 00000010
<pause>
TA1 - rtems_event_send - send RTEMS_EVENT_18 to self after 5 seconds
TA1 - rtems_timer_cancel - cancelling timer for event RTEMS_EVENT_18
TA1 - rtems_event_send - send RTEMS_EVENT_8 to self after 60 seconds
TA1 - rtems_event_send - send RTEMS_EVENT_9 to self after 60 seconds
TA1 - rtems_event_send - send RTEMS_EVENT_10 to self after 60 seconds
TA1 - rtems_timer_cancel - cancelling timer for event RTEMS_EVENT_8
TA1 - rtems_clock_set - 08:15:00   02/12/1988
TA1 - rtems_event_send - send RTEMS_EVENT_1 every second
TA1 - RTEMS_EVENT_1 received - eventout => 00000002 - at 08:15:01
02/12/1988
TA1 - RTEMS_EVENT_1 received - eventout => 00000002 - at 08:15:02
02/12/1988
TA1 - RTEMS_EVENT_1 received - eventout => 00000002 - at 08:15:03
02/12/1988
TA1 - rtems_timer_cancel - cancelling timer for event RTEMS_EVENT_1
<pause>

TA1 - rtems_event_send - sending RTEMS_EVENT_11 to self in 1 day
TA1 - rtems_event_send - sending RTEMS_EVENT_11 to self in 1 day
TA1 - rtems_event_send - sending RTEMS_EVENT_11 to self in 2 days
TA1 - rtems_timer_cancel - cancelling RTEMS_EVENT_11 to self in 1 day
TA1 - rtems_timer_cancel - cancelling RTEMS_EVENT_11 to self in 2 days
TA1 - rtems_event_send - resending RTEMS_EVENT_11 to self in 2 days
TA1 - rtems_clock_set - 08:15:03   02/15/1988
TA1 - rtems_event_receive - waiting forever on RTEMS_EVENT_11
TA1 - RTEMS_EVENT_11 received - eventout => 00000800
<pause>

TA1 - rtems_event_send/rtems_event_receive combination
TA1 - rtems_clock_set - 08:15:00   02/12/1988
TA1 - rtems_event_receive all outstanding events
TA1 - rtems_event_send - sending RTEMS_EVENT_10 to self in 1 day
TA1 - rtems_event_send - sending RTEMS_EVENT_11 to self in 2 days
TA1 - rtems_clock_set - 07:15:00   02/12/1988
TA1 - set time backwards
TA1 - no events received
TA1 - rtems_clock_set - 07:15:00   02/14/1988
TA1 - set time forwards (leave a timer)
TA1 - RTEMS_EVENT_10 received
TA1 - rtems_event_send - sending RTEMS_EVENT_11 to self in 100 ticks
TA1 - rtems_event_send - sending RTEMS_EVENT_11 to self in 200 ticks
TA1 - rtems_event_send - send RTEMS_EVENT_4 to self
TA1 - rtems_event_receive - RTEMS_EVENT_4 AND RTEMS_EVENT_5 - UNSATISFIED
þ** END OF TEST SP 11 ***

The test is completed correctly. 

Now the question: is this a BSP porting problem or a test problem ?
If you consider this a BSP porting problem could suggest me how to try to
solve it ?

Best Regards
Dr. Michele Dekleva

-----Messaggio originale-----
Da: Sebastian Huber <sebastian.huber at embedded-brains.de> 
Inviato: mercoledì 25 marzo 2020 11:01
A: Michele Dekleva <michele.dekleva at m3t.it>; users at rtems.org
Oggetto: Re: sptest SP06 strange behaviour

Hello Michele,

both tests should run without errors. Which RTEMS version do you use?

A frequent error in Cortex-M BSPs are improper interrupt priorities. 
Make sure all interrupt priorities are set up correctly:

https://docs.rtems.org/branches/master/cpu-supplement/arm.html#interrupt-pro
cessing

-- 
Questa e-mail è stata controllata per individuare virus con Avast antivirus.
https://www.avast.com/antivirus