844313 - Call GC more likely when there are lots of Events to collect

Status: RESOLVED FIXED

(Core :: DOM: Events, defect)

Description

[Gregor Wagner [:gwagner]]

I noticed that panning on the B2G phone allocates memory but we don't trigger GCs.
Once we hit a GC, we spend a lot of time sweeping objects.

Comment 1

[Gregor Wagner [:gwagner]]

Attachment: patch

Comment 2

[Gregor Wagner [:gwagner]]

Comment on attachment 717335 [details] [diff] [review]
patch

Maybe we already update the malloc counter along the way but I didn't find anything.

Comment 3

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 717335 [details] [diff] [review]
patch

This would catch only some probably not very often used events.
Doesn't cover interfaces like Event, MouseEvent or TouchEvent.

If there are more than very few suspected cycle collectable objects we should
trigger CC and if it finds enough stuff to collect, it should trigger 
also GC.

Sounds like you might want to tweak nsJSEnvironment, rather than adding
JS_updateMallocCounter to somewhat random place.

Comment 4

[Gregor Wagner [:gwagner]]

Does it make sense to add up "removed" objects and trigger a GC based on them?

The situation looks like following:

E/GeckoConsole(  712): GC(T+80.0) Total Time: 204.6ms, Compartments Collected: 19, Total Compartments: 19, MMU (20ms): 0%, MMU (50ms): 0%, SCC Sweep Total: 28.0ms, SCC Sweep Max Pause: 21.9ms, Max Pause: 78.2ms, Allocated: 6MB, +Chunks: 0, -Chunks: 0
E/GeckoConsole(  712):     Slice: 0, Pause: 37.8 (When: 0.0ms, Reason: FULL_GC_TIMER): Purge: 0.1ms, Mark: 35.2ms, Mark Discard Code: 2.1ms, Mark Roots: 12.9ms
E/GeckoConsole(  712):     Slice: 3, Pause: 78.2 (When: 412.1ms, Reason: INTER_SLICE_GC): Mark: 41.4ms, Mark Gray: 41.2ms, Finalize Start Callback: 0.4ms, Sweep: 34.1ms, Sweep Compartments: 16.9ms, Sweep Tables: 2.2ms, Sweep Object: 12.9ms, Sweep String: 0.4ms, Sweep Script: 0.4ms, Sweep Discard Code: 1.3ms, Discard Analysis: 10.3ms, Discard TI: 4.2ms, Sweep Types: 4.9ms, Clear Script Analysis: 1.0ms, Finalize End Callback: 1.9ms
E/GeckoConsole(  712):     Slice: 6, Pause: 0.4 (When: 784.9ms, Reason: INTER_SLICE_GC): Sweep: 0.2ms, Deallocate: 0.2ms
E/GeckoConsole(  712):     Totals: Purge: 0.1ms, Mark: 155.8ms, Mark Discard Code: 2.1ms, Mark Roots: 12.9ms, Mark Gray: 41.2ms, Finalize Start Callback: 0.4ms, Sweep: 37.4
E/GeckoConsole(  712): CC(T+80.2) duration: 76ms, suspected: 378, visited: 975 RCed and 780 GCed, collected: 31 RCed and 23 GCed (54 waiting for GC)
E/GeckoConsole(  712): ForgetSkippable 24 times before CC, min: 1 ms, max: 41 ms, avg: 4 ms, total: 119 ms, removed: 2973
E/GeckoConsole(  829): CC(T+57.2) duration: 19ms, suspected: 1528, visited: 1729 RCed and 190 GCed, collected: 0 RCed and 0 GCed (13 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 14 times before CC, min: 0 ms, max: 36 ms, avg: 3 ms, total: 50 ms, removed: 1251
E/GeckoConsole(  829): CC(T+63.8) duration: 19ms, suspected: 1521, visited: 1727 RCed and 190 GCed, collected: 0 RCed and 0 GCed (13 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 14 times before CC, min: 0 ms, max: 36 ms, avg: 3 ms, total: 54 ms, removed: 1219
E/GeckoConsole(  829): CC(T+70.5) duration: 20ms, suspected: 1469, visited: 1704 RCed and 190 GCed, collected: 0 RCed and 0 GCed (13 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 14 times before CC, min: 0 ms, max: 32 ms, avg: 3 ms, total: 47 ms, removed: 1236
E/GeckoConsole(  829): CC(T+77.2) duration: 19ms, suspected: 1403, visited: 1626 RCed and 190 GCed, collected: 0 RCed and 0 GCed (13 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 14 times before CC, min: 0 ms, max: 32 ms, avg: 3 ms, total: 47 ms, removed: 1189
E/GeckoConsole(  829): CC(T+83.8) duration: 23ms, suspected: 1552, visited: 1799 RCed and 190 GCed, collected: 0 RCed and 0 GCed (13 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 14 times before CC, min: 0 ms, max: 34 ms, avg: 3 ms, total: 55 ms, removed: 1275
E/GeckoConsole(  829): CC(T+101.1) duration: 33ms, suspected: 633, visited: 825 RCed and 190 GCed, collected: 0 RCed and 0 GCed (13 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 10 times before CC, min: 0 ms, max: 39 ms, avg: 5 ms, total: 55 ms, removed: 929
E/GeckoConsole(  829): CC(T+115.0) duration: 27ms, suspected: 1691, visited: 1929 RCed and 190 GCed, collected: 0 RCed and 0 GCed (13 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 14 times before CC, min: 0 ms, max: 40 ms, avg: 4 ms, total: 57 ms, removed: 1245
E/GeckoConsole(  829): CC(T+121.7) duration: 28ms, suspected: 1708, visited: 1946 RCed and 190 GCed, collected: 0 RCed and 0 GCed (13 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 14 times before CC, min: 0 ms, max: 40 ms, avg: 4 ms, total: 68 ms, removed: 1259
E/GeckoConsole(  829): CC(T+128.4) duration: 28ms, suspected: 1705, visited: 1949 RCed and 190 GCed, collected: 0 RCed and 0 GCed (13 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 14 times before CC, min: 0 ms, max: 39 ms, avg: 3 ms, total: 54 ms, removed: 1285
E/GeckoConsole(  829): CC(T+135.0) duration: 51ms, suspected: 1630, visited: 1874 RCed and 190 GCed, collected: 0 RCed and 0 GCed (13 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 14 times before CC, min: 0 ms, max: 40 ms, avg: 4 ms, total: 57 ms, removed: 1246
E/GeckoConsole(  829): CC(T+141.9) duration: 28ms, suspected: 1680, visited: 1907 RCed and 190 GCed, collected: 0 RCed and 0 GCed (13 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 14 times before CC, min: 0 ms, max: 39 ms, avg: 4 ms, total: 58 ms, removed: 1223
E/GeckoConsole(  829): GC(T+148.8) Total Time: 278.5ms, Compartments Collected: 10, Total Compartments: 10, MMU (20ms): 0%, MMU (50ms): 0%, SCC Sweep Total: 212.6ms, SCC Sweep Max Pause: 141.8ms, Max Pause: 216.7ms, Allocated: 5MB, +Chunks: 2, -Chunks: 0
E/GeckoConsole(  829):     Slice: 0, Pause: 31.3 (When: 0.0ms, Reason: MAYBEGC): Mark: 30.4ms, Mark Discard Code: 0.7ms, Mark Roots: 19.2ms
E/GeckoConsole(  829):     Slice: 2, Pause: 216.7 (When: 155.7ms, Reason: REFRESH_FRAME): Mark: 0.7ms, Mark Gray: 0.5ms, Sweep: 214.6ms, Sweep Compartments: 7.8ms, Sweep Tables: 5.4ms, Sweep Object: 203.1ms, Sweep String: 1.4ms, Sweep Script: 0.2ms, Sweep Discard Code: 0.4ms, Discard Analysis: 2.0ms, Discard TI: 0.9ms, Sweep Types: 0.7ms, Clear Script Analysis: 0.3ms, Finalize End Callback: 0.7ms
E/GeckoConsole(  829):     Slice: 5, Pause: 5.2 (When: 464.6ms, Reason: REFRESH_FRAME): Sweep: 0.2ms, Deallocate: 0.2ms
E/GeckoConsole(  829):     Totals: Mark: 51.9ms, Mark Discard Code: 0.7ms, Mark Roots: 19.2ms, Mark Gray: 0.5ms, Sweep: 215.9ms, Sweep Atoms: 3.0ms, Sweep Compartments: 7.8ms, Sweep Tables: 5.4ms, Sweep Object: 203.1ms, Swe
E/GeckoConsole(  829): CC(T+149.2) duration: 96ms, suspected: 22117, visited: 12238 RCed and 280 GCed, collected: 0 RCed and 0 GCed (0 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 15 times before CC, min: 0 ms, max: 35 ms, avg: 4 ms, total: 67 ms, removed: 13954
E/GeckoConsole(  829): CC(T+155.3) duration: 18ms, suspected: 310, visited: 419 RCed and 280 GCed, collected: 0 RCed and 0 GCed (0 waiting for GC)
E/GeckoConsole(  829): ForgetSkippable 6 times before CC, min: 0 ms, max: 13 ms, avg: 3 ms, total: 20 ms, removed: 16005
E/GeckoConsole(  712): CC(T+206.3) duration: 34ms, suspected: 70, visited: 953 RCed and 746 GCed, collected: 0 RCed and 0 GCed (54 waiting for GC)
E/GeckoConsole(  712): ForgetSkippable 69 times before CC, min: 1 ms, max: 34 ms, avg: 2 ms, total: 184 ms, removed: 8601

Comment 5

[Olli Pettay [:smaug][[e-mail]]]

No. Removed means how many objects we managed to optimize out from cycle collector graph. It is
about forgetSkippable.
Also, based on that log calling GC and then CC doesn't actually end up unlinking much... in fact
collected: 0 RCed and 0 GCed

Comment 6

[Gregor Wagner [:gwagner]]

Hm so back to the update malloc counter approach?

Comment 7

[Olli Pettay [:smaug][[e-mail]]]

But what would that help if even after GC we don't end up collecting anything?

Comment 8

[Olli Pettay [:smaug][[e-mail]]]

Oh, right, this is just about gc, not cc.

Comment 9

[Olli Pettay [:smaug][[e-mail]]]

Ask billm about gc scheduling?

Comment 10

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

I added a timer to see how much time we're spending finalizing each kind of object. The results aren't very precise because of the overhead of PRMJ_Now, but I think they probably give a good ballpark estimate. There seem to be two compartments that are involved.

The format is <classname> <microseconds spent finalizing objects of that class>.

First compartment:

I/Gecko   (  724): finalize ClientRect 12151
I/Gecko   (  724): finalize Event 0
I/Gecko   (  724): finalize XPC_WN_NoMods_NoCall_Proto_JSClass 0
I/Gecko   (  724): finalize TouchEvent 7656
I/Gecko   (  724): finalize XPCWrappedNative_NoHelper 61
I/Gecko   (  724): finalize XPC_WN_ModsAllowed_NoCall_Proto_JSClass 0
I/Gecko   (  724): finalize Object 1184
I/Gecko   (  724): finalize TouchList 11079
I/Gecko   (  724): finalize Touch 12785
I/Gecko   (  724): finalize NotifyPaintEvent 0
I/Gecko   (  724): finalize Proxy 5678
I/Gecko   (  724): finalize Proxy 0
I/Gecko   (  724): finalize WindowUtils 0

Second compartment:

I/Gecko   (  724): finalize DOMStringMap 215
I/Gecko   (  724): finalize Event 10528
I/Gecko   (  724): finalize HTMLBodyElement 0
I/Gecko   (  724): finalize HTMLElement 184
I/Gecko   (  724): finalize TouchEvent 13509
I/Gecko   (  724): finalize HTMLAnchorElement 614
I/Gecko   (  724): finalize HTMLLIElement 488
I/Gecko   (  724): finalize TouchList 6104
I/Gecko   (  724): finalize Touch 6293
I/Gecko   (  724): finalize Iterator 0
I/Gecko   (  724): finalize Proxy 5620
I/Gecko   (  724): finalize MouseEvent 33622

So it looks like the main ones we need to pay attention to are MouseEvent, TouchEvent, Event, Touch, and TouchList.

I think it would be useful to add JS_updateMallocCounter to those classes. This might not do what we need because GCs triggered by the malloc counter are non-incremental. However, it's worth a try to see if we can at least reduce the time to finalize. Olli, if we want to add JS_updateMallocCounter to all these classes, is there an easy way to do it?

Comment 11

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

By the way, another way to fix this problem would be to lower the GC allocation threshold below 3MB. That way we'd trigger GCs based on gcBytes, and those GCs are incremental.

Comment 12

[Olli Pettay [:smaug][[e-mail]]]

We could add JS_updateMallocCounter to nsDOMTouchEvent/MouseEvent/etc ctor but it is IMO a hack,
and it would be bad to do non-iGC.
We should be able to trigger GC more often if we have plenty of new JS objects, especially
objects pointing to some native object. 

Or maybe we could count the number of "likely short living C++ objects", and increase
the likelihood of calling GC after CC is there are many such objects.

Comment 13

[Olli Pettay [:smaug][[e-mail]]]

A patch coming for testing.

Comment 14

[Olli Pettay [:smaug][[e-mail]]]

Attachment: GC more often if we have plenty of new likely short living objects

Something like this, perhaps.

Comment 15

[Olli Pettay [:smaug][[e-mail]]]

(Also, the more we move to webidl bindings, the less we may use addref/release, so we may have to
tweak when to trigger CC. But that is a separate bug.)

Comment 16

[Olli Pettay [:smaug][[e-mail]]]

Attachment: minor tweak

Comment 17

[Olli Pettay [:smaug][[e-mail]]]

https://tbpl.mozilla.org/?tree=Try&rev=b025f8fda889

Comment 18

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 722170 [details] [diff] [review]
minor tweak

Gregor, could you perhaps try this?
2500 limit is hopefully small enough, but not too small to
trigger GC all the times.

Patch seems to work ok on desktop - if there are lots of events
gc is forced to run after cc. 
And based on a simple page
http://mozilla.pettay.fi/moztests/touch.html which I tested on b2g, gc should get triggered
reasonable often when using touch screen.
(but I don't know how to build or install test builds to the b2g device.)

Comment 19

[Gregor Wagner [:gwagner]]

Comment on attachment 722170 [details] [diff] [review]
minor tweak

Looks great!
For fast and constant swiping we get now a GC every 10 sec that look like:

E/GeckoConsole(  488): CC(T+10.1) duration: 3ms, suspected: 0, visited: 34 RCed and 39 GCed, collected: 0 RCed and 0 GCed (0|0 waiting for GC)
E/GeckoConsole(  488): ForgetSkippable 2 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 0 ms, removed: 22
E/GeckoConsole(  475): CC(T+31.5) duration: 6ms, suspected: 3339, visited: 215 RCed and 197 GCed, collected: 0 RCed and 0 GCed (0|94 waiting for GC)
E/GeckoConsole(  475): ForgetSkippable 10 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 8 ms, removed: 3667
E/GeckoConsole(  475): CC(T+38.2) duration: 12ms, suspected: 1150, visited: 1360 RCed and 197 GCed, collected: 0 RCed and 0 GCed (0|2316 waiting for GC)
E/GeckoConsole(  475): ForgetSkippable 13 times before CC, min: 0 ms, max: 24 ms, avg: 2 ms, total: 38 ms, removed: 1085
E/GeckoConsole(  475): CC(T+44.8) duration: 15ms, suspected: 1472, visited: 1687 RCed and 197 GCed, collected: 0 RCed and 0 GCed (0|5002 waiting for GC)
E/GeckoConsole(  475): ForgetSkippable 13 times before CC, min: 0 ms, max: 37 ms, avg: 3 ms, total: 50 ms, removed: 1199
E/GeckoConsole(  475): GC(T+49.1) Total Time: 84.4ms, Compartments Collected: 9, Total Compartments: 9, MMU (20ms): 0%, MMU (50ms): 28%, SCC Sweep Total: 33.3ms, SCC Sweep Max Pause: 21.6ms, Max Pause: 35.7ms, Allocated: 3MB, +Chunks: 0, -Chunks: 0
E/GeckoConsole(  475):     Slice: 0, Pause: 30.8 (When: 0.0ms, Reason: CC_WAITING): Mark: 29.9ms, Mark Discard Code: 0.8ms, Mark Roots: 7.8ms
E/GeckoConsole(  475):     Slice: 5, Pause: 3.7 (When: 256.6ms, Reason: REFRESH_FRAME): 
E/GeckoConsole(  475):     Totals: Mark: 41.3ms, Mark Discard Code: 0.8ms, Mark Roots: 7.8ms, Mark Gray: 0.5ms, Sweep: 35.6ms, Sweep Atoms: 2.0ms, Sweep Compartments: 3.5ms, Sweep Tables: 1.2ms, Sweep Object: 29.2ms, Sweep String: 0.3ms, Sweep Script: 0.2ms, Sweep Shape: 1.0ms, Sweep Discard Code: 0.5ms, Discard Analysis: 1.6ms, Discard TI: 0.7ms, Sweep Types: 0.5ms, Clear Script Analysis: 0.3ms, Finalize End Callback: 0.7ms
E/GeckoConsole(  475): CC(T+49.4) duration: 7ms, suspected: 4823, visited: 234 RCed and 195 GCed, collected: 0 RCed and 0 GCed (0|108 waiting for GC)
E/GeckoConsole(  475): ForgetSkippable 10 times before CC, min: 0 ms, max: 1 ms, avg: 1 ms, total: 11 ms, removed: 5148
E/GeckoConsole(  475): CC(T+56.0) duration: 15ms, suspected: 1603, visited: 1823 RCed and 195 GCed, collected: 0 RCed and 0 GCed (0|2875 waiting for GC)
E/GeckoConsole(  475): ForgetSkippable 14 times before CC, min: 0 ms, max: 38 ms, avg: 3 ms, total: 55 ms, removed: 1198
E/GeckoConsole(  475): GC(T+60.2) Total Time: 74.3ms, Compartments Collected: 9, Total Compartments: 9, MMU (20ms): 0%, MMU (50ms): 36%, SCC Sweep Total: 26.2ms, SCC Sweep Max Pause: 16.7ms, Max Pause: 31.5ms, Allocated: 3MB, +Chunks: 0, -Chunks: 0
E/GeckoConsole(  475):     Slice: 0, Pause: 31.5 (When: 0.0ms, Reason: CC_WAITING): Mark: 30.5ms, Mark Discard Code: 0.9ms, Mark Roots: 8.2ms
E/GeckoConsole(  475):     Slice: 4, Pause: 3.9 (When: 214.9ms, Reason: REFRESH_FRAME): 
E/GeckoConsole(  475):     Totals: Mark: 38.4ms, Mark Discard Code: 0.9ms, Mark Roots: 8.2ms, Mark Gray: 0.5ms, Sweep: 28.3ms, Sweep Atoms: 2.0ms, Sweep Compartments: 3.9ms, Sweep Tables: 1.2ms, Sweep Object: 21.9ms, Sweep String: 0.1ms, Sweep Script: 0.1ms, Sweep Shape: 1.2ms, Sweep Discard Code: 0.4ms, Discard Analysis: 2.1ms, Discard TI: 1.1ms, Sweep Types: 0.6ms, Clear Script Analysis: 0.2ms, Finalize End Callback: 0.6ms

Comment 20

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 722170 [details] [diff] [review]
minor tweak

mccr8, what do you think of this kind of simple approach. I believe we want
safe enough approach so that it can land to b2g18 too.

We could call LikelyShortLivingObjectCreated() in few other places too.


(or if we had spare bits in cycle collectable objects, call some
generic "cycle collectable object created" once for each object when they are
first time suspected or make all cycle collectable objects inherit some class which has ctor which
notifies about creation... but these are more complicated.)

Comment 21

[Andrew McCreight [:mccr8]]

Comment on attachment 722170 [details] [diff] [review]
minor tweak

Review of attachment 722170 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good to me.  Are these events mostly going to be created by user interaction?  Could you end up in a state where a webpage is just spinning in the background and triggering these things without the user doing anything?  As that would seem to be bad.

Do MouseEvents need to have LikelyShortLivingObjectCreated() called on them, too?  There was a lot of time spent on those in Bill's comment 10.  Or is that included here somehow?  I guess if those are being created too then we'd have to adjust the trigger, and on B2G the touch stuff is probably enough.

Those CCs that collect nothing are dumb.  We should investigate why those are happening.  Could we eliminate them without messing up your approach here?

::: dom/base/nsJSEnvironment.h
@@ +147,5 @@
>    static void KillCCTimer();
>    static void KillFullGCTimer();
>    static void KillInterSliceGCTimer();
>  
> +  static void LikelyShortLivingObjectCreated();

Please add some documentation here.  Basically, just say that once we get enough of these, we'll poke the GC or whatever.

Comment 22

[Olli Pettay [:smaug][[e-mail]]]

(In reply to Andrew McCreight [:mccr8] from comment #21) 
> Looks good to me.  Are these events mostly going to be created by user
> interaction?
All the DOM events inherit nsDOMEvent


>  Could you end up in a state where a webpage is just spinning
> in the background and triggering these things without the user doing
> anything?  As that would seem to be bad.
Well, if a script is creating lots of DOM events, we need to collect them soon.
So, the patch should make our behavior better.


> 
> Do MouseEvents need to have LikelyShortLivingObjectCreated() called on them,
> too?
No need to. MouseEvents inherit nsDOMEvent

Comment 23

[Olli Pettay [:smaug][[e-mail]]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/c1ef9a062a88

Comment 24

[Gregor Wagner [:gwagner]]

Attachment: b2g18 version

Comment 25

[Andrew Overholt [:overholt]]

tef+ since it's blocking another tef+ bug

Comment 26

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/c1ef9a062a88

Comment 27

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g18/rev/94927529a55f
https://hg.mozilla.org/releases/mozilla-b2g18_v1_0_1/rev/0fc35d8c3b34