860109 - "Assertion failure: addr % CellSize == 0"

Status: RESOLVED INACTIVE

(Core :: JavaScript Engine, defect)

Description

[ISHIKAWA, Chiaki]

+++ This bug was initially created as a clone of Bug #841487 +++(
I experienced something similar and posted a question there.)

Hi,

I am seeing this particular error in "make mozmill" test of TB (comm-central)
under memcheck. (Done on local PC)
Funny thing is that "make mozmill" runs to completion without valgrind/memcheck.

I suspect that my filling malloc'ed area and free'ed area with known different non-zero patterns under memgrind may lead to a different behavior under memcheck.
(Or the different timing under memgrind may reveal dormant thread races.)

The session log excerpt:

Assertion failure: addr % CellSize == 0, at /COMM-CENTRAL/comm-central/mozilla/js/src/gc/Heap.h:1012

==6885== Invalid write of size 4
==6885==    at 0xB414C89: js::gc::Cell::chunk() const (Heap.h:1012)
==6885==    by 0xB4244C4: js::gc::Cell::isTenured() const (Heap.h:950)
==6885==    by 0xB6E7E29: void MarkInternal<js::GlobalObject>(JSTracer*, js::GlobalObject**) (Heap.h:987)
==6885==    by 0xB6EECAF: js::gc::MarkKind(JSTracer*, void**, JSGCTraceKind) (Marking.cpp:360)
==6885==    by 0xB364C6F: JS_CallGenericTracer(JSTracer*, void*, char const*) (jsapi.cpp:2513)
==6885==    by 0x9D616D8: TraceJSObject(void*, char const*, void*) (XPCJSRuntime.cpp:414)
==6885==    by 0x981AD16: nsJSEventListener::cycleCollection::TraceImpl(void*, void (*)(void*, char const*, void*), void*) (nsJSEventListener.cpp:106)
==6885==    by 0x9D5FDC7: TraceJSHolder(void*, nsScriptObjectTracer*&, void*) (XPCJSRuntime.cpp:420)
==6885==    by 0x9D5FEAD: nsBaseHashtable<nsPtrHashKey<void>, nsScriptObjectTracer*, nsScriptObjectTracer*>::s_EnumStub(PLDHashTable*, PLDHashEntryHdr*, unsigned int, void*) (nsBaseHashtable.h:454)
==6885==    by 0xAD762DC: PL_DHashTableEnumerate (pldhash.cpp:714)
==6885==    by 0x9D690D4: XPCJSRuntime::TraceXPConnectRoots(JSTracer*) (nsBaseHashtable.h:223)
==6885==    by 0x9D69155: XPCJSRuntime::TraceGrayJS(JSTracer*, void*) (XPCJSRuntime.cpp:408)
==6885==    by 0xB6DE909: js::gc::BufferGrayRoots(js::GCMarker*) (RootMarking.cpp:781)
==6885==    by 0xB4438DB: BeginMarkPhase(JSRuntime*) (jsgc.cpp:2834)
        [...]

==6885==  Address 0x0 is not stack'd, malloc'd or (recently) free'd
==6885==



It looks that it happens inside GC activity.

I have switched my linker from stock GNU ld to "gold" recently.
Can this be related to the bug? 
I am asking because the patch mentioned in the original bug 
contains some references to "gold".

> Probably a regression from this inbound merge:
> https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=aceeea086ccb

About the time I switched to "gold", I suddenly have begun to see a crash test of plugin-container to take place during "make mozmill" test of TB, so I was wondering if switching to "gold" may have wider implications than I thought. But this may be a coincidence.

In the original bug, it was mentioned,

>I turned off gczeal(8) for now in the DOM fuzzer.

Is this some kind of test flag for M-C source?
But there does not seem to be a way to turn it off for TB testing(?)

Anyway, seeing an incorrect memory address during "make mozmill"
is surely a bad sign.

TIA



TIA

Comment 1

[Andrew McCreight [:mccr8]]

This basically means that nsJSEventListener is holding onto a bad object.  I don't recall offhand what the % CellSize thing means...

Comment 2

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Can you see if it reproduces in earlier revisions? That would tell us if it has anything to do with gold, and then we could find a regression range.

Comment 3

[ISHIKAWA, Chiaki]

(In reply to Bill McCloskey (:billm) from comment #2)
> Can you see if it reproduces in earlier revisions? That would tell us if it
> has anything to do with gold, and then we could find a regression range.

It may take a few days [this is because I think I need to use valgrind/memcheck to take advantage of filling memory with known non-zero values, and its change of execution timing. I am afraid that these both must be present to trigger the bug. I forgot to explain that execution of "make mozmill" WITHOUT valgrind/memcheck ran to completion without crash(es).

So the difference of memory allocation handling, and timing issues have something
to do with the GC-related issues I am seeing.
[I have another in the log.

I will file another bugzilla entry.]
 


The test takes time since running "make mozmill" using valgrind/memcheck is SLOW.
It took almost one and half a day to finish the run this time.
(I think the additional crashes and its dead wait time by gdb, and others added at least one hour or so to the total elapsed time.)

So I will try to obtain a rough estimate.
My idea is to test the version one month ago first.
Depending on the outcome,
- I will investigate the version 15 days ago if the testing of one month old
source is OK.
- I will investigate the version two months ago if the testing of one month old
source is already bad.

TIA

PS: If both turn out to be OK, then it is likely that "gold" has something to do?

Comment 4

[ISHIKAWA, Chiaki]

(In reply to Bill McCloskey (:billm) from comment #2)
> Can you see if it reproduces in earlier revisions? That would tell us if it
> has anything to do with gold, and then we could find a regression range.

It may take much longer since I am afraid that it is GC-related and depending on the timing of GC invocation, I see the failure either don't see it.
My five tries produced two positives but three others didn't :-(
And each run takes time.

But I was lucky enough to notice that a run produced this error, and at that time, memcheck offered me five minutes window to attach gdb to the busted process so that
I could check the stack and others. 
Most notably, I found that the filling of freed area with a known fixed pattern 
seemed to be good practice to trigger this problem if the timing of GC is right.
Memcheck allowed me to set the malloc'ed area and free'ed area with known patterns.
--malloc-fill=0xA5 --free-fill=0xC3

So if there is an malloc library that allows me to specify the fill-in values
for debugging purposes, and the library is known to work with TB,　Ｉ can run the
test (make "mozmill" without memcheck at full speed to see if it produces 
memory error. Hopefully, I can try 5 times and if no error is seen, the particular revision source tree is free from the bug.
For bisecting purposes, running test under memcheck is way too slow.)

Can anyone suggest such an malloc library (if it exists)?
GNU malloc seems to allow me to define hooks, but that may sound a little complicated.

Oh wait, I thought the crashed program had a value in a pointer fieled
with the filled in value by memcheck (0xA5, 0xC3) but
it is filled with 0xDADADADA:
CheckMarkedThing<js::GlobalObject> (thing=
    (js::GlobalObject *) 0xeb793a0 Cannot access memory at address 0xdadadada, trc=<optimized out>)

Does mozilla code filled in free'ed area with its own pattern for DEBUG BUILD?

TIA

Comment 5

[Terrence Cole [:terrence]]

(In reply to ISHIKAWA, chiaki from comment #4)
> Does mozilla code filled in free'ed area with its own pattern for DEBUG
> BUILD?

0xDADADADA is the free pattern for GC'd things, so this object is being used after it has been collected by the GC. You should find out why the pointer you have here was not keeping the object alive.

Also note, GC things are allocated using mmap/VirtualAlloc, not malloc, so a malloc shim would not help here. Although, we already have our own free pattern, so I guess it's not a problem.

Comment 6

[ISHIKAWA, Chiaki]

(In reply to Terrence Cole [:terrence] from comment #5)
> (In reply to ISHIKAWA, chiaki from comment #4)
> > Does mozilla code filled in free'ed area with its own pattern for DEBUG
> > BUILD?
> 
> 0xDADADADA is the free pattern for GC'd things, so this object is being used
> after it has been collected by the GC. You should find out why the pointer
> you have here was not keeping the object alive.
> 
> Also note, GC things are allocated using mmap/VirtualAlloc, not malloc, so a
> malloc shim would not help here. Although, we already have our own free
> pattern, so I guess it's not a problem.

Thank you for the explanation of 0xDADADADA.
I will try to figure out why, but again, the symptom seems to be very
timing sensitive. I get maybe a clean hit in 5 runs of "make mozmill" using memcheck().
I am trying to see if I can re-create the issue without memcheck(valgrind) by
inserting a call to mallopt() to fill the malloc'ed region and free'ed region
from the viewpoint of system malloc library (but that may not help at all...)
So bisecting is a little out of hope due to the time it takes to run one "make mozmill" session (almost a day, and it may or may not produce a desired GC error :-() Grrr...

But I will keep the session running so that if the timing is right, I will be near the PC and that I can attach gdb quickly to the aborted session in the five minute window that "make mozmill" gives me before beginning next test target.

TIA

PS: On the other hand, I get a consistent crashminidump failure (it tried to access a no-longer-existing lock [nullptr], and causes its own stack dump. This must be the case of crashdump being lost after a crash is reported. This is observed immediately after the intentional crash of plugin-wrapper.
Also, I am seeing sporadically random crashes during shutdown sequence. The symptom is diverse, but it points to a family of problem. I also experienced
similar crashes when I tried to shutdown thunderbird (AND firefox) in the last few months in real-world usage, and I suspect they are the same.
I wonder why these crashes are not observed by others. Maybe my polluting memory area using mallopt() is indeed effective in triggering these problems (malloc() no longer returns zeroed-area even if it returns the system memory for the first time.) Or could it be Debian GNU/Linux's external libraries have something to do.
I am hoping to report more substantial information, but again, this seems to take time before collecting enough data points.

Comment 7

[Terrence Cole [:terrence]]

(In reply to ISHIKAWA, chiaki from comment #6)
> Thank you for the explanation of 0xDADADADA.
> I will try to figure out why, but again, the symptom seems to be very
> timing sensitive. I get maybe a clean hit in 5 runs of "make mozmill" using
> memcheck().

Yes, GCs happen semi-randomly based on a timer and the sizes of external resources. Since GC issues usually depend on the GC happening during the live region of the incorrectly rooted value, it's not surprising that the failure is sporadic.

> I am trying to see if I can re-create the issue without memcheck(valgrind) by
> inserting a call to mallopt() to fill the malloc'ed region and free'ed region
> from the viewpoint of system malloc library (but that may not help at all...)

The pointer that is not being correctly traced is still reachable afterwards, so filling freed memory is not likely to help unless there is a second use-after-free bug.

> So bisecting is a little out of hope due to the time it takes to run one
> "make mozmill" session (almost a day, and it may or may not produce a
> desired GC error :-() Grrr...
> 
> But I will keep the session running so that if the timing is right, I will
> be near the PC and that I can attach gdb quickly to the aborted session in
> the five minute window that "make mozmill" gives me before beginning next
> test target.

A backtrace would likely point you right at the failure in this case, so it is probably a worthwhile time investment.
 
> TIA
> 
> PS: On the other hand, I get a consistent crashminidump failure (it tried to
> access a no-longer-existing lock [nullptr], and causes its own stack dump.
> This must be the case of crashdump being lost after a crash is reported.
> This is observed immediately after the intentional crash of plugin-wrapper.
> Also, I am seeing sporadically random crashes during shutdown sequence. The
> symptom is diverse, but it points to a family of problem. I also experienced
> similar crashes when I tried to shutdown thunderbird (AND firefox) in the
> last few months in real-world usage, and I suspect they are the same.
> I wonder why these crashes are not observed by others. Maybe my polluting
> memory area using mallopt() is indeed effective in triggering these problems
> (malloc() no longer returns zeroed-area even if it returns the system memory
> for the first time.) Or could it be Debian GNU/Linux's external libraries
> have something to do.
> I am hoping to report more substantial information, but again, this seems to
> take time before collecting enough data points.

Are these crashes all on the same machine? I've seen a couple cases where a bad stick of RAM was the culprit, although those generally lead to more diverse crash signatures and other system instability. It may be worth running memtest86 overnight anyway to rule out the possibility.

Comment 8

[ISHIKAWA, Chiaki]

Thank you again for the hints.
After thinking about the problems I saw, I also think 
trying to find a the path where the bad cell (or object) is being
found would be the most likely way to dig up the culrpit. 
(I am familiar with old fashioned 
Lisp-like GC where all the objects have the same resources except maybe for string or vectors, but from my cursory reading of the mozilla code, each subsystem (module i a subdirectory) needs its own handling of objects
under the subdirectory. Is there a comprehensive or introductory document to
the current GC implementation used in mozilla code?
(I found the use of terms a little confusing, also. Mark/Sweep, I understand. But "trace" is something I am unfamiliar with.)

> Are these crashes all on the same machine? I've seen a couple cases where a
> bad stick of RAM was the culprit, although those generally lead to more
> diverse crash signatures and other system instability. It may be worth
> running memtest86 overnight anyway to rule out the possibility.

It is on the same machine. But from the repeated runs, some of the strange
crashes I saw are repeatable (!).
Also, this machine uses ECC memory and I don't think memory hardware is an issue. Well...
(Yes, I specifically bought this small server model to avoid memory related issues. To me using 8GB of main memory without ECC is unbelievable. I got bitten by a flaky hardware long time ago, and so if ECC is available, that is the way to go. Too bad, AMD CPU ditches memory controller that supports ECC from low-end CPU now.)

TIA

Comment 9

[Terrence Cole [:terrence]]

(In reply to ISHIKAWA, chiaki from comment #8)
> Thank you again for the hints.
> After thinking about the problems I saw, I also think 
> trying to find a the path where the bad cell (or object) is being
> found would be the most likely way to dig up the culrpit. 

Agreed.

> (I am familiar with old fashioned 
> Lisp-like GC where all the objects have the same resources except maybe for
> string or vectors, but from my cursory reading of the mozilla code, each
> subsystem (module i a subdirectory) needs its own handling of objects
> under the subdirectory. Is there a comprehensive or introductory document to
> the current GC implementation used in mozilla code?
> (I found the use of terms a little confusing, also. Mark/Sweep, I
> understand. But "trace" is something I am unfamiliar with.)

Memory in mozilla is typically located in one of two heaps. C++ objects use the standard |new| allocator and uses refcounting to track liveness. JS objects are allocated by the SpiderMonkey GC and the GC tracks liveness.

In mozilla code, "tracing" refers to the act of traversing an object graph as implemented by the tracing infrastructure in JSAPI (JS_InitTracer, JS_Call*Tracer, etc). Marking (as in Mark/Sweep) uses the tracing infrastructure to determine liveness, however, the tracing infrastructure is also used for a number of other purposes, e.g. DumpHeap and CycleCollector integration.

The SpiderMonkey GC is under active development at the moment. The most up to date info is probably in this wiki article, but it is probably is a bit lower-level than you want.
https://developer.mozilla.org/en-US/docs/SpiderMonkey/Internals/Garbage_collection

> > Are these crashes all on the same machine? I've seen a couple cases where a
> > bad stick of RAM was the culprit, although those generally lead to more
> > diverse crash signatures and other system instability. It may be worth
> > running memtest86 overnight anyway to rule out the possibility.
> 
> It is on the same machine. But from the repeated runs, some of the strange
> crashes I saw are repeatable (!).
> Also, this machine uses ECC memory and I don't think memory hardware is an
> issue. Well...
> (Yes, I specifically bought this small server model to avoid memory related
> issues. To me using 8GB of main memory without ECC is unbelievable. I got
> bitten by a flaky hardware long time ago, and so if ECC is available, that
> is the way to go. Too bad, AMD CPU ditches memory controller that supports
> ECC from low-end CPU now.)
> 
> TIA

Well, at least we can rule out memory corruption.

Comment 10

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

Not sure if this is still valid. Development on mozmill has been stopped. Paul, do you mind checking that the stack in comment 0 doesn't show a problem anymore?

Comment 11

[Paul Bone [:pbone]]

(In reply to Gary Kwong [:gkw] [:nth10sd] from comment #10)
> Not sure if this is still valid. Development on mozmill has been stopped.
> Paul, do you mind checking that the stack in comment 0 doesn't show a
> problem anymore?

More than that, the bug is so old that so much will have changed in the GC that if this bug hasn't already been fixed, then it will have moved so much that this bug report can't be used anymore.  There's no clear/efficient way of finding out if this bug still exists.

Comment 12

[ISHIKAWA, Chiaki]

Agreed. It is too old. My mozmill runs these days get tripped by other seemingly timing-related assertions.