1364938 - 9.56% of total execution time is spent in nsCycleCollector::forgetSkippable on FF for Android on After the Flood demo

Status: NEW

(Core :: Cycle Collector, defect)

Description

[Jukka Jylänki]

Attachment: Screen Shot 2017-05-12 at 6.55.18 PM.png

Noticed an odd performance disparity in cycle collector on After the Flood demo (our partnered demo with PlayCanvas for Firefox WebGL 2 launch):

https://playcanv.as/e/p/44MRmJRU/

The demo has an inconvenience of giving a yell if run on a mobile browser, so check the "request desktop site" checkbox in mobile Firefox to access. Alternatively, access the demo via emunittest which has the error message removed.

We are currently investigating performance of that demo to aim to getting it to run smoothly on Android as well.

On a MacBook Pro (13-inch, 2016) with 3.3 GHz Intel Core i7, cycle collector does not generally show up at top in profiles at all (around 0.1%), but when profiling a Huawei P10 Plus (Huawei's 2017 Android flagship phone) running the page, there are quite long regular 60ms-150ms cycle collector pauses during execution. See the attached profile.

The large disparity of time spent in CC on Android vs Desktop looks a bit suspicious. I wonder if there might be something worth investigating here?

Comment 1

[Andrew McCreight [:mccr8]]

CC is XPCOM, not GC.

Comment 2

[Andrew McCreight [:mccr8]]

(In reply to Jukka Jylänki from comment #0)
> The large disparity of time spent in CC on Android vs Desktop looks a bit
> suspicious. I wonder if there might be something worth investigating here?

That is certainly odd. I think we've literally never looked at performance of the CC on Android, as nobody's complained about it before, so it is possible there's something platform-specific going wrong.

Comment 3

[Andrew McCreight [:mccr8]]

What is above the stack in forgetSkippable? ForgetSkippable runs many kinds of cleanup code, so we'll need to know exactly what it is spending time on.

Comment 4

[Andrew McCreight [:mccr8]]

On desktop, with javascript.options.mem.log set to true, I see stuff like this:
CC(T+45810.9)[content-18671] max pause: 2ms, total time: 2ms, slices: 2, suspected: 235, visited: 466 RCed and 363 GCed, collected: 0 RCed and 0 GCed (130|0|0 waiting for GC)
ForgetSkippable 44 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 29 ms, max sync: 0 ms, removed: 4215
CC(T+45845.1)[default-18669] max pause: 8ms, total time: 9ms, slices: 2, suspected: 424, visited: 799 RCed and 1019 GCed, collected: 153 RCed and 0 GCed (210|0|0 waiting for GC)
ForgetSkippable 84 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 27 ms, max sync: 0 ms, removed: 19251
CC(T+45849.9)[content-18674] max pause: 22ms, total time: 22ms, slices: 2, suspected: 281, visited: 533 RCed and 57 GCed, collected: 6 RCed and 0 GCed (0|0|0 waiting for GC)
ForgetSkippable 146 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 42 ms, max sync: 0 ms, removed: 19026
CC(T+45856.0)[content-18671] max pause: 8ms, total time: 8ms, slices: 2, suspected: 244, visited: 470 RCed and 363 GCed, collected: 0 RCed and 0 GCed (130|0|0 waiting for GC)
ForgetSkippable 36 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 24 ms, max sync: 0 ms, removed: 3603
CC(T+45855.3)[content-18674] max pause: 0ms, total time: 0ms, slices: 4, suspected: 382, visited: 746 RCed and 91 GCed, collected: 7 RCed and 13 GCed (13|0|0 waiting for GC)
ForgetSkippable 12 times before CC, min: 0 ms, max: 2 ms, avg: 0 ms, total: 6 ms, max sync: 0 ms, removed: 1174
CC(T+45860.9)[content-18674] max pause: 0ms, total time: 0ms, slices: 4, suspected: 420, visited: 789 RCed and 78 GCed, collected: 6 RCed and 0 GCed (13|0|0 waiting for GC)
ForgetSkippable 12 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 3 ms, max sync: 0 ms, removed: 1562

CC is barely running, and forget skippable isn't removing very much.

Comment 5

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

Hmm, forgetSkippable is often run there using a timer, not after RefreshDriver. I wonder why. Are we not animating all the time in this game?

And yes, would be really useful to know what ForgetSkippable actually calls.

Comment 6

[Jukka Jylänki]

Attachment: Screen Shot 2017-05-15 at 8.16.39 PM.png

Here's what a top down call stack looks.

Comment 7

[Jukka Jylänki]

Attachment: Screen Shot 2017-05-15 at 8.12.58 PM.png

Looking in the swim lane shows occasional stalls of 160ms, 80ms, 50ms, though some CCs are very fast with 0.1ms.

Comment 8

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

Is it possible to get proper profiling data on Android? Pseudostack level data isn't enough at all here, unfortunately.

Comment 9

[Jukka Jylänki]

(In reply to Olli Pettay [:smaug] from comment #5)
> Are we not animating all the time in this game?

The demo does use requestAnimationFrame() to drive its rendering. I think that is its sole source of spontaneous/continuous computation, e.g. there are no other setTimeout()s or setInterval()s being run.

Comment 10

[Jukka Jylänki]

Unfortunately the new Gecko Profiler is not yet quite ready for Android. I don't know of other ways to do profiling on Android. If there's another machinery, I could definitely try that one out.

Comment 11

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

Might be worth to re-test this once bug 1367905 lands to Nightly.

Comment 12

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

Jukka, want to test using the latest Nightly? Any difference? Might be better, might be worse - hopefully the former.