Bug 153438

Summary: Modern IDB: LayoutTest imported/w3c/indexeddb/keyorder-private.html is flaky
Product: WebKit Reporter: Ryan Haddad <ryanhaddad>
Component: WebCore Misc.Assignee: Brady Eidson <beidson>
Status: RESOLVED FIXED    
Severity: Normal CC: achristensen, alecflett, beidson, commit-queue, jsbell
Priority: P2    
Version: WebKit Nightly Build   
Hardware: Unspecified   
OS: Unspecified   
Bug Depends on:    
Bug Blocks: 149117    
Attachments:
Description Flags
Patch v1
beidson: review-
Patch v2 none

Comment 1 Ryan Haddad 2016-01-25 13:02:21 PST
--- /Volumes/Data/slave/elcapitan-release-tests-wk1/build/layout-test-results/imported/w3c/indexeddb/keyorder-private-expected.txt
+++ /Volumes/Data/slave/elcapitan-release-tests-wk1/build/layout-test-results/imported/w3c/indexeddb/keyorder-private-actual.txt
@@ -1,26 +1,26 @@
 
-PASS Database readback sort - String < Array 
+TIMEOUT Database readback sort - String < Array Test timed out
 PASS IDBKey.cmp sorted - String < Array 
-PASS Database readback sort - float < String 
+TIMEOUT Database readback sort - float < String Test timed out
 PASS IDBKey.cmp sorted - float < String 
-PASS Database readback sort - float < Date 
+TIMEOUT Database readback sort - float < Date Test timed out
 PASS IDBKey.cmp sorted - float < Date 
-PASS Database readback sort - float < Date < String < Array 
+TIMEOUT Database readback sort - float < Date < String < Array Test timed out
 PASS IDBKey.cmp sorted - float < Date < String < Array 
-PASS Database readback sort - Date(1 sec ago) < Date(now) < Date(1 minute in future) 
+TIMEOUT Database readback sort - Date(1 sec ago) < Date(now) < Date(1 minute in future) Test timed out
 PASS IDBKey.cmp sorted - Date(1 sec ago) < Date(now) < Date(1 minute in future) 
-PASS Database readback sort - -1.1 < 1 < 1.01337 < 1.013373 < 2 
+TIMEOUT Database readback sort - -1.1 < 1 < 1.01337 < 1.013373 < 2 Test timed out
 PASS IDBKey.cmp sorted - -1.1 < 1 < 1.01337 < 1.013373 < 2 
-PASS Database readback sort - -Infinity < -0.01 < 0 < Infinity 
+TIMEOUT Database readback sort - -Infinity < -0.01 < 0 < Infinity Test timed out
 PASS IDBKey.cmp sorted - -Infinity < -0.01 < 0 < Infinity 
-PASS Database readback sort - "" < "a" < "ab" < "b" < "ba" 
+TIMEOUT Database readback sort - "" < "a" < "ab" < "b" < "ba" Test timed out
 PASS IDBKey.cmp sorted - "" < "a" < "ab" < "b" < "ba" 
-PASS Database readback sort - Arrays 
+TIMEOUT Database readback sort - Arrays Test timed out
 PASS IDBKey.cmp sorted - Arrays 
-PASS Database readback sort - Array.length: 10,000 < Array.length: 10,001 
+TIMEOUT Database readback sort - Array.length: 10,000 < Array.length: 10,001 Test timed out
 PASS IDBKey.cmp sorted - Array.length: 10,000 < Array.length: 10,001 
-PASS Database readback sort - Infinity inside arrays 
+TIMEOUT Database readback sort - Infinity inside arrays Test timed out
 PASS IDBKey.cmp sorted - Infinity inside arrays 
-PASS Database readback sort - Test different stuff at once 
+FAIL Database readback sort - Test different stuff at once assert_unreached: unexpected db.error (ConstraintError) Reached unreachable code
 PASS IDBKey.cmp sorted - Test different stuff at once
Comment 2 Alexey Proskuryakov 2016-01-25 14:31:56 PST
This test appears so flaky that we should probably mark it as such.
Comment 3 Ryan Haddad 2016-01-25 14:35:28 PST
(In reply to comment #2)
> This test appears so flaky that we should probably mark it as such.

Done in <http://trac.webkit.org/projects/webkit/changeset/195556>
Comment 4 Brady Eidson 2016-02-03 10:36:05 PST
Really confused by this one.

It's still sometimes happening on the bots. I've never seen it locally (though I'm about to try a "run 1000 times" stress test). The test is very quick to pass locally, which also makes me wonder why sometimes it takes 5, sometimes 7, sometimes 9 seconds on the bots.
Comment 5 Brady Eidson 2016-02-03 11:30:18 PST
The "timeouts" are actually enforced by the test itself, and not run-webkit-tests timeout mechanism.


Locally I've seen one of the tests take "awhile", like maybe a 5 second pause in the test. It doesn't make much sense.

Especially since this is the memory backing store (which can't stall on i/o or anything like that) and the test uses a very unique database name each time.
Comment 6 Brady Eidson 2016-02-03 11:32:17 PST
I've captured IndexedDB logging for a good test run, and managed to capture it for a bad test run as well. Will compare by hand...
Comment 7 Brady Eidson 2016-02-03 13:46:52 PST
There's a specific key in the test which is basically:

var now = new Date;
var key = { 0, now };

We add that key to the object store. Adds only success if the key is not already there. It's a failure if the key is already there.

And guess what? that key is *reported* as already there.

Even though it had never been added before.

So... hashing problem, it seems.

But only semi-rarely.
Comment 8 Brady Eidson 2016-02-03 13:49:53 PST
(In reply to comment #7)
> There's a specific key in the test which is basically:
> 
> var now = new Date;
> var key = { 0, now };
> 
> We add that key to the object store. Adds only success if the key is not
> already there. It's a failure if the key is already there.
> 
> And guess what? that key is *reported* as already there.
> 
> Even though it had never been added before.
> 
> So... hashing problem, it seems.
> 

Crazy thing is... this would also indicate an operator=() problem
Comment 9 Brady Eidson 2016-02-04 09:00:23 PST
The plot thickens...

The MemoryObjectStore keeps both a HashMap of keys-to-values, and a std::map of ordered keys.

Every time we insert a record, we record the key-value-mapping in the HashMap, and insert the key into the std::map for ordered-ness.

The bug is happening because the HashMap *thinks* it has a record for this particular IDBKey. But the std::map does *NOT* have a record for the key.

Lots of printf-style debugging confirms that we've never tried to put this key in either the HashMap or std::map before, nor have we tried to put anything with its hash in those maps before...

Did this test discover a bug in our HashMap?
Comment 10 Brady Eidson 2016-02-04 09:35:04 PST
(In reply to comment #9)
> The plot thickens...
> ...
> Did this test discover a bug in our HashMap?

I know anytime anybody says "I think a discovered a bug in HashMap", they're almost certainly wrong and its misuse...  but I need an expert to walk through some stuff with me to confirm that it's me, and not HashMap.
Comment 11 Brady Eidson 2016-02-04 10:00:07 PST
It was definitely an operator== bug.

Patch coming.
Comment 12 Brady Eidson 2016-02-04 10:05:05 PST
Created attachment 270662 [details]
Patch v1
Comment 13 Brady Eidson 2016-02-04 10:06:18 PST
Comment on attachment 270662 [details]
Patch v1

Actually, I *might* be able to write a targeted test for this.

Will try.
Comment 14 Brady Eidson 2016-02-04 10:39:07 PST
Yup, I can write a targeted test that fails. Sweet.
Comment 15 Brady Eidson 2016-02-04 10:39:27 PST
I mean, reliably fails.
Comment 16 Brady Eidson 2016-02-04 10:55:26 PST
Created attachment 270667 [details]
Patch v2
Comment 17 WebKit Commit Bot 2016-02-04 11:46:52 PST
Comment on attachment 270667 [details]
Patch v2

Clearing flags on attachment: 270667

Committed r196137: <http://trac.webkit.org/changeset/196137>
Comment 18 WebKit Commit Bot 2016-02-04 11:46:56 PST
All reviewed patches have been landed.  Closing bug.