Closed Bug 19014 Opened 25 years ago Closed 25 years ago

JS engine order of magnitude slower since last week

Categories

(Core :: JavaScript Engine, defect, P3)

x86
Windows NT
defect

Tracking

()

VERIFIED FIXED

People

(Reporter: jband_mozilla, Assigned: brendan)

Details

Attachments

(1 file)

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);
Status: NEW → ASSIGNED
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
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.
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
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.
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
Status: ASSIGNED → RESOLVED
Closed: 25 years ago
Resolution: --- → FIXED
Fixed, r=brendan, blame=brendan. I'll make up for this blunder, yes I will. /be
Status: RESOLVED → VERIFIED
Looks OK to me. It clearly restores the old logic - and with a comment now :) Fixes the slowdown in my test case. Thanks.
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: