1272267 - MediaFormatReader returns wrong sample after seeking.

Status: RESOLVED FIXED

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

Description

[Tzuhao Kuo [:kaku]]

Attachment: test.html

Following bug 1193124 comment 11.

The attachment is a simplified test case which load small-shot.mp3, play it to the end and then set its currentTime to 0. After receiving the 'seeked' event, the audio's currentTime should be 0 but 0.026612.

BTW, this bug cannot be re-produced at the released Firefox46 but could be re-produced at the mozilla-central. So, it might be a regression.

Comment 1

[Tzuhao Kuo [:kaku]]

Attachment: small-shot.mp3

Comment 2

[Jean-Yves Avenard [:jya]]

there is nothing we can do about this in MediaFormatReader as this depends on the decoder itself and what API they provide.

The mac decoder for example, will always drop the first MP3 frame. But as the decoding API provides no way to tell which frame is returned, we use the pts of the 2nd input frame (usually 0.026612).
It's the same with the DirectShow reader on Windows XP.

So while you seek at 0, and the first frame passed to the decoder is 0, the first frame coming out of the decoder will have the pts of the second input frame. 

It was working in 46 because it was buggy, and this is what caused some intermittent failures on mochitest.

The WMF will work properly and will have the first frame tag as 0.

AAC doesn't cause this problem with the Apple decoder, only mp3.

BTW, it would be the same with opus. When you seek to 0, the first 30ms are dropped, so the first frame returned will always have a time of 30ms at least.

So the behaviour is platform dependent, and we can never be certain in advance of what the MediaDataDecoder will do (not all MP3 frames see their first sample being dropped). I believe the frames dropped are those containing a VBR header.

Comment 3

[Jean-Yves Avenard [:jya]]

oh, and forgot to add:

The MediaFormatReader time is not always starting at 0.
It is up to the MediaDecoderReaderWrapper to adjust the start time.

So it's normal to see the first frame coming out of the MediaFormatReader to not be 0, but some time in the future.

Could it be that following the changes to the MediaDecoderReaderWrapper , the start time is no longer adjusted?

Before bug 1244639, the mp3 demuxer data wasn't shifted to start at 0 in order to get around the mac decoder issue, but this has been fixed.

JW, could it be due to something not working in MediaDecoderReaderWrapper?

Comment 4

[Jean-Yves Avenard [:jya]]

It could also be an issue in the MP3Demxuer where seeking to 0 doesn't always return the first frame.

Seeking is rather an approximate affair with mp3

Comment 5

[Tzuhao Kuo [:kaku]]

(In reply to Jean-Yves Avenard [:jya] from comment #3)
> oh, and forgot to add:
> 
> The MediaFormatReader time is not always starting at 0.
> It is up to the MediaDecoderReaderWrapper to adjust the start time.
> 
> So it's normal to see the first frame coming out of the MediaFormatReader to
> not be 0, but some time in the future.
> 
> Could it be that following the changes to the MediaDecoderReaderWrapper ,
> the start time is no longer adjusted?
> 
> Before bug 1244639, the mp3 demuxer data wasn't shifted to start at 0 in
> order to get around the mac decoder issue, but this has been fixed.
> 
> JW, could it be due to something not working in MediaDecoderReaderWrapper?

No, it is not. 
In the test case, the audio is first played to the end and the logs show that the MFR emits the following sample sequences:
1st:[26122, 52244], 2nd:[52244, 78366], 3rd:[78366, 104489],...... (<-- before adjusting start time)

And the MDSM receives the following sample sequences:
1st:[0, 26122]      2nd:[26122, 52244], 3rd:[52244, 78366],...... (<-- time has adjusted by the Wrapper)

The MediaDecoderReaderWrapper knows that the start time is 26122 and works well.

I think it is somewhat weird that the 1st sample [26122, 52244] was ever returned by the MFR but cannot be seeked/requested again later...

Comment 6

[Eugen Sawin [:esawin]]

(In reply to Jean-Yves Avenard [:jya] from comment #4)
> It could also be an issue in the MP3Demxuer where seeking to 0 doesn't
> always return the first frame.
> 
> Seeking is rather an approximate affair with mp3

Seeking to 0 is short-circuited to setting mFrameIndex=0 and mOffset=mFirstFrameOffset. This is the same path used as during Init(). So we shouldn't see any difference between initial playback and seeking to 0.

I can't reproduce the issue on Fennec or the latest Windows Nightly, currentTime shows correctly as 0 after seeking.

Comment 7

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

What are the timestamps (unadjusted) of first decoded frames after seeking if you call MediaDecoderReader::Seek(0), MediaDecoderReader::Seek(26122), and MediaDecoderReader::Seek(26121) respectively?

Comment 8

[Tzuhao Kuo [:kaku]]

Oh! Sorry, it's my fault. The wrong currentTime is only observable by first applying the patch of bug 1193124.  If you do not apply, the "wrong seeked time" is still there but not updated to the HTMLMediaElement.

esawin, could you please have another look on this?

Comment 9

[Tzuhao Kuo [:kaku]]

(In reply to JW Wang [:jwwang] from comment #7)
> What are the timestamps (unadjusted) of first decoded frames after seeking
> if you call MediaDecoderReader::Seek(0), MediaDecoderReader::Seek(26122),
> and MediaDecoderReader::Seek(26121) respectively?

First of all, we are not able to call MediaDecoderReader::Seek(0) because the media start time is 26122, so the earlest position we can seek to is 26122. Or, you are talking about MediaDecoderReaderWRAPPER::Seek(0) then here is the numbers:

MediaDecoderReaderWrapper::Seek(0)     -> MediaDecoderReader::Seek(26122)　-> 1st decoded frame: 52244
MediaDecoderReaderWrapper::Seek(26122) -> MediaDecoderReader::Seek(52244)　-> 1st decoded frame: 78366
MediaDecoderReaderWrapper::Seek(26121) -> MediaDecoderReader::Seek(52243)　-> 1st decoded frame: 78366

Comment 10

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

No, I mean to hack the code to see what results are returns for different seek target.

Comment 11

[Jean-Yves Avenard [:jya]]

Ok. So the issue I mentioned are what I wrote in my first post. 

The first audio frame returned *is* 0. It just happens that some decoder will drop it and only return the 2nd. 

So the start time is set to the time of the 2nd frame. Now when seeking to 0; you end up seeking at the time of the 2nd frame instead and as the decoder drops the first frame input, it returns here the 3rd audio frame. 

Conclusion, when seeking to 0; always pass the value 0 to the MediaFormatReader regardless of start time.

Comment 12

[Jean-Yves Avenard [:jya]]

Though, I remember a bug not long ago due to seeking not adjusting the time. So I don't know the best work around.

Comment 13

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

what happens if you seek to 0.000001s or 0.000002s? Will the decoder return 52244us?

Comment 14

[Tzuhao Kuo [:kaku]]

(In reply to JW Wang [:jwwang] from comment #10)
> No, I mean to hack the code to see what results are returns for different
> seek target.
Okay, here you are:
MediaDecoderReader::Seek(0)　    -> 1st decoded frame: 26122
MediaDecoderReader::Seek(26121)　-> 1st decoded frame: 26122
MediaDecoderReader::Seek(26122)　-> 1st decoded frame: 52244

I think you are right that the audio sample which starts from 26122 is still there but somehow cannot be requested agian.

Comment 15

[Jean-Yves Avenard [:jya]]

The first frame contains the seek target. So the demuxer returns the first frame but the decoder returns only the 2nd. 

Then you seek to the 2nd frame and the decoder returns the 3rd. 

the issue really here is that the demuxer think it's working with a start time of 0 but the decoder doesn't.

Comment 16

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

So this is a bug in the decoder?

Comment 17

[Jean-Yves Avenard [:jya]]

Maybe we should add a mechanism where the MFR records the time of the first frame demuxed and the time of the first frame decided. 

It can then only use the time of the first frame demuxed instead of the time of the first frame decoded. 

Seeking is mostly a demuxer job anyway.

Comment 18

[Jean-Yves Avenard [:jya]]

(In reply to JW Wang [:jwwang] from comment #16)
> So this is a bug in the decoder?

It's just the way the decoder works.

Comment 19

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

It is curious the test fails on Windows only. Does windows decoder behave differently?

Comment 20

[Jean-Yves Avenard [:jya]]

(In reply to JW Wang [:jwwang] from comment #19)
> It is curious the test fails on Windows only. Does windows decoder behave
> differently?

Windows decoder behave slightly differently than the Mac or ffmpeg one.

Mac set the decoded sample time to the time of the last input sample. This is why the first sample decoded has the time of the 2nd sample demuxed. 
Ffmpeg actually sets the time of the decoded sample to the time of the sample that was used to produce the decode.

Windows on the other hand, set the time of the first decoded sample to 0 and then use a counter with how many samples have been decoded so far and use this to calculate the time of each sample coming out.

I don't know about gonk or android audio decoder.

Comment 21

[Tzuhao Kuo [:kaku]]

Attachment: MozReview Request: Bug 1272267 - adjust the seek target in the MediaFormatReader; r=jya

Review commit: https://reviewboard.mozilla.org/r/52774/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/52774/

Comment 22

[Blake Wu [:bwu][:blakewu]]

Have more fun in seek!

Comment 23

[Tzuhao Kuo [:kaku]]

Comment on attachment 8752754 [details]
MozReview Request: Bug 1272267 - adjust the seek target in the MediaFormatReader; r=jya

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52774/diff/1-2/

Comment 24

[Tzuhao Kuo [:kaku]]

Try looks good: https://treeherder.mozilla.org/#/jobs?repo=try&revision=f3936a7f7392

Comment 25

[Tzuhao Kuo [:kaku]]

Comment on attachment 8752754 [details]
MozReview Request: Bug 1272267 - adjust the seek target in the MediaFormatReader; r=jya

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52774/diff/2-3/

Comment 26

[Jean-Yves Avenard [:jya]]

Comment on attachment 8752754 [details]
MozReview Request: Bug 1272267 - adjust the seek target in the MediaFormatReader; r=jya

https://reviewboard.mozilla.org/r/52774/#review50212

::: dom/media/MediaFormatReader.h:407
(Diff revision 3)
>      Maybe<media::TimeUnit> mLastTimeRangesEnd;
>      RefPtr<SharedTrackInfo> mInfo;
> +
> +    Maybe<media::TimeUnit> mFirstDemuxedSampleTime;
> +
> +    void SetFirstDemuxedSampleTime() {

I'd prefer if you made this function take the time as argument.

It doesn't need to know about mQueuedSamples.

Use mFirstDemuxedSampleTime = Some(...)

Perform all the logic inside MediaFormatReader::HandleDemuxedSamples

::: dom/media/MediaFormatReader.h:521
(Diff revision 3)
>    // Set the demuxed-only flag.
>    Atomic<bool> mDemuxOnly;
>  
>    // Seeking objects.
> +  void SetSeekTarget(SeekTarget&& aTarget);
> +  media::TimeUnit GetMinFristDemuxedTime();

s/Frist/First

But DemuxStartTime() seems more appropriate to me, so it's similar to the StartTime() function

::: dom/media/MediaFormatReader.cpp:926
(Diff revision 3)
>  
>    if (!EnsureDecoderInitialized(aTrack)) {
>      return;
>    }
>  
> +  if (!ForceZeroStartTime()) {

Please move the logic here,

so if (!ForceZeroStartTime && decoder.mFirstDemuxedSampleTime.isNothing) { .... }

::: dom/media/MediaFormatReader.cpp:1535
(Diff revision 3)
> +  mOriginalSeekTarget = Some(aTarget);
> +  mPendingSeekTime = Some(aTarget.GetTime());
> +}
> +
> +TimeUnit
> +MediaFormatReader::GetMinFristDemuxedTime()

The coding style expressly say that a function name GetXXXX() means that it can fail.

This function can never fail. So it shouldn't be called GetMinFirstDemuxedTime.

As mentioned earlier, please use DemuxStartTime()

::: dom/media/MediaFormatReader.cpp:1542
(Diff revision 3)
> +  MOZ_ASSERT(OnTaskQueue());
> +
> +  TimeUnit minTime = TimeUnit::FromMicroseconds(INT64_MAX);
> +
> +  if (HasAudio()) {
> +    auto& audioDecoder = GetDecoderData(TrackType::kAudioTrack);

Just use mAudio here, no need to call GetDecoderData

::: dom/media/MediaFormatReader.cpp:1544
(Diff revision 3)
> +  TimeUnit minTime = TimeUnit::FromMicroseconds(INT64_MAX);
> +
> +  if (HasAudio()) {
> +    auto& audioDecoder = GetDecoderData(TrackType::kAudioTrack);
> +    MOZ_ASSERT(audioDecoder.mFirstDemuxedSampleTime.isSome());
> +    if (audioDecoder.mFirstDemuxedSampleTime.ref() < minTime) {

You should remove all the logic testing that mFirstDemuxedSampleTime is set.

You can assert that (!HasAudio() || mAudio.mFirstDemuxedSampleTime.isSome()) && (!HasVideo() || mVideo.mFirstDemuxedSampleTime.isSome())

It would be an error for MDSM to call seek prior first frame decoding having started..

Please also assert that it's not called if ForceZeroStartTime is true.

::: dom/media/MediaFormatReader.cpp:1553
(Diff revision 3)
> +
> +  if (HasVideo()) {
> +    auto& videoDecoder = GetDecoderData(TrackType::kVideoTrack);
> +    MOZ_ASSERT(videoDecoder.mFirstDemuxedSampleTime.isSome());
> +    if (videoDecoder.mFirstDemuxedSampleTime.ref() < minTime) {
> +      minTime = videoDecoder.mFirstDemuxedSampleTime.ref();

please use std::min.

std::min(HasAudio() ? mAudio.mFirstDemuxedSampleTime.ref() : TimeUnit::FromInfinity(), HasVideo() ? mVideo.mFirstDemuxedSampleTime.ref() : TimeUnit::FromInfinity()) will replace everything you have here with a single line

::: dom/media/MediaFormatReader.cpp:1558
(Diff revision 3)
> +      minTime = videoDecoder.mFirstDemuxedSampleTime.ref();
> +    }
> +  }
> +
> +  // Should at least has audio or video.
> +  MOZ_ASSERT(minTime != TimeUnit::FromMicroseconds(INT64_MAX));

You can remove this if you have the assert at the start

Comment 27

[Tzuhao Kuo [:kaku]]

https://reviewboard.mozilla.org/r/52774/#review50212

> I'd prefer if you made this function take the time as argument.
> 
> It doesn't need to know about mQueuedSamples.
> 
> Use mFirstDemuxedSampleTime = Some(...)
> 
> Perform all the logic inside MediaFormatReader::HandleDemuxedSamples

If we don't hind the setting logics in this function, then I think we can just set the mFirstDemuxedSampleTime in the MediaFormatReader::HandleDemuxedSamples(); we don't need this function anymore.

> Please move the logic here,
> 
> so if (!ForceZeroStartTime && decoder.mFirstDemuxedSampleTime.isNothing) { .... }

So, we set the mFirstDemuxedSampleTime here without using a setter function.

> The coding style expressly say that a function name GetXXXX() means that it can fail.
> 
> This function can never fail. So it shouldn't be called GetMinFirstDemuxedTime.
> 
> As mentioned earlier, please use DemuxStartTime()

Got it, thanks.

> You should remove all the logic testing that mFirstDemuxedSampleTime is set.
> 
> You can assert that (!HasAudio() || mAudio.mFirstDemuxedSampleTime.isSome()) && (!HasVideo() || mVideo.mFirstDemuxedSampleTime.isSome())
> 
> It would be an error for MDSM to call seek prior first frame decoding having started..
> 
> Please also assert that it's not called if ForceZeroStartTime is true.

MDSM pass seek operation into reader only if the first sample has been decoded. The check is here: https://dxr.mozilla.org/mozilla-central/source/dom/media/MediaDecoderStateMachine.cpp#1464

And, yes, I should make sure that this is not called if the ForceZeroStartTime() is true.

Comment 28

[Tzuhao Kuo [:kaku]]

Comment on attachment 8752754 [details]
MozReview Request: Bug 1272267 - adjust the seek target in the MediaFormatReader; r=jya

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52774/diff/3-4/

Comment 29

[Jean-Yves Avenard [:jya]]

Comment on attachment 8752754 [details]
MozReview Request: Bug 1272267 - adjust the seek target in the MediaFormatReader; r=jya

https://reviewboard.mozilla.org/r/52774/#review50230

::: dom/media/MediaFormatReader.cpp:1519
(Diff revision 4)
>  
>    if (mShutdown) {
>      return SeekPromise::CreateAndReject(NS_ERROR_FAILURE, __func__);
>    }
>  
> -  mOriginalSeekTarget = aTarget;
> +  SetSeekTarget(Move(aTarget));

Don't bother with rvalue here and move semantic. it doesn't serve any purpose nor does it help clarity.

::: dom/media/MediaFormatReader.cpp:1529
(Diff revision 4)
>  
>    return p;
>  }
>  
>  void
> +MediaFormatReader::SetSeekTarget(SeekTarget&& aTarget)

take const SeekTarget& as parameter please

::: dom/media/MediaFormatReader.cpp:1536
(Diff revision 4)
> +  MOZ_ASSERT(OnTaskQueue());
> +
> +  // Transform the seek target time to the demuxer timeline.
> +  if (!ForceZeroStartTime()) {
> +    aTarget.SetTime(aTarget.GetTime() - TimeUnit::FromMicroseconds(StartTime())
> +                    + DemuxeStartTime());

Either DemuxerStartTime() or DemuxStartTime()

::: dom/media/MediaFormatReader.cpp:1551
(Diff revision 4)
> +  MOZ_ASSERT(OnTaskQueue());
> +  MOZ_ASSERT(!ForceZeroStartTime());
> +  MOZ_ASSERT((!HasAudio() || mAudio.mFirstDemuxedSampleTime.isSome()) &&
> +             (!HasVideo() || mVideo.mFirstDemuxedSampleTime.isSome()));
> +
> +  return std::min(HasAudio() ? mAudio.mFirstDemuxedSampleTime.ref() :

the coding style states that it should be:
test
? a
: b

with ? underneath the test and aligned.

https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Coding_Style#Operators

Comment 30

[Tzuhao Kuo [:kaku]]

Comment on attachment 8752754 [details]
MozReview Request: Bug 1272267 - adjust the seek target in the MediaFormatReader; r=jya

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52774/diff/4-5/

Comment 31

[Tzuhao Kuo [:kaku]]

Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=6885e2d4ee3f

Comment 32

[Tzuhao Kuo [:kaku]]

Try looks good. Thanks for the review!

Comment 33

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/fb8ee867138d

Comment 34

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

https://hg.mozilla.org/mozilla-central/rev/fb8ee867138d