Closed Bug 844313 Opened 7 years ago Closed 7 years ago

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

Categories

(Core :: DOM: Events, defect)

x86
macOS
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla22
Tracking Status
firefox20 --- wontfix
firefox21 --- wontfix
firefox22 --- fixed
b2g18 --- fixed
b2g18-v1.0.0 --- wontfix
b2g18-v1.0.1 --- fixed

People

(Reporter: gwagner, Assigned: smaug)

References

Details

Attachments

(2 files, 2 obsolete files)

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.
Attached patch patch (obsolete) — Splinter Review
Assignee: nobody → anygregor
Comment on attachment 717335 [details] [diff] [review]
patch

Maybe we already update the malloc counter along the way but I didn't find anything.
Attachment #717335 - Flags: review?(bugs)
Blocks: 842217
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.
Attachment #717335 - Flags: review?(bugs) → review-
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
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
Hm so back to the update malloc counter approach?
But what would that help if even after GC we don't end up collecting anything?
Oh, right, this is just about gc, not cc.
Ask billm about gc scheduling?
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?
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.
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.
A patch coming for testing.
Something like this, perhaps.
(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.)
Attached patch minor tweakSplinter Review
Attachment #722163 - Attachment is obsolete: true
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.)
Attachment #722170 - Flags: feedback?(anygregor)
Attachment #717335 - Attachment is obsolete: true
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
Attachment #722170 - Flags: feedback?(anygregor) → feedback+
blocking-b2g: --- → tef?
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.)
Attachment #722170 - Flags: review?(continuation)
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.
Attachment #722170 - Flags: review?(continuation) → review+
(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
Summary: Update malloc counter for Events → Call GC more likely when there are lots of Events to collect
Attached patch b2g18 versionSplinter Review
tef+ since it's blocking another tef+ bug
blocking-b2g: tef? → tef+
https://hg.mozilla.org/mozilla-central/rev/c1ef9a062a88
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla22
Assignee: anygregor → bugs
blocking-b2g: tef+ → ---
You need to log in before you can comment on or make changes to this bug.