1146696 - Crash [@ JSObject::finalize] or [@ js::gc::GCRuntime::sweepBackgroundThings]

Status: VERIFIED FIXED

(Core :: JavaScript Engine, defect)

Description

[Gary Kwong [:gkw] [:nth10sd] (NOT official MoCo now)]

// Randomly chosen test: js/src/jit-test/tests/debug/Memory-onGarbageCollection-02.js
dbg1 = new Debugger();
root2 = newGlobal();
dbg1.memory.onGarbageCollection = function(){}
dbg1.addDebuggee(root2);
// jsfunfuzz-generated code
for (var j = 0; j < 9999; ++j) {
    try {
        a
    } catch (e) {}
}
// Randomly chosen test: js/src/jit-test/tests/basic/testBug756919.js
gcparam("maxBytes", gcparam("gcBytes") + 1);
g();
function g() {
    var x = "";
    function f() {}
    eval('');
    g();
}

crashes js 32-bit debug and opt shell on m-c changeset cbd0efcd976c with --fuzzing-safe --no-threads --no-baseline --no-ion at JSObject::finalize with js::gc::GCRuntime::sweepBackgroundThings on the stack.

Debug configure options:

LD=ld CROSS_COMPILE=1 CC="clang -Qunused-arguments -msse2 -mfpmath=sse -arch i386" RANLIB=ranlib CXX="clang++ -Qunused-arguments -msse2 -mfpmath=sse -arch i386" AS=$CC AR=ar STRIP="strip -x -S" HOST_CC="clang -Qunused-arguments -msse2 -mfpmath=sse" AUTOCONF=/usr/local/Cellar/autoconf213/2.13/bin/autoconf213 HOST_CXX="clang++ -Qunused-arguments -msse2 -mfpmath=sse" sh /Users/skywalker/trees/mozilla-central/js/src/configure --target=i386-apple-darwin9.2.0 --enable-macos-target=10.5 --enable-debug --enable-nspr-build --enable-more-deterministic --with-ccache --enable-gczeal --enable-debug-symbols --disable-tests

python -u ~/fuzzing/js/compileShell.py -b "--enable-debug --enable-more-deterministic --enable-nspr-build --32" -r cbd0efcd976c

Opt configure options:

LD=ld CROSS_COMPILE=1 CC="clang -Qunused-arguments -msse2 -mfpmath=sse -arch i386" RANLIB=ranlib CXX="clang++ -Qunused-arguments -msse2 -mfpmath=sse -arch i386" AS=$CC AR=ar STRIP="strip -x -S" HOST_CC="clang -Qunused-arguments -msse2 -mfpmath=sse" AUTOCONF=/usr/local/Cellar/autoconf213/2.13/bin/autoconf213 HOST_CXX="clang++ -Qunused-arguments -msse2 -mfpmath=sse" sh /Users/skywalker/trees/mozilla-central/js/src/configure --target=i386-apple-darwin9.2.0 --enable-macos-target=10.5 --disable-debug --enable-nspr-build --enable-more-deterministic --with-ccache --enable-gczeal --enable-debug-symbols --disable-tests

python -u ~/fuzzing/js/compileShell.py -b "--disable-debug --enable-more-deterministic --enable-nspr-build --32" -r cbd0efcd976c

autoBisect shows this is probably related to the following changeset:

The first bad revision is:
changeset:   https://hg.mozilla.org/mozilla-central/rev/c109ca33d8a7
user:        Jon Coppeard
date:        Tue Mar 17 16:07:40 2015 +0000
summary:     Bug 1144108 - Fix debugger tests that are confused by GC zeal r=terrence

Setting s-s to be safe, not sure if a weird memory address is being accessed here, this might be an OOM bug.

Jon, is bug 1144108 a likely regressor?

Comment 1

[Gary Kwong [:gkw] [:nth10sd] (NOT official MoCo now)]

Attachment: stack of opt crash

(lldb) bt 5
* thread #1: tid = 0x80832, 0x005383d2 js-32-dm-nsprBuild-darwin-cbd0efcd976c`unsigned long js::gc::Arena::finalize<JSObject>(js::FreeOp*, js::gc::AllocKind, unsigned long) [inlined] js::ObjectGroup::clasp(this=0x4b4b4b4b) const at ObjectGroup.h:199, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x4b4b4b4b)
  * frame #0: 0x005383d2 js-32-dm-nsprBuild-darwin-cbd0efcd976c`unsigned long js::gc::Arena::finalize<JSObject>(js::FreeOp*, js::gc::AllocKind, unsigned long) [inlined] js::ObjectGroup::clasp(this=0x4b4b4b4b) const at ObjectGroup.h:199
    frame #1: 0x005383d2 js-32-dm-nsprBuild-darwin-cbd0efcd976c`unsigned long js::gc::Arena::finalize<JSObject>(js::FreeOp*, js::gc::AllocKind, unsigned long) [inlined] JSObject::getClass() const + 3 at jsobj.h:128
    frame #2: 0x005383cf js-32-dm-nsprBuild-darwin-cbd0efcd976c`unsigned long js::gc::Arena::finalize<JSObject>(js::FreeOp*, js::gc::AllocKind, unsigned long) [inlined] JSObject::finalize(fop=<unavailable>) at jsobjinlines.h:59
    frame #3: 0x005383cf js-32-dm-nsprBuild-darwin-cbd0efcd976c`unsigned long js::gc::Arena::finalize<JSObject>(this=<unavailable>, fop=0x0004f300, thingKind=OBJECT8_BACKGROUND, thingSize=<unavailable>) + 415 at jsgc.cpp:500
    frame #4: 0x004dae81 js-32-dm-nsprBuild-darwin-cbd0efcd976c`FinalizeArenas(js::FreeOp*, js::gc::ArenaHeader**, js::gc::SortedArenaList&, js::gc::AllocKind, js::SliceBudget&, js::gc::ArenaLists::KeepArenasEnum) [inlined] bool FinalizeTypedArenas<JSObject>(src=0xbfffe028, keepArenas=<unavailable>) + 219 at jsgc.cpp:560
(lldb)

Comment 2

[Gary Kwong [:gkw] [:nth10sd] (NOT official MoCo now)]

Attachment: debug stack

(lldb) bt 5
* thread #1: tid = 0x804da, 0x0089ce26 js-dbg-32-dm-nsprBuild-darwin-cbd0efcd976c`JSObject::finalize(js::FreeOp*) [inlined] js::ObjectGroup::clasp(this=0x4b4b4b4b) const at ObjectGroup.h:199, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x4b4b4b4b)
  * frame #0: 0x0089ce26 js-dbg-32-dm-nsprBuild-darwin-cbd0efcd976c`JSObject::finalize(js::FreeOp*) [inlined] js::ObjectGroup::clasp(this=0x4b4b4b4b) const at ObjectGroup.h:199
    frame #1: 0x0089ce26 js-dbg-32-dm-nsprBuild-darwin-cbd0efcd976c`JSObject::finalize(js::FreeOp*) [inlined] JSObject::getClass(this=0x0411b060) const + 2 at jsobj.h:128
    frame #2: 0x0089ce24 js-dbg-32-dm-nsprBuild-darwin-cbd0efcd976c`JSObject::finalize(this=0x0411b060, fop=0xbfffdfb0) + 116 at jsobjinlines.h:59
    frame #3: 0x0089c5a2 js-dbg-32-dm-nsprBuild-darwin-cbd0efcd976c`unsigned long js::gc::Arena::finalize<JSObject>(this=<unavailable>, fop=<unavailable>, thingKind=<unavailable>, thingSize=<unavailable>) + 450 at jsgc.cpp:500
    frame #4: 0x007f8e1c js-dbg-32-dm-nsprBuild-darwin-cbd0efcd976c`FinalizeArenas(js::FreeOp*, js::gc::ArenaHeader**, js::gc::SortedArenaList&, js::gc::AllocKind, js::SliceBudget&, js::gc::ArenaLists::KeepArenasEnum) [inlined] bool FinalizeTypedArenas<JSObject>(src=0xbfffdf68, dest=<unavailable>) + 220 at jsgc.cpp:560
(lldb)

Comment 3

[Jon Coppeard (:jonco)]

It looks like the free span for an arena allocated while inside the debugger onGarbageCollection hook is not being correctly update.  When we come to sweeping we try to finalize a cell that has not been initialized.  I can't see how this is happening however.

Changin the onGarbageCollection hook to use a runnable rather than being called directly by the GC would likely fix this problem.

Comment 4

[Andrew McCreight [:mccr8]]

Lowering to moderate because it requires the debugger do something.

Comment 5

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

(In reply to Jon Coppeard (:jonco) from comment #3)
> Changin the onGarbageCollection hook to use a runnable rather than being
> called directly by the GC would likely fix this problem.

Note: it will likely be a bit before I get around to this b/c it isn't part of my Q1 goals.

Comment 6

[Jon Coppeard (:jonco)]

What's happening is that a last ditch GC is triggered (due to setting maxBytes) and after that we are able to allocate a new arena.  But the debugger callback that ran at the end of GC also allocated a new new arena for the required kind, and GCRuntime::refillFreeListFromMainThread() ignores that possibility, overwriting the free list with the span of another arena.  So we lose the fact that any of the original arena's cells were not allocated, and when we sweep we try and finalize them all.

This is only a problem if any of the GC callbacks are allowed to allocate GC things.  At the moment this debugger callback definitely does, but this might be possible for the cycle collector ones too.

Comment 7

[Jon Coppeard (:jonco)]

This is fallout from bug 1130475.

Comment 8

[Jon Coppeard (:jonco)]

Attachment: last-ditch-fix

Comment 9

[Andrew McCreight [:mccr8]]

(In reply to Jon Coppeard (:jonco) from comment #6)
> This is only a problem if any of the GC callbacks are allowed to allocate GC
> things.  At the moment this debugger callback definitely does, but this
> might be possible for the cycle collector ones too.

I don't think it does, though there are a few logging things that are not on by default that might possibly do that.

Comment 10

[Terrence Cole [:terrence]]

Comment on attachment 8583145 [details] [diff] [review]
last-ditch-fix

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

Ouch!

Comment 11

[Jon Coppeard (:jonco)]

Added testcase and pushed:

https://hg.mozilla.org/integration/mozilla-inbound/rev/eaf2526ffd90

Comment 12

[Jon Coppeard (:jonco)]

Fixed testcase not to fail with too much recursion on opt builds:

https://hg.mozilla.org/integration/mozilla-inbound/rev/49aa36d0b28a

Comment 13

[Jon Coppeard (:jonco)]

And backed out again for continued presence of jit-test failures:

https://hg.mozilla.org/integration/mozilla-inbound/rev/aef75ff8a911

Comment 14

[Jon Coppeard (:jonco)]

Fixed testcase and re-landed:

https://hg.mozilla.org/integration/mozilla-inbound/rev/f1bd22adbd0c

Comment 15

[Jon Coppeard (:jonco)]

And more test bustage, this time on Windows.

https://hg.mozilla.org/integration/mozilla-inbound/rev/490d2e6a5026

Comment 16

[Ryan VanderMeulen [:RyanVM]]

Backed out for being the likely cause of intermittent (but reasonably frequent) leaks during mochitest-bc/dt runs.
https://hg.mozilla.org/integration/mozilla-inbound/rev/5ff215f33d8f

https://treeherder.mozilla.org/logviewer.html#?job_id=8228712&repo=mozilla-inbound
https://treeherder.mozilla.org/logviewer.html#?job_id=8229054&repo=mozilla-inbound
etc...

Comment 17

[Ryan VanderMeulen [:RyanVM]]

Only took 3 attempts, but we finally found the actual culprits for the leaks in comment 16. Wasn't this bug. Re-landed.
https://hg.mozilla.org/integration/mozilla-inbound/rev/a9137f699a08

Comment 18

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Backed that out in https://hg.mozilla.org/integration/mozilla-inbound/rev/17b64ef6cb4b because now linux cgc tests are permafailing:

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

Comment 19

[Jon Coppeard (:jonco)]

(In reply to Wes Kocher (:KWierso) from comment #18)
> now linux cgc tests are permafailing:

Right, I think that's due to bug 1145997.  Looks like we'll need to fix that first.

Comment 20

[Jon Coppeard (:jonco)]

CGC tests are green on try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ca1e3baf60a1

Re-re-landing:

https://hg.mozilla.org/integration/mozilla-inbound/rev/2efcea316e96

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/2efcea316e96

Please nominate this for Aurora/Beta approval when you get a chance.

Comment 22

[Jon Coppeard (:jonco)]

Comment on attachment 8583145 [details] [diff] [review]
last-ditch-fix

Approval Request Comment
[Feature/regressing bug #]: Bug 1130475.
[User impact if declined]: Possible crash in low memory conditions.
[Describe test coverage new/current, TreeHerder]: On central since yesterday.
[Risks and why]: Low.
[String/UUID change made/needed]: None.

Comment 23

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8583145 [details] [diff] [review]
last-ditch-fix

Should be in 38 beta 2

Comment 24

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/1131368d1567

Comment 25

[Ryan VanderMeulen [:RyanVM]]

Needs rebasing for beta.

Comment 26

[Christian Holler (:decoder)]

JSBugMon: This bug has been automatically verified fixed.
JSBugMon: This bug has been automatically verified fixed on Fx39

Comment 27

[Ryan VanderMeulen [:RyanVM]]

Looks like Jon landed this on beta.
https://hg.mozilla.org/releases/mozilla-beta/rev/484a6aef6a4f