Closed Bug 530157 Opened 15 years ago Closed 12 years ago

js1_5/GC/regress-383269-01.js & regress-383269-02.js - random jsreftest failure, with message "Leak related to arguments object"

Categories

(Core :: JavaScript Engine, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED

People

(Reporter: bc, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [test disabled])

"s: moz2-win32-slave32"REFTEST TEST-UNEXPECTED-FAIL | file:///e:/builds/moz2_slave/mozilla-central-win32-unittest-everythingelse/build/jsreftest/tests/jsreftest.html?test=js1_5/GC/regress-383269-01.js | Leak related to arguments object Expected value 'No Leak', Actual value 'generate_big_object_graph() leaked, base_gc_time=17, last_gc_time=61' item 1

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258742421.1258745803.12397.gz
Whiteboard: [orange]
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260469639.1260477115.27422.gz
Linux mozilla-central debug test everythingelse on 2009/12/10 10:27:19
s: moz2-linux-slave12
OS: Windows Server 2003 → All
Hardware: x86 → All
Summary: js1_5/GC/regress-383269-01.js - random failure on windows → js1_5/GC/regress-383269-01.js - random jsreftest failure, with message "Leak related to arguments object"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260806889.1260809416.11500.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/14 08:08:09
s: win32-slave18
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1261740072.1261746235.12374.gz
Linux mozilla-central debug test everythingelse on 2009/12/25 03:21:12
s: moz2-linux-slave20
REFTEST TEST-UNEXPECTED-FAIL | file:///builds/slave/mozilla-central-linux-debug-unittest-everythingelse/build/jsreftest/tests/jsreftest.html?test=js1_5/GC/regress-383269-01.js | Leak related to arguments object Expected value 'No Leak', Actual value 'generate_big_object_graph() leaked, base_gc_time=36, last_gc_time=134'  item 1
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1262190277.1262192824.15701.gz
Linux mozilla-central opt test everythingelse on 2009/12/30 08:24:37
s: moz2-linux-slave23
REFTEST TEST-UNEXPECTED-FAIL | file:///builds/slave/mozilla-central-linux-opt-unittest-everythingelse/build/jsreftest/tests/jsreftest.html?test=js1_5/GC/regress-383269-01.js | Leak related to arguments object Expected value 'No Leak', Actual value 'generate_big_object_graph() leaked, base_gc_time=31, last_gc_time=107'  item 1
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1262950637.1262955392.23619.gz
Linux mozilla-central opt test everythingelse on 2010/01/08 03:37:17
s: moz2-linux-slave28
6326 ERROR TEST-UNEXPECTED-FAIL | chrome://mochikit/content/chrome/dom/tests/mochitest/chrome/test_focus.xul | Test timed out.
REFTEST TEST-UNEXPECTED-FAIL | file:///builds/slave/mozilla-central-linux-opt-unittest-everythingelse/build/jsreftest/tests/jsreftest.html?test=js1_5/GC/regress-383269-01.js | Leak related to arguments object Expected value 'No Leak', Actual value 'generate_big_object_graph() leaked, base_gc_time=32, last_gc_time=123'  item 1
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1263939727.1263943068.29796.gz
Linux mozilla-central opt test jsreftest on 2010/01/19 14:22:07  
s: moz2-linux-slave21

begin test: js1_5/GC/regress-383269-01.js
BUGNUMBER: 383269
STATUS: Leak related to arguments object
 FAILED! [reported from test()] Leak related to arguments object : Expected value 'No Leak', Actual value 'generate_big_object_graph() leaked, base_gc_time=33, last_gc_time=169'
REFTEST TEST-UNEXPECTED-FAIL | file:///builds/slave/mozilla-central-linux-opt-unittest-jsreftest/build/jsreftest/tests/jsreftest.html?test=js1_5/GC/regress-383269-01.js | Leak related to arguments object Expected value 'No Leak', Actual value 'generate_big_object_graph() leaked, base_gc_time=33, last_gc_time=169'  item 1
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1264640168.1264643084.11511.gz
Linux mozilla-central debug test jsreftest on 2010/01/27 16:56:08
s: moz2-linux-slave25
REFTEST TEST-UNEXPECTED-FAIL | file:///builds/slave/mozilla-central-linux-debug-unittest-jsreftest/build/jsreftest/tests/jsreftest.html?test=js1_5/GC/regress-383269-02.js | Leak related to arguments object Expected value 'No Leak', Actual value 'generate_big_object_graph() leaked, base_gc_time=32, last_gc_time=152'  item 1
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265107694.1265110692.4850.gz
Linux mozilla-central debug test jsreftest on 2010/02/02 02:48:14
s: moz2-linux-slave01
REFTEST TEST-UNEXPECTED-FAIL | file:///builds/moz2_slave/mozilla-central-linux-debug-unittest-jsreftest/build/jsreftest/tests/jsreftest.html?test=js1_5/GC/regress-383269-01.js | Leak related to arguments object Expected value 'No Leak', Actual value 'generate_big_object_graph() leaked, base_gc_time=19, last_gc_time=62'  item 1
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265136063.1265139841.21201.gz
Linux mozilla-central opt test jsreftest on 2010/02/02 10:41:03
s: moz2-linux-slave23
REFTEST TEST-UNEXPECTED-FAIL | file:///builds/slave/mozilla-central-linux-opt-unittest-jsreftest/build/jsreftest/tests/jsreftest.html?test=js1_5/GC/regress-383269-01.js | Leak related to arguments object Expected value 'No Leak', Actual value 'generate_big_object_graph() leaked, base_gc_time=30, last_gc_time=126'  item 1
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265143254.1265147288.7228.gz
REFTEST TEST-UNEXPECTED-FAIL | file:///builds/slave/mozilla-central-linux-debug-unittest-jsreftest/build/jsreftest/tests/jsreftest.html?test=js1_5/GC/regress-383269-02.js | Leak related to arguments object Expected value 'No Leak', Actual value 'generate_big_object_graph() leaked, base_gc_time=51, last_gc_time=341'  item 1
Linux mozilla-central debug test jsreftest on 2010/02/02 12:40:54
s: moz2-linux-slave22
Blocks: 438871
Summary: js1_5/GC/regress-383269-01.js - random jsreftest failure, with message "Leak related to arguments object" → js1_5/GC/regress-383269-01.js & regress-383269-02.js - random jsreftest failure, with message "Leak related to arguments object"
bc, how does this test work?
Igor knows all.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265187324.1265189091.24525.gz
WINNT 5.2 mozilla-central debug test jsreftest on 2010/02/03 00:55:24
The test does the following:

gc();
gc(); // measure the gc time1 here
generating_big_object_graph
gc();
gc(); // measure the gc time2 here

Then it assumes that if time2 is much greater than time1, then it is a leak from generating_big_object_graph that contributes most of the extra gc time due to marking of the leaked arguments objects.

Now, the background thread finalization broke that assumption as now the second gc most likely will run in parallel with the sweeping task. 

One possibility to fix this is to add an option to the shell gc() function to wait for the sweeping task to finish. Another possibility is to make js_GC() to wait if the sweeping task is still running. I would prefer the second solution since in theory this would also improve things if the browser schedules the second gc before the sweeping task finishes. Currently this would result in two threads to call free in parallel and malloc locks contention. But if the GC would wait, then contention would be avoided.
Assignee: bclary → igor
Second GC waits sounds good, but it could avoid waiting until it was done marking without contention, right?

/be
Let's disable this test until we figure out what the new path is, then -- relying on timing relations on non-performance tests is, in virtually every case that we've done it, a recipe for frustratingly random oranges and quick numbing on the part of developers.  Let's get out of there.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265296841.1265299809.15222.gz
Linux mozilla-central debug test jsreftest on 2010/02/04 07:20:41
s: moz2-linux-slave02
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265306830.1265307373.7339.gz
WINNT 5.2 mozilla-central opt test jsreftest on 2010/02/04 10:07:10
s: win32-slave28
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265328368.1265328965.24234.gz
WINNT 5.2 mozilla-central opt test jsreftest on 2010/02/04 16:06:08
s: win32-slave36
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265423110.1265423642.23083.gz
WINNT 5.2 mozilla-central opt test jsreftest on 2010/02/05 18:25:10
s: win32-slave35
REFTEST TEST-UNEXPECTED-FAIL | file:///e:/builds/moz2_slave/mozilla-central-win32-opt-unittest-jsreftest/build/jsreftest/tests/jsreftest.html?test=js1_5/GC/regress-383269-01.js | Leak related to arguments object Expected value 'No Leak', Actual value 'generate_big_object_graph() leaked, base_gc_time=2, last_gc_time=13'  item 1
More gc timing.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265458629.1265461659.24744.gz
WINNT 5.2 mozilla-central debug test jsreftest on 2010/02/06 04:17:09
s: win32-slave06
This is ridiculous: while you're debating the future of this synchronization, it continues to cost other developers time and confusing because of random oranges.

Do you just not care?  Do members of the JS team not see random failures when *they* run the tests?

Timing-based tests are a bad idea for things other than our perf suite.  The non-perf tests are run on machines with uncontrolled load, and it's entirely possible that the machine will run slower during one GC's period than another.  If you need a hook counting outstanding GC things, add one.  If you want to just run leak tests under the same leak-testing harness we use for other things, do so.

But don't let this bug and its siblings sit around frustrating other developers for *months* without addressing it: it's pretty disrespectful of the people who *are* watching the test state of our application.  (Even though it started to fail last November, when the parallel freeing was added, it was paid no heed by anyone on the JS team until Feb, and since then it continues to be debated.)

Please just disable this test promptly on mozilla-central; you can keep it in place on tracemonkey if you like random oranges there.  If I have to pull a tree to do so, it's a pretty sad statement.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265492120.1265492593.13868.gz
WINNT 5.2 mozilla-central opt test jsreftest on 2010/02/06 13:35:20
s: win32-slave25
I disabled the tests in tm - https://hg.mozilla.org/tracemonkey/rev/44ec2e247b55

(In reply to comment #23)
> Do you just not care?  Do members of the JS team not see random failures when
> *they* run the tests?

I personally have not seen those oranges.

> Timing-based tests are a bad idea for things other than our perf suite.  The
> non-perf tests are run on machines with uncontrolled load, and it's entirely
> possible that the machine will run slower during one GC's period than another. 

The timing tests works if a probability of failure can be made sufficiently small so false positives can be tolerated and the amount of efforts to deal with them is less than implementing non-timing version of the tests. That was the case before the parallel freeing.

I guess the lesson here is that timing tests should not be used for too long. That is, they are fine as *temporary* measure to verify that the bug is indeed addressed, but they should be retired and/or replaced by better tests before the code changes significantly. Which suggests to clearly mark such tests so any false positives can be instantly identified.

> (Even though it started to
> fail last November, when the parallel freeing was added, it was paid no heed by
> anyone on the JS team until Feb, and since then it continues to be debated.)

When I became aware of these bugs, I thought that they were not urgent precisely because the bugs are old. That was a mistake, sorry about that.
sayrer, would you merge the change https://hg.mozilla.org/tracemonkey/rev/44ec2e247b55 to mozilla-central?
Whiteboard: [orange] → [orange][test disabled]
Assignee: igor → general
Status: NEW → RESOLVED
Closed: 12 years ago
Resolution: --- → FIXED
Whiteboard: [orange][test disabled] → [test disabled]
You need to log in before you can comment on or make changes to this bug.