679977 - TM: Variable assignment fails, gets assigned undefined

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Jon Buckley]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:6.0) Gecko/20100101 Firefox/6.0
Build ID: 20110811165603

Steps to reproduce:

In the process of developing Processing.js v1.3, we started running into a strange error in our reference test suite where the variable assignment would fail, and get assigned undefined instead.

I've managed to reduce this problem a little, and have a github branch up at https://github.com/jbuck/processing-js/tree/firefox-bug/ . You can also visit http://jbuckley.ca/~jon/processing-js/test/ref/ if you just want to run it.

To run the test suite, click the "Remove Passed Tests" checkbox, and hit the "Start" button.

This bug is present in Firefox 6 and Firefox Nightly Debug on Mac OS X 10.6 and Windows 7. It also doesn't appear in any of the other major browsers (Chrome, IE9, Safari 5.1, Opera) on either platform.


Actual results:

The test suite will stop executing on test 33 with an error "cachedVertArray is undefined @ http://jbuckley.ca/~jon/processing-js/processing.js:12145"

The interesting part of the code is in the previous for loop:
for (i = 0; i < vertArrayLength; i++) {
  cachedVertArray = vertArray[i]; /* This gets assigned undefined sometimes */
  if (!cachedVertArray) {
    console.log("vertices failed");
    cachedVertArray = vertArray[i]; /* But if we assign it again, it works fine! */




Expected results:

It should've continued drawing the color wheel, rather than dying.

I spoke to several people on #jsapi about this bug:
sstangl: jbuck: it's a JIT bug in JaegerMonkey. If you turn off 'javascript.options.methodjit.content' in about:config, it passes.
sfink: you could also try a debug build to see if you can get an assert out of it

I confirmed that turning off mjit makes the test suite complete properly. The debug build did not give me any useful assertions, just messages related to "WARNING: Unsupported filter type!: file /builds/slave/m-cen-osx64-dbg/build/gfx/layers/opengl/LayerManagerOGL.cpp, line 1172" 

Let me know if I can provide any more information, I'll continue trying to reduce this testcase.

Comment 1

[David Humphrey (:humph)]

Confirmed, I'm bisecting now to try and find a regression window.

Comment 2

[David Humphrey (:humph)]

I can't lock it down, but I've been able to reproduce it back as far as 2010-10-31 (http://hg.mozilla.org/mozilla-central/rev/18caa24f974d) on m-c, so it's not a new regression.

Comment 3

[David Humphrey (:humph)]

One thing about the code that's failing, and which may or may not be related...the array that's being lost by the JIT is being used like this:

var arr = [];
...
arr['some-string'] = true;
...
arr[0] = someNumber;
arr[1] = someOtherNumber;
...

We know this is wrong, and should be an object vs. an array, but I thought I'd mention it in case it's relevant.

Comment 4

[Boris Zbarsky [:bzbarsky]]

This looks bad...

Comment 5

[Jan de Mooij [:jandem]]

Looks like a tracer integration bug. I'll try to reduce this.

Comment 6

[Jan de Mooij [:jandem]]

Attachment: Testcase

After converting this to a shell testcase it was fairly easy to automatically reduce. The attached file fails with -j on the TI branch. The initial testcase also failed on mozilla-central with -m -j, but after reducing it only fails on the TI branch. Probably due to some small differences in GC or trace aborts.

$ ./js -j test.js
test.js:28: Error: Assertion failed: got 719, expected 720

===
25 var vertArrayLength = vertArray.length;
26 assertEq(vertArray.length, 720);
27 for (var i = 0; i < vertArrayLength; i++) {
28     assertEq(vertArray.length, 720);
29     var cachedVertArray = vertArray[i];
30     assertEq(cachedVertArray !== undefined, true);
31 }
===
Somehow the array length is invalid inside the loop. Output with TMFLAGS=minimal:
===
Recording starting from test.js:79@19 (FragID=000000)
  [0.879 ms] Tree at line 44 executed for 0 iterations; executed 8 times; leave for LOOP at test.js:43 (lt)
  [0.711 ms] Tree at line 28 executed for 0 iterations; executed 7 times; leave for LOOP at test.js:27 (lt)
Recording completed at  test.js:79@19 via closeLoop (FragID=000000)

  [1.544 ms] Tree at line 79 executed for 0 iterations; executed 1 times; leave for NESTED at test.js:28 (call)
test.js:28: Error: Assertion failed: got 719, expected 720
===

Comment 7

[Jan de Mooij [:jandem]]

Throwing back. I've never hacked the tracer before and I don't have much time atm.

Comment 8

[Boris Zbarsky [:bzbarsky]]

My first instinct is that something is stomping on memory somewhere here, which if true is really bad.  dmandelin, can we find someone to look at this?

Comment 9

[Terrence Cole [:terrence]]

Attachment: More minimal testcase.

Inlining the first draw appears to remove the failure without changing the order of calls to arc, so I think this is about as minimal as it is likely to get.

Comment 10

[Shu-yu Guo [:shu]]

The loop that's traced in |endShape| never gets re-traced. When it first gets traced, the trace bakes in the Call object from |(new Processing(Processing.compile(0))).draw();|.

When we trace the outer loop in |compile| in |new Processing(Processing.compile(1));|, we link to the existing |endShape| trace that we have. But that trace has the wrong Call object baked in!

We should be bailing on a guard somewhere that isn't happening. Will investigate further.

Comment 11

[Shu-yu Guo [:shu]]

(In reply to Shu-yu Guo [:shu] from comment #10)
> The loop that's traced in |endShape| never gets re-traced. When it first
> gets traced, the trace bakes in the Call object from |(new
> Processing(Processing.compile(0))).draw();|.
> 
> When we trace the outer loop in |compile| in |new
> Processing(Processing.compile(1));|, we link to the existing |endShape|
> trace that we have. But that trace has the wrong Call object baked in!
> 
> We should be bailing on a guard somewhere that isn't happening. Will
> investigate further.

What I said wasn't entirely correct. This is a really subtle bug!

What's actually going on is that the first call to |draw| causes us to record a trace of |arc| where its parent is a deactivated stack frame. This causes the upvar lookup of |vertArray| to be baked in without us guarding on the callee's parent. The tracer, I guess, assumes that we never get a deactivated stack frame without |guardCallee| also being called, which this bug shows to be false. So when we construct the second Processing object, we end up stitching in the recorded |draw| trace even though the closure for |arc| is now a completely different object. So when we execute that trace we've been pushing into the |vertArray| in the first closure, not the second.

Comment 12

[Shu-yu Guo [:shu]]

Attachment: Even more minimal testcase

It's important that we keep the |assertEq(true, true)| line, as importing it between the first and second Processing creation perturbs the global object shape, causing re-recording, which in fact fixes the bug.

Comment 13

[Shu-yu Guo [:shu]]

Attachment: Fix

When I tested this bug is present in m-c and m-i also, not just JM.

Comment 14

[Andreas Gal :gal]

Comment on attachment 556747 [details] [diff] [review]
Fix

Nice fix.

Comment 15

[David Mandelin [:dmandelin]]

Comment on attachment 556747 [details] [diff] [review]
Fix

Only one review is needed. Shu, thanks much for fixing this!

Comment 16

[Ed Morley [:emorley]]

Shu, thanks for the patch :-) It's in my queue with a few other bits that are being sent to try first and then onto inbound.

To save time for future patches, could you set your hgrc to include the author automatically & also add a commit message, along the lines of:
http://blog.bonardo.net/2010/06/22/so-youre-about-to-use-checkin-needed

Thanks :-)

Comment 17

[Shu-yu Guo [:shu]]

Hi Ed,

Sorry for the bad formatting. I'll attach a properly formatted patch.

Comment 18

[Shu-yu Guo [:shu]]

Attachment: Properly formatted patch and testcase

Comment 19

[Ed Morley [:emorley]]

Thanks Shu :-)

http://tbpl.allizom.org/?usebuildbot=1&tree=Try&rev=e9351f9ab296

http://hg.mozilla.org/integration/mozilla-inbound/rev/72974e2ef258

Comment 20

[Marco Bonardo [:mak]]

http://hg.mozilla.org/mozilla-central/rev/72974e2ef258

Comment 21

[Brendan Eich [:brendan]]

Shu has progressed to level of tracing-JIT badass!

/be

Comment 22

[Jon Buckley]

Just tested my firefox-bug branch with the Aug 31st Nightly, and it worked properly!

Thanks for the quick turn-around on this bug shu