Closed Bug 1219178 Opened 6 years ago Closed 6 years ago

Intermittent test_seek_out_of_range.html | Test timed out.

Categories

(Core :: Audio/Video: Playback, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla45
Tracking Status
firefox45 --- fixed

People

(Reporter: cbook, Assigned: esawin)

References

()

Details

(Keywords: intermittent-failure)

Attachments

(9 files, 1 obsolete file)

958 bytes, patch
jya
: review+
Details | Diff | Splinter Review
2.23 KB, patch
jya
: review+
Details | Diff | Splinter Review
2.96 KB, patch
jya
: review+
Details | Diff | Splinter Review
657 bytes, patch
jya
: review+
Details | Diff | Splinter Review
649 bytes, patch
jya
: review+
Details | Diff | Splinter Review
9.15 KB, patch
jya
: review+
Details | Diff | Splinter Review
1.72 KB, patch
jya
: review+
Details | Diff | Splinter Review
589 bytes, patch
jya
: review+
Details | Diff | Splinter Review
1.56 KB, patch
Details | Diff | Splinter Review
https://treeherder.mozilla.org/logviewer.html#?job_id=16375948&repo=mozilla-inbound 

00:18:48 INFO - 46731 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_seek_out_of_range.html | Test timed out.
INFO [finished gizmo.mp4-10] remaining= small-shot.mp3-2
small-shot.mp3 didn't finish playback. Not sure if this is related to recent changes to MP3TrackDemuxer in bug 1163667.
I've also seen this one dom/media/test/test_bug686942.html going intermittent recently (bug 896723 is still closed).

and each time, it was an mp3 file causing the timeout:
like here.

https://treeherder.mozilla.org/logviewer.html#?job_id=13128402&repo=try

most on linux.
Flags: needinfo?(esawin)
test_bug686942.html also involves seeking.
With this patch, I'm adding explicit out-of-range seeking unit tests and they pass fine.

This is likely a regression from bug 1163667, so I will look into reproducing it locally.
Component: Audio/Video → Audio/Video: Playback
Priority: -- → P5
I think I understand what's going on here. The file used for the test (small-shot.mp3) is less then a second long, contains only 12 frames while having TOC headers with 100 entries (100 percent-based offset mappings).

When seeking based on the TOC entries we end up in the middle of the frame payloads, which happen to contain a lot of valid frame header patterns (false positives). We pass the bogus frames to the decoder which aborts decoding.

Although it's less likely to happen with regular files, we currently don't do anything to prevent it.
So, I'm looking into clamping the TOC-based seeking to where we would expect the frame headers instead of trusting the TOC-derived offsets.

We could also further restrict our frame header validation to reduce the chance for false positive detection, but that's not completely avoidable according to the MPEG standard.

I'll also look into making the decoder interaction more robust to that kind of failures in the refactoring bug 1221991.
Assignee: nobody → esawin
Flags: needinfo?(esawin)
Exit early if scanning for the next frame would put us behind the target time frame.

This should help prevent overshooting.
Attachment #8688509 - Flags: review?(jyavenard)
We can only estimate the frame boundaries, so we need mechanics to recognize false-positive frame detection in frame payloads.

This adds a basic mechanism to verify consistency of frame meta data which should stay constant between frames of a stream.
Attachment #8688511 - Flags: review?(jyavenard)
Currently, FastSeek estimates the target offset based on average frame lengths or TOC and derives the frame index from that. This has the effect that even with perfect estimates, we would likely seek into frame payload offsets, instead of frame begins, which increases the likelihood of false-positive detection.

With this patch, we estimate the target frame index based on the same mechanics as before and then derive the target offset from that. This should put us closer to frame boundaries, depending on the quality of the estimates and is generally more consistent with the frame-based handling within the demuxer.
Attachment #8688518 - Flags: review?(jyavenard)
Let's further constrain frame validation by only accepting MP3 frames...
Attachment #8688520 - Flags: review?(jyavenard)
This patch prevents the new tests (to follow) from crashing on initialization (RAII could be a better pattern to solve this, but it's just a test helper class).
Attachment #8688521 - Flags: review?(jyavenard)
This patch adds the small MP3 test file from the failing intermittent test as a unit test case.

This makes yet another copy from the file (there are already two) but it's only 8kB and it's safer not to depend on other tests' resources.
Attachment #8688522 - Flags: review?(jyavenard)
This is an out-of-bounds seeking test, which should help to prevent regressions on similar issues.
Attachment #8680322 - Attachment is obsolete: true
Attachment #8688523 - Flags: review?(jyavenard)
We should never report a duration past the total duration, this is only used in tests.
Attachment #8688524 - Flags: review?(jyavenard)
Comment on attachment 8688509 [details] [diff] [review]
0001-Bug-1219178-1.1-Prevent-ScanUntil-from-overshooting-.patch

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

::: dom/media/MP3Demuxer.cpp
@@ +247,5 @@
>    }
>  
> +  if (Duration(mFrameIndex + 1) > aTime) {
> +    return SeekPosition();
> +  }

I'm not sure I follow the logic here.

So if duration is past where we want to seek to, you abort?

@@ +253,2 @@
>    MediaByteRange nextRange = FindNextFrame();
>    while (SkipNextFrame(nextRange) && Duration(mFrameIndex + 1) < aTime) {

what about swapping the two instead?
Attachment #8688509 - Flags: review?(jyavenard)
Comment on attachment 8688511 [details] [diff] [review]
0002-Bug-1219178-2.1-Add-frame-consistency-verification-t.patch

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

::: dom/media/MP3Demuxer.cpp
@@ +374,5 @@
>  }
>  
> +static bool
> +VerifyFrameConsistency(
> +    const FrameParser::Frame& aFrame1, const FrameParser::Frame& aFrame2) {

VerifyFrameConsistency(const FrameParser::Frame& aFrame1,
                       const FrameParser::Frame& aFrame2)
Attachment #8688511 - Flags: review?(jyavenard) → review+
Comment on attachment 8688518 [details] [diff] [review]
0003-Bug-1219178-3.1-Clamp-seeking-offsets-to-estimated-f.patch

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

::: dom/media/MP3Demuxer.cpp
@@ +530,4 @@
>  }
>  
>  int64_t
> +MP3TrackDemuxer::OffsetFromFrameIndex(int64_t aFrameIndex) const {

{ should be on the following line.. but I guess it's too late by now
Attachment #8688518 - Flags: review?(jyavenard) → review+
Attachment #8688520 - Flags: review?(jyavenard) → review+
Attachment #8688521 - Flags: review?(jyavenard) → review+
Attachment #8688522 - Flags: review?(jyavenard) → review+
Attachment #8688523 - Flags: review?(jyavenard) → review+
Attachment #8688524 - Flags: review?(jyavenard) → review+
(In reply to Jean-Yves Avenard [:jya] from comment #21)
> I'm not sure I follow the logic here.
> 
> So if duration is past where we want to seek to, you abort?

If the *following* frame is past the seek target, we don't scan forward because we would overshoot.
There is a hidden assumption that the current frame is timed earlier than the seek target, so the actual seek target may not correspond to an actual frame start (positioned between the current frame and the following frame).

> @@ +253,2 @@
> >    MediaByteRange nextRange = FindNextFrame();
> >    while (SkipNextFrame(nextRange) && Duration(mFrameIndex + 1) < aTime) {
> 
> what about swapping the two instead?

We shouldn't swap this because FindNextFrame() and {Skip|Get}NextFrame should always come in pairs. FindNextFrame moves the demuxing offset.

But you have a point, I should refactor ScanUntil or replace it with something more sensible since seeking mechanics have changed a bit (it's on my TODO list).
(In reply to Jean-Yves Avenard [:jya] from comment #23)
> { should be on the following line.. but I guess it's too late by now

It's never too late! I'm keeping it consistent within the file for now and will patch the style in one go (prepare for a review :).
Comment on attachment 8688509 [details] [diff] [review]
0001-Bug-1219178-1.1-Prevent-ScanUntil-from-overshooting-.patch

See comment 24 for description.
Attachment #8688509 - Flags: review?(jyavenard)
Attachment #8688509 - Flags: review?(jyavenard) → review+
Lots of failures, but nothing specific to media seeking: https://treeherder.mozilla.org/#/jobs?repo=try&revision=9e27b3a43e79
My build is broken with errors about classes with no SeekPosition or PrevFrame members. I compile with --disable-tests and it looks like these are #ifdef ENABLE_TESTS, but some code outside the ifdef calls them.
(In reply to Brad Jackson from comment #31)
> My build is broken with errors about classes with no SeekPosition or
> PrevFrame members. I compile with --disable-tests and it looks like these
> are #ifdef ENABLE_TESTS, but some code outside the ifdef calls them.

Sorry for the inconvenience, this patch will fix the issue. I will try to land it asap.
Thanks for reporting!
(In reply to Eugen Sawin [:esawin] from comment #32)
> Created attachment 8691950 [details] [diff] [review]
> 0009-Bug-1219178-9.1-Make-SeekPosition-available-with-tes.patch
> 
> (In reply to Brad Jackson from comment #31)
> > My build is broken with errors about classes with no SeekPosition or
> > PrevFrame members. I compile with --disable-tests and it looks like these
> > are #ifdef ENABLE_TESTS, but some code outside the ifdef calls them.
> 
> Sorry for the inconvenience, this patch will fix the issue. I will try to
> land it asap.
> Thanks for reporting!

landed on m-c as https://hg.mozilla.org/mozilla-central/rev/35916735b8af
I'm still seeing some on inbound...
https://treeherder.mozilla.org/logviewer.html#?job_id=18318133&repo=mozilla-inbound
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Depends on: 1256590
Depends on: 1258802
No time outs since 7th December. Closing.
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → FIXED
Depends on: 1236639
You need to log in before you can comment on or make changes to this bug.