Closed Bug 673205 Opened 13 years ago Closed 13 years ago

Defining Object properties becomes 1200x slower per property after 64k props

Categories

(Core :: JavaScript Engine, defect)

Product:
Core
Component:
JavaScript Engine
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED DUPLICATE of bug 639727

People

(Reporter: andrew, Unassigned)

Details

The following script:

var a = {};
for (var i = 0; i < 131072; ++i) {
    a[i] = 1;
}

when run in a custom shell which uses the interruptHook to capture the wall/cpu time for each line of JS execution illustrates a clear jump in wall/cpu time once the inner loop is executed >= 65539 times. This is a drastic jump in constant time (1200x slower).

Here is the chunk of output showing the clear jump from 0.02ms per execution to 24ms per execution. The line # being executed is printed as well as the count of times it has been called so far. (The JSD_* API calls are not being included in the wall/user time being printed, so it should just be the engine code from one call of interruptHook to the next.)

line #1 count 1 wall 0.000018 user 0.000000
line #2 count 1 wall 0.000013 user 0.000000
line #1 count 2 wall 0.000032 user 0.000000
line #2 count 2 wall 0.000027 user 0.000000
line #3 count 1 wall 0.000025 user 0.000000
line #2 count 3 wall 0.000024 user 0.000000
line #3 count 2 wall 0.000019 user 0.000000
line #2 count 4 wall 0.000019 user 0.000000
line #3 count 3 wall 0.000019 user 0.000000
line #2 count 5 wall 0.000019 user 0.000000
line #3 count 4 wall 0.000019 user 0.000000
...
line #2 count 65529 wall 0.000022 user 0.000000
line #3 count 65528 wall 0.000020 user 0.000000
line #2 count 65530 wall 0.000020 user 0.000000
line #3 count 65529 wall 0.000022 user 0.000000
line #2 count 65531 wall 0.000020 user 0.000000
line #3 count 65530 wall 0.000022 user 0.000000
line #2 count 65532 wall 0.000020 user 0.000000
line #3 count 65531 wall 0.000022 user 0.000000
line #2 count 65533 wall 0.000019 user 0.000000
line #3 count 65532 wall 0.000053 user 0.000000
line #2 count 65534 wall 0.000025 user 0.000000
line #3 count 65533 wall 0.000019 user 0.000000
line #2 count 65535 wall 0.000025 user 0.000000
line #3 count 65534 wall 0.000021 user 0.000000
line #2 count 65536 wall 0.000021 user 0.000000
line #3 count 65535 wall 0.000021 user 0.000000
line #2 count 65537 wall 0.000022 user 0.000000
line #3 count 65536 wall 0.000021 user 0.000000
line #2 count 65538 wall 0.000021 user 0.000000
line #3 count 65537 wall 0.000022 user 0.000000
line #2 count 65539 wall 0.000021 user 0.000000
line #3 count 65538 wall 0.000021 user 0.000000
line #2 count 65540 wall 0.000022 user 0.000000
line #3 count 65539 wall 0.011858 user 0.010000
line #2 count 65541 wall 0.026398 user 0.020000 <-- !!! from now on...
line #3 count 65540 wall 0.005045 user 0.010000
line #2 count 65542 wall 0.026433 user 0.030000
line #3 count 65541 wall 0.005037 user 0.000000
line #2 count 65543 wall 0.024764 user 0.030000
line #3 count 65542 wall 0.005054 user 0.000000
line #2 count 65544 wall 0.022932 user 0.020000
line #3 count 65543 wall 0.005048 user 0.010000
line #2 count 65545 wall 0.022988 user 0.020000
line #3 count 65544 wall 0.005032 user 0.010000
line #2 count 65546 wall 0.022890 user 0.020000
line #3 count 65545 wall 0.005038 user 0.010000
line #2 count 65547 wall 0.022521 user 0.020000
line #3 count 65546 wall 0.005037 user 0.000000
line #2 count 65548 wall 0.024679 user 0.030000
line #3 count 65547 wall 0.005047 user 0.000000
line #2 count 65549 wall 0.023510 user 0.030000
line #3 count 65548 wall 0.005071 user 0.000000
... till the end
I can't reproduce this.

var t0 = Date.now(), t1;
var a = {};
for (var i = 0; i < 128*1024; i++) {
    if (i % 10000 === 0) {
	t1 = Date.now();
	print(i + ": " + (t1 - t0));
	t0 = t1;
    }
    a[i] = 1;
}

gives me results like this:

$ ./d-objdir/js crasher.js
0: 0
10000: 27
20000: 27
30000: 28
40000: 26
50000: 31
60000: 26
70000: 27
80000: 27
90000: 27
100000: 38
110000: 27
120000: 26
130000: 26


$ ./d-objdir/js -j crasher.js
0: 1
10000: 11
20000: 13
30000: 12
40000: 10
50000: 13
60000: 10
70000: 11
80000: 10
90000: 10
100000: 22
110000: 10
120000: 10
130000: 10


$ ./d-objdir/js -m -a crasher.js
0: 0
10000: 11
20000: 11
30000: 11
40000: 10
50000: 15
60000: 9
70000: 11
80000: 11
90000: 10
100000: 23
110000: 9
120000: 10
130000: 11


$ ./d-objdir/js -j -m -p crasher.js
0: 0
10000: 12
20000: 11
30000: 10
40000: 10
50000: 14
60000: 10
70000: 10
80000: 11
90000: 10
100000: 23
110000: 9
120000: 10
130000: 9
I added a GC callback and it turns out that the engine is triggering GC on every iteration past 65538:

line #2 count 65537 wall 0.000019 user 0.000000
line #3 count 65536 wall 0.000019 user 0.000000
line #2 count 65538 wall 0.000019 user 0.000000
line #3 count 65537 wall 0.000019 user 0.000000
line #2 count 65539 wall 0.000019 user 0.000000
line #3 count 65538 wall 0.000019 user 0.000000
line #2 count 65540 wall 0.000019 user 0.000000
line #3 count 65539 wall 0.010362 user 0.000000
JSGC_BEGIN
line #2 count 65541 wall 0.025810 user 0.030000
line #3 count 65540 wall 0.005018 user 0.000000
JSGC_BEGIN
line #2 count 65542 wall 0.025855 user 0.030000
line #3 count 65541 wall 0.005021 user 0.010000
JSGC_BEGIN
line #2 count 65543 wall 0.025383 user 0.020000
line #3 count 65542 wall 0.005010 user 0.010000
JSGC_BEGIN
line #2 count 65544 wall 0.025259 user 0.020000
line #3 count 65543 wall 0.005010 user 0.010000
JSGC_BEGIN
line #2 count 65545 wall 0.025397 user 0.020000
line #3 count 65544 wall 0.005007 user 0.010000
JSGC_BEGIN
line #2 count 65546 wall 0.025842 user 0.020000
line #3 count 65545 wall 0.005013 user 0.010000
JSGC_BEGIN
line #2 count 65547 wall 0.025920 user 0.020000
line #3 count 65546 wall 0.005033 user 0.000000
JSGC_BEGIN
line #2 count 65548 wall 0.025476 user 0.030000
line #3 count 65547 wall 0.005020 user 0.000000
JSGC_BEGIN
line #2 count 65549 wall 0.026012 user 0.030000
line #3 count 65548 wall 0.005020 user 0.000000
JSGC_BEGIN
...
I can reproduce this in the stock shell if I change the default memory parameter for JS_NewRuntime from 160 megs to 4 megs (what I use):

$ js crasher.js
0: 0
10000: 29
20000: 29
30000: 31
40000: 41
50000: 40
60000: 25
70000: 124407
...
If you compile with --enable-gctimer, you'll get a file called gcTimer.dat. It lists each GC. The last field on the line should give an indication of why the GC was done.
Ok, narrowed it down to this call:

JS_SetGCParameter(rt, JSGC_MAX_MALLOC_BYTES, 1024 * 1024);

I create my runtime with JS_NewRuntime(4096*1024), but that alone does not cause this behavior. Setting the JSGC_MAX_MALLOC_BYTES alone is what causes it.
     AppTime,  Total,   Mark,  Sweep, FinObj, FinStr, SwShapes, Destroy, +Chunks
, -Chunks
         0.0,   10.8,    7.9,    2.8,    0.1,    0.0,      2.7,     0.0,       1
,       0
       122.9,   23.5,   15.9,    7.6,    0.1,    0.0,      7.4,     0.0,       0
,       0
       151.6,   23.5,   15.4,    8.1,    0.1,    0.0,      7.9,     0.0,       0
,       0
       180.3,   24.8,   16.0,    8.8,    0.1,    0.0,      8.6,     0.0,       0
,       0
       210.2,   24.1,   15.8,    8.3,    0.1,    0.0,      8.2,     0.0,       0
,       0
...

The GC stats printed on each iteration have roughly the same numbers as shown above.
Turns out this is caused by older FF4 code that has since changed which was calling shrinkSlots on each GC. (bug 639727)
Status: NEW → RESOLVED
Closed: 13 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.