Bug 70448

Summary: compositing/video tests time out on Lion
Product: WebKit Reporter: Simon Fraser (smfr) <simon.fraser>
Component: MediaAssignee: Jer Noble <jer.noble>
Status: RESOLVED FIXED    
Severity: Normal CC: eric.carlson, jer.noble, simon.fraser
Priority: P2    
Version: 528+ (Nightly build)   
Hardware: Unspecified   
OS: Unspecified   
Attachments:
Description Flags
Patch
none
Patch simon.fraser: review+

Description Simon Fraser (smfr) 2011-10-19 15:57:06 PDT 
These two tests time out for me every time I run them on Lion:

+compositing/video/video-poster.html	expected actual diff pretty diff		text	pass
+compositing/video/video-with-invalid-source.html	expected actual diff pretty diff		text	pass

This is in DRT, so WebKit1. The tests also time out when run directly from DRT.
Comment 1 Simon Fraser (smfr) 2011-10-19 17:06:33 PDT 
Output with media logging turned on:

HTMLMediaElement::HTMLMediaElement
HTMLMediaElement::removedFromDocument
CONSOLE MESSAGE: line 31: event.type load
HTMLMediaElement::canPlayType(video/ogg) -> 
HTMLMediaElement::scheduleLoad
HTMLMediaElement::prepareForLoad
HTMLMediaElement::cancelPendingEventsAndCallbacks
HTMLMediaElement::setPlaybackRate(1.000000)
HTMLMediaElement::setShouldDelayLoadEvent(true)
HTMLMediaElement::selectMediaResource
HTMLMediaElement::loadResource(file:///Volumes/SSData/Development/OSX/webkit/OpenSource/LayoutTests/compositing/resources/video.mp4, )
HTMLMediaElement::loadResource - m_currentSrc -> file:///Volumes/SSData/Development/OSX/webkit/OpenSource/LayoutTests/compositing/resources/video.mp4
MediaPlayerPrivateAVFoundation::MediaPlayerPrivateAVFoundation(0x10b033760)
HTMLMediaElement::mediaPlayerEngineUpdated
Layer became composited, count=1
MediaPlayerPrivateAVFoundationObjC::platformLayer(0x10b033760)
MediaPlayerPrivateAVFoundation::load(0x10b033760)
HTMLMediaElement::setNetworkState(2) - current state is 2
MediaPlayerPrivateAVFoundationObjC::createAVAssetForURL(0x10b033760)
MediaPlayerPrivateAVFoundationObjC::checkPlayability(0x10b033760)
Layer lost compositing, count=0
HTMLMediaElement::selectMediaResource, using 'src' attribute url
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x10b033760) - notification 11
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x10b033760) - early return
MediaPlayerPrivateAVFoundation::mainThreadCallback(0x10b033760)
MediaPlayerPrivateAVFoundation::dispatchNotification(0x10b033760) - dispatching 11
MediaPlayerPrivateAVFoundation::updateStates(0x10b033760) - entering with networkState = 2, readyState = 0
MediaPlayerPrivateAVFoundation::updateStates(0x10b033760) - exiting with networkState = 2, readyState = 0
MediaPlayerPrivateAVFoundation::playabilityKnown(0x10b033760)
MediaPlayerPrivateAVFoundationObjC::beginLoadingMetadata(0x10b033760) - requesting metadata loading
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x10b033760) - notification 10
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x10b033760) - early return
MediaPlayerPrivateAVFoundation::mainThreadCallback(0x10b033760)
MediaPlayerPrivateAVFoundation::dispatchNotification(0x10b033760) - dispatching 10
HTMLMediaElement::mediaPlayerCharacteristicChanged
WebCoreAVFMovieObserver:tracksChanged(0x10b033760) - hasVideo = true, hasAudio = false, hasCaptions = false
MediaPlayerPrivateAVFoundation:setNaturalSize(0x10b033760) - size = 352 x 288
HTMLMediaElement::mediaPlayerSizeChanged
MediaPlayerPrivateAVFoundation::updateStates(0x10b033760) - entering with networkState = 2, readyState = 0
MediaPlayerPrivateAVFoundation::prepareToPlay(0x10b033760)
MediaPlayerPrivateAVFoundationObjC::createAVPlayerItem(0x10b033760)
MediaPlayerPrivateAVFoundationObjC::createAVPlayer(0x10b033760)
HTMLMediaElement::setReadyState(1) - current state is 0,
HTMLMediaElement::updatePlayState - shouldBePlaying = false, playerPaused = true
MediaPlayerPrivateAVFoundation::updateStates(0x10b033760) - exiting with networkState = 2, readyState = 1
WebCoreAVFMovieObserver:observeValueForKeyPath(0x10b02afa0) - keyPath = tracks
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x10b033760) - notification 2
MediaPlayerPrivateAVFoundation::dispatchNotification(0x10b033760) - dispatching 2
WebCoreAVFMovieObserver:tracksChanged(0x10b033760) - hasVideo = true, hasAudio = false, hasCaptions = false
MediaPlayerPrivateAVFoundation:setNaturalSize(0x10b033760) - size = 352 x 288
MediaPlayerPrivateAVFoundation::updateStates(0x10b033760) - entering with networkState = 2, readyState = 1
MediaPlayerPrivateAVFoundation::updateStates(0x10b033760) - exiting with networkState = 2, readyState = 1
WebCoreAVFMovieObserver:observeValueForKeyPath(0x10b02afa0) - keyPath = rate
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x10b033760) - notification 12
MediaPlayerPrivateAVFoundation::dispatchNotification(0x10b033760) - dispatching 12
MediaPlayerPrivateAVFoundation::updateStates(0x10b033760) - entering with networkState = 2, readyState = 1
MediaPlayerPrivateAVFoundation::updateStates(0x10b033760) - exiting with networkState = 2, readyState = 1
HTMLMediaElement::mediaPlayerRateChanged
HTMLMediaElement::invalidateCachedTime
HTMLMediaElement::invalidateCachedTime
WebCoreAVFMovieObserver:observeValueForKeyPath(0x10b02afa0) - keyPath = status
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x10b033760) - notification 3
MediaPlayerPrivateAVFoundation::dispatchNotification(0x10b033760) - dispatching 3
MediaPlayerPrivateAVFoundation::updateStates(0x10b033760) - entering with networkState = 2, readyState = 1
MediaPlayerPrivateAVFoundation::duration(0x10b033760) - caching 0.995000
HTMLMediaElement::setNetworkState(3) - current state is 2
HTMLMediaElement::setReadyState(3) - current state is 1,
HTMLMediaElement::setShouldDelayLoadEvent(false)
HTMLMediaElement::updatePlayState - shouldBePlaying = false, playerPaused = true
MediaPlayerPrivateAVFoundation::updateStates(0x10b033760) - exiting with networkState = 3, readyState = 3
WebCoreAVFMovieObserver:observeValueForKeyPath(0x10b02afa0) - keyPath = presentationSize
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x10b033760) - notification 6
MediaPlayerPrivateAVFoundation::dispatchNotification(0x10b033760) - dispatching 6
MediaPlayerPrivateAVFoundation:setNaturalSize(0x10b033760) - size = 352 x 288
MediaPlayerPrivateAVFoundation::updateStates(0x10b033760) - entering with networkState = 3, readyState = 3
MediaPlayerPrivateAVFoundation::updateStates(0x10b033760) - exiting with networkState = 3, readyState = 3
FAIL: Timed out waiting for notifyDone to be called
FAIL: Timed out waiting for notifyDone to be called
Content-Type: text/plain
A <video> should not have a layer until playback begins.
This test can not be run manually, it requires layoutTestController.layerTreeAsText.

No src, no poster 
  PASS: wants layers = false, has layers = false


#EOF
HTMLMediaElement::stop
HTMLMediaElement::userCancelledLoad
HTMLMediaElement::cancelPendingEventsAndCallbacks
HTMLMediaElement::stop
HTMLMediaElement::userCancelledLoad
HTMLMediaElement::cancelPendingEventsAndCallbacks
HTMLMediaElement::~HTMLMediaElement
MediaPlayerPrivateAVFoundationObjC::cancelLoad(0x10b033760)
MediaPlayerPrivateAVFoundation::tearDownVideoRendering(0x10b033760)
MediaPlayerPrivateAVFoundationObjC::platformLayer(0x10b033760)
MediaPlayerPrivateAVFoundation::~MediaPlayerPrivateAVFoundation(0x10b033760)
Program ended with exit code: 0
Comment 2 Simon Fraser (smfr) 2011-10-19 17:16:45 PDT 
The 'canplaythrough' event never comes in.
Comment 3 Simon Fraser (smfr) 2011-10-19 17:24:05 PDT 
Looks like a bug in HTMLMediaElement::setReadyState()
Comment 4 Jer Noble 2011-10-19 18:03:13 PDT 
Created attachment 111705 [details]
Patch
Comment 5 Eric Carlson 2011-10-19 18:15:44 PDT 
Comment on attachment 111705 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=111705&action=review

> Source/WebCore/ChangeLog:13
> +        AVFoundation will occasionally fill it's playback buffers before collecting enough
> +        statistical information to answer YES to isLikelyToKeepUp.  In this situation, set the
> +        ready state to HAVE_ENOUGH_DATA, on the presumption that if the playback buffers are
> +        full, playback will probably not stall.

It would be good to have this comment...

> Source/WebCore/platform/graphics/avfoundation/MediaPlayerPrivateAVFoundation.cpp:453
>              case MediaPlayerAVPlayerItemStatusPlaybackLikelyToKeepUp:
> +            case MediaPlayerAVPlayerItemStatusPlaybackBufferFull:

...here as well.
Comment 6 Jer Noble 2011-10-20 00:19:58 PDT 
Committed r97944: <http://trac.webkit.org/changeset/97944>
Comment 7 Simon Fraser (smfr) 2011-10-20 11:25:45 PDT 
Still failing for me:

HTMLMediaElement::HTMLMediaElement
HTMLMediaElement::removedFromDocument
HTMLMediaElement::canPlayType(video/ogg) -> 
HTMLMediaElement::scheduleLoad
HTMLMediaElement::prepareForLoad
HTMLMediaElement::cancelPendingEventsAndCallbacks
HTMLMediaElement::setPlaybackRate(1.000000)
HTMLMediaElement::setShouldDelayLoadEvent(true)
HTMLMediaElement::selectMediaResource
HTMLMediaElement::loadResource(file:///Volumes/SSData/Development/OSX/webkit/OpenSource/LayoutTests/compositing/resources/video.mp4, )
HTMLMediaElement::loadResource - m_currentSrc -> file:///Volumes/SSData/Development/OSX/webkit/OpenSource/LayoutTests/compositing/resources/video.mp4
MediaPlayerPrivateAVFoundation::MediaPlayerPrivateAVFoundation(0x107c0e5e0)
HTMLMediaElement::mediaPlayerEngineUpdated
MediaPlayerPrivateAVFoundationObjC::platformLayer(0x107c0e5e0)
MediaPlayerPrivateAVFoundation::load(0x107c0e5e0)
HTMLMediaElement::setNetworkState(2) - current state is 2
MediaPlayerPrivateAVFoundationObjC::createAVAssetForURL(0x107c0e5e0)
MediaPlayerPrivateAVFoundationObjC::checkPlayability(0x107c0e5e0)
HTMLMediaElement::selectMediaResource, using 'src' attribute url
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x107c0e5e0) - notification 11
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x107c0e5e0) - early return
MediaPlayerPrivateAVFoundation::mainThreadCallback(0x107c0e5e0)
MediaPlayerPrivateAVFoundation::dispatchNotification(0x107c0e5e0) - dispatching 11
MediaPlayerPrivateAVFoundation::updateStates(0x107c0e5e0) - entering with networkState = 2, readyState = 0
MediaPlayerPrivateAVFoundation::updateStates(0x107c0e5e0) - exiting with networkState = 2, readyState = 0
MediaPlayerPrivateAVFoundation::playabilityKnown(0x107c0e5e0)
MediaPlayerPrivateAVFoundationObjC::beginLoadingMetadata(0x107c0e5e0) - requesting metadata loading
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x107c0e5e0) - notification 10
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x107c0e5e0) - early return
MediaPlayerPrivateAVFoundation::mainThreadCallback(0x107c0e5e0)
MediaPlayerPrivateAVFoundation::dispatchNotification(0x107c0e5e0) - dispatching 10
HTMLMediaElement::mediaPlayerCharacteristicChanged
WebCoreAVFMovieObserver:tracksChanged(0x107c0e5e0) - hasVideo = true, hasAudio = false, hasCaptions = false
MediaPlayerPrivateAVFoundation:setNaturalSize(0x107c0e5e0) - size = 352 x 288
HTMLMediaElement::mediaPlayerSizeChanged
MediaPlayerPrivateAVFoundation::updateStates(0x107c0e5e0) - entering with networkState = 2, readyState = 0
MediaPlayerPrivateAVFoundation::prepareToPlay(0x107c0e5e0)
MediaPlayerPrivateAVFoundationObjC::createAVPlayerItem(0x107c0e5e0)
MediaPlayerPrivateAVFoundationObjC::createAVPlayer(0x107c0e5e0)
HTMLMediaElement::setReadyState(1) - current state is 0,
HTMLMediaElement::updatePlayState - shouldBePlaying = false, playerPaused = true
MediaPlayerPrivateAVFoundation::updateStates(0x107c0e5e0) - exiting with networkState = 2, readyState = 1
WebCoreAVFMovieObserver:observeValueForKeyPath(0x107c0d000) - keyPath = tracks
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x107c0e5e0) - notification 2
MediaPlayerPrivateAVFoundation::dispatchNotification(0x107c0e5e0) - dispatching 2
WebCoreAVFMovieObserver:tracksChanged(0x107c0e5e0) - hasVideo = true, hasAudio = false, hasCaptions = false
MediaPlayerPrivateAVFoundation:setNaturalSize(0x107c0e5e0) - size = 352 x 288
MediaPlayerPrivateAVFoundation::updateStates(0x107c0e5e0) - entering with networkState = 2, readyState = 1
MediaPlayerPrivateAVFoundation::updateStates(0x107c0e5e0) - exiting with networkState = 2, readyState = 1
WebCoreAVFMovieObserver:observeValueForKeyPath(0x107c0d000) - keyPath = rate
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x107c0e5e0) - notification 12
MediaPlayerPrivateAVFoundation::dispatchNotification(0x107c0e5e0) - dispatching 12
MediaPlayerPrivateAVFoundation::updateStates(0x107c0e5e0) - entering with networkState = 2, readyState = 1
MediaPlayerPrivateAVFoundation::updateStates(0x107c0e5e0) - exiting with networkState = 2, readyState = 1
HTMLMediaElement::mediaPlayerRateChanged
HTMLMediaElement::invalidateCachedTime
HTMLMediaElement::invalidateCachedTime
WebCoreAVFMovieObserver:observeValueForKeyPath(0x107c0d000) - keyPath = status
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x107c0e5e0) - notification 3
MediaPlayerPrivateAVFoundation::dispatchNotification(0x107c0e5e0) - dispatching 3
MediaPlayerPrivateAVFoundation::updateStates(0x107c0e5e0) - entering with networkState = 2, readyState = 1
MediaPlayerPrivateAVFoundation::duration(0x107c0e5e0) - caching 0.995000
HTMLMediaElement::setNetworkState(3) - current state is 2
HTMLMediaElement::setReadyState(3) - current state is 1,
HTMLMediaElement::setShouldDelayLoadEvent(false)
HTMLMediaElement::updatePlayState - shouldBePlaying = false, playerPaused = true
MediaPlayerPrivateAVFoundation::updateStates(0x107c0e5e0) - exiting with networkState = 3, readyState = 3
WebCoreAVFMovieObserver:observeValueForKeyPath(0x107c0d000) - keyPath = presentationSize
MediaPlayerPrivateAVFoundation::scheduleMainThreadNotification(0x107c0e5e0) - notification 6
MediaPlayerPrivateAVFoundation::dispatchNotification(0x107c0e5e0) - dispatching 6
MediaPlayerPrivateAVFoundation:setNaturalSize(0x107c0e5e0) - size = 352 x 288
MediaPlayerPrivateAVFoundation::updateStates(0x107c0e5e0) - entering with networkState = 3, readyState = 3
MediaPlayerPrivateAVFoundation::updateStates(0x107c0e5e0) - exiting with networkState = 3, readyState = 3
FAIL: Timed out waiting for notifyDone to be called
FAIL: Timed out waiting for notifyDone to be called
Content-Type: text/plain
A <video> should not have a layer until playback begins.
This test can not be run manually, it requires layoutTestController.layerTreeAsText.

No src, no poster 
  PASS: wants layers = false, has layers = false


#EOF
HTMLMediaElement::stop
HTMLMediaElement::userCancelledLoad
HTMLMediaElement::cancelPendingEventsAndCallbacks
HTMLMediaElement::stop
HTMLMediaElement::userCancelledLoad
HTMLMediaElement::cancelPendingEventsAndCallbacks
HTMLMediaElement::~HTMLMediaElement
MediaPlayerPrivateAVFoundationObjC::cancelLoad(0x107c0e5e0)
MediaPlayerPrivateAVFoundation::tearDownVideoRendering(0x107c0e5e0)
MediaPlayerPrivateAVFoundationObjC::platformLayer(0x107c0e5e0)
MediaPlayerPrivateAVFoundation::~MediaPlayerPrivateAVFoundation(0x107c0e5e0)
Comment 8 Jer Noble 2011-10-20 12:49:54 PDT 
The poster test begins succeeding when you null out the <video> element's poster attribute; so yes, this patch probably doesn't fix that problem.  I'm looking into it more.
Comment 9 Jer Noble 2011-10-24 17:17:11 PDT 
Created attachment 112282 [details]
Patch
Comment 10 Jer Noble 2011-10-25 10:41:22 PDT 
Committed r98359: <http://trac.webkit.org/changeset/98359>