822345 - The interface feels sluggish when installing a big app

Status: VERIFIED FIXED

(Firefox OS Graveyard :: Gaia::System, defect, P3)

Description

[Julien Wajsberg [:julienw]]

+++ This bug was initially created as a clone of Bug #815173 +++

STR:
* go to http://owapps.cloudfoundry.com with Firefox
* install the big packaged app
* play with the notification panel (displaying it, hiding it, etc)

=> the animations are sluggish

Comment 1

[Julien Wajsberg [:julienw]]

from :gsvelto :


This is a 3s sample set when installing an app, taken with the notification tray pulled down and the spinner animation disabled by commenting out its 'animation' attribute in apps/homescreen/style/grid.css:

http://people.mozilla.com/~bgirard/cleopatra/#report=f4b552b4bebb852b13da8c7f7944444ddc985924

Strangely enough there's lots of painting going on even though the progress bar is refreshed only once per second. Looking at the whole sample period reveals a number of calls to layout::DoReflow() involving app://system.gaiamobile.org/index.html:

http://people.mozilla.com/~bgirard/cleopatra/#report=9b435be27d4b3210185a0df238be6b4bd6e651b8

This is weird as the progress bar is now refreshed only once per second which points to another periodic activity taking place and affecting the screen. I will try to figure out which element in the DOM tree is being touched and is causing the repainting to happen.

On another note the time spent as a response to nsHttpChannel::OnDataAvailable is down to 16% and is mostly spent inside a write() call likely saving the file to the (slow) sdcard. So that part is now quite well behaved.

Comment 2

[Gabriele Svelto [:gsvelto]]

I've done some further testing and I've got a hunch that I need to verify by taking another profiler trace. I've tried replacing the two animated GIFs that display both network activity and an active download in the status-bar with non-animated versions. What I observed was a significant drop in CPU usage and sliding the utility tray was very smooth.

I will do another profiled run tomorrow with this change and if my hunch is right then they might be the cause of the expensive re-layout and re-painting that we're seeing. The layout operation is triggered by a timer event which is what I would expect when drawing an animated GIF.

Comment 3

[JP Rosevear [:jpr]]

Will wait for the profile run to triage.

Comment 4

[Gabriele Svelto [:gsvelto]]

OK, I've been able to confirm that something is amiss with the way the animated GIFs in the status bar are behaving. This is a snapshot of installing a big application on a regular build:

http://people.mozilla.com/~bgirard/cleopatra/#report=b6da4e222c1616591b987b5ea86343a166d866f0

Notice how ~50% of the time is spent in Timer::Fire while repainting the screen. This sample doesn't show it but on larger samples I can consistently find calls to layout::DoReflow on app://system.gaiamobile.org/index.html which happens to contain the status bar. Now look at the following profile:

http://people.mozilla.com/~bgirard/cleopatra/#report=c310019b61187a3f214e48f10ff34c3440c5e8fe

It's the same interval during the installation but this time taken after having replaced the two animated GIFs that show up in the status bar (system-downloads.gif and network-activtity.gif) replaced with static placeholders. CPU usage is minimal and it involves refreshing the utility tray and writing the file to disk entirely. All repaints are gone except for one per second (which updates the progress bar). The actual difference in CPU usage is even more marked than the profile shows, that's because in the second example the statistical nature of the profile is overstating the actual CPU usage (which is below ~20% when measured with top, while in the first case it's in the 40-60% range).

Interestingly this doesn't happen only when installing a big app, I can reproduce the same behavior on any app causing network activity. The icons being animated in the status bar are causing expensive layout/paint cycles (usually 30-50ms each). The intervals of these two animations are 130ms and 200ms respectively so the can burn up to ~50% CPU time in the main process when they're active at the same time. For example this is the main process captured while the browser app was downloading a page:

http://people.mozilla.com/~bgirard/cleopatra/#report=92a8797f7d3f3186da4f643428dac15ef09a5c01

Notice the calls to layout::DoReflow involving app://system.gaiamobile.org/index.html

I've spent some time looking at the code in the refresh driver but since I'm not very familiar with it I'll speculate a bit. If you open these animated GIFs with an editor you'll notice that the frames are obtained by displaying a sub-rectangle of the original image with different x/y coordinates for each time interval (to show the arrow sliding down for example). My (wild) guess is that the refresh driver is handling the animated frames as if they were moving to different coordinates within the page and thus triggering a reflow & subsequent repaint of the other elements too. I cannot find another way to explain why drawing a 16x16 picture would cost so much nor why would the page be re-laid out.

If somebody with more experience in this area could confirm (or disprove) my theory I'd be grateful. Anyway this seems a fairly major issue to me and it affects every application that might triggers network activity and not only app installation.

Comment 5

[Julien Wajsberg [:julienw]]

I talked with Joe Drew on IRC, he suspects that "because the animated gifs invalidate themselves, layout takes that as an opportunity to run DoReflow() so we need a layout person to figure out what's causing DoReflow() to be called, because imagelib can do whatever makes things better, but maybe we should fix the underlying bug"

So adding CC roc and mattwoodrow per his recommendation :-)

Comment 6

[Julien Wajsberg [:julienw]]

More information from Benoit Jacob on IRC :

There have been recent over-invalidation bugs with animated gifs (Bug 798964 and Bug 820246).
We can easily tell if your bug is an over-invalidation bug:

in about:config set nglayout.debug.paint_flashing = true

And David Baron "definitely remembers some very dodgy code in nsImageFrame that couldn't figure out correctly what area it should invalidate though [he] thinks it's better than it used to be."


:gsvelto can you dig deeper with this information ?

Comment 7

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

(In reply to Gabriele Svelto [:gsvelto] from comment #4)
> I've spent some time looking at the code in the refresh driver but since I'm
> not very familiar with it I'll speculate a bit. If you open these animated
> GIFs with an editor you'll notice that the frames are obtained by displaying
> a sub-rectangle of the original image with different x/y coordinates for
> each time interval (to show the arrow sliding down for example). My (wild)
> guess is that the refresh driver is handling the animated frames as if they
> were moving to different coordinates within the page and thus triggering a
> reflow & subsequent repaint of the other elements too. I cannot find another
> way to explain why drawing a 16x16 picture would cost so much nor why would
> the page be re-laid out.

I'm reasonably sure image animation is entirely separate from anything that would cause reflow.  I could certainly imagine it invalidating more than necessary in some situations, though (and thus triggering unnecessary repainting).

It would be interesting to know what *is* causing the reflow, though.

Comment 8

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

(In reply to Julien Wajsberg [:julienw] from comment #6)
> And David Baron "definitely remembers some very dodgy code in nsImageFrame
> that couldn't figure out correctly what area it should invalidate though
> [he] thinks it's better than it used to be."

I don't think that code is there anymore, though.

Comment 9

[Gabriele Svelto [:gsvelto]]

(In reply to David Baron [:dbaron] from comment #7)
> I'm reasonably sure image animation is entirely separate from anything that
> would cause reflow. I could certainly imagine it invalidating more than
> necessary in some situations, though (and thus triggering unnecessary
> repainting).
> 
> It would be interesting to know what *is* causing the reflow, though.

Yes, I think the only way is to plant a bunch of GDB breakpoints in the right places to investigate what's going on. I'll also follow Julien's suggestion of setting up paint flashing (which I think can be enabled through the Settings menu in B2G) to figure out exactly what's getting repainted.

Comment 10

[Dietrich Ayala (:dietrich)]

Gabriele has more information, but confirmed this is not really a blocker. We should improve if possible, and he might have a workaround that we could try before release.

Comment 11

[Gabriele Svelto [:gsvelto]]

Digging into the problem I found out the following: the timer event caused by the animated GIF is considered by the refresh driver to be a layout change contrary to CSS animations. This is highlighted by the comment here:

http://mxr.mozilla.org/mozilla-central/source/layout/base/nsPresShell.cpp#3754

It looks like the presence of the GIF animation is causing the layout reflow pretty much by design so changing it might be quite complicated. To mitigate this issue I'm cooking up a Gaia workaround that replaces the GIF animations with a static PNG + CSS code animated by a timer; since this could save us quite a bit of CPU time during network activity I'll try to land it before v1.

Comment 12

[Robert O'Callahan (:roc) (email my personal email if necessary)]

(In reply to Gabriele Svelto [:gsvelto] from comment #11)
> Digging into the problem I found out the following: the timer event caused
> by the animated GIF is considered by the refresh driver to be a layout
> change contrary to CSS animations. This is highlighted by the comment here:
> 
> http://mxr.mozilla.org/mozilla-central/source/layout/base/nsPresShell.
> cpp#3754
> 
> It looks like the presence of the GIF animation is causing the layout reflow
> pretty much by design so changing it might be quite complicated.

Have you got a stack for the call to FlushPendingNotifications that's at fault here? Seems to me as long as the image size is not changing animated images should not be causing reflows.

Comment 13

[Gabriele Svelto [:gsvelto]]

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #12)
> Have you got a stack for the call to FlushPendingNotifications that's at
> fault here? Seems to me as long as the image size is not changing animated
> images should not be causing reflows.

Here's a backtrace captured with GDB, if you look at the profiles I've posted above you'll find more (though less detailed).

#0  PresShell::DoReflow (this=0x476ced00, target=0x47903800, aInterruptible=true) at /home/gsvelto/projects/mozilla-b2g18/layout/base/nsPresShell.cpp:7473
#1  0x40abdd60 in PresShell::ProcessReflowCommands (this=0x476ced00, aInterruptible=true) at /home/gsvelto/projects/mozilla-b2g18/layout/base/nsPresShell.cpp:7701
#2  0x40abe07a in PresShell::FlushPendingNotifications (this=0x476ced00, aFlush=...) at /home/gsvelto/projects/mozilla-b2g18/layout/base/nsPresShell.cpp:3900
#3  0x40ab6bac in PresShell::WillPaint (this=0x476ced00, aWillSendDidPaint=<value optimized out>) at /home/gsvelto/projects/mozilla-b2g18/layout/base/nsPresShell.cpp:7142
#4  0x40ccdd3e in nsViewManager::CallWillPaintOnObservers (this=0x471ec280, aWillSendDidPaint=true) at /home/gsvelto/projects/mozilla-b2g18/view/src/nsViewManager.cpp:1260
#5  0x40ccea70 in nsViewManager::ProcessPendingUpdates (this=0x471ec280) at /home/gsvelto/projects/mozilla-b2g18/view/src/nsViewManager.cpp:1219
#6  0x40abfb56 in nsRefreshDriver::Notify (this=0x43a03c10, aTimer=<value optimized out>) at /home/gsvelto/projects/mozilla-b2g18/layout/base/nsRefreshDriver.cpp:436
#7  0x4115ec84 in nsTimerImpl::Fire (this=0x43e812e0) at /home/gsvelto/projects/mozilla-b2g18/xpcom/threads/nsTimerImpl.cpp:476
#8  0x4115ed32 in nsTimerEvent::Run (this=<value optimized out>) at /home/gsvelto/projects/mozilla-b2g18/xpcom/threads/nsTimerImpl.cpp:556
#9  0x4115ce6a in nsThread::ProcessNextEvent (this=0x403098e0, mayWait=<value optimized out>, result=0xbecee7af) at /home/gsvelto/projects/mozilla-b2g18/xpcom/threads/nsThread.cpp:620
#10 0x4113d2a6 in NS_ProcessNextEvent_P (thread=0x471ec280, mayWait=false) at /home/gsvelto/projects/B2G/objdir-gecko/xpcom/build/nsThreadUtils.cpp:236
#11 0x41073658 in mozilla::ipc::MessagePump::Run (this=0x40302400, aDelegate=0x4032b0c0) at /home/gsvelto/projects/mozilla-b2g18/ipc/glue/MessagePump.cpp:82
#12 0x4117e644 in MessageLoop::RunInternal (this=0x1000000) at /home/gsvelto/projects/mozilla-b2g18/ipc/chromium/src/base/message_loop.cc:215
#13 0x4117e6fa in MessageLoop::RunHandler (this=0x4032b0c0) at /home/gsvelto/projects/mozilla-b2g18/ipc/chromium/src/base/message_loop.cc:208
#14 MessageLoop::Run (this=0x4032b0c0) at /home/gsvelto/projects/mozilla-b2g18/ipc/chromium/src/base/message_loop.cc:182
#15 0x40ffbca0 in nsBaseAppShell::Run (this=0x4290d820) at /home/gsvelto/projects/mozilla-b2g18/widget/xpwidgets/nsBaseAppShell.cpp:163
#16 0x40f5f9d0 in nsAppStartup::Run (this=0x42a7b640) at /home/gsvelto/projects/mozilla-b2g18/toolkit/components/startup/nsAppStartup.cpp:290
#17 0x4099aafa in XREMain::XRE_mainRun (this=0xbecee96c) at /home/gsvelto/projects/mozilla-b2g18/toolkit/xre/nsAppRunner.cpp:3794
#18 0x4099d164 in XREMain::XRE_main (this=0xbecee96c, argc=<value optimized out>, argv=0xbecf0b54, aAppData=<value optimized out>) at /home/gsvelto/projects/mozilla-b2g18/toolkit/xre/nsAppRunner.cpp:3860
#19 0x4099d2b0 in XRE_main (argc=1, argv=0xbecf0b54, aAppData=0x1f180, aFlags=<value optimized out>) at /home/gsvelto/projects/mozilla-b2g18/toolkit/xre/nsAppRunner.cpp:3935
#20 0x0000a11e in do_main (argc=1, argv=0xbecf0b54) at /home/gsvelto/projects/mozilla-b2g18/b2g/app/nsBrowserApp.cpp:164
#21 main (argc=1, argv=0xbecf0b54) at /home/gsvelto/projects/mozilla-b2g18/b2g/app/nsBrowserApp.cpp:249

Comment 14

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Hmm, unfortunately that's not useful.

I guess what I really want is a callstack for PresShell::FrameNeedsReflow.

Comment 15

[Gabriele Svelto [:gsvelto]]

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #14)
> I guess what I really want is a callstack for PresShell::FrameNeedsReflow.

I did a few checks and I get different traces depending on the execution time, unfortunately I cannot tell which one are the most interesting for us. I'll attach the ones that crop up more frequently. Additionally I have prepared a Gaia patch that replaces the GIF animation with a static PNG containing the frames; this image is then animated through a timer by changing its background position property. Unfortunately the performance impact seems to be no better than what we're seeing here which is quite disappointing :-(

Comment 16

[Gabriele Svelto [:gsvelto]]

Attachment: Backtrace from PresShell::FrameNeedsReflow

Comment 17

[Gabriele Svelto [:gsvelto]]

Attachment: Backtrace from PresShell::FrameNeedsReflow (second sample)

Comment 18

[Gabriele Svelto [:gsvelto]]

Attachment: Backtrace from PresShell::FrameNeedsReflow (third sample)

Comment 19

[Robert O'Callahan (:roc) (email my personal email if necessary)]

The second and third samples show script running and causing reflows. In the second sample script is calling setValue on a <progress> element; this triggers reflow, I think because the progress element's progress bar needs to change size. In the third sample a setTimeout is setting the textContent of some XML element, which also causes reflow.

The first sample is unclear, but it could be triggered by the code in the third sample.

You might want to try reducing the frequency of those updates. Anyway, these aren't related to animated GIFs.

Comment 20

[Gabriele Svelto [:gsvelto]]

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #19)
> The second and third samples show script running and causing reflows. In the
> second sample script is calling setValue on a <progress> element; this
> triggers reflow, I think because the progress element's progress bar needs
> to change size. In the third sample a setTimeout is setting the textContent
> of some XML element, which also causes reflow.

Yes, this must be the progress bar, it's updated once per second.

> The first sample is unclear, but it could be triggered by the code in the
> third sample.
> 
> You might want to try reducing the frequency of those updates. Anyway, these
> aren't related to animated GIFs.

I see, I will try to turn off all these updates in order to drill down to the actual problem.

Comment 21

[Gabriele Svelto [:gsvelto]]

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #19)
> You might want to try reducing the frequency of those updates. Anyway, these
> aren't related to animated GIFs.

I've hacked Gaia to disable all sort of refreshes but the animated GIFs, and as you suggested the calls to PresShell::DoReflow have gone now that there's only animated GIFs on the screen. I've been chasing the wrong lead all along :-( Thanks for helping out on this, I would have probably wasted more time looking at layout code.

CPU consumption remains high with both GIFs running, this is a sample of one GIF running (~17% CPU consumption in the main process):

http://people.mozilla.com/~bgirard/cleopatra/#report=bce99774310893e1af6751ae1317441d22085798

And this is a sample with both GIFs running (~27-30% CPU consumption):

http://people.mozilla.com/~bgirard/cleopatra/#report=1445ccace7361d7c3da39880466af7a471dcd6f0

Additionally a trace of PresShell::FlushPendingNotifications during these updates looks like this:

#0  PresShell::FlushPendingNotifications (this=0x48337500, aFlush=...) at /home/gsvelto/projects/mozilla-b2g18/layout/base/nsPresShell.cpp:3755
#1  0x40ac6d68 in PresShell::WillPaint (this=0x48337500, aWillSendDidPaint=<value optimized out>) at /home/gsvelto/projects/mozilla-b2g18/layout/base/nsPresShell.cpp:7142
#2  0x40cde1be in nsViewManager::CallWillPaintOnObservers (this=0x474c6940, aWillSendDidPaint=true) at /home/gsvelto/projects/mozilla-b2g18/view/src/nsViewManager.cpp:1260
#3  0x40cdeef0 in nsViewManager::ProcessPendingUpdates (this=0x474c6940) at /home/gsvelto/projects/mozilla-b2g18/view/src/nsViewManager.cpp:1219
#4  0x40acfd0e in nsRefreshDriver::Notify (this=0x42ef6650, aTimer=<value optimized out>) at /home/gsvelto/projects/mozilla-b2g18/layout/base/nsRefreshDriver.cpp:436
#5  0x4116fa4c in nsTimerImpl::Fire (this=0x442b1c40) at /home/gsvelto/projects/mozilla-b2g18/xpcom/threads/nsTimerImpl.cpp:476
#6  0x4116fafa in nsTimerEvent::Run (this=<value optimized out>) at /home/gsvelto/projects/mozilla-b2g18/xpcom/threads/nsTimerImpl.cpp:556
#7  0x4116dc32 in nsThread::ProcessNextEvent (this=0x404098e0, mayWait=<value optimized out>, result=0xbeb2e78f) at /home/gsvelto/projects/mozilla-b2g18/xpcom/threads/nsThread.cpp:620
#8  0x4114e05e in NS_ProcessNextEvent_P (thread=0x474c6940, mayWait=false) at /home/gsvelto/projects/B2G/objdir-gecko/xpcom/build/nsThreadUtils.cpp:237
#9  0x41084d1c in mozilla::ipc::MessagePump::Run (this=0x40402400, aDelegate=0x4042b0c0) at /home/gsvelto/projects/mozilla-b2g18/ipc/glue/MessagePump.cpp:82
#10 0x4118f420 in MessageLoop::RunInternal (this=0x1000000) at /home/gsvelto/projects/mozilla-b2g18/ipc/chromium/src/base/message_loop.cc:215
#11 0x4118f4d6 in MessageLoop::RunHandler (this=0x4042b0c0) at /home/gsvelto/projects/mozilla-b2g18/ipc/chromium/src/base/message_loop.cc:208
#12 MessageLoop::Run (this=0x4042b0c0) at /home/gsvelto/projects/mozilla-b2g18/ipc/chromium/src/base/message_loop.cc:182
#13 0x4100cc60 in nsBaseAppShell::Run (this=0x42d0d940) at /home/gsvelto/projects/mozilla-b2g18/widget/xpwidgets/nsBaseAppShell.cpp:163
#14 0x40f70578 in nsAppStartup::Run (this=0x42e83700) at /home/gsvelto/projects/mozilla-b2g18/toolkit/components/startup/nsAppStartup.cpp:290
#15 0x409aabba in XREMain::XRE_mainRun (this=0xbeb2e94c) at /home/gsvelto/projects/mozilla-b2g18/toolkit/xre/nsAppRunner.cpp:3794
#16 0x409ad224 in XREMain::XRE_main (this=0xbeb2e94c, argc=<value optimized out>, argv=0xbeb30b34, aAppData=<value optimized out>) at /home/gsvelto/projects/mozilla-b2g18/toolkit/xre/nsAppRunner.cpp:3860
#17 0x409ad370 in XRE_main (argc=1, argv=0xbeb30b34, aAppData=0x1f180, aFlags=<value optimized out>) at /home/gsvelto/projects/mozilla-b2g18/toolkit/xre/nsAppRunner.cpp:3935
#18 0x0000a11e in do_main (argc=1, argv=0xbeb30b34) at /home/gsvelto/projects/mozilla-b2g18/b2g/app/nsBrowserApp.cpp:164
#19 main (argc=1, argv=0xbeb30b34) at /home/gsvelto/projects/mozilla-b2g18/b2g/app/nsBrowserApp.cpp:249

I'll look into the paint code, the traces show the code used for building display lists taking a significant amount of time; maybe some savings can be achieved there.

Comment 22

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

We have an optimization in gecko that will drive animated images pretty much as cheaply as possible in current architecture.  If we're going through display-list building we're not hitting that.

mattwoodrow may be able to help diagnose why we're falling off the fastpath.

Comment 23

[Matt Woodrow (:mattwoodrow)]

You'll want to get callstacks for what is driving painting, nsRefreshDriver::ScheduleViewManagerFlush().

The animated image optimization only works if the image gets assigned its own layer. This doesn't happen in the general case, though we could look at adjusting the heuristics here if necessary.

The simplest way to get this behaviour currently is to add a 3d transform to the image, such as "transform: perspective(1px);"

Comment 24

[Gabriele Svelto [:gsvelto]]

(In reply to Matt Woodrow (:mattwoodrow) from comment #23)
> You'll want to get callstacks for what is driving painting,
> nsRefreshDriver::ScheduleViewManagerFlush().

I'll have a look at that and see what's going on. However something happened between yesterday and today because with the latest version of mozilla-b2g18 I have measured a significant drop in CPU usage. One animation now makes the main process over around 13% and with both enabled it's 22%. Still significant but much less than what I was seeing before.

> The animated image optimization only works if the image gets assigned its
> own layer. This doesn't happen in the general case, though we could look at
> adjusting the heuristics here if necessary.
> 
> The simplest way to get this behaviour currently is to add a 3d transform to
> the image, such as "transform: perspective(1px);"

I tried that but it didn't seem to have any effect performance-wise with today's build, however since CPU usage has gone down already I suspect that the way these animations are handled has changed. I'll re-profile & generate back-traces today.

On a side note I've encountered an interesting problem while trying to replace those animations with small canvas elements animated via a timed script (my second Gaia work-around attempt for this bug). Painting the canvas elements doesn't seem to work properly if they're below a certain size and I can partially reproduce the issue in the browser. I might file another bug for this.

Comment 25

[Gabriele Svelto [:gsvelto]]

I've run this behavior through the profiler and this is what I get:

http://people.mozilla.com/~bgirard/cleopatra/#report=7a44e0823781a6d0e602916718cc29ef06d14ce5

Most of the time is being spent within nsDisplayList::PaintRoot() (divided among ShadowLayerForwarder::EndTransaction, BasicLayerManager::EndTransactionInternal and ContainerState::ProcessDisplayItems). Some more time goes in ViewportFrame::ComputeVisibilityForRoot().

A backtrace of nsRefreshDriver::ScheduleViewManagerFlush shows this:

nsRefreshDriver::ScheduleViewManagerFlush (this=0x429f6650) at mozilla-b2g18/layout/base/nsRefreshDriver.cpp:541
PresShell::ScheduleViewManagerFlush (this=0x472c1500) at mozilla-b2g18/layout/base/nsPresShell.cpp:3416
nsIFrame::SchedulePaint (this=0x488e3d20, aFlags=0) at mozilla-b2g18/layout/generic/nsFrame.cpp:4963
InvalidateFrameInternal (aFrame=0x488e3d20, aHasDisplayItem=true) at mozilla-b2g18/layout/generic/nsFrame.cpp:4797
nsIFrame::InvalidateFrame (this=0x488e3d20, aDisplayItemKey=<value optimized out>) at mozilla-b2g18/layout/generic/nsFrame.cpp:4860
mozilla::css::ImageLoader::DoRedraw (this=<value optimized out>, aFrameSet=0x40406f7c) at mozilla-b2g18/layout/style/ImageLoader.cpp:328
mozilla::css::ImageLoader::FrameChanged (this=0x43fa2080, aRequest=<value optimized out>, aContainer=<value optimized out>, aDirtyRect=<value optimized out>) at mozilla-b2g18/layout/style/ImageLoader.cpp:414
imgRequestProxy::FrameChanged (this=0x488dbb80, container=0x40443990, dirtyRect=0xbe882534) at mozilla-b2g18/image/src/imgRequestProxy.cpp:606
imgStatusTracker::SendFrameChanged (this=<value optimized out>, aProxy=0x43fa2080, aContainer=<value optimized out>, aDirtyRect=0x4725f000) at mozilla-b2g18/image/src/imgStatusTracker.cpp:478
imgRequest::FrameChanged (this=0x487a1870, request=<value optimized out>, container=0x40443990, dirtyRect=0xbe882534) at mozilla-b2g18/image/src/imgRequest.cpp:516
mozilla::image::RasterImage::RequestRefresh (this=0x40443990, aTime=<value optimized out>) at mozilla-b2g18/image/src/RasterImage.cpp:521
nsRefreshDriver::ImageRequestEnumerator (aEntry=<value optimized out>, aUserArg=<value optimized out>) at mozilla-b2g18/layout/base/nsRefreshDriver.cpp:474
nsTHashtable<nsISupportsHashKey>::s_EnumStub (table=<value optimized out>, entry=<value optimized out>, number=<value optimized out>, arg=0x4725f000) at ../../dist/include/nsTHashtable.h:486
PL_DHashTableEnumerate (table=0x4820670c, etor=0x40af3055 <nsTHashtable<nsISupportsHashKey>::s_EnumStub(PLDHashTable*, PLDHashEntryHdr*, unsigned int, void*)>, arg=<value optimized out>) at B2G/objdir-gecko/xpcom/build/pldhash.cpp:716
nsTHashtable<nsISupportsHashKey>::EnumerateEntries (this=0x482066b0, aTimer=<value optimized out>) at ../../dist/include/nsTHashtable.h:237
nsRefreshDriver::Notify (this=0x482066b0, aTimer=<value optimized out>) at mozilla-b2g18/layout/base/nsRefreshDriver.cpp:421
nsTimerImpl::Fire (this=0x471f1700) at mozilla-b2g18/xpcom/threads/nsTimerImpl.cpp:476
nsTimerEvent::Run (this=<value optimized out>) at mozilla-b2g18/xpcom/threads/nsTimerImpl.cpp:556
nsThread::ProcessNextEvent (this=0x404098e0, mayWait=<value optimized out>, result=0xbe8827af) at mozilla-b2g18/xpcom/threads/nsThread.cpp:620
NS_ProcessNextEvent_P (thread=0x482f1900, mayWait=true) at B2G/objdir-gecko/xpcom/build/nsThreadUtils.cpp:237
mozilla::ipc::MessagePump::Run (this=0x40402400, aDelegate=0x4042b0c0) at mozilla-b2g18/ipc/glue/MessagePump.cpp:117
MessageLoop::RunInternal (this=0x1000001) at mozilla-b2g18/ipc/chromium/src/base/message_loop.cc:215
MessageLoop::RunHandler (this=0x4042b0c0) at mozilla-b2g18/ipc/chromium/src/base/message_loop.cc:208
MessageLoop::Run (this=0x4042b0c0) at mozilla-b2g18/ipc/chromium/src/base/message_loop.cc:182
nsBaseAppShell::Run (this=0x4280d880) at mozilla-b2g18/widget/xpwidgets/nsBaseAppShell.cpp:163
nsAppStartup::Run (this=0x42983670) at mozilla-b2g18/toolkit/components/startup/nsAppStartup.cpp:290
XREMain::XRE_mainRun (this=0xbe88296c) at mozilla-b2g18/toolkit/xre/nsAppRunner.cpp:3794
XREMain::XRE_main (this=0xbe88296c, argc=<value optimized out>, argv=0xbe884b54, aAppData=<value optimized out>) at mozilla-b2g18/toolkit/xre/nsAppRunner.cpp:3860
XRE_main (argc=1, argv=0xbe884b54, aAppData=0x1f180, aFlags=<value optimized out>) at mozilla-b2g18/toolkit/xre/nsAppRunner.cpp:3935
do_main (argc=1, argv=0xbe884b54) at mozilla-b2g18/b2g/app/nsBrowserApp.cpp:164
main (argc=1, argv=0xbe884b54) at mozilla-b2g18/b2g/app/nsBrowserApp.cpp:249

The repaint is caused by the animated image, as should be expected, by I still don't get why the repaint operation itself is so expensive. Looking at the profile there's some stuff that really surprises me like a significant chunk of time spent in __futex_syscall3 (I'll try to figure out which mutex is involved here).

Finally I've prepared a Gaia workaround using timers + canvas elements to play the animations. CPU usage looks a bit better peaking at ~15% with both animations running at the same time. It took me a lot more than expected because the icons in the statusbar are 16x16 pixels in size and I've stumbled upon bug 792966 while trying to replace them.

Comment 26

[Robert O'Callahan (:roc) (email my personal email if necessary)]

(In reply to Gabriele Svelto [:gsvelto] from comment #24)
> On a side note I've encountered an interesting problem while trying to
> replace those animations with small canvas elements animated via a timed
> script (my second Gaia work-around attempt for this bug). Painting the
> canvas elements doesn't seem to work properly if they're below a certain
> size and I can partially reproduce the issue in the browser. I might file
> another bug for this.

The optimization Matt was talking about only works on <img> elements. Is it possible for you to use those instead of CSS background images?

Comment 27

[Robert O'Callahan (:roc) (email my personal email if necessary)]

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #26)
> The optimization Matt was talking about only works on <img> elements. Is it
> possible for you to use those instead of CSS background images?

(This could be extended to CSS background images, but it would be better not to do that for B2G v1.)

Comment 28

[Gabriele Svelto [:gsvelto]]

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #26)
> The optimization Matt was talking about only works on <img> elements. Is it
> possible for you to use those instead of CSS background images?

Yes, I it's definitely possible and it will be simpler than the canvas solution.

Comment 29

[Gabriele Svelto [:gsvelto]]

I've made some unscientific tests looking at top with the phone in idle state (but with the screen on) with only the network-activity icon enabled for the three different solutions. I've gathered the results by looking at top -s cpu -m 5 -d 1 so the results are not exactly accurate:

- With an unmodified gecko/gaia combination CPU usage hovers in the 12-14% range possibly spending more time towards the lower-end of the spectrum.

- Using <img> tags instead of <div> CPU usage hovers in the 11-13% range again spending more time towards the lower-end of the spectrum.

- Using <canvas> and a timer with JS code to refresh the element CPU usage drops to 7-8% and stays there fairly consistently.

I frankly didn't expect the canvas-based solution to beat the others by this margin (hurrah for HTML5!). Considering the difference I'll go for it even though it adds a small bit of extra complexity to the JS code. I think the CPU savings are worth the trouble considering that they will most likely happen when loading heavy pages in the browser app.

Comment 30

[Robert O'Callahan (:roc) (email my personal email if necessary)]

(In reply to Gabriele Svelto [:gsvelto] from comment #29)
> - Using <img> tags instead of <div> CPU usage hovers in the 11-13% range
> again spending more time towards the lower-end of the spectrum.

Did you follow Matt's advice to add "transform: perspective(1px);" to the <img> elements? When working properly, that approach should be strictly better than using canvas/JS.

Comment 31

[Gabriele Svelto [:gsvelto]]

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #30)
> Did you follow Matt's advice to add "transform: perspective(1px);" to the
> <img> elements? When working properly, that approach should be strictly
> better than using canvas/JS.

No, I misunderstood it and tried it on the <div> elements where it didn't have any effect. I'll try applying it to the <img> elements and measure again.

Comment 32

[Gabriele Svelto [:gsvelto]]

To be absolutely certain that I'm doing things correctly I'll describe my last test:

- I've disabled as in the previous tests all notifications/refreshes but the animated icon

- I turned the <div> element + CSS background into an <img> element

- The <img> element has an associated CSS class that looks like this:

.sb-animated-icon {
  transform: perspective(1);
}

Note, I didn't use 1px as suggested in comment 30 because the argument of perspective() is just a number (I tried passing it 1px anyway and it made the icon disappear entirely).

Testing this setup yielded a 12-14% CPU usage in B2G main process on my Otoro. I suppose this isn't expected so if I'm doing anything wrong please point it out because I'd really like to fix (or at least mitigate) this issue before v1.

Comment 33

[Julien Wajsberg [:julienw]]

He may have meant |perspective: 1px;|
(cf https://developer.mozilla.org/en-US/docs/CSS/perspective)

Comment 34

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

Yes, that.

Comment 35

[Gabriele Svelto [:gsvelto]]

(In reply to Julien Wajsberg [:julienw] from comment #33)
> He may have meant |perspective: 1px;|
> (cf https://developer.mozilla.org/en-US/docs/CSS/perspective)

(In reply to Chris Jones [:cjones] [:warhammer] from comment #34)
> Yes, that.

Tried that too, same result as in comment 32. Since we're running out of time and I'd like to land it because it frees up CPU time in all situations that involve network activity if everybody's OK with it I'll try to land the canvas workaround and we can open a distinct bug specifically regarding the issue of high CPU usage when playing GIF/PNG animated files under these conditions.

Comment 36

[Robert O'Callahan (:roc) (email my personal email if necessary)]

That's fine of course.

Comment 37

[Gabriele Svelto [:gsvelto]]

Attachment: Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7566

Pointer to Github pull-request

Comment 38

[Gabriele Svelto [:gsvelto]]

I'll open a separate bug for the issue we've been having with GIF animations, I'd rather resolve the root issue than having to deploy more workarounds. Additionally I noted a further problem, try going to this address and pressing the button "Big hosted app":

http://owapps.cloudfoundry.com/

We display a progress-like animation instead of the progress bar which is what we always did when we didn't have the size of the transfer available. The issue is that it makes the phone completely unresponsive. I suspect it's because the GIF animation (apps/system/style/shared/progress.gif) has a 30ms refresh rate. I'll try to fix this other issue too before closing the bug.

Comment 39

[Gabriele Svelto [:gsvelto]]

I've run it through the profiler again and the GIF animation is not what's causing the "Big hosted app" slowdown. I can see 60%+ I/O wait while installing so I suspect it's the app-cache, though refreshing the progress animation every 30ms would probably still yield some fairly high CPU usage (if it had the chance).

Comment 40

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Comment on attachment 701051 [details]
Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7566

After a second though Tim is probably better to review this.

Comment 41

[Tim Guan-tin Chien [:timdream] (please needinfo)]

Comment on attachment 701051 [details]
Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7566

I am fine with the change, but I doubt whither or not canvas is an overkill of this. Can we animate the background-position property instead? That will put all the representation code into CSS (instead of a |AnimatedIcon()| object)

Comment 42

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Animating background-position won't help, that will require expensive layer rebuilding.

We just need to fix any bugs to make GIF and PNG animation work optimally.

Comment 43

[Gabriele Svelto [:gsvelto]]

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #42)
> We just need to fix any bugs to make GIF and PNG animation work optimally.

Yes, I'm looking for that issue right now and I'll open a dedicated bug for that if we don't have one already. The patch here was meant as a mitigation measure until we fix the root cause.

Comment 44

[Gabriele Svelto [:gsvelto]]

Attachment: Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7648

Pointer to Github pull-request

Comment 45

[Chris Lord [:cwiiis]]

Just had a look at this with paint flashing on (thanks to dbaron for pointing out where this is in the settings) and you can see that for every frame that gets drawn while dragging the notification panel, the entire notification is redrawn (that is, the spinner and the 'Downloading updates...\nx bytes downloaded' label). When the panel is fully open, the only thing flashing is the animation in the status bar.

Redrawing text is a pretty slow thing to do per-frame, and the fact that it's being redrawn may indicate that a reflow has happened (it may not, it's just a possibility). How are the individual notifications structured?

The 'Notifications' and 'Clear all' label don't invalidate during scrolling. Is there something special about the notifications within the panel that's causing this? Does the invalidation disappear when the animation is removed?

Comment 46

[Gabriele Svelto [:gsvelto]]

I've filed a separate issue (bug 836372) for the animated GIF/PNG high CPU usage. I'll freshen the workaround once more when the fix for bug 792966 lands on mozilla-b2g18; afterwards I think this can be closed and work can continue on the specific bug.

Comment 47

[Gabriele Svelto [:gsvelto]]

Attachment: Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7966

Pointer to Github pull-request

Comment 48

[Gabriele Svelto [:gsvelto]]

Comment on attachment 710167 [details]
Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7966

I've refreshed and re-tested the patch, this makes application installation quite smooth and significantly reduces CPU usage during other activities that make the network activity appear (browsing large web pages, streaming video or audio, etc...).

Comment 49

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Comment on attachment 710167 [details]
Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7966

I made some small comments on github.

If this bring some performace improvement on page loading and app installation I feel like it should be uplifted to 1.0.0 as well.

This is low risk for a nice win.

Comment 50

[Gabriele Svelto [:gsvelto]]

Attachment: Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7968

Pointer to Github pull-request

Comment 51

[Gabriele Svelto [:gsvelto]]

Comment on attachment 710181 [details]
Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7968

(In reply to Vivien Nicolas (:vingtetun) (:21) from comment #49)
> I made some small comments on github.

I've revised the patch according to your comments, thanks for the super-quick review.

> If this bring some performace improvement on page loading and app
> installation I feel like it should be uplifted to 1.0.0 as well.
> 
> This is low risk for a nice win.

Yes, it saves us 5-12% CPU time depending if one or both the animations are running and in some cases (heavy browsing, streaming, maps) I think that we need all the CPU time we can get. Once bug 836372 is fixed we can remove this workaround easily and go back to the animated GIFs which I left around for this purpose.

Comment 52

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Comment on attachment 710181 [details]
Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7968

r+ (there is one small nit)

Comment 53

[Gabriele Svelto [:gsvelto]]

(In reply to Vivien Nicolas (:vingtetun) (:21) from comment #52)
> r+ (there is one small nit)

I fixed the last issue and went ahead and merged it:

https://github.com/mozilla-b2g/gaia/commit/a3f3adc7456d72598ebd1fd32d8b91a1eddd2579

Interaction with the phone is now quite smooth when installing big apps so I'll close.

Comment 54

[John Ford [:jhford] CET/CEST Berlin Time]

(In reply to Gabriele Svelto [:gsvelto] from comment #53)
> (In reply to Vivien Nicolas (:vingtetun) (:21) from comment #52)
> > r+ (there is one small nit)
> 
> I fixed the last issue and went ahead and merged it:
> 
> https://github.com/mozilla-b2g/gaia/commit/
> a3f3adc7456d72598ebd1fd32d8b91a1eddd2579
> 
> Interaction with the phone is now quite smooth when installing big apps so
> I'll close.

I see two pull requests in this bug, does this one commit resolve this bug completely?

Comment 55

[Gabriele Svelto [:gsvelto]]

(In reply to John Ford [:jhford] from comment #54)
> I see two pull requests in this bug, does this one commit resolve this bug
> completely?

Yes, this one fixes the high CPU usage caused by the animated icons; I've obsoleted all other pull requests to avoid confusion.

Comment 56

[Jason Smith [:jsmith]]

Verified on 2/11.

Comment 57

[Jason Smith [:jsmith]]

Oh wait, screw up on my part. Disregard.

Comment 58

[Jason Smith [:jsmith]]

Someone needs to land this on the other branches.

Comment 59

[John Ford [:jhford] CET/CEST Berlin Time]

v1-train: c31a3dbf0464c055b6f54879ffd67c18beaa0c58
v1.0.0: 52c4222f97008e8b75164b940ed31d0fe4fe4a8d

Comment 60

[Nick Davidson]

Tested by installing "Big Hosted App" from http://owapps.cloudfoundry.com no lug noticed other then normal download time...(about 15 sec) after download app installed fast.

Comment 61

[Jason Smith [:jsmith]]

Verified on 2/22.

Comment 62

[Evelyn Hung]

Sorry, is this patch really merged into branch v1-train? I can't find the hash above in v1-train.

Comment 63

[Julien Wajsberg [:julienw]]

same for the v1.0.0 commit btw.

Comment 64

[John Ford [:jhford] CET/CEST Berlin Time]

that's very strange, I remember specifically doing this uplift.  I'm also not seeing those commits on the branches so I've done the uplift again, new commits:

v1-train: ca7fdbd4ec9481b2a2a177616c169b974998c8da
v1.0.1: 63ee6f509bea1d42b424af2f3b062f0ce2767889