834337 - Regression: Slowdown in About:Home load and display of thumbnails

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Aaron Train [:aaronmt]]

On a new profile starting a mozilla-central (01/24) build of Fennec has a large slowdown in the initial appearance of the thumbnails (roughly 2-3 seconds depending on device).

http://hg.mozilla.org/mozilla-central/pushloghtml?&fromchange=2876e73c9b6f&tochange=98ea4d294369

When the thumbnails do display, I see this dumped to console

E/StrictMode( 5855): java.lang.Throwable: Explicit termination method 'close' not called
E/StrictMode( 5855): 	at dalvik.system.CloseGuard.open(CloseGuard.java:184)
E/StrictMode( 5855): 	at android.database.CursorWindow.<init>(CursorWindow.java:107)
E/StrictMode( 5855): 	at android.database.AbstractWindowedCursor.clearOrCreateWindow(AbstractWindowedCursor.java:198)
E/StrictMode( 5855): 	at android.database.sqlite.SQLiteCursor.fillWindow(SQLiteCursor.java:139)
E/StrictMode( 5855): 	at android.database.sqlite.SQLiteCursor.getCount(SQLiteCursor.java:133)
E/StrictMode( 5855): 	at android.content.ContentResolver.query(ContentResolver.java:390)
E/StrictMode( 5855): 	at android.content.ContentResolver.query(ContentResolver.java:315)
E/StrictMode( 5855): 	at org.mozilla.gecko.db.LocalBrowserDB.getPinnedSites(LocalBrowserDB.java:1133)
E/StrictMode( 5855): 	at org.mozilla.gecko.db.BrowserDB.getTopSites(BrowserDB.java:134)
E/StrictMode( 5855): 	at org.mozilla.gecko.AboutHomeContent.loadTopSites(AboutHomeContent.java:306)
E/StrictMode( 5855): 	at org.mozilla.gecko.AboutHomeContent.access$500(AboutHomeContent.java:70)
E/StrictMode( 5855): 	at org.mozilla.gecko.AboutHomeContent$10.run(AboutHomeContent.java:444)
E/StrictMode( 5855): 	at android.os.Handler.handleCallback(Handler.java:725)
E/StrictMode( 5855): 	at android.os.Handler.dispatchMessage(Handler.java:92)
E/StrictMode( 5855): 	at android.os.Looper.loop(Looper.java:137)
E/StrictMode( 5855): 	at org.mozilla.gecko.util.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)
E/StrictMode( 5855): Finalizing a Cursor that has not been deactivated or closed. database = /data/data/org.mozilla.fennec/files/mozilla/0v9ny8t0.default/browser.db, table = bookmarks, query = SELECT _id, url, title, position FROM bookmarks WHERE ((deleted = 0) AND (parent == ?)) ORDER BY position ASC LIMIT 6
E/StrictMode( 5855): android.database.sqlite.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
E/StrictMode( 5855): 	at android.database.sqlite.SQLiteCursor.<init>(SQLiteCursor.java:98)
E/StrictMode( 5855): 	at android.database.sqlite.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:50)
E/StrictMode( 5855): 	at android.database.sqlite.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1314)
E/StrictMode( 5855): 	at android.database.sqlite.SQLiteQueryBuilder.query(SQLiteQueryBuilder.java:400)
E/StrictMode( 5855): 	at android.database.sqlite.SQLiteQueryBuilder.query(SQLiteQueryBuilder.java:333)
E/StrictMode( 5855): 	at org.mozilla.fennec.db.BrowserProvider.query(BrowserProvider.java:2542)
E/StrictMode( 5855): 	at android.content.ContentProvider.query(ContentProvider.java:652)
E/StrictMode( 5855): 	at android.content.ContentProvider$Transport.query(ContentProvider.java:189)
E/StrictMode( 5855): 	at android.content.ContentResolver.query(ContentResolver.java:372)
E/StrictMode( 5855): 	at android.content.ContentResolver.query(ContentResolver.java:315)
E/StrictMode( 5855): 	at org.mozilla.gecko.db.LocalBrowserDB.getPinnedSites(LocalBrowserDB.java:1133)
E/StrictMode( 5855): 	at org.mozilla.gecko.db.BrowserDB.getTopSites(BrowserDB.java:134)
E/StrictMode( 5855): 	at org.mozilla.gecko.AboutHomeContent.loadTopSites(AboutHomeContent.java:306)
E/StrictMode( 5855): 	at org.mozilla.gecko.AboutHomeContent.access$500(AboutHomeContent.java:70)
E/StrictMode( 5855): 	at org.mozilla.gecko.AboutHomeContent$10.run(AboutHomeContent.java:444)
E/StrictMode( 5855): 	at android.os.Handler.handleCallback(Handler.java:725)
E/StrictMode( 5855): 	at android.os.Handler.dispatchMessage(Handler.java:92)
E/StrictMode( 5855): 	at android.os.Looper.loop(Looper.java:137)
E/StrictMode( 5855): 	at org.mozilla.gecko.util.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)
E/StrictMode( 5855): A resource was acquired at attached stack trace but never released. See java.io.Closeable for information on avoiding resource leaks.
E/StrictMode( 5855): java.lang.Throwable: Explicit termination method 'close' not called
E/StrictMode( 5855): 	at dalvik.system.CloseGuard.open(CloseGuard.java:184)
E/StrictMode( 5855): 	at android.content.ContentResolver$CursorWrapperInner.<init>(ContentResolver.java:1855)
E/StrictMode( 5855): 	at android.content.ContentResolver.query(ContentResolver.java:394)
E/StrictMode( 5855): 	at android.content.ContentResolver.query(ContentResolver.java:315)
E/StrictMode( 5855): 	at org.mozilla.gecko.db.LocalBrowserDB.getPinnedSites(LocalBrowserDB.java:1133)
E/StrictMode( 5855): 	at org.mozilla.gecko.db.BrowserDB.getTopSites(BrowserDB.java:134)
E/StrictMode( 5855): 	at org.mozilla.gecko.AboutHomeContent.loadTopSites(AboutHomeContent.java:306)
E/StrictMode( 5855): 	at org.mozilla.gecko.AboutHomeContent.access$500(AboutHomeContent.java:70)
E/StrictMode( 5855): 	at org.mozilla.gecko.AboutHomeContent$10.run(AboutHomeContent.java:444)
E/StrictMode( 5855): 	at android.os.Handler.handleCallback(Handler.java:725)
E/StrictMode( 5855): 	at android.os.Handler.dispatchMessage(Handler.java:92)
E/StrictMode( 5855): 	at android.os.Looper.loop(Looper.java:137)
E/StrictMode( 5855): 	at org.mozilla.gecko.util.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)

Comment 2

[Aaron Train [:aaronmt]]

This is not a duplicate as I still see this on Nightly (01/28). Creating a new profile, and initial load of about:home has regressed in time to completion, it's very slow. Do you see this? Compare builds from a week ago with a new profile and today's. The time it takes for the complete document to finish is slower than normal.

Can I log the time here?

Comment 3

[Kartikaya Gupta (email:[e-mail])]

(In reply to Aaron Train [:aaronmt] from comment #2)
> Can I log the time here?

Not sure what you mean by this. We have various log lines in logcat (grep for "zerdatime") that might provide useful information to bisect.

I also looked at all the mobile/android files changed in that regression range from comment 0, and there's not much in there. The most likely seems to me bug 832321 which switches themes. It's possible that the Holo Light theme is slower to start up and load than Holo. The only other major change was to remove the "unpin tab" code which should speed things up if anything.

If you have time could you test the inbound builds before/after that change to see if that's the cause?

Comment 4

[Aaron Train [:aaronmt]]

On my TF201, it takes a couple seconds before about:home is complete on new profile

W/GeckoThread( 7468): zerdatime 1988961 - runGecko
E/GeckoConsole( 7468): zerdatime 1359662205466 - browser chrome startup finished.
I/GeckoToolbar( 7468): zerdatime 1991597 - Throbber stop
I/GeckoToolbar( 7468): zerdatime 1992551 - Throbber stop

Comment 5

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

(In reply to Aaron Train [:aaronmt] from comment #4)
> On my TF201, it takes a couple seconds before about:home is complete on new
> profile
> 
> W/GeckoThread( 7468): zerdatime 1988961 - runGecko
> E/GeckoConsole( 7468): zerdatime 1359662205466 - browser chrome startup
> finished.
> I/GeckoToolbar( 7468): zerdatime 1991597 - Throbber stop
> I/GeckoToolbar( 7468): zerdatime 1992551 - Throbber stop

Is that only on the very first run? Or do you see the slowdown on subsequent launches too?

Comment 6

[Aaron Train [:aaronmt]]

(In reply to Mark Finkle (:mfinkle) from comment #5)
> (In reply to Aaron Train [:aaronmt] from comment #4)
> [...]
> Is that only on the very first run? Or do you see the slowdown on subsequent
> launches too?

Only on new profile; here's a Galaxy SII

W/GeckoThread(13011): zerdatime 3964202 - runGecko
E/GeckoConsole(13011): zerdatime 1359670590508 - browser chrome startup finished.
I/GeckoToolbar(13011): zerdatime 3966614 - Throbber stop
I/GeckoToolbar(13011): zerdatime 3966808 - Throbber stop
I/GeckoToolbar(13011): zerdatime 3971381 - Throbber stop

Are those times good or bad?

Comment 7

[Aaron Train [:aaronmt]]

I'll re-test with current Nightly given Sriram's work yesterday

Comment 8

[Aaron Train [:aaronmt]]

Nope, still see this on my LG Nexus 4 (Nightly 02/14). Again to reiterate, the time it takes to show the initial Java UI is fine, the delay between seeing nothing on about:home to thumbnails and the initial telemetry prompt has regressed.

I/GeckoToolbar(20927): zerdatime 7013382 - Throbber stop
W/GeckoThread(20927): zerdatime 7014236 - runGecko
E/GeckoConsole(20927): zerdatime 1360869669239 - browser chrome startup finished.
I/GeckoToolbar(20927): zerdatime 7016052 - Throbber stop
I/GeckoToolbar(20927): zerdatime 7016413 - Throbber stop

Comment 9

[Aaron Train [:aaronmt]]

This has been keeping me up at night. Had some time to find a regression-range. This is a regression from bug 780561

http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=176b448e4a38&tochange=2d2f0c12218b

Steps to reproduce

i) Download build from: http://ftp.mozilla.org/pub/mozilla.org/mobile/tinderbox-builds/mozilla-inbound-android/1358942936/fennec-21.0a1.en-US.android-arm.apk
ii) Launch with a new profile
iii) See time it takes to finalize about:home

Repeat and compare with: http://ftp.mozilla.org/pub/mozilla.org/mobile/tinderbox-builds/mozilla-inbound-android/1358937596/fennec-21.0a1.en-US.android-arm.apk

Something in Gecko start-up has really slowed things down. Mike?

Comment 10

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

Could have something to do with the time it takes to create a new profile and copy and default files into the profile.

Comment 11

[Mike Hommey [:glandium]]

I can confirm the regression on ec95c1d93af0, but it makes no sense to me. Still looking.

Comment 12

[Mike Hommey [:glandium]]

It /seems/ I got the regression under control by recompressing omni.ja with the zip tool. And it /seems/ I got it back by recompressing omni.ja with the zip tool in exactly the same order as after plain packaging.

This suggests the "good" performance was mere luck, as the order in which files were layed out with the old packager was uncontrolled (as opposed to the new packager). Which also suggests the fix would be to find what file(s) is(are) making the difference and reordering mobile/android/installer/package-manifest.in.

Comment 13

[Mike Hommey [:glandium]]

And it looks like it's because of chrome/chrome/content/branding/favicon64.png.

Comment 14

[Mike Hommey [:glandium]]

Attachment: Make chrome/chrome/content/branding/favicon64.png the first file in omni.ja

Testing this on try: https://tbpl.mozilla.org/?tree=Try&rev=97e348888645
Aaron, can you try this build when it's done?

Comment 15

[Mike Hommey [:glandium]]

The build is here:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-97e348888645/try-android/fennec-21.0a1.en-US.android-arm.apk

From local runs of that build, it looks like it's even faster than it used to be. I'm tempted to file a new bug (or clone this one) to make GeckoJarReader less problematic: there's really no reason why it should be that slower when the file is at the end as opposed to at the beginning of the omni.ja.

Comment 16

[Mike Hommey [:glandium]]

Comment on attachment 715455 [details] [diff] [review]
Make chrome/chrome/content/branding/favicon64.png the first file in omni.ja

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

The new packager places files in the omnijar in the order they come from the manifest. Adding the favicon at the beginning makes it the first item (well, actually not really, because there are manifests that go before it, but close to first). Note it adds the following packaging warning:

Warning: /builds/slave/try-and-0000000000000000000000/build/obj-firefox/mobile/android/installer/package-manifest:449: chrome/chrome/content/branding/favicon64.png already added

That line of the package manifest is "@BINPATH@/chrome/chrome@JAREXT@", which expands to "bin/chrome/chrome" which adds all files under chrome/chrome, including chrome/chrome/content/branding/favicon64.png, which is already explicitely added in this patch. I think I'll change the packager to allow such manifests without a warning, but for now it doesn't really matter.

Comment 17

[Jim Mathies [:jimm]]

(In reply to Mike Hommey [:glandium] from comment #15)
> The build is here:
> http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-
> 97e348888645/try-android/fennec-21.0a1.en-US.android-arm.apk
> 
> From local runs of that build, it looks like it's even faster than it used
> to be. I'm tempted to file a new bug (or clone this one) to make
> GeckoJarReader less problematic: there's really no reason why it should be
> that slower when the file is at the end as opposed to at the beginning of
> the omni.ja.

That seems like a very worthy bug to file. Do you know if this is something specific to GeckoJarReader on android, or could we be seeing this weirdness on other platforms?

Comment 18

[Mike Hommey [:glandium]]

(In reply to Jim Mathies [:jimm] from comment #17)
> That seems like a very worthy bug to file. Do you know if this is something
> specific to GeckoJarReader on android, or could we be seeing this weirdness
> on other platforms?

It's specific to GeckoJarReader on android, which, afaik, is not really used besides that favicon. Thus my interrogation.

Comment 19

[Aaron Train [:aaronmt]]

(In reply to Mike Hommey [:glandium] from comment #15)
> The build is here:
> http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-
> 97e348888645/try-android/fennec-21.0a1.en-US.android-arm.apk

Tried it out (Nexus 4, 4.2.2), and yes faster.

Comment 20

[Mike Hommey [:glandium]]

(In reply to Aaron Train [:aaronmt] from comment #19)
> (In reply to Mike Hommey [:glandium] from comment #15)
> > The build is here:
> > http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-
> > 97e348888645/try-android/fennec-21.0a1.en-US.android-arm.apk
> 
> Tried it out (Nexus 4, 4.2.2), and yes faster.

Is it back to previous speed (or even faster), or just faster than the current nightlies?

Comment 21

[Aaron Train [:aaronmt]]

(In reply to Mike Hommey [:glandium] from comment #20)
> Is it back to previous speed (or even faster), or just faster than the
> current nightlies?

Only trying one run here, but, yes, faster than Nightly and prior builds

Try build: 

W/GeckoThread( 5477): zerdatime 2416576 - runGecko
E/GeckoConsole( 5477): zerdatime 1361288590506 - browser chrome startup finished.
I/GeckoToolbar( 5477): zerdatime 2418364 - Throbber stop

Nightly:

W/GeckoThread( 6960): zerdatime 3822571 - runGecko
E/GeckoConsole( 6960): zerdatime 1361288996578 - browser chrome startup finished.
I/GeckoToolbar( 6960): zerdatime 3824394 - Throbber stop

Pre-regression build:

W/GeckoThread( 7374): zerdatime 2952804 - runGecko
E/GeckoConsole( 7374): zerdatime 1361289126709 - browser chrome startup finished.
I/GeckoToolbar( 7374): zerdatime 2954577 - Throbber stop

Comment 22

[Mike Hommey [:glandium]]

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

Comment 23

[Mike Hommey [:glandium]]

Comment on attachment 715455 [details] [diff] [review]
Make chrome/chrome/content/branding/favicon64.png the first file in omni.ja

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 780561
User impact if declined: Startup performance regression under some circumstances
Testing completed (on m-c, etc.): The performance regression has been tested to be obliterated by this workaround (and in fact builds with the patch are faster than builds before bug 780561) on try and has now landed on m-i.
Risk to taking this patch (and alternatives if risky): None. The patch is only changing the order in which one particular file appears in omni.ja on android.
String or UUID changes made by this patch: None

Comment 24

[Alex Keybl [:akeybl]]

Is FF20 confirmed affected? Bug 780561 landed in FF21.

Comment 25

[Mike Hommey [:glandium]]

Ah true, so 20 is not affected by the regression, although it's affected by the root cause (bug 842681). The workaround from here only works with the new packager, which was the cause of the regression anyways.

Comment 26

[Ryan VanderMeulen [:RyanVM]]

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

Comment 27

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/7a9688606fec

Comment 29

[Mike Hommey [:glandium]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/99e3a0501c52

Comment 30

[Mike Hommey [:glandium]]

Backed out the backout.
https://hg.mozilla.org/integration/mozilla-inbound/rev/0be8b1c64893

Comment 31

[Mike Hommey [:glandium]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/6a0ae2398901

Comment 32

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/6a0ae2398901