Closed Bug 1524435 Opened 6 years ago Closed 5 years ago

Intermittent http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js | Unknown :0: uncaught exception: out of memory item 1

Categories

(Core :: JavaScript Engine, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla67
Tracking Status
firefox-esr60 --- unaffected
firefox65 --- unaffected
firefox66 --- unaffected
firefox67 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: sfink)

References

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell disable-recommended])

Attachments

(1 file)

#[markdown(off)]
Filed by: shindli [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=225331383&repo=mozilla-central

https://queue.taskcluster.net/v1/task/Wz6WPGeVRo-5l2ul7QQ6_A/runs/0/artifacts/public/logs/live_backing.log

https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/Wz6WPGeVRo-5l2ul7QQ6_A/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2019-01-31T23:44:57.150Z] 23:44:57 INFO - REFTEST TEST-PASS | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/replace.js | item 1
[task 2019-01-31T23:44:57.151Z] 23:44:57 INFO - REFTEST TEST-END | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/replace.js
[task 2019-01-31T23:44:57.152Z] 23:44:57 INFO - REFTEST TEST-START | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js
[task 2019-01-31T23:44:57.152Z] 23:44:57 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js | 154 / 323 (47%)
[task 2019-01-31T23:45:07.766Z] 23:45:07 INFO - REFTEST TEST-UNEXPECTED-FAIL | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js | Unknown :0: uncaught exception: out of memory item 1
[task 2019-01-31T23:45:07.768Z] 23:45:07 INFO - REFTEST INFO | Saved log: START http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js
[task 2019-01-31T23:45:07.769Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
[task 2019-01-31T23:45:07.770Z] 23:45:07 INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2019-01-31T23:45:07.770Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] AfterOnLoadScripts belatedly entering WaitForTestEnd
[task 2019-01-31T23:45:07.770Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] WaitForTestEnd: Adding listeners
[task 2019-01-31T23:45:07.770Z] 23:45:07 INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2019-01-31T23:45:07.771Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FIRE_INVALIDATE_EVENT
[task 2019-01-31T23:45:07.771Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: dispatching MozReftestInvalidate
[task 2019-01-31T23:45:07.771Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_REFTEST_WAIT_REMOVAL
[task 2019-01-31T23:45:07.771Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_SPELL_CHECKS
[task 2019-01-31T23:45:07.771Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_APZ_FLUSH
[task 2019-01-31T23:45:07.771Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: APZ flush not required
[task 2019-01-31T23:45:07.771Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FINISH
[task 2019-01-31T23:45:07.772Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: Doing sync flush to compositor
[task 2019-01-31T23:45:07.772Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: Completed
[task 2019-01-31T23:45:07.772Z] 23:45:07 INFO - REFTEST INFO | Saved log: [CONTENT] RecordResult fired
[task 2019-01-31T23:45:07.772Z] 23:45:07 INFO - REFTEST INFO | Saved log: RecordResult fired
[task 2019-01-31T23:45:07.773Z] 23:45:07 INFO - REFTEST TEST-END | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js
[task 2019-01-31T23:45:18.390Z] 23:45:18 INFO - REFTEST TEST-START | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/search-GetMethod.js
[task 2019-01-31T23:45:18.390Z] 23:45:18 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/search-GetMethod.js | 155 / 323 (47%)
[task 2019-01-31T23:45:18.392Z] 23:45:18 INFO - REFTEST TEST-PASS | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/search-GetMethod.js | item 1
[task 2019-01-31T23:45:18.392Z] 23:45:18 INFO - REFTEST TEST-END | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/search-GetMethod.js
[task 2019-01-31T23:45:18.393Z] 23:45:18 INFO - REFTEST TEST-START | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/search.js
[task 2019-01-31T23:45:18.394Z] 23:45:18 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/search.js | 156 / 323 (48%)
[task 2019-01-31T23:45:18.395Z] 23:45:18 INFO - REFTEST TEST-PASS | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/search.js | item 1
[task 2019-01-31T23:45:18.395Z] 23:45:18 INFO - REFTEST TEST-END | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/search.js
[task 2019-01-31T23:45:29.009Z] 23:45:29 INFO - REFTEST TEST-START | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/split-01.js
[task 2019-01-31T23:45:29.009Z] 23:45:29 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/split-01.js | 157 / 323 (48%)
[task 2019-01-31T23:45:29.011Z] 23:45:29 INFO - REFTEST TEST-PASS | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/split-01.js | item 1
[task 2019-01-31T23:45:29.011Z] 23:45:29 INFO - REFTEST TEST-END | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/split-01.js
[task 2019-01-31T23:45:29.012Z] 23:45:29 INFO - REFTEST TEST-START | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/split-GetMethod.js
[task 2019-01-31T23:45:29.012Z] 23:45:29 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/split-GetMethod.js | 158 / 323 (48%)

Regression from bug 1442481?

Blocks: 1442481
Flags: needinfo?(sphink)
Keywords: regression

Yeah, this one is mysterious -- the test really shouldn't be consuming much memory. Looking.

Steve, any updates on this? It's still on the disable-recommended bugs list and it has 69 failures in the last 7 days across all platforms. https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-02-11&endday=2019-02-18&tree=trunk&bug=1524435

Flags: needinfo?(sdetar)

Sorry for the delay. I have some try pushes with extra diagnostics going.

Flags: needinfo?(sdetar)

Removing the disable recommended tag since this is actively being worked on.

There are 67 total failures in the last 7 days on all platforms.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=230025405&repo=autoland&lineNumber=9687

[task 2019-02-23T03:13:08.128Z] 03:13:08 INFO - REFTEST TEST-START | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js
[task 2019-02-23T03:13:08.128Z] 03:13:08 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js | 833 / 838 (99%)
[task 2019-02-23T03:13:08.134Z] 03:13:08 INFO - REFTEST TEST-UNEXPECTED-FAIL | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js | Unknown :0: uncaught exception: out of memory item 1
[task 2019-02-23T03:13:08.134Z] 03:13:08 INFO - REFTEST INFO | Saved log: START http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js
[task 2019-02-23T03:13:08.134Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
[task 2019-02-23T03:13:08.134Z] 03:13:08 INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2019-02-23T03:13:08.134Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] AfterOnLoadScripts belatedly entering WaitForTestEnd
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] WaitForTestEnd: Adding listeners
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FIRE_INVALIDATE_EVENT
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: dispatching MozReftestInvalidate
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_REFTEST_WAIT_REMOVAL
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_SPELL_CHECKS
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_APZ_FLUSH
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: APZ flush not required
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FINISH
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: Doing sync flush to compositor
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: Completed
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: [CONTENT] RecordResult fired
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST INFO | Saved log: RecordResult fired
[task 2019-02-23T03:13:08.135Z] 03:13:08 INFO - REFTEST TEST-END | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell needswork:owner]

sphink: Any updates on this bug?

There are 96 total failures in the last 7 days on all platforms.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=230863813&repo=mozilla-inbound&lineNumber=9762

[task 2019-02-27T21:49:03.199Z] 21:49:03 INFO - REFTEST TEST-START | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js
[task 2019-02-27T21:49:03.199Z] 21:49:03 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js | 833 / 8384 (9%)
[task 2019-02-27T21:49:03.199Z] 21:49:03 INFO - REFTEST TEST-UNEXPECTED-FAIL | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js | Unknown :0: uncaught exception: out of memory item 1
[task 2019-02-27T21:49:03.199Z] 21:49:03 INFO - REFTEST INFO | Saved log: START http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js
[task 2019-02-27T21:49:03.199Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
[task 2019-02-27T21:49:03.200Z] 21:49:03 INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2019-02-27T21:49:03.200Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] AfterOnLoadScripts belatedly entering WaitForTestEnd
[task 2019-02-27T21:49:03.200Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] WaitForTestEnd: Adding listeners
[task 2019-02-27T21:49:03.200Z] 21:49:03 INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2019-02-27T21:49:03.201Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FIRE_INVALIDATE_EVENT
[task 2019-02-27T21:49:03.201Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: dispatching MozReftestInvalidate
[task 2019-02-27T21:49:03.201Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_REFTEST_WAIT_REMOVAL
[task 2019-02-27T21:49:03.201Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_SPELL_CHECKS
[task 2019-02-27T21:49:03.202Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_APZ_FLUSH
[task 2019-02-27T21:49:03.202Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: APZ flush not required
[task 2019-02-27T21:49:03.202Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FINISH
[task 2019-02-27T21:49:03.202Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: Doing sync flush to compositor
[task 2019-02-27T21:49:03.202Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: Completed
[task 2019-02-27T21:49:03.202Z] 21:49:03 INFO - REFTEST INFO | Saved log: [CONTENT] RecordResult fired
[task 2019-02-27T21:49:03.202Z] 21:49:03 INFO - REFTEST INFO | Saved log: RecordResult fired
[task 2019-02-27T21:49:03.202Z] 21:49:03 INFO - REFTEST TEST-END | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=non262/String/ropes.js

Steve, do you have any updates?

Flags: needinfo?(sphink)
Flags: needinfo?(sphink)
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell needswork:owner]
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell needswork:owner]

Since there is no reply, can we disable this test? If yes, to disable jsreftests can we use the same method as for reftests? I have searched in searchfox for ropes.js but no manifest found.

Joel, can you please advise?

Flags: needinfo?(jmaher)

It's curious this also OOMs on 64-bit platforms so I looked into it. I wonder if the NoGC call here has something to do with it:

https://searchfox.org/mozilla-central/rev/92d11a33250a8e368c8ca3e962e15ca67117f765/js/src/builtin/TestingFunctions.cpp#1656

Steve, is there a reason this can't be just CanGC?

:ccoroiu, jsreftests are much difference and this is the first time we have had a jsreftest fall into the disable-recommended list :)

We edit these in the source file, similar to this:
https://searchfox.org/mozilla-central/source/js/src/tests/non262/Array/regress-322135-02.js#1

you have to be very specific with the spaces used, just put the same line 1 in this file:
https://searchfox.org/mozilla-central/source/js/src/tests/non262/String/ropes.js

of course slow might need a different reason, I think OOM would be appropriate here. Lets see what :sfink replies with, maybe between :jandem and :sfink there will be a fix by tomorrow.

Flags: needinfo?(jmaher)

(In reply to Jan de Mooij [:jandem] from comment #24)

It's curious this also OOMs on 64-bit platforms so I looked into it. I wonder if the NoGC call here has something to do with it:

https://searchfox.org/mozilla-central/rev/92d11a33250a8e368c8ca3e962e15ca67117f765/js/src/builtin/TestingFunctions.cpp#1656

Steve, is there a reason this can't be just CanGC?

Oh, I bet you're right. I've been chasing my tail on this one, dumping out the counts of arenas and things because I wouldn't expect this test to use all that much memory (and it doesn't, locally.) I haven't managed to get an instrumented job to fail, and none of them use all that much.

My reasoning for making that call NoGC is that you can request a nursery-allocated rope by a configuration parameter. If it were CanGC, I reasoned that all of the ropes you wanted to be in the nursery would actually be tenured. But on second thought, if this needs to GC it will do that first, so the returned rope will be nursery-allocated. If you're in a loop, everything you previously allocated will now be tenured, but it seems like the alternative is to OOM.

When I wrote that, I imagined that NoGC meant "allocate whatever you need, even if you cross GC thresholds" (increasing peak memory usage but otherwise not affecting behavior). Instead, it seems to be "if you would normally GC, OOM instead." Honestly, my expectation seems like a better way for it to work -- an OOM because we're unwilling to expand the GC heap doesn't seem that likely to imply that we're truly at OOM. Filed bug 1532445 to discuss that.

For now, I'm going to go ahead and fix this as jandem suggested.

Flags: needinfo?(sphink)
Assignee: nobody → sphink
Status: NEW → ASSIGNED
Pushed by sfink@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/248ccbf196f4
Stop using JSRope::new_<NoGC> when allocating test ropes r=jonco
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla67
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: