Closed Bug 897162 Opened 11 years ago Closed 11 years ago

[Fig] about:home starts up slower on Android 2.3.x

Categories

(Firefox for Android Graveyard :: Awesomescreen, defect, P1)

All
Android
defect

Tracking

(firefox26 fixed, firefox27 fixed, fennec26+)

RESOLVED FIXED
Firefox 27
Tracking Status
firefox26 --- fixed
firefox27 --- fixed
fennec 26+ ---

People

(Reporter: liuche, Assigned: bnicholson)

References

(Depends on 1 open bug)

Details

(Keywords: perf, Whiteboard: abouthome-hackathon)

Attachments

(10 files, 2 obsolete files)

On the DroidX running Android 2.3.4, the hometabs are also extremely slow to load (~5-10 seconds). Scrolling on the Bookmarks hometab also highlights the contents of the page. 

Doesn't seem to be present on the Nexus S, also running Android 2.3.
Whiteboard: abouthome-hackathon
Still reproducible?
Flags: needinfo?(liuche)
Priority: -- → P1
I believe, part of the problem is because history tab is loaded before bookmarks tab is loaded. But on the contrary, the Reading list page is not loaded. So, we need to tweak something to make sure the history page is not loaded during startup. That could save us.
Summary: [Fig] Hometab display problems (DroidX - 2.3) → [Fig] about:home starts up slower on Android 2.3.x
I just noticed this on my Nexus S (2.3.4). The bookmarks thumbnails took a really long time to show up on startup.
This isn't as bad now on 2.3 - bookmarks loads fine, but the reading list never loads.
Flags: needinfo?(liuche)
Keywords: perf
The History tab will be lazily inflated once we land sriram's patch in bug 904840. Let's see if that brings any visible performance benefits.
(In reply to Chenxia Liu [:liuche] from comment #4)
> Created attachment 789785 [details]
> Screenshot: Bookmarks screen while slow-loading
> 
> This isn't as bad now on 2.3 - bookmarks loads fine, but the reading list
> never loads.

What's this grey area? Looks quite broken...
tracking-fennec: --- → ?
Component: Theme and Visual Design → Awesomescreen
Hardware: ARM → All
Can we get numbers for this? Perhaps a stopwatch test?
Keywords: qawanted
Assignee: nobody → bnicholson
tracking-fennec: ? → 26+
Keywords: qawanted
I'm having trouble reproducing this. On my Galaxy S, it takes around the same time for the new about:home to load and show thumbnails as it did previously (3-4 seconds). Are you guys still seeing these problems? Any hints for STR? The reading list also shows up fine for me....
Flags: needinfo?(liuche)
I often see this on my Galaxy Q. I start fennec, and nothing shows on the bookmarks tab of the new about:home for many seconds. This morning I started Fennec and even after Gecko was done loading (the favicon filled in to the nightly favicon) there was nothing on the bookmarks screen. I can get you logcat if it helps. I don't have any particular STR - just start Fennec with an average-sized profile.
Clearing needinfo flag, discussed/demoed in-person.
Flags: needinfo?(liuche)
This is not restricted to Android 2.3.x, the same happens with the Nexus S on Android 4.1.2 (stock) with latest m-c nightly. Startup takes 9 seconds on a profile which has been used for some months.
What would be helpful to add to this bug? Profile attachment? Nexus S's are plentiful and this should be easy to reproduce with just Syncing a hefty profile of which we have many of available.
Flags: needinfo?(liuche)
Switching this needinfo to Brian.
Flags: needinfo?(liuche) → needinfo?(bnicholson)
Attached file log.txt
At a first investigation through the bookmark list and history, I got these logs. And first thing in the morning I will investigate furthermore.
(In reply to Teodora Vermesan (:TeoVermesan) from comment #15)
> Created attachment 802403 [details]
> log.txt
> 
> At a first investigation through the bookmark list and history, I got these
> logs. And first thing in the morning I will investigate furthermore.

Did you just start fennec several times? Have you swiped to different pages in about:home?
Teodora started the app one time, swapped to the bookmark pages, reading list and also panning up and down through the items in the lists. All log data is from one running of Fennec, no white screens appeared.
(In reply to Ioana Chiorean from comment #17)
> Teodora started the app one time, swapped to the bookmark pages, reading
> list and also panning up and down through the items in the lists. All log
> data is from one running of Fennec, no white screens appeared.

What device?
Attached file perf_logs
The profile I've used is not very big. I've started the app several times, and browsed across the awesomescreen. Attached the logs. 
Device: HTC Desire Z A7272(Android 2.3.3)
(In reply to Lucas Rocha (:lucasr) from comment #18)
...
> What device?

HTC Desire (simple, not S nor Z nor HD) Android 2.3
Attached file logs from htc 11.09
I've retested again on HTC Desire (Android 2.2 ) with a sync profile of 3.5 Mb.
I started fennec two times and swiped to the bookmark page, reading list and history. After pressing the quit button and opening fennec again, a white screen appears on the bookmark link for several seconds.
(In reply to Teodora Vermesan (:TeoVermesan) from comment #22)
> Created attachment 802844 [details]
> logs from htc 11.09
> 
> I've retested again on HTC Desire (Android 2.2 ) with a sync profile of 3.5
> Mb.
> I started fennec two times and swiped to the bookmark page, reading list and
> history. After pressing the quit button and opening fennec again, a white
> screen appears on the bookmark link for several seconds.

From the logs, it seems the bottleneck is in the DB query, not on the UI code. I find it a bit surprising that the query to list mobile bookmarks is taking about the same time than the more complex top bookmarks query. Teodora, does the profile have tons of mobile bookmarks?

Margaret, what were the fig-specific changes that we've made on the top bookmarks query?
Flags: needinfo?(margaret.leibovic)
(In reply to Archaeopteryx [:aryx] from comment #25)
> Created attachment 802975 [details]
> logcat Nexus S non-initial startup
> 
> The Nexus S is on Android 4.1.2 (stock).

Ouch. Same bottleneck, the queries are taking 9s (top bookmarks grid) and 10s (list of mobile bookmarks). Archaeopteryx, do you have a large number of mobile bookmarks?
(In reply to Archaeopteryx [:aryx] from comment #25)
> Created attachment 802975 [details]
> logcat Nexus S non-initial startup
> 
> The Nexus S is on Android 4.1.2 (stock).

The non-initial startup one is not too bad. 2s (top bookmarks grid) and 2.5s (list of mobile bookmarks).
(In reply to Lucas Rocha (:lucasr) from comment #23)

> Teodora, does the profile have tons of mobile bookmarks?
No, there are a few mobile bookmarks and more desktop ones.
(In reply to Lucas Rocha (:lucasr) from comment #23)

> Margaret, what were the fig-specific changes that we've made on the top
> bookmarks query?

The only fig-specific change I see for that query is this change to make sure the bookmark id is not null:

http://hg.mozilla.org/mozilla-central/diff/936c053afda0/mobile/android/base/db/LocalBrowserDB.java

I wish we didn't need to use the combined view, but that's the only way to get the visit information to let us computer frecency.
Flags: needinfo?(margaret.leibovic)
Nexus One (Android 2.3) - New Profile startup
Nexus One (Android 2.3) - Sync

> D/lucasrperf( 1095): BookmarksPage loading: 367232
> D/lucasrperf( 1095): HistoryPage loading: 377026

Very slow on the Nexus One
Attachment #804488 - Attachment mime type: text/x-log → text/plain
Just a quick update here: one of the most obvious differences between the old and new UIs is that we now run two queries concurrently on startup: one of the top bookmarks grid and another for the list of mobile bookmarks. I experimented with first running the grid query then running the one for the list. This seems to bring a substantial improvement. In Aaron's Nexus One for example, the grid was taking about 3.9s to load, while with my patch it was consistently taking 2.5s. I'll submit a patch with this change.
Yeah, I found the same thing. Nightly takes 4-5 seconds to load about:home on my Galaxy S. Removing the grid (or the bookmarks list) shaves off about 2 seconds; removing the remaining view and loading an empty bookmarks page reduces load time by another second or so. I also tried adding a simple bookmark check query at startup that runs before any other queries, and this still takes two seconds to load, so this seems to be an issue caused by multiple running threads rather than a single query. I even went as far as disabling the Gecko startup, and that made the bookmarks list start up in 600ms.

One option I discussed with Mark last week was maybe trying to figure out a way to do a single query for the list of bookmarks and thumbnails so we aren't trying to run so much in parallel on single core devices. Another more complex option, given the Gecko load time above, could be to delay loading Gecko until the UI is up and running -- after all, there's not much benefit in Gecko running early if there's no way to interact with it. Of course, we wouldn't want to do this if we're loading any non-Java URL at startup, and we might see a benefit doing this only on single core devices.
Flags: needinfo?(bnicholson)
(In reply to Lucas Rocha (:lucasr) from comment #32)
> I'll submit a patch with this change.

Might be worth also adding telemetry probes for the Nightly audience (maybe?) taking a look at the numbers coming back
Attachment #808891 - Flags: review?(lucasr.at.mozilla)
Comment on attachment 808891 [details] [diff] [review]
Lower Gecko thread priority when showing Top Sites page

Are the Log.d's needed?
(In reply to Mark Finkle (:mfinkle) from comment #36)
> Comment on attachment 808891 [details] [diff] [review]
> Lower Gecko thread priority when showing Top Sites page
> 
> Are the Log.d's needed?

I was thinking they might be a good idea to have initially, at least until we can verify that there aren't any regressions. Though I haven't been able to break it, I'm worried about the possibility that the Gecko thread never gets reset to its default priority. Having these in here can be useful for debugging any reports about Firefox being slow.
Comment on attachment 808891 [details] [diff] [review]
Lower Gecko thread priority when showing Top Sites page

Review of attachment 808891 [details] [diff] [review]:
-----------------------------------------------------------------

Looks fine. Two questions before r+:
- I feel slightly nervous about the possibility of the gecko thread priority not being set back to NORMAL in some (unexpected) scenarios. Wouldn't it make sense to encapsulate the priority setter behind a setGeckoThreadPriority() method so that you can post a timeout behind the scenes to ensure that the gecko thread's priority is restored? Something like: when you setting priority to MIN, set priority back to NORMAL after 10 seconds or something. Cancel the timeout if you set priority back to NORMAL before then. Maybe I'm just being paranoid here. Thoughts?
- This patches makes us tweak the gecko thread's priority every time we show the about:home UI. Is that intended? Any potential side-effects? I thought the plan here was to optimize our startup sequence. I'm not against the change as is but I'd like to hear a bit more about the rationale behind it.
Attachment #808891 - Flags: review?(lucasr.at.mozilla) → feedback+
(In reply to Lucas Rocha (:lucasr) from comment #38)
> - I feel slightly nervous about the possibility of the gecko thread priority
> not being set back to NORMAL in some (unexpected) scenarios. Wouldn't it
> make sense to encapsulate the priority setter behind a
> setGeckoThreadPriority() method so that you can post a timeout behind the
> scenes to ensure that the gecko thread's priority is restored? Something
> like: when you setting priority to MIN, set priority back to NORMAL after 10
> seconds or something. Cancel the timeout if you set priority back to NORMAL
> before then. Maybe I'm just being paranoid here. Thoughts?

I have the same concern, so having a fallback here is probably a good idea. I updated the patch with this behavior.

> - This patches makes us tweak the gecko thread's priority every time we show
> the about:home UI. Is that intended? Any potential side-effects? I thought
> the plan here was to optimize our startup sequence. I'm not against the
> change as is but I'd like to hear a bit more about the rationale behind it.

Yeah, Mark brought this up before too, and I intentionally omitted any startup-specific checks. The rationale is that if we're loading the top sites page, it's what the user sees and we should always want it to load as quickly as possible.

I look at it this way: the Gecko thread will be somewhere between idle and completely busy. The busier the thread is, the more the low priority should help reduce context switching while the top sites page populates. The idler the thread is, the less effect the low priority will have since the thread isn't doing anything anyway.
Attachment #808891 - Attachment is obsolete: true
Attachment #810398 - Flags: review?(lucasr.at.mozilla)
Comment on attachment 810398 [details] [diff] [review]
Lower Gecko thread priority when showing Top Sites page, v2

Review of attachment 810398 [details] [diff] [review]:
-----------------------------------------------------------------

If we really want to be safe about the thread priority fallback, the code to restore NORMAL priority should not follow the loader's lifecycle at all. For instance, there's a possibility of the TopSitesPage fragment being destroyed before the loader finishes, which means onLoadFinished would not necessarily be called. You could call resetGeckoThreadPriority() in onLoaderReset() but this feels more like ThreadUtils material to me.

I'd actually add a setGeckoThreadPriority() in ThreadUtils or something. Having the thread priority centrally managed would probably help you with your idea to raise the gecko thread's priority when throbber is visible and would allow us catch any contradicting priorities being set by different parts of the UI, for example.

::: mobile/android/base/home/TopSitesPage.java
@@ +503,5 @@
> +            public void run() {
> +                resetGeckoThreadPriority();
> +            }
> +        };
> +        ThreadUtils.getBackgroundHandler().postDelayed(mPriorityResetRunnable, PRIORITY_RESET_TIMEOUT);

Any special reason for running this in a background thread? Doesn't seem necessary.

@@ +506,5 @@
> +        };
> +        ThreadUtils.getBackgroundHandler().postDelayed(mPriorityResetRunnable, PRIORITY_RESET_TIMEOUT);
> +    }
> +
> +    private void resetGeckoThreadPriority() {

Is is actually safe to call this method from the background thread?
Attachment #810398 - Flags: review?(lucasr.at.mozilla) → review-
Kats, any thoughts?
Flags: needinfo?(bugmail.mozilla)
I definitely like the idea of posting a runnable to reset the priority if it doesn't happen within a specified timeout.I also think this function is general enough to be moved into ThreadUtils. I would probably add functions with these signatures:

public static void depressGeckoPriority(long howLong)
public static void resetGeckoPriority()

and use a private static Runnable in ThreadUtils that is posted/removed. Later if we want to support multiple concurrent priority depressions we can update the code to do that too by using postAtTime(Runnable,Object,long) and returning the Object identifier from depressGeckoPriority and having the caller pass it back in to resetGeckoPriority.
Flags: needinfo?(bugmail.mozilla)
(In reply to Lucas Rocha (:lucasr) from comment #40)
> If we really want to be safe about the thread priority fallback, the code to
> restore NORMAL priority should not follow the loader's lifecycle at all. For
> instance, there's a possibility of the TopSitesPage fragment being destroyed
> before the loader finishes, which means onLoadFinished would not necessarily
> be called.

I'm not sure I understand your point here. I agree that relying on onLoadFinished to reset the priority is potentially fragile; that's why there's a fallback in place. If something goes wrong, the runnable resets the priority to normal after 10 seconds. What's your concern?

> I'd actually add a setGeckoThreadPriority() in ThreadUtils or something.

That was my plan if we ended up using it elsewhere. I didn't really like the idea of moving this to GeckoThread as-is without fixing the concurrency issue of the method potentially being called from multiple places and interfering with each other. I started working on a general approach where we held a stack of in-progress priority manipulations, where the newest priority change would take precendence and pop to the previous state after being reset. This involved putting the timeouts for previous states on hold, calculating the diff between the start time and the current time, and re-posting the runnables.

To keep things simple, though, I decided to just keep the method dumb for now since we probably won't be using this anywhere else. I moved it to ThreadUtils as requested. I'm not thrilled about having a public utility method being fragile, so we should make sure we're careful about calling it.

> ::: mobile/android/base/home/TopSitesPage.java
> @@ +503,5 @@
> > +            public void run() {
> > +                resetGeckoThreadPriority();
> > +            }
> > +        };
> > +        ThreadUtils.getBackgroundHandler().postDelayed(mPriorityResetRunnable, PRIORITY_RESET_TIMEOUT);
> 
> Any special reason for running this in a background thread? Doesn't seem
> necessary.

Ideally, we'd have some kind of thread pool implementation that allows things like this to be posted to new threads instead of funnelling everything through the background thread. Since that's not implemented, I just picked an arbitrary handler. I moved it to the UI thread in this patch, but it shouldn't really matter.

> @@ +506,5 @@
> > +        };
> > +        ThreadUtils.getBackgroundHandler().postDelayed(mPriorityResetRunnable, PRIORITY_RESET_TIMEOUT);
> > +    }
> > +
> > +    private void resetGeckoThreadPriority() {
> 
> Is is actually safe to call this method from the background thread?

mPriorityResetRunnable should probably be volatile, but yes, Thread#setPriority and Handler#removeCallbacks are both thread-safe.
Attachment #810398 - Attachment is obsolete: true
Attachment #812241 - Flags: review?(lucasr.at.mozilla)
Comment on attachment 812241 [details] [diff] [review]
Lower Gecko thread priority when showing Top Sites page, v3

Review of attachment 812241 [details] [diff] [review]:
-----------------------------------------------------------------

Awesome.
Attachment #812241 - Flags: review?(lucasr.at.mozilla) → review+
https://hg.mozilla.org/mozilla-central/rev/14c51f215f98
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 27
SoftVision, please check your phones again with this on tomorrow's Nightly and compare the speed
Flags: needinfo?(fennec)
Keywords: qawanted
I've tested on the following environments:
1. Device: HTC Desire A8181(Bravo)(Android 2.2.2)
   Build: Nightly 27.0a1 (2013-10-08)
2. Device: HTC Desire S(Android 2.3.3)
   Build: Nightly 27.0a1 (2013-10-08)

Steps performed:
1. Set up Sync with a sync profile of 6.6 Mb
2. Force Stop Nightly
3. Start Nightly
4. Swipe to bookmarks.

Results:
At step 3 it takes for about 2 seconds to fully load TOP SITES tab
At step 4 it takes for about 1 second to load BOOKMARKS tab
I would say it is a big improvement compared to the earlier results from logs.
Keywords: qawanted
Flags: needinfo?(fennec)
Comment on attachment 812241 [details] [diff] [review]
Lower Gecko thread priority when showing Top Sites page, v3

[Approval Request Comment]
Bug caused by (feature/regressing bug #): new-about-home
User impact if declined: slow startup, especially on older devices
Testing completed (on m-c, etc.): m-c
Risk to taking this patch (and alternatives if risky): Low risk; this simply lowers the Gecko priority until thumbnails are loaded and resets the Gecko priority afterwords.
String or IDL/UUID changes made by this patch: none
Attachment #812241 - Flags: approval-mozilla-aurora?
Attachment #812241 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Depends on: 922976
I'm not willing to uplift this to Aurora until bug 922976 is addressed. It's the #1 top orange at the moment.
Flags: needinfo?(bnicholson)
Philor disabled 394751.xhtml on m-c and I just did the same on Aurora, so what the hey.

https://hg.mozilla.org/releases/mozilla-aurora/rev/3b057c4ac36c
Flags: needinfo?(bnicholson)
Shouldn't this be backed out, since this is the cause of bug 922976?
Flags: needinfo?(bnicholson)
The consensus is that these tests shouldn't be affected by changes in about:home startup; these are chrome tests, and their scope should be limited to chrome code. The fact that they are affected means the tests should be changed, so disabling the test makes sense for now.
Flags: needinfo?(bnicholson)
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.