Closed Bug 1150737 Opened 8 years ago Closed 7 years ago

Intermittent test_remove_objectStore.html | Test timed out

Categories

(Core :: Storage: IndexedDB, defect)

Product:
Core
Component:
Storage: IndexedDB
Version:
39 Branch
Platform:
x86_64
macOS
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla47
Tracking Flags:
Tracking Status
firefox45 --- wontfix
firefox46 --- fixed
firefox47 --- fixed
firefox-esr45 --- fixed

People

(Reporter: KWierso, Assigned: khuey)

References

Details

(Keywords: intermittent-failure, Whiteboard: [rr-chaos])

Attachments

(1 file, 1 obsolete file)

Patch
4.51 KB, patch
bent.mozilla
: review+
Details | Diff | Splinter Review 
14:24:07 INFO - 1970 INFO TEST-START | dom/indexedDB/test/test_readonly_transactions.html
14:24:07 INFO - ++DOMWINDOW == 76 (0x124704000) [pid = 1025] [serial = 3687] [outer = 0x12d283400]
14:24:07 INFO - [Parent 1025] WARNING: Performance Entry buffer size maximum reached!: file /builds/slave/m-in-m64-d-0000000000000000000/build/src/dom/base/nsPerformance.cpp, line 593
14:24:07 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
14:24:07 INFO - 1971 INFO TEST-OK | dom/indexedDB/test/test_readonly_transactions.html | took 261ms
14:24:07 INFO - ++DOMWINDOW == 77 (0x125a88800) [pid = 1025] [serial = 3688] [outer = 0x12d283400]
14:24:07 INFO - [Parent 1025] WARNING: Performance Entry buffer size maximum reached!: file /builds/slave/m-in-m64-d-0000000000000000000/build/src/dom/base/nsPerformance.cpp, line 593
14:24:07 INFO - 1972 INFO TEST-START | dom/indexedDB/test/test_readwriteflush_disabled.html
14:24:08 INFO - ++DOMWINDOW == 78 (0x11d14f800) [pid = 1025] [serial = 3689] [outer = 0x12d283400]
14:24:08 INFO - [Parent 1025] WARNING: Performance Entry buffer size maximum reached!: file /builds/slave/m-in-m64-d-0000000000000000000/build/src/dom/base/nsPerformance.cpp, line 593
14:24:08 INFO - 1973 INFO TEST-OK | dom/indexedDB/test/test_readwriteflush_disabled.html | took 159ms
14:24:08 INFO - ++DOMWINDOW == 79 (0x126075c00) [pid = 1025] [serial = 3690] [outer = 0x12d283400]
14:24:08 INFO - [Parent 1025] WARNING: Performance Entry buffer size maximum reached!: file /builds/slave/m-in-m64-d-0000000000000000000/build/src/dom/base/nsPerformance.cpp, line 593
14:24:08 INFO - 1974 INFO TEST-START | dom/indexedDB/test/test_remove_index.html
14:24:08 INFO - ++DOMWINDOW == 80 (0x11d6fa400) [pid = 1025] [serial = 3691] [outer = 0x12d283400]
14:24:08 INFO - [Parent 1025] WARNING: Performance Entry buffer size maximum reached!: file /builds/slave/m-in-m64-d-0000000000000000000/build/src/dom/base/nsPerformance.cpp, line 593
14:24:08 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
14:24:08 INFO - 1975 INFO TEST-OK | dom/indexedDB/test/test_remove_index.html | took 363ms
14:24:08 INFO - ++DOMWINDOW == 81 (0x11d4e6800) [pid = 1025] [serial = 3692] [outer = 0x12d283400]
14:24:08 INFO - [Parent 1025] WARNING: Performance Entry buffer size maximum reached!: file /builds/slave/m-in-m64-d-0000000000000000000/build/src/dom/base/nsPerformance.cpp, line 593
14:24:08 INFO - 1976 INFO TEST-START | dom/indexedDB/test/test_remove_objectStore.html
14:24:08 INFO - ++DOMWINDOW == 82 (0x11d357000) [pid = 1025] [serial = 3693] [outer = 0x12d283400]
14:24:08 INFO - [Parent 1025] WARNING: Performance Entry buffer size maximum reached!: file /builds/slave/m-in-m64-d-0000000000000000000/build/src/dom/base/nsPerformance.cpp, line 593
14:24:08 INFO - [Parent 1025] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001: file /builds/slave/m-in-m64-d-0000000000000000000/build/src/storage/src/mozStorageConnection.cpp, line 644
14:24:08 INFO - [Parent 1025] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001: file /builds/slave/m-in-m64-d-0000000000000000000/build/src/storage/src/mozStorageService.cpp, line 868
14:24:08 INFO - [Parent 1025] WARNING: Received NS_ERROR_STORAGE_BUSY when attempting to open database '3128029391StpsleeTn+ddi.sqlite', retrying for up to 10 seconds: file /builds/slave/m-in-m64-d-0000000000000000000/build/src/dom/indexedDB/ActorsParent.cpp, line 3770
14:24:08 INFO - --DOMWINDOW == 81 (0x109c79c00) [pid = 1025] [serial = 3659] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_objectStore_getAllKeys.html]
14:24:08 INFO - --DOMWINDOW == 80 (0x123509000) [pid = 1025] [serial = 3661] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_objectStore_inline_autoincrement_key_added_on_put.html]
14:24:14 INFO - --DOMWINDOW == 79 (0x127d3b400) [pid = 1025] [serial = 3676] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:14 INFO - --DOMWINDOW == 78 (0x127cc7400) [pid = 1025] [serial = 3678] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:14 INFO - --DOMWINDOW == 77 (0x11cb70800) [pid = 1025] [serial = 3664] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:14 INFO - --DOMWINDOW == 76 (0x127de4c00) [pid = 1025] [serial = 3674] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:14 INFO - --DOMWINDOW == 75 (0x11d35c000) [pid = 1025] [serial = 3672] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:14 INFO - --DOMWINDOW == 74 (0x127d41000) [pid = 1025] [serial = 3668] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:14 INFO - --DOMWINDOW == 73 (0x11d009400) [pid = 1025] [serial = 3667] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_object_identity.html]
14:24:14 INFO - --DOMWINDOW == 72 (0x11e76f400) [pid = 1025] [serial = 3666] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:14 INFO - --DOMWINDOW == 71 (0x12320f000) [pid = 1025] [serial = 3669] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_odd_result_order.html]
14:24:14 INFO - --DOMWINDOW == 70 (0x127d2b800) [pid = 1025] [serial = 3670] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:14 INFO - --DOMWINDOW == 69 (0x11d0e6800) [pid = 1025] [serial = 3663] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_objectStore_openKeyCursor.html]
14:24:14 INFO - --DOMWINDOW == 68 (0x11ce47000) [pid = 1025] [serial = 3665] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_objectStore_remove_values.html]
14:24:16 INFO - --DOMWINDOW == 67 (0x125b1e800) [pid = 1025] [serial = 3657] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_objectCursors.html]
14:24:16 INFO - --DOMWINDOW == 66 (0x1284ec000) [pid = 1025] [serial = 3655] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_names_sorted.html]
14:24:16 INFO - --DOMWINDOW == 65 (0x109c76000) [pid = 1025] [serial = 3677] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_optionalArguments.html]
14:24:16 INFO - --DOMWINDOW == 64 (0x11d159000) [pid = 1025] [serial = 3675] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_open_objectStore.html]
14:24:16 INFO - --DOMWINDOW == 63 (0x11d35c800) [pid = 1025] [serial = 3673] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_open_for_principal.html]
14:24:16 INFO - --DOMWINDOW == 62 (0x125b1ec00) [pid = 1025] [serial = 3671] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_open_empty_db.html]
14:24:21 INFO - --DOMWINDOW == 61 (0x125a88800) [pid = 1025] [serial = 3688] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:21 INFO - --DOMWINDOW == 60 (0x11d14f800) [pid = 1025] [serial = 3689] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_readwriteflush_disabled.html]
14:24:21 INFO - --DOMWINDOW == 59 (0x1237e0c00) [pid = 1025] [serial = 3686] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:21 INFO - --DOMWINDOW == 58 (0x124704000) [pid = 1025] [serial = 3687] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_readonly_transactions.html]
14:24:21 INFO - --DOMWINDOW == 57 (0x11d6b9400) [pid = 1025] [serial = 3682] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:21 INFO - --DOMWINDOW == 56 (0x11d6b6000) [pid = 1025] [serial = 3683] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_put_get_values.html]
14:24:21 INFO - --DOMWINDOW == 55 (0x12350d400) [pid = 1025] [serial = 3684] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:21 INFO - --DOMWINDOW == 54 (0x123510000) [pid = 1025] [serial = 3685] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_put_get_values_autoIncrement.html]
14:24:21 INFO - --DOMWINDOW == 53 (0x11d00c400) [pid = 1025] [serial = 3680] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:21 INFO - --DOMWINDOW == 52 (0x11d035c00) [pid = 1025] [serial = 3681] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_persistenceType.html]
14:24:21 INFO - --DOMWINDOW == 51 (0x11d4e6800) [pid = 1025] [serial = 3692] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:24:21 INFO - --DOMWINDOW == 50 (0x127ccbc00) [pid = 1025] [serial = 3679] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_overlapping_transactions.html]
14:24:21 INFO - --DOMWINDOW == 49 (0x11d6fa400) [pid = 1025] [serial = 3691] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/indexedDB/test/test_remove_index.html]
14:24:21 INFO - --DOMWINDOW == 48 (0x126075c00) [pid = 1025] [serial = 3690] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
14:27:06 INFO - [Parent 1025] WARNING: 1 sort operation has occurred for the SQL statement '0x150508410'. See https://developer.mozilla.org/En/Storage/Warnings details.: file /builds/slave/m-in-m64-d-0000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
14:29:24 INFO - TEST-INFO | screencapture: exit 0
14:29:24 INFO - 1977 INFO Running 'test_remove_objectStore.js'
14:29:24 INFO - 1978 INFO Pushing preferences
14:29:24 INFO - 1979 INFO Pushing permissions
14:29:24 INFO - 1980 INFO Clearing old databases
14:29:24 INFO - 1981 INFO Running test in a worker
14:29:24 INFO - 1982 INFO Worker: loading ["http://mochi.test:8888/tests/dom/indexedDB/test/unit/test_remove_objectStore.js"]
14:29:24 INFO - 1983 INFO Worker: starting tests
14:29:24 INFO - 1984 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | Correct objectStoreNames list
14:29:24 INFO - 1985 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | Correct objectStoreNames list
14:29:24 INFO - 1986 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | Correct name
14:29:24 INFO - 1987 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | Correct object store prior to deleting
14:29:24 INFO - 1988 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | Correct objectStores list
14:29:24 INFO - 1989 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | Got a DOMException
14:29:24 INFO - 1990 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | expect a NotFoundError
14:29:24 INFO - 1991 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | expect a NOT_FOUND_ERR
14:29:24 INFO - 1992 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | Correct objectStoreNames list
14:29:24 INFO - 1993 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | Correct name
14:29:24 INFO - 1994 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | Correct new objectStore
14:29:24 INFO - 1995 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | Old objectStore is not new objectStore
14:29:24 INFO - 1996 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | ObjectStore shouldn't have any items
14:29:24 INFO - 1997 INFO TEST-PASS | dom/indexedDB/test/test_remove_objectStore.html | Correct objectStores list
14:29:24 INFO - 1998 INFO TEST-UNEXPECTED-FAIL | dom/indexedDB/test/test_remove_objectStore.html | Test timed out. - expected PASS
14:29:25 INFO - 1999 INFO MEMORY STAT vsize after test: 4279017472
14:29:25 INFO - 2000 INFO MEMORY STAT residentFast after test: 811659264
14:29:25 INFO - 2001 INFO MEMORY STAT heapAllocated after test: 97633656
14:29:25 INFO - 2002 INFO TEST-OK | dom/indexedDB/test/test_remove_objectStore.html | took 316482ms
14:29:25 INFO - ++DOMWINDOW == 49 (0x11d155000) [pid = 1025] [serial = 3694] [outer = 0x12d283400]
14:29:25 INFO - [Parent 1025] WARNING: Performance Entry buffer size maximum reached!: file /builds/slave/m-in-m64-d-0000000000000000000/build/src/dom/base/nsPerformance.cpp, line 593
14:29:25 INFO - 2003 INFO TEST-START | dom/indexedDB/test/test_request_readyState.html
Here is the sequence of events, starting at http://hg.mozilla.org/mozilla-central/annotate/ac39fba33c6d/dom/indexedDB/test/unit/test_remove_objectStore.js#l52

1. We open the database, from a worker thread. This does a bunch of work via PBackground, etc and eventually we get the upgradeneeded callback.
2. Once we get upgradeneeded, we set up the success handler to advance the test after it fires (line 55), and then we do a bunch of IndexedDB work.
3. Eventually (on the same turn of the event loop) we get to line 84, where we open a cursor.  This keeps the transaction from continuing until that request is complete.
4. Then we yield on line 90 to wait for the cursor's request to complete.  It does, and it that onsuccess handler fires and advances the test.
5. We delete the object store, and call continueToNextStep.  That is supposed to dispatch an event to the current thread to advance the generator.  On the main thread this gets the nsIThread and dispatches a runnable, there is no equivalent API on workers, so instead it does a setTimeout(0).
6. We yield, which finishes the cursor's request and unblocks the original transaction, allowing it to proceed.

Now the transaction has to go to the PBackground thread to keep going, and the continueToNextStep has to go to the timer thread to keep going.  These race with each other.  This wouldn't be so bad, except that on line 98 we don't even start listening for the oncomplete message on the transaction until after continueToNextStep finishes.  If the transaction races and finishes first, then we miss that event and hang the test.

So we could solve this with a simple tweak to the test, but we probably need to fix continueToNextStep on workers too, and that's a lot harder.
Attached patch Patch (obsolete) — — Splinter Review 
Anyways, let's change the test for now, and we can figure out how to make workers do executeSoon better later.
Assignee: nobody → khuey
Status: NEW → ASSIGNED
Attachment #8718063 - Flags: review?(bugs)
Comment on attachment 8718063 [details] [diff] [review]
Patch

Review of attachment 8718063 [details] [diff] [review]:
-----------------------------------------------------------------

<sigh>
Attachment #8718063 - Flags: review?(bugs) → review+
Comment on attachment 8718063 [details] [diff] [review]
Patch

Bug 1150595 is the same underlying issue, so let's just fix this outright.
Attachment #8718063 - Attachment is obsolete: true
Kyle probably should have said that he debugged this on Linux using rr's chaos mode.
Comment on attachment 8718143 [details] [diff] [review]
Patch

Review of attachment 8718143 [details] [diff] [review]:
-----------------------------------------------------------------

Awesome!

::: dom/indexedDB/test/helpers.js
@@ +381,5 @@
>    self.executeSoon = function(_fun_) {
> +    var channel = new MessageChannel();
> +    channel.port1.postMessage("");
> +    channel.port2.onmessage = function(event) { _fun_(); };
> +//    setTimeout(_fun_, 0);

Nit: remove
Attachment #8718143 - Flags: review?(bent.mozilla) → review+
https://hg.mozilla.org/mozilla-central/rev/62a1b39559a7
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox47: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla47
You need to log in before you can comment on or make changes to this bug.