96862 2012-09-15 08:10:23 -0700 [WK2] REGRESSION(r128623): It made layout tests extremely slow 2012-10-24 11:35:33 -0700 1 1 1 Unclassified WebKit New Bugs 528+ (Nightly build) All All RESOLVED FIXED Qt, QtTriaged P1 Blocker --- 57570 96861 1 ossy ossy cdumez hausmann jbadics kbalazs kenneth lauro.neto noam ossy zan oldest_to_newest 721439 0 ossy 2012-09-15 08:10:23 -0700 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 722693 1 ossy 2012-09-18 05:32:44 -0700 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? 722707 2 cdumez 2012-09-18 05:55:55 -0700 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. 727505 3 ossy 2012-09-25 04:29:44 -0700 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. 727513 4 cdumez 2012-09-25 04:45:37 -0700 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. 727885 5 lauro.neto 2012-09-25 12:47:25 -0700 (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. 729302 6 zan 2012-09-27 01:12:33 -0700 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. 729345 7 zan 2012-09-27 02:29:15 -0700 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 729430 8 zan 2012-09-27 04:52:50 -0700 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? 729443 9 cdumez 2012-09-27 05:36:17 -0700 (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. 729469 10 lauro.neto 2012-09-27 06:22:13 -0700 (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. 729674 11 zan 2012-09-27 10:29:36 -0700 (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 731475 12 kbalazs 2012-10-01 01:38:55 -0700 > 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? 731490 13 zan 2012-10-01 01:56:57 -0700 (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. 731494 14 kbalazs 2012-10-01 02:02:19 -0700 (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. 732603 15 166682 ossy 2012-10-02 06:21:30 -0700 Created attachment 166682 workaround We should disable calling WKBundleSetDatabaseQuota() between tests until proper fix. This slowdown made testing impossible, it is absolutely unacceptable. 732605 16 166682 hausmann 2012-10-02 06:25:20 -0700 Comment on attachment 166682 workaround Agreed. The slowdown is massive and in other circumstances the patch that causes it would've been rolled out. 732606 17 kbalazs 2012-10-02 06:25:44 -0700 (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. 732608 18 166682 ossy 2012-10-02 06:29:54 -0700 Comment on attachment 166682 workaround Clearing flags on attachment: 166682 Committed r130163: <http://trac.webkit.org/changeset/130163> 732655 19 zan 2012-10-02 08:08:11 -0700 (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. 749870 20 zan 2012-10-24 11:35:33 -0700 (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. 166682 2012-10-02 06:21:30 -0700 2012-10-02 06:29:54 -0700 workaround bug-96862-20121002062042.patch text/plain 1622 ossy U3VidmVyc2lvbiBSZXZpc2lvbjogMTMwMTUzCmRpZmYgLS1naXQgYS9Ub29scy9DaGFuZ2VMb2cg Yi9Ub29scy9DaGFuZ2VMb2cKaW5kZXggMWJiMjA5Zjk4Y2VkNjUyYjdhNjRjZjIzMWI3YjY3M2Y1 NmYwYjllMC4uMmE0MzgxYmJiYTI1ODkwODRkMTExMzQyMzIzNTA2YWM0NzUyNmU4YyAxMDA2NDQK LS0tIGEvVG9vbHMvQ2hhbmdlTG9nCisrKyBiL1Rvb2xzL0NoYW5nZUxvZwpAQCAtMSwzICsxLDE1 IEBACisyMDEyLTEwLTAyICBDc2FiYSBPc3p0cm9nb27DoWMgIDxvc3N5QHdlYmtpdC5vcmc+CisK KyAgICAgICAgW1dLMl0gUkVHUkVTU0lPTihyMTI4NjIzKTogSXQgbWFkZSBsYXlvdXQgdGVzdHMg ZXh0cmVtZWx5IHNsb3cKKyAgICAgICAgaHR0cHM6Ly9idWdzLndlYmtpdC5vcmcvc2hvd19idWcu Y2dpP2lkPTk2ODYyCisKKyAgICAgICAgUmV2aWV3ZWQgYnkgTk9CT0RZIChPT1BTISkuCisKKyAg ICAgICAgRGlzYWJsZSBjYWxsaW5nIHRoZSBleHRyZW1lbHkgc2xvdyBXS0J1bmRsZVNldERhdGFi YXNlUXVvdGEoKSBiZXR3ZWVuIHRlc3RzIHVudGlsIHByb3BlciBmaXguCisKKyAgICAgICAgKiBX ZWJLaXRUZXN0UnVubmVyL0luamVjdGVkQnVuZGxlL0luamVjdGVkQnVuZGxlLmNwcDoKKyAgICAg ICAgKFdUUjo6SW5qZWN0ZWRCdW5kbGU6OmJlZ2luVGVzdGluZyk6CisKIDIwMTItMTAtMDIgIFBo aWxpcCBSb2dlcnMgIDxwZHJAZ29vZ2xlLmNvbT4KIAogICAgICAgICBGaXggUGVyZlRlc3Qgc3Rh bmRhcmQgZGV2aWF0aW9uIGNhbGN1bGF0aW9uLgpkaWZmIC0tZ2l0IGEvVG9vbHMvV2ViS2l0VGVz dFJ1bm5lci9JbmplY3RlZEJ1bmRsZS9JbmplY3RlZEJ1bmRsZS5jcHAgYi9Ub29scy9XZWJLaXRU ZXN0UnVubmVyL0luamVjdGVkQnVuZGxlL0luamVjdGVkQnVuZGxlLmNwcAppbmRleCAxMzc2NWMw ZmYwYWM0NTIwNzFjMjRiZmQ2NmQ2OTdjOWNjMzIxNWI3Li5mMmIxNzRkYjkwNzIzYmFiMWM2NmVh NWM3N2M0MWQzYzgwNWZiOTViIDEwMDY0NAotLS0gYS9Ub29scy9XZWJLaXRUZXN0UnVubmVyL0lu amVjdGVkQnVuZGxlL0luamVjdGVkQnVuZGxlLmNwcAorKysgYi9Ub29scy9XZWJLaXRUZXN0UnVu bmVyL0luamVjdGVkQnVuZGxlL0luamVjdGVkQnVuZGxlLmNwcApAQCAtMjYwLDcgKzI2MCwxMCBA QCB2b2lkIEluamVjdGVkQnVuZGxlOjpiZWdpblRlc3RpbmcoV0tEaWN0aW9uYXJ5UmVmIHNldHRp bmdzKQogICAgIFdLQnVuZGxlQ2xlYXJBbGxEYXRhYmFzZXMobV9idW5kbGUpOwogICAgIFdLQnVu ZGxlQ2xlYXJBcHBsaWNhdGlvbkNhY2hlKG1fYnVuZGxlKTsKICAgICBXS0J1bmRsZVJlc2V0T3Jp Z2luQWNjZXNzV2hpdGVsaXN0cyhtX2J1bmRsZSk7Ci0gICAgV0tCdW5kbGVTZXREYXRhYmFzZVF1 b3RhKG1fYnVuZGxlLCA1ICogMTAyNCAqIDEwMjQpOworCisgICAgLy8gW1dLMl0gUkVHUkVTU0lP TihyMTI4NjIzKTogSXQgbWFkZSBsYXlvdXQgdGVzdHMgZXh0cmVtZWx5IHNsb3cKKyAgICAvLyBo dHRwczovL2J1Z3Mud2Via2l0Lm9yZy9zaG93X2J1Zy5jZ2k/aWQ9OTY4NjIKKyAgICAvLyBXS0J1 bmRsZVNldERhdGFiYXNlUXVvdGEobV9idW5kbGUsIDUgKiAxMDI0ICogMTAyNCk7CiB9CiAKIHZv aWQgSW5qZWN0ZWRCdW5kbGU6OmRvbmUoKQo=