Kernel crash during Memory_alloc()

Lee Holeva said:

shared region 1:
base addr = 45983000
length = 10000000
oAssertion at Line no: 456 in /home/lholeva/ti-ezsdk_dm816x-evm_5_01_01_80/sysli
nk_2_00_00_78/packages/ti/syslink/utils/hlos/knl/Linux/../../../../../../ti/sysl
ink/ipc/hlos/knl/Linux/GateMPDrv.c: (cargs->args.create.handle != NULL) : failed
wner = 3
Is Valid = 1
name = (null)

While this message appears in-line with your SharedRegion_getEntry() code, it is not related to that code.  The assertion is from a call to GateMP_create(), and SharedRegion_getEntry() does not create a GateMP.  This kernel message is printed to the console immediately as it happens, whereas user output (i.e., your shared region info) is buffered and gets rendered to the console some amount of time after they happen.  So, it's likely that this GateMP_create() assertion is a result of code that runs *after* your SharedRegion_getEntry() code.

Would you be able to turn on SysLink kernel module trace and rerun?  To turn on kernel module trace, do the following:
   % insmod syslink.ko TRACE=1 TRACEENTER=1 TRACEFAILURE=1
You will get *lots* of output on the console, and your app will run much slower as a result, but should still run in the same way as without the syslink.ko trace output.  The TRACEENTER output will show the flow before/after and surrounding the assertion.

My initial "take" on the assertion is that you're running out of memory somehow, and the GateMP_create() is asserting because of a Memory_alloc(NULL, ...) failure (the NULL means use the module's default memory heap).

Lee Holeva said:

VNC: Allocating Unable to handle kernel paging request at virtual address f5afeb
80
b0400 bytes in rpgd = cb6ec000
egion 1
[f5afeb80] *pgd=00000000

Internal error: Oops: 805 [#1]  <--What is this?

last sysfs file: /sys/devices/platform/musb-ti81xx.0/musb-hdrc.0/usb1/1-1/devnum
Modules linked in: bufferclass_ti pvrsrvkm TI81xx_hdmi ti81xxfb vpss syslink ipv
6
CPU: 0    Not tainted  (2.6.37 #1)
PC is at v7_dma_inv_range+0x20/0x48
LR is at Cache_inv+0x50/0x78 [syslink]

The "Internal error: Oops" is a standard Linux "Oops" (a panic), meaning some kernel code dereferenced a pointer that was not mapped.  We can see from the traceback info that it was a result of a SysLink Cache_inv() call, called by HeapMemMP_getStats().

The HeapMemMP_getStats() code walks the heap's freelist, and performs Cache_inv() calls in the process.  There's not really enough info printed to get much of a sense of what's going on.  Perhaps a corrupted HeapMemMP freelist?

If you turn on syslink.ko TRACE as I've mentioned above, perhaps we will see something that will help determine the cause of this.

Regards,

- Rob

Robert Tivy said:

insmod syslink.ko TRACE=1 TRACEENTER=1 TRACEFAILURE=1

Including TRACEENTER=1 causes insmod to go bonkers, its output never stiops.  I can include TRACE=1 and TRACEFAILURE=1, but I do not get any additional output.

According to the EZSDK FAQ, I should have plenty of memory available in shared region 1 starting at 0xB0000000:

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

As i said, at present I am only attempting to allocating a bit more than 5Mbytes.  Here is my memory allocation code:

Int8 *allocinshared(UInt32 numbytes, UInt16 Id)
{
  IHeap_Handle  srHeap = NULL;
  Int8          *Img;
  Memory_Stats  memStats;

  srHeap = SharedRegion_getHeap (Id);

  HeapMemMP_getStats((HeapMemMP_Handle)srHeap, (Ptr)&memStats);
  Osal_printf("Before alloc: Heap totalsize = 0x%x bytes, totalfreesize = 0x%x bytes, largestfreesize = 0x%x bytes\n\n",
  memStats.totalSize, memStats.totalFreeSize, memStats.largestFreeSize);

  Img = (Int8 *) Memory_alloc (srHeap,
          numbytes,
          0,
          NULL);
  if (Img == NULL) {
   
    Osal_printf ("Image allocation in heap %x of region %d failed when allocating 0x%x bytes!.\n",
   srHeap, Id, numbytes);
   
      return(NULL);
  }

Id = 0 or 1.

I notice that syslink_2_00_01_79 is out.  I'll give that a try.

Lee Holeva

Lee Holeva said:

Including TRACEENTER=1 causes insmod to go bonkers, its output never stiops.  I can include TRACE=1 and TRACEFAILURE=1, but I do not get any additional output.

Yeah, TRACEENTER=1 can cause lots of output, seeming to never stop, but if you give it enough time I believe it will eventually stop (and then produce lots more output when you actually run your app, mostly during remote code loading).

If TRACEENTER=1 isn't fruitful, you could try just TRACECLASS=3, which prints information about execution inside the functions (as opposed to just enter/exit prints produced by TRACEENTER).

Lee Holeva said:

According to the EZSDK FAQ, I should have plenty of memory available in shared region 1 starting at 0xB0000000:

I don't think your problem is related to running out of SR heap memory, I suspect it's more related to some other non-shared heap.  Hopefully more TRACE output will shed some light.

Regards,

- Rob

Robert Tivy said:

Yeah, TRACEENTER=1 can cause lots of output, seeming to never stop, but if you give it enough time I believe it will eventually stop (and then produce lots more output when you actually run your app, mostly during remote code loading).

I upgraded to syslink 2.00.01.79.  If I run with TRACEENTER=1 the kernel crash does not happen and all of the Memory_allocs() work as well, my code runs as it should.  If I run without TRACEENTER=1, I get the kernel crash.  Perhaps this is indicative of a timing problem or a race condition somewhere?  I'll see what TRACECLASS=3 does.

Lee Holeva

Robert Tivy said:

If TRACEENTER=1 isn't fruitful, you could try just TRACECLASS=3, which prints information about execution inside the functions (as opposed to just enter/exit prints produced by TRACEENTER).

Using TRACECLASS=3, I managed to get the kernel crash to reappear.  Here is the output:

shared region 0:
base addr = 0x    HeapMemMP_create knl ioctl: Shared addr [0x0]

417fb000
length = 0x4000000 bytes
owner = 3
Is Valid = 1
name = (null)
Heap totalsize = 0x3fff980 bytes, totalfreesize = 0x3ffcf00 bytes, largestfreesi
ze = 0x3ffcf00 bytes

shared region 1:
base addr = 0x458ca000
le    NotifyDriverShm_registerEvent
        Added entry in regChart: [2]

ngth = 0x1000000    NameServer_getLocal name [MSGQ_PREPROCESSINGIN]
0 bytes
owner =    NameServer_getLocal: Entry not found!
 3
Is Valid = 1   ISR handled

name = (null)    MessageQ_open ioctl queueId [0x2]

Heap totalsize    ISR handled
= 0xfffff80 byte    NameServer_getLocal name [normalizeGate]
s, totalfreesize = 0xfffff80 bytes, largestfreesize = 0xfffff80 bytes

Using the following message queues:
MSGQ_PREPROCESSINGIN
MSGQ_CORNERIN
MSGQ_ROIN
Creating the heap
Registering heapId 0 with MessageQ for procId: 0
Copying input image to region 0
Before alloc: Heap totalsize = 0x3fff980 bytes, totalfreesize = 0x3ffbe80 bytes,
 largestfreesize = 0x3ffbe80 bytes

Creating the normalization gate
Creating the GateMP
NORM: Allocating 58200 bytes in region 0
Before alloc: Heap totalsize = 0x3fff980 bytes, totalfreesize = 0x3fa3c80 bytes,
 largestfreesize = 0x3fa3c80 bytes

Registering the Normalization ta   ISR handled
sk
Registered remote event numb    NotifyDriverShm_registerEvent
        Added entry in regChart: [2]

er 10 with Notif    NameServer_getLocal name [MSGQ_ROIN]
y module for pro    NameServer_getLocal: Entry not found!
cessor 0
Doing    ISR handled
the Normalization task
Size of     NotifyDriverShm_registerEvent
        Added entry in regChart: [2]

theMsg = 104
Op    NameServer_getLocal name [MSGQ_CORNERIN]
ening the DSP's     NameServer_getLocal: Entry not found!
message queue fo    MessageQ_open ioctl queueId [0x0]
r task 10
Messa   ISR handled
geQ_open Status     MessageQ_open ioctl queueId [0x1]
0 : procId [0]
MessageQApp_queueId  [0x2] : procId [0]
Allocating 136 bytes of memory for the message
Putting the taskId into the message
Sending a message to the DSP for task 10
Sending taskId 10 to the DSP
completed task 10 from processor 0 with payload 333
Freeing message for task 10
Corners: Allocating b0400 bytes in region 1
Before alloc: Heap totalsize = 0xfffff80 bytes, totalfreesize = 0xfffff00 bytes,
 largestfreesize = 0xfffff00 bytes

Before alloc: Heap totalsize = 0xfffff80 bytes, totalfreesize = 0xffa7d00 bytes,
 largestfreesize = 0xffa7d00 bytes

Ro: Allocating 160800 bytes in region 1
Before alloc: Heap totalsize = 0xfffff80 bytes, totalfreesize = 0xff4fb00 bytes,
 largestfreesize = 0xff4fb00 bytes

Before alloc: Heap totalsize = 0xfffff80 bytes, totalfreesize = 0xfe9f700 bytes,
 largestfreesize = 0xfe9f700 bytes

HCONV: Allocating b0400 bytes in region 1
Before alloc: Heap totalsize = 0xfffff80 bytes, totalfreesize = 0xfdef300 bytes,
 largestfreesize = 0xfdef300 bytes

Registered remote event number 15 with Notify module for processor 0
Calculating the Horizontal convolution
Opening the DSP's message queue for task 15
HNC: Allocating b0400 bytes in region 1
Before alloc: Heap totalsize = 0xfffff80 bytes, totalfreesize = 0xfd3ef00 bytes,
 largestfreesize = 0xfd3ef00 bytes

Registered remote event number 12 with Notify module for processor 0
Calculating the Horizontal cross-correlation
Opening the DSP's message queue for task 12
MessageQ_open Status 0 : procId [0]
MessageQApp_queueId  [0x0] : procId [0]
Allocating 172 bytes of memory for the message
Putting the taskId into the message
Sending a message to the DSP for task 15
Sending taskId 15 to the DSP
MessageQ_open Status 0 : procId [0]
MessageQApp_queueId  [0x1] : procId [0]
Allocating 140 bytes of memory for the message
Putting the taskId into the message
Sending a message to the DSP for task 12
Sending taskId 12 to the DSP
   ISR handled
completed task 15 from processor 0 with payload 333
Freeing message for task 15
VCONV: Allocating b0400 bytes in    NotifyDriverShm_registerEvent
        Added entry in regChart: [3]

 region 1
Befor    NameServer_getLocal name [MSGQ_ROIN]
e alloc: Heap to    NameServer_getLocal: Entry not found!
talsize = 0xffff   ISR handled
f80 bytes, total    MessageQ_open ioctl queueId [0x0]
freesize = 0xfc8eb00 bytes, largestfreesize = 0xfc8eb00 bytes

Registered remote event number 16 with Notify module for processor 0
Calculating the Vertical convolution
Opening the DSP's message queue for task 16
MessageQ_open Status 0 : procId [0]
MessageQApp_queueId  [0x0] : procId [0]
Allocating 172 bytes of memory for the message
Putting the taskId into the message
Sending a message to the DSP for task 16
Sending taskId 16 to the DSP
   ISR handled
completed task 12 from processor 0 with payload 333
Freeing message for task 12
VNC: Allocating Unable to handle kernel paging request at virtual address f6afeb
80
b0400 bytes in rpgd = ca97c000
egion 1
[f6afeb80] *pgd=00000000
Internal error: Oops: 805 [#1]
last sysfs file: /sys/devices/platform/musb-ti81xx.0/musb-hdrc.0/usb1/1-1/devnum
Modules linked in: syslink bufferclass_ti pvrsrvkm TI81xx_hdmi ipv6 [last unload
ed: syslink]
CPU: 0    Not tainted  (2.6.37 #1)
PC is at v7_dma_inv_range+0x20/0x48
LR is at Cache_inv+0x50/0x78 [syslink]
pc : [<c0048dc8>]    lr : [<bf36e41c>]    psr: 00000013
sp : c8945e40  ip : 00030101  fp : c8945e6c
r10: 00000000  r9 : c8944000  r8 : 560c8d18
r7 : 00000000  r6 : bf441cb4  r5 : f6afebb8  r4 : 00000008
r3 : 0000003f  r2 : 00000040  r1 : f6afebc0  r0 : f6afeb80
Flags: nzcv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
Control: 10c5387d  Table: 8a97c019  DAC: 00000015
Process track (pid: 1133, stack limit = 0xc89442e8)
Stack: (0xc8945e40 to 0xc8946000)
5e40: 00000008 0000ffff 00000001 bf36e6dc bf392c58 f6afebb8 d6733000 c8945ec0
5e60: c8945e94 c8945e70 bf3972e0 bf36e3d8 c8945ec0 c01cf35c c8944000 c8945ec0
5e80: 560c8d18 00000017 c8945ef4 c8945e98 bf3cdb18 bf39712c c01cf35c 560c8d18
5ea0: 00000000 d6730000 560c8d54 00060000 00000000 560c8d4c 00000000 00000000
5ec0: 0fffff80 1fafebb8 1fafebb8 c8945ed8 c01b2fb4 d6730000 00000000 00000000
5ee0: cbe5d880 00000017 c8945f04 c8945ef8 c00c49b8 bf3cd53c c8945f74 c8945f08
5f00: c00c50c8 c00c499c 404a5000 cbeab200 00000000 00000000 fffffffd 00000000
5f20: c8945f54 c8945f30 c0357ccc c003b170 cc86201c cbc0f080 00000017 cc829600
5f40: c8944000 00000000 00000001 00000000 560c8d18 c01cf35c 00000017 cbe5d880
5f60: c8944000 00000000 c8945fa4 c8945f78 c00c5160 c00c4bd4 c8945fac 00000001
5f80: c0354434 560c8d98 560c9490 40083550 00000036 c003ff48 00000000 c8945fa8
5fa0: c003fda0 c00c5114 560c8d98 560c9490 00000017 c01cf35c 560c8d18 00000017
5fc0: 560c8d98 560c9490 40083550 00000036 003d0f00 4008f3d8 00000000 560c8d04
5fe0: 00000152 560c8ce8 00039850 40369aec 20000010 00000017 4a4c494a 4a4b4a4a
Backtrace:
[<bf36e3cc>] (Cache_inv+0x0/0x78 [syslink]) from [<bf3972e0>] (HeapMemMP_getStat
s+0x1c0/0x25c [syslink])
 r6:c8945ec0 r5:d6733000 r4:f6afebb8
[<bf397120>] (HeapMemMP_getStats+0x0/0x25c [syslink]) from [<bf3cdb18>] (HeapMem
MPDrv_ioctl+0x5e8/0x77c [syslink])
 r7:00000017 r6:560c8d18 r5:c8945ec0 r4:c8944000
[<bf3cd530>] (HeapMemMPDrv_ioctl+0x0/0x77c [syslink]) from [<c00c49b8>] (vfs_ioc
tl+0x28/0x44)
 r6:00000017 r5:cbe5d880 r4:00000000
[<c00c4990>] (vfs_ioctl+0x0/0x44) from [<c00c50c8>] (do_vfs_ioctl+0x500/0x540)
[<c00c4bc8>] (do_vfs_ioctl+0x0/0x540) from [<c00c5160>] (sys_ioctl+0x58/0x7c)
[<c00c5108>] (sys_ioctl+0x0/0x7c) from [<c003fda0>] (ret_fast_syscall+0x0/0x30)
 r8:c003ff48 r7:00000036 r6:40083550 r5:560c9490 r4:560c8d98
Code: e1a02312 e2423001 e1100003 e1c00003 (1e070f3e)
   ISR handled
---[ end trace 3ddfec2de1c3c639 ]---

I think that the message queue is getting corrupted again.

Lee Holeva

Running once again using Syslink 2.00.01.79, with TRACE=1, TRACEFAILURE=1, and TRACECLASS=3, I notice some failures in the Syslink startup:

DSP is loaded from ARM

SharedRegion Module already initialized!  <-- Could these be a problem? VPSS does this.
GateMP Module already initialized!
Notify Module already initialized!
MessageQ Module already initialized!
HeapBufMP Module already initialized!
HeapMemMP Module already initialized!
ListMP Module already initialized!
ClientNotifyMgr Module already initialized!
FrameQBufMgr Module already initialized!
FrameQ Module already initialized!

Entered SysLinkS    ProcMgr_getProcInfo: bootMode: [0]
amples_startup
MemoryOS_map: pa=0x48180000, va=0xfa180000, sz=0x3000
SysLinkSamples_oMemoryOS_map: pa=0x48140000, va=0xfa140000, sz=0x20000
sStartup
NumberMemoryOS_map: pa=0x40800000, va=0xd6400000, sz=0x40000
 of processors =DM8168DSPPROC_attach: Mapping memory regions
 4
Entered ProcMemoryOS_map: pa=0x48140048, va=0xfa140048, sz=0x4
Manager_startup MemoryOS_map: pa=0x48140044, va=0xfa140044, sz=0x4
with reset vectoMemoryOS_map: pa=0x48140650, va=0xfa140650, sz=0x4
r = 0
MemoryOS_map: entry already exists
    mapInfo->src  [0x48180000]
    mapInfo->dst  [0xfa180000]
    mapInfo->size [0x2fff]
DM8168DSPPROC_attach: slave is now in reset
MemoryOS_map: entry already exists
    mapInfo->src  [0x40800000]
    mapInfo->dst  [0xd6400000]
    mapInfo->size [0x40000]
MemoryOS_map: pa=0x40e00000, va=0xd63a0000, sz=0x8000
MemoryOS_map: pa=0x40f00000, va=0xd63b0000, sz=0x8000
MemoryOS_map: pa=0x40300000, va=0xd6480000, sz=0x40000
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x40300000]
    sgList.paddr  [0x40300000]
    sgList.offset [0x0]
    sgList.size [0x40000]

MemoryOS_map: pa=0x40400000, va=0xd6500000, sz=0x40000
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x40400000]
    sgList.paddr  [0x40400000]
    sgList.offset [0x0]
    sgList.size [0x40000]

    ProcMgr_getProcInfo: bootMode: [0]
ProcMgr_attach status: [0x97d2000]
After attach: ProcMgr_getState
    state [0DLOAD: x1]
ELF: ELF
DLOAD: ELF file header entry point: 94a63000
ElfLoaderTrgWrite_copy: translated 0x10f00000 (sva) --> 0x40f00000 (mpa)
MemoryOS_map: entry already exists
    mapInfo->src  [0x40f00000]
    mapInfo->dst  [0xd63b0000]
    mapInfo->size [0x2c10]
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x10f00000]
    sgList.paddr  [0x40f00000]
    sgList.offset [0x0]
    sgList.size [0x2c10]

ElfLoaderTrgWrite_copy: translated 0x10f02c80 (sva) --> 0x40f02c80 (mpa)
MemoryOS_map: pa=0x40f02c80, va=0xd646cc80, sz=0xbf0
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x10f02000]
    sgList.paddr  [0x40f02000]
    sgList.offset [0xc80]
    sgList.size [0x1870]

ElfLoaderTrgWrite_copy: translated 0x10f03880 (sva) --> 0x40f03880 (mpa)
MemoryOS_map: pa=0x40f03880, va=0xd6474880, sz=0xbe0
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x10f03000]
    sgList.paddr  [0x40f03000]
    sgList.offset [0x880]
    sgList.size [0x1460]

ElfLoaderTrgWrite_copy: translated 0x94a00000 (sva) --> 0x94a00000 (mpa)
MemoryOS_map: pa=0x94a00000, va=0xd6580000, sz=0x38380
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a00000]
    sgList.paddr  [0x94a00000]
    sgList.offset [0x0]
    sgList.size [0x38380]

ElfLoaderTrgWrite_copy: translated 0x94a38380 (sva) --> 0x94a38380 (mpa)
MemoryOS_map: pa=0x94a38380, va=0xd65c0380, sz=0x21b98
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a38000]
    sgList.paddr  [0x94a38000]
    sgList.offset [0x380]
    sgList.size [0x21f18]

ElfLoaderTrgWrite_copy: translated 0x94a59f18 (sva) --> 0x94a59f18 (mpa)
MemoryOS_map: pa=0x94a59f18, va=0xd64c8f18, sz=0x4da6
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a59000]
    sgList.paddr  [0x94a59000]
    sgList.offset [0xf18]
    sgList.size [0x5cbe]

ElfLoaderTrgWrite_copy: translated 0x94a5ecc0 (sva) --> 0x94a5ecc0 (mpa)
MemoryOS_map: pa=0x94a5ecc0, va=0xd64d0cc0, sz=0x211c
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a5e000]
    sgList.paddr  [0x94a5e000]
    sgList.offset [0xcc0]
    sgList.size [0x2ddc]

ElfLoaderTrgWrite_copy: translated 0x94a60de0 (sva) --> 0x94a60de0 (mpa)
MemoryOS_map: pa=0x94a60de0, va=0xd64d8de0, sz=0x2000
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a60000]
    sgList.paddr  [0x94a60000]
    sgList.offset [0xde0]
    sgList.size [0x2de0]

ElfLoaderTrgWrite_copy: translated 0x94a62de0 (sva) --> 0x94a62de0 (mpa)
MemoryOS_map: pa=0x94a62de0, va=0xd64dede0, sz=0x200
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a62000]
    sgList.paddr  [0x94a62000]
    sgList.offset [0xde0]
    sgList.size [0xfe0]

ElfLoaderTrgWrite_copy: translated 0x94a62fe0 (sva) --> 0x94a62fe0 (mpa)
MemoryOS_map: pa=0x94a62fe0, va=0xd64e4fe0, sz=0x14
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a62000]
    sgList.paddr  [0x94a62000]
    sgList.offset [0xfe0]
    sgList.size [0xff4]

ElfLoaderTrgWrite_copy: translated 0x94a63000 (sva) --> 0x94a63000 (mpa)
MemoryOS_map: pa=0x94a63000, va=0xd64ea000, sz=0x200
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a63000]
    sgList.paddr  [0x94a63000]
    sgList.offset [0x0]
    sgList.size [0x200]

ElfLoaderTrgWrite_copy: translated 0x94a63200 (sva) --> 0x94a63200 (mpa)
MemoryOS_map: pa=0x94a63200, va=0xd64f0200, sz=0x120
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a63000]
    sgList.paddr  [0x94a63000]
    sgList.offset [0x200]
    sgList.size [0x320]

ElfLoaderTrgWrite_copy: translated 0x94a63320 (sva) --> 0x94a63320 (mpa)
MemoryOS_map: pa=0x94a63320, va=0xd64f6320, sz=0x80
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a63000]
    sgList.paddr  [0x94a63000]
    sgList.offset [0x320]
    sgList.size [0x3a0]

ElfLoaderTrgWrite_copy: translated 0x94a633a0 (sva) --> 0x94a633a0 (mpa)
MemoryOS_map: pa=0x94a633a0, va=0xd64fc3a0, sz=0x18
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a63000]
    sgList.paddr  [0x94a63000]
    sgList.offset [0x3a0]
    sgList.size [0x3b8]

ElfLoaderTrgWrite_copy: translated 0x94a633b8 (sva) --> 0x94a633b8 (mpa)
MemoryOS_map: pa=0x94a633b8, va=0xd65463b8, sz=0x3e
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a63000]
    sgList.paddr  [0x94a63000]
    sgList.offset [0x3b8]
    sgList.size [0x3f6]

ElfLoaderTrgWrite_copy: translated 0x94a633f8 (sva) --> 0x94a633f8 (mpa)
MemoryOS_map: pa=0x94a633f8, va=0xd654c3f8, sz=0x20
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a63000]
    sgList.paddr  [0x94a63000]
    sgList.offset [0x3f8]
    sgList.size [0x418]

ElfLoaderTrgWrite_copy: translated 0x94a63800 (sva) --> 0x94a63800 (mpa)
MemoryOS_map: pa=0x94a63800, va=0xd6552800, sz=0x4c
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x94a63000]
    sgList.paddr  [0x94a63000]
    sgList.offset [0x800]
    sgList.size [0x84c]

ProcMgr_load staElfLoader_getSymbolAddress: symName [_Ipc_ResetVector]

tus: [0x3046000]    ProcMgr_translateAddr: srcAddr [0x94a63800] dstAddr [0x94a63
800]

    ProcMgr_translateAddr: srcAddr [0x94a63800] dstAddr [0xd6552800]

    ProcMgr_translateAddr: srcAddr [0x94a6381c] dstAddr [0x94a6381c]

    ProcMgr_translateAddr: srcAddr [0x94a6381c] dstAddr [0xd655281c]

handle->slaveSRCfg [0].entryBase 90000000

Platform_loadCallback:
    No SharedRegion.entry[0].cacheEnable configuration value found, using defaul <-- I set cacheEnable=true in the .cfg file, problem?
t FALSE

Platform_loadCallback:
    Mapping SharedRegion 0
    addr [ProcMgr_AddrType_MasterPhys] [0x90000000]
    addr [ProcMgr_AddrType_SlaveVirt]  [0x90000000]
    size                               [0x4000000]
    isCached                           [0]

MemoryOS_map: pa=0x90000000, va=0xd7000000, sz=0x4000000
_ProcMgr_map for SlaveVirt:
    dstAddr       [0x90000000]
    sgList.paddr  [0x90000000]
    sgList.offset [0x0]
    sgList.size [0x4000000]

handle->slaveSRCfg [1].entryBase b0000000

Platform_loadCallback:
    No SharedRegion.entry[1].cacheEnable configuration value found, using defaul
t FALSE

Platform_loadCallback:
    Mapping SharedRegion 1
    addr [ProcMgr_AddrType_MasterPhys] [0xb0000000]
    addr [ProcMgr_AddrType_SlaveVirt]  [0xb0000000]
    size                               [0x10000000]
    isCached                           [0]

MemoryOS_map: pa=0xb0000000, va=0xdc000000, sz=0x10000000
_ProcMgr_map for SlaveVirt:
    dstAddr       [0xb0000000]
    sgList.paddr  [0xb0000000]
    sgList.offset [0x0]
    sgList.size [0x10000000]

    ProcMgr_translateAddr: srcAddr [0x94a63800] dstAddr [0x94a63800]

    ProcMgr_translateAddr: srcAddr [0x94a63800] dstAddr [0xd6552800]

After Ipc_loadca    DM8168DSPPROC_start: Slave successfully started!

llback: ProcMgr_Ipc_attach: Ipc_procSyncStart failed! <--  What is this?
getState
    state [0x3]
ProcMgr_start passed [0x6a85000]
    NotifyDriverShm_registerEvent
        Added entry in regChart: [0]

    NotifyDriverShm_registerEvent
        Added entry in regChart: [0]

After Ipc_startcallback: ProcMgr_getState
    state [0x4]
ProcMgr_close status: [0x97d2000]
Leaving ProcMgrApp_startup
Once the emulator is connected, hit return

shared region 0:
base addr = 0x    HeapMemMP_create knl ioctl: Shared addr [0x0]

4196b000
length = 0x4000000 bytes
owner = 3
Is Valid = 1
name = (null)
Heap totalsize = 0x3fff980 bytes, totalfreesize = 0x3ffcf00 bytes, largestfreesi
ze = 0x3ffcf00 bytes

shared region 1:
base addr = 0x4596d000
le    NotifyDriverShm_registerEvent
        Added entry in regChart: [2]

ngth = 0x1000000    NameServer_getLocal name [MSGQ_PREPROCESSINGIN]
0 bytes
owner =    NameServer_getLocal: Entry not found!
 3
Is Valid = 1   ISR handled

name = (null)    MessageQ_open ioctl queueId [0x2]

Heap totalsize    ISR handled
= 0xfffff80 byte    NameServer_getLocal name [normalizeGate]
s, totalfreesize = 0xfffff80 bytes, largestfreesize = 0xfffff80 bytes

Using the following message queues:
MSGQ_PREPROCESSINGIN
MSGQ_CORNERIN
MSGQ_ROIN
Creating the heap
Registering heapId 0 with MessageQ for procId: 0
Copying input image to region 0
From heap 9aba8 of Id 0: Before alloc: Heap totalsize = 0x3fff980 bytes, totalfr
eesize = 0x3ffbe80 bytes, largestfreesize = 0x3ffbe80 bytes

Creating the normalization gate
Creating the GateMP
NORM: Allocating 58200 bytes in region 0
From heap 9b178 of Id 0: Before alloc: Heap totalsize = 0x3fff980 bytes, totalfr
eesize = 0x3fa3c80 bytes, largestfreesize = 0x3fa3c80 bytes
   ISR handled

Registering the Normalization task
Registered    NotifyDriverShm_registerEvent
        Added entry in regChart: [2]

 remote event nu    NameServer_getLocal name [MSGQ_ROIN]
mber 10 with Not    NameServer_getLocal: Entry not found! <-- problem?
ify module for p   ISR handled
rocessor 0
Doin    MessageQ_open ioctl queueId [0x0]
g the Normalization task
Size o    NotifyDriverShm_registerEvent
        Added entry in regChart: [2]

f theMsg = 104
    NameServer_getLocal name [MSGQ_CORNERIN]
Opening the DSP'    NameServer_getLocal: Entry not found!
s message queue    ISR handled
for task 10
Mes    MessageQ_open ioctl queueId [0x1]
sageQ_open Status 0 : procId [0]
MessageQApp_queueId  [0x2] : procId [0]
Allocating 136 bytes of memory for the message
Putting the taskId into the message
Sending a message to the DSP for task 10
Sending taskId 10 to the DSP
completed task 10 from processor 0 with payload 333
Freeing message for task 10
Corners: Allocating b0400 bytes in region 1
From heap 9b1a8 of Id 1: Before alloc: Heap totalsize = 0xfffff80 bytes, totalfr
eesize = 0xfffff00 bytes, largestfreesize = 0xfffff00 bytes

From heap 9ac20 of Id 1: Before alloc: Heap totalsize = 0xfffff80 bytes, totalfr
eesize = 0xffa7d00 bytes, largestfreesize = 0xffa7d00 bytes

Ro: Allocating 160800 bytes in region 1
From heap 9ace0 of Id 1: Before alloc: Heap totalsize = 0xfffff80 bytes, totalfr
eesize = 0xff4fb00 bytes, largestfreesize = 0xff4fb00 bytes

From heap 9ad10 of Id 1: Before alloc: Heap totalsize = 0xfffff80 bytes, totalfr
eesize = 0xfe9f700 bytes, largestfreesize = 0xfe9f700 bytes

HCONV: Allocating b0400 bytes in region 1
From heap 9add0 of Id 1: Before alloc: Heap totalsize = 0xfffff80 bytes, totalfr
eesize = 0xfdef300 bytes, largestfreesize = 0xfdef300 bytes

Registered remote event number 15 with Notify module for processor 0
Calculating the Horizontal convolution
Opening the DSP's message queue for task 15
MessageQ_open Status 0 : procId [0]
MessageQApp_queueId  [0x0] : procId [0]
Allocating 172 bytes of memory for the message
Putting the taskId into the message
Sending a message to the DSP for task 15
Sending taskId 15 to the DSP
HNC: Allocating b0400 bytes in region 1
From heap 9ae20 of Id 1: Before alloc: Heap totalsize = 0xfffff80 bytes, totalfr
eesize = 0xfd3ef00 bytes, largestfreesize =   ISR handled
 0xfd3ef00 bytes

Registered remote event number 12 with Notify module for processor 0
Calculating the Horizontal cross-correlation
Opening the DSP's message queue for task 12
MessageQ_open Status 0 : procId [0]
MessageQApp_queueId  [0x1] : procId [0]
Allocating 140 bytes of memory for the message
Putting the taskId into the message
Sending a message to the DSP for task 12
Sending taskId 12 to the DSP
completed task 15 from processor 0 with payload 333
Freeing message for task 15
VCONV: Allocating b0400 bytes in    NotifyDriverShm_registerEvent
        Added entry in regChart: [3]

 region 1
From     NameServer_getLocal name [MSGQ_ROIN]
heap 9ae00 of Id    NameServer_getLocal: Entry not found!
 1: Before alloc   ISR handled
: Heap totalsize    MessageQ_open ioctl queueId [0x0]
 = 0xfffff80 bytes, totalfreesize = 0xfc8eb00 bytes, largestfreesize = 0xfc8eb00
 bytes

Registered remote event number 16 with Notify module for processor 0
Calculating the Vertical convolution
Opening the DSP's message queue for task 16
MessageQ_open Status 0 : procId [0]
MessageQApp_queueId  [0x0] : procId [0]
Allocating 172 bytes of memory for the message
Putting the taskId into the message
Sending a message to the DSP for task 16
Sending taskId 16 to the DSP
   ISR handled
completed task 12 from processor 0 with payload 333
Freeing message for task 12
VNC: Allocating Unable to handle kernel paging request at virtual address f6afeb
80
b0400 bytes in rpgd = c8820000
egion 1
[f6afeb80] *pgd=00000000
Internal error: Oops: 805 [#1]
last sysfs file: /sys/devices/platform/musb-ti81xx.0/musb-hdrc.0/usb1/1-1/devnum
Modules linked in: syslink bufferclass_ti pvrsrvkm TI81xx_hdmi ipv6 [last unload
ed: syslink]
CPU: 0    Not tainted  (2.6.37 #1)
PC is at v7_dma_inv_range+0x20/0x48
LR is at Cache_inv+0x50/0x78 [syslink]
pc : [<c0048dc8>]    lr : [<bf22841c>]    psr: 00000013
sp : c894fe40  ip : 00030101  fp : c894fe6c
r10: 00000000  r9 : c894e000  r8 : 5616bce0
r7 : 00000000  r6 : bf2fbcb4  r5 : f6afebb8  r4 : 00000008
r3 : 0000003f  r2 : 00000040  r1 : f6afebc0  r0 : f6afeb80
Flags: nzcv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
Control: 10c5387d  Table: 88820019  DAC: 00000015
Process track (pid: 1129, stack limit = 0xc894e2e8)
Stack: (0xc894fe40 to 0xc8950000)
fe40: 00000008 0000ffff 00000001 bf2286dc bf24cc58 f6afebb8 d6573000 c894fec0
fe60: c894fe94 c894fe70 bf2512e0 bf2283d8 c894fec0 c01cf35c c894e000 c894fec0
fe80: 5616bce0 00000017 c894fef4 c894fe98 bf287b18 bf25112c c01cf35c 5616bce0
fea0: c894fed4 d6570000 5616bd4c 0009ae50 003d0f00 400dc3d8 00010000 5616bd2c
fec0: 0fffff80 1fafebb8 1fafebb8 c035c308 c8834b00 d6570000 00000000 00000000
fee0: cb74c800 00000017 c894ff04 c894fef8 c00c49b8 bf28753c c894ff74 c894ff08
ff00: c00c50c8 c00c499c c005e380 c005b750 00000000 00000000 fffffffd 00000000
ff20: c894ff54 c894ff30 c0357ccc c003b170 cc86201c c8834b00 00000017 cc829600
ff40: c894e000 00000000 00000001 00000000 5616bce0 c01cf35c 00000017 cb74c800
ff60: c894e000 00000000 c894ffa4 c894ff78 c00c5160 c00c4bd4 c894ffac 00000001
ff80: c0354434 5616bd98 5616c490 400d0550 00000036 c003ff48 00000000 c894ffa8
ffa0: c003fda0 c00c5114 5616bd98 5616c490 00000017 c01cf35c 5616bce0 00000017
ffc0: 5616bd98 5616c490 400d0550 00000036 003d0f00 400dc3d8 00000000 5616bccc
ffe0: 00000152 5616bcb0 0003985c 40384aec 20000010 00000017 ffffffff ffffffff
Backtrace:
[<bf2283cc>] (Cache_inv+0x0/0x78 [syslink]) from [<bf2512e0>] (HeapMemMP_getStat
s+0x1c0/0x25c [syslink])
 r6:c894fec0 r5:d6573000 r4:f6afebb8
[<bf251120>] (HeapMemMP_getStats+0x0/0x25c [syslink]) from [<bf287b18>] (HeapMem
MPDrv_ioctl+0x5e8/0x77c [syslink])
 r7:00000017 r6:5616bce0 r5:c894fec0 r4:c894e000
[<bf287530>] (HeapMemMPDrv_ioctl+0x0/0x77c [syslink]) from [<c00c49b8>] (vfs_ioc
tl+0x28/0x44)
 r6:00000017 r5:cb74c800 r4:00000000
[<c00c4990>] (vfs_ioctl+0x0/0x44) from [<c00c50c8>] (do_vfs_ioctl+0x500/0x540)
[<c00c4bc8>] (do_vfs_ioctl+0x0/0x540) from [<c00c5160>] (sys_ioctl+0x58/0x7c)
[<c00c5108>] (sys_ioctl+0x0/0x7c) from [<c003fda0>] (ret_fast_syscall+0x0/0x30)
 r8:c003ff48 r7:00000036 r6:400d0550 r5:5616c490 r4:5616bd98
Code: e1a02312 e2423001 e1100003 e1c00003 (1e070f3e)
   ISR handled
---[ end trace f33e8e455f34a1bf ]---
completed task 16 from processor 0 with payload 333
Freeing message for task 16

Again, if I run with TRACEENTER=1, I do not get the kernel crash, my code runs as it should.

Update:

I commented-out the allocations for some images that are not currently used.  Running the program again the kernel crash still occasionally occurs, suggesting that this issue has nothing to do with how much memory is being allocated, rather it's about the timing of some event.

Here's something to ponder:  I have two threads running on the ARM, both of which communicate to Syslink.  Could Syslink hic-up if it simultaneously receives either a pair of notifications or message puts?  In other words, is Syslink a mutually exculsive resourse?

Something odd:  if task2 starts before task3 on the ARM, the program runs correctly, if however task3 starts before task2, the kernel crash occurs.  The tasks are independent, the start ordering shouldn't matter.

Update Secunda:

I moved the image allocations around, the amount of memory allocated is the same as before, and the kernel crash has apparently gone away.  I do not understand this.

Lee Holeva

Lee Holeva said:

SharedRegion Module already initialized!  <-- Could these be a problem? VPSS does this.

That "already initialized" message is a normal situation, no problem.

Lee Holeva said:

    No SharedRegion.entry[0].cacheEnable configuration value found, using defaul <-- I set cacheEnable=true in the .cfg file, problem?
t FALSE

The .cfg file setting is for the DSP or M3 perspective.  In order to change the ARM-side cacheing policy for the SharedRegion you need to add a setting there.

You're using SysLink 2.00.01.79, right?  You can set a Linux environment variable named SL_PARAMS to contain a string that configures the ARM-side cacheing of a SharedRegion:
    % export SL_PARAMS="SharedRegion.entry[0].cacheEnable=TRUE;"
Make sure you include the ';' within the string at the end.

Lee Holeva said:

llback: ProcMgr_Ipc_attach: Ipc_procSyncStart failed! <--  What is this?

That's normal, Ipc_attach() is meant to spin until the sync is established.  Subsequent activity shows that it eventually passed.

Lee Holeva said:

 remote event nu    NameServer_getLocal name [MSGQ_ROIN]
mber 10 with Not    NameServer_getLocal: Entry not found! <-- problem?

I'm not sure if that's a problem or not.  I'll look more into this. 

Lee Holeva said:

Here's something to ponder:  I have two threads running on the ARM, both of which communicate to Syslink.  Could Syslink hic-up if it simultaneously receives either a pair of notifications or message puts?  In other words, is Syslink a mutually exculsive resourse?

SysLink is designed to handle multiple threads simultaneously.  However, there are certain things that only one thread, the startup/shutdown thread, should do.

I agree that there's a race going on here.  One thing that would help is to separate your application output and the SysLink kernel module output.  You are running your app from the system console, where the kernel module output also goes.  Please try running your application from a different terminal than the console.  That way, the syslink.ko output won't get all interspersed with the application output.

Regards,

- Rob

Robert Tivy said:

I agree that there's a race going on here.  One thing that would help is to separate your application output and the SysLink kernel module output.  You are running your app from the system console, where the kernel module output also goes.  Please try running your application from a different terminal than the console.  That way, the syslink.ko output won't get all interspersed with the application output.

I'm not sure how to separate the output as I am running on Tera Term in Windows feeding from the EVM's serial port output.

I added some new code on both the host and DSP sides and now the kernel crash is happening from MessageQ_alloc():

shared region 0:
base addr = 0x    HeapMemMP_create knl ioctl: Shared addr [0x0]

41b46000
length = 0x4000000 bytes
owner = 3
Is Valid = 1
name = (null)
Heap totalsize = 0x3fff980 bytes, totalfreesize = 0x3ffcf00 bytes, largestfreesi
ze = 0x3ffcf00 bytes

shared region 1:
base addr = 0x45b91000
le    NotifyDriverShm_registerEvent
        Added entry in regChart: [2]

ngth = 0x1000000    NameServer_getLocal name [MSGQ_PREPROCESSINGIN]
0 bytes
owner =    NameServer_getLocal: Entry not found!
 3
Is Valid = 1   ISR handled

name = (null)    MessageQ_open ioctl queueId [0x2]

Heap totalsize    ISR handled
= 0xfffff80 byte    NameServer_getLocal name [normalizeGate]
s, totalfreesize = 0xfffff80 bytes, largestfreesize = 0xfffff80 bytes

Using the following message queues:
MSGQ_PREPROCESSINGIN
MSGQ_CORNERIN
MSGQ_ROIN
Creating the heap
Registering heapId 0 with MessageQ for procId: 0
Copying input image to region 0
Creating the normalization gate
Creating the GateMP
NORM: Allocating 58200 bytes in region 0
Registering the Normalization task
Registered remote event number 10 with Notify module for processor 0
Size of theMsg = 104

Normalizing the image
Opening the DSP's message queue for task 10
MessageQ_open Status 0 : procId [0]
MessageQApp_queueId  [0x2] : proc   ISR handled
Id [0]
Allocating 136 bytes of     NotifyDriverShm_registerEvent
        Added entry in regChart: [2]

memory for the m    NameServer_getLocal name [MSGQ_ROIN]
essage
Putting     NameServer_getLocal: Entry not found!
the taskId into    ISR handled
the message
Sen    NotifyDriverShm_registerEvent
        Added entry in regChart: [2]

ding a message t    NameServer_getLocal name [MSGQ_CORNERIN]
o the DSP for ta    NameServer_getLocal: Entry not found!
sk 10
Sending t    MessageQ_open ioctl queueId [0x0]
askId 10 to the    ISR handled
DSP
completed t    MessageQ_open ioctl queueId [0x1]
ask 10 from processor 0 with payload 333
Freeing message for task 10
Corners: Allocating b0400 bytes in region 1
Ro: Allocating 160800 bytes in region 1
HCONV: Allocating 0xb0400 bytes in region 1
VCONV: Allocating 0xb0400 bytes in region 1
Registered remote event number 15 with Notify module for processor 0

Calculating the Horizontal convolution
Opening the DSP's message queue for task 15
HNC: Allocating 0xb0400 bytes in region 1
VNC: Allocating 0xb0400 bytes in region 1
Registered remote event number 12 with Notify module for processor 0

Calculating the Horizontal cross-correlation
Opening the DSP's message queue for task 12
MessageQ_open Status 0 : procId [0]
MessageQApp_queueId  [0x0] : procId [0]
Allocating 172 bytes of memory for the message
Putting the taskId into the message
Sending a message to the DSP for task 15
Sending taskId 15 to the DSP
MessageQ_open Status 0 : procId [0]
MessageQApp_queueId  [0x1] : procId [0]
Allocating 136 bytes of memory for the message
Putting the taskId into the message
Sending a message to the DSP for task 12
Sending taskId 12 to the DSP
   ISR handled
completed task 15 from processor 0 with payload 333
Freeing message for task 15
    NotifyDriverShm_registerEvent
        Added entry in regChart: [3]

Registered remot    NameServer_getLocal name [MSGQ_ROIN]
e event number 1    NameServer_getLocal: Entry not found!
6 with Notify mo   ISR handled
dule for process    MessageQ_open ioctl queueId [0x0]
or 0

Calculat*** HeapMemMP_alloc: remainSize is not a multiple of obj->minAlign!                               <---- Something significant?  I allocated 4096 bytes to Heap 0.
 Error [0xffffffff] at Line no: 1186 in file /home/lholeva/ti-ezsdk_dm816
x-evm_5_01_01_80/syslink_2_00_01_79/packages/ti/syslink/utils/hlos/knl/Linux/../
../../../../../ti/syslink/ipc/hlos/knl/HeapMemMP.c
ing the Vertical*** Memory_alloc: IHeap_alloc failed!
 Error [0x8c97e001] at Line no: 156 in file /home/lholeva/ti-ezsdk_dm816x
-evm_5_01_01_80/syslink_2_00_01_79/packages/ti/syslink/utils/hlos/knl/Linux/../.
./../../../../ti/syslink/utils/hlos/Memory.c
 convolution
Op*** MessageQ_alloc: Message allocation failed!
 Error [0xfffffffd] at Line no: 1291 in file /home/lholeva/ti-ezsdk_dm816
x-evm_5_01_01_80/syslink_2_00_01_79/packages/ti/syslink/utils/hlos/knl/Linux/../
../../../../../ti/syslink/ipc/hlos/knl/MessageQ.c
ening the DSP's message queue for task 16
MessageQ_open Status 0 : procId [0]
MessageQApp_queueId  [0x0] : procId [0]
Allocating 172 bytes of memory for the message
Error: MessageQ_alloc failed to allocate 0xac bytes for the message in Heap 0
Sending taskId 16 to the DSP
   ISR handled
completed task 1Unable to handle kernel paging request at virtual address 14a3d3
10
2 from processorpgd = cabfc000
 0 with payload [14a3d310] *pgd=00000000333
Freeing mes
sage for task 12Internal error: Oops: 5 [#1]
last sysfs file: /sys/devices/platform/musb-ti81xx.0/musb-hdrc.0/usb1/1-1/devnum
Modules linked in: syslink bufferclass_ti pvrsrvkm TI81xx_hdmi ipv6 [last unload
ed: syslink]
CPU: 0    Not tainted  (2.6.37 #1)
PC is at HeapMemMP_free+0x238/0x3f8 [syslink]
LR is at SharedRegion_getPtr+0x134/0x164 [syslink]
pc : [<bf2515b4>]    lr : [<bf237a94>]    psr: 60000013
sp : c8941e28  ip : 00030101  fp : c8941e5c
r10: 00000100  r9 : 00000000  r8 : d7003380
r7 : 14a3d30c  r6 : d657e000  r5 : d7003280  r4 : 14a3d30c
r3 : 00000000  r2 : 14a3d30c  r1 : 00060000  r0 : 14a3d30c
Flags: nZCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
Control: 10c5387d  Table: 8abfc019  DAC: 00000015
Process track (pid: 1131, stack limit = 0xc89402e8)
Stack: (0xc8941e28 to 0xc8942000)
1e20:                   d7003280 00000088 00000000 d657b000 d7003280 00000088
1e40: 00000013 5638fc90 c8940000 00000000 c8941e84 c8941e60 bf229e14 bf251388
1e60: d7003280 00000088 c8941e84 00000000 c018f35b 5638fc90 c8941ea4 c8941e88
1e80: bf23efc0 bf229d60 5638fc90 00000013 5638fc90 c8940000 c8941ef4 c8941ea8
1ea0: bf2817c4 bf23eddc c018f35b 5638fc90 00003280 00000000 ffffffff 5638fcac
1ec0: 5638fcf4 0000b850 c8941ef4 c8941ed8 c01b2fb4 c005c0b8 ccb6d558 00000000
1ee0: ca8b2c00 00000013 c8941f04 c8941ef8 c00c49b8 bf281630 c8941f74 c8941f08
1f00: c00c50c8 c00c499c 400bc000 cbc44900 c01afa44 ccaf7a40 4de65624 1c9c3800
1f20: 0009bddc cbc44900 400bc000 c8941f70 0000001c 400bc000 c8940000 00000000
1f40: 00000001 0000001c 00000000 00000000 5638fc90 c018f35b 00000013 ca8b2c00
1f60: c8940000 00000000 c8941fa4 c8941f78 c00c5160 c00c4bd4 c8941fac 00000001
1f80: 0009bddc 563904d8 56390490 400c4550 00000036 c003ff48 00000000 c8941fa8
1fa0: c003fda0 c00c5114 563904d8 56390490 00000013 c018f35b 5638fc90 00000013
1fc0: 563904d8 56390490 400c4550 00000036 003d0f00 400d03d8 00000000 5638fc7c
1fe0: 00000152 5638fc60 00037f80 40384aec 20000010 00000013 16013202 0000012b
Backtrace:
[<bf25137c>] (HeapMemMP_free+0x0/0x3f8 [syslink]) from [<bf229e14>] (Memory_free
+0xc0/0x100 [syslink])
[<bf229d54>] (Memory_free+0x0/0x100 [syslink]) from [<bf23efc0>] (MessageQ_free+
0x1f0/0x250 [syslink])
 r6:5638fc90 r5:c018f35b r4:00000000
[<bf23edd0>] (MessageQ_free+0x0/0x250 [syslink]) from [<bf2817c4>] (MessageQDrv_
ioctl+0x1a0/0x6b8 [syslink])
 r4:c8940000
[<bf281624>] (MessageQDrv_ioctl+0x0/0x6b8 [syslink]) from [<c00c49b8>] (vfs_ioct
l+0x28/0x44)
 r6:00000013 r5:ca8b2c00 r4:00000000
[<c00c4990>] (vfs_ioctl+0x0/0x44) from [<c00c50c8>] (do_vfs_ioctl+0x500/0x540)
[<c00c4bc8>] (do_vfs_ioctl+0x0/0x540) from [<c00c5160>] (sys_ioctl+0x58/0x7c)
[<c00c5108>] (sys_ioctl+0x0/0x7c) from [<c003fda0>] (ret_fast_syscall+0x0/0x30)
 r8:c003ff48 r7:00000036 r6:400c4550 r5:56390490 r4:563904d8
Code: e3a01008 e30f2fff e3a03001 ebff5b85 (e5943004)

Perhaps this offers a bit more to go on.

 TRACEENTER=1 now gives something:

MessageQ_open StEntered MessageQDrv_ioctl
 filp [0xcb676a80]
 cmd [0xc018f35a]
 args [0x56105c8c]
atus 0 : procId Entered MessageQ_alloc
 heapId [0x0]
 size [0x88]
[0]
MessageQAppEntered Memory_alloc
 heap [0xd657b000]
 size [0x88]
 align [0x0]
 eb [0x0]
_queueId  [0x0] Entered HeapMemMP_alloc
 handle [0xd657b000]
 reqSize [0x88]
 reqAlign [0x4]
: procId [0]
AlEntered GateMP_enter
 obj [0xd64f8000]
locating 136 bytEntered GateMutex_enter
 gmHandle [0xd5617000]
es of memory forEntered OsalMutex_enter
 mutexHandle [0xd561a000]
 the message
Leaving OsalMutex_enter
Leaving GateMutex_enter
 key [0x0]
Leaving GateMP_enter
 key [0x0]
Entered SharedRegion_getPtr
 srPtr [0x3180]
Leaving SharedRegion_getPtr
 returnPtr [0xd7003180]
*** HeapMemMP_alloc: remainSize is not a multiple of obj->minAlign!
 Error [0xffffffff] at Line no: 1186 in file /home/lholeva/ti-ezsdk_dm816
x-evm_5_01_01_80/syslink_2_00_01_79/packages/ti/syslink/utils/hlos/knl/Linux/../
../../../../../ti/syslink/ipc/hlos/knl/HeapMemMP.c
Entered GateMP_leave
 obj [0xd64f8000]
 key [0x0]
Entered GateMutex_leave
 gmHandle [0xd5617000]
Entered OsalMutex_leave
 mutexHandle [0xd561a000]
 key [0x0]
Leaving OsalMutex_leave
Leaving GateMutex_leave
Leaving GateMP_leave
Leaving HeapMemMP_alloc
 allocAddr [0x0]
*** Memory_alloc: IHeap_alloc failed!
 Error [0x8c97e001] at Line no: 156 in file /home/lholeva/ti-ezsdk_dm816x
-evm_5_01_01_80/syslink_2_00_01_79/packages/ti/syslink/utils/hlos/knl/Linux/../.
./../../../../ti/syslink/utils/hlos/Memory.c
Leaving Memory_alloc
 buffer [0x0]
*** MessageQ_alloc: Message allocation failed!
 Error [0xfffffffd] at Line no: 1291 in file /home/lholeva/ti-ezsdk_dm816
x-evm_5_01_01_80/syslink_2_00_01_79/packages/ti/syslink/utils/hlos/knl/Linux/../
../../../../../ti/syslink/ipc/hlos/knl/MessageQ.c
Leaving MessageQ_alloc
 msg [0x0]
Leaving MessageQDrv_ioctl
 osStatus [0x0]
Error: MessageQ_Entered NotifyDrv_ioctl
 filp [0xcb676a00]
 cmd [0xc014f356]
 args [0x56105c94]
alloc failed to Entered Notify_sendEvent
 procId [0x0]
 lineId [0x0]
 eventId [0xd]
 payload [0x0]
 waitClear [0x1]
allocate 0x88 byEntered MultiProc_getNumProcessors
tes for the messLeaving MultiProc_getNumProcessors
 MultiProc_module->cfg.numProcessors [0x4]
age in Heap 0
SEntered MultiProc_getNumProcessors
ending taskId 13Leaving MultiProc_getNumProcessors
 MultiProc_module->cfg.numProcessors [0x4]
 to the DSP
Entered MultiProc_self
Leaving MultiProc_self
 MultiProc_module->id [0x3]

Lee Holeva

Lee Holeva said:

I'm not sure how to separate the output as I am running on Tera Term in Windows feeding from the EVM's serial port output.

There are a couple of ways to separate the output.  My preferred approach is simply to not use the console login (i.e., TeraTerm) at all, and do all my work from a separate telnet window, assuming you connect your board to a LAN.  putty.exe is a good free telnet client, and you can obtain your boards IP address with "% ifconfig".

The other way to separate it is to redirect your application's stdout and stderr to a file, but that might not be feasible if your application needs any keypress from stdin (I've seen that your app does have getchar() calls that require stdin).  FYI, to redirect stdout and stderr to the same file using a "bash"-like shell:
    % ./app <app_arguments> ... > app_output 2>&1
where "> app_output" redirects stdout to app_output, and "2>&1" redirects stderr (file handle 2) to stdout (file handle 1, which has already been associated with app_output).

Lee Holeva said:

HeapMemMP_alloc: remainSize is not a multiple of obj->minAlign!                               <---- Something significant?  I allocated 4096 bytes to Heap 0.

This seems like an internal error, meaning it should never happen (and probably should be an assertion instead of a basic failure).  HeapMemMP is supposed to, internally, adjust all allocation sizes to the next higher multiple of minAlign (which is set to the cache line size of the ARM, which is 0x80), and is supposed to adjust the 'align' parameter of HeapMemMP_alloc() to the next higher multiple of minAlign.  For your failed allocation, TRACEENTER=1 has informed us that it is for 0x88 bytes aligned to 0x4, which means that internally HeapMemMP_alloc(0x88, 0x4) effectively becomes HeapMemMP_alloc(0x100, 0x80).  However, as long as the original heap size was assured to be a multiple of minAlign, and the internal alignments/padding are followed as stated here, this error should never happen.

FYI, in case you were wondering, this internal alignment/padding is done for the following reason.  All MP-based allocations should be a multiple of 0x80 (or whatever the cache line size is), in order to avoid having cache line operations affect unrelated data.  A given piece of data should completely occupy cache lines.  The only way to guarantee that is to align the allocation to a cache line size boundary and have the allocation size be a multiple of the cache line size.

At this point I'm not sure it will help to separate syslink.ko TRACE output from your application output, since I can literally read between the lines (or, read between the characters), but it wouldn't hurt to see it in a cleaner, separated form, if you could give that a shot.

Regards,

- Rob

If I put the EVM on the company LAN than I would also have to do NFS over the company LAN as well, our IT people may object to me doing that.  Presently I have the EVM isolated by using a separate ethernet port and a cross-over cable.

In the mean time, would a potential work-around be to insure that message sizes are always a multiple of 0x80?

Lee Holeva

Lee Holeva said:

In the mean time, would a potential work-around be to insure that message sizes are always a multiple of 0x80?

I tried doing this and nothing changed, I still get the random occurance of a kernel crash upon MessageQ_alloc().

Update:

Again, I move code around and the kernel crash has apparently gone away.  I do see one of my images in shared memory getting over-written, that could be something that I'm doing. 

Another thing is that I do not have a good place in the DSP code to put Ipc_stop().  The way the software architecture is setup only the host knows when to stop.  Can I call Ipc_stop from the host?  I had the host do a notify for Ipc-stop(), but that is awkward and I have to waste cycles looping a task that is doing nothing else.

Lee Holeva

Lee Holeva said:

If I put the EVM on the company LAN than I would also have to do NFS over the company LAN as well, our IT people may object to me doing that.  Presently I have the EVM isolated by using a separate ethernet port and a cross-over cable.

If you have just a private "LAN" between your board and PC then you still should be able to telnet to the board from your PC.

Regards,

- Rob

Lee Holeva said:

Again, I move code around and the kernel crash has apparently gone away.  I do see one of my images in shared memory getting over-written, that could be something that I'm doing. 

Interesting, might be a cache issue, just a guess.

Lee Holeva said:

Another thing is that I do not have a good place in the DSP code to put Ipc_stop().  The way the software architecture is setup only the host knows when to stop.  Can I call Ipc_stop from the host?  I had the host do a notify for Ipc-stop(), but that is awkward and I have to waste cycles looping a task that is doing nothing else.

It is suggested that the DSP code have a startup and shutdown phase, where the shutdown phase is initiated by the host, through some Ipc mechanism such as Notify or MessageQ.  You could have a shutdown task that just waits on a special MessageQ which the host will write when it's ready to shutdown.  By calling MessageQ_get() with no timeout, this task will not consume any cycles since it will be blocked until the shutdown message is received.

There's more to a DSP shutdown phase than just calling Ipc_stop().  Since shared resources are being utilized by both the host and DSP, these resources need to be closed/deleted by their respective opener/creator, e.g., if a HeapMemMP is created by the host and opened by the DSP, the DSP needs to close it before the host can delete it.  This shared relationship dictates some sort of handshaking for this shutdown phase, so each side knows it's ready to proceed with the next stage of the shutdown phase, including one final handshake that indicates that each side can now safely call Ipc_stop().

TI needs to come up with an example illustrating this model to users, and I've heard that there is one floating around.  I'll try to dig it up for you.

Regards,

- Rob

Robert Tivy said:

It is suggested that the DSP code have a startup and shutdown phase, where the shutdown phase is initiated by the host, through some Ipc mechanism such as Notify or MessageQ.  You could have a shutdown task that just waits on a special MessageQ which the host will write when it's ready to shutdown.  By calling MessageQ_get() with no timeout, this task will not consume any cycles since it will be blocked until the shutdown message is received.

It's doing it again.  I added a task to do Ipc_stop(), blocking on MessageQ_get().  The heap Id registration is getting lost:

NameServer_getLocal name [MSGQ_IPCSTOPIN]
    NameServer_getLocal: Entry not found!
   ISR handled
    MessageQ_open ioctl queueId [0x1]
*** MessageQ_alloc: Heap id is not registered with MessageQ!
 Error [0xfffffff2] at Line no: 1276 in file /home/lholeva/ti-ezsdk_dm816
x-evm_5_01_01_80/syslink_2_00_01_79/packages/ti/syslink/utils/hlos/knl/Linux/../
../../../../../ti/syslink/ipc/hlos/knl/MessageQ.c
    ProcMgr_getProcInfo: bootMode: [0]
ElfLoader_getSymbolAddress: symName [_Ipc_ResetVector]

I confrimed that I am giving MessageQ_alloc() the correct heap Id = 0.

Using TRACEENTER=1 i GET:

Entered MessageQDrv_ioctl
 filp [0xcb366f80]
 cmd [0xc018f35a]
 args [0xbe8a16f4]
Entered MessageQ_alloc
 heapId [0x0]
 size [0x20]
*** MessageQ_alloc: Heap id is not registered with MessageQ!
 Error [0xfffffff2] at Line no: 1276 in file /home/lholeva/ti-ezsdk_dm816
x-evm_5_01_01_80/syslink_2_00_01_79/packages/ti/syslink/utils/hlos/knl/Linux/../
../../../../../ti/syslink/ipc/hlos/knl/MessageQ.c
Leaving MessageQ_alloc
 msg [0x0]
Leaving MessageQDrv_ioctl
 osStatus [0x0]

 Update:

As i change the code, the error changes as well.  I think I saw this before:

    NameServer_getLocal name [MSGQ_CORNERIN]
    NameServer_getLocal: Entry not found!
   ISR handled
    MessageQ_open ioctl queueId [0x0]
   ISR handled
    NotifyDriverShm_registerEvent
        Added entry in regChart: [2]

    NameServer_getLocal name [MSGQ_CORNERIN]
    NameServer_getLocal: Entry not found!
   ISR handled
    MessageQ_open ioctl queueId [0x0]
*** HeapMemMP_alloc: remainSize is not a multiple of obj->minAlign!
 Error [0xffffffff] at Line no: 1186 in file /home/lholeva/ti-ezsdk_dm816
x-evm_5_01_01_80/syslink_2_00_01_79/packages/ti/syslink/utils/hlos/knl/Linux/../
../../../../../ti/syslink/ipc/hlos/knl/HeapMemMP.c
*** Memory_alloc: IHeap_alloc failed!
 Error [0x8c97e001] at Line no: 156 in file /home/lholeva/ti-ezsdk_dm816x
-evm_5_01_01_80/syslink_2_00_01_79/packages/ti/syslink/utils/hlos/knl/Linux/../.
./../../../../ti/syslink/utils/hlos/Memory.c
*** MessageQ_alloc: Message allocation failed!
 Error [0xfffffffd] at Line no: 1291 in file /home/lholeva/ti-ezsdk_dm816
x-evm_5_01_01_80/syslink_2_00_01_79/packages/ti/syslink/utils/hlos/knl/Linux/../
../../../../../ti/syslink/ipc/hlos/knl/MessageQ.c

Lee Holeva

Added a bit more code and the Linux Oops is back:

Unable to handle kernel paging request at virtual address 0f3d
ffc0
pgd = cb710000
[0f3dffc0] *pgd=00000000
Internal error: Oops: 805 [#1]
last sysfs file: /sys/devices/platform/musb-ti81xx.0/musb-hdrc.0/usb1/1-1/devnum
Modules linked in: bufferclass_ti pvrsrvkm TI81xx_hdmi ti81xxfb vpss syslink ipv
6
CPU: 0    Not tainted  (2.6.37 #1)
PC is at v7_dma_inv_range+0x20/0x48
LR is at Cache_inv+0x50/0x78 [syslink]
pc : [<c0048dc8>]    lr : [<bf07241c>]    psr: 00000013
sp : ccb35e30  ip : 00000000  fp : ccb35e5c
r10: 00058200  r9 : 00000000  r8 : db529f00
r7 : 0f3dfffd  r6 : bf145cb4  r5 : 0f3dfffd  r4 : 00000008
r3 : 0000003f  r2 : 00000040  r1 : 0f3e0005  r0 : 0f3dffc0
Flags: nzcv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
Control: 10c5387d  Table: 8b710019  DAC: 00000015
Process track (pid: 1083, stack limit = 0xccb342e8)
Stack: (0xccb35e30 to 0xccb36000)
5e20:                                     00000008 0000ffff 00000001 bf0726dc
5e40: bf096c58 0f3dfffd db4d1d00 d55f3000 ccb35e94 ccb35e60 bf09b5b4 bf0723d8
5e60: db4d1d00 00058200 ccb35e94 00000000 c01cf35a 5613fc6c 00000017 5613fc6c
5e80: ccb34000 00000000 ccb35ef4 ccb35e98 bf0d16c8 bf09b388 c01cf35a 5613fc6c
5ea0: 0000b28c d55f0000 404d1d00 00058200 00060000 00000000 5613fccc 000114c4
5ec0: 5613fce4 00000000 ccb35ef4 00000000 cb696b80 d55f0000 00000000 00000000
5ee0: cb696e00 00000017 ccb35f04 ccb35ef8 c00c49b8 bf0d153c ccb35f74 ccb35f08
5f00: c00c50c8 c00c499c 4007f000 cbdc7980 c01afa44 cbdcd2c0 4de65b4b 1d34ce81
5f20: 0009bef4 cbdc7980 4007f000 ccb35f70 0000001c 4007f000 ccb34000 00000000
5f40: 00000001 0000001c 00000001 00000000 5613fc6c c01cf35a 00000017 cb696e00
5f60: ccb34000 00000000 ccb35fa4 ccb35f78 c00c5160 c00c4bd4 ccb35fa4 00000001
5f80: 0009bef4 5613fd20 56140490 400d8550 00000036 c003ff48 00000000 ccb35fa8
5fa0: c003fda0 c00c5114 5613fd20 56140490 00000017 c01cf35a 5613fc6c 00000017
5fc0: 5613fd20 56140490 400d8550 00000036 003d0f00 400e43d8 00000000 5613fc4c
5fe0: 00000152 5613fc30 0003a150 403c1aec 20000010 00000017 00000000 00000000
Backtrace:
[<bf0723cc>] (Cache_inv+0x0/0x78 [syslink]) from [<bf09b5b4>] (HeapMemMP_free+0x
238/0x3f8 [syslink])
 r6:d55f3000 r5:db4d1d00 r4:0f3dfffd
[<bf09b37c>] (HeapMemMP_free+0x0/0x3f8 [syslink]) from [<bf0d16c8>] (HeapMemMPDr
v_ioctl+0x198/0x77c [syslink])
[<bf0d1530>] (HeapMemMPDrv_ioctl+0x0/0x77c [syslink]) from [<c00c49b8>] (vfs_ioc
tl+0x28/0x44)
 r6:00000017 r5:cb696e00 r4:00000000
[<c00c4990>] (vfs_ioctl+0x0/0x44) from [<c00c50c8>] (do_vfs_ioctl+0x500/0x540)
[<c00c4bc8>] (do_vfs_ioctl+0x0/0x540) from [<c00c5160>] (sys_ioctl+0x58/0x7c)
[<c00c5108>] (sys_ioctl+0x0/0x7c) from [<c003fda0>] (ret_fast_syscall+0x0/0x30)
 r8:c003ff48 r7:00000036 r6:400d8550 r5:56140490 r4:5613fd20
Code: e1a02312 e2423001 e1100003 e1c00003 (1e070f3e)
---[ end trace 1b30fea48b1b5372 ]---

Lee Holeva