Bug 173628 - [mac-wk1] requestAnimationFrame callbacks may not get serviced
Summary: [mac-wk1] requestAnimationFrame callbacks may not get serviced
Alias: None
Product: WebKit
Classification: Unclassified
Component: Tools / Tests (show other bugs)
Version: WebKit Nightly Build
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Chris Dumez
Depends on:
Reported: 2017-06-20 17:27 PDT by Antoine Quint
Modified: 2017-06-25 01:09 PDT (History)
11 users (show)

See Also:

Patch (8.14 KB, patch)
2017-06-22 23:42 PDT, Chris Dumez
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Antoine Quint 2017-06-20 17:27:31 PDT
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.
Comment 1 Antoine Quint 2017-06-22 21:36:01 PDT
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:]
Comment 2 Antoine Quint 2017-06-22 22:18:38 PDT
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
Comment 3 Chris Dumez 2017-06-22 22:32:36 PDT
(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.
Comment 4 Chris Dumez 2017-06-22 23:42:58 PDT
Created attachment 313693 [details]
Comment 5 Chris Dumez 2017-06-22 23:43:33 PDT
Found the bug!
Comment 6 WebKit Commit Bot 2017-06-23 08:44:33 PDT
Comment on attachment 313693 [details]

Clearing flags on attachment: 313693

Committed r218747: <http://trac.webkit.org/changeset/218747>
Comment 7 WebKit Commit Bot 2017-06-23 08:44:35 PDT
All reviewed patches have been landed.  Closing bug.
Comment 8 Antoine Quint 2017-06-25 01:09:32 PDT
We're removing the logging code we added to diagnose this issue in https://bugs.webkit.org/show_bug.cgi?id=173821.