Bug 147718

Summary:

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

Product:

WebKit

Reporter:

Joseph Pecoraro <joepeck>

Component:

Tools / Tests

Assignee:

Joseph Pecoraro <joepeck>

Status:

RESOLVED FIXED

Severity:

Normal

CC:

ap, barraclough, cdumez, joepeck, rniwa, simon.fraser

Priority:

Version:

528+ (Nightly build)

Hardware:

All

OS:

All

Attachments:

Description	Flags
[PATCH] Proposed Fix	ap: review+

Joseph Pecoraro

Reported 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

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 attachment proposed patch, testcase, etc.

Joseph Pecoraro

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

Created attachment 258338 [details] [PATCH] Proposed Fix

Chris Dumez

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

Comment on attachment 258338 [details] [PATCH] Proposed Fix Looks good but what about wk1?

Alexey Proskuryakov

Comment 3 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?

Joseph Pecoraro

Comment 4 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.

Alexey Proskuryakov

Comment 5 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).

Joseph Pecoraro

Comment 6 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.

Joseph Pecoraro

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

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

Joseph Pecoraro

Comment 8 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

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