Last Comment Bug 748994 - Regression in rawfennecstartup 'throbber start' time
: Regression in rawfennecstartup 'throbber start' time
Status: RESOLVED FIXED
: uiwanted
Product: Firefox for Android
Classification: Client Software
Component: General (show other bugs)
: unspecified
: x86_64 Windows 7
: -- normal (vote)
: Firefox 15
Assigned To: Mark Finkle (:mfinkle) (use needinfo?)
:
: Sebastian Kaspari (:sebastian)
Mentors:
Depends on:
Blocks: 734913
  Show dependency treegraph
 
Reported: 2012-04-25 15:08 PDT by Mark Finkle (:mfinkle) (use needinfo?)
Modified: 2012-05-29 13:21 PDT (History)
9 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
fixed
fixed
+


Attachments
GlThrobber (12.20 KB, patch)
2012-05-07 08:51 PDT, Wesley Johnston (:wesj)
no flags Details | Diff | Splinter Review
WIP (21.41 KB, patch)
2012-05-11 15:19 PDT, Sriram Ramasubramanian [:sriram]
mark.finkle: feedback+
Details | Diff | Splinter Review
patch (using android framerate) (39.89 KB, patch)
2012-05-17 08:33 PDT, Mark Finkle (:mfinkle) (use needinfo?)
sriram.mozilla: review+
bugzilla: approval‑mozilla‑aurora+
Details | Diff | Splinter Review

Description Mark Finkle (:mfinkle) (use needinfo?) 2012-04-25 15:08:30 PDT
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?) 2012-04-27 07:26:57 PDT
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] 2012-05-02 09:03:49 PDT
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] 2012-05-03 13:10:43 PDT
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?) 2012-05-04 13:09:45 PDT
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] 2012-05-04 14:41:52 PDT
(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?) 2012-05-04 15:44:27 PDT
(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) 2012-05-07 06:54:04 PDT
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) 2012-05-07 06:57:01 PDT
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) 2012-05-07 08:51:58 PDT
Created attachment 621621 [details] [diff] [review]
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 2012-05-09 13:00:46 PDT
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?) 2012-05-11 14:21:30 PDT
Moving to Sriram. He is working on some new approaches.
Comment 12 Geoff Brown [:gbrown] 2012-05-11 14:41:01 PDT
(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] 2012-05-11 15:19:42 PDT
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.
Comment 14 Mark Finkle (:mfinkle) (use needinfo?) 2012-05-15 08:15:14 PDT
(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?) 2012-05-15 08:30:55 PDT
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) 2012-05-15 08:35:12 PDT
Is there an updated build we can try out?
Comment 17 Mark Finkle (:mfinkle) (use needinfo?) 2012-05-15 08:46:30 PDT
>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?) 2012-05-15 08:46:41 PDT
(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?) 2012-05-16 23:13:38 PDT
(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?) 2012-05-17 08:31:04 PDT
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?) 2012-05-17 08:33:48 PDT
Created attachment 624751 [details] [diff] [review]
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?) 2012-05-21 13:59:12 PDT
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] 2012-05-21 14:01:30 PDT
Comment on attachment 624751 [details] [diff] [review]
patch (using android framerate)

This looks good to me.
Comment 24 Mark Finkle (:mfinkle) (use needinfo?) 2012-05-21 22:01:39 PDT
https://hg.mozilla.org/integration/mozilla-inbound/rev/d1be5a84f402
Comment 25 Ed Morley [:emorley] 2012-05-23 08:12:06 PDT
https://hg.mozilla.org/mozilla-central/rev/d1be5a84f402
Comment 26 Joe Drew (not getting mail) 2012-05-28 11:49:05 PDT
Mark, if this is ready can you nom it for aurora?
Comment 27 Mark Finkle (:mfinkle) (use needinfo?) 2012-05-28 22:24:36 PDT
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?) 2012-05-29 13:21:52 PDT
https://hg.mozilla.org/releases/mozilla-aurora/rev/1b6c19c33023

Note You need to log in before you can comment on or make changes to this bug.