Gst-openmax decoder omx_h264dec blocked when finish decode avi file

Aaron;

Not sure about the question, I going to provide 2 answers;

#1;

State changes looks ok, you are waiting for EOS to be propagated from input buffer to output buffer in a output-loop, and you do OMX_StateSet to OMX_StatePaused after EOS flag is received what is ok.

I can see next print that seems to point to a duplicated output buffer, timestamps are disorder at the end of the ooutput buffer compared to last input buffer's timestamp.

This is the dup (duplicated??) message

0:06:41.133392333 [335m 922[00m 0x1656150 [36mDEBUG [00m [00m omx external/gst-openmax/omx/gstomx_port.c:1014:g_omx_port_recv:[00m <omxh264dec0:out:1> dup'd buffer 0x1670e98

This is last input buffer, nTimeStamp: 28040000

0:06:40.753448485 [335m 922[00m 0x166bc08 [36mDEBUG [00m [00m omx external/gst-openmax/omx/gstomx_port.c:528:release_buffer:[00m <omxh264dec0:in:0> ETB: omx_buffer=0x1655d80, pAppPrivate=0x0, pBuffer=0x40980000, flags=00000001, nTimeStamp: 28040000

With its respective EBD with same buffer address

0:06:41.527618407 [335m 922[00m 0x16560d8 [36mDEBUG [00m [00m omx external/gst-openmax/omx/gstomx_core.c:891:EmptyBufferDone:<omxh264dec0>[00m EBD: omx_buffer=0x1655d80, filledlen=0, alloclen=921600, , flags=0x1, pAppPrivate=0x0, pBuffer=0x40980000

Then FTB? i cannot see FBD for EOS buffer but I imagine that this is needs to be check adding an extra print, if you see timestamps is not the same as input buffer nTimeStamp: 27920000, it could be caused by duplicated output buffers in the pipes, matter to check the procedure when flush before in case of doing it forafter OMX_StateExecuting, and keep buffer tracking for this case.

0:06:43.168548583 [335m 922[00m 0x1656150 [36mDEBUG [00m [00m omx external/gst-openmax/omx/gstomx_port.c:938:g_omx_port_recv:[00m <omxh264dec0:out:1> got eos

0:06:43.168701170 [335m 922[00m 0x1656150 [36mDEBUG [00m [00m omx external/gst-openmax/omx/gstomx_port.c:543:release_buffer:[00m <omxh264dec0:out:1> FTB: omx_buffer=0x1670f98, pAppPrivate=0x0, pBuffer=0x40f50000, flags=00000401, nTimeStamp: 27920000, nFilledLen=0

0:06:43.169158934 [335m 922[00m 0x1656150 [36mDEBUG [00m [00m omx external/gst-openmax/omx/gstomx_base_filter.c:508:output_loop:<omxh264dec0>[00m got eos

then it got EOS and send component to OMX_StatePaused and OMX_CommandFlush for later to unloaded the component and finish the tests.

Setting pipeline to PAUSED ...

0:06:43.170104979 [335m 922[00m 0x1656150 [32;01mINFO [00m [00m omx external/gst-openmax/omx/gstomx_base_filter.c:529:output_loop:<omxh264dec0>[00m pause task, reason: unexpected

0:06:43.170257567 [335m 922[00m 0x1656150 [36mDEBUG [00m [00m omx external/gst-openmax/omx/gstomx_base_filter.c:534:output_loop:<omxh264dec0>[00m Exit external/gst-openmax/omx/gstomx_base_filter.c(534)-output_loop

0:06:43.172393798 [335m 922[00m 0x159b008 [36mDEBUG [00m [00m omx external/gst-openmax/omx/gstomx_base_filter.c:134:change_state:<omxh264dec0>[00m Enter external/gst-openmax/omx/gstomx_base_filter.c(134)-change_state

This duplicated buffers condition could cause that some buffers get lost.

Other point to check is how are frame counted, is it made bya program or you are counting start headers (00 00 00 01-h264)? I know it could not be the case but it is a possibility, just to check, it could be if you are getting 2 frames lost that could be SPS+PPS, but you are losing 4 frames and there is not relation between last frames and possible test cases that matches this condition under normal circunstances of frame counting and frame types, comparing the number of total frames agains lost frames and using a start header theory where some SEI frame or timming frame could cause a no output frame, at lest not a condition a can thing right now, the idea is how are you counting frames? just to check this.

Some other condition could be corrupted frames that are not generating an output buffer.

#2

You are refering to nBufferCountActual? this value is modified by Ducati base in SPS+PPS values in order to get correct buffer count that matches file characteristics and correct processing. This value is returned in OMX_EventPortSettingsChanged, depending on the stage of Ducati is processing the buffer can generate many calls to return proper values to ClientIL. one of this calls is to set nBufferCountActual.

Hi,Manuel

    I have  added  extra prints in the  FillBufferDone and EmptyBufferDone.

    FillBufferDone  (gstomx_core.c)

   fbd_count ++;
    GST_DEBUG_OBJECT (core->object, "%s(%d)--%s FBD: omx_buffer=%p, pAppPrivate=%p, pBuffer=%p, flags=%08x, nTimeStamp: %lld, nFilledLen=%d, portStatus =%d,fbd_count = %d", __FILE__,__LINE__,__FUNCTION__,omx_buffer, omx_buffer ? omx_buffer->pAppPrivate : 0,  omx_buffer ? omx_buffer->pBuffer : 0, omx_buffer->nFlags, omx_buffer->nTimeStamp, omx_buffer->nFilledLen,port->portStatus,fbd_count);

  EmptyBufferDone(gstomx_core.c)

  ebd_count ++;   
    GST_DEBUG_OBJECT (core->object, "%s(%d)--%s  EBD: omx_buffer=%p, filledlen=%d, alloclen=%d, , flags=0x%x, pAppPrivate=%p, pBuffer=%p,nTimeStamp: %lld,ebd_count = %d",  __FILE__,__LINE__,__FUNCTION__,omx_buffer, omx_buffer->nFilledLen, omx_buffer->nAllocLen, omx_buffer->nFlags,omx_buffer->pAppPrivate,  omx_buffer->pBuffer,omx_buffer->nTimeStamp,ebd_count);

use the command  "gst-launch -v filesrc location=/mnt/sdcard/decodefile.avi  ! avidemux name=demux  demux.video_00 ! h264parse ! omx_h264dec ! ffmpegcolorspace ! surfaceflingersink --gst-debug=omx:5".

  1)   after  the command  starts  run , the sufaceflinger  will  display  in a minute  and  slowness

  2)   I  find  the nTimeStamp and  nFilledLen of  first  some buffers in the FillBufferDone  is zero 

    Line 488: 0:00:06.893646241 [331m 1236[00m   0x9d1fc8 [36mDEBUG  [00m [00m                 omx external/gst-openmax/omx/gstomx_core.c:925:FillBufferDone:<omxh264dec0>[00m external/gst-openmax/omx/gstomx_core.c(925)--FillBufferDone FBD: omx_buffer=0x9d1f10, pAppPrivate=0x9d58c0, pBuffer=0x9c9558, flags=00000000, nTimeStamp: 0, nFilledLen=0, portStatus =1,fbd_count = 1
    Line 492: 0:00:06.894439698 [331m 1236[00m   0x9d1fc8 [36mDEBUG  [00m [00m                 omx external/gst-openmax/omx/gstomx_core.c:925:FillBufferDone:<omxh264dec0>[00m external/gst-openmax/omx/gstomx_core.c(925)--FillBufferDone FBD: omx_buffer=0x9da928, pAppPrivate=0x9d5868, pBuffer=0x9d3f18, flags=00000000, nTimeStamp: 0, nFilledLen=0, portStatus =1,fbd_count = 2
    Line 496: 0:00:06.895172120 [331m 1236[00m   0x9d1fc8 [36mDEBUG  [00m [00m                 omx external/gst-openmax/omx/gstomx_core.c:925:FillBufferDone:<omxh264dec0>[00m external/gst-openmax/omx/gstomx_core.c(925)--FillBufferDone FBD: omx_buffer=0x9b6240, pAppPrivate=0x9cb778, pBuffer=0x9d7f88, flags=00000000, nTimeStamp: 0, nFilledLen=0, portStatus =1,fbd_count = 3
    Line 500: 0:00:07.233642579 [331m 1236[00m   0x9d1fc8 [36mDEBUG  [00m [00m                 omx external/gst-openmax/omx/gstomx_core.c:925:FillBufferDone:<omxh264dec0>[00m external/gst-openmax/omx/gstomx_core.c(925)--FillBufferDone FBD: omx_buffer=0x9b65e0, pAppPrivate=0x9cb6c8, pBuffer=0x9b6448, flags=00000000, nTimeStamp: 0, nFilledLen=0, portStatus =1,fbd_count = 4
    Line 741: 0:00:10.188171387 [331m 1236[00m   0x9d1fc8 [36mDEBUG  [00m [00m                 omx external/gst-openmax/omx/gstomx_core.c:925:FillBufferDone:<omxh264dec0>[00m external/gst-openmax/omx/gstomx_core.c(925)--FillBufferDone FBD: omx_buffer=0x9f0d30, pAppPrivate=0x9d5d20, pBuffer=0x9c9558, flags=00000000, nTimeStamp: 0, nFilledLen=4764928, portStatus =1,fbd_count = 5
    Line 745: 0:00:10.526733399 [331m 1236[00m   0x9d1fc8 [36mDEBUG  [00m [00m                 omx external/gst-openmax/omx/gstomx_core.c:925:FillBufferDone:<omxh264dec0>[00m external/gst-openmax/omx/gstomx_core.c(925)--FillBufferDone FBD: omx_buffer=0x9d6e20, pAppPrivate=0x9d5d78, pBuffer=0x9f2500, flags=00000000, nTimeStamp: 0, nFilledLen=0, portStatus =1,fbd_count = 6
    Line 748: 0:00:10.527496339 [331m 1236[00m   0x9d1fc8 [36mDEBUG  [00m [00m                 omx external/gst-openmax/omx/gstomx_core.c:925:FillBufferDone:<omxh264dec0>[00m external/gst-openmax/omx/gstomx_core.c(925)--FillBufferDone FBD: omx_buffer=0x9f2580, pAppPrivate=0x9d5dd0, pBuffer=0x9f1b30, flags=00000000, nTimeStamp: 0, nFilledLen=0, portStatus =1,fbd_count = 7
    Line 751: 0:00:10.528015138 [331m 1236[00m   0x9d1fc8 [36mDEBUG  [00m [00m                 omx external/gst-openmax/omx/gstomx_core.c:925:FillBufferDone:<omxh264dec0>[00m external/gst-openmax/omx/gstomx_core.c(925)--FillBufferDone FBD: omx_buffer=0x9f1848, pAppPrivate=0x9d5e28, pBuffer=0x9f2370, flags=00000000, nTimeStamp: 0, nFilledLen=0, portStatus =1,fbd_count = 8
    Line 977: 0:00:13.872467042 [331m 1236[00m   0x9d1fc8 [36mDEBUG  [00m [00m                 omx external/gst-openmax/omx/gstomx_core.c:925:FillBufferDone:<omxh264dec0>[00m external/gst-openmax/omx/gstomx_core.c(925)--FillBufferDone FBD: omx_buffer=0x9d7fa8, pAppPrivate=0x9d5ed8, pBuffer=0x9f2500, flags=00000200, nTimeStamp: 0, nFilledLen=4764928, portStatus =0,fbd_count = 9

 Is  this  the reason  the display  is slowness? But  the  FilledLen  of the other  buffers  are  not  zero   they   are  slowness  too.

3)  In  the FillBufferDone function    some  pBuffers'  address  are  same   and  the  timestamp  is  chaos. eg:

    Line 13603: 0:03:58.428222657 [331m 1236[00m   0x9d1fc8 [36mDEBUG  [00m [00m                 omx external/gst-openmax/omx/gstomx_core.c:925:FillBufferDone:<omxh264dec0>[00m external/gst-openmax/omx/gstomx_core.c(925)--FillBufferDone FBD: omx_buffer=0x9d6e20, pAppPrivate=0xa20058, pBuffer=0x404b73c5, flags=00000100, nTimeStamp: 13080000, nFilledLen=4764928, portStatus =0,fbd_count = 335
    Line 13662: 0:03:59.112182618 [331m 1236[00m   0x9d1fc8 [36mDEBUG  [00m [00m                 omx external/gst-openmax/omx/gstomx_core.c:925:FillBufferDone:<omxh264dec0>[00m external/gst-openmax/omx/gstomx_core.c(925)--FillBufferDone FBD: omx_buffer=0x9d7fa8, pAppPrivate=0xa200b0, pBuffer=0x404b73c5, flags=00000100, nTimeStamp: 13120000, nFilledLen=4764928, portStatus =0,fbd_count = 336
    Line 13679: 0:03:59.802124024 [331m 1236[00m   0x9d1fc8 [36mDEBUG  [00m [00m                 omx external/gst-openmax/omx/gstomx_core.c:925:FillBufferDone:<omxh264dec0>[00m external/gst-openmax/omx/gstomx_core.c(925)--FillBufferDone FBD: omx_buffer=0x9f1848, pAppPrivate=0xa1ff88, pBuffer=0x404b73c5, flags=00000300, nTimeStamp: 13000000, nFilledLen=4764928, portStatus =0,fbd_count = 337

    if  the timestamp  is  chaos,i  think  the  display  will be chaos,but  the suface  show  the picture  is right.

4)   I  find   the  number of  EmptyBufferDone be called  is 704  and  the FillBufferDone  is  718.why  is the FillBufferDone  more  than  EmptyBufferDone?

all  of  above  is in the file  8080.putty2.log.txt

I  find  that   the  dup  message  appears   many 

begin

ret = ok

end   

in   the  output_loop  (gstomx_base_filter.c) in the android 2.3    but  none  in the ics 4.0.3  .the message  in the ics 4.0.3  dup  is

begin >> omx_state=3, ready=1

end

Why  does the 2.3 not  show  the message as  ics?

regards,

Thank you very much!

Aaron  Pope

Meantime I take a look at the log, could you check GST code for buffers queues to be flushed? in previous log I saw that some flush are made before buffer processing and after last OMX_StatePaused command, this OMX_CommandFlush  commands can increase the number of buffers (4), and make final count between EBD and FBD different, and cause duplicated buffers in queues, plus returned buffers are zero length and zero timestamps too.

Hi,Manuel

I have  check the gst-openmax code.I think  the function  "g_omx_port_flush" (gstomx_port.c)  is for flush buffers queues.but in this  function,the async_queue_pop_full  return null  and does not set the length zero . After that , it call the OMX_SendCommand send the command to  PROXY_VIDDEC_SendCommand(omx_proxy_videodec.c)--PROXY_SendCommand(omx_proxy_common.c)--RPC_SendCommand(omx_rpc_stub.c) .  In this caller sequence, have not deal with the  OMX_CommandFlush  command. so  where  will  deal with this  command ?

Thank you very much!

Aaron