Bug 70699 – [WK2][GTK] Each test takes roughly half a second to load

• Component: Tools / Tests
• Status: RESOLVED FIXED

[Zan Dobersek]

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

[Martin Robinson]

CCing the WebKit2 developers involved in https://bugs.webkit.org/show_bug.cgi?id=62496

[Zan Dobersek]

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

[Martin Robinson]

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.

[Zan Dobersek]

(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

[Martin Robinson]

(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?

[Zan Dobersek]

Created attachment 121460 [details]
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.

[WebKit Review Bot]

Comment on attachment 121460 [details]
Patch

Clearing flags on attachment: 121460

Committed r104387: <http://trac.webkit.org/changeset/104387>

[WebKit Review Bot]

All reviewed patches have been landed.  Closing bug.