901964 - contacts detail/form/settings pages constantly repaint

Status: RESOLVED WORKSFORME

(Firefox OS Graveyard :: Gaia::Contacts, defect, P2)

Description

[Ben Kelly [:bkelly, not reviewing]]

While investigating bug 901657 I noticed that there was also elevated CPU usage when viewing an empty contacts form.  Profiling indicating this was due to repainting.

To investigate I turned on the paint flashing tool under the developer settings.  This showed that the entire page is being repainted.

It seems that this is probably related to the transition animations.  The profile shows the painting activity occurs in a spike every 400ms which corresponds to the 0.4s value in animation.css.

Its unclear to me if using CPU after animationend is a bug in gecko or not.  I can't find any existing bugs.

Comment 1

[Ben Kelly [:bkelly, not reviewing]]

Attachment: profile_1037_1162_Communications.txt

Profile of the idle Add Contact screen.

Comment 2

[Ben Kelly [:bkelly, not reviewing]]

So if I change the app-go-up-in style from:

  .app-go-up-in {
    animation: app-go-up-in 0.5s forwards ease-in;
  }

  @keyframes app-go-up-in {
    0% { transform: translateY(100%); }
    100% { transform: translateY(0); }
  }

To:

  .app-go-up-in {
    transform: translateY(0);
  }

Then the continuous repaints stop.

I do not have a good explanation for this currently.  I rewrote the animation using explicit long-form properties that specify iteration-count, etc, without any change in behavior.  Changing the duration also does not change the frequency at which the repaints occur.  I cannot find any other animations that have been applied.

I'll attempt to generate a minimal test case next in order to determine if this is a gecko bug.

Comment 3

[Ben Kelly [:bkelly, not reviewing]]

I can no longer reproduce this after:

  - updating to latest vendor firmware
  - installing latest m-c with ./flash.sh gecko
  - installing latest gaia/master

It seems possible this was related to the buri hwc firmware problems I was having with the firmware built from our repo.  Marking as WFM.

Comment 4

[Ben Kelly [:bkelly, not reviewing]]

Actually, the painting is still happening.  It appears the paint flashing setting does not work with hwc enabled on the device.  The painting is still occurring, though, because the elevated CPU is still present and I see this continuously in logcat:

D/HWComposer( 2451): Frame rendered
D/HWComposer( 2451): Frame rendered
D/HWComposer( 2451): Frame rendered

Comment 5

[Ben Kelly [:bkelly, not reviewing]]

Attachment: profile_1200_663_b2g.txt

Profile of the issue with vendor firmware and recent m-c.  The long tail shows pretty much nothing but waiting, but at the same time we see ~30%.  The hwc frame rendered messages are also spewing to logcat at this time.

Comment 6

[Ben Kelly [:bkelly, not reviewing]]

Unassigning as I have not had time to work this yet.  If someone else picks this up:

- We can workaround the issue by replacing the transition animations after they complete with static CSS that matches the completion position.  This seems a bit hacky and not the right way to fix it.

- It would be nice to figure out what combination of features in contacts is triggering this.  If its a gecko bug, it would also be good to identify that.

Comment 7

[Jose Manuel Cantera]

assigning to German. Ben, please could you guide Germán with this bug?

thanks!

Comment 8

[Ben Kelly [:bkelly, not reviewing]]

Awesome, thanks!

This was 100% reproduceable for me when I last looked at it.  Here are some steps:

  1) Open contacts.
  2) Run 'adb shell top -m 5' from the console.  The CPU should be fairly close to idle.
  3) Click the '+' button to create a new contact.
  4) Observe in top that the b2g/communications app is now using around 15% to 20% CPU.

Depending on if you are running the vendor firmware or mozilla b2g firmware you may have things to look at in logcat also.  For example, with vendor firmware you will see this repeatedly in logcat:

  D/HWComposer( 2451): Frame rendered

However, the "paint flashing" options in the developer settings does not work with the vendor firmware.

Let me know if you run into any problems reproducing.  Thanks again.

Comment 9

[Germán Toro del Valle (:gtorodelvalle)]

As already discussed with Ben offline, in Unagi using the latest build (Gecko-729cc0) and Gaia code from master the problem does not seem to reproduce right now.

I also tried to test it in Leo but there is a problem with the build I was provided and I am still waiting on a solution for this. Same goes for Inari. Trying to try it to isolate the problem as much as possible.

Since Ben told me that he was using vendor firmware (flashed with TeleWeb) and then mozilla-central gecko and gaia/master, I am trying to set this up and test it that way. As already commented by Ken in comment 3, it seems to be related to "buri hwc firmware problems".

I'll keep you posted.

Comment 10

[Germán Toro del Valle (:gtorodelvalle)]

Quick update: Regarding the build for Buri, Beatriz is in touch with Buri's provider to make the proper build available for Telefónica using TeleWeb :-(

Comment 11

[Ben Kelly [:bkelly, not reviewing]]

I just retested this on my buri using latest gaia master and mozilla-aurora.  I can reproduce by opening the contacts settings page and looking at top:

> User 6%, System 26%, IOW 0%, IRQ 0%
> User 21 + Nice 1 + Sys 84 + Idle 209 + IOW 0 + IRQ 0 + SIRQ 0 = 315
>
>   PID PR CPU% S  #THR     VSS     RSS PCY UID      Name
> 31487  0  26% S    35 195456K  65500K  fg root     /system/b2g/b2g
> 31653  0   7% S    13 127712K  40032K  fg app_3165 /system/b2g/plugin-container

Interestingly, if I lock the phone or let it go to sleep from idle, then the CPU usage goes away after you wake the phone up even though its still on the contacts settings tab.

Comment 12

[Ben Kelly [:bkelly, not reviewing]]

Commands I ran to get the top output above:

> bkelly@lenir:/srv/gaia-master$ adb shell
> root@android:/ # top -m 5

You need to wait for the top results to stabilize.

Comment 13

[Ben Kelly [:bkelly, not reviewing]]

Hmm.  I can't reproduce on 1.3 with hwc disabled with revs:

  Gecko m-c:   149176:5a49762ee832
  Gaia master: 24234de42e9418e5cc602133f482dee7524b887f

I wonder if its still present in 1.2.

Comment 14

[Ben Kelly [:bkelly, not reviewing]]

Actually, I can still reproduce it.  It only seems to happen on settings page now.  If you visit the "add new contact" page, then it stops reproducing on settings.

Comment 15

[Ben Kelly [:bkelly, not reviewing]]

Here is a profile showing the periodic repaint.  Still no clear indication of what the cause is:

  http://people.mozilla.org/~bgirard/cleopatra/#report=76816893ad2850a1d56a37934d5e0d9f639df914

Comment 16

[Ben Kelly [:bkelly, not reviewing]]

Another profile, this time with native stacks and 1000hz sampling:

  http://people.mozilla.org/~bgirard/cleopatra/#report=f5467c431c6852c9a31649cfddffb19d0bea3dad

Comment 17

[Germán Toro del Valle (:gtorodelvalle)]

Setting this bug free since we are still waiting for the Buri build to be able to reproduce the bug Ben mentions :-( Just in case, anyone with the proper build for the Buri is able to reproduce it an to solve it ;-)

Comment 18

[Joe Cheng [:jcheng] (please needinfo)]

ni? gsvelto as he might know somethign about this one

Comment 19

[Gabriele Svelto [:gsvelto]]

I've seen something similar happening once which was caused by a long queue of CSS transactions being slowly executed until they drained up (which could take a few minutes). Ben can you check if mozilla::RestyleTracker::DoProcessRestyles() is being called for every paint event? If it is then the issue might be similar.

Comment 20

[Ben Kelly [:bkelly, not reviewing]]

Adding ni flag to remind myself to test Gabriele's suggestion in comment 19.  I'm working some other bugs at the moment, though, so I won't get to this immediately.

Comment 21

[Ben Kelly [:bkelly, not reviewing]]

So I took this at our last triage, but after looking at it closer I don't think it should block for 1.2.  It needs to be fixed eventually, but its not a regression and its not a direct visible impact to the user.  It also doesn't effect any of our specific release goals.

Therefore, nom'ing for 1.3 and ni'ing mlee/dietrich to set back to koi+ if they disagree.

Comment 22

[Ben Kelly [:bkelly, not reviewing]]

I noticed on v1.2 recently that every time we get this paint flash we also get this logcat:

11-20 15:31:28.629 E/msm7627a.hwcomposer(11901): hwc_set: Unable to render by hwc due to non-pmem memory
11-20 15:31:28.629 E/HWComposer(11901): H/W Composition failed

Benoit, any ideas about what could cause this?

Comment 23

[Benoit Girard (:BenWa)]

When we allocate a buffer we try to map it to PMEM if possible otherwise we fallback. PMEM is a fixed suzed buffer that we map graphics buffer into. On most of our devices the buffer must be mapped into PMEM for hwcomposer to prepare the frame. If we run out of space in PMEM then you get that.

We want to be in PMEM in some use cases like fullscreen video but in some use cases like scrolling we're ok falling off hwcomposer.

Comment 24

[Ben Kelly [:bkelly, not reviewing]]

It just seems odd that we repeatedly try to paint on a screen where nothing is happening.  If I remove the CSS animation that transitioned to the screen (and ended in theory), then the painting stops.  Is it possible whatever code performs CSS transition animations is hitting an error and failing to truly stop?

Comment 25

[Mason Chang [Inactive] [:mchang]]

Just tried reproducing on latest, this is what I'm getting:

User 3%, System 5%, IOW 0%, IRQ 0%
User 2 + Nice 10 + Sys 16 + Idle 280 + IOW 1 + IRQ 0 + SIRQ 0 = 309

  PID PR CPU% S  #THR     VSS     RSS PCY UID      Name
  845  0   5% S    13 104528K  40076K  fg app_845  /system/b2g/plugin-container
  924  0   2% R     1   1028K    420K  fg root     top
    4  0   0% S     1      0K      0K  fg root     kworker/0:0
  661  0   0% S     1   2640K    832K  fg wifi     /system/bin/wpa_supplicant
  168  0   0% S     7   6532K    204K  fg root     /sbin/adbd

I also don't see HWC spew from logcat. Resolving for now.