Please note as of Wednesday, August 15th, 2018 this wiki has been set to read only. If you are a TI Employee and require Edit ability please contact x0211426 from the company directory.

CE DEBUG

From Texas Instruments Wiki
Jump to: navigation, search

Introduction

The CE_DEBUG feature lets the user set one simple environment variable and get all the debugging info there is, in correct order, which he needs when things don't work, for example Engine fails to open or a codec can't be created on the DSP.

Note, the CE_DEBUG feature was introduced in Codec Engine 2.00.

Usage

Setting the CE_DEBUG environment variable causes Codec Engine to enable various levels of tracing (depending on the value assigned to CE_DEBUG), and sends it to stdout. If present, any trace from remote processors is collected automatically at the end of every Codec Engine/VISA call, and is printed immediately following the call that interacted with the remote processor.

The value of the variable only affects the detail level of the information collected and printed:

  • Setting CE_DEBUG=1 before running the Codec Engine-based application, without any other preparation in the build or the code, causes all warnings and errors (both on the application processor and any remote processors, if they exist) to be printed on standard output.
  • Setting CE_DEBUG=2 turns on almost all tracing lines (except for most annoying and largely unnecessary ones), which gives additional insight into what is going on on the ARM (and the optional DSP).
  • Setting CE_DEBUG=3 turns on all tracing. This includes tracing for the infrastructure actually collecting the tracing from remote processors(!).

For example, if the application runs the following code:

printf("creating video decoder...\n");
viddec = VIDDEC_create(engine, ....);

... and the VIDDEC_create() fails - perhaps because DMA resources are mis-configured, on the standard output there will be a line from the app ("creating video decoder..."), followed by lines of CE tracing showing which functions were called and which messages were passed on to the DSP, followed by the message from the DSP (each line being prefixed with "[DSP] ") that shows how and why codec creation failed on the DSP.

One way to easily invoke the application with CE_DEBUG, and capture the tracing to a log file is the following:

root@146.252.161.13> CE_DEBUG=2 ./app.out [any app args here...]  | tee log.txt

Then you can examine "log.txt".

Usage for BIOS

On a BIOS-based system, you can set CE_DEBUG=1 by explicitly setting this global variable in main(), before calling CERuntime_init():

extern __FAR__ Char *ti_sdo_ce_osal_bios_Global_CE_DEBUG;
 
ti_sdo_ce_osal_bios_Global_CE_DEBUG[0] = '1';
ti_sdo_ce_osal_bios_Global_CE_DEBUG[1] = '\0';

Usage for Windows CE

For Windows CE, the registry is used for setting "CE_DEBUG" values. The "CE_DEBUG" entry should be created under the registry key, "SOFTWARE\\Texas Instruments\\ti.sdo.ce.osal", and its value can be set to 1, 2, or 3. A utility, osalsetenv_wince.exe, is provided with codec engine for setting CE_DEBUG values. For OMAP3530, this utility is located in the directory, ti\sdo\ce\osal\wince\utils\bin\ti_platforms_evm3530 (or for Davinci, ti_platforms_evmDM6446), under the codec engine installation.

To set CE_DEBUG to '2' using this utility, copy osalsetenv_wince.exe to your flat release directory (eg, to C:\WINCE600\OSDesigns\TI_EVM_3530\RelDir\TI_EVM_3530_ARMV4I_Release). In platform Builder open a Windows CE target command window (from the menu 'Target'->Target Control'). Then in the target command window, enter

   s osalsetenv_wince.exe CE_DEBUG 2

When you run your codec engine application, you should see the CE_DEBUG trace messages in the Platform Builder output window. To unset CE_DEBUG, in the target command window, enter

   s osalsetenv_wince.exe CE_DEBUG


Build info

By default, all executables built with Codec Engine contain a string list of all packages in the system - their names, version, and absolute directories. The intention is to help the user identify incorrect packages integrated into their system (often a result of an errant package path during the build) - which often leads to mysterious failures, especially with codecs. This 'build info' string is printed at CE_DEBUG=2 or higher (or, without CE_DEBUG, by enabling the "OG+4" trace mask).

To turn off embedding the build info string in the executable, the executables configuration script (.cfg) must contain this line:

    xdc.useModule("ti.sdo.ce.osal.Global").embedBuildInfo = false;

Emacs Utility

For emacs users, this utility function highlights GT trace output in different colors in your emacs buffer:

; GT trace logs
(defun gt-trace-highlight ()
  (interactive)
  (highlight-lines-matching-regexp ".*\\[\\+0 .*" 'hi-green)
  (highlight-lines-matching-regexp ".*\\[\\+2 .*" 'hi-pink)
  (highlight-lines-matching-regexp ".*\\[\\+4 .*" 'hi-yellow)
  (highlight-lines-matching-regexp ".*\\[\\+5 .*" 'hi-blue)
  (highlight-lines-matching-regexp ".*\\[\\+6 .*" 'hi-red-b)
  (highlight-lines-matching-regexp ".*\\[\\+7 .*" 'hi-red-b))

It basically highlights enter/exit trace in green, warnings/error trace in bold red, etc.

TraceUtil

When CE_DEBUG is set, the TraceUtil feature is automatically disabled. This is because the trace from remote devices will be retrieved. A side-effect of this is that DVT and other utilities that rely on TraceUtil are not supported when CE_DEBUG is used.

It is worth noting that TraceUtil is best used to debug a real-time problem; CE_DEBUG is best used when it's not a question of performance but rather functionality. These are in a way orthogonal modes of debugging.

Sample log

App-> Application started.
@0,444,974us: [+4 T:0x4003a6e8] OG - Global_init> This program was built with the following packages:
@0,445,368us: [+4 T:0x4003a6e8] OG -     package ti.platforms.evmDM6446 (/db/rtree/install/trees/products/xdcprod-h05/product/Linux/xdc_3_00/packages/ti/platforms/evmDM6446/) [1,0,0,0,1186449540217]
@0,445,468us: [+4 T:0x4003a6e8] OG -     package ti.catalog.c470 (/db/rtree/install/trees/products/xdcprod-h05/product/Linux/xdc_3_00/packages/ti/catalog/c470/) [1,0,0,0,1186079057604]
@0,445,542us: [+4 T:0x4003a6e8] OG -     package gnu.targets.rts470MV (/db/rtree/install/trees/products/xdcprod-h05/product/Linux/xdc_3_00/packages/gnu/targets/rts470MV/) [1,0,0,0,1186079011344]
@0,445,614us: [+4 T:0x4003a6e8] OG -     package ti.sdo.ce.utils.trace (/db/atree/davor/ce-g25x/src/ti/sdo/ce/utils/trace/) [1,0,1,0]
@0,445,683us: [+4 T:0x4003a6e8] OG -     package ti.xdais.dm (/db/atree/davor/ce-g25x/imports/ti/xdais/dm/) [1,0,3,1192053520287]
@0,445,751us: [+4 T:0x4003a6e8] OG -     package ti.xdais (/db/atree/davor/ce-g25x/imports/ti/xdais/) [1,2,1,1192053514110]
@0,445,818us: [+4 T:0x4003a6e8] OG -     package ti.sdo.ce.alg (/db/atree/davor/ce-g25x/src/ti/sdo/ce/alg/) [1,0,0,0]
@0,445,885us: [+4 T:0x4003a6e8] OG -     package ti.sdo.ce.utils.xdm (/db/atree/davor/ce-g25x/src/ti/sdo/ce/utils/xdm/) [1,0,1,0]
@0,445,950us: [+4 T:0x4003a6e8] OG -     package ti.sdo.utils.trace (/db/atree/davor/ce-g25x/imports/ti/sdo/utils/trace/) [1,0,0,1192603424246]
@0,446,017us: [+4 T:0x4003a6e8] OG -     package dsplink.gpp (/db/atree/davor/ce-g25x/imports/dsplink/gpp/) [1,1,0,0]
@0,446,161us: [+4 T:0x4003a6e8] OG -     package ti.sdo.linuxutils.cmem (/db/atree/davor/ce-g25x/imports/ti/sdo/linuxutils/cmem/) [2,0,0,1192343414458]
@0,446,237us: [+4 T:0x4003a6e8] OG -     package ti.sdo.fc.acpy3 (/db/atree/davor/ce-g25x/imports/ti/sdo/fc/acpy3/) [1,0,2,1192603136778]
@0,446,307us: [+4 T:0x4003a6e8] OG -     package ti.sdo.fc.dman3 (/db/atree/davor/ce-g25x/imports/ti/sdo/fc/dman3/) [1,0,3,1192603177784]
@0,446,375us: [+4 T:0x4003a6e8] OG -     package ti.sdo.ce.osal (/db/atree/davor/ce-g25x/src/ti/sdo/ce/osal/) [2,1,0,0]
@0,446,442us: [+4 T:0x4003a6e8] OG -     package ti.sdo.ce (/db/atree/davor/ce-g25x/src/ti/sdo/ce/) [1,0,5,0]
@0,446,508us: [+4 T:0x4003a6e8] OG -     package ti.sdo.ce.video (/db/atree/davor/ce-g25x/src/ti/sdo/ce/video/) [1,0,2,0]
@0,446,575us: [+4 T:0x4003a6e8] OG -     package ti.sdo.ce.examples.codecs.viddec_copy (/db/atree/davor/ce-g25x/src/codec_engine_2_00/examples/ti/sdo/ce/examples/codecs/viddec_copy/) []
@0,446,646us: [+4 T:0x4003a6e8] OG -     package ti.sdo.ce.examples.codecs.videnc_copy (/db/atree/davor/ce-g25x/src/codec_engine_2_00/examples/ti/sdo/ce/examples/codecs/videnc_copy/) []
@0,446,716us: [+4 T:0x4003a6e8] OG -     package ti.sdo.ce.bioslog (/db/atree/davor/ce-g25x/src/ti/sdo/ce/bioslog/) [1,0,1,0]
@0,446,783us: [+4 T:0x4003a6e8] OG -     package ceapp (/db/atree/davor/ce-g25x/src/codec_engine_2_00/examples/ti/sdo/ce/examples/apps/video_copy/dualcpu/evmDM6446/ceapp/) []
@0,447,667us: [+0 T:0x4003a6e8] OT - Thread_create> Enter (fxn=0x152ec, attrs=0x0)
@0,448,260us: [+0 T:0x4003a6e8] OT - Thread_create> Exit (task=0x39460)
@0,448,579us: [+2 T:0x4003a6e8] ti.sdo.ce.osal.alg - ALG_init> Enter
@0,449,800us: [+2 T:0x4003a6e8] ti.sdo.ce.osal.alg - ALG_init> Exit
@0,450,076us: [+6 T:0x4003a6e8] CE - Engine_init> CE debugging on (CE_DEBUG=2; allowed CE_DEBUG levels: 1=min, 2=good, 3=max)
@0,450,452us: [+0 T:0x4003a6e8] CE - Engine_open> Enter('video_copy', 0x0, 0xbefffc44)
@0,450,595us: [+0 T:0x4003a6e8] CE - rserverOpen('video_copy.x64P'), count = 0
@0,450,693us: [+0 T:0x4003a6e8] OP - Process_create> Enter(imageName='video_copy.x64P', linkCfg='(null)', attrs=0xbefffc48)
@0,454,647us: [+1 T:0x40946b60] OP - daemon> thread created.
@0,462,749us: [+0 T:0x40946b60] OP - Process_create_d> Enter(proc=0x39848)
@0,462,896us: [+2 T:0x40946b60] OP - Process_create_d> Initializing DSP PROC...
@0,462,993us: [+2 T:0x40946b60] OP - Process_create_d> Using DspLink config data for entry #0 [server 'video_copy.x64P']
@0,468,571us: [+2 T:0x40946b60] OP - Process_create_d> Adding DSP segment #0 to Link configuration: name='DDR2', startAddress=0x8fa00000, sizeInBytes=0x400000, shared=1
@0,468,757us: [+2 T:0x40946b60] OP - Process_create_d> Adding DSP segment #1 to Link configuration: name='DSPLINKMEM', startAddress=0x8fe00000, sizeInBytes=0x100000, shared=1
@0,468,872us: [+2 T:0x40946b60] OP - Process_create_d> Adding DSP segment #2 to Link configuration: name='RESET_VECTOR', startAddress=0x8ff00000, sizeInBytes=0x80, shared=0
@0,468,977us: [+2 T:0x40946b60] OP - Process_create_d> Adding DSP segment #3 to Link configuration: name='DDRALGHEAP', startAddress=0x88000000, sizeInBytes=0x7a00000, shared=0
@0,469,083us: [+2 T:0x40946b60] OP - Process_create_d> DOPOWERCONTROL was=0; now=0
@0,470,746us: [+2 T:0x40946b60] OP - Process_create_d> Attaching to DSP PROC...
@0,485,586us: [+2 T:0x40946b60] OP - Process_create_d> Opening MSGQ pool...
@0,486,184us: [+2 T:0x40946b60] OP - Process_create_d> Loading video_copy.x64P on DSP (1 args)...
@0,523,578us: [+2 T:0x40946b60] OP - Process_create_d> Starting DSP PROC...
@0,531,992us: [+2 T:0x40946b60] OP - Process_create_d> Opening remote transport...
@0,532,531us: [+2 T:0x40946b60] OP - Process_create_d> return (1)
@0,532,845us: [+0 T:0x4003a6e8] OP - Process_create> return (0x39848)
@0,532,964us: [+0 T:0x4003a6e8] CE - rserverOpen('video_copy.x64P'): 0x38678 done.
@0,540,944us: [+0 T:0x4003a6e8] CE - checkServer(0x39818)
@0,541,346us: [+0 T:0x4003a6e8] CE - rmsInit> RMS initialized(0x39818); CE_DEBUG on, setting DSP trace mask to *+01234567,CR=67,OM=67,GT_prefix=1235,GT_time=3
@0,541,489us: [+0 T:0x4003a6e8] CE - Engine_setTrace> Enter(engine=0x39818, mask='*+01234567,CR=67,OM=67,GT_prefix=1235,GT_time=3')
@0,541,613us: [+1 T:0x4003a6e8] CE - Engine_setTrace> Requesting DSP set trace ...
@0,542,999us: [+0 T:0x4003a6e8] CE - Engine_setTrace> return(0)
[DSP] @0x0000016b:[T:0x00000000] servers.video_copy.evmDM6446 - main> Welcome to DSP server's main().
[DSP] @0,021,735tk: [+0 T:0x8fa470ac] OG - Global_setSpecialTrace> enter(mask='*+01234567,CR=67,OM=67,GT_prefix=1235,GT_time=3')
[DSP] @0,021,821tk: [+4 T:0x8fa470ac] OG - Global_setSpecialTrace> This program was built with the following packages:
[DSP] @0,021,886tk: [+4 T:0x8fa470ac] OG -     package ti.targets.rts6000 (/db/rtree/install/trees/products/xdcprod-h10/product/Linux/xdc_3_00_01/packages/ti/targets/rts6000/) [1,0,0,0,1190854088447]
[DSP] @0,021,990tk: [+4 T:0x8fa470ac] OG -     package ti.psl (/db/rtree/install/trees/products/sabios-h15/product/Linux/bios_5_31_08/packages/ti/psl/) [5,0,0,0]
[DSP] @0,022,076tk: [+4 T:0x8fa470ac] OG -     package ti.rtdx (/db/rtree/install/trees/products/sabios-h15/product/Linux/bios_5_31_08/packages/ti/rtdx/) []
[DSP] @0,022,159tk: [+4 T:0x8fa470ac] OG -     package ti.bios (/db/rtree/install/trees/products/sabios-h15/product/Linux/bios_5_31_08/packages/ti/bios/) [5,2,3,20,0]
[DSP] @0,022,247tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.fc.dskt2 (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/cetools/packages/ti/sdo/fc/dskt2/) [1,0,3,0]
[DSP] @0,022,337tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.fc.dman3 (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/cetools/packages/ti/sdo/fc/dman3/) [1,0,3,0]
[DSP] @0,022,427tk: [+4 T:0x8fa470ac] OG -     package ti.xdais.dm (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/cetools/packages/ti/xdais/dm/) [1,0,3,0]
[DSP] @0,022,513tk: [+4 T:0x8fa470ac] OG -     package ti.xdais (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/cetools/packages/ti/xdais/) [1,2,1,0]
[DSP] @0,022,596tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.ce.node (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/packages/ti/sdo/ce/node/) [1,0,0,1193029336553]
[DSP] @0,022,695tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.utils.trace (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/cetools/packages/ti/sdo/utils/trace/) [1,0,0,0]
[DSP] @0,022,788tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.ce.utils.xdm (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/packages/ti/sdo/ce/utils/xdm/) [1,0,1,1193029608129]
[DSP] @0,022,884tk: [+4 T:0x8fa470ac] OG -     package ti.bios.utils (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/cetools/packages/ti/bios/utils/) [2,0,0,22,0]
[DSP] @0,022,973tk: [+4 T:0x8fa470ac] OG -     package dsplink.dsp (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/cetools/packages/dsplink/dsp/) [1,1,0,0]
[DSP] @0,023,059tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.fc.acpy3 (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/cetools/packages/ti/sdo/fc/acpy3/) [1,0,2,0]
[DSP] @0,023,149tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.ce.osal (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/packages/ti/sdo/ce/osal/) [2,0,1,1193029416285]
[DSP] @0,023,240tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.ce.alg (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/packages/ti/sdo/ce/alg/) [1,0,0,1193028885493]
[DSP] @0,023,330tk: [+4 T:0x8fa470ac] OG -     package ti.catalog.c6000 (/db/rtree/install/trees/products/xdcprod-h10/product/Linux/xdc_3_00_01/packages/ti/catalog/c6000/) [1,0,0,0,1191285431648]
[DSP] @0,023,432tk: [+4 T:0x8fa470ac] OG -     package ti.platforms.evmDM6446 (/db/rtree/install/trees/products/sabios-h15/product/Linux/bios_5_31_08/packages/ti/platforms/evmDM6446/) [1,0,0,0]
[DSP] @0,023,533tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.ce (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/packages/ti/sdo/ce/) [1,0,5,1193028871674]
[DSP] @0,023,619tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.ce.bioslog (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/packages/ti/sdo/ce/bioslog/) [1,0,1,1193028930811]
[DSP] @0,023,713tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.ce.video (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/packages/ti/sdo/ce/video/) [1,0,2,1193029638079]
[DSP] @0,023,804tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.ce.examples.codecs.viddec_copy (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/examples/ti/sdo/ce/examples/codecs/viddec_copy/) []
[DSP] @0,023,908tk: [+4 T:0x8fa470ac] OG -     package ti.sdo.ce.examples.codecs.videnc_copy (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/examples/ti/sdo/ce/examples/codecs/videnc_copy/) []
[DSP] @0,024,012tk: [+4 T:0x8fa470ac] OG -     package video_copy (/db/atree/library/trees/ce-g25x/src/codec_engine_2_00/examples/ti/sdo/ce/examples/servers/video_copy/evmDM6446/video_copy/) []
[DSP] @0,024,113tk: [+0 T:0x8fa470ac] OG - Global_setSpecialTrace> return
@0,812,321us: [+0 T:0x4003a6e8] CE - Engine_open> return(235544)
TraceUtil_start> note: CE_DEBUG env. var is set, so TraceUtil is not active (unset CE_DEBUG if you need TraceUtil)
@0,812,598us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_create> Enter (engine=0x39818, name='videnc_copy', params=0x0)
@0,812,738us: [+0 T:0x4003a6e8] CV - VISA_create(0x39818, 'videnc_copy', 0x0, 0x828, 'ti.sdo.ce.video.IVIDENC')
@0,812,886us: [+0 T:0x4003a6e8] CV - VISA_create2(0x39818, 'videnc_copy', 0x0, 0x0, 0x828, 'ti.sdo.ce.video.IVIDENC')
@0,813,017us: [+0 T:0x4003a6e8] CE - Engine_createNode(0x39818, 'videnc_copy', 828, 0x0, 0x0, 0xbefffc48)
@0,816,784us: [+4 T:0x4003a6e8] CE - Engine_createNode> created node(stdIn=0x2, stdOut=0x10001, msgq=0x39ac0, algName='videnc_copy', rmsNode=0x8fa47f38, algHandle=0x8fa48018)
[DSP] @0,623,669tk: [+0 T:0x8fa470ac] ti.sdo.ce.video.VIDENC - VIDENC_create> Enter (engine=0x0, name='videnc_copy', params=0x0)
[DSP] @0,623,750tk: [+0 T:0x8fa470ac] CV - VISA_create(0x0, 'videnc_copy', 0x0, 0x828, 'ti.sdo.ce.video.IVIDENC')
[DSP] @0,623,818tk: [+0 T:0x8fa470ac] CV - VISA_create2(0x0, 'videnc_copy', 0x0, 0x0, 0x828, 'ti.sdo.ce.video.IVIDENC')
[DSP] @0,623,901tk: [+0 T:0x8fa470ac] CE - Engine_open> Enter('local', 0x8fa475b4, 0x33c)
[DSP] @0,623,969tk: [+0 T:0x8fa470ac] CE - Engine_open> return(-1885044760)
[DSP] @0,624,032tk: [+0 T:0x8fa470ac] ti.sdo.ce.alg.Algorithm - Algorithm_create> Enter(fxns=0x8fa6d278, idma3Fxns=0x8fa6d2ac, params=0x0, attrs=0x8fa476c8)
[DSP] @0,624,179tk: [+0 T:0x8fa470ac] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_alloc(0x0, 0x8fa47578, 0x8fa483c0)
[DSP] @0,624,281tk: [+0 T:0x8fa470ac] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_initObj(0x88000250, 0x8fa483c0, 0x0, 0x0)
[DSP] @0,624,376tk: [+0 T:0x8fa470ac] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_dmaGetChannels(0x88000250, 0x88000258)
[DSP] @0,624,478tk: [+0 T:0x8fa470ac] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_dmaGetChannels(0x88000250, 0x88000258)
[DSP] @0,624,626tk: [+0 T:0x8fa470ac] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_dmaInit(0x88000250, 0x88000258)
[DSP] @0,624,712tk: [+0 T:0x8fa470ac] ti.sdo.ce.alg.Algorithm - Algorithm_create> return (0x8fa48040)
[DSP] @0,624,776tk: [+0 T:0x8fa470ac] ti.sdo.ce.video.VIDENC - VIDENC_create> return (0x8fa48018)
[DSP] @0,624,838tk: [+4 T:0x8fa470ac] OT - Thread_create > name: "videnc_copy#0", pri:  -1, stack size:  1024, stack seg: 0
@0,819,394us: [+2 T:0x4003a6e8] CE - Engine_createNode> Returning 0x39a98
@0,819,575us: [+5 T:0x4003a6e8] CV - VISA_create> remote codec created (name='videnc_copy', localQueueID=0x10001, remoteQueueID=0x0002)
@0,819,699us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_create> return (0x39a70)
@0,819,821us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_create> Enter (engine=0x39818, name='viddec_copy', params=0x0)
@0,819,954us: [+0 T:0x4003a6e8] CV - VISA_create(0x39818, 'viddec_copy', 0x0, 0x836, 'ti.sdo.ce.video.IVIDDEC')
@0,820,050us: [+0 T:0x4003a6e8] CV - VISA_create2(0x39818, 'viddec_copy', 0x0, 0x0, 0x836, 'ti.sdo.ce.video.IVIDDEC')
@0,820,175us: [+0 T:0x4003a6e8] CE - Engine_createNode(0x39818, 'viddec_copy', 836, 0x0, 0x0, 0xbefffc48)
@0,821,349us: [+4 T:0x4003a6e8] CE - Engine_createNode> created node(stdIn=0x3, stdOut=0x10002, msgq=0x39b50, algName='viddec_copy', rmsNode=0x8fa488c0, algHandle=0x8fa48958)
[DSP] @0,639,513tk: [+0 T:0x8fa470ac] ti.sdo.ce.video.VIDDEC - VIDDEC_create> Enter (engine=0x0, name='viddec_copy', params=0x0)
[DSP] @0,639,589tk: [+0 T:0x8fa470ac] CV - VISA_create(0x0, 'viddec_copy', 0x0, 0x836, 'ti.sdo.ce.video.IVIDDEC')
[DSP] @0,639,657tk: [+0 T:0x8fa470ac] CV - VISA_create2(0x0, 'viddec_copy', 0x0, 0x0, 0x836, 'ti.sdo.ce.video.IVIDDEC')
[DSP] @0,639,739tk: [+0 T:0x8fa470ac] ti.sdo.ce.alg.Algorithm - Algorithm_create> Enter(fxns=0x8fa6d17c, idma3Fxns=0x0, params=0x0, attrs=0x8fa476c8)
[DSP] @0,639,852tk: [+0 T:0x8fa470ac] ti.sdo.ce.examples.codecs.viddec_copy - VIDDECCOPY_TI_alloc(0x0, 0x8fa48990, 0x0)
[DSP] @0,639,936tk: [+0 T:0x8fa470ac] ti.sdo.ce.examples.codecs.viddec_copy - VIDDECCOPY_TI_initObj(0x88000258, 0x0, 0x0, 0x8fa76c50)
[DSP] @0,640,016tk: [+0 T:0x8fa470ac] ti.sdo.ce.alg.Algorithm - Algorithm_create> return (0x8fa48980)
[DSP] @0,640,077tk: [+0 T:0x8fa470ac] ti.sdo.ce.video.VIDDEC - VIDDEC_create> return (0x8fa48958)
[DSP] @0,640,136tk: [+4 T:0x8fa470ac] OT - Thread_create > name: "viddec_copy#1", pri:  -1, stack size:  1024, stack seg: 0
@0,823,202us: [+2 T:0x4003a6e8] CE - Engine_createNode> Returning 0x39b28
@0,823,380us: [+5 T:0x4003a6e8] CV - VISA_create> remote codec created (name='viddec_copy', localQueueID=0x10002, remoteQueueID=0x0003)
@0,823,502us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_create> return (0x39b00)
CEapp-> Allocating contiguous buffer for 'input data' of size 1024...
CEapp-> Allocating contiguous buffer for 'encoded data' of size 1024...
CEapp-> Allocating contiguous buffer for 'output data' of size 1024...
@1,160,554us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_control> Enter (handle=0x39a70, id=0, params=0xbefffc60, status=0xbefffbd0
@1,160,688us: [+5 T:0x4003a6e8] CV - VISA_allocMsg> Allocating message for messageId=0x00020003
@1,160,780us: [+0 T:0x4003a6e8] CV - VISA_call(visa=0x39a70, msg=0x41158c80): messageId=0x00020003, command=0x1
[DSP] @1,393,100tk: [+5 T:0x8fa4846c] CN - NODE> 0x8fa47f60(videnc_copy#0) call(algHandle=0x8fa48018, msg=0x8fe06c80); messageId=0x00020003
[DSP] @1,393,195tk: [+0 T:0x8fa4846c] ti.sdo.ce.video.VIDENC - VIDENC_control> Enter (handle=0x8fa48018, id=0, params=0x8fe06cb4, status=0x8fe06cdc
[DSP] @1,393,293tk: [+5 T:0x8fa4846c] CV - VISA_enter(visa=0x8fa48018): algHandle = 0x8fa48040
[DSP] @1,393,357tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> Enter(handle=0x8fa48040)
[DSP] @1,393,428tk: [+0 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_activate(0x88000250)
[DSP] @1,393,497tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> return
[DSP] @1,393,553tk: [+0 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_control(0x88000250, 0x0, 0x8fe06cb4, 0x8fe06cdc)
[DSP] @1,393,645tk: [+5 T:0x8fa4846c] CV - VISA_exit(visa=0x8fa48018): algHandle = 0x8fa48040
[DSP] @1,393,706tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> Enter(handle=0x8fa48040)
[DSP] @1,393,773tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> return
[DSP] @1,393,828tk: [+0 T:0x8fa4846c] ti.sdo.ce.video.VIDENC - VIDENC_control> Exit (handle=0x8fa48018, retVal=0x0)
[DSP] @1,393,897tk: [+5 T:0x8fa4846c] CN - NODE> returned from call(algHandle=0x8fa48018, msg=0x8fe06c80); messageId=0x00020003
@1,163,821us: [+0 T:0x4003a6e8] CV - VISA_call Completed: messageId=0x00020003, command=0x1, return(status=0)
@1,163,955us: [+5 T:0x4003a6e8] CV - VISA_freeMsg(0x39a70, 0x41158c80): Freeing message with messageId=0x00020003
@1,164,077us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_control> Exit (handle=0x39a70, retVal=0x0)
@1,164,179us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_control> Enter (handle=0x39b00, id=0, params=0xbefffc88, status=0xbefffb28
@1,164,278us: [+5 T:0x4003a6e8] CV - VISA_allocMsg> Allocating message for messageId=0x0003003b
@1,164,367us: [+0 T:0x4003a6e8] CV - VISA_call(visa=0x39b00, msg=0x41159c80): messageId=0x0003003b, command=0x1
[DSP] @1,401,030tk: [+5 T:0x8fa48a3c] CN - NODE> 0x8fa488e8(viddec_copy#1) call(algHandle=0x8fa48958, msg=0x8fe07c80); messageId=0x0003003b
[DSP] @1,401,120tk: [+0 T:0x8fa48a3c] ti.sdo.ce.video.VIDDEC - VIDDEC_control> Enter (handle=0x8fa48958, id=0, params=0x8fe07cb4, status=0x8fe07cc4
[DSP] @1,401,211tk: [+5 T:0x8fa48a3c] CV - VISA_enter(visa=0x8fa48958): algHandle = 0x8fa48980
[DSP] @1,401,271tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> Enter(handle=0x8fa48980)
[DSP] @1,401,336tk: [+0 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_deactivate(0x88000250)
[DSP] @1,401,402tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> return
[DSP] @1,401,457tk: [+0 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.viddec_copy - VIDDECCOPY_TI_control(0x88000258, 0x8fe07cb4, 0x1, 0x0)
[DSP] @1,401,538tk: [+5 T:0x8fa48a3c] CV - VISA_exit(visa=0x8fa48958): algHandle = 0x8fa48980
[DSP] @1,401,598tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> Enter(handle=0x8fa48980)
[DSP] @1,401,662tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> return
[DSP] @1,401,716tk: [+0 T:0x8fa48a3c] ti.sdo.ce.video.VIDDEC - VIDDEC_control> Exit (handle=0x8fa48958, retVal=0x0)
[DSP] @1,401,784tk: [+5 T:0x8fa48a3c] CN - NODE> returned from call(algHandle=0x8fa48958, msg=0x8fe07c80); messageId=0x0003003b
@1,167,070us: [+0 T:0x4003a6e8] CV - VISA_call Completed: messageId=0x0003003b, command=0x1, return(status=0)
@1,167,199us: [+5 T:0x4003a6e8] CV - VISA_freeMsg(0x39b00, 0x41159c80): Freeing message with messageId=0x0003003b
@1,167,299us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_control> Exit (handle=0x39b00, retVal=0x0)
App-> Processing frame 0...
@1,167,696us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_process> Enter (handle=0x39a70, inBufs=0xbefffc98, outBufs=0xbefffc88, inArgs=0xbefffae4, outArgs=0xbefffbe8)
@1,167,845us: [+5 T:0x4003a6e8] CV - VISA_allocMsg> Allocating message for messageId=0x00020004
@1,167,951us: [+0 T:0x4003a6e8] CV - VISA_call(visa=0x39a70, msg=0x41158c80): messageId=0x00020004, command=0x0
[DSP] @2,910,477tk: [+5 T:0x8fa4846c] CN - NODE> 0x8fa47f60(videnc_copy#0) call(algHandle=0x8fa48018, msg=0x8fe06c80); messageId=0x00020004
[DSP] @2,910,577tk: [+0 T:0x8fa4846c] ti.sdo.ce.video.VIDENC - VIDENC_process> Enter (handle=0x8fa48018, inBufs=0x8fa4883c, outBufs=0x8fa48848, inArgs=0x8fe06db8, outArgs=0x8fe06dbc)
[DSP] @2,910,691tk: [+5 T:0x8fa4846c] CV - VISA_enter(visa=0x8fa48018): algHandle = 0x8fa48040
[DSP] @2,910,751tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> Enter(handle=0x8fa48040)
[DSP] @2,910,816tk: [+0 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_activate(0x88000250)
[DSP] @2,910,886tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> return
[DSP] @2,910,940tk: [+0 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_process(0x88000250, 0x8fa4883c, 0x8fa48848, 0x8fe06db8, 0x8fe06dbc)
[DSP] @2,911,062tk: [+2 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_process> ACPY3 Processed 1024 bytes.
[DSP] @2,911,136tk: [+5 T:0x8fa4846c] CV - VISA_exit(visa=0x8fa48018): algHandle = 0x8fa48040
[DSP] @2,911,196tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> Enter(handle=0x8fa48040)
[DSP] @2,911,260tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> return
[DSP] @2,911,315tk: [+0 T:0x8fa4846c] ti.sdo.ce.video.VIDENC - VIDENC_process> Exit (handle=0x8fa48018, retVal=0x0)
[DSP] @2,911,387tk: [+5 T:0x8fa4846c] CN - NODE> returned from call(algHandle=0x8fa48018, msg=0x8fe06c80); messageId=0x00020004
@1,851,240us: [+0 T:0x4003a6e8] CV - VISA_call Completed: messageId=0x00020004, command=0x0, return(status=0)
@1,851,383us: [+5 T:0x4003a6e8] CV - VISA_freeMsg(0x39a70, 0x41158c80): Freeing message with messageId=0x00020004
@1,851,485us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_process> Exit (handle=0x39a70, retVal=0x0)
@1,851,577us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Enter (handle=0x39b00, inBufs=0xbefffc98, outBufs=0xbefffc88, inArgs=0xbefffc78, outArgs=0xbefffbd8)
@1,851,685us: [+5 T:0x4003a6e8] CV - VISA_allocMsg> Allocating message for messageId=0x0003003c
@1,851,784us: [+0 T:0x4003a6e8] CV - VISA_call(visa=0x39b00, msg=0x41159c80): messageId=0x0003003c, command=0x0
[DSP] @2,923,562tk: [+5 T:0x8fa48a3c] CN - NODE> 0x8fa488e8(viddec_copy#1) call(algHandle=0x8fa48958, msg=0x8fe07c80); messageId=0x0003003c
[DSP] @2,923,661tk: [+0 T:0x8fa48a3c] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Enter (handle=0x8fa48958, inBufs=0x8fa48e0c, outBufs=0x8fa48e18, inArgs=0x8fe07db8, outArgs=0x8fe07dc4)
[DSP] @2,923,775tk: [+5 T:0x8fa48a3c] CV - VISA_enter(visa=0x8fa48958): algHandle = 0x8fa48980
[DSP] @2,923,837tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> Enter(handle=0x8fa48980)
[DSP] @2,923,902tk: [+0 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_deactivate(0x88000250)
[DSP] @2,923,968tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> return
[DSP] @2,924,021tk: [+0 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.viddec_copy - VIDDECCOPY_TI_process(0x88000258, 0x8fa48e18, 0x8fe07dc4, 0x0, 0x1)
[DSP] @2,924,126tk: [+2 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.viddec_copy - VIDDECCOPY_TI_process> Processed 1024 bytes.
[DSP] @2,924,205tk: [+5 T:0x8fa48a3c] CV - VISA_exit(visa=0x8fa48958): algHandle = 0x8fa48980
[DSP] @2,924,264tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> Enter(handle=0x8fa48980)
[DSP] @2,924,329tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> return
[DSP] @2,924,382tk: [+0 T:0x8fa48a3c] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Exit (handle=0x8fa48958, retVal=0x0)
[DSP] @2,924,458tk: [+5 T:0x8fa48a3c] CN - NODE> returned from call(algHandle=0x8fa48958, msg=0x8fe07c80); messageId=0x0003003c
@1,854,741us: [+0 T:0x4003a6e8] CV - VISA_call Completed: messageId=0x0003003c, command=0x0, return(status=0)
@1,854,878us: [+5 T:0x4003a6e8] CV - VISA_freeMsg(0x39b00, 0x41159c80): Freeing message with messageId=0x0003003c
@1,854,979us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Exit (handle=0x39b00, retVal=0x0)
App-> Processing frame 1...
@2,193,508us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_process> Enter (handle=0x39a70, inBufs=0xbefffc98, outBufs=0xbefffc88, inArgs=0xbefffae4, outArgs=0xbefffbe8)
@2,193,646us: [+5 T:0x4003a6e8] CV - VISA_allocMsg> Allocating message for messageId=0x00020005
@2,193,784us: [+0 T:0x4003a6e8] CV - VISA_call(visa=0x39a70, msg=0x41158c80): messageId=0x00020005, command=0x0
[DSP] @3,681,069tk: [+5 T:0x8fa4846c] CN - NODE> 0x8fa47f60(videnc_copy#0) call(algHandle=0x8fa48018, msg=0x8fe06c80); messageId=0x00020005
[DSP] @3,681,165tk: [+0 T:0x8fa4846c] ti.sdo.ce.video.VIDENC - VIDENC_process> Enter (handle=0x8fa48018, inBufs=0x8fa4883c, outBufs=0x8fa48848, inArgs=0x8fe06db8, outArgs=0x8fe06dbc)
[DSP] @3,681,280tk: [+5 T:0x8fa4846c] CV - VISA_enter(visa=0x8fa48018): algHandle = 0x8fa48040
[DSP] @3,681,339tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> Enter(handle=0x8fa48040)
[DSP] @3,681,408tk: [+0 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_activate(0x88000250)
[DSP] @3,681,473tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> return
[DSP] @3,681,525tk: [+0 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_process(0x88000250, 0x8fa4883c, 0x8fa48848, 0x8fe06db8, 0x8fe06dbc)
[DSP] @3,681,634tk: [+2 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_process> ACPY3 Processed 1024 bytes.
[DSP] @3,681,712tk: [+5 T:0x8fa4846c] CV - VISA_exit(visa=0x8fa48018): algHandle = 0x8fa48040
[DSP] @3,681,771tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> Enter(handle=0x8fa48040)
[DSP] @3,681,835tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> return
[DSP] @3,681,888tk: [+0 T:0x8fa4846c] ti.sdo.ce.video.VIDENC - VIDENC_process> Exit (handle=0x8fa48018, retVal=0x0)
[DSP] @3,681,960tk: [+5 T:0x8fa4846c] CN - NODE> returned from call(algHandle=0x8fa48018, msg=0x8fe06c80); messageId=0x00020005
@2,196,771us: [+0 T:0x4003a6e8] CV - VISA_call Completed: messageId=0x00020005, command=0x0, return(status=0)
@2,196,905us: [+5 T:0x4003a6e8] CV - VISA_freeMsg(0x39a70, 0x41158c80): Freeing message with messageId=0x00020005
@2,197,002us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_process> Exit (handle=0x39a70, retVal=0x0)
@2,197,095us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Enter (handle=0x39b00, inBufs=0xbefffc98, outBufs=0xbefffc88, inArgs=0xbefffc78, outArgs=0xbefffbd8)
@2,197,204us: [+5 T:0x4003a6e8] CV - VISA_allocMsg> Allocating message for messageId=0x0003003d
@2,197,297us: [+0 T:0x4003a6e8] CV - VISA_call(visa=0x39b00, msg=0x41159c80): messageId=0x0003003d, command=0x0
[DSP] @3,688,809tk: [+5 T:0x8fa48a3c] CN - NODE> 0x8fa488e8(viddec_copy#1) call(algHandle=0x8fa48958, msg=0x8fe07c80); messageId=0x0003003d
[DSP] @3,688,903tk: [+0 T:0x8fa48a3c] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Enter (handle=0x8fa48958, inBufs=0x8fa48e0c, outBufs=0x8fa48e18, inArgs=0x8fe07db8, outArgs=0x8fe07dc4)
[DSP] @3,689,017tk: [+5 T:0x8fa48a3c] CV - VISA_enter(visa=0x8fa48958): algHandle = 0x8fa48980
[DSP] @3,689,077tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> Enter(handle=0x8fa48980)
[DSP] @3,689,141tk: [+0 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_deactivate(0x88000250)
[DSP] @3,689,206tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> return
[DSP] @3,689,259tk: [+0 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.viddec_copy - VIDDECCOPY_TI_process(0x88000258, 0x8fa48e18, 0x8fe07dc4, 0x0, 0x1)
[DSP] @3,689,358tk: [+2 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.viddec_copy - VIDDECCOPY_TI_process> Processed 1024 bytes.
[DSP] @3,689,426tk: [+5 T:0x8fa48a3c] CV - VISA_exit(visa=0x8fa48958): algHandle = 0x8fa48980
[DSP] @3,689,486tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> Enter(handle=0x8fa48980)
[DSP] @3,689,550tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> return
[DSP] @3,689,605tk: [+0 T:0x8fa48a3c] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Exit (handle=0x8fa48958, retVal=0x0)
[DSP] @3,689,680tk: [+5 T:0x8fa48a3c] CN - NODE> returned from call(algHandle=0x8fa48958, msg=0x8fe07c80); messageId=0x0003003d
@2,534,979us: [+0 T:0x4003a6e8] CV - VISA_call Completed: messageId=0x0003003d, command=0x0, return(status=0)
@2,535,154us: [+5 T:0x4003a6e8] CV - VISA_freeMsg(0x39b00, 0x41159c80): Freeing message with messageId=0x0003003d
@2,535,266us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Exit (handle=0x39b00, retVal=0x0)
App-> Processing frame 2...
@2,535,459us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_process> Enter (handle=0x39a70, inBufs=0xbefffc98, outBufs=0xbefffc88, inArgs=0xbefffae4, outArgs=0xbefffbe8)
@2,535,580us: [+5 T:0x4003a6e8] CV - VISA_allocMsg> Allocating message for messageId=0x00020006
@2,535,680us: [+0 T:0x4003a6e8] CV - VISA_call(visa=0x39a70, msg=0x41158c80): messageId=0x00020006, command=0x0
[DSP] @4,438,289tk: [+5 T:0x8fa4846c] CN - NODE> 0x8fa47f60(videnc_copy#0) call(algHandle=0x8fa48018, msg=0x8fe06c80); messageId=0x00020006
[DSP] @4,438,386tk: [+0 T:0x8fa4846c] ti.sdo.ce.video.VIDENC - VIDENC_process> Enter (handle=0x8fa48018, inBufs=0x8fa4883c, outBufs=0x8fa48848, inArgs=0x8fe06db8, outArgs=0x8fe06dbc)
[DSP] @4,438,499tk: [+5 T:0x8fa4846c] CV - VISA_enter(visa=0x8fa48018): algHandle = 0x8fa48040
[DSP] @4,438,559tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> Enter(handle=0x8fa48040)
[DSP] @4,438,624tk: [+0 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_activate(0x88000250)
[DSP] @4,438,689tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> return
[DSP] @4,438,742tk: [+0 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_process(0x88000250, 0x8fa4883c, 0x8fa48848, 0x8fe06db8, 0x8fe06dbc)
[DSP] @4,438,855tk: [+2 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_process> ACPY3 Processed 1024 bytes.
[DSP] @4,438,927tk: [+5 T:0x8fa4846c] CV - VISA_exit(visa=0x8fa48018): algHandle = 0x8fa48040
[DSP] @4,438,988tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> Enter(handle=0x8fa48040)
[DSP] @4,439,052tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> return
[DSP] @4,439,104tk: [+0 T:0x8fa4846c] ti.sdo.ce.video.VIDENC - VIDENC_process> Exit (handle=0x8fa48018, retVal=0x0)
[DSP] @4,439,180tk: [+5 T:0x8fa4846c] CN - NODE> returned from call(algHandle=0x8fa48018, msg=0x8fe06c80); messageId=0x00020006
@2,540,797us: [+0 T:0x4003a6e8] CV - VISA_call Completed: messageId=0x00020006, command=0x0, return(status=0)
@2,540,943us: [+5 T:0x4003a6e8] CV - VISA_freeMsg(0x39a70, 0x41158c80): Freeing message with messageId=0x00020006
@2,541,045us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_process> Exit (handle=0x39a70, retVal=0x0)
@2,541,142us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Enter (handle=0x39b00, inBufs=0xbefffc98, outBufs=0xbefffc88, inArgs=0xbefffc78, outArgs=0xbefffbd8)
@2,541,247us: [+5 T:0x4003a6e8] CV - VISA_allocMsg> Allocating message for messageId=0x0003003e
@2,541,343us: [+0 T:0x4003a6e8] CV - VISA_call(visa=0x39b00, msg=0x41159c80): messageId=0x0003003e, command=0x0
[DSP] @4,450,827tk: [+5 T:0x8fa48a3c] CN - NODE> 0x8fa488e8(viddec_copy#1) call(algHandle=0x8fa48958, msg=0x8fe07c80); messageId=0x0003003e
[DSP] @4,450,921tk: [+0 T:0x8fa48a3c] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Enter (handle=0x8fa48958, inBufs=0x8fa48e0c, outBufs=0x8fa48e18, inArgs=0x8fe07db8, outArgs=0x8fe07dc4)
[DSP] @4,451,034tk: [+5 T:0x8fa48a3c] CV - VISA_enter(visa=0x8fa48958): algHandle = 0x8fa48980
[DSP] @4,451,094tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> Enter(handle=0x8fa48980)
[DSP] @4,451,160tk: [+0 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_deactivate(0x88000250)
[DSP] @4,451,225tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> return
[DSP] @4,451,278tk: [+0 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.viddec_copy - VIDDECCOPY_TI_process(0x88000258, 0x8fa48e18, 0x8fe07dc4, 0x0, 0x1)
[DSP] @4,451,378tk: [+2 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.viddec_copy - VIDDECCOPY_TI_process> Processed 1024 bytes.
[DSP] @4,451,446tk: [+5 T:0x8fa48a3c] CV - VISA_exit(visa=0x8fa48958): algHandle = 0x8fa48980
[DSP] @4,451,505tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> Enter(handle=0x8fa48980)
[DSP] @4,451,569tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> return
[DSP] @4,451,623tk: [+0 T:0x8fa48a3c] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Exit (handle=0x8fa48958, retVal=0x0)
[DSP] @4,451,698tk: [+5 T:0x8fa48a3c] CN - NODE> returned from call(algHandle=0x8fa48958, msg=0x8fe07c80); messageId=0x0003003e
@2,544,321us: [+0 T:0x4003a6e8] CV - VISA_call Completed: messageId=0x0003003e, command=0x0, return(status=0)
@2,544,458us: [+5 T:0x4003a6e8] CV - VISA_freeMsg(0x39b00, 0x41159c80): Freeing message with messageId=0x0003003e
@2,544,560us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Exit (handle=0x39b00, retVal=0x0)
App-> Processing frame 3...
@2,881,388us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_process> Enter (handle=0x39a70, inBufs=0xbefffc98, outBufs=0xbefffc88, inArgs=0xbefffae4, outArgs=0xbefffbe8)
@2,881,522us: [+5 T:0x4003a6e8] CV - VISA_allocMsg> Allocating message for messageId=0x00020007
@2,881,629us: [+0 T:0x4003a6e8] CV - VISA_call(visa=0x39a70, msg=0x41158c80): messageId=0x00020007, command=0x0
[DSP] @5,204,514tk: [+5 T:0x8fa4846c] CN - NODE> 0x8fa47f60(videnc_copy#0) call(algHandle=0x8fa48018, msg=0x8fe06c80); messageId=0x00020007
[DSP] @5,204,610tk: [+0 T:0x8fa4846c] ti.sdo.ce.video.VIDENC - VIDENC_process> Enter (handle=0x8fa48018, inBufs=0x8fa4883c, outBufs=0x8fa48848, inArgs=0x8fe06db8, outArgs=0x8fe06dbc)
[DSP] @5,204,723tk: [+5 T:0x8fa4846c] CV - VISA_enter(visa=0x8fa48018): algHandle = 0x8fa48040
[DSP] @5,204,783tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> Enter(handle=0x8fa48040)
[DSP] @5,204,848tk: [+0 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_activate(0x88000250)
[DSP] @5,204,914tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> return
[DSP] @5,204,966tk: [+0 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_process(0x88000250, 0x8fa4883c, 0x8fa48848, 0x8fe06db8, 0x8fe06dbc)
[DSP] @5,205,077tk: [+2 T:0x8fa4846c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_process> ACPY3 Processed 1024 bytes.
[DSP] @5,205,148tk: [+5 T:0x8fa4846c] CV - VISA_exit(visa=0x8fa48018): algHandle = 0x8fa48040
[DSP] @5,205,207tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> Enter(handle=0x8fa48040)
[DSP] @5,205,272tk: [+0 T:0x8fa4846c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> return
[DSP] @5,205,325tk: [+0 T:0x8fa4846c] ti.sdo.ce.video.VIDENC - VIDENC_process> Exit (handle=0x8fa48018, retVal=0x0)
[DSP] @5,205,395tk: [+5 T:0x8fa4846c] CN - NODE> returned from call(algHandle=0x8fa48018, msg=0x8fe06c80); messageId=0x00020007
@2,885,616us: [+0 T:0x4003a6e8] CV - VISA_call Completed: messageId=0x00020007, command=0x0, return(status=0)
@2,885,758us: [+5 T:0x4003a6e8] CV - VISA_freeMsg(0x39a70, 0x41158c80): Freeing message with messageId=0x00020007
@2,885,863us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_process> Exit (handle=0x39a70, retVal=0x0)
@2,885,959us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Enter (handle=0x39b00, inBufs=0xbefffc98, outBufs=0xbefffc88, inArgs=0xbefffc78, outArgs=0xbefffbd8)
@2,886,064us: [+5 T:0x4003a6e8] CV - VISA_allocMsg> Allocating message for messageId=0x0003003f
@2,886,161us: [+0 T:0x4003a6e8] CV - VISA_call(visa=0x39b00, msg=0x41159c80): messageId=0x0003003f, command=0x0
[DSP] @5,214,539tk: [+5 T:0x8fa48a3c] CN - NODE> 0x8fa488e8(viddec_copy#1) call(algHandle=0x8fa48958, msg=0x8fe07c80); messageId=0x0003003f
[DSP] @5,214,634tk: [+0 T:0x8fa48a3c] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Enter (handle=0x8fa48958, inBufs=0x8fa48e0c, outBufs=0x8fa48e18, inArgs=0x8fe07db8, outArgs=0x8fe07dc4)
[DSP] @5,214,748tk: [+5 T:0x8fa48a3c] CV - VISA_enter(visa=0x8fa48958): algHandle = 0x8fa48980
[DSP] @5,214,808tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> Enter(handle=0x8fa48980)
[DSP] @5,214,873tk: [+0 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_deactivate(0x88000250)
[DSP] @5,214,939tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_activate> return
[DSP] @5,214,992tk: [+0 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.viddec_copy - VIDDECCOPY_TI_process(0x88000258, 0x8fa48e18, 0x8fe07dc4, 0x0, 0x1)
[DSP] @5,215,092tk: [+2 T:0x8fa48a3c] ti.sdo.ce.examples.codecs.viddec_copy - VIDDECCOPY_TI_process> Processed 1024 bytes.
[DSP] @5,215,160tk: [+5 T:0x8fa48a3c] CV - VISA_exit(visa=0x8fa48958): algHandle = 0x8fa48980
[DSP] @5,215,220tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> Enter(handle=0x8fa48980)
[DSP] @5,215,284tk: [+0 T:0x8fa48a3c] ti.sdo.ce.alg.Algorithm - Algorithm_deactivate> return
[DSP] @5,215,338tk: [+0 T:0x8fa48a3c] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Exit (handle=0x8fa48958, retVal=0x0)
[DSP] @5,215,414tk: [+5 T:0x8fa48a3c] CN - NODE> returned from call(algHandle=0x8fa48958, msg=0x8fe07c80); messageId=0x0003003f
@2,889,163us: [+0 T:0x4003a6e8] CV - VISA_call Completed: messageId=0x0003003f, command=0x0, return(status=0)
@2,889,327us: [+5 T:0x4003a6e8] CV - VISA_freeMsg(0x39b00, 0x41159c80): Freeing message with messageId=0x0003003f
@2,889,428us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_process> Exit (handle=0x39b00, retVal=0x0)
App-> Processing frame 4...
App-> Finished encoding and decoding 4 frames
@3,230,372us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_delete> Enter (handle=0x39a70)
@3,230,512us: [+0 T:0x4003a6e8] CV - VISA_delete(0x39a70)
@3,230,634us: [+5 T:0x4003a6e8] CV - VISA_delete> deleting codec (localQueue=0x10001, remoteQueue=0x2)
@3,230,907us: [+0 T:0x4003a6e8] CE - Engine_deleteNode(0x39a98)
@3,231,466us: [+5 T:0x4003a6e8] CE - Engine_deleteNode(0x39a98): algName = videnc_copy, algHandle = 0x8fa48018, stack size = 1024, stack used = 795(78%)
@3,232,045us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDENC - VIDENC_delete> return
@3,232,185us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_delete> Enter (handle=0x39b00)
@3,232,280us: [+0 T:0x4003a6e8] CV - VISA_delete(0x39b00)
@3,232,359us: [+5 T:0x4003a6e8] CV - VISA_delete> deleting codec (localQueue=0x10002, remoteQueue=0x3)
@3,232,625us: [+0 T:0x4003a6e8] CE - Engine_deleteNode(0x39b28)
@3,233,110us: [+5 T:0x4003a6e8] CE - Engine_deleteNode(0x39b28): algName = viddec_copy, algHandle = 0x8fa48958, stack size = 1024, stack used = 731(72%)
@3,233,707us: [+0 T:0x4003a6e8] ti.sdo.ce.video.VIDDEC - VIDDEC_delete> return
@3,233,845us: [+0 T:0x4003a6e8] CE - Engine_close(0x39818)
[DSP] @5,977,553tk: [+0 T:0x8fa4846c] CN - NODE_EXECFXN(0x8fa47f60): videnc_copy#0 exiting per request ...
[DSP] @5,978,146tk: [+0 T:0x8fa470ac] CN - NODE_delete(0x8fa47f60): videnc_copy#0
[DSP] @5,978,209tk: [+0 T:0x8fa470ac] ti.sdo.ce.video.VIDENC - VIDENC_delete> Enter (handle=0x8fa48018)
[DSP] @5,978,271tk: [+0 T:0x8fa470ac] CV - VISA_delete(0x8fa48018)
[DSP] @5,978,316tk: [+5 T:0x8fa470ac] CV - VISA_delete> deleting codec (localQueue=0xffff, remoteQueue=0xffff)
[DSP] @5,978,381tk: [+0 T:0x8fa470ac] ti.sdo.ce.alg.Algorithm - Algorithm_delete> Enter(handle=0x8fa48040)
[DSP] @5,978,462tk: [+0 T:0x8fa470ac] ti.sdo.ce.examples.codecs.videnc_copy - VIDENCCOPY_TI_dmaGetChannels(0x88000250, 0x88000620)
[DSP] @5,978,613tk: [+0 T:0x8fa470ac] ti.sdo.ce.alg.Algorithm - Algorithm_delete> return
[DSP] @5,978,670tk: [+0 T:0x8fa470ac] ti.sdo.ce.video.VIDENC - VIDENC_delete> return
[DSP] @5,981,332tk: [+0 T:0x8fa48a3c] CN - NODE_EXECFXN(0x8fa488e8): viddec_copy#1 exiting per request ...
[DSP] @5,981,955tk: [+0 T:0x8fa470ac] CN - NODE_delete(0x8fa488e8): viddec_copy#1
[DSP] @5,982,012tk: [+0 T:0x8fa470ac] ti.sdo.ce.video.VIDDEC - VIDDEC_delete> Enter (handle=0x8fa48958)
[DSP] @5,982,072tk: [+0 T:0x8fa470ac] CV - VISA_delete(0x8fa48958)
[DSP] @5,982,115tk: [+5 T:0x8fa470ac] CV - VISA_delete> deleting codec (localQueue=0xffff, remoteQueue=0xffff)
[DSP] @5,982,179tk: [+0 T:0x8fa470ac] ti.sdo.ce.alg.Algorithm - Algorithm_delete> Enter(handle=0x8fa48980)
[DSP] @5,982,253tk: [+0 T:0x8fa470ac] ti.sdo.ce.alg.Algorithm - Algorithm_delete> return
[DSP] @5,982,306tk: [+0 T:0x8fa470ac] ti.sdo.ce.video.VIDDEC - VIDDEC_delete> return
@3,236,785us: [+0 T:0x4003a6e8] CE - rserverClose(0x38678), count = 1
@3,236,930us: [+0 T:0x4003a6e8] OP - Process_delete> Enter(proc=0x39848)
@3,237,113us: [+0 T:0x40946b60] OP - Process_delete_d> Enter (proc=0x39848
@3,237,232us: [+2 T:0x40946b60] OP - Process_delete_d> Closing remote transport...
@3,237,785us: [+2 T:0x40946b60] OP - Process_delete_d> Stopping DSP...
@3,238,076us: [+2 T:0x40946b60] OP - Process_delete_d> Closing pool...
@3,238,575us: [+2 T:0x40946b60] OP - Process_delete_d> Detaching from DSP...
@3,257,917us: [+2 T:0x40946b60] OP - Process_delete_d> Destroying DSP... (object, that is)
@3,259,298us: [+0 T:0x40946b60] OP - Process_delete_d> return
@3,259,572us: [+1 T:0x4003a6e8] OP - Process_delete(0x39848) freeing object ...
@3,259,694us: [+0 T:0x4003a6e8] OP - Process_delete> return.
@3,259,776us: [+0 T:0x4003a6e8] CE - rserverClose(0x38678) done.
App-> Application finished successfully.
@3,260,931us: [+0 T:0x4003a6e8] OT - Thread_delete> Enter (task=0x39460)
@3,261,228us: [+4 T:0x4003a6e8] OT - Thread_delete> pthread_cancel (0x0)
@3,261,644us: [+4 T:0x4003a6e8] OT - Thread_delete> pthread_join (0x0)
@3,261,780us: [+0 T:0x4003a6e8] OT - Thread_delete> Exit (task=0x39460)