Arm Mbed OS support forum

EventQueue call target method triggers much later than expected

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

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

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

I tried, without any significant difference.

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?

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

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


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.

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

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

It works, thanks.

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