911570 - JavaScript in XUL runs 5-40 times slower than in HTML

Status: RESOLVED WORKSFORME

(Core :: JavaScript Engine, defect)

Description

[Peter B. Shalimoff]

Attachment: zip_inflate_test.xpi

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:22.0) Gecko/20100101 SeaMonkey/2.19 (Beta/Release)
Build ID: 20130625001820

Steps to reproduce:

Install the attached XPI and go to the test pages. The same code, only markup is different.
1) chrome://zip_inflate_test/content/test.html
2) chrome://zip_inflate_test/content/test_inline.html
3) chrome://zip_inflate_test/content/test.xul
4) chrome://zip_inflate_test/content/test_inline.xul



Actual results:

The code in XUL runs 5 times slower. I get the following average times for 100 passes:
1) test.html: mean: 62.65, median: 52
2) test_inline.html: mean: 64.09, median: 53
3) test.xul: mean: 314.39, median: 287.5 (got the "Script running too slow" prompt at pass 68)
4) test_inline.xul: mean: 311.07, median: 286.5 (the same prompt at pass 69).

In my real situation (an extension), the same code runs 40 (forty) times slower: 60 ms in HTML vs 2400 ms in XUL. The code is in a separate file, loaded with mozIJSSubScriptLoader::loadSubScript(), invoked from my listener's nsIRequestObserver::onStopRequest method. Using Components.utils.import() doesn't make any difference. My other "heavy math" code that resides in the same file code and gets invoked after the zip_inflate() function, runs 10 times slower: 80 ms in HTML vs 800 ms in XUL.

Comment 1

[Phoenix]

Same in Firefox, moving to Core

Comment 2

[Till Schneidereit [:till]]

This is almost certainly due to chrome scripts not using type inference and IonMonkey. In bug 907201, I added about:config flags for activating them, and it is my intention to get them activated by default soon. At that point, these scripts should run as fast in XUL as they do in HTML.

Comment 3

[Boris Zbarsky [:bzbarsky]]

Looks like the "HTML" version gets ion-compiled and the "xul" version does not.  

You real situation is likely bug 776798: you're probably not getting a JIT at all, due to running in a component.  It's hard to tell without seeing the exact code the real situation is using, including exactly how it's loaded.

But that shouldn't be affecting the direct loads of chrome:// URLs in the content area.  Looking into what's going on there.

Comment 4

[Boris Zbarsky [:bzbarsky]]

> This is almost certainly due to chrome scripts not using type inference and IonMonkey.

At first glance, none of the above are "chrome" scripts for purposes of the flags in bug 907201.

Comment 5

[Peter B. Shalimoff]

(In reply to Boris Zbarsky [:bz] from comment #3)
> You real situation is likely bug 776798: you're probably not getting a JIT
> at all, due to running in a component.  It's hard to tell without seeing the
> exact code the real situation is using, including exactly how it's loaded.

My real situatuion is FlashGot (http://flashgot.net/getit), and it doesn't use nsITimerCallback and the other things mentioned in bug 776798 (like setTimeout/setInterval), so that doesn't seem to be my case. Unless my listener's onStopRequest method is called from one of those things?
The code is loaded by a component though:
flashgotService.js loads MediaSniffer.js,
MediaSniffer.js loads Youtube.js,
Youtube.js loads YoutubeSwf.js,
YoutubeSwf.js contains the zip_inflate() function.
The listener is in Youtube.js, in the Youtube.refresh_signature_func() function:
    var stream_listener = {
        onStartRequest: ...,
        onStopRequest: function(){ call a function that calls zip_inflate() },
        onDataAvailable: ...};
    Components.classes["@mozilla.org/network/io-service;1"]
      .getService(Components.interfaces.nsIIOService)
      .newChannel(url, null, null)
      .asyncOpen(stream_listener, null);

Comment 6

[Boris Zbarsky [:bzbarsky]]

> Unless my listener's onStopRequest method is called from one of those things?

onStopRequest and the timer callback setup are functionally identical in terms of how the JS gets called: in both cases it's C++ code calling into JS via XPCWrappedJS.

What matters at that point is where the code implementing onStopRequest lives.  If it's in a JS component, then you're seeing bug 776798.

But, again, the testcase in this bug shows there is also some other problem, since in that testcase the code does _not_ live in a JS component but in a Window.  And a content window at that.

Comment 7

[Peter B. Shalimoff]

Tested my real situation on a brand new Firefox 23.0.1 installation, with only FlashGot installed, i.e. no other extensions and userscripts I have in SeaMonkey. Slightly better times, but still slower.

Build identifier: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:23.0) Gecko/20100101 Firefox/23.0

zip_inflate: 1600 ms (instead of 2400 ms),
the other "heavy" code: 580 ms (instead of 800 ms).

The attached XPI gives the following times for 100 passes:
1) test.html: mean: 53.93, median: 44.5
2) test_inline.html: mean: 50.53, median: 43
3) test.xul: mean: 251.65, median: 223 ("too slow" prompt at pass 85)
4) test_inline.xul: mean: mean: 249.92, median: 233.5 (the same prompt at pass 86)

Comment 8

[Peter B. Shalimoff]

Tested both FlashGot and the attached XPI in the nightly build 26.0a1 (buildID 20130906030202), with both javascript.options.ion.chrome and javascript.options.typeinference.chrome enabled. Compared to my previous results in Firefox 23.0.1, the XPI's times are the same, and FlashGot's times are slightly greater:
zip_inflate: 1800 ms
the other code: 700 ms

Comment 9

[Peter B. Shalimoff]

Installed the Remote XUL Manager add-on (https://addons.mozilla.org/en-US/firefox/addon/remote-xul-manager/) and tested the XUL as local files (via the file: protocol): the times are the same as in the XPI.
Moved the code to workers: XUL times, both in local files and in the XPI, are almost the same as in HTML.
Will attach the new XPI, it has 2 additional test URLs:
1) chrome://zip_inflate_test/content/test_worker.html
2) chrome://zip_inflate_test/content/test_worker.xul

Comment 10

[Peter B. Shalimoff]

Attachment: zip_inflate_test.xpi

Updated the XPI with 2 additional test that use workers:
1) chrome://zip_inflate_test/content/test_worker.html
2) chrome://zip_inflate_test/content/test_worker.xul

Comment 11

[Peter B. Shalimoff]

(In reply to Peter B. Shalimoff from comment #9)
> Moved the code to workers: XUL times, both in local files and in the XPI,
> are almost the same as in HTML.

Sorry, I lied (got lost between SeaMonkey and Firefox windows): the times are the same as in HTML.

Comment 12

[Till Schneidereit [:till]]

I've tried finding out where ion and/or TI (and thus, indirectly, ion as well) are disabled here. Rather unsuccessfully, I must say.

Calling JS_GetOptions from within JS_NewGlobalObject as invoked by xpc::CreateGlobalObject shows ion and TI both active. After that, there's a call to JS_SetOptions from under nsGlobalWindow::SetNewDocument, but that also doesn't deactivate ion or TI.

There are some invocations of nsXPCWrappedJS::CallMethod from under nsDocumentViewer::Init (via nsAutoScriptBlocker::~nsAutoScriptBlocker), and those have ion and TI disabled, but they didn't look related to me.

bholley, you know how window creation works in XPCOM, right? Maybe you also know a place where we check for the document type and disable ion and TI for XUL documents?

Comment 13

[Boris Zbarsky [:bzbarsky]]

Well, it's also possible that we _are_ ion-compiling but just making a heck of a lot more stubcalls than in the HTML case.  It's hard to tell whether scripts actually got ion-compiled or not.  :(

We have no special checks for document type to disable ion or TI on the DOM end.

Comment 14

[Till Schneidereit [:till]]

Using h4writer's tracelogging support, I verified that we spend all time in baseline in the xul version.

I know that we don't explicitly special check for document type, but given that ion and TI are activated during window creation, something document-type related seems to be going on, nevertheless.

Comment 15

[Boris Zbarsky [:bzbarsky]]

Well, the things I know of that XUL does somewhat interestingly:

1)  Background bytecode compilation on the safe context (which I bet does NOT have ion
    enabled).  But note that this is a trunk thing, so I doubt Peter is running into this.
2)  Scripts compiled without COMPILE_N_GO.  Though that may be the case for non-XUL too
    nowadays.

If you want to see what's going on when we enter the JS engine, you can put a breakpoint in XULDocument::ExecuteScript (the two-argument version) and see what things look like when we make the JS_ExecuteScript call....  At that point we have a cx and a JSScript*; I don't know what the relevant things to look for on those objects are.

Comment 16

[Bobby Holley (:bholley)]

Another thing to note is that XUL documents tend to have a much deeper parent chain, because node reflectors are parented to their parent element rather than the document.

Comment 17

[Boris Zbarsky [:bzbarsky]]

According to bug 915485, the "without compile-n-go" bit would in fact disable Ion.

Comment 18

[Till Schneidereit [:till]]

This is still a problem, so I'm betting on compile-n-go. Blocking on its removal.

Comment 19

[Jan de Mooij [:jandem]]

With Firefox 29 and 30:

test.html:        Average (ms): mean: 21.79, median: 16
test_inline.html: Average (ms): mean: 21.71, median: 16
test.xul:         Average (ms): mean: 126.05, median: 123
test_inline.xul:  Average (ms): mean: 128.8, median: 126

Nightly:

test.html:        Average (ms): mean: 19.86, median: 16.5
test_inline.html: Average (ms): mean: 20.14, median: 16.5
test.xul:         Average (ms): mean: 85.06, median: 82
test_inline.xul:  Average (ms): mean: 95.71, median: 85

The XUL improvement is likely from bug 1045529; we can Ion-compile more chrome functions now. We're still 5x slower than the HTML one though.

More than 50% of the time is under js::SetObjectElement. Our type information is probably worse somehow; I want to investigate this a bit more.

Non-CNG code will probably always be slower than CNG code, due to CNG-only name optimizations in the frontend, but it shouldn't be this much slower.

Comment 20

[Jan de Mooij [:jandem]]

Attachment: Shell testcase

I can reproduce this in the shell if I turn off CNG in shell/js.cpp

Comment 21

[Jan de Mooij [:jandem]]

(In reply to Jan de Mooij [:jandem] from comment #19)
> More than 50% of the time is under js::SetObjectElement. Our type
> information is probably worse somehow; I want to investigate this a bit more.

OK, we're not using allocation-site specific TypeObjects in non-CNG code. Removing the CNG check in TypeScript::NewObject improves this dramatically. Since CPG this should be fine but hopefully it won't affect memory usage too much... Will file a bug.

Comment 22

[Jan de Mooij [:jandem]]

(In reply to Jan de Mooij [:jandem] from comment #19)
> Nightly:
> 
> test.html:        Average (ms): mean: 19.86, median: 16.5
> test_inline.html: Average (ms): mean: 20.14, median: 16.5
> test.xul:         Average (ms): mean: 85.06, median: 82
> test_inline.xul:  Average (ms): mean: 95.71, median: 85

With the latest Nightly (includes patches for bug 1064777) I get:

test.xul:         Average (ms): mean: 27.4, median: 23
test_inline.xul:  Average (ms): mean: 27.5, median: 23

So it's still a bit slower, but way better than the 5-7x slowdown we had before.

Comment 23

[Peter B. Shalimoff]

(In reply to Jan de Mooij [:jandem] from comment #19)
> With Firefox 29 and 30:
> 
> test.html:        Average (ms): mean: 21.79, median: 16
> test_inline.html: Average (ms): mean: 21.71, median: 16
> test.xul:         Average (ms): mean: 126.05, median: 123
> test_inline.xul:  Average (ms): mean: 128.8, median: 126

What did you do to get that difference for XUL? Because compared to my previous results in 23.0.1 (see comment #7), I see no difference for XUL in Firefox 32.0.1.
test.html: Average (ms): mean: 26.64, median: 23
test.xul: Average (ms): mean: 264.67, median: 242

Same results with javascript.options.ion.chrome and javascript.options.typeinference.chrome set to true:
test.html: Average (ms): mean: 26.39, median: 23
test.xul: Average (ms): mean: 261.29, median: 241.5

Nightly:
test.html: Average (ms): mean: 26.4, median: 22
test.xul: Average (ms): mean: 39.54, median: 35

Comment 24

[Florian Bender]

Peter, would you mind re-trying with the latest Nightly?

Comment 25

[Peter B. Shalimoff]

Nightly 32-bit, 37.0a1 (2014-11-30):
test.html: Average (ms): mean: 25.87, median: 23
test.xul: Average (ms): mean: 37.04, median: 34

Nightly 64-bit, 37.0a1 (2014-11-30):
test.html: Average (ms): mean: 32.81, median: 29
test:xul: Average (ms): mean: 45.49, median: 41.5

Comment 26

[Peter B. Shalimoff]

Attachment: C/C++ port

Just for the record, some stats for this code ported as-is to an ugly mix of C and C++ and compiled with GCC.
Compiled with -O2: 12 ms.
Compiled with -O0: 40 ms.
I guess I'll attach it just in case.

Comment 27

[Peter B. Shalimoff]

Attachment: zip_inflate_test.cpp.zip

Forgot I attach the test input file.

Comment 28

[Boris Zbarsky [:bzbarsky]]

In a current nighty with the patches from bug 679939:

test.html:        Average (ms): mean: 21.38, median: 17
test_inline.html: Average (ms): mean: 22.92, median: 19
test.xul:         Average (ms): mean: 25.5, median: 21
test_inline.xul:  Average (ms): mean: 26.85, median: 22

so we're clearly not 5-40 times slower anymore, or anything close to that.