634787 - Fix frame wait duration logic in nsBuiltinDecoderStateMachine::AdvanceFrame

Status: VERIFIED FIXED

(Core :: Audio/Video, defect)

Description

[Matthew Gregan [:kinetik]]

Chris noticed in bug 580531 that the frame wait duration logic in AdvanceFrame is incorrect. It always waits for the duration of the frame, effectively assuming the current presentation time is equal to the frame start time.

I've also noticed a second problem that explains microstuttering seen during playback.  sync.webm was a great testcase for this due to the consistent motion.  This happens because AdvanceFrame selects a video frame based on the current presentation time; it skips queued frames before the current time, then exits the frame skip loop with the current frame to display.  After presenting the frame, AdvanceFrame sleeps for the frame duration.  If it wakes early (and it often does), the frame selection loop exits immediately (and does not set |videoData|) because the curent time is before the frame start time.  In this case,  AdvanceFrame sleeps for AUDIO_DURATION and may miss the next frame's presentation deadline.

Patch coming up.

Comment 1

[Matthew Gregan [:kinetik]]

nsBuiltinDecoderStateMachine::Wait suffers from a round down bug that causes higher CPU use with this patch. For example, it's asked to wait for 34ms but due to rounding waits for closer to 33ms.  The next call to AdvanceFrame then tries to wait an additional 1ms, which is rounded to 0 in Wait and causes a short tight loop of AdvanceFrame calls.

Even with that fixed, it seems to suffer from a hilariously large number of early wakes.  One attempt to sleep for 40ms:
*	Wait(40) elapsed=0.000001 d=0.039999 ms=40
	Wait(40) elapsed=0.000123 d=0.039877 ms=40
	Wait(40) elapsed=0.000685 d=0.039315 ms=39
	Wait(40) elapsed=0.001350 d=0.038650 ms=39
	Wait(40) elapsed=0.002034 d=0.037966 ms=38
	Wait(40) elapsed=0.002663 d=0.037337 ms=37
	Wait(40) elapsed=0.003224 d=0.036776 ms=37
	Wait(40) elapsed=0.003812 d=0.036188 ms=36
	Wait(40) elapsed=0.004397 d=0.035603 ms=36
	Wait(40) elapsed=0.004944 d=0.035056 ms=35
	Wait(40) elapsed=0.005528 d=0.034472 ms=34
	Wait(40) elapsed=0.006105 d=0.033895 ms=34
	Wait(40) elapsed=0.006718 d=0.033282 ms=33
	Wait(40) elapsed=0.007313 d=0.032687 ms=33
	Wait(40) elapsed=0.007910 d=0.032090 ms=32
	Wait(40) elapsed=0.008469 d=0.031531 ms=32
	Wait(40) elapsed=0.009048 d=0.030952 ms=31
	Wait(40) elapsed=0.009710 d=0.030290 ms=30
	Wait(40) elapsed=0.013195 d=0.026805 ms=27
	Wait(40) elapsed=0.013448 d=0.026552 ms=27
	Wait(40) elapsed=0.013662 d=0.026338 ms=26
	Wait(40) elapsed=0.013878 d=0.026122 ms=26
	Wait(40) elapsed=0.014088 d=0.025912 ms=26
	Wait(40) elapsed=0.014344 d=0.025656 ms=26
	Wait(40) elapsed=0.014622 d=0.025378 ms=25
	Wait(40) elapsed=0.014904 d=0.025096 ms=25
	Wait(40) elapsed=0.015218 d=0.024782 ms=25
	Wait(40) elapsed=0.015561 d=0.024439 ms=24
	Wait(40) elapsed=0.015770 d=0.024230 ms=24
	Wait(40) elapsed=0.016050 d=0.023950 ms=24
	Wait(40) elapsed=0.016357 d=0.023643 ms=24
	Wait(40) elapsed=0.016622 d=0.023378 ms=23
	Wait(40) elapsed=0.016893 d=0.023107 ms=23
	Wait(40) elapsed=0.017192 d=0.022808 ms=23
	Wait(40) elapsed=0.017368 d=0.022632 ms=23
	Wait(40) elapsed=0.017536 d=0.022464 ms=22
	Wait(40) elapsed=0.017706 d=0.022294 ms=22
	Wait(40) elapsed=0.017870 d=0.022130 ms=22
	Wait(40) elapsed=0.018033 d=0.021967 ms=22
	Wait(40) elapsed=0.018645 d=0.021355 ms=21
	Wait(40) elapsed=0.018808 d=0.021192 ms=21
	Wait(40) elapsed=0.018975 d=0.021025 ms=21
	Wait(40) elapsed=0.019159 d=0.020841 ms=21
	Wait(40) elapsed=0.019314 d=0.020686 ms=21
	Wait(40) elapsed=0.019481 d=0.020519 ms=21
	Wait(40) elapsed=0.019649 d=0.020351 ms=20
	Wait(40) elapsed=0.019817 d=0.020183 ms=20
	Wait(40) elapsed=0.019981 d=0.020019 ms=20
	Wait(40) elapsed=0.020159 d=0.019841 ms=20
	Wait(40) elapsed=0.020318 d=0.019682 ms=20
	Wait(40) elapsed=0.020481 d=0.019519 ms=20
	Wait(40) elapsed=0.020645 d=0.019355 ms=19
	Wait(40) elapsed=0.022996 d=0.017004 ms=17
	Wait(40) elapsed=0.023038 d=0.016962 ms=17
	Wait(40) elapsed=0.025688 d=0.014312 ms=14
	Wait(40) elapsed=0.025726 d=0.014274 ms=14
	Wait(40) elapsed=0.028247 d=0.011753 ms=12
	Wait(40) elapsed=0.028282 d=0.011718 ms=12
	Wait(40) elapsed=0.030844 d=0.009156 ms=9
	Wait(40) elapsed=0.030878 d=0.009122 ms=9
	Wait(40) elapsed=0.033355 d=0.006645 ms=7
	Wait(40) elapsed=0.033388 d=0.006612 ms=7
	Wait(40) elapsed=0.036112 d=0.003888 ms=4
	Wait(40) elapsed=0.036149 d=0.003851 ms=4
	Wait(40) elapsed=0.038669 d=0.001331 ms=1
	Wait(40) elapsed=0.039741 d=0.000259 ms=0

Comment 2

[Matthew Gregan [:kinetik]]

Attachment: patch v0

Since we no longer rely on AUDIO_DURATION_MS for anything but audio playback, increase it to a larger value to make misuse more obvious and to reduce overhead when playing audio-only files.  This change reduces CPU use during playback of a Vorbis file in my debug build from ~27% to ~14%.

Regarding my last comment, it looks like at least half of the spurious wakes are caused by PlayFromAudioQueue's frequent NotifyAll() calls.  We'll deal with that another day (probably by fixing bug 623444 and tossing lots of the AudioLoop logic).

Comment 3

[Mike Beltzner [:beltzner, not reading bugmail]]

Comment on attachment 513022 [details] [diff] [review]
patch v0

r+ before a+, please!

Comment 4

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

Comment on attachment 513022 [details] [diff] [review]
patch v0

>@@ -1351,53 +1351,64 @@ void nsBuiltinDecoderStateMachine::Advan
>     // the end of the audio, use the audio clock. However if we've finished
>     // audio, or don't have audio, use the system clock.
>     PRInt64 clock_time = -1;
>     PRInt64 audio_time = GetAudioClock();
>     if (HasAudio() && !mAudioCompleted && audio_time != -1) {
>       clock_time = audio_time;
>       // Resync against the audio clock, while we're trusting the
>       // audio clock. This ensures no "drift", particularly on Linux.
>-      mPlayStartTime = TimeStamp::Now() - TimeDuration::FromMilliseconds(clock_time);
>+      mPlayDuration = TimeDuration::FromMilliseconds(clock_time);

clock_time gets its value from GetAudioClock(), which is in media time (e.g. in the range [mStartTime,mEndTime]), whereas mPlayDuration should be in the range [0,duration]. So this should be:

mPlayDuration = TimeDuration::FromMilliseconds(clock_time - mStartTime);

Otherwise mPlayDuration will be inconsistent between the HasAudio() and !HasAudio() case for videos with non-zero mStartTime.

>+      mPlayStartTime = TimeStamp::Now();
>     } else {
>       // Sound is disabled on this system. Sync to the system clock.
>       TimeDuration t = TimeStamp::Now() - mPlayStartTime + mPlayDuration;
>       clock_time = (PRInt64)(1000 * t.ToSeconds());
>       // Ensure the clock can never go backwards.
>       NS_ASSERTION(mCurrentFrameTime <= clock_time, "Clock should go forwards");
>       clock_time = NS_MAX(mCurrentFrameTime, clock_time) + mStartTime;
>     }
> 
>+    PRInt64 remainingTime = AUDIO_DURATION_MS;
>+
>     NS_ASSERTION(clock_time >= mStartTime, "Should have positive clock time.");
>-    nsAutoPtr<VideoData> videoData;
>+    nsAutoPtr<VideoData> currentFrame;
>     if (mReader->mVideoQueue.GetSize() > 0) {
>-      VideoData* data = mReader->mVideoQueue.PeekFront();
>-      while (clock_time >= data->mTime) {
>-        mVideoFrameEndTime = data->mEndTime;
>-        videoData = data;
>+      VideoData* frame = mReader->mVideoQueue.PeekFront();
>+      while (clock_time >= frame->mTime) {
>+        mVideoFrameEndTime = frame->mEndTime;
>+        currentFrame = frame;
>         mReader->mVideoQueue.PopFront();
>-        mDecoder->UpdatePlaybackOffset(data->mOffset);
>+        mDecoder->UpdatePlaybackOffset(frame->mOffset);
>         if (mReader->mVideoQueue.GetSize() == 0)
>           break;
>-        data = mReader->mVideoQueue.PeekFront();
>+        frame = mReader->mVideoQueue.PeekFront();
>+      }
>+      // Current frame has already been presented, wait until it's time to
>+      // present the next frame.
>+      if (frame && !currentFrame) {
>+        PRInt64 now = (mPlayDuration +
>+                       (TimeStamp::Now() - mPlayStartTime)).ToMilliseconds();

The frame->mTime is in media time, but (mPlayDuration + (mPlayStartTime - TimeStamp::Now())) will be in the range [0,duration] (currently for videos without audio, and for videos with audio when you address my previous comment), so you need to either add mStartTime to |now| or subtract it from frame->mTime, otherwise this calculation will be wrong for videos with non-zero start time.

Can you change the comment in the header file definition of mPlayDuration so that it's clear mStartTime should be added when calculating the current playback position in ms?

>+        remainingTime = frame->mTime - now;
>       }
>     }
> 
>-    PRInt64 frameDuration = AUDIO_DURATION_MS;
>-    if (videoData) {
>+    if (currentFrame) {
>       // Decode one frame and display it
>-      NS_ASSERTION(videoData->mTime >= mStartTime, "Should have positive frame time");
>+      NS_ASSERTION(currentFrame->mTime >= mStartTime, "Should have positive frame time");
>       {
>         MonitorAutoExit exitMon(mDecoder->GetMonitor());
>         // If we have video, we want to increment the clock in steps of the frame
>         // duration.
>-        RenderVideoFrame(videoData);
>+        RenderVideoFrame(currentFrame);
>       }
>-      frameDuration = videoData->mEndTime - videoData->mTime;
>-      videoData = nsnull;
>+      PRInt64 now = (mPlayDuration +
>+                     (TimeStamp::Now() - mPlayStartTime)).ToMilliseconds();
>+      remainingTime = currentFrame->mEndTime - now;

You need to include mStartTime in this calculation as above as well.

Thanks!

Comment 5

[Matthew Gregan [:kinetik]]

The first chunk came from your patch 1 in bug 580531.  I'm surprised we don't have tests that catch this, I'll see if I can add one when I fix this patch.

Comment 6

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

Yeah, and to your credit you handled it in the second chunk of your patch. Re: testing, maybe it's sufficient to add the Theora stream from bug482461.ogv as a test case?

Comment 7

[Matthew Gregan [:kinetik]]

Attachment: patch v1

The correct chunk was from your patch too.  Sorry, I didn't mean to sound like I was blaming you, I meant to make the point that I hadn't paid close enough attention to that logic.

Fixes the issues you pointed out, and includes a Theora-only test file based on bug482461.ogv.  With patch v0 it hangs test_playback, with v1 it passes, so it definitely adds new test coverage for this case.

Comment 8

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

Comment on attachment 513346 [details] [diff] [review]
patch v1

Looks good!

Comment 9

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

http://hg.mozilla.org/mozilla-central/rev/62257785dc70

Comment 10

[u279076]

Is there an easy way for me to verify this bug has been fixed?

Comment 11

[Matthew Gregan [:kinetik]]

Try playing http://tinyvid.tv/show/u6sdgeu4t8gq - before this was fixed, it was possible to see frames dropped once in a while.  With the fix, playback should be perfectly smooth.

Comment 12

[u279076]

(In reply to comment #11)
> Try playing http://tinyvid.tv/show/u6sdgeu4t8gq - before this was fixed, it was
> possible to see frames dropped once in a while.  With the fix, playback should
> be perfectly smooth.

It doesn't play completely smooth.  It pauses for a split second every 3-5 seconds.

Comment 13

[Matthew Gregan [:kinetik]]

It does on my machines, it'll depend a bit on how fast your machine is.  If you try a build from before this fix, are the short pauses noticeably worse?

Comment 14

[u279076]

Yeah, it plays worse on an earlier build.  My Minefield instance is eating up over 900MB right now, so it might be related to that.

Marking VERIFIED.