Clean up MDSM start time handling

RESOLVED FIXED in Firefox 41

Status

()

Core
Audio/Video
RESOLVED FIXED
3 years ago
2 years ago

People

(Reporter: Bobby Holley (parental leave - send mail for anything urgent), Assigned: Bobby Holley (parental leave - send mail for anything urgent))

Tracking

unspecified
mozilla41
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox41 fixed)

Details

Attachments

(10 attachments, 2 obsolete attachments)

16.21 KB, patch
jwwang
: review+
Details | Diff | Splinter Review
4.71 KB, patch
jwwang
: review+
Details | Diff | Splinter Review
4.68 KB, patch
jwwang
: review+
Details | Diff | Splinter Review
2.36 KB, patch
jwwang
: review+
Details | Diff | Splinter Review
28.15 KB, patch
jwwang
: review+
Details | Diff | Splinter Review
6.63 KB, patch
jwwang
: review+
Details | Diff | Splinter Review
2.35 KB, patch
jwwang
: review+
Details | Diff | Splinter Review
5.42 KB, patch
jwwang
: review+
Details | Diff | Splinter Review
2.13 KB, patch
cpearce
: review+
Details | Diff | Splinter Review
1.43 KB, patch
jwwang
: review+
Details | Diff | Splinter Review
This whole setup is extremely complicated and error-prone, and exists on the wrong level of abstraction - samples from the reader should simple be adjusted for a start-time of 0.

This is a first step on the road to bug 1160695.
So dealing with this in the demuxers turns out to be pretty yucky also. The annoying part is that we can't compute start time (and thus return samples) until the first sample of each channel has been decoded, and so we have to delay the sample-returning promises with special-case logic.

So instead, I came up with a clever way to handling this further up the pipeline by extending the MediaPromise architecture. I'll post patches soon.
Summary: Stop exposing the concept of start time to the MDSM and handle it in MediaDecoderReader → Clean up MDSM start time handling
Depends on: 1168004
Depends on: 1168008
https://treeherder.mozilla.org/#/jobs?repo=try&revision=a6eabde9e938
Depends on: 1168040
No longer blocks: 1160695
Depends on: 1160695
Blocks: 1172264
Created attachment 8617018 [details] [diff] [review]
Part 1 - Introduce StartTimeRendezvous and route samples through it. v1

No sample adjusting is done yet - this just makes the data available.
Attachment #8617018 - Flags: review?(jwwang)
Created attachment 8617019 [details] [diff] [review]
Part 2 - Use AwaitStartTime to handle metadata end time. v1
Attachment #8617019 - Flags: review?(jwwang)
Created attachment 8617020 [details] [diff] [review]
Part 3 - Use AwaitStartTime to invoke MediaDecoderReader::SetStartTime. v1
Attachment #8617020 - Flags: review?(jwwang)
Created attachment 8617021 [details] [diff] [review]
Part 4 - Be more explicit about firing metadata when we have duration and start time. v1
Attachment #8617021 - Flags: review?(jwwang)
Created attachment 8617022 [details] [diff] [review]
Part 5 - Adjust incoming samples for start time. v1
Attachment #8617022 - Flags: review?(jwwang)
Created attachment 8617023 [details] [diff] [review]
Part 6 - Remove MediaDecoderStateMachine::mStartTime. v1
Attachment #8617023 - Flags: review?(jwwang)
Comment on attachment 8617018 [details] [diff] [review]
Part 1 - Introduce StartTimeRendezvous and route samples through it. v1

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

::: dom/media/MediaDecoderStateMachine.h
@@ +931,5 @@
> +    void SetChannelStartTime(int64_t aStartTime)
> +    {
> +      MOZ_LOG(gMediaDecoderLog, LogLevel::Debug,
> +              ("StartTimeRendezvous=%p Setting %s start time to %lld",
> +               this, SampleType::sTypeName, mAudioStartTime.ref()));

s/mAudioStartTime.ref()/aStartTime/
Attachment #8617018 - Flags: review?(jwwang) → review+
Attachment #8617019 - Flags: review?(jwwang) → review+
Attachment #8617020 - Flags: review?(jwwang) → review+
Comment on attachment 8617021 [details] [diff] [review]
Part 4 - Be more explicit about firing metadata when we have duration and start time. v1

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

::: dom/media/MediaDecoderStateMachine.cpp
@@ +1487,4 @@
>    if (mStartTime == -1) {
>      SetStartTime(0);
>    }
> +  mDurationSet = true;

Why moving down this assignment?
Attachment #8617021 - Flags: review?(jwwang) → review+
Attachment #8617022 - Flags: review?(jwwang) → review+
Comment on attachment 8617023 [details] [diff] [review]
Part 6 - Remove MediaDecoderStateMachine::mStartTime. v1

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

Wonderful!
Attachment #8617023 - Flags: review?(jwwang) → review+
(In reply to JW Wang [:jwwang] from comment #9)
> s/mAudioStartTime.ref()/aStartTime/

Good catch.

(In reply to JW Wang [:jwwang] from comment #10)
> >    if (mStartTime == -1) {
> >      SetStartTime(0);
> >    }
> > +  mDurationSet = true;
> 
> Why moving down this assignment?

Because SetStartTime does different things in the mDurationSet case. Anyway, it's more or less moot because SetStartTime goes away in the next patch.

Thanks for the reviews!

https://treeherder.mozilla.org/#/jobs?repo=try&revision=82693e93fa09
Created attachment 8617726 [details] [diff] [review]
Part 1 Adendum - Force Zero start time in the encrypted case. v1

This causes orange in dom/media/test/test_eme_non_mse_fails.html
Attachment #8617726 - Flags: review?(jwwang)
Comment on attachment 8617726 [details] [diff] [review]
Part 1 Adendum - Force Zero start time in the encrypted case. v1

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

::: dom/media/MediaDecoderStateMachine.cpp
@@ +2195,5 @@
> +  // We force zero start time in a couple of situations:
> +  // * If the reader requests it (i.e. MSE).
> +  // * If the stream is real time.
> +  // * If the media is encrypted, since we can't get the first frame in finite
> +  //   time.

I am sketical about the encrypted case since the 1st frame might end up being non-zero.

Chris should have more insight about it.
Attachment #8617726 - Flags: review?(jwwang) → review?(cpearce)
Honestly we could also just not support start time sniffing for mp4 - According to jya other browsers don't handle it either. Can you confirm, Jean-Yves?
Flags: needinfo?(jyavenard)
Btw, can you detail the problem in dom/media/test/test_eme_non_mse_fails.html? MDSM will go to DECODER_STATE_WAIT_FOR_CDM if waiting for CDM resource and then switch to DECODER_STATE_DECODING_FIRSTFRAME when CDM is available. I don't see how StartTimeRendezvous can fail on this.
Comment on attachment 8617726 [details] [diff] [review]
Part 1 Adendum - Force Zero start time in the encrypted case. v1

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

::: dom/media/MediaDecoderStateMachine.cpp
@@ +2197,5 @@
> +  // * If the stream is real time.
> +  // * If the media is encrypted, since we can't get the first frame in finite
> +  //   time.
> +  bool forceZeroStartTime = mReader->ForceZeroStartTime() ||
> +                            IsRealTime() || mReader->IsWaitingOnCDMResource();

JW is correct I believe, EME first frames can end up with a non-zero start time.

Why can't the StartTimeRendezvous wait until the CDMProxy is made available to the Reader and we're able to produce frames?

We can't get the start time in the current architecture until we have a CDMProxy and decrypted and decoded samples, but we could hack something in to get the start time from the undecrypted samples before they are decrypted by the CDM. I'd prefer to not add more hacks if we can avoid it.
(In reply to Bobby Holley (:bholley) from comment #13)
> Created attachment 8617726 [details] [diff] [review]
> Part 1 Adendum - Force Zero start time in the encrypted case. v1
> 
> This causes orange in dom/media/test/test_eme_non_mse_fails.html

The bibbop video originally had an edts that were manually removed. This is what caused those videos to not have a proper start time. Gerald should redo them and not remove the required atoms. Then we need bug 1168040 applied.
Flags: needinfo?(jyavenard) → needinfo?(gsquelart)
In general, we should assume that we will encounter files that aren't "proper", and we should try to handle them.
(In reply to Bobby Holley (:bholley) from comment #15)
> Honestly we could also just not support start time sniffing for mp4 -
> According to jya other browsers don't handle it either. Can you confirm,
> Jean-Yves?

We don't need to decrypt the frame to get the start time.

It's unfortunate that we rely on "decoding" the first frame in order to get the timing, when all we need is demuxing it (and that doesn't need the CDM to be ready).

In regards to start time, the issue is only in regards to how the state machine handles it right? not what we report to JS (like buffered range)

In regards to what we report to JS (via XX.buffered), the Youtube tests until 3 days ago had videos that had a start time of 0.089s (caused all the youtube video tests to fail)
The webref tests all have MP4 that have a video track starting at 0.06s.

How we should handle this is puzzling. No browser do it the same way.
Our existing MSE "shift" the entire track timeline left or right to make it start exactly at 0.

In the new MSE implementation I decided not to do it as it's too complicated.
(In reply to JW Wang [:jwwang] from comment #16)
> Btw, can you detail the problem in
> dom/media/test/test_eme_non_mse_fails.html? MDSM will go to
> DECODER_STATE_WAIT_FOR_CDM if waiting for CDM resource and then switch to
> DECODER_STATE_DECODING_FIRSTFRAME when CDM is available. I don't see how
> StartTimeRendezvous can fail on this.

The problem is that we don't fire metadataloaded until we have a start time. So this means that, if the caller is waiting on metadataloaded to attach the CDM, we'll hang forever.

The other approach here is to fire metadataloaded without knowing the start time. I suppose I'll do that.
Attachment #8617726 - Attachment is obsolete: true
Attachment #8617726 - Flags: review?(cpearce)
We don't need the start time to fire metadataloaded. That's why we have DECODER_STATE_DECODING_METADATA during which we decode metadata and DECODER_STATE_DECODING_FIRSTFRAME where we decode 1st frames to get the start time.
(In reply to JW Wang [:jwwang] from comment #22)
> We don't need the start time to fire metadataloaded. That's why we have
> DECODER_STATE_DECODING_METADATA during which we decode metadata and
> DECODER_STATE_DECODING_FIRSTFRAME where we decode 1st frames to get the
> start time.

Well, Part 4 changes that, but I think that's probably the wrong thing. I'll attach an updated version.
Created attachment 8620733 [details] [diff] [review]
Part 4 - Be more explicit about when we notify metadata. v2
Attachment #8617021 - Attachment is obsolete: true
Attachment #8620733 - Flags: review?(jwwang)
Created attachment 8620735 [details] [diff] [review]
Part 7 - Reuse rendezvous when coming out of dormant mode. v1

This fixes the test_dormant_playback issues.
Attachment #8620735 - Flags: review?(jwwang)
Attachment #8620733 - Flags: review?(jwwang) → review+
Attachment #8620735 - Flags: review?(jwwang) → review+
See Also: → bug 1173650
Spawned bug 1173650 to respond to ni in comment 18.
Flags: needinfo?(gsquelart)
Depends on: 1174039
Created attachment 8621387 [details] [diff] [review]
Part 8 - Move bailout case in GetBuffered into the readers. v1

The problem here is that, because we run mReader->SetStartTime() as a promise
callback, MDSM::HasStartTime() may be true while the reader hasn't been
notified yet. This is obviously broken, but no more broken than the fact that
GetBuffered operates synchronously (and is basically the last piece of
machinery left doing so). Fixing that is next on my list, but let's just hack
around this for now to get this stack landed.
Attachment #8621387 - Flags: review?(jwwang)
Repeated From IRC:

Because of [1], if all the data is downloaded, readystate isn't a reliable indicator of state machine progress. So using loadeddata, canplay, and canplaythrough don't help here. Chris, can we just do timeupdate to move on?


[1] https://dxr.mozilla.org/mozilla-central/source/dom/html/HTMLMediaElement.cpp?from=HTMLMediaElement.cpp&case=true#3564
Flags: needinfo?(cpearce)
Created attachment 8621390 [details] [diff] [review]
Part 9 - Switch test_buffered to use timeupdate rather than loadedmetadata. v1

The problem is that we can't compute buffered until we know the start time, but don't
necessarily know the start time by the time we fire loadedmetadata (we just know the
duration). Chris determined that there was nothing in the spec that requires any
particular behavior from .buffered after loadedmetadata, so this should be fine.
Attachment #8621390 - Flags: review?(cpearce)
Attachment #8621390 - Flags: review?(cpearce) → review+
Flags: needinfo?(cpearce)
Comment on attachment 8621387 [details] [diff] [review]
Part 8 - Move bailout case in GetBuffered into the readers. v1

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

::: dom/media/MediaFormatReader.cpp
@@ +1284,5 @@
>    }
>    int64_t startTime;
>    {
>      ReentrantMonitorAutoEnter mon(mDecoder->GetReentrantMonitor());
> +    NS_ENSURE_TRUE(mStartTime >= 0, media::TimeIntervals());

Do we treat this an abnormal case and have to raise a warning?
Attachment #8621387 - Flags: review?(jwwang) → review+
(In reply to JW Wang [:jwwang] from comment #30)
> Do we treat this an abnormal case and have to raise a warning?

I think it's abnormal enough that this warning might be quite useful when debugging an intermittent test from the logs. :-)
Blocks: 1174120
https://treeherder.mozilla.org/#/jobs?repo=try&revision=2ac5d9dbcb20

This try push is green except for a null-deref in test_media_selection.html, which I've fixed by adding a bail-out case.

I also had to rebase this a little bit on top of bug 1171311, which just landed on inbound. The changes are straightforward, and I've re-run some local tests.

Comment 33

3 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/074ba7f9496d
https://hg.mozilla.org/integration/mozilla-inbound/rev/c00a89bad6c8
https://hg.mozilla.org/integration/mozilla-inbound/rev/2d95a87fe0ce
https://hg.mozilla.org/integration/mozilla-inbound/rev/3bd4024e0a70
https://hg.mozilla.org/integration/mozilla-inbound/rev/cd763e4327f3
https://hg.mozilla.org/integration/mozilla-inbound/rev/a8f7e2ad9543
https://hg.mozilla.org/integration/mozilla-inbound/rev/a8271be8264e
https://hg.mozilla.org/integration/mozilla-inbound/rev/4cbdd2f615c2
https://hg.mozilla.org/integration/mozilla-inbound/rev/f2c4e81d7abc
https://hg.mozilla.org/integration/mozilla-inbound/rev/8985172298c0
Backed out for OSX asserts/crashes/leaks.
https://treeherder.mozilla.org/logviewer.html#?job_id=10729948&repo=mozilla-inbound
https://treeherder.mozilla.org/logviewer.html#?job_id=10729571&repo=mozilla-inbound

https://hg.mozilla.org/integration/mozilla-inbound/rev/db848e0a090d
Depends on: 1174939
Created attachment 8623148 [details] [diff] [review]
Part 1 Adendum - Make sure StartTimeRendedzvous never waits for start time after it's been destroyed. v1

The leaks in the log appear as 3 MediaPromises and 2 ThenValues. My theory is
that we end up in ProcessFirstSample at some point after Destroy() has been
called. In the current code, this could cause us to re-Ensure the
StartTimePromise, holding it, the returned promise, and the completion promise
alive, along with the two ThenValues.

This should hopefully fix the issue.
Attachment #8623148 - Flags: review?(jwwang)
https://treeherder.mozilla.org/#/jobs?repo=try&revision=832900b116fd
(In reply to Bobby Holley (:bholley) from comment #36)
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=832900b116fd

Looks green, and inbound is open. The leak fix is small enough that I'm comfortable rolling it into part 1 and pushing it, but leaving jww flagged to double-check it.

Comment 38

3 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/7b6804398fc3
https://hg.mozilla.org/integration/mozilla-inbound/rev/aea6b8d15318
https://hg.mozilla.org/integration/mozilla-inbound/rev/5193508738f8
https://hg.mozilla.org/integration/mozilla-inbound/rev/20e25e93ed5f
https://hg.mozilla.org/integration/mozilla-inbound/rev/9e7651567cad
https://hg.mozilla.org/integration/mozilla-inbound/rev/b2e10f194455
https://hg.mozilla.org/integration/mozilla-inbound/rev/a7ee6eb45f62
https://hg.mozilla.org/integration/mozilla-inbound/rev/c1b33c43f0c5
I had to back these out in https://hg.mozilla.org/integration/mozilla-inbound/rev/3fe20c75349b so I could cleanly get bug 1147668 backed out for bustage. Feel free to reland this whenever. Sorry for the trouble.
Flags: needinfo?(bobbyholley)

Comment 40

3 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/8baf29b879aa
https://hg.mozilla.org/integration/mozilla-inbound/rev/84ab38ab2fac
https://hg.mozilla.org/integration/mozilla-inbound/rev/2b13e8f82843
https://hg.mozilla.org/integration/mozilla-inbound/rev/7a5c93857d68
https://hg.mozilla.org/integration/mozilla-inbound/rev/81d780ecb4b6
https://hg.mozilla.org/integration/mozilla-inbound/rev/33b15da770ae
https://hg.mozilla.org/integration/mozilla-inbound/rev/534be03edda3
https://hg.mozilla.org/integration/mozilla-inbound/rev/0e80ea297120
File sets disjoint.
Flags: needinfo?(bobbyholley)
(In reply to Bobby Holley (:bholley) from comment #41)
> File sets disjoint.

Yeah, sorry about that. Must've been something screwy locally that got fixed when I cleaned up my local repo after hitting the failures. I panicked and jumped at the fact that both bugs touched media stuff.
(In reply to Wes Kocher (:KWierso) from comment #42)
> (In reply to Bobby Holley (:bholley) from comment #41)
> > File sets disjoint.
> 
> Yeah, sorry about that. Must've been something screwy locally that got fixed
> when I cleaned up my local repo after hitting the failures. I panicked and
> jumped at the fact that both bugs touched media stuff.

No worries - thanks for all your tireless sheriffing efforts!
Attachment #8623148 - Flags: review?(jwwang) → review+
https://hg.mozilla.org/mozilla-central/rev/7b6804398fc3
https://hg.mozilla.org/mozilla-central/rev/aea6b8d15318
https://hg.mozilla.org/mozilla-central/rev/5193508738f8
https://hg.mozilla.org/mozilla-central/rev/20e25e93ed5f
https://hg.mozilla.org/mozilla-central/rev/9e7651567cad
https://hg.mozilla.org/mozilla-central/rev/b2e10f194455
https://hg.mozilla.org/mozilla-central/rev/a7ee6eb45f62
https://hg.mozilla.org/mozilla-central/rev/c1b33c43f0c5
https://hg.mozilla.org/mozilla-central/rev/8baf29b879aa
https://hg.mozilla.org/mozilla-central/rev/84ab38ab2fac
https://hg.mozilla.org/mozilla-central/rev/2b13e8f82843
https://hg.mozilla.org/mozilla-central/rev/7a5c93857d68
https://hg.mozilla.org/mozilla-central/rev/81d780ecb4b6
https://hg.mozilla.org/mozilla-central/rev/33b15da770ae
https://hg.mozilla.org/mozilla-central/rev/534be03edda3
https://hg.mozilla.org/mozilla-central/rev/0e80ea297120
Status: NEW → RESOLVED
Last Resolved: 3 years ago
status-firefox41: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla41

Updated

2 years ago
Depends on: 1188643

Updated

2 years ago
Depends on: 1253928
You need to log in before you can comment on or make changes to this bug.