Bug 173628 – [mac-wk1] requestAnimationFrame callbacks may not get serviced

• Status: RESOLVED
• Resolution: FIXED
• Component: Tools / Tests

[Antoine Quint]

As we found in https://bugs.webkit.org/show_bug.cgi?id=168409, and in other flaky tests, we have an issue where some media/modern-media-controls tests time out due to requestAnimationFrame callbacks not being serviced. We added some logging to identify when ScriptedAnimationController would get suspended in webkit.org/b/173326. This logging points to the fact that the reason rAF callbacks aren't serviced is because Document::requestAnimationFrame() suspends rAF when the page reports that scripted animations ought to be suspended, which is true when m_scriptedAnimationsSuspended is true. We are adding more logging to track this with https://bugs.webkit.org/show_bug.cgi?id=173626. This bug tracks the general issue until it is fixed.

[Antoine Quint]

During https://build.webkit.org/builders/Apple%20El%20Capitan%20Release%20WK1%20(Tests)/builds/2788, media/modern-media-controls/airplay-button/airplay-button-on.html starts with ScriptedAnimationController suspended as Document::requestAnimationFrame() is called and page()->scriptedAnimationsSuspended() is true. For this worker and this Page instance, the last previous call to Page::suspendScriptedAnimations() is made while running fast/events/page-visibility-transition-test.html as a result of Page::setIsVisibleInternal(false) being called. Here's the backtrace:

1   0x109b848bf WebCore::Page::setActivityState(unsigned int)
2   0x10be0381c -[WebView(WebPrivate) _setVisibilityState:isInitialState:]
3   0x106613b45 setPageVisibilityCallback(OpaqueJSContext const*, OpaqueJSValue*, OpaqueJSValue*, unsigned long, OpaqueJSValue const* const*, OpaqueJSValue const**)
4   0x106e6e4dd long long JSC::APICallbackFunction::call<JSC::JSCallbackFunction>(JSC::ExecState*)
5   0x106fc0bb5 JSC::LLInt::setUpCall(JSC::ExecState*, JSC::Instruction*, JSC::CodeSpecializationKind, JSC::JSValue, JSC::LLIntCallLinkInfo*)
6   0x106fc8800 llint_entry
7   0x106fc880e llint_entry
8   0x106fc880e llint_entry
9   0x106fc1bbb vmEntryToJavaScript
10  0x106e1643f JSC::JITCode::execute(JSC::VM*, JSC::ProtoCallFrame*)
11  0x106ddb0e4 JSC::Interpreter::executeCall(JSC::ExecState*, JSC::JSObject*, JSC::CallType, JSC::CallData const&, JSC::JSValue, JSC::ArgList const&)
12  0x10699b2dd JSC::profiledCall(JSC::ExecState*, JSC::ProfilingReason, JSC::JSValue, JSC::CallType, JSC::CallData const&, JSC::JSValue, JSC::ArgList const&, WTF::NakedPtr<JSC::Exception>&)
13  0x1096e5722 WebCore::JSEventListener::handleEvent(WebCore::ScriptExecutionContext*, WebCore::Event*)
14  0x10923f484 WebCore::EventTarget::fireEventListeners(WebCore::Event&, WTF::Vector<WTF::RefPtr<WebCore::RegisteredEventListener>, 1ul, WTF::CrashOnOverflow, 16ul>)
15  0x10923f11e WebCore::EventTarget::fireEventListeners(WebCore::Event&)
16  0x1091ba7b6 WebCore::DOMWindow::dispatchEvent(WebCore::Event&, WebCore::EventTarget*)
17  0x1091c1482 WebCore::DOMWindow::dispatchLoadEvent()
18  0x109161dc5 WebCore::Document::implicitClose()
19  0x1092dc76f WebCore::FrameLoader::checkCompleted()
20  0x1092db2c0 WebCore::FrameLoader::finishedParsing()
21  0x10916f69a WebCore::Document::finishedParsing()
22  0x1093a0c42 WebCore::HTMLDocumentParser::prepareToStopParsing()
23  0x1093a1cb3 WebCore::HTMLDocumentParser::finish()
24  0x1091a17da WebCore::DocumentWriter::end()
25  0x10918a1ec WebCore::DocumentLoader::finishedLoading()
26  0x108f6b6f9 WebCore::CachedResource::checkNotify()
27  0x108f675bc WebCore::CachedRawResource::finishLoading(WebCore::SharedBuffer*)
28  0x109f8485a WebCore::SubresourceLoader::didFinishLoading(WebCore::NetworkLoadMetrics const&)
29  0x109ddadd2 WebCore::ResourceLoader::didFinishLoading(WebCore::ResourceHandle*)
30  0x7fff9634a4a5 __65-[NSURLConnectionInternal _withConnectionAndDelegate:onlyActive:]_block_invoke
31  0x7fff9634a3ba -[NSURLConnectionInternal _withConnectionAndDelegate:onlyActive:]

[Antoine Quint]

I can finally reproduce this issue, or at least one reason it occurs:

OpenSource > Tools/Scripts/run-webkit-tests --no-retry --no-sample-on-timeout --time-out-ms=5000 --release -1 --child-processes=1 --verbose fast/events/page-visibility-transition-test.html media/modern-media-controls/airplay-button/airplay-button-on.html

[Chris Dumez]

(In reply to Antoine Quint from comment #2)
> I can finally reproduce this issue, or at least one reason it occurs:
> 
> OpenSource > Tools/Scripts/run-webkit-tests --no-retry
> --no-sample-on-timeout --time-out-ms=5000 --release -1 --child-processes=1
> --verbose fast/events/page-visibility-transition-test.html
> media/modern-media-controls/airplay-button/airplay-button-on.html

Interestingly, document.hidden return false when running the second test. So it *is* visible but somehow scripted animations are still suspended.

[Chris Dumez]

Created attachment 313693 [details]
Patch

[Chris Dumez]

Found the bug!

[WebKit Commit Bot]

Comment on attachment 313693 [details]
Patch

Clearing flags on attachment: 313693

Committed r218747: <http://trac.webkit.org/changeset/218747>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Antoine Quint]

We're removing the logging code we added to diagnose this issue in https://bugs.webkit.org/show_bug.cgi?id=173821.