Bug 65862 – [Chromium] storage/indexeddb tests sometimes timeout

• Status: RESOLVED
• Resolution: WONTFIX
• Component: Layout and Rendering

[Jian Li]

storage/indexeddb/index-cursor.html timeouts on Mac Debug

[Joshua Bell]

Does this still occur? 

I'm fairly sure I know what this was, and it should be fixed now.

[Joshua Bell]

Created attachment 125677 [details]
Patch

[Joshua Bell]

tony@ - r?

[Tony Chang]

FWIW, changes that only touch test_expectations.txt can be landed unreviewed (but make sure to lint the test files!).

[Joshua Bell]

Comment on attachment 125677 [details]
Patch

Thanks!

[WebKit Review Bot]

Comment on attachment 125677 [details]
Patch

Clearing flags on attachment: 125677

Committed r106857: <http://trac.webkit.org/changeset/106857>

[WebKit Review Bot]

All reviewed patches have been landed.  Closing bug.

[Joshua Bell]

This is still timing out:

http://test-results.appspot.com/dashboards/flakiness_dashboard.html#showExpectations=true&tests=storage%2Findexeddb%2Findex-cursor.html

Will re-mark it as TIMEOUT and investigate further.

[Joshua Bell]

Marked as slow again:

BUGWK65862 MAC DEBUG SLOW : storage/indexeddb/index-cursor.html = PASS

From looking at the output, it appears this is truly just a slow test that trips the timeout on the MAC DEBUG combination. It does several iterations over a dataset, but it's not fetching enough data in each test to take advantage of the prefetch cache and the cache isn't saved between runs.

We'll probably have to keep this marked as SLOW until more performance work is done.

[Joshua Bell]

For reference, the re-marking was: http://trac.webkit.org/changeset/106971

[Ojan Vafai]

Turning this into a meta bug for the indexeddb tests being slow. I'm marking them all as slow.

http://test-results.appspot.com/dashboards/flakiness_dashboard.html#tests=storage%2Findexeddb

A large number of them timeout. It sounds like there are some performance problems that will be resolved and then we can unmark them as slow?

[Joshua Bell]

(In reply to comment #11)
> Turning this into a meta bug for the indexeddb tests being slow. I'm marking them all as slow.
> 
> http://test-results.appspot.com/dashboards/flakiness_dashboard.html#tests=storage%2Findexeddb
> 
> A large number of them timeout. It sounds like there are some performance problems that will be resolved and then we can unmark them as slow?

Thanks!

What seems to be common to the layout tests that are timing out (other than the index-cursor, which just does WAY too much work and produces a huge amount of output) is that they open/close multiple database connections. This seems to intermittently take much more time than expected, causing the timeout.

We're not sure at this point if it's something to do with running the tests in DRT or a real problem, and of course the issue disappears the minute we look closely at it.

[Joshua Bell]

Created attachment 166929 [details]
Patch

[Joshua Bell]

ojan@ - r? storage/indexeddb/index-cursor.html ?

(This is obviously not a comprehensive fix, but that particular test is atrocious.)

[Joshua Bell]

(In reply to comment #14)
> ojan@ - r? storage/indexeddb/index-cursor.html ?

That should read:

ojan@ - r? on reducing the output of storage/indexeddb/index-cursor.html ?

[WebKit Review Bot]

Comment on attachment 166929 [details]
Patch

Clearing flags on attachment: 166929

Committed r130334: <http://trac.webkit.org/changeset/130334>

[WebKit Review Bot]

All reviewed patches have been landed.  Closing bug.

[Joshua Bell]

Re-opening, as this has become a tracking bug for general storage/indexeddb test slowness.

[Joshua Bell]

FYI, storage/indexeddb/index-cursor.html run times have dropped from 12s/16s/25s linux-debug/win-debug/mac-debug respectively to 2s/3s/2s. w00t!

[Joshua Bell]

Root cause of the slow tests appears to be a leveldb issue:

http://code.google.com/p/leveldb/issues/detail?id=125

Each open() or deleteDatabase() could take an additional second(!) to execute. The persnickety tests that open/delete multiple times would be the most affected, which is what #c12 points to.

[Joshua Bell]

If the leveldb patch helps, I would expect times like this:

http://test-results.appspot.com/dashboards/flakiness_dashboard.html#group=%40ToT%20-%20webkit.org&tests=storage%2Findexeddb%2Fintversion-encoding.html

...to drop once chromium r161754 rolls into WebKit.

[Joshua Bell]

(In reply to comment #21)
> If the leveldb patch helps, I would expect times like this:
> 
> http://test-results.appspot.com/dashboards/flakiness_dashboard.html#group=%40ToT%20-%20webkit.org&tests=storage%2Findexeddb%2Fintversion-encoding.html
> 
> ...to drop once chromium r161754 rolls into WebKit.

... which it did in http://trac.webkit.org/changeset/131332 and the times are now all < 1 second. Fingers crossed...

[Joshua Bell]

Ojan - I'll let you make the call on un-marking the tests as slow, but the flakiness dashboard looks promising.

[Ojan Vafai]

Overall the performance is much much better. Thanks!

Unfortunately the upstream Chromium Linux Release bot seems to still have the occasional slow run for most tests. If they weren't marked slow, they would have timed out (any time >= 6 would be a timeout on release Chromium bots). Many of the timeouts are after http://trac.webkit.org/changeset/131332.

The vast majority of the time, all these tests take <1 second on this bot. So, it seems like there might be some fishy locking or something going on for each of these tests to intermittently get 10x slower.

http://test-results.appspot.com/dashboards/flakiness_dashboard.html#group=%40ToT%20-%20webkit.org&tests=storage%2Findexeddb

[Joshua Bell]

By dropping the timeout to 3s locally and running all storage/indexeddb tests under fully-parallel (32 workers), I was able to semi-reliably get timeouts and add some instrumentation. 

It looks like the symptom for e.g. key-generator.html that the deleteDatabase() call can take around half a second when the system is loaded. This is all going into the commit of the delete write-batch, which is forced to be synchronous on disk via leveldb writeOptions.sync = true which forces an fflush. That would be the "lock" that ojan speculated about.

Setting writeOptions.sync = false drops the times significantly.

Two approaches come to mind:

* Add an Internals API that lets us turn off sync writes for tests
* Switch back to using in-memory backing stores but come up with a mechanism to retain them for the lifetime of a test.

[Alec Flett]

I like 1) - and I wonder if we could synchronously delete the database metadata, but asynchronously delete the data? It may not actually help that much though.

[Joshua Bell]

(In reply to comment #26)
> I wonder if we could synchronously delete the database metadata, but asynchronously delete the data? It may not actually help that much though.

When this is running in DumpRenderTree I don't think we gain much from it being async.

[Dimitri Glazkov (Google)]

Looks like now it's just flakey.

[Joshua Bell]

FWIW, I moved my /tmp dir to a ramdisk. All 200 IDB layout tests now take only about 2 seconds to run since disk seek time is no longer relevant.

Perhaps we should configure the bots this way?