Clock function delayed

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?

Thanks
~ Ramsey