I'm getting an LW_delayed log event from the ti.sysbios.knl.Clock module. How to I fix this?
I'm seeing the timer interrupt event, then I normally see the clock work function (swi) events. But once in a while (repeatable) I see the timer interrupt and no clock work events. Eventually, the clock work function does run (after 4 ticks) and it logs the LW_delayed event. I can conclude that the work function was not posted (Swi_post) by the timer interrupt for some reason. What is my program doing to make this occur?
Thanks~ Ramsey
Hi Ramsey,
It sounds like the Clock Swi is not being allowed to run for a while, and then when it does get to run, it detects that it was delayed. (It does this by checking the count of the number of times the Swi was posted, and if it is greater than 1, then the delayed message gets logged as a warning.) Since you see this message, the Swi is indeed getting posted, but the running of it is getting delayed.
Is it possible there is a very long running ISR in the app that causes this?
The other thing that could be happening is that there is a same or higher-priority Swi that is running extra long. By default, Clock’s Swi is maximum priority, but this can be changed via the Clock.swiPriority config parameter. Has the Clock Swi been de-prioritized in the app? Or, is there another highest-priority level Swi that may be running extra long?
Scott
Hi Scott,
Thanks for the suggestions. I could not find any long running ISR or SWI which would prevent the clock swi from running. After further study, I came to realize that the clock work function is only posted when there is a sleeping task. In my program, it is the supervisor task which sleeps. When the supervisor task is not sleeping (its either running or blocked), and a timer tick occurs, then no clock swi is posted. Eventually, the supervisor task will sleep again. On the very next clock tick, I get the Clock_LW_delayed event. I believe this Clock_LW_delayed event should not have been logged.
When the timer interrupt occurs, it calls ti_sysbios_timers_dmtimer_Timer_stub__E which calls ti_sysbios_knl_Clock_doTick__I. Here is the call stack when there are no sleeping task. See the legend below to help read the call stack.
Timer call stack when *no* sleeping tasks intNum 14 --> 0 --> hwi dispatcher 1 --> ti_sysbios_timers_dmtimer_Timer_stub__E 2 --> ti_sysbios_knl_Clock_doTick__I 3 --> ti_sysbios_knl_Clock_logTick__E 4 --> Log_write(Clock_LM_tick) <-- Log_write 4 --- ti_sysbios_knl_Clock_logTick__E <-- ti_sysbios_knl_Clock_logTick__E 3 --- ti_sysbios_knl_Clock_doTick__I <-- ti_sysbios_knl_Clock_doTick__I 2 --- ti_sysbios_timers_dmtimer_Timer_stub__E <-- ti_sysbios_timers_dmtimer_Timer_stub__E 1 --- hwi dispatcher <-- hwi dispatcher 0 ---
Stack Legend Compact Form 0 --> 1 funcA | 0 --> funcA 1 --> 2 funcB | 1 --> funcB 2 --> 3 funcC | 2 --> funcC 2 <-- 3 funcC | <-- funcC 2 --- funcB | 2 --- funcB 2 --> 3 funcD | 2 --> funcD 2 <-- 3 funcD | <-- funcD 2 --- funcB | 2 --- funcB 1 <-- 2 funcB | <-- funcB 1 --- funcA | 1 --- funcA 0 <-- 1 funcA | 0 <-- funcA
For compactness, we omit numbers where possible and left justify names.
The ti_sysbios_knl_Clock_doTick__I function is a generated function found in big.c.
/* * ======== ti.sysbios.knl.Clock TEMPLATE ======== */Void ti_sysbios_knl_Clock_doTick__I(UArg arg) { /* update system time */ (&ti_sysbios_knl_Clock_Module__state__V)->ticks++; (&ti_sysbios_knl_Clock_Module__state__V)->swiCount++; ti_sysbios_knl_Clock_logTick__E(); if (!ti_sysbios_knl_Queue_empty(ti_sysbios_knl_Clock_Module_State_clockQ())) { ti_sysbios_knl_Swi_post((&ti_sysbios_knl_Clock_Module__state__V)->swi); }}
I see that this function always increments the swiCount, even if the clockQ is empty. This would occur when there are no sleeping tasks. When the supervisor task sleeps again and this function is called on the next tick, it will increment swiCount again and also post the clock swi because the clockQ is no longer empty. The swi dispatcher will then call ti_sysbios_knl_Clock_workFunc. This function checks the swiCount and logs the warning if it is greater than one. Here is the code fragment.
Void Clock_workFunc(UArg arg0, UArg arg1){ : hwiKey = Hwi_disable(); time = Clock_module->ticks; count = Clock_module->swiCount; Clock_module->swiCount = 0; Hwi_restore(hwiKey);
/* Log when count > 1, meaning Clock_swi is delayed */ if (count > 1) { Log_write1(Clock_LW_delayed, (UArg)count); } :}
I would conclude that the Clock_doTick function should only increment swiCount if the clockQ is not empty.
I have also observed that when there is a periodic function, I no longer get the warning. I think this comes from the fact that the clockQ is never empty and now the clock swi is always posted, matching the swiCount increment.
Here is the call stack with a sleeping task for reference.
Timer call stack when supervisor task is sleeping intNum 14 --> 0 --> hwi dispatcher 1 --> ti_sysbios_timers_dmtimer_Timer_stub__E 2 --> ti_sysbios_knl_Clock_doTick__I 3 --> ti_sysbios_knl_Clock_logTick__E 4 --> Log_write(Clock_LM_tick) <-- Log_write 4 --- ti_sysbios_knl_Clock_logTick__E <-- ti_sysbios_knl_Clock_logTick__E 3 --- ti_sysbios_knl_Clock_doTick__I 3 --> ti_sysbios_knl_Queue_empty <-- ti_sysbios_knl_Queue_empty 3 --- ti_sysbios_knl_Clock_doTick__I 3 --> ti_sysbios_knl_Swi_post <-- ti_sysbios_knl_Swi_post 3 --- ti_sysbios_knl_Clock_doTick__I <-- ti_sysbios_knl_Clock_doTick__I 2 --- ti_sysbios_timers_dmtimer_Timer_stub__E <-- ti_sysbios_timers_dmtimer_Timer_stub__E 1 --- hwi dispatcher 1 --> swi dispatcher 2 --> ti_sysbios_knl_Clock_workFunc 3 --> Log_write(Clock_LW_delayed) <-- Log_write 2 --- ti_sysbios_knl_Clock_workFunc <-- ti_sysbios_knl_Clock_workFunc 1 --- swi dispatcher <-- swi dispatcher 1 --- hwi dispatcher <-- hwi dispatcher 0 ---
Does this make sense or am I overlooking something?
Yes, your analysis is correct.
If there are no Clock objects with active timeouts, then as an optimization, the Clock Swi will not be posted, because there is no work to do, and activating the Swi would be a waste of cycles.
In this case the delay is because of an optimization, not because of an application issue that needs to be “warned” about. I just filed a defect report about this (SDOCM00091101).
Thanks very much for pointing this out!