789664 - Framerate of simple test code makes wide swings

Status: RESOLVED WORKSFORME

(Core :: General, defect)

Description

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Attachment: Test case as Gaia Template app

STR
 (1) Apply attached patch to $b2g/gaia, ./flash.sh gaia
 (2) Enable FPS counter (Settings -> About phone)
 (3) Load Template app

The test spends most of the time at 57fps (display refresh rate), but every few seconds drops to ~38fps and then bounces back up to 57fps.  This can also be seen as visible slowdown in the animated divs.

There's no GC/CC spew in logcat so we seem to be avoiding JS garbage successfully.

Is it possible there's something CC-related that might be causing this variation in fps, but not showing up as part of the GC/CC logging?  smaug mentioned yesterday having patches to optimize CC; maybe that would help here?

The odd thing is that in a profile of this test,

http://people.mozilla.com/~bgirard/cleopatra/?report=d544b2db65c7fc1de7be3504106ed8fd773aca91

there's nothing that looks CC related ...

It's also possible that there's something in the b2g process that's unexpectedly running once in a while and stealing some CPU from the content process.

Comment 1

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Recent profile from the b2g process while this test runs (and has the ~20fps swings)

http://people.mozilla.com/~bgirard/cleopatra/?report=a47026e1fd7d29684845b2b8cc61118aa6ac4473

Nothing there.  Could be a non-main thread ruining things, but my money is on content-process main thread.

Comment 2

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Representative sample from |top|

 1563  0  48% R    11  77376K  23748K  fg app_0    /system/b2g/plugin-container
 1427  0  16% S    38 207916K  76124K  fg root     /system/b2g/b2g
 1617  0   5% S     9  57472K  18468K  fg app_0    /system/b2g/plugin-container
 1466  0   5% S    11 101596K  28244K  fg app_0    /system/b2g/plugin-container

So there's plenty of CPU time to go around.

(The background processes must be using 5% CPU because profiling is enabled.)

Comment 3

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

New profile from content process

http://people.mozilla.com/~bgirard/cleopatra/?report=1e9659bc6f25c64f4791b0282442d9d3f1b58bfe

In the profile, (I think) you can see the fps "modes" as series of bars of different thickness.  The "slow mode" seems to be the fatter peaks, and the "fast mode" seems to be the thinner ones.  In the "fast mode", I see the same breakdown of CPU time as "slow mode"

46% PresShell::Paint
42% ProcessRestyles
 5% RunScript

BUT! there's a lot of unidentified "dark matter" samples during the "slow mode".

My kingdom for symbols!

Comment 4

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

(In reply to Chris Jones [:cjones] [:warhammer] from comment #0)
> Is it possible there's something CC-related that might be causing this
> variation in fps, but not showing up as part of the GC/CC logging?
forgetSkippable phases run even when we don't run full CC.
forgetSkippable is what keeps CC times low and (somewhat) rare.
The message about CC runs tells also how many forgetSkippables there were
before CC.
(One thing I started to think about yesterday is to make sure all the JS stuff added for B2G are properly optimized
out from CC to keep pauses smaller. It would have been easier with C++ implementation but oh well...)


>  smaug
> mentioned yesterday having patches to optimize CC; maybe that would help
> here?
Actually I mentioned addref/release optimizations, which affect quite a bit for example to event dispatching
in deep DOM trees.

Comment 5

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

If I read the test correctly, it does create some JS garbage
({ type: 'mousemove', clientX: pos } objects and some strings in moveTo) so at some point
GC needs to kick in, and when it does, it is probably incremental, and while
iGC is doing it stuff I could imagine it might slow down other things.
But this is all just guessing.

Comment 6

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Since the CC/GC logging isn't showing anything, is there another way to rule out CC/GC from slowing this test down?

Comment 7

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

I'll try changing the test to remove the JS garbage.  Does iGC not show up in the CC/GC logging?

Comment 8

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Hah!  I ran the test again with my USB cable unplugged, and the jank went away!  I guess this is adb logcat causing problems.  What a hog.

Well, this was an easy one :).