70699 2011-10-23 10:38:29 -0700 [WK2][GTK] Each test takes roughly half a second to load 2012-01-07 09:46:27 -0800 1 1 1 Unclassified WebKit Tools / Tests 528+ (Nightly build) Unspecified Unspecified RESOLVED FIXED P2 Normal --- 69523 0 zan webkit-unassigned abarth andersca mrobinson ojan sam webkit.review.bot oldest_to_newest 489037 0 zan 2011-10-23 10:38:29 -0700 When running layout tests for WebKit2, the testing takes considerably longer than when testing for WebKit1. This occurs when running the tests through either ORWT or NRWT. The problem is that the simple loading of the test file takes 400-600 milliseconds. The loading call is done in TestInvocation::invoke()[1]. I've then traced the problem deep into WebKit2. All the excess time is wasted between when sending the LoadURL message between WebPageProxy::loadURL()[2] in UIProcess and WebPage::loadURL()[3]. Digging deeper, the problem seems to occur when a new message is enqueued and work is scheduled on the run loop in Connection::enqueueIncomingMessage()[4]. But the callback of the source that this call creates and appends to the main context doesn't get called any time soon, even stranger, the messages are still dispatched by a Connection::dispatchMessages function that is still in progress. I've then put a static counter outside Connection::dispatchMessages and increased it when it was called. When a message was dispatched in this function, I printed it out. I've then ran 69 tests with some tests ensured to fail. (By the way, these tests take ~30 seconds with WKTR and ~7 seconds with DRT.) The output showed that in the seventh test of those 69 (first to fail), the last call to Connection::dispatchMessages before WebPageProxy::loadURL was called was the 392th call since the start of testing. The call to Connection::dispatchMessages that (about half a second later) actually dispatched the LoadURL message was only 68th. I thought that was strange and hit the ChangeLogs with some grepping, and found bug #62496. Reverting changes made in that commit (r88588), there were some minor changes in behavior - the call to RunLoop::scheduleWork now properly set up the source, which later triggered the callback to Connection::dispatchMessages. While this seemed to be an improvement, the time difference between RunLoop::scheduleWork and Connection::dispatchMessages was still those 400-600 milliseconds. This seems to be the problem, suggestions/fix warmly welcome! [1] http://trac.webkit.org/browser/trunk/Tools/WebKitTestRunner/TestInvocation.cpp#L153 [2] http://trac.webkit.org/browser/trunk/Source/WebKit2/UIProcess/WebPageProxy.cpp#L433 [3] http://trac.webkit.org/browser/trunk/Source/WebKit2/WebProcess/WebPage/WebPage.cpp#L530 [4] http://trac.webkit.org/browser/trunk/Source/WebKit2/Platform/CoreIPC/Connection.cpp#L666 489044 1 mrobinson 2011-10-23 11:37:01 -0700 CCing the WebKit2 developers involved in https://bugs.webkit.org/show_bug.cgi?id=62496 528352 2 zan 2012-01-01 09:30:29 -0800 So, I've taken some time to further investigate this bug, and I'm glad that time did not go to waste. I used strace on WebKitTestRunner to see what exactly is going on during that 400-500 milliseconds that are wasted upon each load. The trace showed that the LoadURL message is enqueued and dispatched properly and that those milliseconds are not wasted here as I previously assumed. This meant that the LoadURL message was successfully transmitted to WebProcess and that I should investigate there, and that the WebKit2 message structure is working fine, so there's no problem there. I attached strace to the WebKitWebProcess and it was soon clear that all the time wasted was due to clearing the application cache. This is not done in the DumpRenderTree for the Gtk port, but is done for the Mac port. In WebKitTestRunner, this is done for every port that utilizes it. The clearing in WebKitTestRunner is actually done in the injected bundle before every test[1]. This call ends up in WebCore, in ApplicationCacheStorage::deleteAllEntries[2], where the sqlite database is emptied and vacuumed. At the start, my ApplicationCache.db file in ~/.cache/webkitgtk/applications was 28KB in size, so this resulted in about that half a second being wasted on both emptying and vacuuming when the database was populated, but would still take about that half a second just to vacuum an empty database. The Web Dev edition of the HTML5 spec at whatwg.org gives an appcache of about 3.5MB. At the loading of first test with a populated database, it took over 4 seconds to empty and vacuum it, and then again about half a second when the database was empty. The solution could vary - we could simply opt out of cleaning the appcache before each test. A better option would be to provide a clean (as in empty, or rather non-existing) cache for testing purposes that we would point the WebProcess at before any tests. That could be done through an env and some work in NRWT. Or perhaps there's a way to optimize SQLite operations. The mac port does not seem to be affected time-wise by emptying out the cache before each test, but the reason may be that it doesn't exist (yet there's no indication that the mac port deletes the cache before running WKTR). [1] http://trac.webkit.org/browser/trunk/Tools/WebKitTestRunner/InjectedBundle/InjectedBundle.cpp#L211 [2] http://trac.webkit.org/browser/trunk/Source/WebCore/loader/appcache/ApplicationCacheStorage.cpp#L1519 528516 3 mrobinson 2012-01-02 08:21:40 -0800 Nice detective work! Might want to poke Sam or Anders on IRC to confirm that the Mac port isn't doing anything special. It could just be a difference in the version of SQLite that WebKit is using. 530981 4 zan 2012-01-06 01:07:19 -0800 (In reply to comment #3) > Nice detective work! Might want to poke Sam or Anders on IRC to confirm that the Mac port isn't doing anything special. It could just be a difference in the version of SQLite that WebKit is using. I've looked into that and found that the Mac port is indeed setting a different cache directory for testing. For DumpRenderTree, the Mac port sets the WebKitLocalCacheDefaultsKey in user defaults to be pointing to a directory in the temporary directory that is used for testing.[1][2][3][4] This key's value is then set as the cache directory in WebView.mm[5][6] However, while this key is used to provide application cache location for the Mac port in WebKit2[7], it does not seem to be modified in WebKitTestRunner as it is in DumpRenderTree. I'll ask for some clarification on that in #webkit, but currently it seems that we should mimic what Mac port does (in DumpRenderTree). This could be achieved by setting the XDG_CACHE_HOME environment variable, which would then be returned when application cache directory path is built with calling g_get_user_cache_dir. [1] http://trac.webkit.org/browser/trunk/Tools/DumpRenderTree/mac/DumpRenderTree.mm#L532 [2] http://trac.webkit.org/browser/trunk/Tools/DumpRenderTree/mac/DumpRenderTree.mm#L484 [3] http://trac.webkit.org/browser/trunk/Tools/Scripts/webkitpy/layout_tests/port/webkit.py#L489 [4] http://trac.webkit.org/browser/trunk/Tools/Scripts/webkitpy/layout_tests/port/webkit.py#L447 [5] http://trac.webkit.org/browser/trunk/Source/WebKit/mac/WebView/WebView.mm#L592 [6] http://trac.webkit.org/browser/trunk/Source/WebKit/mac/Misc/WebKitNSStringExtras.mm#L330 [7] http://trac.webkit.org/browser/trunk/Source/WebKit2/UIProcess/mac/WebContextMac.mm#L47 531081 5 mrobinson 2012-01-06 08:36:22 -0800 (In reply to comment #4) > However, while this key is used to provide application cache location for the Mac port in WebKit2[7], it does not seem to be modified in WebKitTestRunner as it is in DumpRenderTree. I'll ask for some clarification on that in #webkit, but currently it seems that we should mimic what Mac port does (in DumpRenderTree). This could be achieved by setting the XDG_CACHE_HOME environment variable, which would then be returned when application cache directory path is built with calling g_get_user_cache_dir. Would it be possible to change the cache directory directly instead of changing the parent directly? 531232 6 121460 zan 2012-01-06 12:02:13 -0800 Created attachment 121460 Patch As discussed on IRC with Martin, a temporary solution of setting the XDG_CACHE_HOME env should be used. In future it should be possible to set the desired application cache path through a WebKitWebContext. This might require that a new context must be created by application, hence removing the use of the default shared context. Until then, the workaround should suffice. 531667 7 121460 webkit.review.bot 2012-01-07 09:46:22 -0800 Comment on attachment 121460 Patch Clearing flags on attachment: 121460 Committed r104387: <http://trac.webkit.org/changeset/104387> 531668 8 webkit.review.bot 2012-01-07 09:46:27 -0800 All reviewed patches have been landed. Closing bug. 121460 2012-01-06 12:02:13 -0800 2012-01-07 09:46:22 -0800 Patch p text/plain 2200 zan ZGlmZiAtLWdpdCBhL1Rvb2xzL0NoYW5nZUxvZyBiL1Rvb2xzL0NoYW5nZUxvZwppbmRleCAzZGIx OGM1Li41ZDBkZWE1IDEwMDY0NAotLS0gYS9Ub29scy9DaGFuZ2VMb2cKKysrIGIvVG9vbHMvQ2hh bmdlTG9nCkBAIC0xLDMgKzEsMjMgQEAKKzIwMTItMDEtMDYgIFphbiBEb2JlcnNlayAgPHphbmRv YmVyc2VrQGdtYWlsLmNvbT4KKworICAgICAgICBbV0syXVtHVEtdIEVhY2ggdGVzdCB0YWtlcyBy b3VnaGx5IGhhbGYgYSBzZWNvbmQgdG8gbG9hZAorICAgICAgICBodHRwczovL2J1Z3Mud2Via2l0 Lm9yZy9zaG93X2J1Zy5jZ2k/aWQ9NzA2OTkKKworICAgICAgICBSZXZpZXdlZCBieSBOT0JPRFkg KE9PUFMhKS4KKworICAgICAgICBTZXQgdGhlIFhER19DQUNIRV9IT01FIGVudmlyb25tZW50IHZh cmlhYmxlIHdoZW4gdGVzdGluZyB3aXRoCisgICAgICAgIFdlYktpdFRlc3RSdW5uZXIuIFRoaXMg d2F5IHRoZSB0ZXN0aW5nIGlzIHN0YXJ0ZWQgd2l0aCBhIG5vbi1leGlzdGluZworICAgICAgICBh cHBsaWNhdGlvbiBjYWNoZS4gSWYgdGhlIGNhY2hlIGV4aXN0cyBhbmQgaXMgbm90IGVtcHR5LCB0 aGUgZW1wdHlpbmcKKyAgICAgICAgYW5kIHZhY3V1bWluZyB0aGF0IGlzIHBlcmZvcm1lZCBiZWZv cmUgZXZlcnkgdGVzdCBjYW4gY29uc3VtZSBhIGxvdCBvZgorICAgICAgICB0aW1lLgorCisgICAg ICAgIFRoaXMgaXMganVzdCBhIHRlbXBvcmFyeSB3b3JrYXJvdW5kIHVudGlsIGl0IGJlY29tZXMg cG9zc2libGUgdG8gc2V0CisgICAgICAgIGEgZGVzaXJlZCBkaXJlY3RvcnkgdG8gYmUgdXNlZCBh cyB0aGUgYXBwbGljYXRpb24gY2FjaGUgbG9jYXRpb24gdGhyb3VnaAorICAgICAgICBXZWJLaXRX ZWJDb250ZXh0LgorCisgICAgICAgICogU2NyaXB0cy93ZWJraXRweS9sYXlvdXRfdGVzdHMvcG9y dC9ndGsucHk6CisgICAgICAgIChHdGtQb3J0LnNldHVwX2Vudmlyb25fZm9yX3NlcnZlcik6CisK IDIwMTItMDEtMDYgIFRvciBBcm5lIFZlc3Riw7ggIDx0b3IuYXJuZS52ZXN0Ym9Abm9raWEuY29t PgogCiAgICAgICAgIFtRdF0gTW92ZSBsaXN0aW5nIG9mIGluY2x1ZGUgcGF0aHMgYW5kIGxpYnMg dG8gcHJpIGZpbGVzIGluIHNvdXJjZXMKZGlmZiAtLWdpdCBhL1Rvb2xzL1NjcmlwdHMvd2Via2l0 cHkvbGF5b3V0X3Rlc3RzL3BvcnQvZ3RrLnB5IGIvVG9vbHMvU2NyaXB0cy93ZWJraXRweS9sYXlv dXRfdGVzdHMvcG9ydC9ndGsucHkKaW5kZXggZDA1ZGRhOS4uM2Y1NjMwNCAxMDA2NDQKLS0tIGEv VG9vbHMvU2NyaXB0cy93ZWJraXRweS9sYXlvdXRfdGVzdHMvcG9ydC9ndGsucHkKKysrIGIvVG9v bHMvU2NyaXB0cy93ZWJraXRweS9sYXlvdXRfdGVzdHMvcG9ydC9ndGsucHkKQEAgLTk0LDYgKzk0 LDExIEBAIGNsYXNzIEd0a1BvcnQoV2ViS2l0UG9ydCk6CiAgICAgICAgIGVudmlyb25tZW50WydU RVNUX1JVTk5FUl9URVNUX1BMVUdJTl9QQVRIJ10gPSBzZWxmLl9idWlsZF9wYXRoKCdUZXN0TmV0 c2NhcGVQbHVnaW4nLCAnLmxpYnMnKQogICAgICAgICBlbnZpcm9ubWVudFsnV0VCS0lUX0lOU1BF Q1RPUl9QQVRIJ10gPSBzZWxmLl9idWlsZF9wYXRoKCdQcm9ncmFtcycsICdyZXNvdXJjZXMnLCAn aW5zcGVjdG9yJykKICAgICAgICAgZW52aXJvbm1lbnRbJ1dFQktJVF9UT1BfTEVWRUwnXSA9IHNl bGYuX2NvbmZpZy53ZWJraXRfYmFzZV9kaXIoKQorICAgICAgICBpZiBzZWxmLmdldF9vcHRpb24o J3dlYmtpdF90ZXN0X3J1bm5lcicpOgorICAgICAgICAgICAgIyBGSVhNRTogVGhpcyBpcyBhIHdv cmthcm91bmQgdG8gZW5zdXJlIHRoYXQgdGVzdGluZyB3aXRoIFdlYktpdFRlc3RSdW5uZXIgaXMg c3RhcnRlZCB3aXRoCisgICAgICAgICAgICAjIGEgbm9uLWV4aXN0aW5nIGNhY2hlLiBUaGlzIHNo b3VsZCBiZSByZW1vdmVkIHdoZW4gKGFuZCBpZikgaXQgd2lsbCBiZSBwb3NzaWJsZSB0byBwcm9w ZXJseQorICAgICAgICAgICAgIyBzZXQgdGhlIGNhY2hlIGRpcmVjdG9yeSBwYXRoIHRocm91Z2gg YSBXZWJLaXRXZWJDb250ZXh0LgorICAgICAgICAgICAgZW52aXJvbm1lbnRbJ1hER19DQUNIRV9I T01FJ10gPSBzZWxmLl9maWxlc3lzdGVtLmpvaW4oc2VsZi5yZXN1bHRzX2RpcmVjdG9yeSgpLCAn YXBwY2FjaGUnKQogICAgICAgICByZXR1cm4gZW52aXJvbm1lbnQKIAogICAgIGRlZiBfZ2VuZXJh dGVfYWxsX3Rlc3RfY29uZmlndXJhdGlvbnMoc2VsZik6Cg==