DSP Block due to MessageQ_alloc/free on ARM

Kishor,

It sounds like the same HeapMemMP instance is used for sending messages in both directions. This puts heavy contention on the heap instance because both sides are doing alloc and free. You could try creating two heap instances, one for sending messages in each direction. This would reduce the contention.

Creating a heap instance without a gate means the heap will inherit the default GateMP instance. This means that if any thread, running on any processor, takes the gate, it will cause the ARM and DSP tasks to spin waiting on the same gate. The default GateMP instance is used in many places (Notify, ListMP, etc.). I suggest you create a GateMP instance specifically for the heap you are using. This will reduce the contention. I would create a gate instance for each heap instance.

~Ramsey

Ramsey,

We have a highest priority task on DSP which does not call any IPC/Syslink API.

It only pends on a SYS/BIOS Mailbox which is posted by a Hwi.

We see that this task also gets blocked during this case.

We see from BIOS logs that Hwi are happening and the task is ready to run but it does not run.

Why do you think this will happen?

Also sometimes we saw the task running but it takes too long to run. It runs every 1 ms and usually finishes processing in 0.2 ms.

But in this case it takes >2ms to finish.  We put Hwi_disable and Hwi_enable around the processing of the task and still we were observing this behavior sometimes.

-Kishor

Kishor,

Perhaps the scheduler is disabled. Unfortunately, we don't have any log events to report this. You could add some Log_print statements in the following functions to add your own log events. This would help you to know if the scheduler has been disabled.

Task_disable
Task_enable
Task_restore
Swi_enable
Swi_disable

Then set your BIOS lib type to custom in your config file to rebuild the SYS/BIOS sources.

BIOS.libType = BIOS.LibType_Custom;

As for the long running time, it's hard to guess without knowing what the task is doing. Here are some things to consider.

1. Cache maintenance. Maybe in the long run, there is a lot of cache write-back and reloading, in the fast run there might be lots of cache hits.

2. If the task is writing to L3 addresses, there could be lots of bus contention.

3. Is the task busy waiting on some peripheral?

~Ramsey

Ramsey

Attached is the log I have from sysbios rta agent when the problem is observed.

8880.bios_log.txt

2678.task_rov.txt

You might be interested from the logid 147195510 ti.sysbios.knl.Swi,LM_begin

This  swi ends only at 147195540 after 4ms (DSP is running at 600MHz)

Task with pri 15 is readu to run at 147195514.

So it seems this Swi is taking too long??

This task does some sort bit formatting 14 bit to 16 bit conversion and Sample rate conversion. Most of the code/data is in DSP L2 IRAM.

--Kishor

Ramsey,

How can I change the GateMP params to disable Kernel Preemption?

Hi Kishor,

If you have CONFIG_PREEMPT_RT enabled, then Gate_enterSystem() will be interruptable.  Otherwise,
Gate_enterSystem() disables interrupts.  Here is the code for the kernel side of Gate_enterSystem():

IArg  Gate_enterSystem (void)
{
    unsigned long flags;

#if defined (CONFIG_PREEMPT_RT)
  if( staticOwner != get_current() ) {
    mutex_lock_interruptible(&staticMutex);
    staticOwner = get_current();
  }
  staticDepth++;
#else
    local_irq_save (flags);
#endif /*!defined (CONFIG_PREEMPT_RT) */

    return (IArg)flags;
}

So maybe what's happening is that a lower priority thread enters the MP gate and is then
preempted.  Meanwhile, a thread on the DSP tries to enter the same MP gate, but cannot
do so until the ARM side thread has released it.

From the MessageQ code (ti/syslink/ipc/hlos/knl/MessageQ.c), it does not appear that MessageQ_get()
and MessageQ_put() are using GateMP, so it may be some other function you are calling.  Could it be
MessageQ_alloc()?

You can try to raise your thread's realtime priority before entering the system gate to see if the problem
goes away.  Here is some example code for changing the thread priority:

        #include <sched.h>

        struct sched_param params;
        Int retc = 0;

        retc = sched_getparam(getpid(), &params);
        params.sched_priority = 55;

        retc = sched_setparam(getpid(), &params);

You can then lower the threads priority back to what it was after making the call that entered
the GateMP.

Best regards,

    Janet

Janet,

Janet,

snip from GateMP.c

<<<<

unsigned long gateMP_flags=0;
/*
 *  ======== GateMP_enter ========
 */
IArg GateMP_enter (GateMP_Object * obj)
{
    IArg key;

    local_irq_save (gateMP_flags);
    
    GT_1trace (curTrace, GT_ENTER, "GateMP_enter", obj);
    key = IGateProvider_enter(obj->gateHandle);
    GT_1trace (curTrace, GT_LEAVE, "GateMP_enter", key);

    return (key);
}

/*
 *  ======== GateMP_leave ========
 */
Void GateMP_leave (GateMP_Object * obj, IArg key)
{
    GT_2trace (curTrace, GT_ENTER, "GateMP_leave", obj, key);
    IGateProvider_leave(obj->gateHandle, key);
    GT_0trace (curTrace, GT_LEAVE, "GateMP_leave");

    local_irq_restore ((unsigned long) gateMP_flags);
}

>>>>

Janet,

------------[ cut here ]------------
WARNING: at kernel/softirq.c:159 local_bh_enable+0x54/0xd4()
Modules linked in: radio_pll_pinmux syslink
Backtrace:
[<c004ae90>] (dump_backtrace+0x0/0x110) from [<c04071b8>] (dump_stack+0x18/0x1c)
 r7:00000000 r6:c0076184 r5:c04dd1db r4:0000009f
[<c04071a0>] (dump_stack+0x0/0x1c) from [<c00701c0>] (warn_slowpath_common+0x54/0x6c)
[<c007016c>] (warn_slowpath_common+0x0/0x6c) from [<c00701fc>] (warn_slowpath_null+0x24/0x2c)
 r9:00000001 r8:d5400980 r7:00000004 r6:ccb84b00 r5:c056e828
r4:c05c28c0
[<c00701d8>] (warn_slowpath_null+0x0/0x2c) from [<c0076184>] (local_bh_enable+0x54/0xd4)
[<c0076130>] (local_bh_enable+0x0/0xd4) from [<c00690f4>] (omap_mbox_msg_send+0xdc/0xec)
 r5:c056e828 r4:00000000
[<c0069018>] (omap_mbox_msg_send+0x0/0xec) from [<c032fe04>] (notify_shm_drv_send_event+0x1c8/0
x208)
 r5:00000080 r4:00000000
[<c032fc3c>] (notify_shm_drv_send_event+0x0/0x208) from [<c032d594>] (notify_send_event+0x114/0
x26c)
[<c032d480>] (notify_send_event+0x0/0x26c) from [<bf03bce0>] (Notify_sendEvent+0x64/0x94 [sysli
nk])
[<bf03bc7c>] (Notify_sendEvent+0x0/0x94 [syslink]) from [<bf054de8>] (NameServerRemoteNotify_ge
t+0x3a4/0x57c [syslink])
[<bf054a44>] (NameServerRemoteNotify_get+0x0/0x57c [syslink]) from [<bf02cfc4>] (NameServer_get
+0x268/0x3bc [syslink])
[<bf02cd5c>] (NameServer_get+0x0/0x3bc [syslink]) from [<bf076ff8>] (_ClientNotifyMgr_create+0x
5c4/0xcb8 [syslink])
[<bf076a34>] (_ClientNotifyMgr_create+0x0/0xcb8 [syslink]) from [<bf0777ac>] (ClientNotifyMgr_c
reate+0xc0/0x114 [syslink])
[<bf0776ec>] (ClientNotifyMgr_create+0x0/0x114 [syslink]) from [<bf076238>] (RingIOShm_create+0
x86c/0x970 [syslink])
 r4:00000180
[<bf0759cc>] (RingIOShm_create+0x0/0x970 [syslink]) from [<bf06fb6c>] (RingIO_create+0x160/0x2f
0 [syslink])
[<bf06fa0c>] (RingIO_create+0x0/0x2f0 [syslink]) from [<bf084e18>] (RingIODrv_ioctl+0x2d8/0x10c
0 [syslink])
 r5:c028f355 r4:00000000
[<bf084b40>] (RingIODrv_ioctl+0x0/0x10c0 [syslink]) from [<c00e1ad0>] (vfs_ioctl+0x28/0x44)
 r8:41c8dcf8 r7:0000001d r6:0000001d r5:cb8a4a00 r4:cc025060
[<c00e1aa8>] (vfs_ioctl+0x0/0x44) from [<c00e2264>] (do_vfs_ioctl+0x558/0x5a0)
[<c00e1d0c>] (do_vfs_ioctl+0x0/0x5a0) from [<c00e2304>] (sys_ioctl+0x58/0x7c)
[<c00e22ac>] (sys_ioctl+0x0/0x7c) from [<c0046f40>] (ret_fast_syscall+0x0/0x30)
 r8:c00470e8 r7:00000036 r6:001058d8 r5:c028f355 r4:41c8dcf8
---[ end trace e188b6cc692f473c ]---

Hi Kishor,

Could you try replacing the local_irq_save() and local_irq_restore() calls with preempt_disable() and preempt_enable()
in GateMP_enter() and GateMP_exit(), and see if that fixes the problem?  We looked into the kernel warning, and that is
happening because interrupts are disabled.

Thanks,

    Janet

Hi Kishor,

I dug through the Syslink code some more, and I have something else you can try.  When you create the HeapMemMP
heap that you will register with MessageQ, you are not creating your own gate for it,  correct?  If that is the case, HeapMemMP
will use GateMP's default gate (as Ramsey mentioned in an earlier post).  It looks like the default gate for GateMP is a mutex
gate, so that probably wouldn't keep you from being preempted.  Could you try creating a GateMP gate for the heap that
uses GateMP_LocalProtect_INTERRUPT, and see if that helps?  Here is some sample code for creating the gate:

    GateMP_Params   gateParams;

    GateMP_Params_init (&gateParams);

    gateParams.name             = GATEMP_NAME;  /*  Your GateMP name */
    gateParams.regionId         = SHARED_REGION_1;
    gateParams.localProtect     = GateMP_LocalProtect_INTERRUPT;
    gateParams.remoteProtect    = GateMP_RemoteProtect_SYSTEM;

    gateMPHandle = GateMP_create (&gateParams);

    HeapMemMP_Params    heapParams;

    HeapMemMP_Params_init (&heapParams);

    heapParams.name         =   GPP_HEAPMEMMP_NAME;  /* Your heap name */
    heapParams.regionId     =   SHARED_REGION_1;
    heapParams.gate         =  gateMPHandle;

If this works, it would be a better way to fix the problem than adding preempt_disable()/preempt_enable()
calls to GateMP_enter()/GateMP_exit(). But I haven't actually tried this out.

Thanks,

    Janet

I'm only seeing Gate_enterSystem() calls in NotifyDriverShm_sendEvent()  when sending to a remote proc.  It looks like
it waits for a previous event on the remote pocessor to be cleared.

    Janet

Kishor,

Sorry, but I was looking at the wrong MessageQ transport function in my last post.  The default transport function,
TransportShm, uses ListMP for the messages.  I was looking at the code in TransportShmNotify.c.  You might be
able to get better performance on the MessageQ_put() calls by switching to TransportShmNotify.  Here is a link
that explains the SysLink Notify drivers and transports, and how you can configure them:

http://processors.wiki.ti.com/index.php/SysLink_Notify_Drivers_and_Transports

Take note, though, that you will need to use the NotifyShmDrv if you are using a TI81XX device, but you may change
the transport.  There are also some limitations to using TransportShmNotify.  The sender will have to wait until the
receiver has moved the message.

Best regards,

    Janet

Janet,

Attached is the exception log with Syslink TRACEENTER=1

Can you check this and see if you can find why it crashes? Let me know if you need some other logs.

3465.syslink_trace.log

Kishor,

From the trace, it looks like the error:

Leaving GateMPDrv_drvioctl
    osStatus    [0x0]
BUG: scheduling while atomic: RadioApp/1259/0x00000002
Modules linked in: radio_pll_pinmux syslink
Backtrace:
[<c004ae90>] (dump_backtrace+0x0/0x110) from [<c04071b8>] (dump_stack+0x18/0x1c)
 r7:00000036 r6:00106404 r5:cc011600 r4:00000000
[<c04071a0>] (dump_stack+0x0/0x1c) from [<c006aad8>] (__schedule_bug+0x54/0x60)
[<c006aa84>] (__schedule_bug+0x0/0x60) from [<c04074fc>] (schedule+0x78/0x3c0)
 r5:cc011600 r4:4242f7ec
[<c0407484>] (schedule+0x0/0x3c0) from [<c0046fa0>] (ret_slow_syscall+0x0/0x10)

is occurring because the kernel is calling 'schedule()' while preemption is disabled.   It looks like GateMP_enter()
is called in user mode, which goes down to the kernel mode GateMP_enter() (where preemption is disabled).
Then when leaving the GateMP_drvioctl, the kernel calls schedule().  So it seems to me that calling schedule()
with preemption disabled is not allowed.  That was the only place in the trace where I could find GateMP_enter()
called from user mode.

It was hard to tell from the trace what was really happening.  It looked to me like maybe one thread was blocked
waiting for a message, and another was calling ClientNotifyMgr_create().

Best regards,

    Janet

Janet,

Hi Kishor,

I think what is happening here is that you have threads trying to enter an OsalMutex gate, but another thread
is holding the gate.  GateMP_enter() tries to acquire a local gate (OsalMutex) but before that, it has called
preempt_disable().  So if another thread is holding the OsalMutex, GateMP_enter() will time out trying to
acquire the local gate.  Looking at the file ti/syslink/utils/hlos/knl/osal/OsalMutex.c, you can see that
OsalMutex_enter() will call schedule_timeout() if it is blocked.

So, I think calling preempt_disable() in the GateMP_enter() code is not a good idea after all.

Going back to the suggestion of using TransportShmNotify instead of TransportShm, I don't understand
why you would need to change the application to have only one message on the queue.  I think the isr will
just transfer one message to the queue, instead of going through the list of messages to put on queues.
So, I think there would be just some configuration code that you would need to add, as described in

http://processors.wiki.ti.com/index.php/SysLink_Notify_Drivers_and_Transports#Shared_Memory_Notify_Transport

This would allow the Arm side to get messages to the DSP faster, since it avoids going through ListMP.  And, if
the DSP is really blocked waiting for messages from the Arm, the Arm side may not have to spin waiting for the receiver
to move the message to the queue.  Maybe this wording in the link above is a little confusing:

Using NotifyDriverShm will only allow one message at a time to be placed in the MessageQ.

(This means using NotifyDriverShm with TransportShmNotify)  You can have multiple messages on the queue,
it's just that the isr will just put one message on it. Anyway, I think it's still worth trying out to see if performance
improves.

Best regards,

    Janet

Janet,

I tried using  TransportShmNotify.

-Kishor

I think I am observing the same issue. A periodic EDMA interrupt that is scheduled to fire every 750 microseconds on the DSP is sometimes delayed to be as long as 1200 microseconds. I am measuring times in the DSP's EDMA HWI interrupt routine. Can you elaborate on the background of what you think is happening and why changing the MessageQ's Gate protection method will have an effect.

For the record, DSP is doing MessageQ_alloc(), MessageQ_put() and MessageQ_free().

Is the theory that the ARM side does a MesageQ_alloc() and the DSP side tries to do a MessageQ_alloc() at the same time and the DSP spins in a loop with HWIs disabled?

Is there documentation somewhere on what syslink operations disable interrupts? I can't seem to find anything written down.