Intermittent | test_streams_element_capture.html | vp9.webm current time at end: 0.4329996109008789 should be: 4

RESOLVED FIXED in mozilla31

Status

()

defect
RESOLVED FIXED
5 years ago
4 years ago

People

(Reporter: cbook, Assigned: jwwang)

Tracking

({intermittent-failure})

Trunk
mozilla31
ARM
Android
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox-esr31 unaffected)

Details

()

Attachments

(1 attachment)

Reporter

Description

5 years ago
Android 2.2 Tegra mozilla-inbound opt test mochitest-3 on 2014-03-07 00:29:12 PST for push b9fc2eb18bd1

slave: tegra-177

https://tbpl.mozilla.org/php/getParsedLog.php?id=35778365&tree=Mozilla-Inbound

1267 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_streams_element_capture.html | vp9.webm current time at end: 0.4329996109008789 should be: 4
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Assignee

Updated

5 years ago
Assignee: nobody → jwwang
Assignee

Comment 4

5 years ago
There are some abnormal behaviors I observed from the logs:
1. In MediaDecoderStateMachine::AdvanceFrame(), |clock_time| is calculated from the last stream output time when the the media element is captured. |clock_time| won't advance if stream doesn't advance. Therefore I think state machine should be scheduled based on the stream output time instead of a real-time time when it is captured.

2. In MediaDecoderStateMachine::DecodeVideo(), |mReader->DecodeVideoFrame| is wrapped in an ReentrantMonitorAutoExit monitor. It allows MediaDecoderStateMachine::AdvanceFrame() to kick in to consume |mReader->VideoQueue()| before SendStreamData() is called which writes video frames to the media stream. Therefore, some video frames are missed from the media stream.

3. In test_streams_element_capture.html, |vout.currentTime| depends on how many frames are played by the media stream graph. When there is a frame-skip, the number of frames played by the media stream graph will be less than the total frames and results in a |currentTime| less than the duration. The more frames are skipped, the smaller the |currentTime| is. It looks like frame-skip is unavoidable.

Hi Chris,
Are (1) and (2) should be identified as bugs and fixed? What is your opinion about (3)?
Flags: needinfo?(cpearce)
(In reply to JW Wang[:jwwang] from comment #4)
> There are some abnormal behaviors I observed from the logs:
> 1. In MediaDecoderStateMachine::AdvanceFrame(), |clock_time| is calculated
> from the last stream output time when the the media element is captured.
> |clock_time| won't advance if stream doesn't advance. Therefore I think
> state machine should be scheduled based on the stream output time instead of
> a real-time time when it is captured.

I think roc should answer this one.

 
> 2. In MediaDecoderStateMachine::DecodeVideo(), |mReader->DecodeVideoFrame|
> is wrapped in an ReentrantMonitorAutoExit monitor. It allows
> MediaDecoderStateMachine::AdvanceFrame() to kick in to consume
> |mReader->VideoQueue()| before SendStreamData() is called which writes video
> frames to the media stream. Therefore, some video frames are missed from the
> media stream.


Thank you for catching this. I think we need to change our code to fix this. The problem is that we have two consumers of MediaData objects, which race. So we need to ensure we define a deliberate order in which the consumers run.

We should move MediaQueues from the MediaDecoderReader into the MediaDecoderStateMachine. We then pass callbacks to the MediaDecoderReader which it calls when it has decoded a VideoData or AudioData. In these callbacks, we send the MediaData into the MSG (i.e. do what SendStreamData) does, and *then* we insert the sample into the MediaDecoderStateMachine's MediaData queues, where it can be picked up by AdvanceFrame().

Make sense? We will need to move some other code in MediaDecoderReader into the MediaDecoderStateMachine, like FindStartTime() and, DecodeToTarget().

I am planning on changing MediaDecoderStateMachine and MediaDecoderReader a bit more for bug 979104, so you should wait until after that before starting this.


> 3. In test_streams_element_capture.html, |vout.currentTime| depends on how
> many frames are played by the media stream graph. When there is a
> frame-skip, the number of frames played by the media stream graph will be
> less than the total frames and results in a |currentTime| less than the
> duration. The more frames are skipped, the smaller the |currentTime| is. It
> looks like frame-skip is unavoidable.

Yes, I think frame-skip is unavoidable.

You should be able to calculate the number of frame skips in JavaScript as (HTMLVideoElement.mozParsedFrames - HTMLVideoElement.mozPresentedFrames), does that help?

I suspect this may not be 100% reliable for all MediaDecoderReaders, so you may need to fix it.
Flags: needinfo?(cpearce) → needinfo?(roc)
(In reply to Chris Pearce (:cpearce) from comment #5)
> (In reply to JW Wang[:jwwang] from comment #4)
> > There are some abnormal behaviors I observed from the logs:
> > 1. In MediaDecoderStateMachine::AdvanceFrame(), |clock_time| is calculated
> > from the last stream output time when the the media element is captured.
> > |clock_time| won't advance if stream doesn't advance. Therefore I think
> > state machine should be scheduled based on the stream output time instead of
> > a real-time time when it is captured.
> 
> I think roc should answer this one.

I think JW is right.
Flags: needinfo?(roc)
Assignee

Comment 7

5 years ago
(In reply to JW Wang[:jwwang] from comment #4)
> There are some abnormal behaviors I observed from the logs:
> 1. In MediaDecoderStateMachine::AdvanceFrame(), |clock_time| is calculated
> from the last stream output time when the the media element is captured.
> |clock_time| won't advance if stream doesn't advance. Therefore I think
> state machine should be scheduled based on the stream output time instead of
> a real-time time when it is captured.

09:20:06.718643 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) AdvanceFrame, clock_time=132731,frameTime=133000,remainingTime=269
09:20:06.718803 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) ScheduleStateMachine, RunAgain, reason=AdvanceFrame 3
09:20:06.718944 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) AdvanceFrame, clock_time=132731,frameTime=133000,remainingTime=269
09:20:06.719079 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) ScheduleStateMachine, RunAgain, reason=AdvanceFrame 3
09:20:06.744524 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) AdvanceFrame, clock_time=132731,frameTime=133000,remainingTime=269
09:20:06.744737 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) ScheduleStateMachine, RunAgain, reason=AdvanceFrame 3
09:20:06.753352 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) UpdatePlaybackPositionInternal, start=0,time=166999,current=166999
09:20:06.753574 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) ScheduleStateMachine, RunAgain, reason=AdvanceFrame 3
09:20:06.753809 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) ScheduleStateMachine, timeout=40000, reason=AdvanceFrame 3
09:20:06.795433 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) AdvanceFrame, clock_time=166999,frameTime=167000,remainingTime=1
09:20:06.795592 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) ScheduleStateMachine, RunAgain, reason=AdvanceFrame 3
09:20:06.795752 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) AdvanceFrame, clock_time=166999,frameTime=167000,remainingTime=1
09:20:06.795891 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) ScheduleStateMachine, RunAgain, reason=AdvanceFrame 3
09:20:06.796033 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) AdvanceFrame, clock_time=166999,frameTime=167000,remainingTime=1
09:20:06.796784 UTC - 51272[43756980]: MediaDecoderStateMachine(42ff6db0) ScheduleStateMachine, RunAgain, reason=AdvanceFrame 3

This log show that when remainingTime=269(us), it will be round down to 0ms in MediaDecoderStateMachine::ScheduleStateMachine(), and AdvanceFrame() will be called immediately right next event cycle. The same thing will be repeated until clock time is advanced by the stream output time . It looks like a waste of CPU cycles.
Assignee

Comment 8

5 years ago
(In reply to JW Wang[:jwwang] from comment #4)

> 3. In test_streams_element_capture.html, |vout.currentTime| depends on how
> many frames are played by the media stream graph. When there is a
> frame-skip, the number of frames played by the media stream graph will be
> less than the total frames and results in a |currentTime| less than the
> duration. The more frames are skipped, the smaller the |currentTime| is. It
> looks like frame-skip is unavoidable.

09:59:55.157703 UTC - 51464[4379b500]: MediaDecoderStateMachine(42ff6db0) DecodeVideo, before DecodeVideoFrame, VideoQueueSize=1
09:59:55.178324 UTC - 51176[4375e700]: MediaDecoderStateMachine(42ff6db0) AdvanceFrame, pop frame, time=(667000,700000)
09:59:55.194853 UTC - 51464[4379b500]: MediaDecoderStateMachine(42ff6db0) DecodeVideo, after DecodeVideoFrame, VideoQueueSize=1
09:59:55.229319 UTC - 51176[4375e700]: MediaDecoderStateMachine(42ff6db0) AdvanceFrame, pop frame, time=(700000,733000)
09:59:55.231515 UTC - 51240[4379a300]: MediaDecoderStateMachine(42ff6db0) Skipping video decode to the next keyframe, GetClock=702110,GetMediaTime=699999,mVideoFrameEndTime=733000

If DecodeVideo() and AdvanceFrame() are called interleavedly, the video queue size will change between 1 and 2 (ex: 1 (VideoPreRolling) => 2 (pushed by mReader->DecodeVideoFrame) => 1 (popped by AdvanceFrame)). There will be not frame-skip.

However, depending on the thread scheduling, there could be 2 pops in-between and video queue size will drop to 0 and kick off frame-skip.

When |aKeyframeSkip| is true in WebMReader::DecodeVideoFrame, it will keep advancing to next packet for not being able to find a key frame until the end of stream as is observed from the file vp9.webm.

For GetClock=702110 < mVideoFrameEndTime=733000, we are still in the safe range and will not underrun the frame data. Maybe we should also take |clock time| and |mVideoFrameEndTime| into account when calculating frame-skipping.
Assignee

Comment 9

5 years ago
Btw, only the first frame of vp9.webm is a key frame. Therefore, once frame-skip is started, it will keep skipping till the end.
Comment hidden (Legacy TBPL/Treeherder Robot)
Assignee

Updated

5 years ago
Blocks: 982246
Comment hidden (Legacy TBPL/Treeherder Robot)
Assignee

Comment 12

5 years ago
cause:
In test_streams_element_capture.html, |vout.currentTime| depends on how many frames are played by the media stream graph. When there is a frame-skip, the number of frames played by the media stream graph will be less than the total frames and results in a |currentTime| less than the duration. The more frames are skipped, the smaller the |currentTime| is.

fix:
See comment 8. Don't skip video frame when |clock time| is less than |mVideoFrameEndTime| for we are still in the safe range without underruning video frames.
Attachment #8398295 - Flags: review?(cpearce)
Comment on attachment 8398295 [details] [diff] [review]
part1_fix_v1.patch

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

This is fine, but a frame skip could still happen if the test machine is very busy, right? So this patch will make the failure less likely, but not make it impossible.

Did you try checking if you could account for frames dropping by checking the difference between HTMLVideoElement.mozParsedFrames and HTMLVideoElement.mozPresentedFrames?
Attachment #8398295 - Flags: review?(cpearce) → review+
Assignee

Comment 14

5 years ago
(In reply to Chris Pearce (:cpearce) from comment #13)
> This is fine, but a frame skip could still happen if the test machine is
> very busy, right? So this patch will make the failure less likely, but not
> make it impossible.
In the case of stream capture, clock time is driven by the stream output time which is driven by how many frames sent to the stream from the state machine. Therefore the clock time can never go beyond the frame end time of our decoded frames. That means |GetClock() <= mVideoFrameEndTime| always holds in the case of stream capture. Is that right?
 
> Did you try checking if you could account for frames dropping by checking
> the difference between HTMLVideoElement.mozParsedFrames and
> HTMLVideoElement.mozPresentedFrames?
The logs without applying the patch:
TEST-INFO | unknown test url | v.mozParsedFrames=119, v.mozPresentedFrames=113
TEST-INFO | unknown test url | vout.mozParsedFrames=0, vout.mozPresentedFrames=0
There is no frame count info for a video element whose source is a stream. However, if we can convert the number of skipped frames (119-113=6) to seconds, we should be able to compensate for the currentTime as long as frame rate is available.
Assignee

Updated

5 years ago
Keywords: checkin-needed
Whiteboard: [leave open]
The following changeset is now in Firefox Nightly:

> 96c308b6ec18 Bug 980868 - Don't skip video frame when |clock time| is less than |mVideoFrameEndTime| for we are still in the safe range without underruning video frames. r=cpearce

Nightly Build Information:

        ID: 20140402030201
 Changeset: 4941a2ac0786109b08856738019b016a6c5a66a6
   Version: 31.0a1
      TBPL: https://tbpl.mozilla.org/?rev=4941a2ac0786
       URL: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central

Download Links:

>         Linux x86: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central/firefox-31.0a1.en-US.linux-i686.tar.bz2
>      Linux x86_64: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central/firefox-31.0a1.en-US.linux-x86_64.tar.bz2
> Linux x86_64 ASAN: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central/firefox-31.0a1.en-US.linux-x86_64-asan.tar.bz2
>               Mac: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central/firefox-31.0a1.en-US.mac.dmg
>             Win32: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central/firefox-31.0a1.en-US.win32.installer.exe
>             Win64: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central/firefox-31.0a1.en-US.win64-x86_64.installer.exe

Previous Nightly Build Information:

        ID: 20140401030203
 Changeset: 1417d180a1d8665b1a91b897d1cc4cc31e7980d4
   Version: 31.0a1
      TBPL: https://tbpl.mozilla.org/?rev=1417d180a1d8
       URL: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-01-03-02-03-mozilla-central
Comment hidden (Legacy TBPL/Treeherder Robot)
Assignee

Comment 20

4 years ago
Looks like it is fixed.
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Whiteboard: [leave open]
Target Milestone: --- → mozilla31
You need to log in before you can comment on or make changes to this bug.