848803 - JS engine changes in Nightly have broken JSIL demos

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Katelyn Gadd (:kael)]

Recent JS engine changes in Nightly have broken JSIL demos such that they frequently fail while parsing type names (JSIL.ParseTypeName) during the process of loading content (typically XNA SpriteFont assets). In particular, I can reproduce this almost 100% of the time by running Escape Goat (see URL) in Nightly. It still works fine in Chrome and Aurora and I've verified that this isn't caused by any recent code changes on my end.

I can't debug this because enabling Firebug or the built-in Debugger causes the browser to perform horribly and hang indefinitely roughly when the error would have occurred.

Occasionally it does work in Nightly which makes me suspect the problem is intermittent somehow.

One possibility I haven't ruled out is that the startup code could be overflowing the stack; type initialization is by necessity recursive and I know SpiderMonkey responds incredibly poorly to stack overflows.

The failure looks like this in the log (click Show Log):

Unhandled exception at line 0:
uncaught exception: Microsoft.Xna.Framework.Content.ContentLoadException: Failed to load asset 'DebugFont' because an asset loader threw an exception.
-- Inner exception follows --
Error: The type 'Microsoft.Xna.Framework.Content.SpriteFontReader, Microsoft.Xna.Framework.Graphics, Version=4.0.0.0, Culture=neutral, PublicKeyToken=842cf8be1de50553' could not be found while loading asset 'DebugFont'.

Marking 848665 as a dependency since that debugger problem prevents me from looking into this further myself (apologies if that's wrong :D)

URL tested and working in:

Aurora 21.0a2 (2013-03-06)
Chrome Version 27.0.1432.0 canary
IE 10.0.9200.16521

Comment 1

[Katelyn Gadd (:kael)]

Managed to manually capture a stack from the failure. Doesn't look like a stack overflow:

[08:13:32.808] Failure stack:  ReadTypeManifest@http://127.0.0.1:82/static/Libraries/JSIL.XNA.Content.js:564
PreInitMethod_Invoke@http://127.0.0.1:82/static/Libraries/JSIL.Core.js:476
PreInitMethod_Invoke@http://127.0.0.1:82/static/Libraries/JSIL.Core.js:476
ReadHeader@http://127.0.0.1:82/static/Libraries/JSIL.XNA.Content.js:700
RawXNBAsset_ReadAsset@http://127.0.0.1:82/static/Libraries/JSIL.XNA.Core.js:158
ContentManager_Load@http://127.0.0.1:82/static/Libraries/JSIL.XNA.Content.js:51
Microsoft_Xna_Framework_Content_ContentManager_Load$b1@http://127.0.0.1:82/static/Libraries/JSIL.Core.js:2415
BoundGenericMethod_Invoke@http://127.0.0.1:82/static/Libraries/JSIL.Core.js:4724
BastilleGame_LoadContent@http://127.0.0.1:82/static/EscapeGoat,%20Version=1.0.5.0,%20Culture=neutral,%20PublicKeyToken=null.js:13655
@http://127.0.0.1:82/static/Libraries/JSIL.XNA.Core.js:1220
BastilleGame_Initialize@http://127.0.0.1:82/static/EscapeGoat,%20Version=1.0.5.0,%20Culture=neutral,%20PublicKeyToken=null.js:13627
@http://127.0.0.1:82/static/Libraries/JSIL.XNA.Core.js:1305
doRunMain@http://127.0.0.1:82/static/Scripts/Main.js:381
runMain@http://127.0.0.1:82/static/Scripts/Main.js:392
browserFinishedLoadingCallback@http://127.0.0.1:82/static/Libraries/JSIL.Browser.js:1050

Comment 2

[Boris Zbarsky [:bzbarsky]]

Is there a regression range by chance?

Comment 3

[Luke Wagner [:luke]]

(In reply to Kevin Gadd (:kael) from comment #0)
> One possibility I haven't ruled out is that the startup code could be
> overflowing the stack; type initialization is by necessity recursive and I
> know SpiderMonkey responds incredibly poorly to stack overflows.

It is OOM we respond poorly too, stack overflow reliably generates an exception and is somewhat well-tested.

Comment 4

[Katelyn Gadd (:kael)]

No. Is there a bisect tool out there I could run to generate you one? Alternately, a folder full of dated nightly builds would be enough.

Comment 5

[Boris Zbarsky [:bzbarsky]]

http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/ and http://harthur.github.com/mozregression/

Comment 6

[Katelyn Gadd (:kael)]

I already tried digging through the nightly builds folder but I couldn't make sense of all the branch names and the layout of the folders. It'd be great to have a 'build names for dummies' page somewhere easy-to-find that explains what branch name is trunk and how to find the build for a given date.

I'm installing mozregression right now, thanks.

Comment 7

[Katelyn Gadd (:kael)]

(In reply to Luke Wagner [:luke] from comment #3)
> (In reply to Kevin Gadd (:kael) from comment #0)
> > One possibility I haven't ruled out is that the startup code could be
> > overflowing the stack; type initialization is by necessity recursive and I
> > know SpiderMonkey responds incredibly poorly to stack overflows.
> 
> It is OOM we respond poorly too, stack overflow reliably generates an
> exception and is somewhat well-tested.

That's really good to hear; the last time I had to debug a JS stack overflow in Firefox it required setting breakpoints in the JS engine from a debugger and extracting the stack by looking at locals. :)


(In reply to Boris Zbarsky (:bz) from comment #5)
> http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/ and
> http://harthur.github.com/mozregression/

OK, mozregression rules. Here's a preliminary regression range (I tested loading the game 3 times in each build)

Last good nightly: 2013-02-22
First bad nightly: 2013-02-23

Pushlog:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=885cde564ff3&tochange=08a034e1d43a

I'll try and bisect with local builds but no promises; I always seem to have trouble building firefox locally.

Comment 8

[Boris Zbarsky [:bzbarsky]]

Trunk is "mozilla-central", for what it's worth.

There's a bunch of jseng changes in that regression range, unfortunately.  :(

Comment 9

[Katelyn Gadd (:kael)]

(In reply to Boris Zbarsky (:bz) from comment #8)
> Trunk is "mozilla-central", for what it's worth.
> 
> There's a bunch of jseng changes in that regression range, unfortunately.  :(

Yeah, when I looked at the pushlog my brain made a little slide whistle noise. I've got mozregression doing the fetch/build for a bisect, so maybe that'll be fast and I'll be able to nail down a commit or group of commits.

If I can ease debugging this by adding instrumentation to the JS, let me know and I can push a new build to that public server and give you a URL for it.

Comment 10

[Katelyn Gadd (:kael)]

OK, I can't figure out how to get mozregression to bisect commits. I already had to fiddle with my mercurial.ini and deviate from the directions on the mozregression site so it could find my compiler, but I don't know what to do about this:

Adding configure options from c:/Users/Kevin\.moz-commitbuilder-cache\mozconf\config-default:
  --disable-optimize
  --enable-debug
  --enable-tests
  --with-windows-version=600
  --enable-application=browser
configure: error: Invalid value for --with-windows-version (600)
make[2]: *** [configure] Error 1
make[1]: *** [/c/Users/Kevin/.moz-commitbuilder-cache/mozbuild-trunk/obj-ff-dbg/Makefile] Error 2
make: *** [build] Error 2

Comment 11

[Alice0775 White]

Regression window(m-c)
Good:
http://hg.mozilla.org/mozilla-central/rev/885cde564ff3
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:22.0) Gecko/20130221 Firefox/22.0 ID:20130221115546
Bad:
http://hg.mozilla.org/mozilla-central/rev/67f2a2816651
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:22.0) Gecko/20130221 Firefox/22.0 ID:20130222031138
Pushlog:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=885cde564ff3&tochange=67f2a2816651

Regression window(m-i)
Good:
http://hg.mozilla.org/integration/mozilla-inbound/rev/45a1e69221ef
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:22.0) Gecko/20130221 Firefox/22.0 ID:20130221064259
Bad:
http://hg.mozilla.org/integration/mozilla-inbound/rev/9fb2083111af
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:22.0) Gecko/20130221 Firefox/22.0 ID:20130221065759
Pushlog:
http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=45a1e69221ef&tochange=9fb2083111af

Suspicion bug: Bug 843038, Bug 843518

Comment 12

[Alice0775 White]

In local build:
Last Good: 9d5e10ca36a4
First Bad: 9fb2083111af
Triggered by :
9fb2083111af	Hannes Verschore — Bug 843038: IonMonkey: Correct the definition of when an instruction is part of the loop, r=jandem

Comment 13

[Hannes Verschore [:h4writer]]

The bug shows itself in "JSIL.ParseTypeNameImpl" (JSIL.Core.js:5764). And only when ion-parallel-compile=on. I.e. when users have 2+ cores. Else the function is to big to get compiled by ionmonkey.

Comment 14

[Hannes Verschore [:h4writer]]

Can you provide a standalone version of this? So I can run it locally.
It's been a pain in the ass to debug this problem remotely.

Comment 15

[Katelyn Gadd (:kael)]

Attachment: Headless version of code that breaks

Here's a headless version of the code that breaks in the browser. Sadly, no matter what I do I can't get this to break in the JS shell, but I figure it might still be useful...

Comment 16

[Katelyn Gadd (:kael)]

till and dvander on #jsapi helped me figure out a way to intermittently reproduce this in the js shell using the headless test case:

js --ion-parallel-compile=on --no-jm --ion-eager runTest.js

Will sometimes cause the failure to occur a few times during the startup phase of the headless test. Interestingly, the actual loop where it loads the asset never seems to fail. Some sort of race.

You're looking for the text 'could not be found while loading asset'. A failure looks like this:


C:\Users\Kevin\Desktop\ParseTypeNameBug>js --ion-parallel-compile=on --no-jm --ion-eager runTest.js
Loading DebugFont.xnb 1024 time(s)
Could not resolve open generic parameter 'System.Threading.Tasks.Shared`1.T' when building field list for type 'System.T
hreading.Tasks.Shared`1'

Could not resolve open generic parameter 'System.Threading.Tasks.Task`1.TResult' when building field list for type 'Syst
em.Threading.Tasks.Task`1'

The external method 'void .ctor()' of type 'System.IO.Stream' has not been implemented; calling inherited method.

The external method 'void .ctor()' of type 'System.MarshalByRefObject' has not been implemented; calling inherited metho
d.

The external method 'System.Int32 ReadByte()' of type 'System.IO.MemoryStream' has not been implemented; calling inherit
ed method.

The type 'Microsoft.Xna.Framework.Content.Texture2DReader, Microsoft.Xna.Framework.Graphics, Version=4.0.0.0, Culture=ne
utral, PublicKeyToken=842cf8be1de50553' could not be found while loading asset 'DebugFont'.
ReadTypeManifest@TestLibraries/JSIL.XNA.Content.js:564
PreInitMethod_Invoke@TestLibraries/JSIL.Core.js:476
PreInitMethod_Invoke@TestLibraries/JSIL.Core.js:476
ReadHeader@TestLibraries/JSIL.XNA.Content.js:697
RawXNBAsset_ReadAsset@TestLibraries/JSIL.XNA.Core.js:161
[e-mail]:145
shellStartup@TestLibraries/JSIL.Shell.js:105
@runTest.js:157

The type 'Microsoft.Xna.Framework.Content.SpriteFontReader, Microsoft.Xna.Framework.Graphics, Version=4.0.0.0, Culture=n
eutral, PublicKeyToken=842cf8be1de50553' could not be found while loading asset 'DebugFont'.
ReadTypeManifest@TestLibraries/JSIL.XNA.Content.js:564
PreInitMethod_Invoke@TestLibraries/JSIL.Core.js:476
PreInitMethod_Invoke@TestLibraries/JSIL.Core.js:476
ReadHeader@TestLibraries/JSIL.XNA.Content.js:697
RawXNBAsset_ReadAsset@TestLibraries/JSIL.XNA.Core.js:161
[e-mail]:145
shellStartup@TestLibraries/JSIL.Shell.js:105
@runTest.js:157

The type 'Microsoft.Xna.Framework.Content.SpriteFontReader, Microsoft.Xna.Framework.Graphics, Version=4.0.0.0, Culture=n
eutral, PublicKeyToken=842cf8be1de50553' could not be found while loading asset 'DebugFont'.
ReadTypeManifest@TestLibraries/JSIL.XNA.Content.js:564
PreInitMethod_Invoke@TestLibraries/JSIL.Core.js:476
PreInitMethod_Invoke@TestLibraries/JSIL.Core.js:476
ReadHeader@TestLibraries/JSIL.XNA.Content.js:697
RawXNBAsset_ReadAsset@TestLibraries/JSIL.XNA.Core.js:161
[e-mail]:145
shellStartup@TestLibraries/JSIL.Shell.js:105
@runTest.js:157

The external method 'System.Single ReadSingle()' of type 'Microsoft.Xna.Framework.Content.ContentReader' has not been im
plemented; calling inherited method.

Could not resolve open generic parameter 'System.Nullable`1.T' when building field list for type 'System.Nullable`1'

....................................................................^C

Comment 17

[Katelyn Gadd (:kael)]

More fiddling: js --no-jm --ion-eager runTest.js makes it completely busted. Fails every loop iteration. Not sure why parallel compile makes it better...

Comment 18

[Hannes Verschore [:h4writer]]

Attachment: Reduced js testcase

Thanks gkw for helping on this one. This testcase shouldn't assert under ionmonkey. There is something fishy going on. Looks like u.assembly isn't set to the right value, but looking at LIRs, the opcodes are correct.

Comment 19

[Hannes Verschore [:h4writer]]

Attachment: Don't hoist if instruction depends on store in/after the loop

Comment 20

[Hannes Verschore [:h4writer]]

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

Comment 21

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/a9e5d4379740

Comment 22

[Katelyn Gadd (:kael)]

Confirmed fixed in 22.0a1 (2013-03-14)