EventQueue call target method triggers much later than expected

maiorfi · September 14, 2020, 2:50pm

I have this code:

#include "mbed.h"

InterruptIn btnInt(BUTTON1);                     

Thread thread_eq_events;        
EventQueue eq_events;           

Timer timer;

void event_function_periodic()
{
    printf("[DEBUG - event_function_periodic] at %d ms\n", timer.read_ms());
}

void event_function_interrupt_handler(bool state)
{
    printf("[DEBUG - event_function_interrupt_handler] at %d ms (%s)\n", timer.read_ms(), state ? "L->H" : "H->L");
}

void btn_interrupt_handler()
{
    eq_events.call(&event_function_interrupt_handler, btnInt.read());
}

//////////
// MAIN //
//////////
int main()
{
    eq_events.call_every(1000, &event_function_periodic);                               
    
    btnInt.rise(&btn_interrupt_handler);
    btnInt.fall(&btn_interrupt_handler);
    
    thread_eq_events.start(callback(&eq_events, &EventQueue::dispatch_forever));

    timer.start(); 
}

The behavior I would expect is that pressing (or releasing) board button I should immediately see output by function event_function_interrupt_handler()

Instead, the behavior I observe is that such function output is delayed with respect to actual button action (I would say 500-1000 ms, roughly).

Using debugger I can see than delay is introduced between isr handler (which enqueues callback execution) and actual callback execution.

For sake of completeness, here is program output:

[DEBUG - event_function_periodic] at 3999 ms
[DEBUG - event_function_periodic] at 4999 ms
[DEBUG - event_function_periodic] at 6000 ms
[DEBUG - event_function_periodic] at 7000 ms
[DEBUG - event_function_interrupt_handler] at 7015 ms (H->L)
[DEBUG - event_function_periodic] at 8000 ms
[DEBUG - event_function_periodic] at 9000 ms
[DEBUG - event_function_periodic] at 10000 ms
[DEBUG - event_function_periodic] at 11000 ms
[DEBUG - event_function_interrupt_handler] at 11039 ms (L->H)
[DEBUG - event_function_periodic] at 12000 ms
[DEBUG - event_function_periodic] at 13000 ms
[DEBUG - event_function_periodic] at 14000 ms
[DEBUG - event_function_periodic] at 15000 ms
[DEBUG - event_function_periodic] at 16001 ms
[DEBUG - event_function_periodic] at 17001 ms
[DEBUG - event_function_periodic] at 18001 ms

ladislas · September 14, 2020, 4:16pm

You can try having a higher priority on your isr event/queue thread.

hudakz · September 14, 2020, 5:45pm

Hello Lorenzo,

I think the behaveour is correct. On button status change (push/release) the ISR, in this case the btn_interrupt_handler() function, should be called immediately rather than the event_function_interrupt_handler(). Because the event_function_interrupt_handler function is called from the ISR via the EventQueue::call() it’s execution is deferred (delayed) as explained in the EventQueue example: deferring from interrupt context example program. To measure the actual delay modify the code as below:

#include "mbed.h"

InterruptIn btnInt(BUTTON1);                     

Thread thread_eq_events;        
EventQueue eq_events;
volatile int isrCallTime;

Timer timer;

void event_function_periodic()
{
    printf("[DEBUG - event_function_periodic] at %d ms\n", timer.read_ms());
}

void event_function_interrupt_handler(bool state)
{
    printf("[DEBUG - event_function_interrupt_handler] delayed (deferred) by %d ms (%s)\n", timer.read_ms() - isrCallTime, state ? "L->H" : "H->L");
}

void btn_interrupt_handler()
{
    isrCallTime = timer.read_ms();
    eq_events.call(&event_function_interrupt_handler, btnInt.read());
}

//////////
// MAIN //
//////////
int main()
{
    eq_events.call_every(1000, &event_function_periodic);                               
    
    btnInt.rise(&btn_interrupt_handler);
    btnInt.fall(&btn_interrupt_handler);
    
    thread_eq_events.start(callback(&eq_events, &EventQueue::dispatch_forever));

    timer.start(); 
}

Best regards, Zoltan

maiorfi · September 15, 2020, 12:00pm

I tried, without any significant difference.

maiorfi · September 15, 2020, 12:13pm

The expected deferring delay is actually not written explicitly in docs, since probably it isn’t deterministic.

Taking into consideration that is the only solution provided in mbed-os for running functions not runnable by an isr as a consequence of an interrupt I think such delay (or at least the maximum delay) should be explicit or configurable in an RTOS.

I’m also quite sure that in some previous version such delay was much shorter (we used STL containers to manage parsing of frame received via UART using same approach where trigger was uart Rx isr)…maybe it is due to something recently introduced on low-power management?

hudakz · September 15, 2020, 1:22pm

What target board do you compile for? Could you please share a printout made by running the modified code?

Below is a printout from a NUCLEO-F446RE. As you can see, the delays are much shorter than 500ms (usually less than 1ms):

[DEBUG - event_function_periodic] at 999 ms
[DEBUG - event_function_periodic] at 1999 ms
[DEBUG - event_function_periodic] at 2999 ms
[DEBUG - event_function_periodic] at 3999 ms
[DEBUG - event_function_periodic] at 4999 ms
[DEBUG - event_function_interrupt_handler] delayed (deferred) by 0 ms (H->L)
[DEBUG - event_function_interrupt_handler] delayed (deferred) by 0 ms (L->H)
[DEBUG - event_function_periodic] at 5999 ms
[DEBUG - event_function_periodic] at 6999 ms
[DEBUG - event_function_periodic] at 7999 ms
[DEBUG - event_function_interrupt_handler] delayed (deferred) by 0 ms (H->L)
[DEBUG - event_function_interrupt_handler] delayed (deferred) by 2 ms (L->H)
[DEBUG - event_function_periodic] at 8999 ms
[DEBUG - event_function_periodic] at 9999 ms
[DEBUG - event_function_periodic] at 10999 ms
[DEBUG - event_function_interrupt_handler] delayed (deferred) by 0 ms (H->L)
[DEBUG - event_function_interrupt_handler] delayed (deferred) by 0 ms (L->H)
[DEBUG - event_function_periodic] at 11999 ms
[DEBUG - event_function_periodic] at 12999 ms
[DEBUG - event_function_periodic] at 13999 ms

maiorfi · September 15, 2020, 3:50pm

Here is my output using a NUCLEO_L476RG board (I actually kept button pressed a while before releasing it on both activation you can see in following log, but it isn’t important for the point the sample program is proving):

[DEBUG - event_function_periodic] at 11000 ms
[DEBUG - event_function_periodic] at 12000 ms
[DEBUG - event_function_periodic] at 13000 ms
[DEBUG - event_function_periodic] at 14000 ms
[DEBUG - event_function_periodic] at 15000 ms
[DEBUG - event_function_periodic] at 16000 ms
[DEBUG - event_function_periodic] at 17001 ms
[DEBUG - event_function_periodic] at 18001 ms
[DEBUG - event_function_periodic] at 19001 ms
[DEBUG - event_function_periodic] at 20001 ms
[DEBUG - event_function_periodic] at 21001 ms
[DEBUG - event_function_interrupt_handler] delayed (deferred) by 1279 ms (H->L)
[DEBUG - event_function_periodic] at 22001 ms
[DEBUG - event_function_periodic] at 23001 ms
[DEBUG - event_function_periodic] at 24001 ms
[DEBUG - event_function_interrupt_handler] delayed (deferred) by 1279 ms (L->H)
[DEBUG - event_function_periodic] at 25001 ms
[DEBUG - event_function_periodic] at 26002 ms
[DEBUG - event_function_periodic] at 27002 ms
[DEBUG - event_function_interrupt_handler] delayed (deferred) by 1280 ms (H->L)
[DEBUG - event_function_periodic] at 28002 ms
[DEBUG - event_function_periodic] at 29002 ms
[DEBUG - event_function_periodic] at 30002 ms
[DEBUG - event_function_interrupt_handler] delayed (deferred) by 1280 ms (L->H)
[DEBUG - event_function_periodic] at 31002 ms
[DEBUG - event_function_periodic] at 32002 ms
[DEBUG - event_function_periodic] at 33002 ms
[DEBUG - event_function_periodic] at 34002 ms

hudakz · September 15, 2020, 5:21pm

The NUCLEO-L476RG is using the tickless feature of the Mbed RTOS. When the system has nothing to do, based on the system status (taking into account scheduled tasks to be executed in the future) the RTOS calculates how mutch time it can spend in deep sleep state to save power and falls into deep sleep. Once the calculated time has elapsed, the system wakes up and performs the task scheduled as next. To make the program more responsive (at the cost of using more power) try to disable the tickless feature via a mbed_app.json configuration file. For example:

{
    "target_overrides": {
        "*": {
            "target.macros_remove": ["MBED_TICKLESS"]
        }
    }
}

To learn more about low power, tickless and deep sleep watch this Mbed Office Hours.

JojoS · September 15, 2020, 6:14pm

there is also a sleep_manager_lock_deep_sleep(); to disable the deep sleep mode.

maiorfi · September 16, 2020, 8:10am

Yes, this way I get delay of 0-1 ms. Thanks.

maiorfi · September 16, 2020, 8:16am

It works, thanks.

maiorfi · September 17, 2020, 1:12pm

As a side node, it seems that locking sleep manager requires an hardware reset (i.e. through reset pin) to actually become effective.

Topic		Replies	Views
How does EventQueue handle overlap? Mbed OS	8	336	January 21, 2022
Using a class's member function to handle EventQueue events? Mbed OS	18	1144	October 18, 2021
Difference between the .call and .event classes of EventQueue Mbed OS	3	1789	June 9, 2020
RTOS Thread and EventQueue freezes the application when using Timeout Mbed OS mbed_os , cmsis-rtos	0	486	February 14, 2021
Is printf in timer callback a good idea? Mbed OS	2	1651	March 25, 2020

EventQueue call target method triggers much later than expected

Related topics