1068963 - Frame drops during end-to-end playback

Status: RESOLVED INCOMPLETE

(Core :: Audio/Video, defect)

Description

[bhargavg1]

Hi See that on FFOS we see higher rate of framedrops in end-to-end playback (no seek action involved) when compared to other platforms on the same chipset.

This behavior is seen across different video codecs.
   Clip         FFOS               FFOS        Comparison    Comparison
              (Frame Rate)    (Frame Drops)   (Frame Rate)   (Frame Drops)
mpeg4_asp       29.52             6/309          30.37            0/310
mpeg4_amr_wide  12.3               3/189         12.55            0/188
h263_fwvga_aac  29.94             18/1072        24.88            0/1073
h263_amr_narrow 24.18             6/372          24.88            1/374

Comment 1

[bhargavg1]

[Blocking Requested - why for this release]:

Comment 2

[Hema Koka [:hema]]

Sotaro/Milan, 

Probably belongs to core media for triage. Please help route it to the right team. 

Thanks
Hema

Comment 3

[Sotaro Ikeda [:sotaro]]

bhargavg1, how did you measure the frame drop?

Comment 4

[Sotaro Ikeda [:sotaro]]

> Probably belongs to core media for triage. Please help route it to the right
> team. 

I am not sure how the frame drop is observed. But gecko could easily do frame drops compared to android on display.

In android, video rendering is done like the following sequence. In android, Binder ipc is multi-threaded ipc, then there is no blocking problem until SurfaceFlinger.

> applciation's playback thread->(Binder ipc)->SurfaceFlinger process' binder ipc thread->"Trigger SurfaceFlinger's composition"

In b2g, video rendering is done like the following sequence. gecko ipc is single threaded ipc, then ImageBridge thread and compositor thread could be blocked by some reasons.

> "applciation's playback thread"->ImageBridge thread->gecko ipc->compositor thread->trigger compositor's composition

Therefore it is unavoidable video frames are dropped in the middle of composition.

Comment 5

[Sotaro Ikeda [:sotaro]]

In current gecko, MediaDecoderStateMachine do video rendering based on video frame's timestamp. To address the problem, compositor side need to have a video buffer queue and do rendering based on timestamp.

The problem sit in the middle of "gfx layers" and "Video/Audio". For the time being, it seems better to be categorized to "Video/Audio".

Comment 6

[bhargavg1]

(In reply to Sotaro Ikeda [:sotaro] from comment #3)
> bhargavg1, how did you measure the frame drop?

As per dumps from logcat at the end of playback by video_stats.js

Comment 7

[Sotaro Ikeda [:sotaro]]

(In reply to bhargavg1 from comment #6)
> (In reply to Sotaro Ikeda [:sotaro] from comment #3)
> > bhargavg1, how did you measure the frame drop?
> 
> As per dumps from logcat at the end of playback by video_stats.js

If it is get from video_stats.js, comment 4 and comment 5 are not directly related.

Comment 8

[Sotaro Ikeda [:sotaro]]

> If it is get from video_stats.js, comment 4 and comment 5 are not directly
> related.

This is a problem of "Video/Audio".

Comment 9

[Chris Pearce [:cpearce (Not reading bugmail)]]

(In reply to Sotaro Ikeda [:sotaro] from comment #5)
> In current gecko, MediaDecoderStateMachine do video rendering based on video
> frame's timestamp. To address the problem, compositor side need to have a
> video buffer queue and do rendering based on timestamp.

Roc has been thinking about implementing this change, but I think it's still not at the front of his queue.

Roc: Any idea when you'll get to this?

Comment 10

[Robert O'Callahan (:roc) (email my personal email if necessary)]

I'm looking for a new project right now and that's probably going to be it.

(In reply to Sotaro Ikeda [:sotaro] from comment #4)
> In android, video rendering is done like the following sequence. In android,
> Binder ipc is multi-threaded ipc, then there is no blocking problem until
> SurfaceFlinger.
> 
> > applciation's playback thread->(Binder ipc)->SurfaceFlinger process' binder ipc thread->"Trigger SurfaceFlinger's composition"
> 
> In b2g, video rendering is done like the following sequence. gecko ipc is
> single threaded ipc, then ImageBridge thread and compositor thread could be
> blocked by some reasons.
> 
> > "applciation's playback thread"->ImageBridge thread->gecko ipc->compositor thread->trigger compositor's composition

I don't quite follow. You mean we're doing a synchronous ImageBridge transaction each time we update a video frame?

I agree that publishing all available video frames to the compositor and letting the compositor choose the right one is going to help here, but can you explain why you think it's the most important thing we can do to help here?

Comment 11

[bhavana bajaj [:bajaj]]

bhargav, is this a regression in 2.1 ? Can we map this comparison to 2.0 ?

:roc/:cpearce, anything we changed in 2.1 that might have cuased this ?

Comment 12

[Sotaro Ikeda [:sotaro]]

n.b: This bug is about local drop that happen at MediaDecoderStateMachine. This bug is not related frame drop that might happen between MediaDecoderStateMachine and compositor.

Comment 13

[Robert O'Callahan (:roc) (email my personal email if necessary)]

I don't know of anything indicating this is a regression.

Comment 14

[Chris Pearce [:cpearce (Not reading bugmail)]]

I don't know of anything indicating this is a regression.

Comment 15

[bhargavg1]

Bhavana, doesnt seem to be a regression issue, the test teams have concern more from the quality/competitive comparison

Comment 16

[Sotaro Ikeda [:sotaro]]

At some point in near future, audio/video decoding is changed from OMXCodec to MediaCodec. It could affect to the frame drop.

Comment 17

[Sotaro Ikeda [:sotaro]]

brsun, do you know when the codec will be changed to MediaCodec as in Comment 16?

Comment 18

[Bruce Sun [:brsun]]

(In reply to Sotaro Ikeda [:sotaro] from comment #17)
> brsun, do you know when the codec will be changed to MediaCodec as in
> Comment 16?

Hi Sotaro, kindly refer to bug 1052206 comment 111.

Comment 19

[Dietrich Ayala (:dietrich)]

Triage group decided blocking+ due to commercialization requirement.

Comment 20

[Milan Sreckovic [:milan] (needinfo for best results)]

(In reply to Dietrich Ayala (:dietrich) from comment #19)
> Triage group decided blocking+ due to commercialization requirement.

It is a "new feature" though, so the milestones are not going to be observed for this.

Comment 21

[KTucker [:KTucker][Inactive 3/4/2016]]

Bobby, I'm sorry but I am not sure what is being requested here from the QA Wanted team.

Comment 22

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

(In reply to Milan Sreckovic [:milan] from comment #20)
> It is a "new feature" though, so the milestones are not going to be observed
> for this.

I can't resource it at this point. You will need to butter up Eric if you want this to be fixed. My guess is that there isn't a simple fix for this.

Comment 23

[Bobby Chien]

(In reply to KTucker [:KTucker] from comment #21)
> Bobby, I'm sorry but I am not sure what is being requested here from the QA
> Wanted team.

Hi,

we need QA team provides more testing result for evaluating the situation. basically, we don't know the root cause yet, so we need info to dig out problem.

Comment 24

[StevenLee[:slee]]

[Blocking Requested - why for this release]:
per comment 20 and comment 22, remove 2.1+ flag. I'm assigning Blake to look this issue.

Comment 25

[Eric Chou [:ericchou] [:echou]]

(In reply to Anthony Jones (:kentuckyfriedtakahe, :k17e) from comment #22)
> (In reply to Milan Sreckovic [:milan] from comment #20)
> > It is a "new feature" though, so the milestones are not going to be observed
> > for this.
> 
> I can't resource it at this point. You will need to butter up Eric if you
> want this to be fixed. My guess is that there isn't a simple fix for this.

Bruce is blocked by other issues, so I butter up Steven and it seems to work!

Comment 26

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

Hi bhargavg1, 
Is it possible to share with us your test content?

Comment 27

[Ken Chang[:kenkai]]

Hi Michael,
According to comment 20 and comment 22, I wonder if we could remove this bug from CAF 2.1 list?

Comment 28

[Bobby Chien]

Hi Bhavana, I agree with Ken, what do you think? 

I think we also need more effort to dig the root cause.

Comment 29

[Joshua Mitchell (Inactive)]

(In reply to Bobby Chien [:bchien] from comment #23)
> (In reply to KTucker [:KTucker] from comment #21)
> > Bobby, I'm sorry but I am not sure what is being requested here from the QA
> > Wanted team.
> 
> Hi,
> 
> we need QA team provides more testing result for evaluating the situation.
> basically, we don't know the root cause yet, so we need info to dig out
> problem.

TTL testing through the dev hub has been deemed an invalid means of testing perf / load times / frame rate issues and we do not have the tools available to us that automation or eng have so QA-Wanted has no actionable items here.

Comment 30

[Tony Chung [:tchung]]

(In reply to Joshua Mitchell [:Joshua_M] from comment #29)
> (In reply to Bobby Chien [:bchien] from comment #23)
> > (In reply to KTucker [:KTucker] from comment #21)
> > > Bobby, I'm sorry but I am not sure what is being requested here from the QA
> > > Wanted team.
> > 
> > Hi,
> > 
> > we need QA team provides more testing result for evaluating the situation.
> > basically, we don't know the root cause yet, so we need info to dig out
> > problem.
> 
> TTL testing through the dev hub has been deemed an invalid means of testing
> perf / load times / frame rate issues and we do not have the tools available
> to us that automation or eng have so QA-Wanted has no actionable items here.

It sounds like we need CAF quality to provide more details.   Moz QA is out of ideas at the moment.

Comment 31

[bhargavg1]

(In reply to Blake Wu [:bwu][:blakewu] from comment #26)
> Hi bhargavg1, 
> Is it possible to share with us your test content?

You should be able to see the framedrops with any video clips in logcat at the end of the playback

Comment 32

[bhargavg1]

(In reply to Ken Chang[:ken] from comment #27)
> Hi Michael,
> According to comment 20 and comment 22, I wonder if we could remove this bug
> from CAF 2.1 list?

Which version we are considering to bring this in v2.2?

Comment 33

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

Hi bhargavg1, 
I would like to base on the same environment as yours to observe this problem. 
Could you share us how you measured the frames dropped in more details? 
For FFOS, you used video app to play video and monitor the statistics from video_stats.js? 
How did you measure that on Android? 
Thanks!

Comment 34

[bhargavg1]

(In reply to Blake Wu [:bwu][:blakewu] from comment #33)
> Hi bhargavg1, 
> I would like to base on the same environment as yours to observe this
> problem. 
> Could you share us how you measured the frames dropped in more details? 
> For FFOS, you used video app to play video and monitor the statistics from
> video_stats.js? 

For FFOS currently at the end of video playback stats info is dumped, we are going by that which is spit out by video_stats.js

> How did you measure that on Android? 

On Android as well we get similar info but need to set certain property, 

|adb shell setprop persist.debug.sf.statistics 1|

Sample output on Android would be

01-02 00:01:14.269   232  2667 I AwesomePlayer: ===========================
01-02 00:01:14.269   232  2667 I AwesomePlayer:    videoDimensions(4096 x 2160)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    Total Video Frames Decoded(1)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    Total Video Frames Rendered(0)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    Total Playback Duration(0 ms)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    numVideoFramesDropped(0)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    Average Frames Per Second(0.0000)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    Last Seek To Time(0 ms)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    Last Paused Time(0 ms)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    First Frame Latency (322 ms)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    Number of times AV Sync Lost(0)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    Max Video Ahead Time Delta(0)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    Max Video Behind Time Delta(0)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    Max Time Sync Loss(0)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    EOS(0)
01-02 00:01:14.269   232  2667 I AwesomePlayer:    PLAYING(1)

And for FFOS it would be,
5-30 12:43:21.314  1272  1272 I GeckoDump: Total frames: 1150
05-30 12:43:21.314  1272  1272 I GeckoDump: Decoded frames: 1150
05-30 12:43:21.314  1272  1272 I GeckoDump: Corrupted frames: 0
05-30 12:43:21.314  1272  1272 I GeckoDump: Rendered frames: 1122
05-30 12:43:21.314  1272  1272 I GeckoDump: Dropped frames: 28
05-30 12:43:21.314  1272  1272 I GeckoDump: Average rendered FPS: 28.02

Let me know if you need more info

Comment 35

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

Thanks for your info. 
Did you use Flame to get these statistics and do the comparisons? 
If yes, do you have android's image to run on Flame? Could you share the image?

Comment 36

[bhargavg1]

(In reply to Blake Wu [:bwu][:blakewu] from comment #35)
> Thanks for your info. 
> Did you use Flame to get these statistics and do the comparisons? 

The logs I pasted are just for reference as to how on Android the stats are printed. 

comment 0 stats are from the same chipset.

Comment 37

[bhargavg1]

(In reply to Blake Wu [:bwu][:blakewu] from comment #35)
> If yes, do you have android's image to run on Flame? Could you share the image?

We dont have images for flame

Comment 38

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

Should not block bug 1025317

Comment 39

[Ken Chang[:kenkai]]

After talking with Blake, he confirms that he can finish this on 2.2.

Comment 40

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

(In reply to Ken Chang[:ken] from comment #39)
> After talking with Blake, he confirms that he can finish this on 2.2.

Do we know the cause of the frame drops? If not then it is premature to commit this for 2.2.

Comment 41

[bhavana bajaj [:bajaj]]

(In reply to Anthony Jones (:kentuckyfriedtakahe, :k17e) from comment #40)
> (In reply to Ken Chang[:ken] from comment #39)
> > After talking with Blake, he confirms that he can finish this on 2.2.
> 
> Do we know the cause of the frame drops? If not then it is premature to
> commit this for 2.2.

Blake may know, NI him.

Comment 42

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

For FFOS v2.2, the decoding module will be changed, so we will check this problem with new decoder module again. 
We plan to use Gonk decode module to play all mp4 files (bug 1061034) and use MediaCodecReader (Bug 1033900) to decode non-mp4 files.

Comment 43

[Ravi Dandu]

Hi Blake, When can we know if this can be planned for 2.2?

Comment 44

[StevenLee[:slee]]

Hi rdandu,

We've added this into 2.2.

Hi bhargavg1,

Can you provide the testing clips? Are you running the test on video app?

Comment 45

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

For what I understood from comment 34 and its above, it looks like FFOS and Android both use video APP to play a local file.

Comment 46

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

A possible root cause for frame dropped may be FFOS' AV sync mechanism[1] is different from Android's[2]. 

[1]http://dxr.mozilla.org/mozilla-central/source/dom/media/MediaDecoderStateMachine.cpp#2804
[2]http://androidxref.com/4.4.4_r1/xref/frameworks/av/media/libstagefright/AwesomePlayer.cpp#1919

Comment 47

[StevenLee[:slee]]

I tested the latest gecko/gaia from m-c. Here is my testing results and environment.

* versions
Gaia-Rev        ae3a84acaab80a5b35d5542d63e68462273c8a1b
Gecko-Rev       https://hg.mozilla.org/mozilla-central/rev/2d0a51ef828d
Build-ID        20141117160200
Version         36.0a1
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.yy.20141022.095218
FW-Date         Wed Oct 22 09:52:38 CST 2014
Bootloader      L1TC00011880

* testing target - http://donsnotes.com/big-files/fish.mp4

* results
Video statistics start
Dimensions: 1280x720
Complete duration: 01:47
Start time: 00:00
End time: 00:00
Total frames: 3229
Decoded frames: 3228
Corrupted frames: 1
Rendered frames: 3228
Dropped frames: 1
Average rendered FPS: 29.96
Video statistics end


Hi bhargavg1,

Can you test with the latest gecko again? Thanks

Comment 48

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

(In reply to Blake Wu [:bwu][:blakewu] from comment #46)
> A possible root cause for frame dropped may be FFOS' AV sync mechanism[1] is
> different from Android's[2]. 
> 
> [1]http://dxr.mozilla.org/mozilla-central/source/dom/media/
> MediaDecoderStateMachine.cpp#2804
> [2]http://androidxref.com/4.4.4_r1/xref/frameworks/av/media/libstagefright/
> AwesomePlayer.cpp#1919

Yes, Awesomeplayer results are totally bogus. It counts frames up to 40ms late as not dropped.

Comment 49

[Michael Vines [:m1] [:evilmachines]]

(closing for now, we can raise again if it this is observed during v2.2 test)

Comment 50

[Eric Chang [:ericcc] [:echang]]

Just checked in v2.2, here are the statistics.

*** versions
Serial: e47cd843 (State: device)
Build ID               20150202162500
Gaia Revision          d6141fa3208f224393269e17c39d1fe53b7e6a05
Gaia Date              2015-01-30 03:46:29
Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/6f3e016aead3
Gecko Version          37.0a2
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20150202.215916
Firmware Date          Mon Feb  2 21:59:27 EST 2015
Bootloader             L1TC000118D0

*** testing target 
http://donsnotes.com/big-files/fish.mp4

*** results
02-03 17:56:18.911  1582  1582 I GeckoDump: Video statistics start
02-03 17:56:18.911  1582  1582 I GeckoDump: Dimensions: 1280x720
02-03 17:56:18.911  1582  1582 I GeckoDump: Complete duration: 01:47
02-03 17:56:18.911  1582  1582 I GeckoDump: Start time: 00:00
02-03 17:56:18.911  1582  1582 I GeckoDump: End time: 00:00
02-03 17:56:18.911  1582  1582 I GeckoDump: Total frames: 3229
02-03 17:56:18.911  1582  1582 I GeckoDump: Decoded frames: 3228
02-03 17:56:18.911  1582  1582 I GeckoDump: Corrupted frames: 1
02-03 17:56:18.911  1582  1582 I GeckoDump: Rendered frames: 3225
02-03 17:56:18.911  1582  1582 I GeckoDump: Dropped frames: 4
02-03 17:56:18.911  1582  1582 I GeckoDump: Average rendered FPS: 29.94
02-03 17:56:18.911  1582  1582 I GeckoDump: Video statistics end