19014 - JS engine order of magnitude slower since last week

Status: VERIFIED FIXED

(Core :: JavaScript Engine, defect, P3)

Description

[John Bandhauer]

Brendan, this is another bug that I've tracked to your 11/11/1999 13:52 jsengine
checkin. Again I'm doing dumb QA and letting you figure out what might be the
cause of the problem.

I noticed that my informal xpconnect speed tests suddenly showed calls using
xpconnect are faster than calls in plain JS (after being 3 or 4 times slower).

So I tested with xpconnect out of the picture.

Using the plain jsshell on NT and the code shown below I get output for the two
tests (in seconds):
                       old tree         new tree
Debug build...         .02 and .04     .22 and .53
Release build...       .00 and .00     .06 and .15

The project file did not change so no new build flags are in effect. The tests
focus on repeated name resolution and function calls.

The test code I used was...

print(".......................................");
print("simple speed tests...");

var iterations = 1000;

var receiver2 = new Object();
receiver2.SetReceiver = function() {};
receiver2.SendOneString = function(str) {/*print(str);*/};

var echoJS = new Object();
echoJS.SetReceiver = function(r) {this.r = r;};
echoJS.SendOneString = function(str) {if(this.r)this.r.SendOneString(str)};
echoJS.SimpleCallNoEcho = function(){}

/*********************************************/
/*********************************************/

print("\nEcho.SimpleCallNoEcho (just makes call with no params and no
callback)");
var start_time = new Date().getTime()/1000;
echoJS.SetReceiver(receiver2);
for(i = 0; i < iterations; i++)
    echoJS.SimpleCallNoEcho();
var end_time = new Date().getTime()/1000;
var interval = parseInt(100*(end_time - start_time),10)/100;
print("JS control did "+iterations+" iterations in "+interval+ " seconds.");

/*
var start_time = new Date().getTime()/1000;
echo.SetReceiver(receiver2);
for(i = 0; i < iterations; i++)
    echo.SimpleCallNoEcho();
var end_time = new Date().getTime()/1000;
var interval = parseInt(100*(end_time - start_time),10)/100;
print("XPConnect  did "+iterations+" iterations in "+interval+ " seconds.");
*/

/*********************************************/

print("\nEcho.SendOneString (calls a callback that does a call)");
var start_time = new Date().getTime()/1000;
echoJS.SetReceiver(receiver2);
for(i = 0; i < iterations; i++)
    echoJS.SendOneString("foo");
var end_time = new Date().getTime()/1000;
var interval = parseInt(100*(end_time - start_time),10)/100;
print("JS control did "+iterations+" iterations in "+interval+ " seconds.");

/*
var start_time = new Date().getTime()/1000;
echo.SetReceiver(receiver2);
for(i = 0; i < iterations; i++)
    echo.SendOneString("foo");
var end_time = new Date().getTime()/1000;
var interval = parseInt(100*(end_time - start_time),10)/100;
print("XPConnect  did "+iterations+" iterations in "+interval+ " seconds.");
*/

print(".......................................");

echoJS.SetReceiver(null);

Comment 1

[Brendan Eich [:brendan]]

I'll look into this pronto.  It's not expected; my changes essentially moved
costs from compile to runtime, with a little bytecode overhead added.  It may be
that the property cache is busted due to some unintended change (mine or anyone
who checked in).  Cc'ing waterson for review and profiling help.

/be

Comment 2

[John Bandhauer]

Hey I got visual quantify. I set it up and did a couple of runs and am looking
at the run diff in the tool. That was the easy part.

The big time costing diffs are the mallocs/frees. The old code had about 2k
calls of each the new code has 44k calls.

The biggest call count diff is js_list_scope_lookup: 260 -> 51k calls. Many
are from js_LookupProperty. A big time contributer here is js_PutCallObject.
Interestingly there are a nearly equal number of calls to js_Invoke
(3022->3027), but js_PutArgsObject and js_PutCallObject go from 0 -> 3003.

The only call count diff that significantly lower in the new code is
JS_EnumerateStub which goes from 15k -> 0.

All the kinda stuff associated with property lookups - hashing, messing with
object maps, compare functions, etc - have big diffs.

I really don't know this stuff well enough to debug it effectively. I hope these
clues help. I can help go over the data in Visual Quantify tomorrow (or
whatever is needed) if it will help.

John.

Comment 3

[Brendan Eich [:brendan]]

Dammit, unintended consequences forsooth -- loads of Call objects being created
instead of good ol' brendan-hacked Function objects proxying for all activations
of their code.  Thanks, this helps a lot.  More soon.

/be

Comment 4

[John Bandhauer]

For posterity's sake... brendan's checkin in question is the one on
"11/11/1999 22:03". I pasted the wrong value into the top of this report.

Comment 5

[Brendan Eich [:brendan]]

Pure-D regression: I deoptimized top-level lambda expressions to use full-weight
closure calling, which is required only for function definitions and lambda
expressions nested in other functions, and lambdas in top-level with statements.
All that logic I worked out years ago really was needed!  Too much ECMA spec
simplicity on my brain.

Patch in next update.

/be

Comment 6

[Brendan Eich [:brendan]]

Attachment: restore my old logic for function definition bytecode selection

Comment 7

[Brendan Eich [:brendan]]

Fixed, r=brendan, blame=brendan.  I'll make up for this blunder, yes I will.

/be

Comment 8

[John Bandhauer]

Looks OK to me. It clearly restores the old logic - and with a comment now :)
Fixes the slowdown in my test case.

Thanks.