1458852 - HTMLMediaElement::GetCurrentImage may return old image

Status: RESOLVED FIXED

(Core :: Audio/Video: Recording, enhancement, P2)

Description

[Andreas Pehrson [:pehrsons]]

See bug 1403307 comment 49.

> I've debugged a case of this intermittent, and what happens is that the last
> (green) frame hits the underrun path in [1].
> 
> The only way we can append the same frame again is then to wait 1 second,
> but we reach EOS before that happens.
> 
> I need to look at why exactly we hit the underrun path here, and check
> whether some logic is flawed.
> 
> 
> [1] https://searchfox.org/mozilla-central/rev/ce9ff94ffed34dc17ec0bfa406156d489eaa8ee1/dom/media/encoder/TrackEncoder.cpp#769

This is for fixing that issue and re-enabling dom/media/test/test_mediarecorder_pause_resume_video.html.

Comment 1

[Andreas Pehrson [:pehrsons]]

The analysis in comment 0 was completely wrong :-)

Hitting the underrun path in VideoTrackEncoder is OK because VideoTrackEncoder::NotifyEndOfStream will still send the image to be encoded.

I continued debugging the issue, and we are getting a stale image from HTMLMediaElement::GetCurrentImage, [1].

In this particular case I have been using Pernosco to debug further. It showed that the image was both encoded and decoded just fine. To find the issue I jumped to the logged error ("Last frame should be green") and reversed to the previous HTMLMediaElement::GetCurrentImage(). This is the call where we're trying to draw the last frame (alas after the media element's "ended" event) to a canvas to inspect pixels. Verified by the js stack:

> (pernosco) call DumpJSStack() 
> 0 getPixel(video = [object HTMLVideoElement]) ["http://mochi.test:8888/tests/dom/canvas/test/captureStream_common.js":69]
>     this = [object Object]
> 1 startTest/mediaRecorder.onstop/video.onended([object Event]) ["http://mochi.test:8888/tests/dom/media/test/test_mediarecorder_pause_resume_video.html":104]

At this point (see locals in [1]) the relevant state of the image container is:
> (pernosco) p container->mCurrentImages
> $95 = nsTArray<mozilla::layers::ImageContainer::OwningImage> =
> {{mImage = [(mozilla::layers::SharedPlanarYCbCrImage *) 0x245e1f87df20], mTimeStamp = {mValue = 1046879333653654}, mFrameID = 1, mProducerID = 3, mComposited = true},
> {mImage = [(mozilla::layers::SharedPlanarYCbCrImage *) 0x4208138994a0], mTimeStamp = {mValue = 1046880333653654}, mFrameID = 2, mProducerID = 3, mComposited = true},
> {mImage = [(mozilla::layers::SharedPlanarYCbCrImage *) 0x424f43b9f660], mTimeStamp = {mValue = 1046880446653654}, mFrameID = 3, mProducerID = 3, mComposited = true}}

Note that AutoLockImage(container)::GetImage() always returns mCurrentImages[0]. In this case that's not the last image in the webm file.

From this point, breaking on the *previous* TimeStamp::Now(), it returned a value of 1046880601280795:
> Thread 1 hit Breakpoint 15, mozilla::TimeStamp::Now (aHighResolution=aHighResolution@entry=true) at /builds/worker/workspace/build/src/mozglue/misc/TimeStamp_posix.cpp:204
> (pernosco) fin 
> Run till exit from #0  mozilla::TimeStamp::Now (aHighResolution=aHighResolution@entry=true) at /builds/worker/workspace/build/src/mozglue/misc/TimeStamp_posix.cpp:204
> Value returned is $96 = {mValue = 1046880601280795}

Note that the last frame in the image container has a timestamp of value 1046880446653654, and wall clock time has definitely passed 1046880601280795, which is *later* (8th digit is a 6, last frame has a 4). The values are in nanoseconds so the diff is ~0.15 seconds.

It's clear that the last frame has been played out so returning the first frame here is wrong. This should be as simple as changing `AutoLockImage(container)::GetImage()` to `AutoLockImage(container)::GetImage(TimeStamp::Now())`.


[1] https://searchfox.org/mozilla-central/rev/c0d81882c7941c4ff13a50603e37095cdab0d1ea/dom/html/HTMLMediaElement.cpp#1670

Comment 2

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1458852 - Re-enable mochitest.

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

Comment 3

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1458852 - Return real current image in HTMLMediaElement::GetCurrentImage().

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

Comment 4

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

Comment on attachment 8973627 [details]
Bug 1458852 - Re-enable mochitest.

https://reviewboard.mozilla.org/r/241738/#review247884

Comment 5

[Matt Woodrow (:mattwoodrow)]

Comment on attachment 8973628 [details]
Bug 1458852 - Return real current image in HTMLMediaElement::GetCurrentImage().

https://reviewboard.mozilla.org/r/241740/#review248032

Thanks for the detailed explanation!

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/77251c0e21a3
Re-enable mochitest. r=bryce
https://hg.mozilla.org/integration/autoland/rev/632bb768b1dd
Return real current image in HTMLMediaElement::GetCurrentImage(). r=mattwoodrow

Comment 7

[Arthur Iakab [arthur_iakab]]

https://hg.mozilla.org/mozilla-central/rev/77251c0e21a3
https://hg.mozilla.org/mozilla-central/rev/632bb768b1dd