147718 – Running tests for a long time results in some tests running very slowly (throttling)

Bug 147718 - Running tests for a long time results in some tests running very slowly (throttling)

Summary: Running tests for a long time results in some tests running very slowly (thro...

Status:	RESOLVED FIXED

Alias:	None

Product:	WebKit
Classification:	Unclassified
Component:	Tools / Tests (show other bugs)
Version:	528+ (Nightly build)
Hardware:	All All

Importance:	P2 Normal
Assignee:	Joseph Pecoraro

URL:
Keywords:

Depends on:
Blocks:

Reported:	2015-08-05 19:17 PDT by Joseph Pecoraro
Modified:	2015-08-07 11:12 PDT (History)
CC List:	6 users (show)

See Also:

Attachments
[PATCH] Proposed Fix (1.42 KB, patch) 2015-08-05 19:18 PDT, Joseph Pecoraro	ap: review+	Details \| Formatted Diff \| Diff
View All Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.

Description Joseph Pecoraro 2015-08-05 19:17:17 PDT

* SUMMARY
Running tests for a very long time results in some tests running very slowly.

* STEPS TO REPRODUCE
shell> run-webkit-tests inspector/dom --iterations=1000 --v
shell> run-webkit-tests fast/editing/selection --iterations=100 --v
  => after 1000-3000 successes, some tests start taking a very long time instead of being almost instant

* NOTES
- The common thread seems to be tests with a setTimeout take much longer.
- Suspected DOM Timer Throttling, disabling throttling solved the problem, did not investigate exactly why throttling was kicking in

Comment 1 Joseph Pecoraro 2015-08-05 19:18:51 PDT

Created attachment 258338 [details]
[PATCH] Proposed Fix

Comment 2 Chris Dumez 2015-08-05 19:49:39 PDT

Comment on attachment 258338 [details]
[PATCH] Proposed Fix

Looks good but what about wk1?

Comment 3 Alexey Proskuryakov 2015-08-05 20:27:29 PDT

Comment on attachment 258338 [details]
[PATCH] Proposed Fix

We shouldn't have runaway throttling, however how does it get triggered?

Comment 4 Joseph Pecoraro 2015-08-06 12:58:17 PDT

Putting in some logging, I was able to detect the UIProcess updated view state after 5 and 6 minutes, in the second case the window was no longer Active, the view state ended up being only ViewState::IsVisuallyIdle, and throttling got enabled:

    Aug  6 12:16:11 WebKitTestRunner[26393] <Warning>: >>> WebPageProxy::updateViewState
    Aug  6 12:16:11 WebKitTestRunner[26393] <Notice>: 1   0x103f22777 WebKit::WebPageProxy::dispatchViewStateChange()
    Aug  6 12:16:11 WebKitTestRunner[26393] <Notice>: 2   0x7fff96e86127 __CFRUNLOOP_IS_CALLING_OUT_TO_AN_OBSERVER_CALLBACK_FUNCTION__
    Aug  6 12:16:11 WebKitTestRunner[26393] <Notice>: 3   0x7fff96e86080 __CFRunLoopDoObservers
    Aug  6 12:16:11 WebKitTestRunner[26393] <Notice>: 4   0x7fff96e77bf8 CFRunLoopRunSpecific
    Aug  6 12:16:11 WebKitTestRunner[26393] <Notice>: 5   0x7fff8a078b29 -[NSRunLoop(NSRunLoop) runMode:beforeDate:]
    Aug  6 12:16:11 WebKitTestRunner[26393] <Notice>: 6   0x1032a11d9 WTR::TestController::platformRunUntil(bool&, double)
    Aug  6 12:16:11 WebKitTestRunner[26393] <Notice>: 7   0x1032a1d5a WTR::TestInvocation::invoke()
    Aug  6 12:16:11 WebKitTestRunner[26393] <Notice>: 8   0x10329d943 WTR::TestController::runTest(char const*)
    Aug  6 12:16:11 WebKitTestRunner[26393] <Notice>: 9   0x10329d9fa WTR::TestController::runTestingServerLoop()
    Aug  6 12:16:11 WebKitTestRunner[26393] <Notice>: 10  0x10329af01 WTR::TestController::TestController(int, char const**)
    Aug  6 12:16:11 WebKitTestRunner[26393] <Notice>: 11  0x103299212 main
    Aug  6 12:16:11 WebKitTestRunner[26393] <Notice>: 12  0x7fff8c3ca5c9 start
    Aug  6 12:16:11 WebKitTestRunner[26393] <Warning>: >>> ViewState::IsVisuallyIdle

    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Warning>: >>>>>>> Page::setTimerThrottlingEnabled(true)
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 1   0x10eb0ef67 WebCore::Page::setViewState(unsigned int)
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 2   0x10ca0f7ff WebKit::WebPage::setViewState(unsigned int, bool, WTF::Vector<unsigned long long, 0ul, WTF::CrashOnOverflow, 16ul> const&)
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 3   0x10ca2e68e void IPC::handleMessage<Messages::WebPage::SetViewState, WebKit::WebPage, void (WebKit::WebPage::*)(unsigned int, bool, WTF::Vector<unsigned long long, 0ul, WTF::CrashOnOverflow, 16ul> const&)>(IPC::MessageDecoder&, WebKit::WebPage*, void (WebKit::WebPage::*)(unsigned int, bool, WTF::Vector<unsigned long long, 0ul, WTF::CrashOnOverflow, 16ul> const&))
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 4   0x10ca2b31f WebKit::WebPage::didReceiveWebPageMessage(IPC::Connection&, IPC::MessageDecoder&)
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 5   0x10c8c30b0 IPC::MessageReceiverMap::dispatchMessage(IPC::Connection&, IPC::MessageDecoder&)
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 6   0x10ca7d048 WebKit::WebProcess::didReceiveMessage(IPC::Connection&, IPC::MessageDecoder&)
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 7   0x10c87c36c IPC::Connection::dispatchMessage(std::__1::unique_ptr<IPC::MessageDecoder, std::__1::default_delete<IPC::MessageDecoder> >)
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 8   0x10c87e86e IPC::Connection::dispatchOneMessage()
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 9   0x10dc843dd WTF::RunLoop::performWork()
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 10  0x10dc84af2 WTF::RunLoop::performWork(void*)
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 11  0x7fff96e86a01 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 12  0x7fff96e78b8d __CFRunLoopDoSources0
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 13  0x7fff96e781bf __CFRunLoopRun
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 14  0x7fff96e77bd8 CFRunLoopRunSpecific
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 15  0x7fff8893256f RunCurrentEventLoopInMode
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 16  0x7fff889322ea ReceiveNextEventCommon
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 17  0x7fff8893212b _BlockUntilNextEventMatchingListInModeWithFilter
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 18  0x7fff892488ab _DPSNextEvent
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 19  0x7fff89247e58 -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 20  0x7fff8923daf3 -[NSApplication run]
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 21  0x7fff891ba244 NSApplicationMain
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 22  0x7fff964ab928 _xpc_objc_main
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 23  0x7fff964ad030 _parse_sysctl_once
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 24  0x105140675 WebKit::XPCServiceEventHandler(NSObject<OS_xpc_object>*)
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 25  0x7fff8c3ca5c9 start
    Aug  6 12:16:11 com.apple.WebKit.WebContent.Development[26398] <Notice>: 26  0x1

Going to try to see if I can find the root cause of the ViewState change, since it seems to update asynchronously by scheduling a run loop observer.

Comment 5 Alexey Proskuryakov 2015-08-06 17:51:59 PDT

Comment on attachment 258338 [details]
[PATCH] Proposed Fix

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

> Tools/ChangeLog:10
> +        Ensure Throttling is disabled for tests for all ports, as COCOA ports

This is slightly misleading, as some timer throttling remains enabled. Nested DOM timers will still be throttled (under certain conditions that are unrelated to page visibility).

Comment 6 Joseph Pecoraro 2015-08-06 17:55:33 PDT

Tracked this down to the root cause.

A WindowServerConnection state change windowServerConnectionStateChanged() notifies of that we will no longer receive window updates:

    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> WebPageProxy::viewStateDidChange - suppressing?(false) 32
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 1   0x10c75b992 WebKit::WebProcessProxy::windowServerConnectionStateChanged()
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 2   0x10c74e635 WebKit::WebProcessPool::windowServerConnectionStateChanged()
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 3   0x10c7785c4 WebKit::WindowServerConnection::windowServerConnectionStateChanged()
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 4   0x7fff8a612359 CGSConnectionNotifier::invoke_callbacks(unsigned int, void*, unsigned long) const
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 5   0x7fff8a612098 (anonymous namespace)::notify_datagram_handler(unsigned int, CGSDatagramType, void*, unsigned long, void*)
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 6   0x7fff8a5ef9b9 CGSDatagramReadStream::dispatch_next_datagram()
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 7   0x7fff8a5ef69e CGSDatagramReadStream::dispatch_datagrams()
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 8   0x7fff8a5ef4b3 CGSDatagramReadStreamDispatchDatagramsWithData
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 9   0x7fff8a5ef13b CGSSnarfAndDispatchDatagrams
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 10  0x7fff8a5eee8c CGSGetNextEventRecordInternal
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 11  0x7fff8a5eedd7 CGEventCreateNextEvent
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 12  0x7fff8893a75c PullEventsFromWindowServerOnConnection(unsigned int, unsigned char, __CFMachPortBoost*)
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 13  0x7fff8893a6c3 MessageHandler(__CFMachPort*, void*, long, void*)
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 14  0x7fff96e86d87 __CFMachPortPerform
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 15  0x7fff96e86c79 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE1_PERFORM_FUNCTION__
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 16  0x7fff96e86beb __CFRunLoopDoSource1
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 17  0x7fff96e78767 __CFRunLoopRun
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 18  0x7fff96e77bd8 CFRunLoopRunSpecific
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 19  0x7fff8a078b29 -[NSRunLoop(NSRunLoop) runMode:beforeDate:]
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 20  0x10ba781d9 WTR::TestController::platformRunUntil(bool&, double)
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 21  0x10ba78d9f WTR::TestInvocation::invoke()
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 22  0x10ba74943 WTR::TestController::runTest(char const*)
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 23  0x10ba749fa WTR::TestController::runTestingServerLoop()
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 24  0x10ba71f01 WTR::TestController::TestController(int, char const**)
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 25  0x10ba70212 main
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 26  0x7fff8c3ca5c9 start

We then set the ViewState to VisuallyIdle, which enables throttling.

    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> WebPageProxy::updateViewState
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 1   0x10c6f86ab WebKit::WebPageProxy::dispatchViewStateChange()
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 2   0x7fff96e86127 __CFRUNLOOP_IS_CALLING_OUT_TO_AN_OBSERVER_CALLBACK_FUNCTION__
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 3   0x7fff96e86080 __CFRunLoopDoObservers
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 4   0x7fff96e77bf8 CFRunLoopRunSpecific
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 5   0x7fff8a078b29 -[NSRunLoop(NSRunLoop) runMode:beforeDate:]
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 6   0x10ba781d9 WTR::TestController::platformRunUntil(bool&, double)
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 7   0x10ba78d9f WTR::TestInvocation::invoke()
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 8   0x10ba74943 WTR::TestController::runTest(char const*)
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 9   0x10ba749fa WTR::TestController::runTestingServerLoop()
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 10  0x10ba71f01 WTR::TestController::TestController(int, char const**)
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 11  0x10ba70212 main
    Aug  6 16:11:11 WebKitTestRunner[39786] <Notice>: 12  0x7fff8c3ca5c9 start
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> flagsToUpdate:
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> ViewState::IsVisuallyIdle
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> m_viewState BEFORE:
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> ViewState::IsFocused
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> ViewState::WindowIsActive
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> ViewState::IsVisible
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> ViewState::IsVisibleOrOccluded
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> ViewState::IsInWindow
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> m_viewState AFTER:
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> ViewState::IsFocused
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> ViewState::WindowIsActive
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> ViewState::IsVisible
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> ViewState::IsVisibleOrOccluded
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> ViewState::IsInWindow
    Aug  6 16:11:11 WebKitTestRunner[39786] <Warning>: >>> ViewState::IsVisuallyIdle

Currently solution is to just disable throttling in tests, and have tests that want it enable it.

An alternative solution would be to add WK SPI to turn off / override WebKit::WindowServerConnection's behavior.

Comment 7 Joseph Pecoraro 2015-08-06 18:23:01 PDT

http://trac.webkit.org/changeset/188102

Comment 8 Joseph Pecoraro 2015-08-07 11:12:37 PDT

Follow-up to address Chris' comment, and do the same in WebKit1's Test Harness, for consistency:
http://trac.webkit.org/changeset/188139