PROCESSOR-SDK-DRA7X: DRA744: No surface creation during gstreamer playback

6590392

Prodigy 10 points

Part Number: PROCESSOR-SDK-DRA7X

Hi Ti Team,

Please refer below past references for this Issue, this ticket is reopened again.

https://e2e.ti.com/support/processors/f/791/t/927586
e2e.ti.com/.../913442
e2e.ti.com/.../899304

Issue: Issue was seen in Decoder (check previous TI tickets for Reference).

BR,

Prnav.

over 3 years ago

0 6590392 over 3 years ago

Prodigy 10 points

Link to Logs:

transfer.harman.com/.../iLh2HDX8MU2oHHJDOyXC9c

0 Shashikiran Bhagavath1 over 3 years ago in reply to 6590392

Prodigy 100 points

More details:

Full Log is Available @ https://transfer.harman.com/link/VB5y6ksqoNoMiPb6VPfp8J

1. Issue happened with cppres (CarPlay service)with PID 2196.

2. Video data which was pushed is available as Video_Dump_40350765928.h264. iPhone pushed only one frame here.

3. Size of the Video frame 27330 bytes.

4. HW Decoder got stuck around below mentioned logs in "journal.log"

Mar 22 00:00:40 mmt2020-a880 cppres[2196]: 0:00:49.806868437 [331m 2196[00m 0x23af80 [33;01mLOG [00m [00;01;42m GST_BUFFER gstbuffer.c:212:_get_merged_memory:[00m buffer 0xaed69c18, idx 0, length 1
Mar 22 00:00:40 mmt2020-a880 cppres[2196]: 0:00:49.806907240 [331m 2196[00m 0x23af80 [37mDEBUG [00m [00m ducati gstducatividdec.h:229:push_input:<vpudecoder>[00m push: 27330 bytes)
Mar 22 00:00:40 mmt2020-a880 cppres[2196]: 0:00:49.903278587 [331m 2196[00m 0x23af80 [33;01mLOG [00m [00;01;42m GST_BUFFER gstbuffer.c:641:_gst_buffer_free:[00m finalize 0xaed69c18
Mar 22 00:00:40 mmt2020-a880 cppres[2196]: 0:00:49.903398046 [331m 2196[00m 0x23af80 [37mDEBUG [00m [00;01;34m GST_MEMORY gstmemory.c:87:_gst_memory_free:[00m free memory 0xaeda8ab8
Mar 22 00:00:40 mmt2020-a880 cppres[2196]: 0:00:49.903484632 [331m 2196[00m 0x23af80 [37mDEBUG [00m [00m ducati gstducatividdec.c:556:codec_process:<vpudecoder>[00m dce_buf_lock(inputID: aed68378, fd: 125)

5. User had entered with CarPlay screen multiple times. Data given by iPhone for each such instance is stored in a different file. We observe a black screen with all these contents (Decoding not successful). There was no recovery for Hardware decoder side with multiple attempts.

Video_Dump_73734213246.h264
Video_Dump_75390875970.h264
Video_Dump_88699630996.h264
Video_Dump_103036963672.h264
Video_Dump_104680074740.h264
Video_Dump_109596012514.h264
Video_Dump_137781870856.h264
Video_Dump_204218852281.h264
Video_Dump_231049553581.h264
Video_Dump_240364078528.h264

6. After unsuccessful CarPlay decoding, the user had tried to play the video file (mp4) from a USB source. Still, there was no recovery. Video playback was unsuccessful.

7. dmesg*, ipu2state*, iputrace*, interrupts* logs are taken before and after trying video file playback from USB.

0 Shashikiran Bhagavath1 over 3 years ago in reply to Shashikiran Bhagavath1

Prodigy 100 points

In the working case, we see "viddec3_process took <XX> ms" logs. Here we don't see such logs.

0 Karthik Ramanan over 3 years ago in reply to Shashikiran Bhagavath1

TI__Guru** 113800 points

HI Shashi,

Thank you for the detailed post.

I would like to understand a few additional points:

From the attached log, I understand that cppress 2196 corresponds to the carplay instance of the failing case and it is clear that the VIDDEC3_process call did not return. However, how can I see the logs of the decode instance that was launched following this failure - I'm expecting to see some codec_create logs following this but this is missing. What is the path for this playback, my understanding is that this is also via GStreamer - please confirm.
IPUMM state is running and therefore it is a bit strange that the Ducati is not returning, hence #1 will be important.
We are in parallel trying to analyze the Video dump as well to see if this problem is originating from the Video stream and we can have a way to handle this - this is under analysis (our standalone test setup was not accessible remotely).
The journal log seems to be across reboots, were there any abnormal shutdown of the device during a carplay session - I don't see matching create/delete calls from the logs (not very important) but just an observation.
Also, this is not important for the moment, do you have the ability to connect JTAG on this board?

Regards

Karthik

0 Shashikiran Bhagavath1 over 3 years ago in reply to Karthik Ramanan

Prodigy 100 points

Hi Karthik,

I can answer for #1 and #4 Please find answers to your query below:

1. Playback is through Gstreamer. CarPlay will push the Frame Data to Gstreamer "appSrc" element. It is not through local file playback. It is through buffer push.

4. We are keeping the pipeline alive all the time and the CarPlay application is running as a service all the time. So during the ignition cycle, systems will just kill the carplay service. Hence delete logs are not captured.

Regards,

Shashikiran

0 Karthik Ramanan over 3 years ago in reply to Shashikiran Bhagavath1

TI__Guru** 113800 points

Hi Shashi,

Thank you. Can you please comment further on #1,

On #1, I would like to know how to differentiate logs between Carplay and normal playback.

#4 - thanks this is clear.

Please get back to me on the other questions as well.

Regards

Karthik

0 Karthik Ramanan over 3 years ago in reply to Karthik Ramanan

TI__Guru** 113800 points

Further updates:

On #3, we have analyzed the video and the video looks good. We can rule out the frame being incorrect.

I have another observation, will record it as #6.

6. There is a flush call right after the codec_process call which seems a little suspicious.

Please look the journal.log with the line number:

2240244 Mar 22 00:00:40 mmt2020-a880 cppres[2196]: 0:00:49.903278587 ^[[331m 2196^[[00m 0x23af80 ^[[33;01mLOG ^[[00m ^[[00;01;42m GST_BUFFER gstbuffer.c:641:_gst_buffer_free:^[[00m finalize 0xaed69c18
2240245 Mar 22 00:00:40 mmt2020-a880 cppres[2196]: 0:00:49.903398046 ^[[331m 2196^[[00m 0x23af80 ^[[37mDEBUG ^[[00m ^[[00;01;34m GST_MEMORY gstmemory.c:87:_gst_memory_free:^[[00m free memory 0xaeda8ab8
2240246 Mar 22 00:00:40 mmt2020-a880 cppres[2196]: 0:00:49.903484632 ^[[331m 2196^[[00m 0x23af80 ^[[37mDEBUG ^[[00m ^[[00m ducati gstducatividdec.c:556:codec_process:<vpudecoder>^[[00m dce_buf_lock(inputID: aed68378, f d: 125)
2240247 Mar 22 00:00:40 mmt2020-a880 cppres[2196]: 0:00:50.243270183 ^[[331m 2196^[[00m 0x25dfa0 ^[[37mDEBUG ^[[00m ^[[00;01;34m GST_EVENT gstevent.c:302:gst_event_new_custom:^[[00m creating new event 0xaed4a800 flush-sta rt 2563
2240248 Mar 22 00:00:40 mmt2020-a880 cppres[2196]: 0:00:50.243393539 ^[[331m 2196^[[00m 0x25dfa0 ^[[37mDEBUG ^[[00m ^[[00;01;37;41m GST_ELEMENT_PADS gstelement.c:1562:gst_element_send_event:^[[00m send flush-start event on eleme nt dec-pipeline

Regards

Karthik

0 Shashikiran Bhagavath1 over 3 years ago in reply to Karthik Ramanan

Prodigy 100 points

Hi Karthik,

On #1:

CarPlay uses the following pipeline with appropriate caps filters regarding input to the decoder.

appSrc ! ducatih264dec ! waylandsink

Video Playback use case from media player uses

gst-launch-1.0 -v playbin uri=file:///tmp/USB3-1.3-sda1/BigRabitVideo_720x480_20mb.mp4

We got streamer logs for video playback failure after seeing a blank screen with the CarPlay use case. Failure is as follows.

MmRpc_create: Error: connect failed
0:00:05.339005938 11365 0xb4804090 ERROR ducati gstducatividdec.c:148:engine_open:<decoder> could not create engine
0:00:05.339066430 11365 0xb4804090 ERROR ducati gstducatividdec.c:1640:gst_ducati_viddec_change_state:<decoder> could not open

Another observation is, even "gst-inspect-1.0 ducatih264dec" fails to provide the complete information in this particular use case.

Full logs, Code snippet of the failure return portion are available @

https://transfer.harman.com/link/0v0GnOdXlAOzDKrAfpVy43

Hope this gives some clues. At this moment, all logs are not there. We are trying to get complete logs (CarPlay failure logs and VideoPlayback failure logs)

Regards,

Shashikiran

0 Shashikiran Bhagavath1 over 2 years ago in reply to Shashikiran Bhagavath1

Prodigy 100 points

Hi Karthik,

New set of logs are present @ https://transfer.harman.com/link/5h3fGSZyVnr9aFfP2PoKET

Analysis from Harman side:

CarPlay screen switch was tried after 91 sec of ignition cycle.
CPU load was 30% before swtitching
During initial playback it shoots to 88% and settles down to 68 to 72% during carplay usecase.

1. No surface creation log:
carplay_Blackscreen.DLT:
280898 2021/04/19 15:29:31.000000 91.4302 46 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:00.813159 AM [CarPlay][DevCtrl] CarPlay Session created
280907 2021/04/19 15:29:31.000000 91.4537 54 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:00.836701 AM [CarPlay][DevCtrl] CarPlay Session is UP and RUNNING with IP: 172.16.222.100, on Transport: WiFi
280922 2021/04/19 15:29:31.000000 91.4544 55 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:00.837350 AM [CarPlay][DevCtrl] CarPlay Session is ready to start iAP2 on Wi-Fi
285925 2021/04/19 15:29:32.000000 92.3960 83 ECU1 CPPR PF 2037 log warn verbose 1 2021-04-06 12:01:01.778991 AM [CarPlay][ScreenStream] Video dump file is available at /tmp//Video_Dump_92395964050.h264
286206 2021/04/19 15:29:32.000000 92.4946 85 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:01.877584 AM [CarPlay][ScreenStream] FrameNo 1 len 853 at 92494648823
286379 2021/04/19 15:29:32.000000 92.5159 86 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:01.898843 AM [CarPlay][ScreenStream] FrameNo 2 len 125 at 92515906473
286523 2021/04/19 15:29:32.000000 92.5380 87 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:01.920924 AM [CarPlay][ScreenStream] FrameNo 3 len 3982 at 92537986607
286655 2021/04/19 15:29:32.000000 92.5693 88 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:01.952243 AM [CarPlay][ScreenStream] FrameNo 4 len 6694 at 92569306036
286713 2021/04/19 15:29:32.000000 92.6051 89 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:01.987950 AM [CarPlay][ScreenStream] FrameNo 5 len 9315 at 92605011874
286762 2021/04/19 15:29:32.000000 92.6396 90 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:02.022548 AM [CarPlay][ScreenStream] FrameNo 6 len 17848 at 92639609206
286843 2021/04/19 15:29:32.000000 92.6762 91 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:02.059115 AM [CarPlay][ScreenStream] FrameNo 7 len 23000 at 92676178194
286886 2021/04/19 15:29:32.000000 92.7129 92 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:02.095865 AM [CarPlay][ScreenStream] FrameNo 8 len 24176 at 92712923065
286948 2021/04/19 15:29:32.000000 92.7481 93 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:02.131068 AM [CarPlay][ScreenStream] FrameNo 9 len 27393 at 92748129550
287107 2021/04/19 15:29:32.000000 92.7824 94 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:02.165372 AM [CarPlay][ScreenStream] FrameNo 10 len 25168 at 92782434591
287285 2021/04/19 15:29:32.000000 92.8156 95 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:02.198478 AM [CarPlay][ScreenStream] FrameNo 11 len 27364 at 92815539456
287449 2021/04/19 15:29:32.000000 92.8503 96 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:02.233176 AM [CarPlay][ScreenStream] FrameNo 12 len 30653 at 92850236253
287628 2021/04/19 15:29:32.000000 92.8834 97 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:02.266319 AM [CarPlay][ScreenStream] FrameNo 13 len 31670 at 92883380938
287657 2021/04/19 15:29:32.000000 92.9145 98 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:02.297372 AM [CarPlay][ScreenStream] FrameNo 14 len 31386 at 92914429765
287699 2021/04/19 15:29:32.000000 92.9488 99 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:02.331684 AM [CarPlay][ScreenStream] FrameNo 15 len 29771 at 92948747853
287894 2021/04/19 15:29:32.000000 92.9779 100 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:02.360791 AM [CarPlay][ScreenStream] FrameNo 16 len 25937 at 92977852644
287911 2021/04/19 15:29:32.000000 93.0147 101 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:01:02.397600 AM [CarPlay][ScreenStream] FrameNo 17 len 33123 at 93014663598
288200 2021/04/19 15:29:33.000000 93.0599 50 ECU1 LMGR IMPL 1048 log info verbose 1 CLMStub::showLayerList LayerName = MMTCARPLAYLAYER
288208 2021/04/19 15:29:33.000000 93.0602 58 ECU1 LMGR IMPL 1048 log info verbose 1 CLMStub::showLayerList Setting layer MMTCARPLAYLAYER [1003] visibility to true
288304 2021/04/19 15:29:33.000000 93.0678 65 ECU1 LMGR LMCH 1048 log debug verbose 1 Layer MMTCARPLAYLAYER Visibility :1
288306 2021/04/19 15:29:33.000000 93.0678 78 ECU1 LMGR IMPL 1048 log info verbose 1 CLMStub::layerPropertyNotification: firing LayerVisibilityUpdate for layer = MMTCARPLAYLAYER, Id = 1003, visibility = 1 ....

2. CarPlay service PID is 2037

3. Jouranl log reference:
journal.txt
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494107411 [334m 2037[00m 0xa8a05180 [37mDEBUG [00m [00m ducati gstducatividdec.c:230:codec_create:[00m Codec version H264VDEC_TI DEV.500.V.H264AVC.D.HP.IVAHD.02.00.21.01
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494502725 [334m 2037[00m 0xa8a05180 [37mDEBUG [00m [00m GST_META gstmeta.c:87:gst_meta_api_type_register:[00m register API "GstMetaDucatiBufferPrivAPI"
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494577789 [334m 2037[00m 0xa8a05180 [37mDEBUG [00m [00m GST_META gstmeta.c:94:gst_meta_api_type_register:[00m adding tag "ducatibufferpriv"
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494652345 [334m 2037[00m 0xa8a05180 [37mDEBUG [00m [00m GST_META gstmeta.c:192:gst_meta_register:[00m register "GstMetaDucatiBufferPriv" implementing "GstMetaDucatiBufferPrivAPI" of size 20
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494693181 [334m 2037[00m 0xa8a05180 [37mDEBUG [00m [00;01;42m GST_BUFFER gstbuffer.c:2089:gst_buffer_add_meta:[00m alloc metadata 0x1937c4 (GstMetaDucatiBufferPriv) of size 20
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494732492 [334m 2037[00m 0xa8a05180 [37mDEBUG [00m [00;04m default gstducatibufferpriv.c:52:ducatibufferpriv_init_func:[00m init called on buffer 0xa8a2e690, meta 0x1937c4
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494774853 [334m 2037[00m 0xa8a05180 [33;01mLOG [00m [00;01;42m GST_BUFFER gstbuffer.c:1637:gst_buffer_map_range:[00m buffer 0xa8a2e050, idx 0, length -1, flags 0001
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494818231 [334m 2037[00m 0xa8a05180 [33;01mLOG [00m [00;01;42m GST_BUFFER gstbuffer.c:212:_get_merged_memory:[00m buffer 0xa8a2e050, idx 0, length 1
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494873639 [334m 2037[00m 0xa8a05180 [37mDEBUG [00m [00m ducati gstducatividdec.h:229:push_input:<vpudecoder>[00m push: 853 bytes)
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.502068080 [334m 2037[00m 0xa8a05180 [33;01mLOG [00m [00;01;42m GST_BUFFER gstbuffer.c:641:_gst_buffer_free:[00m finalize 0xa8a2e050
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.502135349 [334m 2037[00m 0xa8a05180 [37mDEBUG [00m [00;01;34m GST_MEMORY gstmemory.c:87:_gst_memory_free:[00m free memory 0xa8a2c158
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.502184658 [334m 2037[00m 0xa8a05180 [37mDEBUG [00m [00m ducati gstducatividdec.c:556:codec_process:<vpudecoder>[00m dce_buf_lock(inputID: a8a2e690, fd: 136)

4. Flush event sent late:
dlt: (374.926 - 92.494 = 282.432 sec)
445939 2021/04/19 15:34:14.000000 374.8363 84 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:05:44.219239 AM [CarPlay][ScreenStream] FrameNo 1417 len 1743 at 374836298474
446035 2021/04/19 15:34:14.000000 374.9250 92 ECU1 CPPR PF 2037 log info verbose 1 2021-04-06 12:05:44.307970 AM [CarPlay][ScreenStream] sent flush-start event successfully
446164 2021/04/19 15:34:15.000000 375.0766 96 ECU1 LMGR IMPL 1048 log info verbose 1 CLMStub::showLayerList Setting layer MMTCARPLAYLAYER [1003] visibility to false
446229 2021/04/19 15:34:15.000000 375.0870 69 ECU1 LMGR LMCH 1048 log debug verbose 1 Layer MMTCARPLAYLAYER Visibility :0

journal log: (5:52.831 - 1:10.502 = 282.329 sec)
Apr 06 00:05:44 mmt2020-a880 cppres[2037]: 0:05:52.831807821 [334m 2037[00m 0x9f310ca0 [33;01mLOG [00m [00m ducati gstducatividdec.c:1581:gst_ducati_viddec_event:<vpudecoder>[00m end

5. Video dump file, where blank screen is seen Video_Dump_92395964050.h264

6. VideoPlayback failure: MediaOneService PID is 2206.
DLT:
482971 2021/04/19 15:34:51.000000 411.4099 156 ECU1 CrM API 2206 log info verbose 1 T2304 CgstPlayerApi:waitFor() Wait for NULL
482973 2021/04/19 15:34:51.000000 411.4101 158 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[NULL] pending:[VOID_PENDING] ret = 1
482975 2021/04/19 15:34:51.000000 411.4101 159 ECU1 CrM API 2206 log info verbose 1 T2304 CgstPlayerApi:waitFor() Wait for NULL
482977 2021/04/19 15:34:51.000000 411.4102 161 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[NULL] pending:[VOID_PENDING] ret = 1
482991 2021/04/19 15:34:51.000000 411.4108 162 ECU1 CrM API 2206 log info verbose 1 T2304 CgstPlayerApi:playAsync() set state to playing
483018 2021/04/19 15:34:51.000000 411.4131 189 ECU1 CrM API 2206 log debug verbose 1 T2206 CgstPlayerApi::gstBusCallback() Got state-changed message: Element "URI Pipeline" state NULL --> READY
483081 2021/04/19 15:34:51.000000 411.4235 241 ECU1 CrM API 2206 log debug verbose 1 T2206 CgstPlayerApi::gstBusCallback()(default) Got stream-status message from Element "sink", type: 0, owner: typefind, object type: GstTask, value: 0xb256d8d0
483091 2021/04/19 15:34:51.000000 411.4243 250 ECU1 CrM API 2206 log debug verbose 1 T2206 CgstPlayerApi::gstBusCallback()(default) Got stream-status message from Element "sink", type: 1, owner: typefind, object type: GstTask, value: 0xb256d8d0
483227 2021/04/19 15:34:51.000000 411.4332 33 ECU1 CrM API 2206 log info verbose 1 T2304 CgstPlayerApi:waitFor() Wait for PLAYING
483640 2021/04/19 15:34:51.000000 411.4629 155 ECU1 CrM API 2206 log debug verbose 1 T2206 CgstPlayerApi::gstBusCallback()(default) Got stream-status message from Element "sink", type: 0, owner: ittmp4parser0, object type: GstTask, value: 0xb25942c8
483641 2021/04/19 15:34:51.000000 411.4630 156 ECU1 CrM API 2206 log debug verbose 1 T2206 CgstPlayerApi::gstBusCallback()(default) Got stream-status message from Element "sink", type: 1, owner: ittmp4parser0, object type: GstTask, value: 0xb25942c8
483643 2021/04/19 15:34:51.000000 411.4630 158 ECU1 CrM API 2206 log debug verbose 1 T2206 CgstPlayerApi::gstBusCallback()(default) Got stream-status message from Element "src_0", type: 1, owner: multiqueue0, object type: GstTask, value: 0x4f1e10
483775 2021/04/19 15:34:51.000000 411.4935 34 ECU1 CrM API 2206 log debug verbose 1 T2206 CgstPlayerApi::gstBusCallback()(default) Got stream-status message from Element "src_1", type: 1, owner: multiqueue0, object type: GstTask, value: 0x4f1eb8
484353 2021/04/19 15:34:52.000000 412.4335 64 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
484906 2021/04/19 15:34:53.000000 413.4339 68 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
485423 2021/04/19 15:34:54.000000 414.4343 72 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
486012 2021/04/19 15:34:55.000000 415.4347 76 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
486577 2021/04/19 15:34:56.000000 416.4350 80 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
487200 2021/04/19 15:34:57.000000 417.4354 84 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
487902 2021/04/19 15:34:58.000000 418.4357 88 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
488521 2021/04/19 15:34:59.000000 419.4361 92 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
489163 2021/04/19 15:35:00.000000 420.4365 96 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
489750 2021/04/19 15:35:01.000000 421.4369 100 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
489751 2021/04/19 15:35:01.000000 421.4369 101 ECU1 CrM API 2206 log error verbose 1 T2304 CgstPlayerApi:waitFor() can't change the state to PLAYING!
489760 2021/04/19 15:35:01.000000 421.4374 106 ECU1 CrM API 2206 log warn verbose 1 T2206 CgstPlayerApi::gstBusCallback() do flush
489763 2021/04/19 15:35:01.000000 421.4374 107 ECU1 CrM API 2206 log error verbose 1 T2206 CgstPlayerApi::gstBusCallback() Got error message from Element errcode=1, domain=1751 "URI Pipeline": Abnormal file Debug Info: /data/work/Perforce/MMT2020/MediaOne_SOP2/src/Adaptor/Engine/CoreMedia/Player/CgstBasePlayer.cpp(440): play (): /GstPlayBin:URI Pipeline: Can't conver state to play
489766 2021/04/19 15:35:01.000000 421.4375 108 ECU1 CrM API 2206 log debug verbose 1 T2206 CgstPlayerApi::getUri uri=file:///tmp/SDCard%5FSlot1%2Dp1/Video%5Fsongs/TeluguWap%2ECo%2Ein%20%2D%20Bad%20Boy%20Video%20Song%20%2D%20Saaho%2D1080p%2Emp4
490292 2021/04/19 15:35:01.000000 421.4767 109 ECU1 CrM API 2206 log info verbose 1 T2304 CgstPlayerApi:stop() set state to stop
490293 2021/04/19 15:35:01.000000 421.4767 110 ECU1 CrM API 2206 log info verbose 1 T2304 CgstPlayerApi:stopAsync() set state to stop

journal.txt:
MediaOneService[2206]
Line 513640: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: 0:06:32.635598468 [335m 2206[00m 0x49ec80 [36mINFO [00m [00m filesrc gstfilesrc.c:263:gst_file_src_set_location:[00m filename : /tmp/SDCard_Slot1-p1/Video_songs/TeluguWap.Co.in - Bad Boy Video Song - Saaho-1080p.mp4
Line 513965: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: 0:06:32.704135349 [335m 2206[00m 0xb2e41890 [36mINFO [00m [00;01;37;41m GST_ELEMENT_FACTORY gstelementfactory.c:364:gst_element_factory_create:[00m creating element "ducatih264decvpe"
Line 513970: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: 0:06:32.708447201 [335m 2206[00m 0xb2e41890 [36mINFO [00m [00;01;37;41m GST_ELEMENT_FACTORY gstelementfactory.c:362:gst_element_factory_create:[00m creating element "ducatih264dec" named "decoder"
Line 513989: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: 0:06:32.711705787 [335m 2206[00m 0xb2e41890 [36mINFO [00m [00;01;37;41m GST_ELEMENT_PADS gstelement.c:646:gst_element_add_pad:<GstDucatiH264decVpe@0xb254a6e0>[00m adding pad 'sink'
Line 513990: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: 0:06:32.711784070 [335m 2206[00m 0xb2e41890 [36mINFO [00m [00;01;37;41m GST_ELEMENT_PADS gstelement.c:646:gst_element_add_pad:<GstDucatiH264decVpe@0xb254a6e0>[00m adding pad 'src'
Line 513991: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: 0:06:32.711960631 [335m 2206[00m 0xb2e41890 [36mINFO [00m [00;01;31;41m GST_PADS gstpad.c:2234:gst_pad_link_prepare:[00m trying to link capsfilter0:src and ducatih264decvpe0:sink
Line 513992: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: 0:06:32.712028240 [335m 2206[00m 0xb2e41890 [36mINFO [00m [00;01;31;41m GST_PADS gstpad.c:2440:gst_pad_link_full:[00m linked capsfilter0:src and ducatih264decvpe0:sink, successful
Line 513997: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: 0:06:32.712935615 [335m 2206[00m 0xb2e41890 [36mINFO [00m [00;01;31m GST_STATES gstbin.c:2707:gst_bin_change_state_func:<ducatih264decvpe0>[00m child 'vpe' changed state to 2(READY) successfully
Line 513998: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: 0:06:32.713015762 [335m 2206[00m 0xb2e41890 [36mINFO [00m [00;01;31m GST_STATES gstbin.c:2243:gst_bin_element_set_state:<decoder>[00m current NULL pending VOID_PENDING, desired next READY
Line 513999: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: 0:06:33.649040155 [335m 2206[00m 0x49ec80 [36mINFO [00m [00;01;31m GST_STATES gstelement.c:2062:gst_element_get_state_func:<URI Pipeline>[00m timed out
Line 514000: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: 0:06:33.649155716 [335m 2206[00m 0x49ec80 [36mINFO [00m [00;01;31m GST_STATES gstbin.c:1842:gst_bin_get_state_func:<URI Pipeline>[00m getting state
Line 514001: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: 0:06:33.649226036 [335m 2206[00m 0x49ec80 [36mINFO [00m [00;01;31m GST_STATES gstelement.c:2048:gst_element_get_state_func:<URI Pipeline>[00m waiting for element to commit state
...
...
..

Line 514616: Apr 06 00:06:30 mmt2020-a880 MediaOneService[2206]: 0:06:42.652374484 [335m 2206[00m 0x49ec80 [36mINFO [00m [00;01;31m GST_STATES gstelement.c:2062:gst_element_get_state_func:<URI Pipeline>[00m timed out
Line 514617: Apr 06 00:06:30 mmt2020-a880 MediaOneService[2206]: 0:06:42.652602217 [335m 2206[00m 0x49ec80 [33;01mWARN [00m [00;04m default CgstBasePlayer.cpp:440:play:<URI Pipeline>[00m error: Abnormal file
Line 514618: Apr 06 00:06:30 mmt2020-a880 MediaOneService[2206]: 0:06:42.652674570 [335m 2206[00m 0x49ec80 [33;01mWARN [00m [00;04m default CgstBasePlayer.cpp:440:play:<URI Pipeline>[00m error: Can't conver state to play
Line 514619: Apr 06 00:06:30 mmt2020-a880 MediaOneService[2206]: 0:06:42.652789284 [335m 2206[00m 0x49ec80 [36mINFO [00m [00;01;31;47m GST_ERROR_SYSTEM gstelement.c:1837:gst_element_message_full:<URI Pipeline>[00m posting message: Abnormal file
Line 514620: Apr 06 00:06:30 mmt2020-a880 MediaOneService[2206]: 0:06:42.652935006 [335m 2206[00m 0x49ec80 [36mINFO [00m [00;01;31;47m GST_ERROR_SYSTEM gstelement.c:1860:gst_element_message_full:<URI Pipeline>[00m posted error message: Abnormal file

0 Shashikiran Bhagavath1 over 2 years ago in reply to Shashikiran Bhagavath1

Prodigy 100 points

Hi Karthik,

Nee set logs: https://transfer.harman.com/link/5h3fGSZyVnr9aFfP2PoKET

CarPlay screen switch was tried after 91 sec of the ignition cycle.
CPU load was 30% before switching
During initial playback, it shoots to 88% and settles down to 68 to 72% during carplay use case.

2. CarPlay service PID is 2037

5. Video dump file, where blank screen is seen Video_Dump_92395964050.h264

6. VideoPlayback failure: MediaOneService PID is 2206.
DLT:
486012 2021/04/19 15:34:55.000000 415.4347 76 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
486577 2021/04/19 15:34:56.000000 416.4350 80 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
487200 2021/04/19 15:34:57.000000 417.4354 84 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
487902 2021/04/19 15:34:58.000000 418.4357 88 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
488521 2021/04/19 15:34:59.000000 419.4361 92 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
489163 2021/04/19 15:35:00.000000 420.4365 96 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
489750 2021/04/19 15:35:01.000000 421.4369 100 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 2
489751 2021/04/19 15:35:01.000000 421.4369 101 ECU1 CrM API 2206 log error verbose 1 T2304 CgstPlayerApi:waitFor() can't change the state to PLAYING!
489760 2021/04/19 15:35:01.000000 421.4374 106 ECU1 CrM API 2206 log warn verbose 1 T2206 CgstPlayerApi::gstBusCallback() do flush
489763 2021/04/19 15:35:01.000000 421.4374 107 ECU1 CrM API 2206 log error verbose 1 T2206 CgstPlayerApi::gstBusCallback() Got error message from Element errcode=1, domain=1751 "URI Pipeline": Abnormal file Debug Info: /data/work/Perforce/MMT2020/MediaOne_SOP2/src/Adaptor/Engine/CoreMedia/Player/CgstBasePlayer.cpp(440): play (): /GstPlayBin:URI Pipeline: Can't conver state to play
489766 2021/04/19 15:35:01.000000 421.4375 108 ECU1 CrM API 2206 log debug verbose 1 T2206 CgstPlayerApi::getUri uri=file:///tmp/SDCard%5FSlot1%2Dp1/Video%5Fsongs/TeluguWap%2ECo%2Ein%20%2D%20Bad%20Boy%20Video%20Song%20%2D%20Saaho%2D1080p%2Emp4
490292 2021/04/19 15:35:01.000000 421.4767 109 ECU1 CrM API 2206 log info verbose 1 T2304 CgstPlayerApi:stop() set state to stop
490293 2021/04/19 15:35:01.000000 421.4767 110 ECU1 CrM API 2206 log info verbose 1 T2304 CgstPlayerApi:stopAsync() set state to stop

0 Shashikiran Bhagavath1 over 2 years ago in reply to Shashikiran Bhagavath1

Prodigy 100 points

Hi Karthik.

Log files are present @ transfer.harman.com/.../5h3fGSZyVnr9aFfP2PoKET

1. CarPlay screen switch was tried after 91 sec of the ignition cycle. CPU load was 30% before switching
During initial playback, it shoots to 88% and settles down to 68 to 72% during carplay use case.

2. CarPlay service PID is 2037

3. Jouranl log reference:
journal.txt
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494107411 ducati gstducatividdec.c:230:codec_create: Codec version H264VDEC_TI DEV.500.V.H264AVC.D.HP.IVAHD.02.00.21.01
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494502725 GST_META gstmeta.c:87:gst_meta_api_type_register: register API "GstMetaDucatiBufferPrivAPI"
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494577789 GST_META gstmeta.c:94:gst_meta_api_type_register: adding tag "ducatibufferpriv"
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494652345 GST_META gstmeta.c:192:gst_meta_register: register "GstMetaDucatiBufferPriv" implementing "GstMetaDucatiBufferPrivAPI" of size 20
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494693181 GST_BUFFER gstbuffer.c:2089:gst_buffer_add_meta: alloc metadata 0x1937c4 (GstMetaDucatiBufferPriv) of size 20
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494732492 default gstducatibufferpriv.c:52:ducatibufferpriv_init_func: init called on buffer 0xa8a2e690, meta 0x1937c4
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494774853 GST_BUFFER gstbuffer.c:1637:gst_buffer_map_range: buffer 0xa8a2e050, idx 0, length -1, flags 0001
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494818231 GST_BUFFER gstbuffer.c:212:_get_merged_memory: buffer 0xa8a2e050, idx 0, length 1
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.494873639 ducati gstducatividdec.h:229:push_input:<vpudecoder> push: 853 bytes)
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.502068080 GST_BUFFER gstbuffer.c:641:_gst_buffer_free: finalize 0xa8a2e050
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.502135349 GST_MEMORY gstmemory.c:87:_gst_memory_free: free memory 0xa8a2c158
Apr 06 00:01:03 mmt2020-a880 cppres[2037]: 0:01:10.502184658 ducati gstducatividdec.c:556:codec_process:<vpudecoder> dce_buf_lock(inputID: a8a2e690, fd: 136)

journal log: (5:52.831 - 1:10.502 = 282.329 sec)
Apr 06 00:05:44 mmt2020-a880 cppres[2037]: 0:05:52.831807821 ducati gstducatividdec.c:1581:gst_ducati_viddec_event:<vpudecoder> end

5. Video dump file, where the blank screen is seen Video_Dump_92395964050.h264

6. video playback failure: MediaOneService PID is 2206.
DLT:
486012 2021/04/19 15:34:55.000000 415.4347 76 ECU1 CrM API 2206 log debug verbose 1 T2304 CgstPlayerApi:waitFor() Obtained the play state:[READY] pending:[PLAYING] ret = 22
489751 2021/04/19 15:35:01.000000 421.4369 101 ECU1 CrM API 2206 log error verbose 1 T2304 CgstPlayerApi:waitFor() can't change the state to PLAYING!
489760 2021/04/19 15:35:01.000000 421.4374 106 ECU1 CrM API 2206 log warn verbose 1 T2206 CgstPlayerApi::gstBusCallback() do flush
489763 2021/04/19 15:35:01.000000 421.4374 107 ECU1 CrM API 2206 log error verbose 1 T2206 CgstPlayerApi::gstBusCallback() Got error message from Element errcode=1, domain=1751 "URI Pipeline": Abnormal file Debug Info: /data/work/Perforce/MMT2020/MediaOne_SOP2/src/Adaptor/Engine/CoreMedia/Player/CgstBasePlayer.cpp(440): play (): /GstPlayBin:URI Pipeline: Can't conver state to play
489766 2021/04/19 15:35:01.000000 421.4375 108 ECU1 CrM API 2206 log debug verbose 1 T2206 CgstPlayerApi::getUri uri=file:///tmp/SDCard%5FSlot1%2Dp1/Video%5Fsongs/TeluguWap%2ECo%2Ein%20%2D%20Bad%20Boy%20Video%20Song%20%2D%20Saaho%2D1080p%2Emp4
490292 2021/04/19 15:35:01.000000 421.4767 109 ECU1 CrM API 2206 log info verbose 1 T2304 CgstPlayerApi:stop() set state to stop
490293 2021/04/19 15:35:01.000000 421.4767 110 ECU1 CrM API 2206 log info verbose 1 T2304 CgstPlayerApi:stopAsync() set state to stop

journal.txt:
MediaOneService[2206]
Line 513640: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: filesrc gstfilesrc.c:263:gst_file_src_set_location: filename : /tmp/SDCard_Slot1-p1/Video_songs/TeluguWap.Co.in - Bad Boy Video Song - Saaho-1080p.mp4
Line 513965: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: GST_ELEMENT_FACTORY gstelementfactory.c:364:gst_element_factory_create:creating element "ducatih264decvpe"
Line 513970: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: GST_ELEMENT_FACTORY gstelementfactory.c:362:gst_element_factory_create: creating element "ducatih264dec" named "decoder"
Line 514001: Apr 06 00:06:21 mmt2020-a880 MediaOneService[2206]: GST_STATES gstelement.c:2048:gst_element_get_state_func:<URI Pipeline> waiting for element to commit state
...
...
..

Line 514616: Apr 06 00:06:30 mmt2020-a880 MediaOneService[2206]: GST_STATES gstelement.c:2062:gst_element_get_state_func:<URI Pipeline> timed out
Line 514617: Apr 06 00:06:30 mmt2020-a880 MediaOneService[2206]: default CgstBasePlayer.cpp:440:play:<URI Pipeline error: Abnormal file
Line 514618: Apr 06 00:06:30 mmt2020-a880 MediaOneService[2206]: default CgstBasePlayer.cpp:440:play:<URI Pipeline> error: Can't conver state to play
Line 514619: Apr 06 00:06:30 mmt2020-a880 MediaOneService[2206]: GST_ERROR_SYSTEM gstelement.c:1837:gst_element_message_full:<URI Pipeline> posting message: Abnormal file
Line 514620: Apr 06 00:06:30 mmt2020-a880 MediaOneService[2206]: GST_ERROR_SYSTEM gstelement.c:1860:gst_element_message_full:<URI Pipeline> posted error message: Abnormal file

As per Harman Media team VideoPlayback failure is due "MmRpc_create: Error: connect failed", as mentioned previous note

0 Karthik Ramanan over 2 years ago in reply to Shashikiran Bhagavath1

TI__Guru** 113800 points

Shashi,

Thanks. Can you please also add your comments about the flush-start event getting called right after the Carplay session initiation?

Regards

Karthik

0 Shashikiran Bhagavath1 over 2 years ago in reply to Karthik Ramanan

Prodigy 100 points

Hi Karthik,

Flush -start event will be sent when user switches from CarPlay to Native HMI.

In the recent logs, user had entered the CarPlay screen. A blank screen is seen. After 282.329 sec and 1417 frames, Flush start event is sent to gst pipeline.

So flush start event is not sent immediately.

Regards,

Shashikiran

0 Karthik Ramanan over 2 years ago in reply to Shashikiran Bhagavath1

TI__Guru** 113800 points

Just to recap - here are the set of actions that were captured for this issue when it was first reported: https://e2e.ti.com/support/processors-group/processors/f/processors-forum/927586/dra744-no-surface-creation-during-gstreamer-playback/3431554#3431554

The TI analysis from the logs is attached:/cfs-file/__key/communityserver-discussions-components-files/791/VIDDEC3_5F00_log.7z

The logs of the video playback after the carplay hang are still not conclusive enough - it is not verbose to show any failures from Ducati side.

We decided to take 3 actions:

Team will share the logs with a different instance of failure.
Team will reproduce the issue again and collect logs with more verbosity, as described.
- When carplay blackscreen happened, we run "GST_DEBUG=4,ducatih264dec*:6 gst-launch-1.0 -v playbin uri=file:///path/to/mp4" to get above log.
Team will notify for a joint debug after the issue is reproduced, some sanitization will be done before notifying TI for joint debug availability.

Regards

Karthik

0 Shashikiran Bhagavath1 over 2 years ago in reply to Karthik Ramanan

Prodigy 100 points

Hi Karthik,

Please find the new set of logs @ https://transfer.harman.com/link/7MqPV2x05t7qzTqL1XRFQk

3062172_cp_blank_screen_and_no_Video_Playback_after_blankscreen.7z\CoverNotes_for_carplay_Blackscreen-June2.txt has details about use case.

After CarPlay Blank screen, Video playback using ""GST_DEBUG=4,ducatih264dec*:6 gst-launch-1.0 -v playbin uri=file:///path/to/mp4"" command is failing to due

Engine_open ERROR: Failed dce_ipc_init(coreIdx) == DCE_EOK error val -4MmRpc_create: Error: connect failed.

The same error is seen even in the log provided on Apr 15, 2021 log as well.

0 Karthik Ramanan over 2 years ago in reply to Shashikiran Bhagavath1

TI__Guru** 113800 points

We are discussing this offline. Will update with the summary when the investigation is completed.

Processors

Processors forum

PROCESSOR-SDK-DRA7X: DRA744: No surface creation during gstreamer playback