Bug 96862 – [WK2] REGRESSION(r128623): It made layout tests extremely slow

• Component: New Bugs
• Status: RESOLVED FIXED

[Csaba Osztrogonác]

runtime on Ubuntu 11.10:
-------------------------
- before r128623: 23.5 minutes - http://build.webkit.sed.hu/builders/x86-64%20Linux%20Qt%20Release%20WebKit2%20%28Amazon%20EC2%29/builds/8815
- after r128623: 43.5 minutes - http://build.webkit.sed.hu/builders/x86-64%20Linux%20Qt%20Release%20WebKit2%20%28Amazon%20EC2%29/builds/8816

runtime on Debian Squeeze:
---------------------------
- before r128623: 31 minutes - http://build.webkit.sed.hu/builders/x86-32%20Linux%20Qt%20Release%20WebKit2/builds/28827
- after r128623: 201 minutes - http://build.webkit.sed.hu/builders/x86-32%20Linux%20Qt%20Release%20WebKit2/builds/28829

This bug might be related to https://bugs.webkit.org/show_bug.cgi?id=96861

[Csaba Osztrogonác]

Christophe, Kenneth, have you got any idea how to fix this bug?
This huge runtime regression isn't so good to catch regression ...
Is it possible if there is performance regressions on real sites too?

[Chris Dumez]

I guess it could be caused by the new call to WKBundleSetDatabaseQuota(m_bundle, 5 * 1024 * 1024); before each test. I'll try to remove it and see how much impact it has.

I don't think the patch can impact performance of real sites though, it is really WebkitTestRunner specific.

[Csaba Osztrogonác]

Is there any progress with fixing it? This bug is P1/blocker, it is
so painful for us, because running layout tests takes long long time.
3.5 hours runtime is absolutely unacceptable to make 2 more tests pass.

[Chris Dumez]

Ossy would you be able to remove WKBundleSetDatabaseQuota(m_bundle, 5 * 1024 * 1024); in WebKitTestRunner and see if it helps for you?

This is the only thing that could make things slower, however, it does not have any impact on the 2 machines I tested.

Since I cannot reproduce the slowliness, it is difficult for me to fix.

[Lauro Moura Maranhao Neto]

(In reply to comment #4)
> Ossy would you be able to remove WKBundleSetDatabaseQuota(m_bundle, 5 * 1024 * 1024); in WebKitTestRunner and see if it helps for you?
> 
> This is the only thing that could make things slower, however, it does not have any impact on the 2 machines I tested.
> 
> Since I cannot reproduce the slowliness, it is difficult for me to fix.

Testing locally I had the following results running fast/dom (almost 1000 tests):

With WKBundleSetDatabaseQuota: 23s.
Without WKBundleSetDatabaseQuota: 9m7s.

Ubuntu 11.10 / 8-core Core i7 / 16GB / QtWebKit Release 64bits.

[Zan Dobersek]

I'm hitting the same issue locally on a GTK WK2 build. I can also confirm that WKBundleSetDatabaseQuota call is the bottleneck. It's an interesting issue, it's not occurring on the GTK WK2 builder so there's a possibility that a specific SQLite version is to blame.

OTOH, in DumpRenderTree, at least for the GTK and Qt ports, the database quota is only reset if the quota is exceeded. Here it's being reset before every test. That's somewhat strange but since there are environments currently not hitting the slow test execution I'd investigate the problem behind the slowness rather than remove the WKBundleSetDatabaseQuota call.

[Zan Dobersek]

Well, here's the breakdown of what's slow (nothing surprising):
In DatabaseTracker::setQuota:
- opening the database[1] takes around 0.38 seconds
- inserting the origin into the database[2] takes around 0.18 seconds
- the whole method is executed in around 0.5 seconds (too long!)

In DatabaseTracker::openTrackerDatabase[3], the two biggest time consumers are:
- Origins table creation, takes around 0.18 seconds
- Databases table creation, takes around 0.2 seconds

In SQLiteStatement::executeCommand[4] when creating the Databases table:
- the step()[5] call takes most of the time

Just to note, I'm running the tests on Ubuntu 12.10 and the problems are occurring with both SQLite 3.7.13 and 3.7.14. Interestingly the GTK WK2 builder is running Debian, either testing or unstable distribution, but in any case SQLite 3.7.13 or 3.7.14 would be used[n], so the problem is probably not originating directly from SQLite.

[1] http://trac.webkit.org/browser/trunk/Source/WebCore/Modules/webdatabase/DatabaseTracker.cpp#L665
[2] http://trac.webkit.org/browser/trunk/Source/WebCore/Modules/webdatabase/DatabaseTracker.cpp#L670
[3] http://trac.webkit.org/browser/trunk/Source/WebCore/Modules/webdatabase/DatabaseTracker.cpp#L106
[4] http://trac.webkit.org/browser/trunk/Source/WebCore/platform/sql/SQLiteStatement.cpp#L136
[5] http://trac.webkit.org/browser/trunk/Source/WebCore/platform/sql/SQLiteStatement.cpp#L95
[n] http://packages.debian.org/search?keywords=sqlite3&searchon=names&suite=all&section=all

[Zan Dobersek]

Reinspecting the strace output showed that the bottleneck seems to be the fsync call. For instance, in one measurement DatabaseTracker::setQuota completed in 0.565244 seconds, during that time 12 calls to fsync were made. In average the fsync call took 0.045393 seconds which means that 0.544713 seconds were spent in fsync, which represents 96.37% of the complete DatabaseTracker::setQuota execution time.

I'm starting to wonder if the filesystems can be at blame here. Philippe notified me that the GTK builders are using UFS. I, for instance, am using ext4 on two different systems and the slowness is occurring on both of them. Can other people chip in on what OS and filesystem they are running into this problem?

[Chris Dumez]

(In reply to comment #8)
> Reinspecting the strace output showed that the bottleneck seems to be the fsync call. For instance, in one measurement DatabaseTracker::setQuota completed in 0.565244 seconds, during that time 12 calls to fsync were made. In average the fsync call took 0.045393 seconds which means that 0.544713 seconds were spent in fsync, which represents 96.37% of the complete DatabaseTracker::setQuota execution time.
> 
> I'm starting to wonder if the filesystems can be at blame here. Philippe notified me that the GTK builders are using UFS. I, for instance, am using ext4 on two different systems and the slowness is occurring on both of them. Can other people chip in on what OS and filesystem they are running into this problem?

Yes, synchronous writes are much slower on ext4 with write barriers enabled, due to fsync calls. I personally disable barriers on my ext4 file system so this is not surprising I could not reproduce.

I don't know what we can do besides reducing the number of such synchronous calls. Maybe we should get rid of the WKBundleSetDatabaseQuota() calls between each test.

[Lauro Moura Maranhao Neto]

(In reply to comment #8)
> I'm starting to wonder if the filesystems can be at blame here. Philippe notified me that the GTK builders are using UFS. I, for instance, am using ext4 on two different systems and the slowness is occurring on both of them. Can other people chip in on what OS and filesystem they are running into this problem?

ext4 here.

[Zan Dobersek]

(In reply to comment #9)
> (In reply to comment #8)
> > Reinspecting the strace output showed that the bottleneck seems to be the fsync call. For instance, in one measurement DatabaseTracker::setQuota completed in 0.565244 seconds, during that time 12 calls to fsync were made. In average the fsync call took 0.045393 seconds which means that 0.544713 seconds were spent in fsync, which represents 96.37% of the complete DatabaseTracker::setQuota execution time.
> > 
> > I'm starting to wonder if the filesystems can be at blame here. Philippe notified me that the GTK builders are using UFS. I, for instance, am using ext4 on two different systems and the slowness is occurring on both of them. Can other people chip in on what OS and filesystem they are running into this problem?
> 
> Yes, synchronous writes are much slower on ext4 with write barriers enabled, due to fsync calls. I personally disable barriers on my ext4 file system so this is not surprising I could not reproduce.
> 

Indeed, disabling write barriers does the job, but that's not really an option.

> I don't know what we can do besides reducing the number of such synchronous calls. Maybe we should get rid of the WKBundleSetDatabaseQuota() calls between each test.

How about setting the synchronous pragma to off? It seems to work.
http://www.sqlite.org/pragma.html#pragma_synchronous
http://trac.webkit.org/browser/trunk/Source/WebCore/platform/sql/SQLiteDatabase.cpp#L237

[Balazs Kelemen]

 > I don't know what we can do besides reducing the number of such synchronous calls. Maybe we should get rid of the WKBundleSetDatabaseQuota() calls between each test.

Yes, we should remove it, as now working with tests locally is impossible with a default file system. Is this call necessary between each tests at all?

[Zan Dobersek]

(In reply to comment #12)
>  > I don't know what we can do besides reducing the number of such synchronous calls. Maybe we should get rid of the WKBundleSetDatabaseQuota() calls between each test.
> 
> Yes, we should remove it, as now working with tests locally is impossible with a default file system. Is this call necessary between each tests at all?

To chip in, I don't think it's necessary but in my opinion it's not wrong either.

As said in comment #11, setting the synchronous pragma to off removes the problem, but it currently seems to appear only on Linux. We should get input from other ports' devs and the authors of this particular code about whether setting the synchronous pragma to off is a viable solution and whether it should be done across all ports or just on Linux systems.

[Balazs Kelemen]

(In reply to comment #13)
> (In reply to comment #12)
> >  > I don't know what we can do besides reducing the number of such synchronous calls. Maybe we should get rid of the WKBundleSetDatabaseQuota() calls between each test.
> > 
> > Yes, we should remove it, as now working with tests locally is impossible with a default file system. Is this call necessary between each tests at all?
> 
> To chip in, I don't think it's necessary but in my opinion it's not wrong either.
> 
> As said in comment #11, setting the synchronous pragma to off removes the problem, but it currently seems to appear only on Linux. We should get input from other ports' devs and the authors of this particular code about whether setting the synchronous pragma to off is a viable solution and whether it should be done across all ports or just on Linux systems.

If it's not necessary than we should remove it. Slowing down tests with a magnitude or more on a default linux install for testing one particular feature is not acceptable in my opinion.
Otherwise, if you think our database performance can be improved by removing the synchronous pragma, than let's investigate it it, but that's another story.

[Csaba Osztrogonác]

Created attachment 166682 [details]
workaround

We should disable calling WKBundleSetDatabaseQuota() between tests until proper fix. This slowdown made testing impossible, it is absolutely unacceptable.

[Simon Hausmann]

Comment on attachment 166682 [details]
workaround

Agreed. The slowdown is massive and in other circumstances the patch that causes it would've been rolled out.

[Balazs Kelemen]

(In reply to comment #15)
> Created an attachment (id=166682) [details]
> workaround
> 
> We should disable calling WKBundleSetDatabaseQuota() between tests until proper fix. This slowdown made testing impossible, it is absolutely unacceptable.

In fact this should be the proper fix as nobody stated a reason why the call is necessary.

[Csaba Osztrogonác]

Comment on attachment 166682 [details]
workaround

Clearing flags on attachment: 166682

Committed r130163: <http://trac.webkit.org/changeset/130163>

[Zan Dobersek]

(In reply to comment #17)
> (In reply to comment #15)
> > Created an attachment (id=166682) [details] [details]
> > workaround
> > 
> > We should disable calling WKBundleSetDatabaseQuota() between tests until proper fix. This slowdown made testing impossible, it is absolutely unacceptable.
> 
> In fact this should be the proper fix as nobody stated a reason why the call is necessary.

Let's close this bug then. I'll open a new bug about setting the synchronous pragma to off for SQLite databases and then probably raise the issue on the mailing list as well.

[Zan Dobersek]

(In reply to comment #19)
> (In reply to comment #17)
> > (In reply to comment #15)
> > > Created an attachment (id=166682) [details] [details] [details]
> > > workaround
> > > 
> > > We should disable calling WKBundleSetDatabaseQuota() between tests until proper fix. This slowdown made testing impossible, it is absolutely unacceptable.
> > 
> > In fact this should be the proper fix as nobody stated a reason why the call is necessary.
> 
> Let's close this bug then. I'll open a new bug about setting the synchronous pragma to off for SQLite databases and then probably raise the issue on the mailing list as well.

FWIW, I opened bug #100274.