66AK2G12: DSP Interrupt service routine delayed

Additionally,

The interrupt of PRUICSS is setup as followed:

    /* PRUSS driver API: Creates handle for PRUICSS instance */

    pruss0_handle = PRUICSS_create(cfg, pruss_num); // [1 or 2]

…

    /*

     * PRUICSS interrupt config structure

     */

    intrCfg.pruEvtoutNum = 2;  /* mapped to -> Channel 2 -> Host 2 */

    intrCfg.waitEnable = 0;  // I use semaphore in Task

    intrCfg.irqHandler = pruss0_pru0_isr;

    /**< DSP: int vector number */

    intrCfg.intNum = 15;

    /* Use DSP eventId not CIC */

    intrCfg.eventId = 4; /* PRUICSS_0_HOST_INT0 DSP eventId 4 */

    intrCfg.intcMuxNum = PRUSS_INVALID_INTC_MUX_NUM; /* 0:CIC; -1:DSP eventId */

    /*

     * PRUSS driver API: Register an Interrupt Handler for an event

     */

    PRUICSS_registerIrqHandler2(pruss0_handle, &intrCfg);

I originally set PRUICSS interrupt intrCfg.intNum = 4. But from UIA log it was preempted by ti_sysbios_knl_Clock_doTick__I() which has intNum: 14.

PRUICSS interrupt, PRUICSS_hwiIntHandler(), now  can preempt ti_sysbios_knl_Clock_doTick__I() after I changed PRUICSS interrupt intrCfg.intNum = 15.

I thought the lower the intNum number, the higher the priority. But The UIA log shows the higher the number, the higher the priority. Am I wrong?

Hi,

From TMS320C66x DSP CPU and Instruction Set (SPRUGH7), Table 6-1 Interrupt Priorities: lower vectId/interrupt number has higher priority. This is  intrCfg.intNum used for PRUCSS interrupt setup. In the SYSBIOS, there is a system timer tick runs using INT14. Are you able to see the ROV view of your project, Under Hwi, there should be:

ti_sysbios_knl_Clock_doTick__I with intNum=14 and 

PRUICSS_hwiIntHandler() with intNum = 15, 

Do you see any other interrupts registered here? 15 has a lower priority and I don't expect timer interrupt can preempt it. In fact timer uses 14 as a background task, it leaves room for other interrupts to be served quicker. 

How fast is the K2G CPU, are you able to use a finer resolution for the SYSBIOS timer tick, e.g. from 100 us to 10 us and see the same issue?

I calculated a few more timer clock intervals, e.g., line 4343 - line 4340 of the log, most of them are ~100,000, that is 100 us. For PRU, line 4437 - line 4411 of log, it is 614265, that is the expected number.

Given this is a spreadsheet log, the line for timer/pru interrupt starts are not at a fixed location, it is hard to do a statistics what the percentage are out of range. Do you have any visualization or statistics for this? How occasionally? Are timer and PRU running late correlated to each other? How do you make sure that PRU interrupt signal incoming at very controlled interval?

The CPU load is 28% in idle, is it possible that CPU is almost 100% (you can see from the UIA CPU load graph) when processing the periodic PRU ISR, so the process and UIA log is delayed?

Regards, Eric      

Hi Eric,

I'll send you an email offline with the log and picture to also help with this. Please see my answers to your questions answered below.

From TMS320C66x DSP CPU and Instruction Set (SPRUGH7), Table 6-1 Interrupt Priorities: lower vectId/interrupt number has higher priority. This is  intrCfg.intNum used for PRUCSS interrupt setup. In the SYSBIOS, there is a system timer tick runs using INT14. Are you able to see the ROV view of your project, Under Hwi, there should be:

ti_sysbios_knl_Clock_doTick__I with intNum=14 and 

PRUICSS_hwiIntHandler() with intNum = 15, 

Do you see any other interrupts registered here? 15 has a lower priority and I don't expect timer interrupt can preempt it. In fact timer uses 14 as a background task, it leaves room for other interrupts to be served quicker. 

Ans: The Inversion of HWI priority  only occurs when the unknow delay of HWI interrupts happens. I changed SYSBIOS timer tick, from 100 us to 10 us. And added a higher priority(intNum = 13) timer interrupt, timer6KHzIsr. The log, 2020_0109_UIA_live.csv, is attached.

From the attached picture, 2020_0109_HWI_delay_Inversion_of_HWI_priority, the intNum15(PRUICSS_hwiIntHandler) preempted intNum14(ti_sysbios_knl_Clock_doTick__I) and intNum14 preempted intNum13(timer6KHzIsr). The 10us tick, ti_sysbios_knl_Clock_doTick__I, is delayed more than 80us to get serviced. Other two HWIs are also delayed but hard to see it from picture. During this 80us gap, only low priority task, task_filter, is continuously running. Its priority only higher than ti_sysbios_knl_Idle_loop__E.

Is the Inversion of HWI priority is caused by UIA logging delay due to task_filter, is continuously running?

How fast is the K2G CPU, are you able to use a finer resolution for the SYSBIOS timer tick, e.g. from 100 us to 10 us and see the same issue?

Ans: Both ARM and DSP are running at 600MHz. PRU core is running at 200MHz.

I calculated a few more timer clock intervals, e.g., line 4343 - line 4340 of the log, most of them are ~100,000, that is 100 us. For PRU, line 4437 - line 4411 of log, it is 614265, that is the expected number.

Given this is a spreadsheet log, the line for timer/pru interrupt starts are not at a fixed location, it is hard to do a statistics what the percentage are out of range. Do you have any visualization or statistics for this? How occasionally? Are timer and PRU running late correlated to each other? How do you make sure that PRU interrupt signal incoming at very controlled interval?

Ans: PRU core is running independent to any DSP timer. I make PRU toggle PRU_GPO to indicate there is an interrupt sent to DSP. DSP toggles a GPIO when it runs PRUICSS_hwiIntHandler. From observing the PRU_GPO signal on scope, the PRU interrupt signal is always running as expected. The delta time between PPRU_GPO toggles and DSP GPIO toggles is less than 8us except the unknown HWI delay occurs. The task, task_filter, is the only task running. It doesn’t have any disable/enable HWI code in it.

The CPU load is 28% in idle, is it possible that CPU is almost 100% (you can see from the UIA CPU load graph) when processing the periodic PRU ISR, so the process and UIA log is delayed?

Ans: DSP CPU load should be 100%. The issue always occurs when the task with taskParams.priority = 2,  task_filter , is continuously running. Unfortunately, the last CPU load in log (600MHz tick timestamp is 36768073233) is way ahead when the unknown HWI delay occurs((600MHz tick timestamp is 37093395998).

Let me know what you think!

Best,

Adam

Adam,

Thanks for the additional information! Please attach the log spreadsheet and picture here. If it contains sensitive information, please send me by e-mail.

So the PRU_GPO is always at the expected interval. But there is somehow a delay pushed both timer ISR and PRU ISR on C66x, even the 6KHz timer ISR on INT13. Task_filter() is a task, correct? Is it part of UIA function?

If above are all the observation and CPU is always 100% busy, I would think switch out from task into HWI need some cycles and caused delay? How frequent is that?

Regards, Eric

Hi,

I looked several timestamps for the PRUICSS_hwiIntHandler() starts, 

line 8197: 

line 8393: delta from above line: 680,223 cycles, delayed

line 8582: delta from above line: 569,222 cycles, shortened 

line 8787: delta from above line: 634,728 cycles, came back to normal

It looks to me once a HWI is delayed in capture, it will not propagate to the next. 

How do you find out that interrupt priority get reverted from the log, when a delay in HWI occurred? If I look at lines 8391, 8392 and 8393, the order of HWI is correct (INT13 > INT14 > INT15). 

Regards, Eric 

Hi Eric,

Task_filter() is a task, correct? Is it part of UIA function?

Answer: Task_filter() is a task. It is not part of UIA. It runs several IIR and FIR filters.

If above are all the observation and CPU is always 100% busy, I would think switch out from task into HWI need some cycles and caused delay? How frequent is that?

Answer: The last log shows delay more than 80us. Usually the context switch takes less than 5us. The HWI delay happens when Task_filter() is requested to process a lot of data stored in DDR3.

How do you find out that interrupt priority get reverted from the log, when a delay in HWI occurred? If I look at lines 8391, 8392 and 8393, the order of HWI is correct (INT13 > INT14 > INT15). 

Answer: You need to look when HWIs end. It’s much easier to see it in Execution Analysis view in CCS. You can also find it in the .csv log as followed:

line 8391: HWI13 timer6KHzIsr() starts. The HWI14 preempts HWI13 before HWI13 timer6KHzIsr() completes

line 8392: HWI14 ti_sysbios_knl_Clock_doTick__I() starts. The HWI15 starts in line 8393 before Hwi14 completes.

line 8393: HWI15 PRUICSS_hwiIntHandler() starts

line 8396: HWI15 PRUICSS_hwiIntHandler() stops. Now the HWI14 got served instead of HWI13.

line 8398: HWI14 ti_sysbios_knl_Clock_doTick__I() stops

line 8399: HWI13 timer6KHzIsr() stops

The toggling GPIO when HWI15 gets served does show the HWI delay shown in the log matching the observation of GPIO signal on scope.

 Thanks!

Adam

Adam,

Thanks for the explanation! I asked the RTOS team to look into this, how accurate the UIA tools:

- Why occasionally all HWIs got delayed up to 80 us?

- Why HWI priority inverted when delay is happening?

Regards, Eric

Just on the Inverted HWI issue.

On The C6x, we allow nested interrupts so I think whats going on is, the Hardware interrupts are processed in the correct priority order but
because nested interrupts are allowed, you are seeing that HWI14 is preempting HWI13 and so forth.  There's an option to mask out
interrupts so that they do not preempt the running interrupt.  You can do this for both statically created Hwis in your .cfg or Hwis created at runtime:

Statically would look something like:

var hwiParams = new Hwi.Params();
hwiParams.maskSetting = Hwi.MaskingOption_BITMASK;
hwiParams.disableMask = 0xffff;
hwiParams.restoreMask = 0xffff;

Then pass hwiParams to the Hwi.create() call

Dynamically at runtime would be like:

Hwi_Params_init(&hwiParams);

//Disable all interrupts before entering ISR
hwiParams.maskSetting = Hwi_MaskingOption_ALL;            /* this would disable all interrupts during your isr */
hwiHandle = Hwi_create(HWI_INTERRUPT, isrFunc, &hwiParams, NULL);

Hwi_Params_init(&hwiParams);

//Disable interrupts based on bit mask before entering ISR
hwiParams.maskSetting = Hwi_MaskingOption_BITMASK;    /* this would disable interrupts based on mask */
hwiParams.disableMask = 0xE000;                                         /* this would disable interrupts 13, 14, 15 while your in your isr */
hwiParams.restoreMask = 0xE000;                                         /* this restores the interrupt mask when exiting your isr */
hwiHandle = Hwi_create(HWI_INTERRUPT, isrFunc, &hwiParams, NULL);

Judah

Hello,

Any update on why occasionally all HWIs got delayed up to 80 us?

Thanks,

Adam

Adam,

Did you try my suggested changes to see if the inverted Hwi priorites problem goes away?
Maybe the delay might go away too?

You wrote:

Answer: The last log shows delay more than 80us. Usually the context switch takes less than 5us. The HWI delay happens when Task_filter() is requested to process a lot of data stored in DDR3.

Question: Is the Task_filter() run in the context of the Task thread?  Is caching enabled?  Are Interrupts disabled when running Task_filter()?

From your answer it sounds like this function is taking too long and is causing the next Hwi to be delayed.  How long is it supposed to take?

Judah

Hi Judah,

Thanks for the help. See my answers below. 

Also, is the Task_filter() run in the context of the Task thread?  Is caching enabled?  Are Interrupts disabled when running Task_filter()?

Answer: yes, Task_filter() run in the context of the Task thread. Both L1P is L1D act as cache. Cache is enabled. L2SRAM is for program and data and not act as cache. Task_filter() is the lowest priority other than idle task. It doesn't disable interrupt.  

From your answer it sounds like this function is taking too long and is causing the next Hwi to be delayed.  They’re asking how long is it supposed to take?

Answer: Task_filter() usually receives its semaphore every several ms. And take about several hundred us to finish its task. The HWI delay occurs when Task_filter() is requested to process a huge data in DDR3. It would take several minutes to complete which is ok since it has low priority and can run it in background. But I don't know why HWIs got delay to 80us (usually several us).

Thanks,

Adam

Adam,

Ok, looks like your thread priorities are correct.  Yes, I would expect an interrupt to preempt the Task_filter() function.  It does not make sense
why its not at the moment.

Can you try my suggestion to prevent the Hwi priority inversion?  (I dont know if this will solve the delay problem but at least we can rule that out)

Also, I would recommend to keep the BIOS clock at 100us or larger instead of 10us, just because this means you're code is going to be servicing the
Timer interrupt quite often.

Judah