• State
  • Locked Locked
  • Replies 2 replies
  • Subscribers 97 subscribers
  • Views 405 views
  • Users 0 members are here
Support feedback
Options
Options
Related

This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

Trouble on 128th restart of codec

chris2476
Intellectual 310 points

I am working with a DM6446, dvevm_1_20, codec_engine_1_10_01.  I am trying to restart (delete and create) a codec many times for stress testing.  It keeps failing on the 128th restart.  For successful restarts, I see a log like this:

[DSP] @0x78dbcd78:[T:0x8fb3b244] CR - processRmsCmd(0x8fe01928, 4056): cmd = 0
[DSP] @0x78dbcdbf:[T:0x8fb3b244] OM - Memory_alloc> Enter(size=0x18)
[DSP] @0x78dbcdf7:[T:0x8fb3b244] OM - Memory_alloc> return (0x8fb42b68)
[DSP] @0x78dbce30:[T:0x8fb3b244] OM - Memory_alloc> Enter(size=0xf)
[DSP] @0x78dbce62:[T:0x8fb3b244] OM - Memory_alloc> return (0x8fb42b80)
[DSP] @0x78dbce9d:[T:0x8fb3b244] OM - Memory_alloc> Enter(size=0x20)
[DSP] @0x78dbced0:[T:0x8fb3b244] OM - Memory_alloc> return (0x8fb42b90)
[DSP] @0x78dbcf0a:[T:0x8fb3b244] OM - Memory_alloc> Enter(size=0x24)
[DSP] @0x78dbcf3e:[T:0x8fb3b244] OM - Memory_alloc> return (0x8fb42bb0)
(followed by successful VISA_create call for the codec)

For the unsuccessful restart, I see this:

[DSP] @0x79cd6509:[T:0x8fb3b244] CR - processRmsCmd(0x8fe01928, 4056): cmd = 5
[DSP] @0x79cd6548:[T:0x8fb3b244] CR - remote time = 0x0, trace buffer size = 4032
(then the VISA_Create fails)

So it looks like on the 128th try, for some reason the VISA_Create doesn't create a node and allocate buffers, but instead gets the trace data.

If I call Engine_getLastError() after the failure, I get error 4, which is

#define Engine_ENOCOMM      4   /**< Unable to create a comm connection to the DSP.*/

I tried putting a 3 minute pause in the restart code at restart 126 to see if there was a timing issue, but the problem remains.

Another test I ran:  The application deletes/creates the codec in one thread, and makes the process calls in a different thread.  A semaphore is used as a mutex so that only one thread at a time can access the codec.  In the test that fails, the process task processes a few frames of video between restarts.  If I do a tight loop and restart more than 128 times without letting the process task run (i.e. I hold on to the mutex in the delete/create task), then I do not see the problem.

Any suggestions?  Am I hitting some limit on an 8-bit signed value in the codec engine?

  • 0
    Intellectual 310 points

    I am also able to reproduce when I run the same test on a dm6467 (dvsdk_1_40_00_28, codec_engine_2_10_01)

    Here is the CE log output for the failure:

    [DSP] @1230,942,073tk: [+0 T:0x8fb4d8ec S:0x8aa079b4] CR - processRmsCmd(0x8fe038a8, 4056): cmd = 5
    [DSP] @1230,942,148tk: [+0 T:0x8fb4d8ec S:0x8aa079b4] CR - remote time = 0x0, trace buffer size = 4032
    [DSP] @1231,004,747tk: [+0 T:0x8fb4d8ec S:0x8aa079b4] CR - processRmsCmd(0x8fe038a8, 4056): cmd = 5
    [DSP] @1231,004,814tk: [+0 T:0x8fb4d8ec S:0x8aa079b4] CR - remote time = 0x0, trace buffer size = 4032
    @531,283,806us: [+0 T:0x47b2db60 S:0x47b2cec0] CE - Engine_fwriteTrace> returning count [6734]
    @531,284,507us: [+2 T:0x47b2db60 S:0x47b2cf30] CE - Engine_createNode> Returning 0x0
    @531,285,189us: [+2 T:0x47b2db60 S:0x47b2cfa0] CV - VISA_create> FAILED to create remote codec (0x4).
    @531,285,903us: [+0 T:0x47b2db60 S:0x47b2cf78] CV - VISA_delete(0xb9e20)
    @531,286,558us: [+5 T:0x47b2db60 S:0x47b2cf78] CV - VISA_delete> deleting codec (localQueue=0xffff, remoteQueue=0xffff)
    @531,287,313us: [+0 T:0x47b2db60 S:0x47b2cf50] OM - Memory_free> Enter(0xb9e20, 0x30)
    @531,288,008us: [+0 T:0x47b2db60 S:0x47b2cf50] OM - Memory_free> return (0x1)

  • 0 in reply to chris2476
    Intellectual 310 points

    I was looking at the log from the DM6467 again and I noticed that the failure messages start earlier in the VISA_Create.  Here are more logs.  The first failure is the line that says "Comm_create('gppfromnode_130', ...) failed: status 0x8000802d".  It looks like this failure leads to a node create failure, which then results in a NODE_delete and VISA_delete before the message "VISA_create> FAILED to create remote codec (0x4)."

    Any suggestions would be much appreciated.

    @531,230,889us: [+0 T:0x47b2db60 S:0x47b2d0a8] extensions.blah.IBLAH - BLAH_create> Entry and calling VISA_create (server=0xb9698, name='vendorblah', params=0xb991c)
    @531,231,309us: [+0 T:0x47b2db60 S:0x47b2d078] CV - VISA_create(0xb9698, 'vendorblah', 0xb991c, 0x956, 'extensions.blah.IBLAH')
    @531,231,655us: [+0 T:0x47b2db60 S:0x47b2cfa0] CV - VISA_create2(0xb9698, 'vendorblah', 0xb991c, 0x74, 0x956, 'extensions.blah.IBLAH')
    @531,232,030us: [+0 T:0x47b2db60 S:0x47b2cf88] OM - Memory_alloc> Enter(0x30)
    @531,232,284us: [+0 T:0x47b2db60 S:0x47b2cf88] OM - Memory_alloc> return (0xb9e20)
    @531,232,529us: [+0 T:0x47b2db60 S:0x47b2cf30] CE - Engine_createNode(0xb9698, 'vendorblah', 956, 0xb991c, 0x74, 0x47b2d0a4)
    @531,232,849us: [+0 T:0x47b2db60 S:0x47b2cf18] OM - Memory_alloc> Enter(0x20)
    @531,233,082us: [+0 T:0x47b2db60 S:0x47b2cf18] OM - Memory_alloc> return (0xb9e58)
    @531,233,348us: [+0 T:0x47b2db60 S:0x47b2cf08] OC - Comm_create> Enter(queueName='gppfromnode_130', queue=0xb9e60, attrs=0x0)
    @531,233,662us: [+0 T:0x47b2db60 S:0x47b2cef0] OM - Memory_alloc> Enter(0x4)
    @531,233,899us: [+0 T:0x47b2db60 S:0x47b2cef0] OM - Memory_alloc> return (0xb9e80)
    @531,234,449us: [+6 T:0x47b2db60 S:0x47b2cf08] OC - Comm_create('gppfromnode_130', ...) failed: status 0x8000802d
    @531,234,749us: [+0 T:0x47b2db60 S:0x47b2cee0] OM - Memory_free> Enter(0xb9e80, 0x4)
    @531,234,999us: [+0 T:0x47b2db60 S:0x47b2cee0] OM - Memory_free> return (0x1)
    @531,235,231us: [+0 T:0x47b2db60 S:0x47b2cf08] OM - Memory_free> Enter(0xb9e58, 0x20)
    @531,235,480us: [+0 T:0x47b2db60 S:0x47b2cf08] OM - Memory_free> return (0x1)
    @531,235,712us: [+6 T:0x47b2db60 S:0x47b2cf30] CE - Engine_createNode> Node allocation failed.
    @531,235,977us: [+0 T:0x47b2db60 S:0x47b2ce90] OC - Comm_put> Enter(queue=0x0, msg=0x41d87880)
    @531,236,286us: [+0 T:0x47b2db60 S:0x47b2ce90] OC - Comm_put> return (0)
    @531,236,590us: [+0 T:0x47b2db60 S:0x47b2ce88] OC - Comm_get> Enter(queue=0x10000, msg=0x47b2cf1c, timeout=-1)
    @531,236,920us: [+0 T:0x47b2db60 S:0x47b2ce88] OC - Comm_get> MSGQ_Get() status=0x8000, return (0)
    [DSP] @1228,906,856tk: [+0 T:0x8fb4e0ec S:0x8aab90bc] CN - NODE_EXECFXN(0x8fb4dbb8): vendorblah#80 exiting per request ...
    [DSP] @1228,922,911tk: [+0 T:0x8fb4d8ec S:0x8aa079b4] CR - processRmsCmd(0x8fe038a8, 4056): cmd = 2
    [DSP] @1228,923,520tk: [+0 T:0x8fb4d8ec S:0x8aa0796c] CN - NODE_delete(0x8fb4dbb8): vendorblah#80
    [DSP] @1228,923,623tk: [+0 T:0x8fb4d8ec S:0x8aa0794c] extensions.blah.IBLAH - BLAH_delete> Entry (handle=0x8fb4dc80)
    [DSP] @1228,923,708tk: [+0 T:0x8fb4d8ec S:0x8aa0791c] CV - VISA_delete(0x8fb4dc80)
    [DSP] @1228,923,766tk: [+5 T:0x8fb4d8ec S:0x8aa0791c] CV - VISA_delete> deleting codec (localQueue=0xffff, remoteQueue=0xffff)
    [DSP] @1228,923,846tk: [+0 T:0x8fb4d8ec S:0x8aa078fc] ti.sdo.ce.alg.Algorithm - Algorithm_delete> Enter(handle=0x8fb4dcb0)
    [DSP] @1228,923,938tk: [+0 T:0x8fb4d8ec S:0x8aa078ac] blah.vendorblah - BLAHBLAH_BLAH_dmaGetChannels(0x8aa07e80, 0x8aaaa190)
    [DSP] @1228,924,033tk: [+0 T:0x8fb4d8ec S:0x8aa0786c] ti.sdo.fc.dskt2 - DSKT2_freeScratch Enter (mutexId=0, addr=0x1181f800, size=0x160)
    [DSP] @1228,924,121tk: [+0 T:0x8fb4d8ec S:0x8aa07854] ti.sdo.fc.dskt2 - _DSKT2_decrScratchReferenceCount> Enter (scratchMutexId=0)
    [DSP] @1228,924,202tk: [+0 T:0x8fb4d8ec S:0x8aa07854] ti.sdo.fc.dskt2 - _DSKT2_decrScratchReferenceCount> Exit
    [DSP] @1228,924,270tk: [+0 T:0x8fb4d8ec S:0x8aa0784c] ti.sdo.fc.dskt2 - _DSKT2_exitScratch> Enter (scratchMutexId=0)
    [DSP] @1228,924,342tk: [+0 T:0x8fb4d8ec S:0x8aa0786c] ti.sdo.fc.dskt2 - DSKT2_allocScratch Exit
    [DSP] @1228,924,405tk: [+0 T:0x8fb4d8ec S:0x8aa0786c] ti.sdo.fc.dskt2 - DSKT2_freeScratch Enter (mutexId=0, addr=0x1181f960, size=0x160)
    [DSP] @1228,924,489tk: [+0 T:0x8fb4d8ec S:0x8aa07854] ti.sdo.fc.dskt2 - _DSKT2_decrScratchReferenceCount> Enter (scratchMutexId=0)
    [DSP] @1228,924,566tk: [+0 T:0x8fb4d8ec S:0x8aa07854] ti.sdo.fc.dskt2 - _DSKT2_decrScratchReferenceCount> Exit
    [DSP] @1228,924,633tk: [+0 T:0x8fb4d8ec S:0x8aa0784c] ti.sdo.fc.dskt2 - _DSKT2_exitScratch> Enter (scratchMutexId=0)
    [DSP] @1228,924,703tk: [+0 T:0x8fb4d8ec S:0x8aa0786c] ti.sdo.fc.dskt2 - DSKT2_allocScratch Exit
    [DSP] @1228,924,779tk: [+0 T:0x8fb4d8ec S:0x8aa078c4] ti.sdo.fc.dskt2 - DSKT2_freeAlg> Enter (scratchMutexId=0, alg=0x8aa07e80)
    [DSP] @1228,924,859tk: [+2 T:0x8fb4d8ec S:0x8aa078c4] ti.sdo.fc.dskt2 - DSKT2_freeAlg> Dequeue alg  information
    [DSP] @1228,924,928tk: [+0 T:0x8fb4d8ec S:0x8aa0788c] ti.sdo.fc.dskt2 - _DSKT2_dequeueMemTab> Enter (segId=0, alg=0x8aa07e80)
    [DSP] @1228,925,010tk: [+0 T:0x8fb4d8ec S:0x8aa0788c] ti.sdo.fc.dskt2 - _DSKT2_dequeueMemTab> Exit (memTab=0x8fb4e050)
    [DSP] @1228,925,088tk: [+2 T:0x8fb4d8ec S:0x8aa078c4] ti.sdo.fc.dskt2 - DSKT2_freeAlg> Dequeued alg information, memTab 0x8fb4e050 memTabSize 80, numRecs 3, extHeapId 1
    [DSP] @1228,925,187tk: [+2 T:0x8fb4d8ec S:0x8aa078c4] ti.sdo.fc.dskt2 - DSKT2_freeAlg> Free instance memory
    [DSP] @1228,925,254tk: [+0 T:0x8fb4d8ec S:0x8aa0789c] ti.sdo.fc.dskt2 - _DSKT2_freeInstanceMemory> Enter (scratchMutexId=0, numRecs=3, extHeapId=1)
    [DSP] @1228,925,342tk: [+0 T:0x8fb4d8ec S:0x8aa0786c] ti.sdo.fc.dskt2 - _DSKT2_freeAllocatedMemory> Enter (scratchMutexId=0, number=3, extHeapId=1)
    [DSP] @1228,925,451tk: [+0 T:0x8fb4d8ec S:0x8aa0784c] ti.sdo.fc.dskt2 - _DSKT2_isSharedScratchAddr> Enter (scratchMutexId=0, addr=0x8aa07e80)
    [DSP] @1228,925,538tk: [+0 T:0x8fb4d8ec S:0x8aa0784c] ti.sdo.fc.dskt2 - _DSKT2_isSharedScratch> Exit (status=0 )
    [DSP] @1228,925,612tk: [+0 T:0x8fb4d8ec S:0x8aa0784c] ti.sdo.fc.dskt2 - _DSKT2_isSharedScratchAddr> Enter (scratchMutexId=0, addr=0x11818000)
    [DSP] @1228,925,698tk: [+0 T:0x8fb4d8ec S:0x8aa0784c] ti.sdo.fc.dskt2 - _DSKT2_isSharedScratch> Exit (status=1 )
    [DSP] @1228,925,766tk: [+0 T:0x8fb4d8ec S:0x8aa0784c] ti.sdo.fc.dskt2 - _DSKT2_isSharedScratchAddr> Enter (scratchMutexId=0, addr=0x8aa0eb80)
    [DSP] @1228,925,851tk: [+0 T:0x8fb4d8ec S:0x8aa0784c] ti.sdo.fc.dskt2 - _DSKT2_isSharedScratch> Exit (status=0 )
    [DSP] @1228,925,921tk: [+0 T:0x8fb4d8ec S:0x8aa0786c] ti.sdo.fc.dskt2 - _DSKT2_freeAllocatedMemory> Exit (returnVal=1)
    [DSP] @1228,925,993tk: [+0 T:0x8fb4d8ec S:0x8aa0787c] ti.sdo.fc.dskt2 - _DSKT2_usesInternalScratch> Enter (numRecs=3)
    [DSP] @1228,926,064tk: [+0 T:0x8fb4d8ec S:0x8aa0787c] ti.sdo.fc.dskt2@531,262,419us: [+0 T:0x47b2db60 S:0x47b2ce90] OC - Comm_put> Enter(queue=0x0, msg=0x41d87880)
    @531,263,308us: [+0 T:0x47b2db60 S:0x47b2ce90] OC - Comm_put> return (0)
    @531,264,018us: [+0 T:0x47b2db60 S:0x47b2ce88] OC - Comm_get> Enter(queue=0x10000, msg=0x47b2cf1c, timeout=-1)
    @531,264,799us: [+0 T:0x47b2db60 S:0x47b2ce88] OC - Comm_get> MSGQ_Get() status=0x8000, return (0)
     - _DSKT2_usesInternalScratch> Exit (returnVal=1)
    [DSP] @1228,926,135tk: [+0 T:0x8fb4d8ec S:0x8aa07884] ti.sdo.fc.dskt2 - _DSKT2_decrScratchReferenceCount> Enter (scratchMutexId=0)
    [DSP] @1228,926,214tk: [+0 T:0x8fb4d8ec S:0x8aa07884] ti.sdo.fc.dskt2 - _DSKT2_decrScratchReferenceCount> Exit
    [DSP] @1228,926,280tk: [+0 T:0x8fb4d8ec S:0x8aa0787c] ti.sdo.fc.dskt2 - _DSKT2_exitScratch> Enter (scratchMutexId=0)
    [DSP] @1228,926,353tk: [+0 T:0x8fb4d8ec S:0x8aa0787c] ti.sdo.fc.dskt2 - _DSKT2_exitScratch> Exit (status=0)
    [DSP] @1228,926,420tk: [+0 T:0x8fb4d8ec S:0x8aa0789c] ti.sdo.fc.dskt2 - _DSKT2_freeInstanceMemory> Exit (returnVal=1)
    [DSP] @1228,926,492tk: [+0 T:0x8fb4d8ec S:0x8aa078c4] ti.sdo.fc.dskt2 - DSKT2_freeAlg> Exit
    [DSP] @1228,926,552tk: [+0 T:0x8fb4d8ec S:0x8aa078cc] OM - Memory_free> Enter(addr=0x8fb4dcb0, size=16)
    [DSP] @1228,926,622tk: [+0 T:0x8fb4d8ec S:0x8aa078cc] OM - Memory_free> return (0x1)
    [DSP] @1228,926,677tk: [+0 T:0x8fb4d8ec S:0x8aa078fc] ti.sdo.ce.alg.Algorithm - Algorithm_delete> return
    [DSP] @1228,926,741tk: [+0 T:0x8fb4d8ec S:0x8aa078ec] OM - Memory_free> Enter(addr=0x8fb4dc80, size=48)
    [DSP] @1228,926,809tk: [+0 T:0x8fb4d8ec S:0x8aa078ec] OM - Memory_free> return (0x1)
    [DSP] @1228,926,864tk: [+0 T:0x8fb4d8ec S:0x8aa0794c] extensions.blah.IBLAH - BLAH_delete> Exit
    [DSP] @1228,926,942tk: [+0 T:0x8fb4d8ec S:0x8aa07934] OM - Memory_free> Enter(addr=0x8fb4dbd8, size=36)
    [DSP] @1228,927,010tk: [+0 T:0x8fb4d8ec S:0x8aa07934] OM - Memory_free> return (0x1)
    [DSP] @1228,927,064tk: [+0 T:0x8fb4d8ec S:0x8aa0793c] OM - Memory_free> Enter(addr=0x8fb4dbb8, size=32)
    [DSP] @1228,927,132tk: [+0 T:0x8fb4d8ec S:0x8aa0793c] OM - Memory_free> return (0x1)
    [DSP] @1228,927,188tk: [+0 T:0x8fb4d8ec S:0x8aa0795c] OM - Memory_free> Enter(addr=0x8fb4dba8, size=15)
    [DSP] @1228,927,258tk: [+0 T:0x8fb4d8ec S:0x8aa0795c] OM - Memory_free> return (0x1)
    [DSP] @1228,927,313tk: [+0 T:0x8fb4d8ec S:0x8aa0795c] OM - Memory_free> Enter(addr=0x8fb4db90, size=24)
    [DSP] @1228,927,381tk: [+0 T:0x8fb4d8ec S:0x8aa0795c] OM - Memory_free> return (0x1)
    [DSP] @1230,942,073tk: [+0 T:0x8fb4d8ec S:0x8aa079b4] CR - processRmsCmd(0x8fe038a8, 4056): cmd = 5
    [DSP] @1230,942,148tk: [+0 T:0x8fb4d8ec S:0x8aa079b4] CR - remote time = 0x0, trace buffer size = 4032
    [DSP] @1231,004,747tk: [+0 T:0x8fb4d8ec S:0x8aa079b4] CR - processRmsCmd(0x8fe038a8, 4056): cmd = 5
    [DSP] @1231,004,814tk: [+0 T:0x8fb4d8ec S:0x8aa079b4] CR - remote time = 0x0, trace buffer size = 4032
    @531,283,806us: [+0 T:0x47b2db60 S:0x47b2cec0] CE - Engine_fwriteTrace> returning count [6734]
    @531,284,507us: [+2 T:0x47b2db60 S:0x47b2cf30] CE - Engine_createNode> Returning 0x0
    @531,285,189us: [+2 T:0x47b2db60 S:0x47b2cfa0] CV - VISA_create> FAILED to create remote codec (0x4).
    @531,285,903us: [+0 T:0x47b2db60 S:0x47b2cf78] CV - VISA_delete(0xb9e20)
    @531,286,558us: [+5 T:0x47b2db60 S:0x47b2cf78] CV - VISA_delete> deleting codec (localQueue=0xffff, remoteQueue=0xffff)
    @531,287,313us: [+0 T:0x47b2db60 S:0x47b2cf50] OM - Memory_free> Enter(0xb9e20, 0x30)
    @531,288,008us: [+0 T:0x47b2db60 S:0x47b2cf50] OM - Memory_free> return (0x1)
    @531,288,678us: [+0 T:0x47b2db60 S:0x47b2d0a8] extensions.blah.IBLAH - BLAH_create > Exit