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.

DRA746: Video seetk fail or hang.

Part Number: DRA746

Hi TI team,

There are two similar tickets(Seek failed and Seeck hang) in our side. We see a lot of memory alocate issue, and confirmed with MMT system team they configure the memory as TI suggestion. could you please help to check from your POV. Thanks.
Attach the logs here. Seek issue.rar
And videos to link transfer.harman.com/.../KmD5iaIi5J3YtJNOoiTQ3A .

Ticket 1: Seek failed
In seek_failed.txt, there are many memory allocate and ducati error when do seek for video file Raghu Dixit - Gudugudiya Sedi Nodo Cowshed Glastonbury 2011.mp4:
96869 2019/11/13 19:49:39.000000 1064.8214 68 ECU1 CrM API 2421 log info verbose 1 T8918 GSTLogs WARN ducati gstducatividdec.c(1483):gst_ducati_viddec_chain:<decoder> push from codec_process failed flushing
96877 2019/11/13 19:49:39.000000 1064.8347 69 ECU1 CrM API 2421 log info verbose 1 T2561 GSTLogs WARN ducati gstducatividdec.c(571):codec_process:<decoder> err=-1, extendedError=00040000
96878 2019/11/13 19:49:39.000000 1064.8348 70 ECU1 CrM API 2421 log info verbose 1 T2561 GSTLogs ERROR ducati gstducati.c(61):gst_ducati_log_extended_error_info: Bit 18 (00040000): stream end
96879 2019/11/13 19:49:39.000000 1064.8372 71 ECU1 CrM API 2421 log info verbose 1 T9651 GSTLogs WARN basesink gstbasesink.c(3374):gst_base_sink_chain_unlocked:<asink> warning: Internal data flow problem.
96880 2019/11/13 19:49:39.000000 1064.8373 72 ECU1 CrM API 2421 log info verbose 1 T9651 GSTLogs WARN basesink gstbasesink.c(3374):gst_base_sink_chain_unlocked:<asink> warning: Received buffer without a new-segment. Assuming timestamps start from 0.
96884 2019/11/13 19:49:39.000000 1064.8389 76 ECU1 CrM API 2421 log info verbose 1 T2561 GSTLogs WARN ducati gstducatividdec.c(571):codec_process:<decoder> err=-1, extendedError=00040000
96885 2019/11/13 19:49:39.000000 1064.8390 77 ECU1 CrM API 2421 log info verbose 1 T2561 GSTLogs ERROR ducati gstducati.c(61):gst_ducati_log_extended_error_info: Bit 18 (00040000): stream end
96886 2019/11/13 19:49:39.000000 1064.8404 78 ECU1 CrM API 2421 log error verbose 1 T2561 CgstPlayerApi::seek(): Seek failed
96887 2019/11/13 19:49:39.000000 1064.8404 101 ECU1 CrM CoMN 2421 log info verbose 1 T2561 HResult: Unknown
96888 2019/11/13 19:49:39.000000 1064.8405 110 ECU1 CrM HMPE 2421 log error verbose 1 T2561 CURIPlayer::SeekTo(): Seek failed
97094 2019/11/13 19:49:39.000000 1064.9337 91 ECU1 CrM API 2421 log info verbose 1 T8918 GSTLogs WARN waylandsink wlvideoformat.c(102):gst_wl_shm_format_to_video_format: gst video format not found
97097 2019/11/13 19:49:39.000000 1064.9466 94 ECU1 CrM API 2421 log info verbose 1 T8918 GSTLogs WARN waylandsink wlvideoformat.c(102):gst_wl_shm_format_to_video_format: gst video format not found
97112 2019/11/13 19:49:39.000000 1064.9568 95 ECU1 CrM API 2421 log info verbose 1 T9647 GSTLogs WARN bufferpool gstbufferpool.c(300):do_alloc_buffer:<vpebufferpool17> alloc function failed
97113 2019/11/13 19:49:39.000000 1064.9568 96 ECU1 CrM API 2421 log info verbose 1 T9650 GSTLogs WARN basesink gstbasesink.c(3374):gst_base_sink_chain_unlocked:<vsink> warning: Internal data flow problem.
97114 2019/11/13 19:49:39.000000 1064.9570 97 ECU1 CrM API 2421 log info verbose 1 T9650 GSTLogs WARN basesink gstbasesink.c(3374):gst_base_sink_chain_unlocked:<vsink> warning: Received buffer without a new-segment. Assuming timestamps start from 0.
97118 2019/11/13 19:49:39.000000 1064.9675 101 ECU1 CrM API 2421 log info verbose 1 T9647 GSTLogs WARN bufferpool gstbufferpool.c(300):do_alloc_buffer:<vpebufferpool17> alloc function failed

Ticket 2: Seek hang
In Seek_hang.txt, seek was hang when play file: NaJa (Full Song) - Pav Dharia - Latest Punjabi Songs - White Hill Music.mp4, found many allocate error in the logs:
151596 2019/11/14 17:25:04.000000 5419.0772 93 ECU1 CrM API 2488 log info verbose 1 T4330 GSTLogs WARN bufferpool gstbufferpool.c(300):do_alloc_buffer:<vpebufferpool1> alloc function failed
151759 2019/11/14 17:25:04.000000 5419.2259 94 ECU1 CrM API 2488 log info verbose 1 T4330 GSTLogs WARN bufferpool gstbufferpool.c(300):do_alloc_buffer:<vpebufferpool1> alloc function failed
151760 2019/11/14 17:25:04.000000 5419.2367 95 ECU1 CrM API 2488 log info verbose 1 T4330 GSTLogs WARN bufferpool gstbufferpool.c(300):do_alloc_buffer:<vpebufferpool1> alloc function failed
152369 2019/11/14 17:25:06.000000 5420.6470 152 ECU1 CrM HMPE 2488 log info verbose 1 T2729 CURIPlayer::seekTo() pos: 233000
152370 2019/11/14 17:25:06.000000 5420.6470 153 ECU1 CrM HMPE 2488 log info verbose 1 T2729 CURIPlayer::seekTo() playstate is 3, not cover targetPlayState:0

  • Hi Vicky,

    I am downloading the videos.

    Can you explain me what is seek failed issue here? Are you not able to seek? or not able to resume?

    Does the hang happens for the first seek itself or you have to try multiple seeks? 

    The warnings for alloc failure are normal, will be observe during normal working seek also.

    Thanks

    Ram

  • Hi Ram,

    Thanks for your analysis.

    Next action, we will increate the gStreamer to level 4 and reproduce this ticket to get more logs. Whether the level 4 gStreamer logs enough for you to do further analysis? 

    Thanks.

  • Hi Vicky,

    I tried to reproduce the issue with gst-play-1.0 application and seek operations with Left and Right Arrows on key-board.

    I tried multiple times but could not see any hang for both the streams.

    When you try to reproduce the issue next time please make sure if VIDDEC3_process in gst-ducati plugin is returning or not. If there is hang for some reason,

    this call may not be returning .

    then also check cat /sys/kernel/debug/remoteproc/remoteproc1/trace0 when this issue happens to collect IPUMM log, this should show some traces if the hang is inside VIDDEC3_process.

    Thanks

    RamPrasad

  • Hi RamPrasad,

    For the issue "seek hang", we can't reproduce it, and once it is reproduced, I will provide the logs.
    For the issue "seek failed", we can reproduce it now. Let me share the steps.
    Steps:
    1. Play with the video in the link I shared "Raghu Dixit - Gudugudiya Sedi Nodo Cowshed Glastonbury 2011.mp4". The duration is 330256000.
    2. Seek to 330000000, nearly the end of the video. We use the API gst_element_seek_simple.
    Behavior:
    Got error return from the API.
    Additional:
    We find an old similar issue, which fixed from TI and integrated in our project, ticket has been verified.

    My questions: 
    Why the issue here again? whether they are the same root cause?

    May I know what should be the expected behavior when seek to the end? Whether TI will report EOS message when seek to the end?

    Please provide the comments from your POV. Thanks.

    Logs:
    hardware decoder report “reach end”, the error is:
    96877 2019/11/13 19:49:39.000000 1064.8347 69 ECU1 CrM API 2421 log info verbose 1 T2561 GSTLogs WARN ducati gstducatividdec.c(571):codec_process:<decoder> err=-1, extendedError=00040000
    96878 2019/11/13 19:49:39.000000 1064.8348 70 ECU1 CrM API 2421 log info verbose 1 T2561 GSTLogs ERROR ducati gstducati.c(61):gst_ducati_log_extended_error_info: Bit 18 (00040000): stream end
    96879 2019/11/13 19:49:39.000000 1064.8372 71 ECU1 CrM API 2421 log info verbose 1 T9651 GSTLogs WARN basesink gstbasesink.c(3374):gst_base_sink_chain_unlocked:<asink> warning: Internal data flow problem.
    96880 2019/11/13 19:49:39.000000 1064.8373 72 ECU1 CrM API 2421 log info verbose 1 T9651 GSTLogs WARN basesink gstbasesink.c(3374):gst_base_sink_chain_unlocked:<asink> warning: Received buffer without a new-segment. Assuming timestamps start from 0.
    96881 2019/11/13 19:49:39.000000 1064.8376 73 ECU1 CrM API 2421 log debug verbose 1 T2421 CgstBasePlayer::gstBusCallback()(default) Got reset-time message from Element "vsink"
    96882 2019/11/13 19:49:39.000000 1064.8380 74 ECU1 CrM API 2421 log debug verbose 1 T2421 CgstBasePlayer::gstBusCallback()(default) Got reset-time message from Element "asink"
    96883 2019/11/13 19:49:39.000000 1064.8381 75 ECU1 CrM API 2421 log warn verbose 1 T2421 CgstPlayerApi::gstBusCallback() WARNING: Got warning message from Element "asink", Internal data flow problem. Debug Info:[/home/buildserver/work/jenkins/var/lib/jenkins/workspace/SDK2-sstate-cache-Build/project/elina-distro/build_sstate_cache/tmp/work/cortexa15hf-vfp-neon-elina-linux-gnueabi/gstreamer1.0/1.6.3-r0/gstreamer-1.6.3/libs/gst/base/gstbasesink.c(3374): gst_base_sink_chain_unlocked (): /GstPlayBin:URI Pipeline/GstPlaySink:playsink/GstBin:abin/GstAlsaSink:asink: Received buffer without a new-segment. Assuming timestamps start from 0.]
    96884 2019/11/13 19:49:39.000000 1064.8389 76 ECU1 CrM API 2421 log info verbose 1 T2561 GSTLogs WARN ducati gstducatividdec.c(571):codec_process:<decoder> err=-1, extendedError=00040000
    96885 2019/11/13 19:49:39.000000 1064.8390 77 ECU1 CrM API 2421 log info verbose 1 T2561 GSTLogs ERROR ducati gstducati.c(61):gst_ducati_log_extended_error_info: Bit 18 (00040000): stream end

  • Hi Vicky,

    Thanks for updates. I tried to reproduce the issue with a sample application gsttestplayer to seek to 330 seconds then resume playback, I am not seeing any issue. 

    I am still not able to understand what is meant by seek failure here. Does the resume fail? 

    Error 0x40000 tells that it is the End of stream and there are no more frames to decode.

    Thanks

    RamPrasad

  • Hi RamPrasad,

    Seek failed means when the seeek failed, resume is also failed, could you resume success on your side?

    When seek to the end of the stream, will TI report any EOS message so that we can handle the upper logic such as switch to the next file in the playlist? 

    One more question, We received many patch from your side, is there any way that we can check the version applied on our target(MMT)? If not, could you help to share the newest files(libgstvpe.so & libgstducati.so) to us again? Thanks.

  • Hi Vicky,

    Harman India keeps all patches in their yocto recipes. 

    Can you please check with Harman India team?

    Thanks

    RamPrasad

  • Hi Ramprasad,

    Could you seek to 330 seconds success for file "Raghu Dixit - Gudugudiya Sedi Nodo Cowshed Glastonbury 2011.mp4", I tried in VLC player, it success. I don't know what is the difference. if user seek to the file end fail, the play position will not update, it seems not friendly for user, could you help to give some advice? thanks.

  • Hi Vicky,

    On EVM , I am trying to reproduce with gst-play to seek to 330seconds but did not show any issue.

    Can you check if you have applied this patch vpe_handle_EOS.patch mentioned here?

    I guess I have suggested this patch for one of the similar issue reported by you.

    Ram

  • Hi Ram,

    Thanks for the info, we have asked system team to check about the patch.

    During reproducing, tester found another issue, could you please check from you POV? It is about stuck issue. Thanks.

    Seems it is once issue, little related logs, not sure whether it is helpfule. The file is uploaded to  .

    Reproduce steps:
    1)Play "Jimikki Kammal Mohanlal Dance Video Song HD - Velipadinte Pusthakam - Lal Jose.mp4", it is corrupt file.
    2)Then tester try to play another track.
    Before start the new track, we will do stop first by call “gst_element_set_state(mPipeline, GST_STATE_NULL);” it was stuck.

    The logs,
    255967 2019/12/03 18:28:26.000000 104.2145 230 ECU1 CrM API 2451 log info verbose 1 T2598 CgstPlayerApi:stopAsync() set state to stop
    256255 2019/12/03 18:28:26.000000 104.2488 205 ECU1 CrM API 2451 log info verbose 1 T2598 GSTLogs INFO GST_STATES gstbin.c(2707):gst_bin_change_state_func:<ducatih264decvpe0> child 'vpe' changed state to 2(READY) successfully
    256256 2019/12/03 18:28:26.000000 104.2489 206 ECU1 CrM API 2451 log info verbose 1 T2598 GSTLogs INFO GST_STATES gstbin.c(2243):gst_bin_element_set_state:<decoder> current PAUSED pending VOID_PENDING, desired next READY
    =>It stuck without any more status changed

  • Hi Vicky,

    I did not see any issue with Jimikki stream. Is there any way to reproduce the issue?

    Thanks

    Ram

  • Hi Ram,

    Any comments for last issue? Thanks.

  • Hi Vicky,

    I did n't see any issue with Jimmiki. video. Are you seeing the issue consistently.

    Please share how to reproduce the issue? where to seek etc.

    RamPrasad

  • Hi Ram,

    It is difficult to reproduce I think.
    The steps, play a corrupt file, get play error. Then call gst_element_set_state(mPipeline, GST_STATE_NULL), stuck.

    I wander whether we can collect all the useful logs for TI side to do further analysis? Or the issues must be reporduced in TI side before analysis?
    If we can collect the logs, could you please list the requirement for the logs, such as enable gstreamer level, etc.
    Then we can prepare all the logs for you for the sometimes/once issues.

    Thanks.

  • Hi Vicky,

    We need to first identify if the issue is with ducati, vpe or any other element. For this you need to enable logs for these two elements and reproduce the issue.

    Please share me the logs if you can reproduce again.

    Thanks

    RamPrasad