Closed Bug 1150737 Opened 10 years ago Closed 9 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: 9 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.

Attachment

General

Creator:
Created:
Updated:
Size: