748994 - Regression in rawfennecstartup 'throbber start' time

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Mark Finkle (:mfinkle) (use needinfo?)]

To see the data:
* Go to http://mrcote.info/phonedash/#
* Pick 'Nightly', 'Local Twitter Page', and 'time to throbber start'
* Pick 'nexus one' and both 'nexus s' devices

You should see a 200ms regression starting on Apr 24th. We need to figure out what caused this issue. I originally thought it was bug 734913, which starts the throbber ASAP in Java even before Gecko is loaded.

However, the tests framework looks for "Throbber Start" in the logcat. Bug 734913 would cause "Throbber Start" to be output to logcat much earlier than previously. I am confused.

Comment 1

[Mark Finkle (:mfinkle) (use needinfo?)]

After looking at the code for the log parser, we are using the last "start" and "stop" pair. Since both "time to throbber start" and "time to throbber stop" have regressed, the earlier throbber is causing the regression.

Comment 2

[Geoff Brown [:gbrown]]

I forgot about this bug and commented in the original bug: see https://bugzilla.mozilla.org/show_bug.cgi?id=734913#c11 -- confirmation of regression due to earlier throbber start.

Comment 3

[Geoff Brown [:gbrown]]

Using the procedure described in bug 734913, I repeated the test with different duration values in mobile/android/base/resources/drawable/progress_spinner.xml.

Duration    Average Ts (latest "throbber start" message)
50          2755 
100         2499 
200         2392 
300         2361 

The 300 ms throbber is obviously less smooth in appearance than the 50 ms version, but is still re-assuring of progress and reasonably appealing. I recommend 200 ms since there seems little improvement beyond that.

Comment 4

[Mark Finkle (:mfinkle) (use needinfo?)]

Geoff, Sriram - If either of you can post a link to an APK with the 200ms value, it would be useful for UX to evaluate the animation.

Comment 5

[Geoff Brown [:gbrown]]

(In reply to Mark Finkle (:mfinkle) from comment #4)
> Geoff, Sriram - If either of you can post a link to an APK with the 200ms
> value, it would be useful for UX to evaluate the animation.

Here is one: http://people.mozilla.org/~gbrown/fennec-15.0a1.en-US.android-arm.apk

This change is simply:

-    <item android:duration="50" android:drawable="@drawable/progress_spinner_1"/>
...
-    <item android:duration="50" android:drawable="@drawable/progress_spinner_18"/>
+    <item android:duration="200" android:drawable="@drawable/progress_spinner_1"/>
...
+    <item android:duration="200" android:drawable="@drawable/progress_spinner_18"/>

Comment 6

[Mark Finkle (:mfinkle) (use needinfo?)]

(In reply to Geoff Brown [:gbrown] from comment #5)
> (In reply to Mark Finkle (:mfinkle) from comment #4)
> > Geoff, Sriram - If either of you can post a link to an APK with the 200ms
> > value, it would be useful for UX to evaluate the animation.
> 
> Here is one:
> http://people.mozilla.org/~gbrown/fennec-15.0a1.en-US.android-arm.apk

Testing this 200ms duration. The animation doesn't feel too bad to me. I barely notice the jank. Given the performance impact, I'd be OK with making this change.

Looking for UX feedback now. Yes, it's not as smooth as it was, but is it acceptable on any level?

Comment 7

[Ian Barlow (:ibarlow)]

This is way too slow. It feels like the phone is bogging down while trying to load a page. We need to do better.

Comment 8

[Ian Barlow (:ibarlow)]

Is there anything we can learn from how Android's stock progress spinner is assembled? Seems like no matter where it shows up (when typing in the google bar, when waiting for email to sync), it is always smooth and fast.

Comment 9

[Wesley Johnston (:wesj)]

Attachment: GlThrobber

I was curious on Friday if spinning the throbber using GL would be less CPU intensive. Turns out, according to top at least, it isn't (5% CPU vs. 0% for the current throbber)? Thought I'd throw this up in case someone else wanted to experiment at least.

Comment 10

[cmtalbert]

We changed the throbberstart/throbberstop to pick up the first occurrence of these instrumentation messages on Monday (May 7). We are now going to re-run all the nightly builds through s1/s2 from 4/20/12 to present so that we can see the results before the regression on 4/23 with this new style of instrumentation.

Those are running now, they will likely finish later tonight or tomorrow.

Results will show up here: http://mrcote.info/phonedash/#/org.mozilla.fennec/throbberstart/remote-twitter/00_23_76_96_cc_6f_nexus_one|78_d6_f0_cf_8d_11_nexus_s|98_0c_82_33_ec_8d_samsung_gs2/2012-04-25/2012-05-09

We removed the old results for this time range from the graph so you'll see things pop in as the tests run. We have the old data in case we need to compare builds.

Comment 11

[Mark Finkle (:mfinkle) (use needinfo?)]

Moving to Sriram. He is working on some new approaches.

Comment 12

[Geoff Brown [:gbrown]]

(In reply to Mark Finkle (:mfinkle) from comment #11)
> Moving to Sriram. He is working on some new approaches.

Fine with me! Let me know if I can do anything to help.


Also, here is another attempt at a simple change: duration=100 and eliminate every 2nd image, so the throbber spins as fast as normal, but is more "jumpy":

http://people.mozilla.org/~gbrown/fennec-15.0a1.en-US.android-arm-100-halfimages.apk

Comment 13

[Sriram Ramasubramanian [:sriram]]

Attachment: WIP

This patch adds back notification code to browser.js.

The progress-bar padding varies to show progress.

The current problems:
1. Sometimes the progress is just current: 1, total: 1. There are no intermediate states. Restarting fennec fixes it.
2. When restarting fennec, progress-bar is shown with full width. This is just the "start throbber on session-restore" code, which needs to be optimized for this progress bar.

Comment 14

[Mark Finkle (:mfinkle) (use needinfo?)]

(In reply to Sriram Ramasubramanian [:sriram] from comment #13)
> Created attachment 623325 [details] [diff] [review]
> WIP
> 
> This patch adds back notification code to browser.js.
> 
> The progress-bar padding varies to show progress.
> 
> The current problems:
> 1. Sometimes the progress is just current: 1, total: 1. There are no
> intermediate states. Restarting fennec fixes it.
> 2. When restarting fennec, progress-bar is shown with full width. This is
> just the "start throbber on session-restore" code, which needs to be
> optimized for this progress bar.

This seems to be working OK for me. I have the following feedback (mainly about progressbars in general):
* The color is not contrasting enough to get my attention.
* We should never show 0% or 100% progress using the onProgress messages. Since we also fire documentStart and documentEnd, those should be the true initial and final progress.
* We should never really display 0% via documentStart or onProgress because the user has no feedback that a process has started. I would suggest showing 5% as a minimum.

Comment 15

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 623325 [details] [diff] [review]
WIP

>+    public void updateProgress(int progress, int total) {

After looking at the entire patch, I am thinking that this method should take no params, but use the selected tab internally.

>     public void setProgressVisibility(boolean visible) {

>             Tab selectedTab = Tabs.getInstance().getSelectedTab();
>             if (selectedTab != null)
>                 setFavicon(selectedTab.getFavicon());

I don't think you need this code anymore

>     void handleDocumentStart(int tabId, final boolean showProgress, String uri) {

>         tab.setState("about:home".equals(uri) ? Tab.STATE_SUCCESS : Tab.STATE_LOADING);
>         tab.updateIdentityData(null);
>+        tab.setProgress(-1, -1);
>         if (Tabs.getInstance().isSelectedTab(tab))
>             getLayerController().getView().getRenderer().resetCheckerboard();
>         mMainHandler.post(new Runnable() {
>             public void run() {
>                 if (Tabs.getInstance().isSelectedTab(tab)) {
>                     mBrowserToolbar.setSecurityMode(tab.getSecurityMode());
>                     if (showProgress && tab.getState() == Tab.STATE_LOADING)
>                         mBrowserToolbar.setProgressVisibility(true);
>+                        mBrowserToolbar.updateProgress(-1, -1);

setProgressVisibility already uses the data from the Tab, so you don't need to call updateProgress here
 
>+    void handleProgressChange(final int tabId, final int current, final int total) {
>+        final Tab tab = Tabs.getInstance().getTab(tabId);
>+        if (tab == null)
>+            return;
>+
>+        tab.setProgress(current, total);
>+
>+        mMainHandler.post(new Runnable() { 
>+            public void run() {
>+                if (!Tabs.getInstance().isSelectedTab(tab))
>+                    return;
>+
>+                mBrowserToolbar.updateProgress(tab.getProgressCurrent(), tab.getProgressTotal());

If updateProgress used the selected tab internally, we could avoid the selectedTab check here. It might feel safer too since a developer couldn't try setting the progress without checking the selected tab first.

>diff --git a/mobile/android/base/Tab.java b/mobile/android/base/Tab.java

>+    private int mProgressCurrent;
>+    private int mProgressTotal;

What if we just stored a percentage? Either as a Float (50% == 0.5) or an Integer (50% == 50)
Then we only need one data member and one setter and one getter

>diff --git a/mobile/android/chrome/content/browser.js b/mobile/android/chrome/content/browser.js

>   this.clickToPlayPluginsActivated = false;
>+   this.filter = {
>+     percentage: 0,
>+     requestsFinished: 0,
>+     requestsTotal: 0
>+   };

The indent looks off

feedback+ for now. we are still not ready to land this. we need:
* Timing tests to show it's actually better
* UX review to make sure they like it enough
* 0% and 100% tweaks for better UX

Comment 16

[Ian Barlow (:ibarlow)]

Is there an updated build we can try out?

Comment 17

[Mark Finkle (:mfinkle) (use needinfo?)]

>diff --git a/mobile/android/base/Makefile.in b/mobile/android/base/Makefile.in

>+  mobile/android/base/resources/drawable/progress.xml                           \

Forgot to add the file? Causes a compile error.

Comment 18

[Mark Finkle (:mfinkle) (use needinfo?)]

(In reply to Ian Barlow (:ibarlow) from comment #16)
> Is there an updated build we can try out?

http://dl.dropbox.com/u/3017599/fennec-throbber.apk

Comment 19

[Mark Finkle (:mfinkle) (use needinfo?)]

(In reply to Geoff Brown [:gbrown] from comment #12)

> Also, here is another attempt at a simple change: duration=100 and eliminate
> every 2nd image, so the throbber spins as fast as normal, but is more
> "jumpy":
> 
> http://people.mozilla.org/~gbrown/fennec-15.0a1.en-US.android-arm-100-
> halfimages.apk

Ian & Madhava: Can you try this build? moving from 50ms (20fps) to 100ms (10fps) does seem to have a big impact on lessening the regression.

Comment 20

[Mark Finkle (:mfinkle) (use needinfo?)]

Bad news for the progress bar. We actually regress more! Not totally surprising since we knew that the Java/JS proxying of the progress messages would affect speed. Also, receiving progress events from nsIWebProgress is known to be slow in JS too.

On my Nexus S:
without patch: 1889 ms
With patch:    2120 ms

Comment 21

[Mark Finkle (:mfinkle) (use needinfo?)]

Attachment: patch (using android framerate)

This patch uses the same frame count and duration as the Android spinners: 12 frames (new images) and 100ms

On my Nexus S:
With patch:  1795 ms

Comment 22

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 624751 [details] [diff] [review]
patch (using android framerate)

OK. This bug is a blocker and the patch works fairly well. It's a compromise between "looks pretty" and "hurts performance".

Comment 23

[Sriram Ramasubramanian [:sriram]]

Comment on attachment 624751 [details] [diff] [review]
patch (using android framerate)

This looks good to me.

Comment 24

[Mark Finkle (:mfinkle) (use needinfo?)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/d1be5a84f402

Comment 25

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/d1be5a84f402

Comment 26

[Joe Drew (not getting mail)]

Mark, if this is ready can you nom it for aurora?

Comment 27

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 624751 [details] [diff] [review]
patch (using android framerate)

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 
User impact if declined: performance regression during startup, possibly during any pageload as well.
Testing completed (on m-c, etc.): a few nigthlies
Risk to taking this patch (and alternatives if risky): low risk
String or UUID changes made by this patch: none

Comment 28

[Mark Finkle (:mfinkle) (use needinfo?)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/1b6c19c33023