1140995 - mochitest test_bug1113600.html and test_bug879717.html timeout.

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[Benjamin Chen [:bechen]]

Now, I'm trying to enable MediaCodec on emulator-kk build.
The mochitest testcase test_bug1113600 usually timeout on my emulator-kk build.

Comment 1

[Benjamin Chen [:bechen]]

The root cause is that because there exists deviation in MicrosecondsToStreamTimeRoundDown() function, so
the GetClock() function doesn't go forward enough. Cause the MediaDecoderStateMachine::AdvanceFrame() function can't render or drop the last video frame, keeps in DECODER_STATE_COMPLETED state infinitely.

Comment 2

[Benjamin Chen [:bechen]]

Attachment: bug-1140995-timeout-part1.v01.patch

part 1: fix the timeout by adding deviation clocktime at the end of stream.

The timeout case usually happened at video only captured stream. The deviation between the MicrosecondsToStreamTimeRoundDown() and GetClock() make the MDSM falls into infinite loop (DECODER_STATE_COMPLETED and VideoQueue is always not empty)

Comment 3

[Benjamin Chen [:bechen]]

Attachment: bug-1140995-timeout-part2.v01.patch

part 2: fix the timeout by check the audio/video sample's timestamp.

This timeout usually happened at b2g-emulator, because the OMXCodec/MediaCodec decode a audio sample with a back-forward timestamp cause the timeout.

STR: when running the testcase test_bug879717.html, the gizmo.mp4 "sometimes" timeout because there is some audio samples still in the AudioQueue.
The audio clock doesn't go forward enough to finish the testcase. That is because there is a invalid audio sample in the AudioQueue.
For example: the timestamp in AudioQueue are:
1,2,3,4, ... 7,8,9,10,5 (the last audio sample's ts is 5)
Then looks these two functions
https://dxr.mozilla.org/mozilla-central/source/dom/media/MediaQueue.h#127
https://dxr.mozilla.org/mozilla-central/source/dom/media/MediaDecoderStateMachine.cpp#519

GetElementsAfter()'s implementation start the search from the end of the queue.
But the while loop in MediaDecoderStateMachine::SendStreamData() drops the audio sample from the head of the queue. So the invalid audio sample(5s timestamp) might make the 6~10 samples can not be sent to the DecodedStream => audio clock doens't go forward => MDSM falls in infinite loop.

Comment 4

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

Comment on attachment 8577923 [details] [diff] [review]
bug-1140995-timeout-part1.v01.patch

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

You should add comment for this adjustment is for B2G only where VideoData.mDuration is 1. Also, the fuzzy value should be used for comparison only, not to alter the result of clock time. (See also ESTIMATED_DURATION_FUZZ_FACTOR_USECS).

::: dom/media/MediaDecoderStateMachine.cpp
@@ +3112,5 @@
>    } else {
>      if (mAudioCaptured) {
>        clock_time = mStartTime + mDecoder->GetDecodedStream()->GetClock();
> +      if (mState == DECODER_STATE_COMPLETED) {
> +        clock_time += mDeviationClockTimeFromDecodedStream_usec;

This will result in wrong end time.

Comment 5

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

Comment on attachment 8577933 [details] [diff] [review]
bug-1140995-timeout-part2.v01.patch

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

::: dom/media/MediaDecoderStateMachine.cpp
@@ +718,5 @@
>    nsRefPtr<AudioData> audio(aAudioSample);
>    MOZ_ASSERT(audio);
>    mAudioDataRequest.Complete();
> +  if (audio->GetEndTime() <= mDecodedAudioEndTime) {
> +    DECODER_WARN("Illegal audio sample, audio->GetEndTime() < mDecodedAudioEndTime");

Please print the begin/end time of |audio| for easier debugging.

Comment 6

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

Comment on attachment 8577923 [details] [diff] [review]
bug-1140995-timeout-part1.v01.patch

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

This is MSG related code, roc should review it.

Comment 7

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

Comment on attachment 8577933 [details] [diff] [review]
bug-1140995-timeout-part2.v01.patch

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

This won't work. Sometimes on Mac and Windows the first audio sample output has a negative timestam. Those samples are valid, and we can play them. The first time OnAudioDecoded() runs mDecodedAudioEndTime will be -1, so we'll reject those samples with this change here. 

You may need a flag to denote whether mDecodedAudioEndTime is valid, or you could make it an Optional<int64_t> to represent that.

Comment 8

[Benjamin Chen [:bechen]]

(In reply to Chris Pearce (:cpearce) from comment #7)
> Comment on attachment 8577933 [details] [diff] [review]
> bug-1140995-timeout-part2.v01.patch
> 
> Review of attachment 8577933 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> This won't work. Sometimes on Mac and Windows the first audio sample output
> has a negative timestam. Those samples are valid, and we can play them. The
> first time OnAudioDecoded() runs mDecodedAudioEndTime will be -1, so we'll
> reject those samples with this change here. 
> 
> You may need a flag to denote whether mDecodedAudioEndTime is valid, or you
> could make it an Optional<int64_t> to represent that.

How about set the initial value of mDecodedAudioEndTime to INT64_MIN? So that I can still check the timestamp is monotonic increasing or not.

Comment 9

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

It should work. But I think Optional<> is clearer for sometimes I am confused by the sentinel value.

Comment 10

[Benjamin Chen [:bechen]]

Now the part2 patch reject the audio/video samples with reorder timestamp fails on the chain.ogg because the chained audio/video will repeat the timestamp from the 0.

It is a problem if we still want to support chained audio/video..

Comment 11

[Benjamin Chen [:bechen]]

Attachment: bug-1140995-timeout-part1.v02.patch

Address comment 4.

Comment 12

[Benjamin Chen [:bechen]]

Attachment: bug-1140995-timeout-part2.v03.patch

The version 2 patch was skipped because I found if I reject the audio/video data at MDSM, it breaks the chained ogg/ogv playback. And since I found the invalid timestamp data only occurs on device and emulator, patch version 3 fix the bug at MediaCodecReader only.

Comment 13

[Benjamin Chen [:bechen]]

(In reply to Benjamin Chen [:bechen] from comment #11)
> Created attachment 8587142 [details] [diff] [review]
> bug-1140995-timeout-part1.v02.patch
> 
> Address comment 4.

Another approach is to fix the videoData's duration.
It depends on bug 1146729, enable the MP4Reader for local playback. Since bug 1020679 add the duration field for video sample, the videoData should have duration for mp4 file.

Comment 14

[Benjamin Chen [:bechen]]

Attachment: bug-1140995-timeout-part1.v03.patch

Comment 15

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

Comment on attachment 8591539 [details] [diff] [review]
bug-1140995-timeout-part1.v03.patch

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

::: dom/media/MediaDecoderStateMachine.cpp
@@ +505,5 @@
> +        // Send the mLastVideoImage till the end of stream, if there is no
> +        // duration for the stream, we send it a deviation clock.
> +        VideoSegment endSegment;
> +        int64_t endtime = GetEndTime();
> +        if (endtime == INT64_MAX) {

What does |endtime == -1| mean?

@@ +510,5 @@
> +          //Calculate the deviation clock time from DecodedStream.
> +          TrackRate rate = stream->mStream->GraphRate();
> +          uint64_t deviation_usec = 0;
> +          if (rate > 0) {
> +            deviation_usec = (1000000 / rate) + 1;

deviation_usec = stream->mStream->StreamTimeToMicroseconds(1) + 1;

@@ +515,5 @@
> +          }
> +          endtime = stream->mNextVideoTime + deviation_usec;
> +        }
> +        WriteVideoToMediaStream(mediaStream, stream->mLastVideoImage,
> +          endtime, stream->mNextVideoTime, stream->mLastVideoImageDisplaySize,

check |endtime > stream->mNextVideoTime|

Comment 16

[Benjamin Chen [:bechen]]

(In reply to JW Wang [:jwwang] from comment #15)
> Comment on attachment 8591539 [details] [diff] [review]
> bug-1140995-timeout-part1.v03.patch
> 
> Review of attachment 8591539 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: dom/media/MediaDecoderStateMachine.cpp
> @@ +505,5 @@
> > +        // Send the mLastVideoImage till the end of stream, if there is no
> > +        // duration for the stream, we send it a deviation clock.
> > +        VideoSegment endSegment;
> > +        int64_t endtime = GetEndTime();
> > +        if (endtime == INT64_MAX) {
> 
> What does |endtime == -1| mean?
> 

If the value is -1, that means the SetDuration() function is never called from MediaDecoder or MDSM. It should be a bug. So here I only check the value is INT64_MAX or not.

Comment 17

[Benjamin Chen [:bechen]]

Attachment: bug-1140995-timeout-part1.v03.patch

Address comment 15.

Comment 18

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

Comment on attachment 8592073 [details] [diff] [review]
bug-1140995-timeout-part1.v03.patch

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

Better but still have some problems to fix.

::: dom/media/MediaDecoderStateMachine.cpp
@@ +507,5 @@
> +        VideoSegment endSegment;
> +        int64_t endtime = GetEndTime();
> +        if (endtime == INT64_MAX) {
> +          // Calculate the deviation clock time from DecodedStream.
> +          int64_t deviation_usec = mediaStream->StreamTimeToMicroseconds(1) + 1;

In fact, I think it should be enough to just compensate |mediaStream->StreamTimeToMicroseconds(1)| us instead of |mediaStream->StreamTimeToMicroseconds(1) + 1| us.

The problem here is that if the duration is very short, we could have
stream->MicrosecondsToStreamTimeRoundDown(v->mTime) == stream->MicrosecondsToStreamTimeRoundDown(v->GetEndTime()) and it contributes zero ticks to the stream time.

Therefore the last video frame will never be popped in AdvanceFrame() since the clock time is always smaller than v->mTime for the last frame.

Doing some simple math, we can prove stream->MicrosecondsToStreamTimeRoundDown(v->GetEndTime() + mediaStream->StreamTimeToMicroseconds(1)) - stream->MicrosecondsToStreamTimeRoundDown(v->mTime) >= 1. Therefore, mediaStream->StreamTimeToMicroseconds(1) is the smallest duration we need to compensate in order for last video to contribute at least one tick.

@@ +510,5 @@
> +          // Calculate the deviation clock time from DecodedStream.
> +          int64_t deviation_usec = mediaStream->StreamTimeToMicroseconds(1) + 1;
> +          endtime = stream->mNextVideoTime + deviation_usec;
> +        }
> +        if (stream->mNextVideoTime < endtime) {

What if endtime is very close to stream->mNextVideoTime and we still contribute zero ticks to the stream time?

@@ +515,5 @@
> +          WriteVideoToMediaStream(mediaStream, stream->mLastVideoImage,
> +            endtime, stream->mNextVideoTime, stream->mLastVideoImageDisplaySize,
> +            &endSegment);
> +          stream->mNextVideoTime = endtime;
> +          if (endSegment.GetDuration() > 0) {

Assert |endSegment.GetDuration() > 0| to make sure we compensate enough ticks fix the problem mentioned above.

Comment 19

[Benjamin Chen [:bechen]]

Attachment: bug-1140995-timeout-part1.v03.patch

Address comment 18.

Comment 20

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

Comment on attachment 8592611 [details] [diff] [review]
bug-1140995-timeout-part1.v03.patch

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

::: dom/media/MediaDecoderStateMachine.cpp
@@ +518,5 @@
> +            endtime, stream->mNextVideoTime, stream->mLastVideoImageDisplaySize,
> +            &endSegment);
> +          stream->mNextVideoTime = endtime;
> +          MOZ_ASSERT(endSegment.GetDuration() > 0);
> +          if (endSegment.GetDuration() > 0) {

Since you assert it above, you don't need to check it again.

Comment 21

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

Comment on attachment 8592611 [details] [diff] [review]
bug-1140995-timeout-part1.v03.patch

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

::: dom/media/MediaDecoderStateMachine.cpp
@@ +509,5 @@
> +        int64_t endtime = GetEndTime();
> +        // Calculate the deviation clock time from DecodedStream.
> +        int64_t deviation_usec = mediaStream->StreamTimeToMicroseconds(1);
> +        if (endtime == INT64_MAX ||
> +            (endtime - stream->mNextVideoTime) < deviation_usec) {

Also you need to check if the duration of last video frame is more than 1 tick, you don't need this compensation.

Comment 22

[Benjamin Chen [:bechen]]

Attachment: bug-1140995-timeout-part1.v04.patch

Comment 23

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

Comment on attachment 8593837 [details] [diff] [review]
bug-1140995-timeout-part1.v04.patch

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

::: dom/media/MediaDecoderStateMachine.cpp
@@ +501,5 @@
>                &output);
>            stream->mNextVideoTime = v->GetEndTime();
>            stream->mLastVideoImage = v->mImage;
>            stream->mLastVideoImageDisplaySize = v->mDisplay;
> +          if (i == video.Length() - 1) { // The end of for-loop

You don't need this if statement. All you need to do is keep updating
StreamTime lastFrameDuration =
  mediaStream->MicrosecondsToStreamTimeRoundDown(v->mTime) -
  mediaStream->MicrosecondsToStreamTimeRoundDown(v->GetEndTime())
in the for loop.

|lastFrameDuration| will be the duration of last frame in |if (stream->mEOSVideoCompensation)|.

@@ +502,5 @@
>            stream->mNextVideoTime = v->GetEndTime();
>            stream->mLastVideoImage = v->mImage;
>            stream->mLastVideoImageDisplaySize = v->mDisplay;
> +          if (i == video.Length() - 1) { // The end of for-loop
> +            stream->mEOSVideoCompensation = ZeroDurationAtLastChunk(output);

It is wrong because output could contain data from other frames.

@@ +513,5 @@
>        if (output.GetDuration() > 0) {
>          mediaStream->AppendToTrack(videoTrackId, &output);
>        }
>        if (VideoQueue().IsFinished() && !stream->mHaveSentFinishVideo) {
> +        if (stream->mEOSVideoCompensation) {

mEOSVideoCompensation is only read/written here. It can be a local variable instead of a member.

Comment 24

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

Comment on attachment 8593837 [details] [diff] [review]
bug-1140995-timeout-part1.v04.patch

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

::: dom/media/MediaDecoderStateMachine.cpp
@@ +393,5 @@
> +static bool ZeroDurationAtLastChunk(VideoSegment& aInput)
> +{
> +  StreamTime lastVideoStratTime;
> +  aInput.GetLastFrame(&lastVideoStratTime);
> +  return lastVideoStratTime == aInput.GetDuration();

The code is tricky. Please put a comment to explain it.

Comment 25

[Benjamin Chen [:bechen]]

Attachment: bug-1140995-timeout-part1.v04.patch

Address comment 23, comment 24.

Comment 26

[Benjamin Chen [:bechen]]

Attachment: bug-1140995-timeout-part2.v03.patch

part2 patch, r=cpearce

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

Comment 27

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/e73f7d6a138d
https://hg.mozilla.org/integration/mozilla-inbound/rev/e428ba6470b9

Comment 28

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/e73f7d6a138d
https://hg.mozilla.org/mozilla-central/rev/e428ba6470b9

Comment 29

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Backed out this bug and bug 1153690 for causing bug 1157654.

Comment 30

[Benjamin Chen [:bechen]]

Attachment: bug-1140995-timeout-part1.v04.patch

Rebase.

Comment 31

[Benjamin Chen [:bechen]]

Attachment: bug-1140995-timeout-part2.v03.patch

Rebase.
try server:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=5f05567c53ef

Comment 32

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/a50fbea53921
https://hg.mozilla.org/integration/mozilla-inbound/rev/3dee2a2ce28b

Comment 33

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/a50fbea53921
https://hg.mozilla.org/integration/mozilla-inbound/rev/3dee2a2ce28b

Comment 34

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/a50fbea53921
https://hg.mozilla.org/mozilla-central/rev/3dee2a2ce28b