1266938 - Frames are displayed out of order on Shaka Player's demo video "Sintel 4K (multicodec, widevine)"

Status: VERIFIED FIXED

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

Description

[Jean-Yves Avenard [:jya]]

STR:

1: http://shaka-player-demo.appspot.com/demo/
2: Select "Sintel 4K (multicodec, widevine)
3: Click Load
4: Click on "info" button, and select the 1921x818 stream
5: Move playback position back to 0

Frames are completely out of order, and continues to do so for the first 2 minutes.

Sometimes it gets better, more often than not it doesn't.

Reproduced on OS X 10.1, Nightly 48.0a1 (2016-04-22)

Comment 1

[Chris Peterson [:cpeterson]]

Jean-Yves, are you playing the video with WebM or MP4?

The WebM video doesn't even play for me on OS X or Windows. I hit a "Shaka Error STREAMING.BAD_SEGMENT" error (bug 1265040).

Comment 2

[Jean-Yves Avenard [:jya]]

It has to be MP4; we have no support for webm EME; I did have MSE with webm enabled. 

This is using stock nightly.

Comment 3

[Chris Peterson [:cpeterson]]

Until we know more, I'm marking this bug as something we should investigate for Amazon Video in Beta 47.

Jean-Yves says Chrome on OS X plays this video correctly.

Comment 5

[Jean-Yves Avenard [:jya]]

I don't see how the two are related. This is purely inside the widevine cdm video decoder.

Comment 6

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

We probably just need to add our re-orderer into the WidevineVideoDecoder object.

Comment 7

[Chris Peterson [:cpeterson]]

jya: cpearce suggested you take a look at this issue.

Comment 8

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

I get this intermittently on https://www.choicetv.co.nz/#!/play/tv/190/season/2/episode/8/episode-8

Comment 9

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

(In reply to Anthony Jones (:kentuckyfriedtakahe, :k17e) from comment #8)
> I get this intermittently on
> https://www.choicetv.co.nz/#!/play/tv/190/season/2/episode/8/episode-8

This is reproducible with basic layers but not consistently.

Comment 10

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

I can't repro this issue on the Sintel4K trailer on Win10 Nightly and Beta builds. Can you still repro?

Comment 11

[Jean-Yves Avenard [:jya]]

Couldn't reproduce it in today's Nightly. So will close as WFM and reopen if I ever see it again

This is what it looked like when the problem occurred: https://www.youtube.com/watch?v=QjjAMsU_IOk

Comment 12

[Jean-Yves Avenard [:jya]]

It's still still happening. cpearce believes the issue is related to shmem allocations happening out of order.

Comment 13

[Jean-Yves Avenard [:jya]]

Video exhibiting the behaviour: https://www.youtube.com/watch?v=QjjAMsU_IOk

Comment 15

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

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

Comment 16

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Attachment: Bug 1266938 - Prevent WidevineVideoDeocder emitting out of order frames.

It was possible for WidevineVideoDeocder when allocating shmems for frames to
become reentrant. If a further frame was allocated during this reentrancy it
would be returned before the first frame being allocated. As frames are fed into
the decoder in order, altering this order for returned frames would result in an
out of order display.

This is addressed by keeping a deque of frames and allocating them in order.

There are changes to guard again reentracy issues with draining also. Previously
it was possible to drain a decoder, but still have a frame allocation be
pending, resulting in a drain being completed, and a frame being returned follow
that. This has been addressed by not draining during reentrancy.

This changeset also adds further logging to some of the ipc logs, this logging
can be used to determine the message types being passed around, and is useful
for debugging the other changes made here.

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

Comment 17

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

Comment on attachment 8774156 [details]
Bug 1266938 - Prevent WidevineVideoDeocder emitting out of order frames.

https://reviewboard.mozilla.org/r/66732/#review63442

This is a tricky patch, so a few comments here. Please let me know if the assertions I suggest you add fail.

::: dom/media/gmp/widevine-adapter/WidevineVideoDecoder.h:69
(Diff revision 1)
>    bool mSentInput;
> +  // Frames waiting on allocation
> +  std::deque<WidevineVideoFrame> mFrameAllocationQueue;
> +  // Number of calls of ReturnOutput currently in progress.
> +  int32_t mReturnOutputCallDepth;
> +  // If we're waiting to drain. Used to prevent drain happening while

Do you mean "Used to prevent drain *completing* while ReturnOutput calls are on the stack"?

::: dom/media/gmp/widevine-adapter/WidevineVideoDecoder.cpp:134
(Diff revision 1)
>        Log("WidevineVideoDecoder::Decode() Failed in ReturnOutput()");
>        mCallback->Error(GMPDecodeErr);
>        return;
>      }
> +    // Only request more data if we're not resetting and don't have pending samples.
> +    if (!mResetInProgress && mFrameAllocationQueue.empty()) {

Isn't mResetInProgress always false here, since if we did Reset inside the reentrant CreateEmptyFrame() call in the "dump the current frame and complete the reset" branch in ReturnOutput, we'd call CompleteReset()?

Doesn't that mean we'll set mResetInProgress=false in CompleteReset() and thus call InputDataExhausted() here?

It seems to me that the caller of ReturnOutput() needs to handle the reset-in-progress and drain-in-progress cases?

::: dom/media/gmp/widevine-adapter/WidevineVideoDecoder.cpp:150
(Diff revision 1)
> +  if (mDrainPending && mReturnOutputCallDepth == 0) {
> +    Drain();
> +  }
> +}
> +
> +WidevineVideoDecoder::CounterHelper::CounterHelper(int32_t& counter)

CounterHelper is only used inside this class, so you don't need to define it in the header, you can just define it inside the .cpp file.

::: dom/media/gmp/widevine-adapter/WidevineVideoDecoder.cpp:171
(Diff revision 1)
>  {
> +  MOZ_ASSERT(mReturnOutputCallDepth >= 0);
> +  CounterHelper counterHelper(mReturnOutputCallDepth);
> +  mFrameAllocationQueue.push_back(Move(aCDMFrame));
> +  if (mReturnOutputCallDepth > 1) {
> +    // In a reentrant call

Nit: Missing full stop at end of sentence.

::: dom/media/gmp/widevine-adapter/WidevineVideoDecoder.cpp:176
(Diff revision 1)
> +    // In a reentrant call
> +    return true;
> +  }
> +  while (!mFrameAllocationQueue.empty()) {
> +    MOZ_ASSERT(mReturnOutputCallDepth == 1);
> +    if (mResetInProgress) {

You shouldn't need to reset both here and after the CreateEmptyFrame() call. The only place that adds reentrancy is the CreateEmptyFrame() call, so in theory we should never be inside a Reset operation here.

So I think you could remove the CompleteReset() here, and even assert !mResetInProgress.

::: dom/media/gmp/widevine-adapter/WidevineVideoDecoder.cpp:195
(Diff revision 1)
> -  Size size = aCDMFrame.Size();
> -  const int32_t yStride = aCDMFrame.Stride(VideoFrame::kYPlane);
> -  const int32_t uStride = aCDMFrame.Stride(VideoFrame::kUPlane);
> -  const int32_t vStride = aCDMFrame.Stride(VideoFrame::kVPlane);
> +    Size size = currentCDMFrame.Size();
> +    const int32_t yStride = currentCDMFrame.Stride(VideoFrame::kYPlane);
> +    const int32_t uStride = currentCDMFrame.Stride(VideoFrame::kUPlane);
> +    const int32_t vStride = currentCDMFrame.Stride(VideoFrame::kVPlane);
> -  const int32_t halfHeight = size.height / 2;
> +    const int32_t halfHeight = size.height / 2;
> +    // This call can cause a shmem alloc, during this alloc other calls

I think this comment should be clearer. Possibly with a big ALL BETS ARE OFF here. Basically all state needs to be re-evaluated, as everything could have changed.

You should say "other IPC messages can be processed which may result in calls into the CDM..."

::: dom/media/gmp/widevine-adapter/WidevineVideoDecoder.cpp:211
(Diff revision 1)
>  
> +    // If a reset started we need to dump the current frame and complete the reset.
> +    if (mResetInProgress) {
> +      MOZ_ASSERT(mCDMWrapper);
> +      MOZ_ASSERT(mFrameAllocationQueue.empty());
> +      gmpFrame->Destroy();

We should actually be calling Destroy() on the output frame on the other paths that return failure here too.

This is a problem with the existing code.

Can you add a helper class that destroys the frame in its destructor? We don't want shmem's leaking. Don't forget to reset the destroy behaviour before passing the frame to mCallback->Decoded().

::: dom/media/gmp/widevine-adapter/WidevineVideoDecoder.cpp:262
(Diff revision 1)
>  
>  void
>  WidevineVideoDecoder::Reset()
>  {
>    Log("WidevineVideoDecoder::Reset() mSentInput=%d", mSentInput);
> +  mResetInProgress = true;

We should assert that we're not draining for consistency.

::: dom/media/gmp/widevine-adapter/WidevineVideoDecoder.cpp:308
(Diff revision 1)
>      }
>      if (rv == kSuccess) {
>        if (!ReturnOutput(frame)) {
>          Log("WidevineVideoDecoder::Decode() Failed in ReturnOutput()");
>        }
>      }

I think you should assert that we don't get a Reset() before finishing the drain.

::: ipc/glue/MessageChannel.cpp:957
(Diff revision 1)
>      // shouldWakeUp is true, it's easier to post anyway than to have to
>      // guarantee that every Send call processes everything it's supposed to
>      // before returning.
>      bool shouldPostTask = !shouldWakeUp || wakeUpSyncSend;
>  
> -    IPC_LOG("Receive on link thread; seqno=%d, xid=%d, shouldWakeUp=%d",
> +    IPC_LOG("Receive on link thread; seqno=%d, xid=%d, type=%d, shouldWakeUp=%d",

You should split the changes to ipc/ off into another patch and get an IPC peer to review them. Probably by :billm.

Comment 18

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Comment on attachment 8774156 [details]
Bug 1266938 - Prevent WidevineVideoDeocder emitting out of order frames.

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

Comment 19

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

https://reviewboard.mozilla.org/r/66732/#review63442

> Isn't mResetInProgress always false here, since if we did Reset inside the reentrant CreateEmptyFrame() call in the "dump the current frame and complete the reset" branch in ReturnOutput, we'd call CompleteReset()?
> 
> Doesn't that mean we'll set mResetInProgress=false in CompleteReset() and thus call InputDataExhausted() here?
> 
> It seems to me that the caller of ReturnOutput() needs to handle the reset-in-progress and drain-in-progress cases?

Removing this and replacing with an assert after discussion. We shouldn't recieve any more decodes after we recieve a reset, until we've issued a reset complete.

> You shouldn't need to reset both here and after the CreateEmptyFrame() call. The only place that adds reentrancy is the CreateEmptyFrame() call, so in theory we should never be inside a Reset operation here.
> 
> So I think you could remove the CompleteReset() here, and even assert !mResetInProgress.

Agreed.

Comment 20

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

Comment on attachment 8774156 [details]
Bug 1266938 - Prevent WidevineVideoDeocder emitting out of order frames.

https://reviewboard.mozilla.org/r/66732/#review63890

::: dom/media/gmp/widevine-adapter/WidevineVideoDecoder.cpp:168
(Diff revision 2)
> +};
> +
> +CounterHelper::CounterHelper(int32_t& counter)
> +  : mCounter(counter)
> +{
> +  mCounter++;

Nit: Given the simplicity of CounterHelper, I'd have put the function definitions inline in the class.

Then you'll save 10 lines.

Ditto for FrameHolderHelper.

::: dom/media/gmp/widevine-adapter/WidevineVideoDecoder.cpp:179
(Diff revision 2)
> +}
> +
> +// Util class to make sure GMP frames are freed. Holds a GMPVideoi420Frame*
> +// and will destroy it when the holder is destroyed unless ForgetFrame is
> +// called.
> +class FrameHolderHelper {

Maybe call it FrameDestroyerHelper, since destroying frames is what it's helping with.

::: dom/media/gmp/widevine-adapter/WidevineVideoDecoder.cpp:247
(Diff revision 2)
> -  const int32_t halfHeight = size.height / 2;
> +    const int32_t halfHeight = size.height / 2;
> +    // This call can cause a shmem alloc, during this alloc other calls
> +    // may be made to this class and placed on the stack. ***WARNING***:
> +    // other IPC calls can happen during this call, resulting in calls
> +    // being made to the CDM. After this call state can have changed,
> +    // and should be verified.

I'd say "should be reevaluated".

::: dom/media/gmp/widevine-adapter/WidevineVideoFrame.cpp:26
(Diff revision 2)
>    memset(mPlaneOffsets, 0, sizeof(mPlaneOffsets));
>    memset(mPlaneStrides, 0, sizeof(mPlaneStrides));
>  }
>  
> +WidevineVideoFrame::WidevineVideoFrame(WidevineVideoFrame&& other)
> +  : mFormat(other.mFormat)

aOther to conform to Mozilla coding style.

Comment 21

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

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

Comment 22

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Comment on attachment 8774156 [details]
Bug 1266938 - Prevent WidevineVideoDeocder emitting out of order frames.

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

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/212b7e507a61
Prevent WidevineVideoDecoder emitting out of order frames. r=cpearce

Comment 24

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/c8261ef537e0591497988faba7e8b3da5bdb65f8
Bug 1266938 - Add explicit to ctors for helper classes in WidevineVideoDecoder. r=bustage

Comment 25

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c8261ef537e0
Add explicit to ctors for helper classes in WidevineVideoDecoder. r=bustage

Comment 26

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/212b7e507a61
https://hg.mozilla.org/mozilla-central/rev/c8261ef537e0

Comment 27

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Attachment: Original patch with :cpearce's fix to make new ctors explicit.

Approval Request Comment
[Feature/regressing bug #]: Bug 1266938
[User impact if declined]: Possible for video frames to be displayed out of order when playing encrypted videos such as those on Netflix, Amazon Prime Video, or Youtube. Any video played back using Widevine can be impacted. Pre patch, if frames are fed into the decoder fast enough that pending memory allocations stack up, it is guaranteed that they will be returned out of order like a stack, rather than a queue -- queue being the desired behaviour.
[Describe test coverage new/current, TreeHerder]: TreeHerder: https://treeherder.mozilla.org/#/jobs?repo=try&revision=5b4ebc48c2b2&selectedJob=24526270 - No video breakages have been introduced, other failures are unrelated. This patch does not add any new tests. There is currently no automated test coverage for the issue addressed by this patch. It can and has been manually tested by playing back widevine encrypted videos at https://shaka-player-demo.appspot.com/demo/ and inspecting if frames are out of order (this could often be seen after seeking, particularly in debug builds). Using NSPR_LOG_MODULES=MediaFormatReader:5 will show out of order frames being emitted in the logs before patch is applied, after patch is applied no such frames exist. The patch has also been manually tested to ensure no breakages of sites such as Netflix or Youtube.
[Risks and why]: Low to medium. Patch affects video playback, which is complex, however patch is isolated to specific unit of playback stack. When changing the video stack it is possible to impact performance (bad), or the ability to playback video (very bad). Neither of these appear to have been impacted based on manual testing.
[String/UUID change made/needed]: No changes made.

Comment 28

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8777549 [details] [diff] [review]
Original patch with :cpearce's fix to make new ctors explicit.

OK, let's try it because we care about video. Should be in 49 beta 2

Bryce, how can we verify that it is fixed?

Comment 29

[Sylvestre Ledru [:Sylvestre]]

This is early in the cycle, we can always backout it in case it causes too much regressions.

Comment 30

[Carsten Book [:Tomcat]]

 https://hg.mozilla.org/releases/mozilla-beta/rev/efa6e16e9e4d

Comment 31

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

The issue is dependant on how fast FF can process frames on this path, so it's more notable in slower environments (I noticed it a lot in a debug build). The following appears to work fairly well for optimised/release builds:

1. Head over to Shaka player: https://shaka-player-demo.appspot.com/demo/
2. Load the Sintel 4K (multicodec, Widevine) video
3. Repeatedly seek to the same location as fast as you can click (you may need to wait for the range around this location to buffer).
4. Stop seeking and watch as the frames play back out of order.

Will add attachments showing expected before and after patch behaviour.

Comment 32

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Attachment: Repeatedly seeking to 3:51 in Shaka's Sintel 4K Multicodec Widevine using FireFox 48, shows out of order playback

Comment 33

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Attachment: Repeatedly seeking to 3:51 in Shaka's Sintel 4K Multicodec Widevine using FireFox 51

Comment 34

[Alexandru Simonca [:asimonca], Release Desktop QA]

This issue is VERIFIED FIXED on Windows 10 x64 & OS X 10.11 on the following builds:
- Firefox Beta 50.0b1 build 2 (id: 20160920155715)
- Firefox 49.0.1 build 3 (id: 20160922113459)