1118139 - [FFOS7715 v2.1] [dolphin][Youtube video] 7715 FFOS shows black screen on launching some video, while audio can be heared while using Youtube app or Youtube site

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[[e-mail]]

DEFECT DESCRIPTION:
  7715 FFOS shows black screen on launching some video, while audio can be heared in using Youtube app or Youtube site.

Steps to reproduce:
----------------------------------------------------
Step 1: Place SIM card in respective slot.
Step 2: Reboot the Phone.
Step 3: Download Youtube app from Marketplace.(App Version :- NA)
Step 4: Launch Youtube app.
Step 5: Select any video to play.
Step 6: 7715 FFOS shows black screen on launching some video, while audio can be heared.

This issue also happened in youtube site both FFOS & flame.

Expected result:
--------------------------------------- 
7715 & flame should properly show the video while launching video in Youtube app and Youtube site.

Additional info:
--------------------------------------
Reproduce rate:  1/5

Comment 1

[[e-mail]]

Dear Vchen:

This issue in wifi condition seems working fine and with the very lower probability.

Please help to find some teammates to check whether this issue is associated with network condition or the 3rd app？

Thanks very much!

Comment 2

[[e-mail]]

Dear vchen & shawn:

If using sim data to playing video, the probability will increasing. 

So could your help to find someone to check this issue? 

Thanks!

Comment 3

[shawn ku [:sku]]

Vincent:
 Please help check this issue.

Comment 4

[Vincent Liu[:vliu]]

(In reply to shawn ku [:sku] from comment #3)
> Vincent:
>  Please help check this issue.

Sure. I will have a study.

Comment 5

[[e-mail]]

Dear Vincent:

Using Youtube app playing a video, audio and video data are received in timely, the log prints look like this(wifi condition):

01-23 04:35:17.955   783   783 I lin.hui ==>: Play Started in HTMLMediaElement.cpp
01-23 04:35:17.955   783   869 I lin.hui ==>: DecodeSeek: seekTime:0
01-23 04:35:17.955   783   783 I lin.hui ==>: Play started in MediaDecoder.cpp
01-23 04:35:17.985   783   869 I lin.hui ==>: In SeekCompleted-->RenderVideoFrame
01-23 04:35:17.985   783   869 I lin.hui ==>: RenderVideoFrame: LIN_HUI_COUNT = 238
01-23 04:35:17.985   783   869 I lin.hui ==>: Render-->playing video frame 0
01-23 04:35:18.135   783   868 I lin.hui ==>: In advanceFrame: VideoData droppedFrames
01-23 04:35:18.135   783   868 I lin.hui ==>: In AdvanceFrame-->RenderVideoFrame
01-23 04:35:18.135   783   868 I lin.hui ==>: RenderVideoFrame: LIN_HUI_COUNT = 239
>> 01-23 04:35:18.135   783   868 I lin.hui ==>: Render-->playing video frame 0
>> 01-23 04:35:18.165   783   893 I lin.hui ==>: playing 1024 frames of audio at time 0
>> 01-23 04:35:18.165   783   893 I lin.hui ==>: playing 1024 frames of audio at time 46439
>> 01-23 04:35:18.805   783   868 I lin.hui ==>: clock_time:28979
>> 01-23 04:35:18.805   783   893 I lin.hui ==>: playing 1024 frames of audio at time 1346757
>> 01-23 04:35:18.815   783   868 I lin.hui ==>: Render-->playing video frame 33366

But sometimes the audio can be heared but video picture do not displayed in timely, the log look like this(wifi condition):

01-23 04:34:52.365   783   783 I lin.hui ==>: Play Started in HTMLMediaElement.cpp
01-23 04:34:53.725   783   783 I lin.hui ==>: Play started in MediaDecoder.cpp
01-23 04:34:54.135   783   879 I lin.hui ==>: DecodeMetadata first video frame start 0
01-23 04:34:54.135   783   879 I lin.hui ==>: DecodeMetadata first audio frame start 46439
01-23 04:34:54.135   783   879 I lin.hui ==>: In FinishDecodeMetadata-->RenderVideoFrame
01-23 04:34:54.135   783   879 I lin.hui ==>: RenderVideoFrame: LIN_HUI_COUNT = 1
01-23 04:34:54.135   783   879 I lin.hui ==>: Render-->playing video frame 0
01-23 04:34:54.135   783   879 I lin.hui ==>: Media goes from 0 to 20062040 (duration 20062040) transportSeekable=1, mediaSeekable=1
01-23 04:34:54.135   783   879 I lin.hui ==>: Changed state from DECODING_METADATA to DECODING!
01-23 04:34:54.135   783   868 I lin.hui ==>: In advanceFrame: VideoData droppedFrames
01-23 04:34:54.135   783   868 I lin.hui ==>: In AdvanceFrame-->RenderVideoFrame
01-23 04:34:54.135   783   868 I lin.hui ==>: RenderVideoFrame: LIN_HUI_COUNT = 2
>> 01-23 04:34:54.135   783   868 I lin.hui ==>: Render-->playing video frame 0
>> 01-23 04:34:54.205   783   881 I lin.hui ==>: playing 1023 frames of silence
>> 01-23 04:34:54.205   783   881 I lin.hui ==>: playing 1024 frames of audio at time 46439
>> 01-23 04:34:55.105   783   868 I lin.hui ==>: clock_time:28979
>> 01-23 04:34:55.115   783   868 I lin.hui ==>: Render-->playing video frame 33366

So those two logs is different, please help to do a further investigation about this.

BTW, we couldn't using SIM data visit the youtube site, the issue found in India, they using SIM data to visit youtube site.

Comment 6

[Vincent Liu[:vliu]]

(In reply to [e-mail] from comment #0)
> DEFECT DESCRIPTION:
>   7715 FFOS shows black screen on launching some video, while audio can be
> heared in using Youtube app or Youtube site.
> 
> Steps to reproduce:
> ----------------------------------------------------
> Step 1: Place SIM card in respective slot.
> Step 2: Reboot the Phone.
> Step 3: Download Youtube app from Marketplace.(App Version :- NA)
> Step 4: Launch Youtube app.
> Step 5: Select any video to play.
> Step 6: 7715 FFOS shows black screen on launching some video, while audio
> can be heared.
> 
> This issue also happened in youtube site both FFOS & flame.
> 
> Expected result:
> --------------------------------------- 
> 7715 & flame should properly show the video while launching video in Youtube
> app and Youtube site.
> 
> Additional info:
> --------------------------------------
> Reproduce rate:  1/5

I tried many youtube file but I can't reproduce this issue. Many I confirm somthing?

1. When you reproduce this issue? Which network you used to try? GPRS or 3G?
2. Do you have specific link to reproduce it more easily? Thanks

Comment 7

[Vincent Liu[:vliu]]

More questions to confirm.

3. If you have specific link to reproduce this issue, what video format it has inside this video file?
4. Does the fail rate of this specific link is 100%?

Comment 8

[[e-mail]]

(In reply to Vincent Liu[:vliu] from comment #6)
>> 1. When you reproduce this issue? Which network you used to try? GPRS or 3G?
[lin hui] 
1.I clarify this in Comment 5 ，In China, we couldn't using SIM data visit the Youtube app, so I did this test in wifi condition. 
2.This issue found in India, the tester in India using SIM data to visit Youtube site or Youtube app.

>> 2. Do you have specific link to reproduce it more easily? 
>> 3. If you have specific link to reproduce this issue, what video format it has inside this video 
>> file?
[lin hui] In my test(wifi condition), many of video launched using Youtube app or Youtube site(In browser), we can hearing audio played but video picture are not displayed in timely.

4. Does the fail rate of this specific link is 100%?
If this issue occurred in a video, the fail rate is almost 100%.

Thanks!

Comment 9

[[e-mail]]

In addition, I uploaded the test video in India using SIM data, you can go this address to download:
  http://pan.baidu.com/s/1bn4KaiN

and I also did this test in wifi condition and captured a video:
  http://pan.baidu.com/s/1sjuidBJ

It seems using wifi this issue also existed, but seems not very serious, please help to check it.

Comment 10

[[e-mail]]

(In reply to Vincent Liu[:vliu] from comment #7)
> More questions to confirm.
> 
> 3. If you have specific link to reproduce this issue, what video format it
> has inside this video file?
> 4. Does the fail rate of this specific link is 100%?

In my case, using India video songs to do the test, this issue has the probability with 100%, the video songs like DJ songs seem very obvious!

Comment 11

[Vincent Liu[:vliu]]

(In reply to [e-mail] from comment #5)

> But sometimes the audio can be heared but video picture do not displayed in
> timely, the log look like this(wifi condition):
> 

May I confirm that the video is not always black screen when playing, right? From your description, does it mean Audio/Video doesn't sync during playing?

Comment 12

[[e-mail]]

(In reply to Vincent Liu[:vliu] from comment #11)
> May I confirm that the video is not always black screen when playing, right?
> From your description, does it mean Audio/Video doesn't sync during playing?
The issue just occurred when you select a video to playing(At the beginning of the play, you can hearing audio, but do not watch the picture, due to this issue video frame may be missed.), other times have no problems.

Comment 13

[Vance Chen [:vchen][skype:vance.lucida][[e-mail]]]

(In reply to [e-mail] from comment #9)
> In addition, I uploaded the test video in India using SIM data, you can go
> this address to download:
>   http://pan.baidu.com/s/1bn4KaiN
> 
> and I also did this test in wifi condition and captured a video:
>   http://pan.baidu.com/s/1sjuidBJ
> 
> It seems using wifi this issue also existed, but seems not very serious,
> please help to check it.

Hi Lin.hui -

From your video it looks like the delay is caused by the buffering and and mismatch between audio and video are not that obvious. 

Is it possible you can ask your India colleague to capture a video for this issue? It will help us to further clarify the problem

Comment 14

[[e-mail]]

(In reply to Vance Chen [:vchen][[e-mail]] from comment #13)
> Is it possible you can ask your India colleague to capture a video for this
> issue? It will help us to further clarify the problem

Dear Vchen:
In Comment 9 , I have already uploaded the video captured by India colleague, they did test by using SIM data, not in wifi condition, video info as blow:
   http://pan.baidu.com/s/1bn4KaiN

BTW, I will asked for them at wifi case's testing result, and upload here.

Comment 15

[[e-mail]]

(In reply to Vance Chen [:vchen][[e-mail]] from comment #13)
> Is it possible you can ask your India colleague to capture a video for this
> issue? It will help us to further clarify the problem
Our India colleague have already captured a video for this issue, please go this address to download:
    http://pan.baidu.com/s/1pJE4X5L

In my test, this bug can reproduce easily when playing India video songs and DJ songs on Youtube, missing video for 1-2 seconds is the major issue, customer will not accept the missed video, So please help to investigate this issue.

Thanks!

Comment 16

[Vincent Liu[:vliu]]

(In reply to [e-mail] from comment #15)
> (In reply to Vance Chen [:vchen][[e-mail]] from comment #13)
> > Is it possible you can ask your India colleague to capture a video for this
> > issue? It will help us to further clarify the problem
> Our India colleague have already captured a video for this issue, please go
> this address to download:
>     http://pan.baidu.com/s/1pJE4X5L
> 
> In my test, this bug can reproduce easily when playing India video songs and
> DJ songs on Youtube, missing video for 1-2 seconds is the major issue,
> customer will not accept the missed video, So please help to investigate
> this issue.
> 
> Thanks!

From the attached file, I can see the real problem. I test on my dolphin and saw there was about 0.5~0.8 seconds I can only hear audio showing up in the beginning of playing media file on youtube. Since this is a video case, I would transfer this issue to Blake for deeper investigation.

Comment 17

[Blake Wu [:bwu][:blakewu]]

After checking the testing video, it looks many frames are dropped in the first several seconds and might be due to AV unsync.
I am going to check further.

Comment 18

[Blake Wu [:bwu][:blakewu]]

After some investigations, this problem is not caused by frames dropped due to AV unsync. It looks video frames are fed to render pipeline via [1] but not be rendered in time.
Continue to check deeper. 

[1]https://mxr.mozilla.org/mozilla-b2g34_v2_1/source/content/media/MediaDecoderStateMachine.cpp#2550

Comment 19

[Blake Wu [:bwu][:blakewu]]

Chiajung,
May I have your help to look into rendering pipeline part?

Comment 20

[Peter Chang[:pchang]]

boris, please help to check this is related to the video rendering problem or not.

Comment 21

[Boris Chiou [:boris]]

(In reply to peter chang[:pchang][:peter] from comment #20)
> boris, please help to check this is related to the video rendering problem
> or not.

As per Peter's suggestion, I checked the GrallocImage::SetData()[1] function. When I heard the audio, we called GrallocImage::SetData() immediately, and then I saw the video after the loading icon disappeared. I still cannot figure out which part has problems, and maybe we should discuss this with Chiajung tomorrow.

[1] https://dxr.mozilla.org/mozilla-central/source/gfx/layers/GrallocImages.cpp?from=grallocImages.cpp#148

Comment 22

[Vincent Liu[:vliu]]

Attachment: audio-out.patch

Hi Boris,

The attached file add a log info for tracking start_output_stream for audio. Please have a reference.

Comment 23

[Blake Wu [:bwu][:blakewu]]

(In reply to Blake Wu [:bwu][:blakewu] from comment #18)
> After some investigations, this problem is not caused by frames dropped due
> to AV unsync. It looks video frames are fed to render pipeline via [1] but
To check if there is any dropped frames due to AV sync, it can be watched by enabling log in [1]

[1]http://mxr.mozilla.org/mozilla-b2g34_v2_1/source/content/media/MediaDecoderStateMachine.cpp#2652

Comment 24

[Vincent Liu[:vliu]]

Attachment: logs-for-av-sync.log

The log file to monitor av-sync was attached. The log file contains the log point for Comment 18 and Comment 23, plus the log point for audio part. From log info, the log for video like SetData() or |playing video frame| seems always print out before audio. Blake, do you have any idea with that?

Comment 25

[Blake Wu [:bwu][:blakewu]]

(In reply to Vincent Liu[:vliu] from comment #24)
> Created attachment 8558972 [details]
> logs-for-av-sync.log
> 
> The log file to monitor av-sync was attached. The log file contains the log
> point for Comment 18 and Comment 23, plus the log point for audio part. From
> log info, the log for video like SetData() or |playing video frame| seems
> always print out before audio. Blake, do you have any idea with that?
I think we should need to check the rendering pipeline but I'm not familiar with it.
Chiajung, 
Could you help to check it?

Comment 26

[Blake Wu [:bwu][:blakewu]]

As discussing with Vincent offline, we can dump yuv data to make sure if the data is valid or not.

Comment 27

[Chiajung Hung [:chiajung]]

(In reply to Blake Wu [:bwu][:blakewu] from comment #26)
> As discussing with Vincent offline, we can dump yuv data to make sure if the
> data is valid or not.

From LayerScope, the video is invisible at first even though audio playback started: (Frame 86)
https://drive.google.com/a/mozilla.com/file/d/0BwLc-XVjXSlzalpZYjI3SnAxcVU/view?usp=sharing

This means the problem is in content side, and we need some code to dump the raw data there to make sure whether the decoded frame is correct.

Since the Layer may take video's intrinsic size into consideration while reflow, if the frame passed into ImageContainer is (0, 0), the layer would be invisible, too.

Comment 28

[Chiajung Hung [:chiajung]]

Forgot to mention that you can download the Layerscope dump in comment 27 and upload to Layerscope viewer tool to see the framedump.

Comment 29

[Vincent Liu[:vliu]]

(In reply to Blake Wu [:bwu][:blakewu] from comment #26)
> As discussing with Vincent offline, we can dump yuv data to make sure if the
> data is valid or not.

Hi Blake, Chiajung,

We may dump raw data from the below line.

https://dxr.mozilla.org/mozilla-central/source/gfx/layers/GrallocImages.cpp#150

Comment 30

[Peter Chang[:pchang]]

(In reply to Vincent Liu[:vliu] from comment #24)
> Created attachment 8558972 [details]
> logs-for-av-sync.log
> 
> The log file to monitor av-sync was attached. The log file contains the log
> point for Comment 18 and Comment 23, plus the log point for audio part. From
> log info, the log for video like SetData() or |playing video frame| seems
> always print out before audio. Blake, do you have any idea with that?

Blake, did you confirm the video data pass to rendering pipeline was correct before audio?
BTW, please also confirm the video data is valid at the same time.

Comment 31

[Blake Wu [:bwu][:blakewu]]

(In reply to peter chang[:pchang][:peter] from comment #30)
> (In reply to Vincent Liu[:vliu] from comment #24)
> > Created attachment 8558972 [details]
> > logs-for-av-sync.log
> > 
> > The log file to monitor av-sync was attached. The log file contains the log
> > point for Comment 18 and Comment 23, plus the log point for audio part. From
> > log info, the log for video like SetData() or |playing video frame| seems
> > always print out before audio. Blake, do you have any idea with that?
> 
> Blake, did you confirm the video data pass to rendering pipeline was correct
> before audio?
No. Since the buffer using between codec and render is only passing some metadata (Metadata mode) and doesn't expose the real YUV data in the OMXCodec, so it will be better to be dumped in the render side.  
> BTW, please also confirm the video data is valid at the same time.
With Chiajung's help, we successfully dumped the yuv data and has checked the yuv data is correct. 
Now we are going to check the youtube side to see if video tag is in the hidden state in the beginning or not.

Comment 32

[Blake Wu [:bwu][:blakewu]]

Attachment: 0001-Bug-1118139-Add-log-for-debug.patch

Comment 33

[Blake Wu [:bwu][:blakewu]]

We are checking if video tag is bound to tree too late which causes video frame not to be rendered in time.
I have attached a patch to add more logs to understand the problem further. 
Could you help us to apply the patch and collect the logs for us?
Thanks!

Comment 34

[[e-mail]]

Attachment: 0-main-06-54-38.log

(In reply to Blake Wu [:bwu][:blakewu] from comment #33)
> We are checking if video tag is bound to tree too late which causes video
> frame not to be rendered in time.
> I have attached a patch to add more logs to understand the problem further. 
> Could you help us to apply the patch and collect the logs for us?
> Thanks!
After applying the log patch, I have already collect the log, see attachment, the time to playing video in Youtube app is "02-06 06:48:52:xxx".

Thanks for your help.

Comment 35

[Blake Wu [:bwu][:blakewu]]

(In reply to [e-mail] from comment #34)
> Created attachment 8560416 [details]
> 0-main-06-54-38.log
> 
> (In reply to Blake Wu [:bwu][:blakewu] from comment #33)
> > We are checking if video tag is bound to tree too late which causes video
> > frame not to be rendered in time.
> > I have attached a patch to add more logs to understand the problem further. 
> > Could you help us to apply the patch and collect the logs for us?
> > Thanks!
> After applying the log patch, I have already collect the log, see
> attachment, the time to playing video in Youtube app is "02-06 06:48:52:xxx".
> 
> Thanks for your help.

Thanks for your prompt replay and sorry not to mention earlier about recording a video file.
Could you record a video when you collect the logs?
That would be helpful for us to know how long from "audio starts to play" to "video frame start to be rendered". 
Thanks!

Comment 36

[[e-mail]]

(In reply to Blake Wu [:bwu][:blakewu] from comment #35)
> Thanks for your prompt replay and sorry not to mention earlier about
> recording a video file.
> Could you record a video when you collect the logs?
> That would be helpful for us to know how long from "audio starts to play" to
> "video frame start to be rendered". 
> Thanks!
Sorry, I didn't realize this yet.

I have uploaded the log and the video to this address, please go and download:
http://pan.baidu.com/s/1mgh1vrM

Thanks!

Comment 37

[Blake Wu [:bwu][:blakewu]]

From the logs attached and what I saw on my Dolphin, video tag is bound to tree very early, so we should rule late-binding out.

Comment 38

[Blake Wu [:bwu][:blakewu]]

(In reply to Blake Wu [:bwu][:blakewu] from comment #37)
> From the logs attached and what I saw on my Dolphin, video tag is bound to
> tree very early, so we should rule late-binding out.

More info about what I mentioned about BindToTree[1]

[1]https://dxr.mozilla.org/mozilla-central/source/dom/html/HTMLMediaElement.cpp?from=HTMLMediaElement.cpp&case=true#2521

Comment 39

[Blake Wu [:bwu][:blakewu]]

ChiaJung, 
Could you help to check the render part further to see if the decoded frame is sent to composer or not? 
Thanks!

Comment 40

[Chiajung Hung [:chiajung]]

From LayerScope result, I would say Compositor do not rendering the video, but it may be not very precise, due to the lack of audio infomation.

To be precise, I think we can log frame sending/receiving/rendering with audio logs, but I have no workable dolphin devices. The only one I got from my team has a broken battery.

@Vincent
Can you help to check whether the problem reproducible on Flame-master device?

Comment 41

[Vincent Liu[:vliu]]

(In reply to Chiajung Hung [:chiajung] from comment #40)
> From LayerScope result, I would say Compositor do not rendering the video,
> but it may be not very precise, due to the lack of audio infomation.
> 
> To be precise, I think we can log frame sending/receiving/rendering with
> audio logs, but I have no workable dolphin devices. The only one I got from
> my team has a broken battery.
> 
> @Vincent
> Can you help to check whether the problem reproducible on Flame-master
> device?

Sure. I can try it on Flame-master.

Comment 42

[Vance Chen [:vchen][skype:vance.lucida][[e-mail]]]

Hi Chiajung -

I have one Dolphin with good battery with me now, do you want it to do further investigation?

Thanks

Comment 43

[Vincent Liu[:vliu]]

I can also see this issue on Flame-master. It seems that frame dropping happens in the beginning of few frames.

Comment 44

[Chiajung Hung [:chiajung]]

Ok, if this is reproducible on flame-master, I can check it on my flame directly.

Comment 45

[Chiajung Hung [:chiajung]]

This bug seems because of delayed timeupdate event: we run async video, and layout system wait the event to link the Layer and the ImageContainer.

On dolphin, the observed delay is about 1.8 sec, and on flame it is 200~500ms for different video.

Comment 46

[[e-mail]]

(In reply to Chiajung Hung [:chiajung] from comment #45)
> This bug seems because of delayed timeupdate event: we run async video, and
> layout system wait the event to link the Layer and the ImageContainer.
> 
> On dolphin, the observed delay is about 1.8 sec, and on flame it is
> 200~500ms for different video.
Dear Chiajung -

About your comment, I also see dolphin delayed more than flame, so could you find someway to fix this issue or make some optimization to improve user's experience?

Thanks!

Comment 47

[Vance Chen [:vchen][skype:vance.lucida][[e-mail]]]

(In reply to [e-mail] from comment #46)
> (In reply to Chiajung Hung [:chiajung] from comment #45)
> > This bug seems because of delayed timeupdate event: we run async video, and
> > layout system wait the event to link the Layer and the ImageContainer.
> > 
> > On dolphin, the observed delay is about 1.8 sec, and on flame it is
> > 200~500ms for different video.
> Dear Chiajung -
> 
> About your comment, I also see dolphin delayed more than flame, so could you
> find someway to fix this issue or make some optimization to improve user's
> experience?
> 
> Thanks!

Hi Chiajung, Lin.hui - 

I am not familiar with the async video part, but is it possible to delay is due to the platform limitation(e.g. The CPU is just slower in 7715, compared to QCT platform)?

Understand the nature of the delay might help us to find a better way to deal this issue

Thanks

Comment 48

[Chiajung Hung [:chiajung]]

I tried to make the sync operation runs earlier by doing needed layout operation in first SetCurrentImage rather than first playing evnt.

That way, I can observe better result from log, but the problem is still observable. So I think this problem maybe rather complex than expected.

So, I am still searching for the problem of display part.

Comment 49

[Chiajung Hung [:chiajung]]

We found this bug is because main thread have no chance to reflow (to insert the video frame) especially on low speed CPU (we can reproduce this on Flame by limit its speed).

To know what CPU is busy on, we may need systrace. However, I don't know how to config kernel to make systrace work. 
I also tried to use GeckoProfiler for this, but the Audio thread spawns lazily, I can not profile that thread by GeckoProfiler.

Comment 50

[Blake Wu [:bwu][:blakewu]]

Un-assign myself since it looks like not related to video part and currently I am not working on this.

Comment 51

[[e-mail]]

(In reply to Blake Wu [:bwu][:blakewu] from comment #50)
> Un-assign myself since it looks like not related to video part and currently
> I am not working on this.
Hi Blake:

As your says this bug looks like not related to video part(render or GPU part?), could you help to find another colleague to investigate this issue?

Thank you.

Comment 52

[Blake Wu [:bwu][:blakewu]]

Peter, 
Could you find someone to help Chiajung for comment 49?

Comment 53

[Peter Chang[:pchang]]

vliu, could you help to provide systrace when this problem happens?

Before using systrace, you need to add "export MOZ_USE_SYSTRACE=1" in your .userconfig to rebuild gecko.

Comment 54

[Vincent Liu[:vliu]]

(In reply to peter chang[:pchang][:peter] from comment #53)
> vliu, could you help to provide systrace when this problem happens?
> 
> Before using systrace, you need to add "export MOZ_USE_SYSTRACE=1" in your
> .userconfig to rebuild gecko.

ni? by myself to keep tracking.

Comment 55

[Munro Mengjue Chiang [:mchiang] Be Mozillian since 1/19/2018]

Please refer to the attached systrace
When issue happened (no video but only audio in the first couple seconds), CPU is occupied by RX_thread and b2g.

Comment 56

[Munro Mengjue Chiang [:mchiang] Be Mozillian since 1/19/2018]

Attachment: trace.html

Comment 57

[Wenyuan Chi [:wchi]]

Attachment: dolphin_trace.html

use gdb to stop at MediaDecoderStateMachine::Play() then start capture.

Comment 58

[Chiajung Hung [:chiajung]]

(In reply to Munro Chiang from comment #55)
> Please refer to the attached systrace
> When issue happened (no video but only audio in the first couple seconds),
> CPU is occupied by RX_thread and b2g.

Youtube insert <video> after press of play button. So if CPU is occupied, we have no chance to reflow the page, and thus no frame shown.

I can not find where RX_thread spawn, and the name suggests that it is a network thread.

Comment 59

[Blake Wu [:bwu][:blakewu]]

To make things clearer, you can set the value [1] to be smaller to avoid reading data from network and writing to storage which should reduce the CPU loading. 


[1]https://dxr.mozilla.org/mozilla-central/source/dom/media/MediaCache.cpp?from=MediaCache.cpp&case=true#1170

Comment 60

[Vance Chen [:vchen][skype:vance.lucida][[e-mail]]]

Hi Chiajung -

Per Comment#58, could you try different value of media.cache_readahead_limit to see if it will result in different performance of playing video on youtube?

Thanks

Comment 61

[Peter Chang[:pchang]]

After some discussion, we have several actions about this bug.

1. Reduce CPU loading
  a. Try to reduce the cache size when reading data from network to reduce the cpu loading - Munro

2. Make render available as early as possible 
  a. Media provides the meta data ready event with video size to render - Blake
  b. Render prepares the video frame to display based on above meta data ready event -Chiajung

Comment 62

[Chiajung Hung [:chiajung]]

Based on comment 61, forward ni to munro.

Comment 63

[Munro Mengjue Chiang [:mchiang] Be Mozillian since 1/19/2018]

I didn't observe significant improve when I reduce the max read ahead buffer size from 30 to 10.

Comment 64

[Peter Chang[:pchang]]

(In reply to Munro Chiang [:mchiang] from comment #63)
> I didn't observe significant improve when I reduce the max read ahead buffer
> size from 30 to 10.

Then who is still consuming the CPU resource...

Comment 65

[Munro Mengjue Chiang [:mchiang] Be Mozillian since 1/19/2018]

Here is more detail.
We tried to decrease the cache size / resumeThreshold (cache low water mark) / readaheadLimit (cache high water mark). However, when CPU is busy, video codec consume the data faster than stream feed it. In this case, cache is always close to empty and Mediacache will ignore the water mark we set and keep reading.
The only way to ease the problem should be adding more mechanism to force stopping cache.
However, we need to know if the first frame has been rendered. After that, we should enable the cache again.

Comment 66

[Vincent Liu[:vliu]]

(In reply to Munro Chiang [:mchiang] from comment #65)
> Here is more detail.
> We tried to decrease the cache size / resumeThreshold (cache low water mark)
> / readaheadLimit (cache high water mark). However, when CPU is busy, video
> codec consume the data faster than stream feed it. In this case, cache is
> always close to empty and Mediacache will ignore the water mark we set and
> keep reading.

From systrace observation, it seems that accessing sdcard occupies most cpu time. And that's why the attach time of ImageContainer can't be done as soon as possible. Since stream control is held by media, would you have any idea for the stream control?

Comment 67

[Blake Wu [:bwu][:blakewu]]

Per comment 65, changing media cache size looks like that it didn't work as expected. If we don't do cache, that would make necko read data from network more often which may cause CPU busy as well. If we do cache and writing to storage, that may make CPU busy too. Currently I don't have good idea.

Comment 68

[Blake Wu [:bwu][:blakewu]]

IMO, since media cache should not occupy CPU *all the time* for around 3 seconds, UI thread should be able to grab some CPU resource. Unless the priority of UI thread is quite low.

Comment 69

[Wenyuan Chi [:wchi]]

Attachment: wip1-defer-startdecoding.patch

This a initial proposal to introduce a new state(WAIT_FOR_DISPLAY) to MediaDecoderStateMachine.

By doing so, we are able to free CPU resource from decoder threads and make layout and restyle routines run first.

Comment 70

[Blake Wu [:bwu][:blakewu]]

Could you share us what you observed with this patch before and after? Video frames are rendered out with audio samples almost at the same time after several seconds?

Comment 71

[Wenyuan Chi [:wchi]]

(In reply to Blake Wu [:bwu][:blakewu] from comment #70)
> Could you share us what you observed with this patch before and after? Video
> frames are rendered out with audio samples almost at the same time after
> several seconds?

Based on this youtube movie, https://www.youtube.com/watch?v=LS5TlwV7BjI

Before this patch, the video is always 4~5 seconds behind audio.
After this patch, audio and video are sync. they come out at the same time.


There are still timing issues needed to solve.

Comment 72

[Chiajung Hung [:chiajung]]

Comment on attachment 8586590 [details] [diff] [review]
wip1-defer-startdecoding.patch

Review of attachment 8586590 [details] [diff] [review]:
-----------------------------------------------------------------

Which branch this patch based on? I can not find MetadataDecoded and I think it is FinishDecodeFirstFrame now. If this is intended to land in central, please rebase.

BTW, I suggest blake will feedback for Decoder part, and I will just skip that part.

I think the display part missing ImageContainer.cpp in this patch. And for the callback in ImageContainer, we have a similar thing in https://dxr.mozilla.org/mozilla-central/source/gfx/layers/ImageContainer.h#576

We may simply use this callback and make the callback fired only after attach.

Either way, the solution just ease the av out of sync because the attach operation can be send to Compositor asynchronously, we should add an ack message of attach and poke decoder at that time.

Comment 73

[Wenyuan Chi [:wchi]]

(In reply to Chiajung Hung [:chiajung] from comment #72)
> Comment on attachment 8586590 [details] [diff] [review]
> wip1-defer-startdecoding.patch
> 
> Review of attachment 8586590 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Which branch this patch based on? I can not find MetadataDecoded and I think
> it is FinishDecodeFirstFrame now. If this is intended to land in central,
> please rebase.
> 
I was working on branch v2.1s.
Not sure if we need to land this patch to mc.

> BTW, I suggest blake will feedback for Decoder part, and I will just skip
> that part.
> 
> I think the display part missing ImageContainer.cpp in this patch. And for
> the callback in ImageContainer, we have a similar thing in
> https://dxr.mozilla.org/mozilla-central/source/gfx/layers/ImageContainer.
> h#576

Working on this.

> We may simply use this callback and make the callback fired only after
> attach.
> 
> Either way, the solution just ease the av out of sync because the attach
> operation can be send to Compositor asynchronously, we should add an ack
> message of attach and poke decoder at that time.

Yes, we will need the ack message.
Do you know what to modify?

Thanks for your time.

Comment 74

[Blake Wu [:bwu][:blakewu]]

Comment on attachment 8586590 [details] [diff] [review]
wip1-defer-startdecoding.patch

Review of attachment 8586590 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks wchi! 
I can tell this patch really can work well when I tried it with wchi. 
But It would be better to try to push UI reflow task to be done first as possible as we can. 
The main reasons are below.
1. This additional state (which is only needed for low end device) causes the complexity of MediaDecoderStateMachine. IMO, it is not worth doing so. 
2. The better solution should be let UI ready before decoding video frames. Not make decoding process wait UI ready.  

Per discussion offline, 
Resolution, like height and width, can be obtained before creating decoder (required to change some codes). We can get height and width to do UI reflow before creating decoder.

::: content/media/MediaDecoderStateMachine.cpp
@@ +1231,4 @@
>    "DECODING_METADATA",
>    "WAIT_FOR_RESOURCES",
>    "DORMANT",
> +  "WAIT_FOR_DISPLAY",

For this additional state, need to further check if there is no problem caused during state transition, like WAIT_FOR_DISPLAY -> DORMANT.

Comment 75

[Blake Wu [:bwu][:blakewu]]

(In reply to Blake Wu [:bwu][:blakewu] from comment #74)
> Comment on attachment 8586590 [details] [diff] [review]
> wip1-defer-startdecoding.patch
> 
> Review of attachment 8586590 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Thanks wchi! 
> I can tell this patch really can work well when I tried it with wchi. 
> But It would be better to try to push UI reflow task to be done first as
> possible as we can. 
> The main reasons are below.
> 1. This additional state (which is only needed for low end device) causes
> the complexity of MediaDecoderStateMachine. IMO, it is not worth doing so. 
> 2. The better solution should be let UI ready before decoding video frames.
> Not make decoding process wait UI ready.  
> 
> Per discussion offline, 
> Resolution, like height and width, can be obtained before creating decoder
> (required to change some codes). We can get height and width to do UI reflow
> before creating decoder.
Wchi, 
Could you help evaluate the idea mentioned above? With hard-coded height and width, it should be able to check if this idea can work or not.

Comment 76

[Wenyuan Chi [:wchi]]

Attachment: wip2-defer-play.patch

This patch defers the timing of MediaDecoder::Play().
It have the same effect as WIP-1.

Comment 77

[Wenyuan Chi [:wchi]]

Hi black, 
After discussion, there are other fundamental issues within this bug.
(In reply to Blake Wu [:bwu][:blakewu] from comment #75)
> (In reply to Blake Wu [:bwu][:blakewu] from comment #74)
> > Comment on attachment 8586590 [details] [diff] [review]
> > wip1-defer-startdecoding.patch
> > 
> > Review of attachment 8586590 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > Thanks wchi! 
> > I can tell this patch really can work well when I tried it with wchi. 
> > But It would be better to try to push UI reflow task to be done first as
> > possible as we can. 
> > The main reasons are below.
> > 1. This additional state (which is only needed for low end device) causes
> > the complexity of MediaDecoderStateMachine. IMO, it is not worth doing so. 
> > 2. The better solution should be let UI ready before decoding video frames.
> > Not make decoding process wait UI ready.  
> > 
> > Per discussion offline, 
> > Resolution, like height and width, can be obtained before creating decoder
> > (required to change some codes). We can get height and width to do UI reflow
> > before creating decoder.
> Wchi, 
> Could you help evaluate the idea mentioned above? With hard-coded height and
> width, it should be able to check if this idea can work or not.

Hi Black,

I think WIP-2 is pretty much what you want.
Do you still need me to test the idea of hard-coded height and width?

Is WIP-2  has the same ef

Comment 78

[Chiajung Hung [:chiajung]]

Comment on attachment 8587298 [details] [diff] [review]
wip2-defer-play.patch

Review of attachment 8587298 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good to me, just clear log before review or landing.

Comment 79

[Blake Wu [:bwu][:blakewu]]

Comment on attachment 8587298 [details] [diff] [review]
wip2-defer-play.patch

Review of attachment 8587298 [details] [diff] [review]:
-----------------------------------------------------------------

This looks better than last patch! 
However this patch makes mediadecoder wait to play until callback is called.  
I think it would be better not to make them coupled.

Comment 80

[Blake Wu [:bwu][:blakewu]]

Comment on attachment 8587298 [details] [diff] [review]
wip2-defer-play.patch

Review of attachment 8587298 [details] [diff] [review]:
-----------------------------------------------------------------

Sotaro,
The current analysis of this bug is as comment 49. 
Since dolphin is single core, when the problem occurs CPU seems busy in many things, like reading data from network, writing data to storage, and decoding video and audio data, there is no available CPU resource to do UI reflow. 
How do you think?

Comment 81

[Wenyuan Chi [:wchi]]

Attachment: wip3-defer-start-play.patch

Try to decouple decoder from callback to address bwu's concern,

Comment 82

[Wenyuan Chi [:wchi]]

Hi black,

Update my observation.

The solution (wip2,3) cannot solve this issue 100%. It can only ease the pain.
Usually the solution works. But it fails sometimes. (it could possibly caused by busy networking.)
I still can see about 1~2 second delay between audio and video in bad case.

By the way, I see this log after apply the patch.
Not sure if it is ok. Can you comment?

> 04-07 03:41:56.010 18966 19083 I Gecko   : Slow video decode, set mLowAudioThresholdUsecs=318778 mAmpleAudioThresholdUsecs=1000000
> 04-07 03:41:56.010 18966 19083 I Gecko   : Skipping video decode to the next keyframe
> 04-07 03:41:56.030 18966 19083 I Gecko   : Skipping video decode to the next keyframe
> 04-07 03:41:56.040 18966 19075 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb2b81de0
> 04-07 03:41:56.040 18966 19083 I Gecko   : Skipping video decode to the next keyframe
> 04-07 03:41:56.060 18966 19084 I Gecko   : Skipping video decode to the next keyframe

Comment 83

[Blake Wu [:bwu][:blakewu]]

Comment on attachment 8588955 [details] [diff] [review]
wip3-defer-start-play.patch

Review of attachment 8588955 [details] [diff] [review]:
-----------------------------------------------------------------

This patch still makes mediadecoder to wait to play until layer is attached. 
I think this would be helpful to fix this bug for single-core device, but would impact the performance of multi-core device since this patch avoid mediadecoder playing (preparing the decoding pipeline and moreover decoding data) and layer attaching at the same time.

Comment 84

[Blake Wu [:bwu][:blakewu]]

(In reply to Wenyuan Chi [:wchi] from comment #82)
> Hi black,
> 
> Update my observation.
> 
> The solution (wip2,3) cannot solve this issue 100%. It can only ease the
> pain.
> Usually the solution works. But it fails sometimes. (it could possibly
> caused by busy networking.)
> I still can see about 1~2 second delay between audio and video in bad case.
> 
> By the way, I see this log after apply the patch.
> Not sure if it is ok. Can you comment?
> 
> > 04-07 03:41:56.010 18966 19083 I Gecko   : Slow video decode, set mLowAudioThresholdUsecs=318778 mAmpleAudioThresholdUsecs=1000000
> > 04-07 03:41:56.010 18966 19083 I Gecko   : Skipping video decode to the next keyframe
> > 04-07 03:41:56.030 18966 19083 I Gecko   : Skipping video decode to the next keyframe
> > 04-07 03:41:56.040 18966 19075 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb2b81de0
> > 04-07 03:41:56.040 18966 19083 I Gecko   : Skipping video decode to the next keyframe
> > 04-07 03:41:56.060 18966 19084 I Gecko   : Skipping video decode to the next keyframe
This is the skipToNextKeyFrame mechanism. It is supposed to seek to next key frame when audio or video data is *not enough*, however in OmxDecoder it is not implemented correctly. Anyway, it will skip frames, so you will see there is no frames rendering. 
For more info, you can refer to Bug 1120243 comment 0.

Comment 85

[Blake Wu [:bwu][:blakewu]]

(In reply to Wenyuan Chi [:wchi] from comment #77)
> Hi black, 
> After discussion, there are other fundamental issues within this bug.
> (In reply to Blake Wu [:bwu][:blakewu] from comment #75)
> > (In reply to Blake Wu [:bwu][:blakewu] from comment #74)
> > > Comment on attachment 8586590 [details] [diff] [review]
> > > wip1-defer-startdecoding.patch
> > > 
> > > Review of attachment 8586590 [details] [diff] [review]:
> > > -----------------------------------------------------------------
> > > 
> > > Thanks wchi! 
> > > I can tell this patch really can work well when I tried it with wchi. 
> > > But It would be better to try to push UI reflow task to be done first as
> > > possible as we can. 
> > > The main reasons are below.
> > > 1. This additional state (which is only needed for low end device) causes
> > > the complexity of MediaDecoderStateMachine. IMO, it is not worth doing so. 
> > > 2. The better solution should be let UI ready before decoding video frames.
> > > Not make decoding process wait UI ready.  
> > > 
> > > Per discussion offline, 
> > > Resolution, like height and width, can be obtained before creating decoder
> > > (required to change some codes). We can get height and width to do UI reflow
> > > before creating decoder.
> > Wchi, 
> > Could you help evaluate the idea mentioned above? With hard-coded height and
> > width, it should be able to check if this idea can work or not.
> 
> Hi Black,
> 
> I think WIP-2 is pretty much what you want.
> Do you still need me to test the idea of hard-coded height and width?
That would be great if you can help on it. Thanks a lot! 
For this idea, if it can work on single-core platform, I think it should not impact the performance of multi-core platform.

Comment 86

[Blake Wu [:bwu][:blakewu]]

Comment on attachment 8587298 [details] [diff] [review]
wip2-defer-play.patch

Cancel feedback? and discuss the possible solution first.

Comment 87

[Wenyuan Chi [:wchi]]

Attachment: wip4-force-attach-layer.patch

Comment 88

[Wenyuan Chi [:wchi]]

Hi Black,

Your idea of "attach layer before decode" is implemented in wip4-force-attach-layer.patch

Here is the result.

https://youtu.be/rVwhz_dFQ2w
https://youtu.be/25GgNvcDaFI
https://youtu.be/7Ser6IOsfRs
https://youtu.be/C05JM3AJ068

Comment 89

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Attachment: temporay patch

I skim through the bug. From it, to fix the problem the following thing seems necessary.
- When video should be shown in a display, MediaDecoder need to wait in PLAY_STATE_LOADING state until the video frame is shown in the display.

I quickly created a patch to do it. There might be a better way to do it.

Comment 90

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Comment on attachment 8589977 [details] [diff] [review]
temporay patch

bwu, I created a patch. Can you check how it works to the problem?

Comment 91

[Wenyuan Chi [:wchi]]

(In reply to Sotaro Ikeda [:sotaro] from comment #90)
> Comment on attachment 8589977 [details] [diff] [review]
> temporay patch
> 
> bwu, I created a patch. Can you check how it works to the problem?

Hi Sotaro,

I try to port your patch to branch v2.1s and encounter a problem.
In v2.1s, there is no MediaDecoder::FirstFrameLoaded().
So, where do you think is a good place to call WaitOneTransactionIfNecessary() in v2.1s


I have tried MediaDecoder::MetadataLoaded(). It doesn't work well.

Comment 92

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

I do not have v2.1s environment. Therefore I am checking on v2.1 flame-kk. 

I recognize that on v2.1, MediaDecoder's state change is very different compared to master/v2.2. It seems one reason of the problem. MediaDecoer could changed to PLAY_STATE_PLAYING or PLAY_STATE_SEEKING states even before metadata loaded event.

On master, it can change state after MediaDecoder::FirstFrameLoaded().

Comment 93

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Attachment: patch for v2.1 - Change MediaDecoder's state transition

Comment 94

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Attachment: patch for v2.1 - Wait one refresh

Comment 95

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

wchi, I created attachment 8591018 [details] [diff] [review] and attachment 8591019 [details] [diff] [review]. Can you check if either patch fix the problem?

attachment 8591018 [details] [diff] [review] is less risky patch.

Comment 96

[Blake Wu [:bwu][:blakewu]]

Comment on attachment 8589583 [details] [diff] [review]
wip4-force-attach-layer.patch

Review of attachment 8589583 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks for your help! 
After sync with you, although this patch works ok, it causes some problem like sometimes audio playing is not smooth. 
It should be required to consider more to fix this bug.

Comment 97

[Wenyuan Chi [:wchi]]

(In reply to Sotaro Ikeda [:sotaro] from comment #95)
> wchi, I created attachment 8591018 [details] [diff] [review] and attachment
> 8591019 [details] [diff] [review]. Can you check if either patch fix the
> problem?
> 
> attachment 8591018 [details] [diff] [review] is less risky patch.

Hi Sotaro,

attachment 8589583 [details] [diff] [review] "patch for v2.1 - Change MediaDecoder's state transition" work well.
attachment 8591019 [details] [diff] [review] "patch for v2.1 - Wait one refresh" doesn't work.

Can you explain the change more details? I'm very curious.

Comment 98

[Wenyuan Chi [:wchi]]

Note.

Judged by the log.
We now start playing after receiving MetadataLoaded.

> 5697  5697 I Gecko   : SetSrc=http://r2--.....
> 5544  5573 I Gecko   : 0xad0dc5e0 LayerTransactionParent::Attach aCompositable=0xad0e4c80, ShadowLayerParent=0xb0b3b920
> 5697  5697 I Gecko   : HTMLMediaElement::BindToTree
> 5697  5697 I Gecko   : HTMLMediaElement::InitializeDecoderForChannel
> 5697  5697 I Gecko   : HTMLMediaElement::GetVideoFrameContainer - Create 0xb1a1ecd0
> 5697  5697 I Gecko   : HTMLMediaElement::FinishDecoderSetup
> 5697  5697 I Gecko   : ChangeState PAUSED => LOADING
> 5697  5860 I Gecko   : Change machine state from NONE to DECODING_METADATA
> 5697  5861 I Gecko   : Decoding Media Headers
> 5697  5862 I Gecko   : NotifyWaitingForResourcesStatusChanged
> 5697  5861 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0x0
> 5697  5861 I Gecko   : FinishDecodeMetadata
> 5697  5861 I Gecko   : DecodeMetadata first video frame start 0
> 5697  5861 I Gecko   : DecodeMetadata first audio frame start 23219
> 5697  5861 I Gecko   : SetStartTime(0)
> 5697  5861 I Gecko   : Set media start time to 0
> 5697  5861 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb184ed40
> 5697  5861 I Gecko   : Media goes from 0 to 253376145 (duration 253376145) transportSeekable=1, mediaSeekable=1
> 5697  5861 I Gecko   : Changed state from DECODING_METADATA to DECODING
> 5697  5861 I Gecko   : Change machine state from DECODING_METADATA to DECODING
> 5697  5861 I Gecko   : CheckIfDecodeComplete NOT completed
> 5697  5861 I Gecko   : CheckIfDecodeComplete NOT completed
> 5697  5697 I Gecko   : PresShell::DoReflow target=0xb36212b8
> 5697  5697 I Gecko   : MetadataLoaded, channels=2 rate=44100 hasAudio=1 hasVideo=1
> 5697  5697 I Gecko   : InvalidateWithFlags mImageSizeChanged=1, mIntrinsicSizeChanged=1, asyncInvalidate=1
> 5697  5697 I Gecko   : ChangeState LOADING => PLAYING
This step is deferred after apply patch.
Now, StartPlaying() after MetadataLoaded
> 5697  5860 I Gecko   : StartPlayback()
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb184ed40
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb18731a0
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb1873380
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb1873420
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb184ed40
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb18731a0
> 5697  5697 I Gecko   : PresShell::DoReflow target=0xb36212b8
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb1873380
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb1873420
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb184ed40
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb18731a0
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb1873380
> 5697  5697 I Gecko   : 0xb2dafa80 ClientImageLayer::RenderLayer
> 5697  5697 I Gecko   : try to attach 0
> 5544  5573 I Gecko   : 0xad0dc5e0 LayerTransactionParent::Attach aCompositable=0xabc36fb0, ShadowLayerParent=0xac51a780
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb1873420
> 5697  5860 I Gecko   : VideoFrameContainer::SetCurrentFrame 640x360 image=0xb184ed40

Comment 99

[Wenyuan Chi [:wchi]]

Hi Sotaro

FYI.

Result of "patch for v2.1 - Change MediaDecoder's state transition"

https://www.youtube.com/watch?v=8MiDTibHlFo

Comment 100

[Blake Wu [:bwu][:blakewu]]

(In reply to Sotaro Ikeda [:sotaro] from comment #95)
> wchi, I created attachment 8591018 [details] [diff] [review] and attachment
> 8591019 [details] [diff] [review]. Can you check if either patch fix the
> problem?
> 
> attachment 8591018 [details] [diff] [review] is less risky patch.
Thanks for your weight-in!

Comment 101

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

(In reply to Wenyuan Chi [:wchi] from comment #97)
> (In reply to Sotaro Ikeda [:sotaro] from comment #95)
> > wchi, I created attachment 8591018 [details] [diff] [review] and attachment
> > 8591019 [details] [diff] [review]. Can you check if either patch fix the
> > problem?
> > 
> > attachment 8591018 [details] [diff] [review] is less risky patch.
> 
> Hi Sotaro,
> 
> attachment 8589583 [details] [diff] [review] "patch for v2.1 - Change
> MediaDecoder's state transition" work well.
> attachment 8591019 [details] [diff] [review] "patch for v2.1 - Wait one
> refresh" doesn't work.
> 
> Can you explain the change more details? I'm very curious.

attachment 8591019 [details] [diff] [review] also include attachment 8589583 [details] [diff] [review]. But attachment 8591019 [details] [diff] [review]  could trigger additional reflow. It might affect to this. It is very good that attachment 8589583 [details] [diff] [review]  works well :-) It seems most low risk patch to this problem.

Comment 102

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

(In reply to Sotaro Ikeda [:sotaro] from comment #101)
> attachment 8591019 [details] [diff] [review] also include attachment 8589583 [details] [diff] [review]
> [details] [diff] [review]. But attachment 8591019 [details] [diff] [review] 
> could trigger additional reflow. It might affect to this. It is very good
> that attachment 8589583 [details] [diff] [review]  works well :-) It seems
> most low risk patch to this problem.

Sorry, in the above text, he referred patch was wrong.

Comment 103

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

(In reply to Wenyuan Chi [:wchi] from comment #97)
> 
> attachment 8589583 [details] [diff] [review] "patch for v2.1 - Change
> MediaDecoder's state transition" work well.
> attachment 8591019 [details] [diff] [review] "patch for v2.1 - Wait one
> refresh" doesn't work.
> 
> Can you explain the change more details? I'm very curious.

wchi, "patch for v2.1 - Change MediaDecoder's state transition" is attachment 8591018 [details] [diff] [review]. Did you check it?

Comment 104

[Wenyuan Chi [:wchi]]

(In reply to Sotaro Ikeda [:sotaro] from comment #103)
> (In reply to Wenyuan Chi [:wchi] from comment #97)
> > 
> > attachment 8589583 [details] [diff] [review] "patch for v2.1 - Change
> > MediaDecoder's state transition" work well.
> > attachment 8591019 [details] [diff] [review] "patch for v2.1 - Wait one
> > refresh" doesn't work.
> > 
> > Can you explain the change more details? I'm very curious.
> 
> wchi, "patch for v2.1 - Change MediaDecoder's state transition" is
> attachment 8591018 [details] [diff] [review]. Did you check it?

Yes, I check attachment 8591018 [details] [diff] [review]. It works well.
I wrote the wrong attachment number in comment 97.

Comment 105

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

> > wchi, "patch for v2.1 - Change MediaDecoder's state transition" is
> > attachment 8591018 [details] [diff] [review]. Did you check it?
> 
> Yes, I check attachment 8591018 [details] [diff] [review]. It works well.
> I wrote the wrong attachment number in comment 97.

Good! I think it is most low risk patch in this bug.

Comment 106

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

attachment 8591018 [details] [diff] [review] just change "MediaDecoder state change" more similar to master.

Comment 107

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Attachment: patch for v2.1 - Change MediaDecoder's state transition

Update nits. Carry "r=cpearce".

Comment 108

[Steven Yang [:styang]]

Hi Vincent,
Let's land it to 2.1S. thanks.

Comment 109

[Vincent Liu[:vliu]]

https://hg.mozilla.org/releases/mozilla-b2g34_v2_1s/rev/95b706bcbe10

Comment 110

[[e-mail]]

(In reply to Sotaro Ikeda [:sotaro] from comment #107)
Hi Sotaro - 

Thank you all for your great support, Can you explain the changes to fix this bug more details? I'm very curious and maybe I can learning something about this bug.

Thank you.

Comment 111

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

On default v2.1/v2.1s, MediaDecoder could request starting playback even when MediaDecoderStateMachine does not prepared, it makes MediaDecoderStateMachine start playback as soon as possible if metadata is prepared by MediaDecoderStateMachine. It could make the cpu always busy.

By applying attachment 8592832 [details] [diff] [review], MediaDecoder waits in PLAY_STATE_LOADING state until metadata is prepared in MediaDecoderStateMachine. When MediaDecoder received MetadataLoaded event from MediaDecoderStateMachine, MediaDecoder requests MediaDecoderStateMachine to start playback. MediaDecoder run on main thread and MediaDecoderStateMachine run on state machine thread. These event delivery and the play request is done by message passing. If cpu is too busy for other tasks, these message passing were also delayed. It seems to make throttling play back start.

Especially, MediaDecoder runs on main thread. If this problem is caused by un-scheduled main thread. The patch makes effect of waiting to start playback until main thread is scheduled. 

The followings are related state machine diagrams.
https://github.com/sotaroikeda/firefox-diagrams/blob/master/media/dom_media_MediaDecoderStateMachine_state_FirefoxOS_2_2.pdf
https://github.com/sotaroikeda/firefox-diagrams/blob/master/media/dom_media_MediaDecoder_state_FirefoxOS_2_2.pdf

It makes MediaDecoderStateMachine to wait start playback

Comment 112

[[e-mail]]

(In reply to Sotaro Ikeda [:sotaro] from comment #111)
> On default v2.1/v2.1s, MediaDecoder could request starting playback even
> when MediaDecoderStateMachine does not prepared, it makes
> MediaDecoderStateMachine start playback as soon as possible if metadata is
> prepared by MediaDecoderStateMachine. It could make the cpu always busy.
> 
> By applying attachment 8592832 [details] [diff] [review], MediaDecoder waits
> in PLAY_STATE_LOADING state until metadata is prepared in
> MediaDecoderStateMachine. When MediaDecoder received MetadataLoaded event
> from MediaDecoderStateMachine, MediaDecoder requests
> MediaDecoderStateMachine to start playback. MediaDecoder run on main thread
> and MediaDecoderStateMachine run on state machine thread. These event
> delivery and the play request is done by message passing. If cpu is too busy
> for other tasks, these message passing were also delayed. It seems to make
> throttling play back start.
> 
> Especially, MediaDecoder runs on main thread. If this problem is caused by
> un-scheduled main thread. The patch makes effect of waiting to start
> playback until main thread is scheduled. 
> 
> The followings are related state machine diagrams.
> https://github.com/sotaroikeda/firefox-diagrams/blob/master/media/
> dom_media_MediaDecoderStateMachine_state_FirefoxOS_2_2.pdf
> https://github.com/sotaroikeda/firefox-diagrams/blob/master/media/
> dom_media_MediaDecoder_state_FirefoxOS_2_2.pdf
> 
> It makes MediaDecoderStateMachine to wait start playback
Thanks you for your great help.

Comment 113

[[e-mail]]

Dear Sotaro -

I'm so sorry to trouble you again, After "patch for v2.1 - Change MediaDecoder's state transition" landed in 2.1s, when playing video in youtube, we can also hearing the sounds firstly, then with 2-3s the video displayed.

Could you help to double check this issue? thanks.

Comment 114

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

I am going to check it tomorrow.

Comment 115

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

(In reply to [e-mail] from comment #113)
> Dear Sotaro -
> 
> I'm so sorry to trouble you again, After "patch for v2.1 - Change
> MediaDecoder's state transition" landed in 2.1s, when playing video in
> youtube, we can also hearing the sounds firstly, then with 2-3s the video
> displayed.
> 
> Could you help to double check this issue? thanks.

Bug 1065827 makes MediaDecoder actually wait first video frame. It might work to the problem.

Comment 116

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Attachment: Bug 1065827 patch for v2.1s part 1 - Start MediaDecoder playback state in LOADING

Comment 117

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Attachment: Bug 1065827 patch for v2.1s part 2 - Do not always wait to decode frames to emit loadedmetadata

Comment 118

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Attachment: Bug 1065827 patch for v2.1s part 3 - Invalidate video frame container during FirstFrameLoaded

Comment 119

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

lin.hui, can you check if attachment 8600048 [details] [diff] [review], attachment 8600051 [details] [diff] [review] and attachment 8600054 [details] [diff] [review] works for the problem?

Comment 120

[[e-mail]]

Dear Sotaro:

Sorry for the delay, after applying the three patches, A/V sync seems have some improve, but some times I still can reproduce it, when audio coming in timely but video delayed, I think it's may network condition related.

If indeed related with network, we can fix this issue by applying above three patches.

Thanks you for your great help.

Comment 121

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Comment on attachment 8600051 [details] [diff] [review]
Bug 1065827 patch for v2.1s part 2 - Do not always wait to decode frames to emit loadedmetadata

cpearce, can you review the patch? It is uplift of Bug 1065827 except seeking related change. The seeking related change was already uplifted to b2g v2.1s.

Comment 122

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

(In reply to [e-mail] from comment #120)
> Dear Sotaro:
> 
> Sorry for the delay, after applying the three patches, A/V sync seems have
> some improve, but some times I still can reproduce it, when audio coming in
> timely but video delayed, I think it's may network condition related.

Hi lin.hui, is the delay is only video start delay, not a/v sync delay?

Comment 123

[[e-mail]]

(In reply to Sotaro Ikeda [:sotaro] from comment #122)
> Hi lin.hui, is the delay is only video start delay, not a/v sync delay?
Yes, I mean the delay is only video start delay, sometimes there have no delay.

Comment 124

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Attachment: Bug 1065827 patch for v2.1s part 1 - Start MediaDecoder playback state in LOADING

Add header to the patch. Carry "r=cpearce".

Comment 125

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Attachment: Bug 1065827 patch for v2.1s part 2 - Do not always wait to decode frames to emit loadedmetadata

Comment 126

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Attachment: Bug 1065827 patch for v2.1s part 3 - Invalidate video frame container during FirstFrameLoaded

Comment 127

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

vliu, can you apply the following patch to v2.1s?
- attachment 8602098 [details] [diff] [review]
- attachment 8602099 [details] [diff] [review]
- attachment 8602100 [details] [diff] [review]

Comment 128

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

(In reply to Sotaro Ikeda [:sotaro] from comment #127)
> vliu, can you apply the following patch to v2.1s?
> - attachment 8602098 [details] [diff] [review]
> - attachment 8602099 [details] [diff] [review]
> - attachment 8602100 [details] [diff] [review]

lin.hui, can you check if the above 3 patchs + attachment 8602242 [details] [diff] [review] in Bug 1091037 affect to the problem?

Comment 129

[[e-mail]]

(In reply to Sotaro Ikeda [:sotaro] from comment #128)
> (In reply to Sotaro Ikeda [:sotaro] from comment #127)
> > vliu, can you apply the following patch to v2.1s?
> > - attachment 8602098 [details] [diff] [review]
> > - attachment 8602099 [details] [diff] [review]
> > - attachment 8602100 [details] [diff] [review]
> 
> lin.hui, can you check if the above 3 patchs + attachment 8602242 [details] [diff] [review]
> [diff] [review] in Bug 1091037 affect to the problem?
Dear Sotaro, sadly to tell you after applying above four patches, I still can see the video start delay, we can hearing sounds but no video output.

Thank you.

Comment 130

[Vincent Liu[:vliu]]

(In reply to Sotaro Ikeda [:sotaro] from comment #127)
> vliu, can you apply the following patch to v2.1s?
> - attachment 8602098 [details] [diff] [review]
> - attachment 8602099 [details] [diff] [review]
> - attachment 8602100 [details] [diff] [review]

Done!

https://hg.mozilla.org/releases/mozilla-b2g34_v2_1s/rev/00d393720d6f
https://hg.mozilla.org/releases/mozilla-b2g34_v2_1s/rev/1e72cb67c1cc
https://hg.mozilla.org/releases/mozilla-b2g34_v2_1s/rev/6b61a152c89e

Comment 131

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

lin.hui, I could not reproduce the problem on my side, can you explain more about the symptom(how much delay?) and frequency? Can you attach a current symptom's video?

Comment 132

[[e-mail]]

(In reply to Sotaro Ikeda [:sotaro] from comment #131)
> lin.hui, I could not reproduce the problem on my side, can you explain more
> about the symptom(how much delay?) and frequency? Can you attach a current
> symptom's video?
Dear Sotaro:
My gecko build has already contains the following patches:
>patch for v2.1 - Change MediaDecoder's state transition
>Bug 1065827 patch for v2.1s part 1 - Start MediaDecoder playback state in LOADING
>Bug 1065827 patch for v2.1s part 2 - Do not always wait to decode frames to emit loadedmetadata
>Bug 1065827 patch for v2.1s part 3 - Invalidate video frame container during FirstFrameLoaded 
Then do the test with youtube video, I captured the video, please go to following path to downloading:
  ftp://ftp.spreadtrum.com/for_sprd_mozilla/Youtube_Issue/     fie name: Youtube_video_delay.MOV
    username: mouzhi
    password: mouZHI$$61​

Dear vance: 
  If sotaro can not visit the site, please help to upload the reproduce video to youtube.
  Really thanks!

Comment 133

[Vance Chen [:vchen][skype:vance.lucida][[e-mail]]]

Hi Sotaro -

Update the video here:

https://www.youtube.com/watch?v=icyqzO3zyKM&feature=youtu.be

As you can see from the video, the sound and the video has about 1 - 2 seconds delay

Thanks

Comment 134

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Thanks for the video. I confirmed the delay in the video. But I do not think this is a same bug to this bug. Such delay also exit on master flame-kk.

Comment 135

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

And this bug is set as major. The video in comment 133 seems not major bug. From comment 134, I think that it seems better handle the problem of 1-2 sec delay as a different bug.

Comment 136

[Sotaro Ikeda [:sotaro PTO July/5 - July/11]]

Created Bug 1163766.