725914 - Takes longer than 40 seconds for awesomescreen results to show up on first load

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Joe Drew (not getting mail)]

Using Aurora 12.0a2 2012-02-09, it takes more than 40 seconds for any results to show up in my awesomescreen after I load it.

To be clear, this is just me starting up Fennec, then clicking on the location bar. The location displays about:home and the results screen was blank for 42 seconds on my last attempt.

I am using sync with my main profile.

Comment 1

[Johnathan Nightingale [:johnath]]

I think this is a dupe, but I know who will know...

Comment 2

[Richard Newman [:rnewman]]

Joe: how many bookmarks do you have?

It sounds like Fennec could use an ANALYZE and some indices, unless we're talking 40,000 bookmarks here.

Comment 3

[Joe Drew (not getting mail)]

I don't have many bookmarks. I haven't done an exact count, but it's probably around 100-200.

Comment 4

[Richard Newman [:rnewman]]

Curious. Got a log?

(Instructions here: http://160.twinql.com/how-to-file-a-good-android-sync-bug )

Comment 5

[Joe Drew (not getting mail)]

Attachment: logcat -v time

Comment 6

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

02-10 16:08:24.890 I/GeckoAwesomeBarTabs(17594): Got cursor in 37925ms

Comment 7

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

Do we have options for getting Joe's Aurora DB ?

Comment 8

[Joe Drew (not getting mail)]

Tell me what to pull and I'll pull it and send it to you privately.

Comment 9

[Kevin Brosnan [Ex-Mozilla]]

Home button > menu button > settings > applications > Manage applications > find/select Aurora > Move to SD card > launch Aurora > Mount the phone as a USB storage device > /sdcard/android/data/org.mozilla.fennec_aurora/files/mozilla/$PROFILE_Name

Comment 10

[Joe Drew (not getting mail)]

Strangely, I had two profiles in there, but the profiles.ini made it clear which was the active one.

To whom should I send my profile?

Comment 11

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

the browser.db has ~13K records. Querying the DB using the SQLite that ships with Firefox desktop takes ~300ms.

Joe - what device and Android version?

Comment 12

[Joe Drew (not getting mail)]

Nexus S, 2.3.6 stock.

Comment 13

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

I did a little testing with Joe's DB (~8MB) and my DB (~2MB) on desktop Firefox, using the SQLite Manager add-on. To fetch the awesomebar list, we use a query like this:

SELECT title, url, favicon FROM history_with_images WHERE url LIKE '%' OR title LIKE '%' ORDER BY visits * MAX(1, (date - 1326862480802) / 86400000 + 120) DESC

where history_with_images is a VIEW created between the history and images table using a LEFT OUTER JOIN. This JOIN seems to be one of the causes of the slowdown. The query ends up doing a table scan on the history and the images tables.

All times are on desktop, but I am using them to be representative. Times for using the above query:

Joe's DB: 430ms (~13K records in history)
Mark's DB: 26ms (~120 records in history)

If I switch to use a simpler subquery, like this:

SELECT url,title, (SELECT favicon FROM images I where H.url = I.url_key) as favicon  FROM history H WHERE url LIKE '%' OR title LIKE '%' ORDER BY visits * MAX(1, (date - 1326862480802) / 86400000 + 120) DESC

Joe's DB: 186ms (~13K records in history)
Mark's DB: 17ms (~120 records in history)

Comment 14

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

More...

Adding a LIMIT clause, which we seem to be doing in the code, also reduces the query times:

Using the existing VIEW based query
Without LIMIT:
Joe's DB: 430ms (~13K records in history)

With LIMIT 100:
Joe's DB: 257ms (~13K records in history)

Using the faster, subquery:
Without LIMIT:
Joe's DB: 186ms (~13K records in history)

With LIMIT 100:
Joe's DB: 42ms (~13K records in history)

Comment 15

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

Attachment: crazy test patch

I put a quick patch together, trying to see if I could get a bif speed improvement. I added a query URI for the subquery SQL statement.

I tested it using my own DB, since I could not get Joe's DB to work with my device. On device, my own DB was taking 1.7 seconds to get the cursor. With the patch, I dropped that to 1.4 seconds. A 17% improvement, but still way too long.

Comment 16

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

I tried something different. I need a sqlite query in JS. This means I was using the sqlite engine that comes with Gecko and not the Android sqlite. Here is the code I ran in browser.js, in the startup function:

    Components.utils.import("resource://gre/modules/Services.jsm");  
    Components.utils.import("resource://gre/modules/FileUtils.jsm");  
      
    let file = FileUtils.getFile("ProfD", ["browser.db"]);  
    let dbConn = Services.storage.openDatabase(file);

    let start = Date.now();    
    let statement = dbConn.createStatement("SELECT title, url, favicon FROM history_with_images WHERE url GLOB '*' OR title GLOB '*' ORDER BY visits * MAX(1, (date - 1326862480802) / 86400000 + 120) DESC LIMIT 100");  
    try {  
      // cause the query to execute
      statement.step();
    }  
    finally {  
      statement.reset();  
    }
    let end = Date.now();
    dump("*********** time for query:" + (end - start));

This query took 433ms to execute compared to ~1700ms in Java. Just something else to look into I guess.

Comment 17

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

tl;dr

The version of sqlite dramatically affects the performance of the LEFT OUTER JOIN query. We can try to use the version of sqlite that ships with gecko for everything, including Java based queries. We can also look for ways to avoid the LEFT OUTER JOIN. Or we can do both.

More data. I have two Galaxy S phones. One with sqlite 3.7.2 (Device A) and one with sqlite 3.6.22 (device B). For some idea as to what sqlite is on what android device, see:
http://stackoverflow.com/a/4377116

Using the command line sqlite3 console app, via adb shell, to run the current SQL select on Joe's DB I have numbers:

Device A: 4 secs
Device B: 22 secs

I could also install Aurora on these phones and use Joe's DB as the app data. I was able to run Aurora just like Joe! Here are the numbers for the awesomebar query:

Device A: 4 secs
Device B: 47 secs

My conclusion: sqlite version plays a big role in performance of some complex JOINs. Running the simple SQL query to only show data from the history table - no join - was nearly instant on both phones. I could not time a difference. Note that 4 secs is not really acceptable either, but it is 10 times faster.

My recommendation: Start work on using the Gecko sqlite for ALL database usage. It's newer than any Android version and it's constant. This is a long term project though and not likely to be ready for initial release.

We should also stop using outer joins in all situations where we can fallback to other strategies. In the case of the awesomebar, we should delay load and cache the favicons as rows are created.

The latter project should be the focus of this bug.

Comment 18

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

More data:

Gian-Carlo asked about the sub select in the current history_with_images VIEW. We added it to handle some potential conflicting column names between the two tables. We removed the sub-select to see what affect it had on performance.

It had a big affect. I modified the VIEW in the DB and tested via the sqlite3 commandline and via Aurora itself using Device B (the slow one):

via sqlite3: ~1 sec
via aurora: 1770ms the first access, 865ms the second

This change is now the best fix we can make. Lucas is looking into a DB migration patch for both VIEWs.

Comment 19

[Lucas Rocha (:lucasr)]

Attachment: Remove sub-select from the table join for bookmark and history

Comment 20

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

Comment on attachment 599075 [details] [diff] [review]
Remove sub-select from the table join for bookmark and history

You already have some performance tests underway. Those will be helpful to catch issues like this in the future.

Comment 22

[Lucas Rocha (:lucasr)]

Pushed: http://hg.mozilla.org/integration/mozilla-inbound/rev/23fef78981b5

Comment 23

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/23fef78981b5

Comment 24

[Joe Drew (not getting mail)]

Is this going to be ported to aurora?

Comment 25

[Doug Turner (:dougt)]

no.  we no longer care about ff12.  this may change, but everyone is focused only on m-c.

Comment 26

[Cristian Nicolae (:xti)]

Verified fixed on:

Firefox 13.0a1 (2012-03-05)
20120305031045
http://hg.mozilla.org/mozilla-central/rev/433cfbd2a0da

--
Device: HTC Desire
OS: Android 2.2

Comment 27

[Adrian Tamas (:AdrianT)]

Behavior covered in the test case:

https://moztrap.mozilla.org/manage/cases/_detail/6313/

The test was added in the BFTs run in the Awesomescreen and Awesomescreen[Tablet] test suites