747067 - Clear History is extremely slow on some devices or profiles

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Aaron Train [:aaronmt]]

E/GeckoConsole( 5146): Error reading pref [null]: [Exception... "Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIPrefBranch.getPrefType]"  nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)"  location: "JS frame :: chrome://browser/content/browser.js :: getPreferences :: line 756"  data: no]

Steps to Reproduce

i) Visit a variety of sites, check 'History Tab' to note number of entries 
iii) 'Clear History', check 'History Tab'

ER: Zero entries
AR: Multiple entries

--
Samsung Galaxy SII (Android 2.3.4)
Nightly (04/19)

Comment 1

[Aaron Train [:aaronmt]]

Doesn't happen after I nuked my profile.

Comment 2

[Matt Brubeck (:mbrubeck)]

I can still reproduce this.

Comment 3

[Matt Brubeck (:mbrubeck)]

In addition to "Error reading pref" (which I think might be harmless), I get this error when trying to instantiate the global-history service (nsIBrowserHistory):

E/GeckoConsole( 7288): Error sanitizing history: [Exception... "Component returned failure code: 0x80570016 (NS_ERROR_XPC_GS_RETURNED_FAILURE) [nsIJSCID.getService]"  nsresult: "0x80570016 (NS_ERROR_XPC_GS_RETURNED_FAILURE)"  location: "JS frame :: chrome://browser/content/sanitize.js :: <TOP_LEVEL> :: line 185"  data: no]

Comment 4

[Matt Brubeck (:mbrubeck)]

Attachment: part 1: Remove broken nsIBrowserHistory code

nsNavHistory::Init is returning an error, because it can't initialize the places database, because MOZ_ANDROID_HISTORY disables it.  Since we don't use the the history service in Fennec, we can just remove this code.  (Alternately, we could wrap it in a try/catch block in case so it will run if we ever re-enable Places in a future version.)

This fixes the error message from comment 3, but unfortunately does not fix the bug.  There must be an additional bug somewhere...

Comment 5

[Matt Brubeck (:mbrubeck)]

Oops, actually I was following the wrong steps and fixed a different bug.  The error in comment 3 which is fixed by comment 4 is seen when using the "Clear Private Data" button, not the "Clear History" button.

I can't reproduce the original problem as described in comment 0.  (I assume it's intentional that "Clear Private Data" no longer clears history, since we now have a separate menu item for that.)  I'll move my patch to a different bug to avoid confusion.

Comment 6

[Aaron Train [:aaronmt]]

So, now this got me curious. I can reproduce again *if you Clear Private Data first!*.

Use the STR in comment #0 but prior to clearing history, clear private data first.

Comment 7

[Matt Brubeck (:mbrubeck)]

Attachment: part 1: Silence log errors

This patch avoids passing "null" to getPreferences, which fixes the error messages from comment 0 (but does not fix the buggy behavior).

Comment 8

[Matt Brubeck (:mbrubeck)]

(In reply to Aaron Train [:aaronmt] from comment #6)
> So, now this got me curious. I can reproduce again *if you Clear Private
> Data first!*.
> 
> Use the STR in comment #0 but prior to clearing history, clear private data
> first.

I still haven't managed to reproduce this bug

Comment 9

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

I thought it was broken as well.  I had set the device down and then when I picked it up, I found that the history content did delete after a time.  I think the bug is that the deletion is slow.

Comment 10

[Aaron Train [:aaronmt]]

Can't reproduce initial reported issue again. No idea what's up here.

Comment 11

[Brian Nicholson (:bnicholson)]

I'm having this problem too. Looks like Naoki is right...we're slow. REALLY slow:

04-20 12:46:37.763  5904  5912 D BRN     : Deleting history entry for URI: content://org.mozilla.fennec_brian.db.browser/history?profile=default
04-20 12:47:35.091  5904  5912 D BRN     : done with deletion

It took a full minute to delete my 2 history entries. My profile isn't particularly huge, either. It's reproducible on my profile every time I try to clear the history.

Comment 12

[Brian Nicholson (:bnicholson)]

(In reply to Brian Nicholson (:bnicholson) from comment #11)
> It took a full minute to delete my 2 history entries. My profile isn't
> particularly huge, either. It's reproducible on my profile every time I try
> to clear the history.

Note that while I only had 2 visible history entries, my history table has a total of 1423 (empty) entries that have all been marked as deleted, but not yet cleaned up.

Comment 13

[Aaron Train [:aaronmt]]

So I've been testing with a couple entries, but prior I had a couple hundred entries when I saw this guess I was seeing the entries before deletion

Comment 14

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

An IRC guest had come online two nights ago and mentioned that there was a deleted column where some of the URLS were marked for deletion but not deleted.  He mentioned that these records were bogging down the history.  I believe that Comment 12 proves this point.

Should I file a separate bug for db cleanup to flush the database of deleted records?

Comment 15

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

(In reply to Brian Nicholson (:bnicholson) from comment #11)
> I'm having this problem too. Looks like Naoki is right...we're slow. REALLY
> slow:
> 
> 04-20 12:46:37.763  5904  5912 D BRN     : Deleting history entry for URI:
> content://org.mozilla.fennec_brian.db.browser/history?profile=default
> 04-20 12:47:35.091  5904  5912 D BRN     : done with deletion
> 
> It took a full minute to delete my 2 history entries. My profile isn't
> particularly huge, either. It's reproducible on my profile every time I try
> to clear the history.

Brian - Can you add more details about this slowdown? You mentioned that "deleteHistory" ends up looping over a cursor and updating the history row by row instead of using a single query.

Comment 16

[Brian Nicholson (:bnicholson)]

Through logging, I found that it was looping through each individual entry here: http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/db/BrowserProvider.java.in#1933

imageValues was null each time, meaning the loop didn't go any farther than this: http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/db/BrowserProvider.java.in#1949

The phone I'm using is a Droid RAZR - a relatively high-end phone.

Comment 17

[Brian Nicholson (:bnicholson)]

Attachment: test case patch

Here's a simple patch that should allow you to reproduce this on any profile. With the patch applied, open Fennec, click the menu button, and select "Add dummy DB entries". After a minute or so, 1,000 dummy entries will be added to the history table.

Comment 18

[Matt Brubeck (:mbrubeck)]

Landed part 1 to get it out of my queue:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d7ff6b36438e

Please leave this bug open after merging this changeset.

Comment 19

[Matt Brubeck (:mbrubeck)]

Using the test patch here, clearHistory takes about 3 seconds on my G2.  Still need to profile to figure out where the time is going...

04-25 17:30:59.823 I/GeckoLocalBrowserDB(22495): clearHistory start
04-25 17:30:59.823 I/GeckoBrowserProvider(22495): delete start
04-25 17:30:59.823 I/GeckoBrowserProvider(22495): cleanupSomeDeletedRecords start
04-25 17:30:59.883 I/GeckoBrowserProvider(22495): cleanupSomeDeletedRecords end, count = 0
04-25 17:31:02.695 I/GeckoBrowserProvider(22495): cleanupSomeDeletedRecords start
04-25 17:31:02.705 I/GeckoBrowserProvider(22495): cleanupSomeDeletedRecords end, count = 0
04-25 17:31:02.745 I/GeckoBrowserProvider(22495): delete end
04-25 17:31:02.745 I/GeckoLocalBrowserDB(22495): clearHistory end

Comment 20

[Matt Brubeck (:mbrubeck)]

Attachment: patch

This avoids calling updateHistory (which loops through each item) and instead just updates the db directly with a single SQLite call.

Comment 21

[Ed Morley [:emorley]]

(In reply to Matt Brubeck (:mbrubeck) from comment #18)
> Landed part 1 to get it out of my queue:
> https://hg.mozilla.org/integration/mozilla-inbound/rev/d7ff6b36438e

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

Comment 22

[Brian Nicholson (:bnicholson)]

Comment on attachment 618687 [details] [diff] [review]
patch

This doesn't update DATE_MODIFIED, which could break sync or cleanup. You can probably just copy that line from updateHistory() and add it with the other values.put() calls.

Comment 23

[Matt Brubeck (:mbrubeck)]

Attachment: part 2 v2

Addresses review feedback.

We could use similar optimizations in other places, like cleanupSomeDeletedRecords.  I'll do that in a follow-up bug.

Comment 24

[Matt Brubeck (:mbrubeck)]

Part 2 landed.  This can be resolved now.
https://hg.mozilla.org/integration/mozilla-inbound/rev/0bf543de76db

Comment 25

[Matt Brubeck (:mbrubeck)]

Comment on attachment 618742 [details] [diff] [review]
part 2 v2

[Approval Request Comment]
User impact if declined: "Clear History" command in Fennec is so slow it appears not to work at all.

Risk to taking this patch (and alternatives if risky): Very low-risk two-line mobile-only patch.  Fennec 1.0 blocker.

String changes made by this patch: None.

Comment 26

[Ed Morley [:emorley]]

(In reply to Matt Brubeck (:mbrubeck) from comment #24)
> Part 2 landed.  This can be resolved now.
> https://hg.mozilla.org/integration/mozilla-inbound/rev/0bf543de76db

https://hg.mozilla.org/mozilla-central/rev/0bf543de76db

Comment 27

[JP Rosevear [:jpr]]

Comment on attachment 618742 [details] [diff] [review]
part 2 v2

Mobile only.

Comment 28

[Matt Brubeck (:mbrubeck)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/f5cc74ac3ee6

Comment 29

[Paul Feher]

Verified/Fixed on:
Nightly Fennec 16.0a1 (2012-06-13)
Aurora Fennec 15.0a2 (2012-06-13)
Device: HTC Desire Z
OS: Android 2.3.3

The history section is properly cleared, there are no delays after selecting clear history option.