797692 - OOM (malloc mmap fail) with testcase involving Iterator

Status: RESOLVED INVALID

(Core :: JavaScript Engine, defect)

Description

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

y = 'x'
y += 'x'
y += y
for (var a = 0; a < 99; a++) {
    this.w += y
}
for (z in [{}, {}, (7), (7), {}, {}, {}, (7), {}, (7), (7), (7), {}, {}]) {
    eval("w+=w", {})
}
Iterator(w, true)


shows the following error on 32-bit js debug and opt shell on m-c changeset 1a2f506b1a92 without any CLI arguments:

malloc: *** mmap(size=8388608) failed (error code=12)
*** error: can't allocate region
*** set a breakpoint in malloc_error_break to debug

Compilation command on 10.7.5 was:

LD=ld CROSS_COMPILE=1 CC="clang -Qunused-arguments -fcolor-diagnostics -arch i386" RANLIB=ranlib CXX="clang++ -Qunused-arguments -fcolor-diagnostics -arch i386" AS=$CC AR=ar STRIP="strip -x -S" HOST_CC="clang -Qunused-arguments -fcolor-diagnostics" HOST_CXX="clang++ -Qunused-arguments -fcolor-diagnostics" sh /Users/fuzz3/Desktop/jsfunfuzz-dbg-32-mozilla-central-109038-1a2f506b1a92-V1oiPC/compilePath/js/src/configure --target=i386-apple-darwin9.2.0 --enable-macos-target=10.5 --enable-optimize --disable-debug --enable-profiling --enable-gczeal --enable-debug-symbols --enable-methodjit --enable-type-inference --enable-more-deterministic --disable-tests --enable-valgrind

autoBisect shows this is probably related to the following changeset:

The first bad revision is:
changeset:   94274:648093316d93
user:        Jason Orendorff
date:        Thu May 17 18:54:30 2012 -0500
summary:     Bug 755808 - Add more options to JS shell evaluate() function. r=jimb.

Comment 1

[Jason Orendorff [:jorendorff]]

This produces the same error on my machine. I doubt the evaluate() changeset is really relevant.

var w = "x";
for (var i = 0; i < 23; i++)
    w += w;
Iterator(w, true);

Comment 2

[Jim Blandy :jimb]

It's not clear to me that this is a bug, nor that the changeset suggested by autoBisect is relevant.

I could not reproduce the crash on 64-bit Linux, but I did look at the memory consumption before and after the changeset; it seemed to peak at around 1GiB in both changesets.

Changeset 648093316d93 doesn't seem to touch anything that the test case uses. It changes one test in js/src/jit-test/debug, and changes the implementation of 'evaluate' (not 'eval') in js/src/shell/js.cpp. As far as I can tell, that code should never be executed by the given test case.

Gary, could you verify that this test case crashes, reproducibly, in changesets that include 648093316d93, but does not in earlier changesets? Just, say, a handful before and after would be enough to persuade me the changeset is relevant. Does it matter if one starts or stops other memory-hungry processes on the same machine?

Even if it does, perhaps what's going on is that this test uses *almost* enough memory to crash, and that changeset happens to push it over the edge. That would not be a flaw in the changeset.

Comment 3

[Jim Blandy :jimb]

(In reply to Jason Orendorff [:jorendorff] from comment #1)
> This produces the same error on my machine. I doubt the evaluate() changeset
> is really relevant.
> 
> var w = "x";
> for (var i = 0; i < 23; i++)
>     w += w;
> Iterator(w, true);

I'll bet all those "+=" operations are producing ropes, and the call to Iterator flattens it. I'm surprised a 16MiB string (2^23 * sizeof(jschar)) breaks us, though.

Comment 4

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

That blamed changeset is a red herring - I'm re-running autoBisect on jorendorff's testcase in comment 1.

Comment 5

[Jason Orendorff [:jorendorff]]

Maybe the JS_MORE_DETERMINISTIC code in Snapshot is causing this. It does a largeish MergeSort with a fairly gross comparator, which is enough to trigger GC at least.

If I rebuild with --disable-more-deterministic, the error doesn't happen.

Comment 6

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

> That blamed changeset is a red herring - I'm re-running autoBisect on
> jorendorff's testcase in comment 1.

autoBisect shows this is probably related to the following changeset:

The first bad revision is:
changeset:   87140:2a8ceeb27f7c
user:        Bill McCloskey
date:        Fri Feb 17 14:35:20 2012 -0800
summary:     Bug 641025 - Incremental GC (r=igor,smaug,roc,cdleary,gregor)

Comment 7

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

Attachment: stack from setting a breakpoint at malloc_error_break on gdb

Comment 8

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

I have a hypothesis for what's going on here.

* We have a big string with 2^23 characters and we wrap it in a string object.
* We call the enumerate hook on the string object.
* For each character, enumerate is creating a dependent string that is 1 character long.
* Then it adds that 1-character string as an element of the string object (i.e., a property with an integer ID).
* Then we create several vectors to hold all these shapes and their propids and sort them.
* During the sorting, inside the comparator, we convert each integer-valued propid to a string. We allocate a new string each time.

In the last step, while appending to one of these vectors, malloc crashes with this weird error. I googled for the error, and it seems to be a general sort of "running out of memory" error. I don't see why it doesn't return NULL the way it's supposed to. The shell is not built with jemalloc, and I suspect that jemalloc would behave differently and return NULL the way we expect. Then we'd have a chance at handling the error in our usual blundering way.

When I run the test before incremental GC landed, we get a bunch of last ditch GCs. During the sorting process, these GCs allow us to clean up the strings that are created by previous comparator calls. After incremental GC, there are no last ditch GCs, so we don't clean them up and we use more memory.

The reason I removed these sort of last ditch GCs is that they messed up incremental GC. On the one hand, you want last ditch GCs to be non-incremental because they signal that we're running low on memory and we need to reclaim right away. On the other hand, we actually used to get last ditch GCs all the time, and that was causing lots of non-incremental collections to be triggered. Specifically, last ditch GC would trigger whenever we exceeded gcTriggerBytes (which happens pretty commonly) and allocated again before running the operation callback. This is something that happens pretty much at random, and it doesn't in any way signal the need for immediate GC.

Consequently, I changed the trigger for last ditch GCs. One way to fix this would be to add back more last ditch GCs (but not so many that we get them in normal situations). Another solution would be to invoke the operation callback in some of these big loops. We should probably do that anyway, since we spend several seconds in them, and we probably want a chance to show the slow script dialog during that time.

In summary, a few things are going wrong here:
1. The Mac malloc implementation seems to be broken regarding OOMs.
2. We're not invoking the operation callback enough.
3. JS_MORE_DETERMINISTIC causes lots of extra allocations that cause its behavior to diverge significantly from a normal build.
4. We may not be doing enough last ditch GCs.

Comment 9

[Terrence Cole [:terrence]]

It looks like OSX's malloc is just broken on x86.  If this repo'd with je_malloc, it would be concerning, but as is, I don't think there is anything we can or should do here.