Debugging Engine_open

Flamingo

My Engine_open hangs in SEM_pend:

backtrace =

#0 0x40031fe4 in __new_sem_wait (sem=0x4e1d8)
at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:48
#1 0x00018c58 in Sem_pend ()
#2 0x00012ed4 in doCmd ()
#3 0x000143b4 in Processor_create ()
#4 0x00010710 in Engine_open ()
#5 0x0000a284 in smain (argc=1, argv=0xbe82bdf4) at app.c:110
#6 0x0000a044 in main (argc=1, argv=0xbe82bdf4) at main_native.c:34

I tried putting a breakpoint in putReply, but the breakpoint is never reached. (Thus explaining why the Engine_open hangs at the SEM_pend.) A partial debug trace output follows:

@1,195,750us: [+2 T:0x4001cf50] mycompany.z2_apps.vqm_results - main> mycompany.z2_apps.vqm_results
@3,196,174us: [+1 T:0x4001cf50] mycompany.z2_apps.vqm_results - App-> Application started with engineName = vqm_results and codecName = vqm_results
@5,196,564us: [+1 T:0x4001cf50] mycompany.z2_apps.vqm_results - App-> name: vqm_results, algTab: 0x4cb3c, remoteName: vqm_results_server.x674, linkCfg: (null), numAlgs = 1
@5,196,854us: [+1 T:0x4001cf50] mycompany.z2_apps.vqm_results - App-> algTab: name = vqm_results, fxns = 0x4cbb8, typeTab = ti.sdo.ce.universal.IUNIVERSAL
@7,197,206us: [+0 T:0x4001cf50] CE - Engine_open> Enter('vqm_results', 0x0, 0xbe82bc1c)
@7,197,496us: [+0 T:0x4001cf50] CE - rserverOpen('vqm_results_server.x674'), count = 0
@7,197,666us: [+0 T:0x4001cf50] OP - Processor_create> Enter(imageName='vqm_results_server.x674', linkCfg='(null)', attrs=0xbe82bc00)
@7,198,925us: [+0 T:0x4001cf50] OP - doCmd> Enter (cmdId=1, proc=0x4e428)
@7,199,157us: [+0 T:0x4001cf50] ti.sdo.ce.osal.Sem - Entered Sem_post> sem[0x4e1c0]
@7,199,522us: [+0 T:0x4001cf50] ti.sdo.ce.osal.Sem - Leaving Sem_post> sem[0x4e1c0]
@7,199,714us: [+0 T:0x4001cf50] ti.sdo.ce.osal.Sem - Entered Sem_pend> sem[0x4e1d8] timeout[0xffffffff]

It is unclear to me which processor half (ARM9/DSP) is failing. I've seen hangs like this while loading, starting, attaching, etc. All in Engine_open. Any ideas how to debug this problem? I've tried increasing the size of my heaps and stacks every where I could find, but if you can think of one I might have missed, let me know.

over 16 years ago

0 janet over 16 years ago

TI__Mastermind 22760 points

Hi,

There is a daemon thread on the ARM side that is making calls to dsplink to load the DSP server and start the DSP. You're pending on a semaphore to wait for this thread to post the semaphore once the DSP has been started. You should see some more trace messages indicating that the daemon thread has gotten the command to do this. For example, you should see something like:

3051160 PID:41b0012 TID:4390012 @3053,695,000us: [+2 T:0x04390012] OP - Processor_create_d> Attaching to DSP PROC...

(The '_d' indicates that it is the daemon thread that output the trace message). Are you getting any trace from the daemon thread? If not, it may not be running for some reason.

Thanks,

Janet

0 Flamingo over 16 years ago in reply to janet

Expert 2290 points

I do see the daemon messages. That is how I'm guessing what "phase" the Engine_open call is hanging. That is, when I said that I saw hangs during load, start, attach, etc, those messages were from the daemon thread.

The Engine_open is working right now, and I'm hoping it continues to. If it hangs again, I'll post the full trace log.

Is there something that would cause the daemon to die silently?

0 janet over 16 years ago in reply to Flamingo

TI__Mastermind 22760 points

No. The daemon thread should not die until your app exits.

Regards,

Janet

0 Flamingo over 16 years ago in reply to janet

Expert 2290 points

A typical trace output follows. The previous version completed the Engine_open and ran through most of my _control functions. I was getting a bad parameter passed to one function, so I added 2 GT_ trace statements just before the call to check whether my inputs were okay. The build completed with no problems and I ran the code. There are about 10 calls to the _control function before I get to the call that would hit my new trace statements. The normal output is probably more than 1000 lines.

./app*
@0,989,874us: [+4 T:0x4001cf50] OG - Global_init> This program was built with the following packages:
@0,990,896us: [+4 T:0x4001cf50] OG -     package gnu.targets.arm.rtsv5T (/home/username/xdctools_3_10_03/packages/gnu/targets/arm/rtsv5T/) [1,0,0,0,1225517428507]
@0,991,169us: [+4 T:0x4001cf50] OG -     package mycompany.vqm_results (/home/username/serverexamples/mycompany/vqm_results/) [1,0,0,1249393776000]
@0,991,337us: [+4 T:0x4001cf50] OG -     package ti.sdo.ce.global (/home/username/OMAPL137_arm_1_00_00_07/codec_engine_2_22/packages/ti/sdo/ce/global/) [1,0,0,1232382539005]
@0,991,500us: [+4 T:0x4001cf50] OG -     package dsplink.gpp (/home/username/OMAPL137_arm_1_00_00_07/dsplink-1_61-prebuilt/packages/dsplink/gpp/) [5,0,0,1236093819000]
@0,991,655us: [+4 T:0x4001cf50] OG -     package ti.sdo.linuxutils.cmem (/home/username/OMAPL137_arm_1_00_00_07/framework_components_2_22_01/fctools/packages/ti/sdo/linuxutils/cmem/) [2,2,0,1233090301393]
@0,991,812us: [+4 T:0x4001cf50] OG -     package gnu.targets (/home/username/xdctools_3_10_03/packages/gnu/targets/) [1,0,1,1225517427930]
@0,991,958us: [+4 T:0x4001cf50] OG -     package gnu.targets.arm (/home/username/xdctools_3_10_03/packages/gnu/targets/arm/) [1,0,0,0,1225517428045]
@0,992,103us: [+4 T:0x4001cf50] OG -     package ti.sdo.utils.trace (/home/username/OMAPL137_arm_1_00_00_07/framework_components_2_22_01/packages/ti/sdo/utils/trace/) [1,0,0,1233266118323]
@0,992,254us: [+4 T:0x4001cf50] OG -     package ti.xdais.dm (/home/username/OMAPL137_arm_1_00_00_07/xdais_6_22_01/packages/ti/xdais/dm/) [1,0,5,1231972806824]
@0,992,402us: [+4 T:0x4001cf50] OG -     package ti.xdais (/home/username/OMAPL137_arm_1_00_00_07/xdais_6_22_01/packages/ti/xdais/) [1,2,1,1231972799069]
@0,992,548us: [+4 T:0x4001cf50] OG -     package ti.sdo.ce.utils.xdm (/home/username/OMAPL137_arm_1_00_00_07/codec_engine_2_22/packages/ti/sdo/ce/utils/xdm/) [1,0,2,1232382752733]
@0,992,700us: [+4 T:0x4001cf50] OG -     package ti.sdo.fc.global (/home/username/OMAPL137_arm_1_00_00_07/framework_components_2_22_01/packages/ti/sdo/fc/global/) [1,0,0,1233265934923]
@0,992,851us: [+4 T:0x4001cf50] OG -     package ti.sdo.fc.dman3 (/home/username/OMAPL137_arm_1_00_00_07/framework_components_2_22_01/packages/ti/sdo/fc/dman3/) [1,0,4,1233265902746]
@0,993,000us: [+4 T:0x4001cf50] OG -     package ti.sdo.fc.memutils (/home/username/OMAPL137_arm_1_00_00_07/framework_components_2_22_01/packages/ti/sdo/fc/memutils/) [1,0,0,1233266018513]
@0,993,251us: [+4 T:0x4001cf50] OG -     package ti.sdo.fc.acpy3 (/home/username/OMAPL137_arm_1_00_00_07/framework_components_2_22_01/packages/ti/sdo/fc/acpy3/) [1,0,4,1233265900565]
@0,993,415us: [+4 T:0x4001cf50] OG -     package ti.catalog.c470 (/home/username/xdctools_3_10_03/packages/ti/catalog/c470/) [1,0,1,0,0]
@0,993,564us: [+4 T:0x4001cf50] OG -     package ti.catalog.c6000 (/home/username/xdctools_3_10_03/packages/ti/catalog/c6000/) [1,0,0,0,0]
@0,993,784us: [+4 T:0x4001cf50] OG -     package ti.platforms.evmOMAPL137 (/home/username/bios_5_33_03/packages/ti/platforms/evmOMAPL137/) [1,0,0,0]
@0,993,945us: [+4 T:0x4001cf50] OG -     package ti.sdo.ce.osal (/home/username/OMAPL137_arm_1_00_00_07/codec_engine_2_22/packages/ti/sdo/ce/osal/) [2,0,2,1232382580470]
@0,994,096us: [+4 T:0x4001cf50] OG -     package ti.sdo.ce.osal.linux (/home/username/OMAPL137_arm_1_00_00_07/codec_engine_2_22/packages/ti/sdo/ce/osal/linux/) [2,0,1,1232382587024]
@0,994,248us: [+4 T:0x4001cf50] OG -     package ti.sdo.ce.ipc (/home/username/OMAPL137_arm_1_00_00_07/codec_engine_2_22/packages/ti/sdo/ce/ipc/) [2,0,1,1232382546088]
@0,994,396us: [+4 T:0x4001cf50] OG -     package ti.sdo.ce.ipc.dsplink (/home/username/OMAPL137_arm_1_00_00_07/codec_engine_2_22/packages/ti/sdo/ce/ipc/dsplink/) [2,0,1,1232382563989]
@0,994,544us: [+4 T:0x4001cf50] OG -     package ti.sdo.ce.alg (/home/username/OMAPL137_arm_1_00_00_07/codec_engine_2_22/packages/ti/sdo/ce/alg/) [1,0,1,1232382167587]
@0,994,695us: [+4 T:0x4001cf50] OG -     package ti.sdo.ce (/home/username/OMAPL137_arm_1_00_00_07/codec_engine_2_22/packages/ti/sdo/ce/) [1,0,6,1232382164585]
@1,459,796us: [+4 T:0x4001cf50] OG -     package ti.sdo.ce.universal (/home/username/OMAPL137_arm_1_00_00_07/codec_engine_2_22/packages/ti/sdo/ce/universal/) [1,0,0,1232382737413]
@1,460,010us: [+4 T:0x4001cf50] OG -     package mycompany.vqm_results.ce (/home/username/serverexamples/mycompany/vqm_results/ce/) [1,0,0,1249393781000]
@1,460,177us: [+4 T:0x4001cf50] OG -     package mycompany.z2_apps.vqm_results (/home/username/serverexamples/mycompany/z2_apps/vqm_results/) [1,0,0,1249393792000]
@1,461,302us: [+0 T:0x4001cf50] ti.sdo.ce.osal.Sem - Sem_create> count: 0
@1,461,637us: [+0 T:0x4001cf50] ti.sdo.ce.osal.Sem - Leaving Sem_create> sem[0x501c0]
@1,461,831us: [+0 T:0x4001cf50] ti.sdo.ce.osal.Sem - Sem_create> count: 0
@1,461,995us: [+0 T:0x4001cf50] ti.sdo.ce.osal.Sem - Leaving Sem_create> sem[0x501d8]
@1,462,169us: [+0 T:0x4001cf50] OT - Thread_create> Enter (fxn=0x14c64, attrs=0x0)
@1,463,049us: [+0 T:0x4001cf50] OT - Thread_create> Exit (task=0x50210)
@1,463,439us: [+0 T:0x4001cf50] ti.sdo.ce.alg - ALG_init> Enter
@1,463,635us: [+0 T:0x4001cf50] ti.sdo.ce.alg - ALG_init> Exit
@1,463,990us: [+6 T:0x4001cf50] CE - Engine_init> CE debugging on (CE_DEBUG=2; allowed CE_DEBUG levels: 1=min, 2=good, 3=max)
@1,464,318us: [+0 T:0x4001cf50] CS - Server_init()
@1,464,491us: [+0 T:0x4001cf50] CS - Server_init> Global_useLinkArbiter = 0
@1,464,729us: [+2 T:0x4001cf50] mycompany.z2_apps.vqm_results - main> mycompany.z2_apps.vqm_results
@1,464,897us: [+1 T:0x4001cf50] mycompany.z2_apps.vqm_results - App-> Application started with engineName = vqm_results and codecName = vqm_results
@1,465,199us: [+0 T:0x4001cf50] CE - Engine_open> Enter('vqm_results', 0x0, 0xbea77c24)
@1,465,411us: [+0 T:0x4001cf50] CE - rserverOpen('vqm_results_server.x674'), count = 0
@1,465,644us: [+0 T:0x4001cf50] OP - Processor_create> Enter(imageName='vqm_results_server.x674', linkCfg='(null)', attrs=0xbea77c08)
@1,467,065us: [+1 T:0x4095b490] OP - daemon> thread created.
@1,467,355us: [+0 T:0x4001cf50] OP - doCmd> Enter (cmdId=1, proc=0x50520)
@1,467,563us: [+0 T:0x4001cf50] ti.sdo.ce.osal.Sem - Entered Sem_post> sem[0x501c0]
@1,467,795us: [+0 T:0x4001cf50] ti.sdo.ce.osal.Sem - Leaving Sem_post> sem[0x501c0]
@1,468,011us: [+0 T:0x4001cf50] ti.sdo.ce.osal.Sem - Entered Sem_pend> sem[0x501d8] timeout[0xffffffff]
@1,468,291us: [+0 T:0x4095b490] OP - getCmd_d> Enter (proc=0x4095adf0)
@1,468,473us: [+0 T:0x4095b490] ti.sdo.ce.osal.Sem - Entered Sem_pend> sem[0x501c0] timeout[0xffffffff]
@1,468,634us: [+0 T:0x4095b490] ti.sdo.ce.osal.Sem - Leaving Sem_pend> sem[0x501c0] status[0]
@1,468,781us: [+0 T:0x4095b490] OP - getCmd_d> Exit (result=1)
@1,468,923us: [+0 T:0x4095b490] OP - Processor_create_d> Enter(proc=0x50520)
@1,469,068us: [+2 T:0x4095b490] OP - Processor_create_d> Initializing DSP PROC...
@1,469,229us: [+2 T:0x4095b490] OP - Processor_create_d> Using DspLink config data for entry #0 [server 'vqm_results_server.x674']
@1,469,685us: [+2 T:0x4095b490] OP - Processor_create_d> Adding DSP segment #0 to Link configuration: name='DDR2', startAddress=0xc2000000, sizeInBytes=0x1000000, shared=1, syncd=0
@1,469,917us: [+2 T:0x4095b490] OP - Processor_create_d> Adding DSP segment #1 to Link configuration: name='DSPLINKMEM', startAddress=0xc5001000, sizeInBytes=0xff000, shared=1, syncd=0
@1,470,112us: [+2 T:0x4095b490] OP - Processor_create_d> Adding DSP segment #2 to Link configuration: name='RESET_VECTOR', startAddress=0xc5000000, sizeInBytes=0x1000, shared=1, syncd=0
@1,470,299us: [+2 T:0x4095b490] OP - Processor_create_d> Adding DSP segment #3 to Link configuration: name='DDRALGHEAP', startAddress=0xc6000000, sizeInBytes=0x1000000, shared=0, syncd=0
@1,470,481us: [+2 T:0x4095b490] OP - Processor_create_d> DODSPCTRL was=1; now=1
Entered PROC_setup ()
    linkCfg    [0x4ef70]
Entered DRV_Initialize ()
    drvObj    [0x4fb38]
    arg    [0x0]
Leaving DRV_Initialize ()     status [0x8000]
Entered DRV_ProtectInit ()
    drvObj    [0x50630]
Leaving DRV_ProtectInit ()     status [0x8000]
Entered DRV_ProtectEnter ()
    drvObj    [0x50630]
Leaving DRV_ProtectEnter ()     status [0x8000]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x6c01]
    arg1    [0x4095ad80]
    arg2    [0x0]
Entered DRV_installCleanupRoutines ()
    linkCfgPtr    [0x4ef70]
Leaving DRV_installCleanupRoutines ()
osStatus: 0
Entered _POOL_init ()
Leaving _POOL_init ()
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Entered _MEM_USR_init ()
Leaving _MEM_USR_init ()     status [0x8000]
Entered _IDM_USR_init ()
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7351]
    arg1    [0x4095ad4c]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Leaving _IDM_USR_init ()     status [0x8000]
Entered _SYNC_USR_init ()
Entered _IDM_USR_create ()
    key    [0x10080]
    attrs    [0x4095ad54]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7353]
    arg1    [0x4095ad24]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Leaving _IDM_USR_create ()     status [0x8000]
Leaving _SYNC_USR_init ()     status [0x8000]
Entered _SYNC_USR_createCS ()
    idKey    [0x43750]
    csObj    [0x4fb40]
Entered _IDM_USR_acquireId ()
    key    [0x10080]
    idKey    [0x43750]
    id    [0x4095ad58]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7355]
    arg1    [0x4095ad24]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Leaving _IDM_USR_acquireId ()     status [0x8000]
Leaving _SYNC_USR_createCS ()     status [0x8000]
Entered DRV_ProtectLeave ()
    drvObj    [0x50630]
Leaving DRV_ProtectLeave ()     status [0x8000]
Entered PROC_resetCurStatus ()
Leaving PROC_resetCurStatus ()
Leaving PROC_setup ()     status [0x8000]
@1,822,370us: [+2 T:0x4095b490] OP - Processor_create_d> Attaching to DSP PROC...
Entered PROC_attach ()
    procId    [0x0]
    attr    [0x0]
Entered DRV_Initialize ()
    drvObj    [0x4fb38]
    arg    [0x0]
Entered _SYNC_USR_enterCS ()
    csObj    [0x50648]
Leaving _SYNC_USR_enterCS ()     status [0x8000]
Entered _SYNC_USR_leaveCS ()
    csObj    [0x50648]
Leaving _SYNC_USR_leaveCS ()     status [0x8000]
Leaving DRV_Initialize ()     status [0x8000]
Entered _SYNC_USR_enterCS ()
    csObj    [0x50648]
Leaving _SYNC_USR_enterCS ()     status [0x8000]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x6c08]
    arg1    [0x4095ad7c]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Entered _NOTIFY_init ()
    dspId    [0x0]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7301]
    arg1    [0x4095ad2c]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Leaving _NOTIFY_init ()     status [0x8000]
Entered _MPCS_init ()
    procId    [0x0]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7201]
    arg1    [0x4095ad40]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Entered _MPCS_open ()
    procId    [0x0]
    name    [0x40d54]
    mpcsHandle    [0x4f7c4]
    mpcsShObj    [0x4115c500]
Entered _MPCS_OS_open ()
    procId    [0x0]
    name    [0x40d54]
    mpcsHandle    [0x4f7c4]
    mpcsShObj    [0x4115c500]
Entered _MEM_USR_calloc ()
    ptr    [0x4f7c4]
    bytes    [0x10]
_MEM_USR_calloc *ptr [0x506f0]
Leaving _MEM_USR_calloc ()     status [0x8000]
Entered _SYNC_USR_createCS ()
    idKey    [0x40d54]
    csObj    [0x506f4]
Entered _IDM_USR_acquireId ()
    key    [0x10080]
    idKey    [0x40d54]
    id    [0x4095aca0]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7355]
    arg1    [0x4095ac6c]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Leaving _IDM_USR_acquireId ()     status [0x8000]
Leaving _SYNC_USR_createCS ()     status [0x8000]
Leaving _MPCS_OS_open ()     status [0x8000]
Leaving MPCS_open ()     status [0x8000]
Leaving _MPCS_init ()     status [0x8000]
Entered _MPLIST_moduleInit ()
    procId    [0x0]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7321]
    arg1    [0x4095ad28]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Entered MPCS_create ()
    procId    [0x0]
    name    [0x41628]
    mpcsShObj    [0x4001f700]
    attrs    [0x4095ad26]
Entered MPCS_enter ()
    mpcsHandle    [0x506f0]
Entered _SYNC_USR_enterCS ()
    csObj    [0x50708]
Leaving _SYNC_USR_enterCS ()     status [0x8000]
Leaving MPCS_enter ()     status [0x8000]
Entered MPCS_leave ()
    mpcsHandle    [0x506f0]
Entered _SYNC_USR_leaveCS ()
    csObj    [0x50708]
Leaving _SYNC_USR_leaveCS ()     status [0x8000]
Leaving MPCS_leave ()     status [0x8000]
Leaving MPCS_create ()     status [0x8000]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7322]
    arg1    [0x4095ad28]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Leaving _MPLIST_moduleInit ()     status [0x8000]
Entered _RingIO_moduleInit ()
    procId    [0x0]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7311]
    arg1    [0x4095ad28]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Entered MPCS_create ()
    procId    [0x0]
    name    [0x44058]
    mpcsShObj    [0x4001fe00]
    attrs    [0x4095ad26]
Entered MPCS_enter ()
    mpcsHandle    [0x506f0]
Entered _SYNC_USR_enterCS ()
    csObj    [0x50708]
Leaving _SYNC_USR_enterCS ()     status [0x8000]
Leaving MPCS_enter ()     status [0x8000]
Entered MPCS_leave ()
    mpcsHandle    [0x506f0]
Entered _SYNC_USR_leaveCS ()
    csObj    [0x50708]
Leaving _SYNC_USR_leaveCS ()     status [0x8000]
Leaving MPCS_leave ()     status [0x8000]
Leaving MPCS_create ()     status [0x8000]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7312]
    arg1    [0x4095ad28]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Leaving _RingIO_moduleInit ()     status [0x8100]
Entered _MPLIST_init ()
    procId    [0x0]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7321]
    arg1    [0x4095ad40]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Entered _MPCS_open ()
    procId    [0x0]
    name    [0x41628]
    mpcsHandle    [0x4f7e4]
    mpcsShObj    [0x4001f700]
Entered _MPCS_OS_open ()
    procId    [0x0]
    name    [0x41628]
    mpcsHandle    [0x4f7e4]
    mpcsShObj    [0x4001f700]
Entered _MEM_USR_calloc ()
    ptr    [0x4f7e4]
    bytes    [0x10]
_MEM_USR_calloc *ptr [0x50720]
Leaving _MEM_USR_calloc ()     status [0x8000]
Entered _SYNC_USR_createCS ()
    idKey    [0x41628]
    csObj    [0x50724]
Entered _IDM_USR_acquireId ()
    key    [0x10080]
    idKey    [0x41628]
    id    [0x4095aca0]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7355]
    arg1    [0x4095ac6c]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Leaving _IDM_USR_acquireId ()     status [0x8000]
Leaving _SYNC_USR_createCS ()     status [0x8000]
Leaving _MPCS_OS_open ()     status [0x8000]
Leaving MPCS_open ()     status [0x8000]
Leaving _MPLIST_init ()     status [0x8000]
Entered _RingIO_init ()
    procId    [0x0]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7311]
    arg1    [0x4095ad40]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Entered _MPCS_open ()
    procId    [0x0]
    name    [0x44058]
    mpcsHandle    [0x4fbf0]
    mpcsShObj    [0x41165e00]
Entered _MPCS_OS_open ()
    procId    [0x0]
    name    [0x44058]
    mpcsHandle    [0x4fbf0]
    mpcsShObj    [0x41165e00]
Entered _MEM_USR_calloc ()
    ptr    [0x4fbf0]
    bytes    [0x10]
_MEM_USR_calloc *ptr [0x50750]
Leaving _MEM_USR_calloc ()     status [0x8000]
Entered _SYNC_USR_createCS ()
    idKey    [0x44058]
    csObj    [0x50754]
Entered _IDM_USR_acquireId ()
    key    [0x10080]
    idKey    [0x44058]
    id    [0x4095aca0]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7355]
    arg1    [0x4095ac6c]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Leaving _IDM_USR_acquireId ()     status [0x8000]
Leaving _SYNC_USR_createCS ()     status [0x8000]
Leaving _MPCS_OS_open ()     status [0x8000]
Leaving MPCS_open ()     status [0x8000]
Leaving _RingIO_init ()     status [0x8100]
Entered _SYNC_USR_leaveCS ()
    csObj    [0x50648]
Leaving _SYNC_USR_leaveCS ()     status [0x8000]
Leaving PROC_attach ()     status [0x8000]
@2,186,120us: [+2 T:0x4095b490] OP - Processor_create_d> Opening MSGQ pool...
Entered POOL_open ()
    poolId    [0x0]
    params    [0x4ec10]
Entered _SYNC_USR_enterCS ()
    csObj    [0x50648]
Leaving _SYNC_USR_enterCS ()     status [0x8000]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x7101]
    arg1    [0x4095ad78]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Entered _SYNC_USR_leaveCS ()
    csObj    [0x50648]
Leaving _SYNC_USR_leaveCS ()     status [0x8000]
Leaving POOL_open ()     status [0x8000]
@2,188,229us: [+2 T:0x4095b490] OP - Processor_create_d> Loading vqm_results_server.x674 on DSP (1 args)...
Entered PROC_load ()
    procId    [0x0]
    imagePath    [0x39738]
    argc    [0x1]
    argv    [0xbea77c14]
Entered _SYNC_USR_enterCS ()
    csObj    [0x50648]
Leaving _SYNC_USR_enterCS ()     status [0x8000]
procId = 0
imagePath = vqm_results_server.x674
argc = 1
argv = vqm_results_server.x674
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x6c05]
    arg1    [0x4095ad7c]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
    DRV_Invoke: csObjExists = 1
    csObjExists = true
Entered _SYNC_USR_leaveCS ()
    csObj    [0x50648]
Leaving _SYNC_USR_leaveCS ()     status [0x8000]
    tmpStatus = 32768
Leaving PROC_load ()     status [0x8000]
@2,655,729us: [+2 T:0x4095b490] OP - Processor_create_d> Starting DSP PROC...
Entered PROC_start ()
    procId    [0x0]
Entered _SYNC_USR_enterCS ()
    csObj    [0x50648]
Leaving _SYNC_USR_enterCS ()     status [0x8000]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x6c03]
    arg1    [0x4095ad7c]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Entered _SYNC_USR_leaveCS ()
    csObj    [0x50648]
Leaving _SYNC_USR_leaveCS ()     status [0x8000]
Leaving PROC_start ()     status [0x8000]
@2,726,321us: [+2 T:0x4095b490] OP - Processor_create_d> Opening remote transport...
Entered MSGQ_transportOpen ()
    procId    [0x0]
    attrs    [0x4095adf6]
Entered _SYNC_USR_enterCS ()
    csObj    [0x50648]
Leaving _SYNC_USR_enterCS ()     status [0x8000]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x6f01]
    arg1    [0x4095ad7c]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Entered _SYNC_USR_leaveCS ()
    csObj    [0x50648]
Leaving _SYNC_USR_leaveCS ()     status [0x8000]
Leaving MSGQ_transportOpen ()     status [0x8000]
@2,728,868us: [+2 T:0x4095b490] OP - Processor_create_d> return (1)
@2,729,046us: [+0 T:0x4095b490] ti.sdo.ce.osal.Sem - Entered Sem_post> sem[0x501d8]
@2,729,436us: [+0 T:0x4001cf50] ti.sdo.ce.osal.Sem - Leaving Sem_pend> sem[0x501d8] status[0]
@2,729,656us: [+0 T:0x4001cf50] OP - doCmd> Exit (result=1)
@2,729,811us: [+0 T:0x4001cf50] OP - Processor_create> return (0x50520)
@2,729,970us: [+0 T:0x4001cf50] CE - rserverOpen('vqm_results_server.x674'): 0x4f650 done.
Entered MSGQ_open ()
    queueName    [0x50780]
    msgqQueue    [0x50500]
    attrs    [0x0]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x6f03]
    arg1    [0xbea77b98]
    arg2    [0x0]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Leaving MSGQ_open ()     status [0x8000]
Entered MSGQ_alloc ()
    poolId    [0x0]
    size    [0x1000]
    msg    [0x5050c]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x6f08]
    arg1    [0xbea77ba4]
    arg2    [0x0]
Entered _POOL_xltBuf ()
    poolId    [0x0]
    bufPtr    [0xbea77bac]
    xltFlag    [0x2]
Leaving _POOL_xltBuf ()     status [0x8000]
Status: 8000
Leaving DRV_Invoke
()     status [0x8000]
Leaving MSGQ_alloc ()     status [0x8000]
Entered MSGQ_locate ()
    queueName    [0x3b9cc]
    msgqQueue    [0x504fc]
    attrs    [0xbea77bc4]
Entered DRV_Invoke ()
    drvObj    [0x50630]
    cmdId    [0x6f05]
    arg1    [0xbea77b88]
    arg2    [0x0]
@2,734,172us: [+0 T:0x4095b490] ti.sdo.ce.osal.Sem - Leaving Sem_post> sem[0x501d8]
@2,734,421us: [+0 T:0x4095b490] OP - getCmd_d> Enter (proc=0x4095adf0)
@2,734,586us: [+0 T:0x4095b490] ti.sdo.ce.osal.Sem - Entered Sem_pend> sem[0x501c0] timeout[0xffffffff]

0 janet over 16 years ago in reply to Flamingo

TI__Mastermind 22760 points

From the trace output, it looks like the DSP server was loaded and started, and then the daemon thread is pending on a semaphore waiting to get another command (such as "DELETE"). Is there any more trace output from your main application thread? You can see the thread ID in the trace statements, in this example, 0x4095b490 is the daemon thread and 0x4001cf50 is your application thread. It's possible that the DSP has done something to cause the whole system to hang. With CE_DEBUG=2, you should also be seeing some trace from the DSP.

Regards,

Janet

0 Flamingo over 16 years ago in reply to janet

Expert 2290 points

What I posted was the full log, and that has trace turned on in dsplink too (obviously). As I said, before adding two trace calls, the whole thing worked fine. The previous version (which ran) included a stacksize report that shows that I've only used 11% of the available stack, so the two trace calls should not have caused the issue (even if they had ever executed). I'm no where close to the memory limits for ddr2.

When I back the calls out, it works again (except for the SEM_pend problems, and I can comment those out for now.)

0 janet over 16 years ago in reply to Flamingo

TI__Mastermind 22760 points

Did you make sure the GT object was initialized? For example, if I add trace to my application's main() function, I need to call GT_create() before calling GT_xtrace() functions. Here is how I have trace set up in my main.c file:

#include <ti/sdo/ce/trace/gt.h>

/* trace info: module name, mask */
#define MOD_NAME "ti.sdo.ce.test.engtest"
GT_Mask curMask = {0,0};

/*
* ======== main ========
*/
Int main(Int argc, String argv[])
{

   ...
    /* create a mask to allow a trace-print welcome message below */
    GT_create(&curMask, MOD_NAME);

/* Enable all trace for this module */
GT_set(MOD_NAME "=01234567");

GT_0trace(curMask, GT_2CLASS, "main> " MOD_NAME "\n");

...

}

0 Flamingo over 16 years ago in reply to janet

Expert 2290 points

Yes (although I have made that mistake in the past). As I said, when I leave the new statements out, everything sort of works, including hundreds of trace output lines, including those in the same function using the same mask. In fact (and here's the weird part), I'm having problems with a SEM_pend call hanging (not timing out when I expect it to). If I comment that SEM_pend (now SEM_pendBinary) call out, then I hang as shown. When I put it back, I can actually get the Engine to open and the new debug trace output works (although I hang on Engine_delete then). Please bear in mind that I am hanging before I get to execute this function. I know because I have more than 2000 lines of trace output that occur when the code runs normally. I have embedded usleep calls in my app-side code to pace the output. When I get this hang, it happens so fast that none of the usleep calls could have occurred.

If it happens again (if I get disgusted and take the SEM_pendBinary call out), I'll have that check=TRUE turned on. Maybe that will help.

Processors

Processors forum

Debugging Engine_open