Codec engine sometimes hangs

Hi Dennis,

From the trace, it looks like the VIDANALYTICS_control call is sent down to the DSP and the ARM side code is waiting for a reply using Comm_get. The code on the DSP seems to be "stuck", possibly in your algorithm's control function. Do you see the control function of your algorithm getting called on the DSP given you said you have instrumented your code? How do you normally print out your debug statements (i.e. via CCS, using the GT module, or by some other means) on the DSP? If you have Code Composer Studio, one possibility is to connect to the DSP and take a look at where the code is halted (see http://processors.wiki.ti.com/index.php/Debugging_the_DSP_side_of_a_CE_application_using_CCS). Another quick test would be to replace your control function on the DSP with a dummy function (like the one in the codec engine vidanalytics_copy codec example) so that it is more likely to return properly, and then either backtrack to see what your control function is missing, or isolate the issue to something outside of the function.

Best regards,

Vincent

Hi Vincent,

You're right, it appears to be "stuck" waiting for the DSP side to respond to a message from the ARM.  When it is working, the CE_DEBUG=2 output for the VIDANALYTICS_control call looks like this:

[+0 T:0x400204c0 S:0xbe9a96e4] ti.sdo.ce.vidanalytics.VIDANALYTICS - VIDANALYTICS_control> Enter (handle=0x5fa38, id=1, dynParams=0xbe9a97cc (size=0x104), status=0xbe9a98d0 (size=0x158)

[+4 T:0x400204c0 S:0xbe9a9654] CV - VISA_getMaxMsgSize(0x5fa38): returning 0x1000

[+5 T:0x400204c0 S:0xbe9a965c] CV - VISA_allocMsg> Allocating message for messageId=0x0002ff03

[+0 T:0x400204c0 S:0xbe9a963c] CV - VISA_call(visa=0x5fa38, msg=0x4160a880): messageId=0x0002ff03, command=0x1

[+0 T:0x400204c0 S:0xbe9a9604] OC - Comm_put> Enter(queue=0x2, msg=0x4160a880)

[+0 T:0x400204c0 S:0xbe9a9604] OC - Comm_put> return (0)

[+0 T:0x400204c0 S:0xbe9a95fc] OC - Comm_get> Enter(queue=0x10001, msg=0xbe9a96f4, timeout=-1)

[+0 T:0x400204c0 S:0xbe9a95fc] OC - Comm_get> MSGQ_get() status=0x8000, return (0)

[+0 T:0x400204c0 S:0xbe9a958c] OC - Comm_put> Enter(queue=0x0, msg=0x41609880)

[+0 T:0x400204c0 S:0xbe9a958c] OC - Comm_put> return (0)

[+0 T:0x400204c0 S:0xbe9a9584] OC - Comm_get> Enter(queue=0x10000, msg=0xbe9a9624, timeout=-1)

[+0 T:0x400204c0 S:0xbe9a9584] OC - Comm_get> MSGQ_get() status=0x8000, return (0)

[DSP] @0,208,961tk: [+5 T:0x87f195c4 S:0x87f1b68c] CN - NODE> 0x87f190b8(vmd#0) call(algHandle=0x87f19180, msg=0x87305880); messageId=0x0002ff03

[DSP] @0,209,053tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,224,132tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,224,173tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,239,247tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,239,289tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,254,366tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,254,408tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,269,481tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,269,523tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,284,597tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,284,640tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,299,713tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,299,755tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffffff, sizeInBytes=16776960)

[DSP] @0,314,831tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,314,873tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,329,950tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,329,992tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=285212416)

[DSP] @0,591,456tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,591,498tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,606,572tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,606,614tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,621,687tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,621,728tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,636,802tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,636,844tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,651,918tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,651,960tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776448)

[DSP] @0,667,033tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,667,075tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,682,149tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,682,191tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> Enter(addr=0xffff00, sizeInBytes=16776960)

[DSP] @0,697,265tk: [+0 T:0x87f195c4 S:0x87f1b4ac] OM - Memory_cacheInv> return

[DSP] @0,697,309tk: [+0 T:0x87f195c4 S:0x87f1b44c] ti.sdo.ce.vidanalytics.VIDANALYTICS - VIDANALYTICS_control> Enter (handle=0x87f19180, id=1, dynParams=0x873058b4 (size=0x104), status=0x873059b8 (size=0x158)

[DSP] @0,697,425tk: [+5 T:0x87f195c4 S:0x87f1b42c] CV - VISA_enter(visa=0x87f19180): algHandle = 0x87f191b8

[DSP] @0,697,488tk: [+0 T:0x87f195c4 S:0x87f1b40c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> Enter(alg=0x87f191b8)

[DSP] @0,697,563tk: [+0 T:0x87f195c4 S:0x87f1b40c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> Exit

[DSP] @0,697,617tk: [+5 T:0x87f195c4 S:0x87f1b414] VMD - +VMD_TI_control() -> OK

So as you can see, during the failure condition, it never gets to my algorithm's control function (the successful entry into that function is demonstrated by the last line, "VMD_TI_control() -> OK").

I use the GT module to print out debug statements.  We don't use CCS and I don't think that switching to use it is an option at this time.

Thanks for your reply,

Dennis

Hi Dennis,

The DSP trace (lines that start with [DSP]) do not get printed out til after the remote call has completed successfully. So if your control function gets "stuck" on the DSP, you will not see the GT output unless the call completes and a message is sent back to the ARM to unblock it. As I mentioned, it may be worth substituting in a simple control function that is certain to work to allow you to better isolate the problem.

Best regards,

Vincent

I have some new information about this issue that I hope someone will be able to use to let me know what I'm doing wrong.

I have a situation where I can run a custom (I wrote it) video processing algorithm (video motion detection using IVIDANALYTICS) and it seems to work fine. Then I run the H.264 encoder to encode a video file and it works fine.  Then I run the same custom VMD algorithm, and it fails on the first call after create, every time. It doesn't matter if it's a IVIDANALYTICS_control() or IVIDANALYTICS_process() call, it causes the application to hang or crash with the DSP MMU fault.  The same thing happens if I attempt to run the H.264 encoder at the same time as the VMD algorithm.  It doesn't matter what the contents of my control() or process() functions are, I have even dummied them out so they just return success, and the results are the same.  It's almost as if the statically allocated function pointer table that provides the pointers to the implementation of the VMD algorithm is somehow getting corrupted when I run the H.264 encoder.

My codec server is a modified version of cs.x64P from cs1omap3530_1_01_00 from dvsdk 3.01.00.10.  I have added the TI AAC encoder and my custom VMD algorithm.  I have all codecs using stackMemId 0, the video codecs are using groupId 0, the audio codecs are using groupId 2, and the VMD algorithm is using groupId 1.  VMD uses DMA so I have adjusted DMAN3.numPaRamGroup[] and DMAN3.numTccGroup[] accordingly.

This problem is getting very serious and we need to solve it ASAP. Thanks in advance for any help you may be able to provide.

Dennis

Dennis Estenson said:

I have a situation where I can run a custom (I wrote it) video processing algorithm (video motion detection using IVIDANALYTICS) and it seems to work fine. Then I run the H.264 encoder to encode a video file and it works fine.  Then I run the same custom VMD algorithm, and it fails on the first call after create, every time.

Can you describe this failure case in more detail?  Do you have 2 separate apps, one for each codec, that use the same server?  Or is there one app that does VMD create/process/delete, then does h264_create/process/delete, then does VMD_create/process <-- crash?

I'm also interested in where Engine_open()/close() is happening in this flow.  If two separate apps, each one probably Engine_open() (which loads the Server on the DSP), VMD_create/process/delete, then Engine_close() (which unloads the DSP).  Those mountains of trace are useful to help explain the call flows like this, too... I know they can be a pain, but maybe you can post the CE_DEBUG=3 output of a recent failed run?  Best would be to link the trace enabled FC libraries into the Server as well so we can see DSKT2 and DMAN3 resource allocations, too.

Finally, does your VMD algorithm request/use any internal scratch memory via its memTabs?  If so, it doesn't access it until it's been activated, right?  If you're using scratch resources, does it crash if you stub out your control() call _and_ the activate()/deactivate() calls?

Chris

Chris,

Chris Ring said:

Can you describe this failure case in more detail?  Do you have 2 separate apps, one for each codec, that use the same server?  Or is there one app that does VMD create/process/delete, then does h264_create/process/delete, then does VMD_create/process <-- crash?

In my test case, I am using a gstreamer pipeline.  There is a single app, gst-launch, that I use, and 2 separate plugins to access the codecs.  For VMD only I'm using essentially the command line: gst-launch v4l2src ! vmd ! fakesink; for H.264 I'm using: v4l2src ! dmaienc_h264 ! fakesink; and for both I use v4l2src ! vmd ! dmaienc_h264 ! fakesink.  In my test script, I run the vmd only command line, then the H.264 command line 3 times, then the vmd command line again.  It always fails on the first vmd command line after doing H.264.

I have attached logs with CE_DEBUG=3.  I have grown used to looking at these logs, I don't mind capturing them.  There is one log of VMD working successfully (without crashing or hanging), one log of H.264 working successfully, and one log of VMD causing the DSP MMU fault:
DSP MMU Error Fault!  MMU_IRQSTATUS = [0x1]. Virtual DSP addr reference that generated the interrupt = [0xbebebeb8].

I do use external scratch memory, and external persistent memory via memTabs.  The scratch memory is initialized and used only from within the process function.  If I stub out the control, and activate/deactivate functions, it still crashes.

Thanks,

Dennis

4034.celogs.zip

(Per Prateek's request, I've also included the codec.cfg, server.cfg, and server.tcf files for the codec server):
0511.cfgs.zip

Hi Dennis,

What is CE version you are using? Found that the error DSP MMU Error Fault!  MMU_IRQSTATUS = [0x1]. Virtual DSP addr reference that generated the interrupt = [0xbebebeb8] could be part of some CE issues in older version with regards to supporting IUNIVERSAL

http://tiexpressdsp.com/index.php/Codec_Engine_Known_Issues

Also, check out thiswhy MMU Faults can happen -

http://wiki.omap.com/index.php/DSP_MMU_Faults

Prateek

Prateek Bansal said:

What is CE version you are using?

We're using Codec Engine version 2.25.02.11.

The trace logs show CE 2.25.02.11.  I don't think it's the IUNIVERSAL issue.

The MMU fault does concern me.  It says someone on the DSP is trying to access the address 0xbebebeb8 - obviously not a valid address.  The thing that most interests me is that stacks are initialized to 0xbebebebe.  So that addr seems like a bad ptr dereference.

Stacks look ok as best I can tell.  From the successful runs, the ARM-side logs report only 15% of the codec stacks were used.

It sure would be nice to attach to the DSP with CCS, set a breakpoint on the DSP-side and step through this...

Chris

It seems to me that the error:

DSP MMU Error Fault! MMU_IRQSTATUS = [0x1]. Virtual DSP addr reference that generated the interrupt = [0xbebebeb8].

must've occurred  when some memory containing the value 0xbebebeb8 was treated like a pointer and dereferenced.

A sanity check you might do - can you run with CE_CHECK=1?  I'm kinda wondering about some of the buffer descriptors.

Chris

Chris Ring said:

The trace logs show CE 2.25.02.11.  I don't think it's the IUNIVERSAL issue.

JTAG is not working on our boards.  I just asked our hardware guys how hard it would be to get it working.  They're looking into it but it may be 5 days or more before it's ready. For now, I'm going to attempt to replicate the problem on the OMAP EVM Rev. G board.

Dennis

Chris Ring said:

A sanity check you might do - can you run with CE_CHECK=1?

I don't see any differences in the logs.

Dennis

6560.cedebugchk.zip

Chris,

We've successfully attached CCS (v3.3.82.13) to the Mistral OMAP EVM and I am able to set breakpoints and step through the code.  Do you have any suggestions for where to set my breakpoints? I have tried putting it in my algorithm's alg*() functions and came to the conclusion that the Algorithm_create() appears to succeed, but none of my breakpoints are hit after that and before the DSP MMU error fault.  Is there a way to have the debugger break on that error fault so I could see the call stack and other useful debugging data?

Thanks,

Dennis

Great to hear.

Dennis Estenson said:

Do you have any suggestions for where to set my breakpoints?

There's some similar debugging described in this thread:  http://e2e.ti.com/support/embedded/f/353/p/70176/254585.aspx

I'd like to see what happens on the DSP side after the ARM sends the control() msg.  The DSP-side breakpoint is likely in the NODE fxns described in the other thread.  If we receive the DSP-side MSGQ_get() but aren't getting to your alg fxns, it may be something in the framework between the DSP-side MSGQ_get() and your alg's control() call.

Chris

Hi Chris,

I was able to put a breakpoint at the beginning of NODE_EXECFXN() function, but it is unable to step from there.  It's as if that code that implements that function is in release mode.

I was also able to fix one bug that was definitely causing some problems.  Unfortunately there must be more, because it still crashes in the same way.

Thanks,

Dennis

I was missing

xdc.useModule('ti.sdo.ce.global.Settings').profile = "debug";
xdc.useModule('ti.sdo.fc.global.Settings').profile = "debug";

in my codec.cfg file.  Now I have much more fully-featured debugging capabilities.  Unfortunately, now that debugging works so well, the crash didn't happen the first time I ran it.  I will keep trying.

Hopefully I can get this problem nailed down before the webex conference.

Thanks,

Dennis

After 5-6 runs, it appears that the problem occurs much less often with all of the debugging enabled.  It only crashed once, and I wasn't able to gather anything useful from that time.  I am continuing to try to replicate the problem.  What does the fact that the crash happens less often with full debugging enabled tell you?

Thanks,

Dennis