Last Comment Bug 530157 - js1_5/GC/regress-383269-01.js & regress-383269-02.js - random jsreftest failure, with message "Leak related to arguments object"
: js1_5/GC/regress-383269-01.js & regress-383269-02.js - random jsreftest failu...
Status: RESOLVED FIXED
[test disabled]
: intermittent-failure
Product: Core
Classification: Components
Component: JavaScript Engine (show other bugs)
: Trunk
: All All
: -- normal (vote)
: ---
Assigned To: general
:
Mentors:
Depends on:
Blocks: 438871
  Show dependency treegraph
 
Reported: 2009-11-20 12:04 PST by Bob Clary [:bc:]
Modified: 2012-11-25 19:31 PST (History)
10 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments

Description Bob Clary [:bc:] 2009-11-20 12:04:11 PST
"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
Comment 1 Daniel Holbert [:dholbert] (mostly OOTO until Aug 9th) 2009-12-10 12:36:54 PST
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
Comment 2 Daniel Holbert [:dholbert] (mostly OOTO until Aug 9th) 2009-12-14 09:51:26 PST
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
Comment 3 David Baron :dbaron: ⌚️UTC+1 (mostly busy through August 4; review requests must explain patch) 2009-12-25 05:55:15 PST
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
Comment 4 Phil Ringnalda (:philor, back in August) 2009-12-30 13:32:41 PST
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
Comment 5 Jonathan Kew (:jfkthame) 2010-01-08 05:26:57 PST
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
Comment 6 Chris Jones [:cjones] inactive; ni?/f?/r? if you need me 2010-01-19 15:22:11 PST
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
Comment 7 David Baron :dbaron: ⌚️UTC+1 (mostly busy through August 4; review requests must explain patch) 2010-01-27 19:05:04 PST
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
Comment 8 Phil Ringnalda (:philor, back in August) 2010-02-02 09:45:10 PST
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
Comment 9 Phil Ringnalda (:philor, back in August) 2010-02-02 12:04:28 PST
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
Comment 10 Daniel Holbert [:dholbert] (mostly OOTO until Aug 9th) 2010-02-02 14:02:03 PST
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
Comment 11 Robert Sayre 2010-02-02 14:16:58 PST
bc, how does this test work?
Comment 12 Bob Clary [:bc:] 2010-02-02 14:24:25 PST
Igor knows all.
Comment 13 Benjamin Smedberg AWAY UNTIL 2-AUG-2016 [:bsmedberg] 2010-02-03 06:32:51 PST
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
Comment 14 Igor Bukanov 2010-02-04 04:20:16 PST
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.
Comment 15 Brendan Eich [:brendan] 2010-02-04 07:39:12 PST
Second GC waits sounds good, but it could avoid waiting until it was done marking without contention, right?

/be
Comment 16 Mike Shaver (:shaver -- probably not reading bugmail closely) 2010-02-04 07:41:01 PST
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.
Comment 17 Phil Ringnalda (:philor, back in August) 2010-02-04 08:26:45 PST
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
Comment 18 Phil Ringnalda (:philor, back in August) 2010-02-04 10:21:42 PST
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
Comment 19 Phil Ringnalda (:philor, back in August) 2010-02-04 16:22:48 PST
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
Comment 20 Phil Ringnalda (:philor, back in August) 2010-02-05 19:06:30 PST
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
Comment 21 Bob Clary [:bc:] 2010-02-06 07:22:37 PST
More gc timing.
Comment 22 Phil Ringnalda (:philor, back in August) 2010-02-06 10:23:02 PST
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
Comment 23 Mike Shaver (:shaver -- probably not reading bugmail closely) 2010-02-06 11:07:34 PST
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.
Comment 24 Phil Ringnalda (:philor, back in August) 2010-02-06 13:50:12 PST
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
Comment 25 Igor Bukanov 2010-02-06 13:50:57 PST
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.
Comment 26 Igor Bukanov 2010-02-07 05:50:34 PST
sayrer, would you merge the change https://hg.mozilla.org/tracemonkey/rev/44ec2e247b55 to mozilla-central?

Note You need to log in before you can comment on or make changes to this bug.