Events sent to a task entering rtems_event_receive() may be lost

[mickd]

Although we are using RTEMS 4.5.0, we have replaced the files event*.c with those from 4.6.1 to address previously reported problems with lost events, such as PR 584 of feb 04.

The problem here is that events may be lost when sent to a task which enters rtems_event_receive() with options set to wait with a timeout and to return on receipt of any event.

The events are sent from an interrupt source such as a timer service routine. If more than one set of events is sent to the task before it returns, the first event set may be overwritten.

Using a debug logging function for the task which receives the event and the timer service routine which sends the event, it was seen that the following happened;

1) Task entered rtems_event_receive (RTEMS_ALL_EVENTS, RTEMS_EVENT_ANY |
RTEMS_WAIT, TEST_INTERVAL, &rx_event)
2) Timer service routine sent event 1
3) Timer service routine sent event 2
4) Timer service routine sent event 3
5) Task returned successfully from rtems_event_receive() with events 2 and 3
6) Event 1 was never received with successive calls to rtems_event_receive()

A review of the event code led to the following analysis and successful fix.

The task enters the function rtems_event_receive() and then _Event_Seize() in eventseize.c.

For the case of no pending events, the task does not immediately return from this function. At line 91 of eventseize.c, the function enables interrupts in order to begin a timeout to wait for sent events. At the time the function enables interrupts, the variable _Event_Sync_state has been set to EVENT_SYNC_NOTHING_HAPPENED but the call to set the thread state to STATES_WAITING_FOR_EVENT has not been made (Line 103).

If the task is now interrupted with a call from the timer service routine to rtems_event_send(), execution continues in eventsend.c .

The new events are set in the task's pending events variable, and the service routine enters _Event_Surrender() in eventsurrender.c .

Since the task is waiting for the new events, execution enters the block

if ( !_Event_sets_Is_empty( seized_events ) ) {

However, since the task has not yet set the waiting for event flag, the code does not enter the block

if ( _States_Is_waiting_for_event( the_thread->current_state ) )

and proceeds to the switch statement for the variable _Event_Sync_state, entering the case for EVENT_SYNC_NOTHING_HAPPENED.

Since the thread is executing, and the option to return on any event is set, the Wait.return_argument is set to the value of seized_events and these events are cleared from those which are pending. The timer service routine then returns.

At this point, if the task resumes execution, the sent events will be received correctly. However, if a second timer service routine is pending, hen execution will reenter _Event_Surrender(). The same path may be followed, and since the second set of new events will also satisfy the options used in the call to rtems_event_receive(), they will also be written to the Wait.return_argument and cleared from the pending events, which will overwrite the value of Wait.return_argument set by the first timer service routine. This means the events set by the first timer service routine are not returned to the task, and are lost.

Release:
4.6.1

Environment:
Motorola coldfire 5307 (m68k) target, cygwin tools

How-To-Repeat:
/* The problem may be demonstrated with a number of tasks which use rtems_timer_fire_after() to run a service routine which sends an event to the same task. The delay used to fire the timer should be the same as the delay used to timeout the call to rtems_event_receive (), which is quickly re entered. In this way, events are being sent to the task as it enters rtems_event_receive () */

#include <stdlib.h>
#include <stdio.h>
#include <rtems.h>

#define TEST_TASKS 2
#define TEST_INTERVAL 100

/* This struct is used for every event a task send/receives with a

timer_fire_after call */

typedef struct
{

/* SR's data */
rtems_id task_id; /< ID of associated rtems task */
rtems_event_set events; /< Mask of events to send */
/* Task's data */
rtems_id timer_id; /< RTEMS timer ID */
rtems_interval sent_tick; /< Tick timer was started */
boolean blLate; /< TRUE = Event is late arriving */

} t_TimerData;

t_TimerData tTimerData[TEST_TASKS][32];

static void vTestEventsInstance (unsigned32 u32Instance);
static rtems_timer_service_routine event_timer_SR (rtems_id tId,

void *pvTimer);

/* Code */

void
vStartTasks (void)
{

rtems_id idTask;
rtems_name tName;
unsigned32 i;

for (i = 0; i < TEST_TASKS; i++) {

tName = rtems_build_name ('E', 'V', '0', '0' + i);

rtems_task_create (tName, 175, 1024, 0, 0, &idTask);

rtems_task_start (idTask, vTestEventsInstance, i);

}

}

static void
vTestEventsInstance (unsigned32 u32Instance)
{

rtems_status_code status;
unsigned32 i;
rtems_name tName;
rtems_interval tick;
rtems_event_set rx_event;
rtems_id selfId;
t_TimerData *ptTimerData;

rtems_task_ident (RTEMS_SELF, RTEMS_SEARCH_LOCAL_NODE, &selfId);

printf ("vTestEventsInstance %u started\n", u32Instance);

/* Get things started - Init t_TimerData, send first event */
for (i = 0; i < 32; i++) {

ptTimerData = &tTimerData[u32Instance][i];

ptTimerData->task_id = selfId;
ptTimerData->events = 1 << i;

tName = rtems_build_name ('E', 'V', 'N', 'T');

status = rtems_timer_create (tName, &ptTimerData->timer_id);

status = rtems_timer_fire_after (ptTimerData->timer_id,

TEST_INTERVAL,
event_timer_SR, ptTimerData);

rtems_clock_get (RTEMS_CLOCK_GET_TICKS_SINCE_BOOT,

&ptTimerData->sent_tick);

ptTimerData->blLate = FALSE;

}

/* Event Send-receive loop */
while (1) {

rx_event = 0;

status = rtems_event_receive (RTEMS_ALL_EVENTS,

RTEMS_EVENT_ANY | RTEMS_WAIT,
TEST_INTERVAL, &rx_event);

if (status == RTEMS_SUCCESSFUL) {

rtems_clock_get (RTEMS_CLOCK_GET_TICKS_SINCE_BOOT, &tick);

for (i = 0; i < 32; i++) {

/* For every event */
ptTimerData = &tTimerData[u32Instance][i];

if (rx_event & (1 << i)) {

/* This event flag received */

if (ptTimerData->blLate) {

printf ("vTestEventsInstance %u event %u now arrived\n",

u32Instance, i);

ptTimerData->blLate = FALSE;

}

/* Send events to line up with entry/exit to rtems_event_receive */
rtems_timer_fire_after (ptTimerData->timer_id,

TEST_INTERVAL, event_timer_SR, ptTimerData);

rtems_clock_get (RTEMS_CLOCK_GET_TICKS_SINCE_BOOT,

&ptTimerData->sent_tick);

} else {

/* This event not received - has it been lost ? */
if (!ptTimerData->blLate) {

if (tick - ptTimerData->sent_tick > 10 * TEST_INTERVAL) {

printf ("Task %u Event %u Overdue\n", u32Instance, i);

ptTimerData->blLate = TRUE;

}

}

}

}

}

}

}

static rtems_timer_service_routine
event_timer_SR (rtems_id tId, void *pvTimer)
{

rtems_status_code status;
t_TimerData *ptTimer = pvTimer;

(void) tId;

status = rtems_event_send (ptTimer->task_id, ptTimer->events);

}

[Joel Sherrill]

State-Changed-From-To: open->closed
State-Changed-Why: Attached patch applied to 4.6 branch and CVS trunk.

Thank you for reporting this and including a nice analysis
and (especially) the patch. :)

[mickd]

eventsurrender.c.diff