Clear History is extremely slow on some devices or profiles

VERIFIED FIXED in Firefox 14

Status

()

defect
VERIFIED FIXED
7 years ago
7 years ago

People

(Reporter: aaronmt, Assigned: mbrubeck)

Tracking

({perf})

Trunk
Firefox 15
ARM
Android
Points:
---

Firefox Tracking Flags

(firefox14 fixed, firefox15 verified, firefox16 verified, blocking-fennec1.0 +)

Details

Attachments

(3 attachments, 2 obsolete attachments)

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)
Doesn't happen after I nuked my profile.
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → WORKSFORME
I can still reproduce this.
Assignee: nobody → mbrubeck
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
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]
Status: REOPENED → ASSIGNED
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...
Attachment #616661 - Flags: review?(mark.finkle)
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.
Status: ASSIGNED → RESOLVED
Closed: 7 years ago7 years ago
Resolution: --- → WORKSFORME
Attachment #616661 - Attachment is obsolete: true
Attachment #616661 - Flags: review?(mark.finkle)
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.
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
This patch avoids passing "null" to getPreferences, which fixes the error messages from comment 0 (but does not fix the buggy behavior).
Attachment #616685 - Flags: review?(bnicholson)
Status: REOPENED → ASSIGNED
(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
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.
Attachment #616685 - Flags: review?(bnicholson) → review+
Can't reproduce initial reported issue again. No idea what's up here.
blocking-fennec1.0: ? → -
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.
blocking-fennec1.0: - → ?
Summary: Clear History broken - Error reading pref [null]: [Exception... "Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIPrefBranch.getPrefType]" → Clear History is extremely slow on some devices or profiles
(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.
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
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?
(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.
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.
blocking-fennec1.0: ? → soft
blocking-fennec1.0: soft → +
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.
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.
Whiteboard: [leave open]
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
Posted patch patch (obsolete) — Splinter Review
This avoids calling updateHistory (which loops through each item) and instead just updates the db directly with a single SQLite call.
Attachment #618687 - Flags: review?(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.
Attachment #618687 - Flags: review?(bnicholson) → review-
Posted patch part 2 v2Splinter Review
Addresses review feedback.

We could use similar optimizations in other places, like cleanupSomeDeletedRecords.  I'll do that in a follow-up bug.
Attachment #618687 - Attachment is obsolete: true
Attachment #618742 - Flags: review?(bnicholson)
Attachment #618742 - Flags: review?(bnicholson) → review+
Part 2 landed.  This can be resolved now.
https://hg.mozilla.org/integration/mozilla-inbound/rev/0bf543de76db
Whiteboard: [leave open]
Target Milestone: --- → Firefox 15
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.
Attachment #618742 - Flags: approval-mozilla-aurora?
(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
Status: ASSIGNED → RESOLVED
Closed: 7 years ago7 years ago
Resolution: --- → FIXED
Comment on attachment 618742 [details] [diff] [review]
part 2 v2

Mobile only.
Attachment #618742 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
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.
Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.