Closed Bug 721934 Opened 8 years ago Closed 7 years ago

"Setting up Nightly..." displays on every startup due to slow device storage

Categories

(Firefox for Android :: General, defect, P1, major)

All
Android
defect

Tracking

()

RESOLVED WORKSFORME
Tracking Status
blocking-fennec1.0 --- +
fennec 11+ ---

People

(Reporter: heycam, Assigned: gcp)

References

Details

(Keywords: perf)

Attachments

(4 files)

Installed today's Nightly, and when I start it up I'm brought to a "Setting up Nightly..." screen and it seems to hang there.  At least, it has been showing that for the last 15 minutes and the phone isn't warm so I assume it's not doing anything.
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → DUPLICATE
Duplicate of bug: 721320
I don't see any reason why this would be a dupe of bug 721320. The worst time noted there is <2 minutes. If it takes 15 minutes something is seriously wrong.

Do you know exactly what revision saw this problem? Are you able to get a log off the device?
Status: RESOLVED → REOPENED
Resolution: DUPLICATE → ---
Status: REOPENED → NEW
Duplicate of this bug: 722104
I saw this problem for a couple days across a couple different downloads (via going to nightly.mozilla.org. I finally disappeared on it's own this morning.
Severity: normal → major
Keywords: perf
Hi Cameron,
Any chance you were trying to migrate your Fennec XUL profile (eg. Firefox 9 from Market) to the latest Native Fennec?   And if so, how large is your profile?

Agree with comment 2, this is a serious problem if you're getting that kind of lag.

Paul, did you also have a large profile to migrate when you saw this?

Any more specific reproducible steps will help us narrow down the problem.  THanks for the report.
I've been using Fennec Native daily for months, so if something landed to migrate the profile, then that's possibly what triggered this problem. Back when Fennec was XUL I had sync set up and so between desktop and being my mobiles main browser, I'd expect the profile was huge.

As for more specific steps. I have no clue. I literally opened up Fennec and saw that, for a couple days, I'd go back to Fennec (accidentally far too often) and keep seeing the setting up screen. I even downloaded two different nightly builds in the interim to try and fix the problem and still just kept seeing this screen.
Are you able to go back to XUL Fennec (needs to be Nightly if you were running Nightly, Aurora if you're running Aurora), wait for Sync to have imported your history and everything (again), and then switch back to Native Fennec?

(Maybe copy your places.sqlite file somewhere before the switch back to Native, if possible.)

The change the 27th was to show that screen while profile migration runs. The question is why it's (apparently) running so long. Or why it suddenly decided to finish (=no more screen), for that matter.
Go back to XUL Nightly how? As I say, I've been running Fennec Native for a while (since it came to the nightly channel) and this thing came right out of the blue. It was ignorant of the back button and for some reason felt the need to utilise full screen to be as obtrusive and user unfriendly as possible. Had I have had the option regarding profile migration, I'd have definitely opted against it as I really don't want Google to have free access to my bookmarks or my browsing behaviour to a degree where I can be profiled so completely. It's one of the reasons I choose desktop Firefox over Chrome and most certainly one of the reasons I haven't set up Native Sync on my phone. I at least remember signing up to a service where I was in charge of my data and it would seem that isn't the case any more.
>... and this thing came right out of the blue...as obtrusive and user unfriendly 
>as possible.

I understand your experience with this feature was very bad. We're trying to fix it. But I need help here to track down what went wrong.

I asked you if you were able to go back to XUL Fennec (=install it over the Native Fennec you're using now) and let it sync, because doing so will regenerate the Places (history+bookmarks) database, which is what took so long importing. If you then install Native Fennec over it again, we'll hopefully see this problem reappear. If you can snatch an Android log off the device at that moment, it will provide helpful information (see for example https://wiki.mozilla.org/Mobile/Fennec/Android#Using_logcat --> Using aLogCat)

If anyone else who's seeing this can save a log while it happens, that'll help, too.

>as I really don't want Google to have free access to my bookmarks

We went the effort to implement our own Android bookmark/history storage, completely separated from Google's, and that feature was enabled the 11th of January. Google does not have access to your information.
(In reply to Gian-Carlo Pascutto (:gcp) from comment #9)
> We went the effort to implement our own Android bookmark/history storage,
> completely separated from Google's, and that feature was enabled the 11th of
> January. Google does not have access to your information.

See that's strange because I just opened up the default browser (must be the fifth ever time), checked my bookmarks and low and behold, there are all of my bookmarks which I thought I only shared between myself and Mozilla's sync service.
(In reply to Paul [sabret00the] from comment #10)
> (In reply to Gian-Carlo Pascutto (:gcp) from comment #9)
> > We went the effort to implement our own Android bookmark/history storage,
> > completely separated from Google's, and that feature was enabled the 11th of
> > January. Google does not have access to your information.
> 
> See that's strange because I just opened up the default browser (must be the
> fifth ever time), checked my bookmarks and low and behold, there are all of
> my bookmarks which I thought I only shared between myself and Mozilla's sync
> service.

There was a time, about a week, where we were Sync'ing and using the Android DBs. We do not anymore. Go into the Stock browser and "Clear History". You should not see any of your Firefox data in the stock browser after that.
>There was a time, about a week, where we were Sync'ing and using the Android DBs.

Before the 11th of Jan, Profile Migration (enabled somewhere around Xmas) also synced to the Android DB.
I can't find the option to clear all of my bookmarks which the stock browser appears to be holding on to for dear life.

also can someone link me to the last xul nightly please?
>I can't find the option to clear all of my bookmarks which the stock browser 
>appears to be holding on to for dear life.

Bookmarks: Inside the browser, go to them, click menu->delete, select all
Rest: Settings->privacy settings->...

Might be named somewhat differently - its localized here.

>also can someone link me to the last xul nightly please?

I think this should do the trick:
http://ftp.mozilla.org/pub/mozilla.org/mobile/nightly/latest-mozilla-central-android-xul/fennec-12.0a1.multi.android-arm.apk
Open stock browser -> menu button -> bookmarks -> delete

Only deletes one at a time. I'm unable to find a select all option and there are a numerous amount of bookmarks.
(In reply to Paul [sabret00the] from comment #15)
> Open stock browser -> menu button -> bookmarks -> delete
> 
> Only deletes one at a time. I'm unable to find a select all option and there
> are a numerous amount of bookmarks.

2.3 -> Menu button -> More -> Settings -> Clear History
4.0 -> Menu button -> Settings -> Privacy & Security -> Clear History
I'm on 2.3.7 and that isn't working. I even restarted my phone after. My history from last month and older won't delete and neither will my bookmarks.
(In reply to Paul [sabret00the] from comment #17)
> I'm on 2.3.7 and that isn't working. I even restarted my phone after. My
> history from last month and older won't delete and neither will my bookmarks.

Is this Cyanogenmod?
Yup. CyanogenMod Nightly installed on a HTC Incredible S (Vivo).
(In reply to Tony Chung [:tchung] from comment #5)
> Any chance you were trying to migrate your Fennec XUL profile (eg. Firefox 9
> from Market) to the latest Native Fennec?   And if so, how large is your
> profile?
> 
> Agree with comment 2, this is a serious problem if you're getting that kind
> of lag.
> 
> Paul, did you also have a large profile to migrate when you saw this?
> 
> Any more specific reproducible steps will help us narrow down the problem. 
> THanks for the report.

I am not quite sure how profile migration works.  On my phone, I used both Nightly XUL builds and Firefox Beta from the Market.  When the autoupdating switch was made to Native Fennec last year, I held out on updating my nightly until a couple of weeks ago.  Last week, one of the Fennec Native nightlies had this "Setting up Nightly..." hang.  Is that trying to migrate my Fennec XUL profile data?  What about the history that has been collected while running the Fennec Nightly for the last few weeks?

I downloaded a new nightly late last week and that doesn't show the "Setting up Nightly..." screen.  I don't know whether that is because the profile migration was already considered to have been done, or whether the new build did it correctly (and quickly).  

Where does the profile directory live, so I can check its size?

If I just install the Fennec XUL nightly again, run it, install the Fennec Native nightly, then run it -- will I get the same profile migration as before?  Or will I have lost most of my (potentially large) history and so not be as useful?
>Last week, one of the Fennec Native nightlies had this "Setting up Nightly..." 
>hang.  Is that trying to migrate my Fennec XUL profile data? 

Yes.

>What about the history that has been collected while running the Fennec Nightly 
>for the last few weeks?

They are merged, most recent data takes precedence.

>I downloaded a new nightly late last week and that doesn't show the "Setting up 
>Nightly..." screen.  I don't know whether that is because the profile migration 
>was already considered to have been done, or whether the new build did it 
>correctly (and quickly).  

The actual migration code didn't change after the initial commit that enabled the "Setting up" UI. If you didn't get it later it must have been finished by a previous run.

>Where does the profile directory live, so I can check its size?

You can check the Android log for ProfMigr output; it will print where it expects the profile. Looking there now probably won't reveal anything relevant, though.

>If I just install the Fennec XUL nightly again, run it, install the Fennec Native nightly, 
>then run it -- will I get the same profile migration as before?  Or will I have lost most of 
>my (potentially large) history and so not be as useful?

Your Fennec XUL won't have any history and there will be nothing to migrate when switching back to Native. You'd need to use Sync to get it filled again. Another thing that you can try is to take a places.sqlite from your desktop machine and copy it inside the profile directory on your Android device. If you do the latter, you don't need to reinstall XUL Fennec, just menu->quit Native.
Are there any suggestions on getting the data cleared that Fennec forgot to clean up?
Tracking to make sure this is not a wide scale issue for the relase
tracking-fennec: --- → 11+
I got this today when upgrading Nightly. Last time I upgraded Nightly was perhaps 2-3 weeks ago (I've been mostly testing on Aurora recently, hence the long time since the last update).

The message was there for about two minutes. I eventually pressed the home button to get back to Android's main screen, and then launched Nightly again, but that of course just brought the "Setting up Nightly" screen back up again. However, only about 5 seconds after that, the screen finally disappeared and the normal Fennec start page was shown instead.
Attached file Logfile from a hang.
Logfile from a "Setting up..." hang provided by a user.
(In reply to Gian-Carlo Pascutto (:gcp) from comment #25)
> Logfile from a "Setting up..." hang provided by a user.

that's from me.  i figured out what was happening.. it wasn't technically hung, it was busy migrating history (or something similar) according to the logs.

however this took a very long time (probably 30 to 45 minutes all up), and with no percentage bar, or any other visual indication that it was busy working, it looked hung.
Does this need any other data? As I've now managed to clear the browser data. I can now grab log data.
If anyone has a profile that produces this behavior, and it's reproducible using the steps in comment 9 (or comment 21), then that would be interesting. If you're willing to share your places database (privately) that is nice, if you don't I'll try to post some instructions to get the relevant stats from the places database.
Here's the instructions on how to get the relevant stats from your places.sqlite file (in your profile). I'm interested if it took more than 2 minutes to get your profile migrated to Native Fennec. If you're using Sync (I presume everybody who encountered this bug is), doing this on your desktop profile might already be enough.

Install https://addons.mozilla.org/en-US/firefox/addon/sqlite-manager/

Go to Tools (Press ALT to get the menu)->SQLite Manager

Database->Connect New Database->places.sqlite
Left Window->Tables->moz_bookmarks
Right Window->Structure->More Info->No of Records  <- note down
Same for moz_favicons, moz_historyvisits and moz_places <- note down

Right Window->Execute SQL

Enter SQL:
SELECT places.url AS a_url, places.title AS a_title, MAX(history.visit_date) AS a_date, COUNT(*) AS a_visits, favicon.data AS a_favicon_data, favicon.mime_type AS a_favicon_mime FROM (moz_historyvisits AS history JOIN moz_places AS places ON places.id = history.place_id LEFT OUTER JOIN moz_favicons AS favicon ON places.favicon_id = favicon.id) WHERE places.hidden <> 1 GROUP BY a_url ORDER BY a_visits DESC LIMIT 300

Complete bottom right:  ET: xxxx ms <- note down

Right Window->Execute SQL

Enter SQL:
SELECT places.url AS a_url, places.title AS a_title FROM (moz_places as places JOIN moz_bookmarks as bookmarks ON places.id = bookmarks.fk) WHERE places.hidden <> 1 ORDER BY bookmarks.dateAdded

Complete bottom right: Number of Rows return: xxx ET: xxxx ms <- note down both
moz_bookmarks
# of Records: 1589
# of Indexes: 4
# of Triggers: 0

moz_favicons
# of Records: 366
# of Indexes: 1
# of Triggers: 0

moz_historyvisits 
# of Records: 34168
# of Indexes: 3
# of Triggers: 0

moz_places
# of Records: 26451
# of Indexes: 7
# of Triggers: 0

Query 1 ET: 464ms
Query 2 ET: 18ms
Apologies for the delay.
Assignee: nobody → gpascutto
Priority: -- → P1
blocking-fennec1.0: --- → beta+
Status: NEW → ASSIGNED
Depends on: 721352
Gian-Carlo - What's the plan for this bug?
From what I can gather from the feedback in comment 30, the problem is that these users have *big* profiles. We limit the number of history entries, but not the number of bookmarks. Importing 1600 bookmarks at 2-3 transactions per second easily takes 10 minutes.

I implemented support for batch processing in bug 721352, and adapted the Profile Migrator to use that. Once that lands, migration times for these big profiles should be significantly faster (more than 3 times, probably).

So, I hope that bug 721352 makes this bearable. If you have tens of thousands of bookmarks, it might still take a while. Bug 727129 deals with asking the user if he really wants to do it, and perhaps display a warning that it might take a while.
Cameron/Paul - can you guys still reproduce this on current builds, now that bug 721352 has landed? Trying to assess whether this is still a beta-blocking issue.
I got this twice today.
gcp - what can paul do to help you, here?
I'm not sure what "I got this twice today" means. If Paul's profile failed to migrate, he should have been stuck at this screen every launch on every version since this bug started. If he made it past the screen once, it shouldn't ever come back.

The profile size described in comment 30 should take 45s to migrate with the new code.

Paul, can you describe more precisely what happened? If you can fetch a logfile after it occurs, that can help too. There's more logging in the Profile Migrator now.
Next time (if) it appears. I'll grab a logfile. Basically on two occasions today, I attempted to open a link from Tweetdeck for Android, selected Nightly and instead of being taken to the page, this setup page appeared. I was actually in a rush at the time, so didn't wait around to see how long it took. But did have full access to Nightly in between the two appearances the setup page made.
>But did have full access to Nightly in between the two appearances the setup page 
>made.

Ok, so this isn't actually the database operations being slow. 

We start a timer that shows the "setting up..." screen if 100ms pass before we cancel it. The timer is started right before Profile Migration launches, and stopped right after. If Profile Migration has already run, all it does is check the existence of a single file in the profile.

>Next time (if) it appears. I'll grab a logfile.

Please do so. This looks strange right now.
Our suspicion is this is being caused by a really really horrible file system. Could someone from QA please buy the world's worst sd card, move their profile to it and see if they can reproduce? Thanks.
Keywords: qawanted
(In reply to Johnathan Nightingale [:johnath] from comment #34)
> Cameron/Paul - can you guys still reproduce this on current builds, now that
> bug 721352 has landed? Trying to assess whether this is still a
> beta-blocking issue.

Sorry for the late reply.  I only ever saw this when I tried upgrading from XUL Fennec to Native Fennec.  Since comment 20 I never saw the problem again.
Unfortunately the nature of these migration issues is that they only show up once, unless you do the steps described above the force a reproduction.

While testing some other patches, I discovered you can also get this if the screen *after* Profile Migration (AboutHome) is slow or "almost" locks up. As long as it doesn't allow the graphics thread to run, you'll see the "Setting up" screen, even though it has already finished.
kbrosnan and I don't think this should block beta.
ignore my above comments, qa is working on re-testing.
This has been retested last friday and in the results are in the dev meeting 

https://wiki.mozilla.org/Mobile/Notes/11-Apr-2012#QA

Migration is done under 2 minutes for a huge bookmark list.  1 min for an average sized bookmark list.
re-noming given the latest findings.
blocking-fennec1.0: beta+ → ?
Status: ASSIGNED → RESOLVED
Closed: 8 years ago8 years ago
Resolution: --- → WORKSFORME
blocking-fennec1.0: ? → +
(In reply to Brad Lassey [:blassey] from comment #40)
> Our suspicion is this is being caused by a really really horrible file
> system. Could someone from QA please buy the world's worst sd card, move
> their profile to it and see if they can reproduce? Thanks.

Finally tracked down class 2 microSD cards, arriving tomorrow.   Will look at this again.
Keywords: qawanted
So I guess this bug still needs to be looked at by QA then?
Keywords: qawanted
(In reply to Martijn Wargers [:mw22] (QA - IRC nick: mw22) from comment #49)
> So I guess this bug still needs to be looked at by QA then?

cards wont arrive until monday or tuesday.
(In reply to Tony Chung [:tchung] from comment #50)
> (In reply to Martijn Wargers [:mw22] (QA - IRC nick: mw22) from comment #49)
> > So I guess this bug still needs to be looked at by QA then?
> 
> cards wont arrive until monday or tuesday.

cards arrived, but they are class 4, not class 2.   we still dont have the right hardware to verify this yet.
I was trying to make a migration from XUL build (Nightly 14.0a1 - 4/15) to Native UI build (Nightly 14.0a1 - 4/16). After approx 1m and half in the "Setting up Nightly..." the build crashes. 
Reproducible on both class 4 and class 2 SD card. 
Device: HTC Desire Z
This appeared again briefly yesterday. Should I post a log? Would I be right that I'm just looking for the I/ProfileManager stuff?
>Log crash while setting profile

Can you file a separate bug for that? Doesn't seem to have anything to do with this bug...
>Should I post a log? Would I be right that I'm just looking for the 
>I/ProfileManager stuff?

If it's a log from when this happened, very much. If you can, I'd much rather have the whole log. We don't know what part of Fennec causes this.
I filtered out a few references to my email address that were from another app.
I/ProfileMigrator(18183): Opening path: /data/data/org.mozilla.fennec/files/mozilla/1q8yq42j.default/places.sqlite
I/ProfileMigrator(18183): No database
V/Telemetry(18183): Sending telemetry: {"value":128,"name":"BROWSERPROVIDER_XUL_IMPORT_TIME"}
I/GeckoApp(18183): Profile migration took 586 ms
I/GeckoApp(18183): Startup mode: NORMAL

- It takes 128ms to verify that a single file doesn't exist.
- It takes another 450+ms just to dismiss a dialog.

Brad was right: something is causing your phone/filesystem to run extremely slowly. (Not sure if it's only storage, those 450ms extra seem to disprove that)

We could avoid the screen popping up if we increase our timeout to 200-250ms for example. I did some tests on mine and typical values are 6ms, but sometimes it takes 46ms, so more margin over the 100ms might be good.

Do we have someone with an HTC Incredible S that can verify the performance there?
qawanted: assigning to kevin to also look.  he has a class2 card on his G2
Can't test the worse case due to bug 746860.
Bug 746630 contains the fix.
The fix for bug 746860 you mean?
No. I mean that bug 746630 contains the fix for this bug (seeing this screen is no longer dependent on your SD card/storage speed).
Attached file logs HTC Desire
I am able to reproduce the issue on the HTC Desire (Android 2.2) when migrating from Nightly 15.0a1 2012-05-03 XUL to Nightly 15.0a1 2012-05-03 Native whit the app installed on the phone not the SD card.

Steps to reproduce:
1. Install Nightly XUL 15.0a1.
2. Set up a profile sync on the device and wait for the data to be synced.
3. Download and install Nightly Native 15.0a1
4. Tap the Open button and wait for Nightly to start.

Actual:
After a few minutes I get a "Force close" dialog. Tapping on Wait to continue setting up Nightly just leaves the app standing at the setup screen.

The issue happened twice out of 2 tries.
Keywords: qawanted
Doesn't look related to migration, which finishes after 27 seconds. There's this error further on:

05-03 17:18:28.404: I/GeckoAboutHome(755): error reading json file
05-03 17:18:28.404: I/GeckoAboutHome(755): org.json.JSONException: No value for homepageURL
05-03 17:18:28.404: I/GeckoAboutHome(755): 	at org.json.JSONObject.get(JSONObject.java:354)
05-03 17:18:28.404: I/GeckoAboutHome(755): 	at org.json.JSONObject.getString(JSONObject.java:510)
05-03 17:18:28.404: I/GeckoAboutHome(755): 	at org.mozilla.gecko.AboutHomeContent$10.run(AboutHomeContent.java:516)
05-03 17:18:28.404: I/GeckoAboutHome(755): 	at android.os.Handler.handleCallback(Handler.java:587)
05-03 17:18:28.404: I/GeckoAboutHome(755): 	at android.os.Handler.dispatchMessage(Handler.java:92)
05-03 17:18:28.404: I/GeckoAboutHome(755): 	at android.os.Looper.loop(Looper.java:144)
05-03 17:18:28.404: I/GeckoAboutHome(755): 	at android.app.ActivityThread.main(ActivityThread.java:4937)
05-03 17:18:28.404: I/GeckoAboutHome(755): 	at java.lang.reflect.Method.invokeNative(Native Method)
05-03 17:18:28.404: I/GeckoAboutHome(755): 	at java.lang.reflect.Method.invoke(Method.java:521)
05-03 17:18:28.404: I/GeckoAboutHome(755): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:858)
05-03 17:18:28.404: I/GeckoAboutHome(755): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
05-03 17:18:28.404: I/GeckoAboutHome(755): 	at dalvik.system.NativeStart.main(Native Method)

I'm going to change the title of this bug to avoid it becoming a collection bin for unrelated problems.
Summary: startup hangs at "Setting up Nightly..." → "Setting up Nightly..." displays on every startup due to slow device storage
Looking further the ANR actually seems to be in Sync code. Created Bug 751646. I'll create a separate bug for the warning (doesn't look fatal?) in comment 64.
Created Bug 751648 for that JSON Exception (which looks pretty harmless to me).
Renominating due to comment #63 and the inability to actually use the product one might update to.
Status: RESOLVED → REOPENED
blocking-fennec1.0: + → ?
Resolution: WORKSFORME → ---
Aaron, I see no evidence the report in comment 63 has anything to do with this bug, which is why I created new bugs for it.
Status: REOPENED → RESOLVED
blocking-fennec1.0: ? → +
Closed: 8 years ago7 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.