59588 - simple optimization nets maybe 10% speedup in js_gc marking

Status: VERIFIED FIXED

(Core :: JavaScript Engine, defect, P3)

Description

[John Bandhauer]

I was playing with PureCoverage (a sibling of Quantify and Purify from 
Rational) and noticing that js_MarkAtom is the number one most called method in 
mozilla. I knew this before. The really interesting thing I saw was that for the 
simple test of startig the browser and loading a couple of pages js_MarkAtom 
gets called 38.4M times but only 2.4M of the calls get past the 
  "if (_atom->flags & ATOM_MARK)" test in that function. It occured to me that 
moving that test outside of the function call would avoid a *lot* of function 
calls.

I did the following in a debug build...

 - I added some timing code to js_gc.

 - I ran the following using xpcshell...

print("creating objects");
foo = [];
for(var i = 0; i < 500; i++) {
    foo[i] = [];
    for(var j = 0; j < 200; j++)
        foo[i][j] = {};
}
print("calling gc");
gc();
print("freeing objects");
foo = null;
print("calling gc");
gc();

- The baseline output for that is:

--- js_gc: call 1, 158.542636 ms. Total 158.542636 ms. Average 158.542636 ms.
--- js_gc: call 2, 317.728937 ms. Total 476.271573 ms. Average 238.135786 ms.
calling gc
--- js_gc: call 3, 345.728347 ms. Total 821.999920 ms. Average 273.999973 ms.
before 909468, after 909468, break 00000000
freeing objects
calling gc
--- js_gc: call 4, 1128.960884 ms. Total 1950.960804 ms. Average 487.740201 ms.
before 909468, after 4959, break 00000000
--- js_gc: call 5, 5.833210 ms. Total 1956.794014 ms. Average 391.358803 ms.
--- js_gc: call 6, 0.348652 ms. Total 1957.142666 ms. Average 326.190444 ms.
--- js_gc: call 7, 1.394607 ms. Total 1958.537272 ms. Average 279.791039 ms.

- After the patch I'll attach I saw:

creating objects
--- js_gc: call 1, 132.407171 ms. Total 132.407171 ms. Average 132.407171 ms.
--- js_gc: call 2, 264.264546 ms. Total 396.671718 ms. Average 198.335859 ms.
calling gc
--- js_gc: call 3, 313.920588 ms. Total 710.592306 ms. Average 236.864102 ms.
before 909468, after 909468, break 00000000
freeing objects
calling gc
--- js_gc: call 4, 1179.059445 ms. Total 1889.651751 ms. Average 472.412938 ms.
before 909468, after 4959, break 00000000
--- js_gc: call 5, 5.605246 ms. Total 1895.256997 ms. Average 379.051399 ms.
--- js_gc: call 6, 0.335242 ms. Total 1895.592238 ms. Average 315.932040 ms.
--- js_gc: call 7, 1.461655 ms. Total 1897.053894 ms. Average 271.007699 ms.

The call '3' is pretty representative of pure mark/sweep w/o actually doing a 
lot of finalization. The time saving looks like about 10%.

Comment 1

[John Bandhauer]

Attachment: a simple patch to test flag before calling js_MarkAtom

Comment 2

[Brendan Eich [:brendan]]

Cc'ing shaver, assigning to jband (you know you want it!).

Looks good.  Nits: no need to prepend macro formal parameter names with _, but
do parenthesize (atom).

+#define GC_MARK_ATOM(_cx, _atom, _arg)                                        \
+    JS_BEGIN_MACRO                                                            \
+        if (!(_atom->flags & ATOM_MARK))                                      \
+            js_MarkAtom(_cx, _atom, _arg);                                    \
+    JS_END_MACRO
+

becomes

+#define GC_MARK_ATOM(cx, atom, arg)                                           \
+    JS_BEGIN_MACRO                                                            \
+        if (!((atom)->flags & ATOM_MARK))                                     \
+            js_MarkAtom(cx, atom, arg);                                       \
+    JS_END_MACRO
+

That's quite a ratio of reached to unmarked atoms.  I wonder what the common,
15-way-reachable ones are?

/be

Comment 3

[Brendan Eich [:brendan]]

Cc'ing jst -- it seems to me we're GC'ing too much still.  Of course, if shaver
coughs up an incremental GC soon, and we switch the DOM to call JS_IncrementalGC
or whatever, maybe the number of such calls won't matter (shaver and I hope to
make the increment adapt itself to garbate creation).

/be

Comment 4

[Johnny Stenback (:jst)]

One reason we GC too much is that there's still some pre "branch callback" code
in mozilla that calls JS_MaybeGC() after every 20:eth script is executed (in
nsJSContext::ScriptEvaluated()). Given the number of onXXX event handlers in our
UI we end up calling JS_MaybeGC() more often than we need to when the user
interacts with the UI at least...

Comment 5

[Brendan Eich [:brendan]]

jst: it would be interesting to measure how many of those JS_MaybeGC calls
actually do anything.  JS_MaybeGC won't force a GC unless the nominally alive GC
heap has grown by 50% from its last post-GC live (non-garbage) population.

/be

Comment 6

[Johnny Stenback (:jst)]

I seem to recall that I was some time back looking into the number JS_GC() calls
that are made during opening a new window in mozilla and one of the calls came
from nsJSContext::ScriptEvaluated() so it seems like mozilla executed more than
20 scripts that caused JS_MaybeGC() to call JS_GC() when opening a new window. I
dunno how often nsJSContext::ScriptEvaluated() causes JS_GC() calls while using
the UI tho, and even if it's called it's most likely not in a performance
critical piece of code, but yes, it would be interesting to know...

Comment 7

[John Bandhauer]

Attachment: if you just want to see how often gc *really* happens...

Comment 8

[John Bandhauer]

Attachment: proposed fix with brendan's nits scratched. looking for review

Comment 9

[John Bandhauer]

BTW. I did a release xpconnect standalone build on NT and saw roughly the same 
10% speed improvement.

Comment 10

[Brendan Eich [:brendan]]

r=[e-mail] -- shaver, you around to sr=?

/be

Comment 11

[John Bandhauer]

Attachment: updated version looking for r= and sr=

Comment 12

[Brendan Eich [:brendan]]

(diff -u next time, please).  sr=[e-mail], upgrading my r=.

/be

Comment 13

[John Bandhauer]

Attachment: Oops! Sorry. diff -u of same change. looking for r=

Comment 14

[Mike McCabe]

r=mccabe.

Comment 15

[John Bandhauer]

fix checked in

Comment 16

[Phil Schwartau]

Verified checkins; marking Verified. 

jband, is it necessary to use xpcshell to test this? Couldn't the same 
debug timing code in js_gc be used and run within the JS shell? This may be 
obvious, but just thought I would ask - thanks.