Closed Bug 1068963 Opened 10 years ago Closed 10 years ago

Frame drops during end-to-end playback

Categories

(Core :: Audio/Video, defect)

Product:
Core
Component:
Audio/Video
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED INCOMPLETE
Milestone:
2.2 S1 (5dec)
Project Flags:
blocking-b2g 2.2+
feature-b2g 2.2+

People

(Reporter: bhargavg1, Assigned: bwu)

References

Details

(Whiteboard: [caf priority: p2][CR 723018]) 

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
[Blocking Requested - why for this release]:
blocking-b2g: --- → 2.1?
Component: Gaia::Video → Video/Audio
Product: Firefox OS → Core
Sotaro/Milan, 

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

Thanks
Hema
Flags: needinfo?(sotaro.ikeda.g)
bhargavg1, how did you measure the frame drop?
Flags: needinfo?(sotaro.ikeda.g) → needinfo?(bhargavg1)
> 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.
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".
(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
Flags: needinfo?(bhargavg1)
(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.
> If it is get from video_stats.js, comment 4 and comment 5 are not directly
> related.

This is a problem of "Video/Audio".
Whiteboard: [CR 723018] → [caf priority: p2][CR 723018]
(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?
Flags: needinfo?(roc)
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?
Flags: needinfo?(roc)
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 ?
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.
Flags: needinfo?(roc)
Flags: needinfo?(cpearce)
Flags: needinfo?(bhargavg1)
I don't know of anything indicating this is a regression.
Flags: needinfo?(roc)
I don't know of anything indicating this is a regression.
Flags: needinfo?(cpearce)
Bhavana, doesnt seem to be a regression issue, the test teams have concern more from the quality/competitive comparison
Flags: needinfo?(bhargavg1)
At some point in near future, audio/video decoding is changed from OMXCodec to MediaCodec. It could affect to the frame drop.
brsun, do you know when the codec will be changed to MediaCodec as in Comment 16?
Flags: needinfo?(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.
Flags: needinfo?(brsun)
Triage group decided blocking+ due to commercialization requirement.
blocking-b2g: 2.1? → 2.1+
(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.
Flags: needinfo?(ajones)
Keywords: qawanted
Bobby, I'm sorry but I am not sure what is being requested here from the QA Wanted team.
Flags: needinfo?(bchien)
(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.
Flags: needinfo?(ajones) → needinfo?(echou)
(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.
Flags: needinfo?(bchien) → needinfo?(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.
blocking-b2g: 2.1+ → 2.1?
Flags: needinfo?(slee)
Flags: needinfo?(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!
Hi bhargavg1, 
Is it possible to share with us your test content?
Flags: needinfo?(bhargavg1)
Hi Michael,
According to comment 20 and comment 22, I wonder if we could remove this bug from CAF 2.1 list?
Flags: needinfo?(mvines)
Hi Bhavana, I agree with Ken, what do you think? 

I think we also need more effort to dig the root cause.
Flags: needinfo?(bbajaj)
(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.
Keywords: qawanted
(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.
(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
Flags: needinfo?(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?
Flags: needinfo?(mvines)
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!
Assignee: nobody → bwu
blocking-b2g: 2.1? → 2.2?
Flags: needinfo?(bbajaj)
Blocks: CAF-v2.2-metabug
No longer blocks: CAF-v2.1-FC-metabug
Flags: needinfo?(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
Flags: needinfo?(bhargavg1)
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?
(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.
(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
Should not block bug 1025317
No longer blocks: CAF-v2.1-FC-metabug
No longer blocks: CAF-v2.1-FC-metabug
After talking with Blake, he confirms that he can finish this on 2.2.
blocking-b2g: 2.2? → 2.2+
(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.
(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.
Flags: needinfo?(bwu)
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.
Flags: needinfo?(bwu)
Hi Blake, When can we know if this can be planned for 2.2?
Flags: needinfo?(bwu)
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?
Flags: needinfo?(bwu) → needinfo?(bhargavg1)
feature-b2g: --- → 2.2+
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.
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
(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.
Flags: needinfo?(bhargavg1) → needinfo?(mvines)
QA Whiteboard: [2.2-feature-qa+]
(closing for now, we can raise again if it this is observed during v2.2 test)
Status: NEW → RESOLVED
Closed: 10 years ago
Flags: needinfo?(mvines)
Resolution: --- → INCOMPLETE
Flags: in-moztrap?(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
Flags: in-moztrap?(echang) → in-moztrap-
Target Milestone: --- → 2.2 S1 (5dec)
Blocks: CAF-v3.0-FL-metabug
No longer blocks: CAF-v3.0-FL-metabug
You need to log in before you can comment on or make changes to this bug.