1163223 - Clean up MDSM start time handling

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[Bobby Holley (:bholley)]

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.

Comment 1

[Bobby Holley (:bholley)]

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.

Comment 2

[Bobby Holley (:bholley)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=a6eabde9e938

Comment 3

[Bobby Holley (:bholley)]

Attachment: Part 1 - Introduce StartTimeRendezvous and route samples through it. v1

No sample adjusting is done yet - this just makes the data available.

Comment 4

[Bobby Holley (:bholley)]

Attachment: Part 2 - Use AwaitStartTime to handle metadata end time. v1

Comment 5

[Bobby Holley (:bholley)]

Attachment: Part 3 - Use AwaitStartTime to invoke MediaDecoderReader::SetStartTime. v1

Comment 6

[Bobby Holley (:bholley)]

Attachment: Part 4 - Be more explicit about firing metadata when we have duration and start time. v1

Comment 7

[Bobby Holley (:bholley)]

Attachment: Part 5 - Adjust incoming samples for start time. v1

Comment 8

[Bobby Holley (:bholley)]

Attachment: Part 6 - Remove MediaDecoderStateMachine::mStartTime. v1

Comment 9

[JW Wang [:jwwang] [:jw_wang]]

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/

Comment 10

[JW Wang [:jwwang] [:jw_wang]]

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?

Comment 11

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8617023 [details] [diff] [review]
Part 6 - Remove MediaDecoderStateMachine::mStartTime. v1

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

Wonderful!

Comment 12

[Bobby Holley (:bholley)]

(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

Comment 13

[Bobby Holley (:bholley)]

Attachment: 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

Comment 14

[JW Wang [:jwwang] [:jw_wang]]

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.

Comment 15

[Bobby Holley (:bholley)]

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?

Comment 16

[JW Wang [:jwwang] [:jw_wang]]

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 17

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

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.

Comment 18

[Jean-Yves Avenard [:jya]]

(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.

Comment 19

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

In general, we should assume that we will encounter files that aren't "proper", and we should try to handle them.

Comment 20

[Jean-Yves Avenard [:jya]]

(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.

Comment 21

[Bobby Holley (:bholley)]

(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.

Comment 22

[JW Wang [:jwwang] [:jw_wang]]

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.

Comment 23

[Bobby Holley (:bholley)]

(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.

Comment 24

[Bobby Holley (:bholley)]

Attachment: Part 4 - Be more explicit about when we notify metadata. v2

Comment 25

[Bobby Holley (:bholley)]

Attachment: Part 7 - Reuse rendezvous when coming out of dormant mode. v1

This fixes the test_dormant_playback issues.

Comment 26

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Spawned bug 1173650 to respond to ni in comment 18.

Comment 27

[Bobby Holley (:bholley)]

Attachment: 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.

Comment 28

[Bobby Holley (:bholley)]

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

Comment 29

[Bobby Holley (:bholley)]

Attachment: 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.

Comment 30

[JW Wang [:jwwang] [:jw_wang]]

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?

Comment 31

[Bobby Holley (:bholley)]

(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. :-)

Comment 32

[Bobby Holley (:bholley)]

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

[Pulsebot]

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

Comment 34

[Ryan VanderMeulen [:RyanVM]]

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

Comment 35

[Bobby Holley (:bholley)]

Attachment: 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.

Comment 36

[Bobby Holley (:bholley)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=832900b116fd

Comment 37

[Bobby Holley (:bholley)]

(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

[Pulsebot]

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

Comment 39

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

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.

Comment 40

[Pulsebot]

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

Comment 41

[Bobby Holley (:bholley)]

File sets disjoint.

Comment 42

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

(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.

Comment 43

[Bobby Holley (:bholley)]

(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!

Comment 44

[Ryan VanderMeulen [:RyanVM]]

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