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

RESOLVED WORKSFORME

Status

()

Core
JavaScript Engine
RESOLVED WORKSFORME
4 years ago
2 years ago

People

(Reporter: Peter B. Shalimoff, Unassigned)

Tracking

(Blocks: 1 bug)

Trunk
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(3 attachments, 2 obsolete attachments)

1.44 MB, application/octet-stream
Details
328.97 KB, application/x-bzip
Details
366.60 KB, application/zip
Details
(Reporter)

Description

4 years ago
Created attachment 798289 [details]
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

4 years ago
Same in Firefox, moving to Core
Assignee: nobody → general
Status: UNCONFIRMED → NEW
Component: General → JavaScript Engine
Ever confirmed: true
OS: Windows 7 → All
Product: SeaMonkey → Core
Hardware: x86_64 → All
Version: SeaMonkey 2.19 Branch → Trunk
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.
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.
> 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.
Blocks: 913182
(Reporter)

Comment 5

4 years ago
(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);
> 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.
(Reporter)

Comment 7

4 years ago
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)
(Reporter)

Comment 8

4 years ago
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
(Reporter)

Updated

4 years ago
Attachment #798289 - Attachment is obsolete: true
(Reporter)

Comment 9

4 years ago
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
(Reporter)

Comment 10

4 years ago
Created attachment 801107 [details]
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
(Reporter)

Comment 11

4 years ago
(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.
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?
Flags: needinfo?(bobbyholley+bmo)
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.
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.
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.
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.
Flags: needinfo?(bobbyholley+bmo)
According to bug 915485, the "without compile-n-go" bit would in fact disable Ion.
This is still a problem, so I'm betting on compile-n-go. Blocking on its removal.
Depends on: 679939
(Assignee)

Updated

3 years ago
Assignee: general → nobody
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.
Flags: needinfo?(jdemooij)
Created attachment 8486296 [details]
Shell testcase

I can reproduce this in the shell if I turn off CNG in shell/js.cpp
(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.
Flags: needinfo?(jdemooij)

Updated

3 years ago
Depends on: 1064777
(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.
(Reporter)

Comment 23

3 years ago
(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

3 years ago
Peter, would you mind re-trying with the latest Nightly?
Flags: needinfo?(vshalimhr)
(Reporter)

Comment 25

3 years ago
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
(Reporter)

Comment 26

3 years ago
Created attachment 8530752 [details]
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.
Flags: needinfo?(vshalimhr)
(Reporter)

Comment 27

3 years ago
Created attachment 8530761 [details]
zip_inflate_test.cpp.zip

Forgot I attach the test input file.
Attachment #8530752 - Attachment is obsolete: true
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.
Status: NEW → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.