Closed Bug 835515 Opened 12 years ago Closed 3 years ago

Nightly becomes unresponsive when importing months of history from Chrome

Categories

(Firefox :: Migration, defect)

x86_64
Windows 8
defect
Not set
major

Tracking

()

RESOLVED DUPLICATE of bug 1332225
Tracking Status
firefox26 --- affected
firefox27 --- affected
firefox28 --- affected
firefox29 --- affected
firefox44 --- affected
firefox45 --- affected
firefox46 --- affected
firefox47 --- affected
firefox-esr52 --- affected
firefox55 --- affected
firefox56 --- affected
firefox57 --- affected

People

(Reporter: geeknik, Unassigned)

Details

(Keywords: nightly-community, perf)

I'm running the latest build of Nightly and I just imported a couple of months of browsing history from Chrome and the entire browser became unresponsive even after the import dialog showed that the import was finished. Looking at the Windows 8 Resource monitor, Nightly was writing at a rate of 32MB/sec or so (even now, the browser is responsive again, it is still writing about 2MB/sec and the History window is still updating. Is this because importing is done on the main thread? Is this something that can be moved off the main thread?
Component: General → Migration
Product: Core → Firefox
no, import of history is off main-thread, but on each history addition we may update the ui, for example if you do the import with the History view open. The ui is on main-thread so there's no way to do that off main-thread. was that the case? the only other alternative is some add-on observing history and doing something on eacj visit addition. For such a case I suppose we may evaluate some batching support...
In regards to ui updates, I didn't see any UI updates during the importation, and afterwards, the UI updaters were incredibly slow. After I thought the import was completed, Nightly was still thrashing the disk and updating the UI. And to my knowledge, I have no extensions that monitor/observe/touch the history.
I have some additional information from telemetry that may or may not be helpful: Slow SQL Statements on Main Thread Hits Avg. Time (ms) Statement 588 190 SELECT CAST(( strftime(:private,:private,:private,:private) - (SELECT MIN(visit_date)/1000000 FROM moz_historyvisits) ) AS DOUBLE) /86400, strftime(:private,:private,:private,:private,:private,:private) * 1000000 /* places.sqlite */ 886 138 SELECT null, :private||beginTime||:private||endTime, dayTitle, null, null, beginTime, null, null, null, null, null, null, null FROM (SELECT :dayTitle0 AS dayTitle, (strftime(:private,:private,:private,:private,:private)*1000000) AS beginTime, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS endTime WHERE EXISTS ( SELECT id FROM moz_historyvisits WHERE visit_date >= (strftime(:private,:private,:private,:private,:private)*1000000) AND visit_date < (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_type NOT IN (0,4,8) LIMIT 1 ) UNION ALL SELECT :dayTitle1 AS dayTitle, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS beginTime, (strftime(:private,:private,:private,:private,:private)*1000000) AS endTime WHERE EXISTS ( SELECT id FROM moz_historyvisits WHERE visit_date >= (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_date < (strftime(:private,:private,:private,:private,:private)*1000000) AND visit_type NOT IN (0,4,8) LIMIT 1 ) UNION ALL SELECT :dayTitle2 AS dayTitle, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS beginTime, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS endTime WHERE EXISTS ( SELECT id FROM moz_historyvisits WHERE visit_date >= (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_date < (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_type NOT IN (0,4,8) LIMIT 1 ) UNION ALL SELECT :dayTitle3 AS dayTitle, (strftime(:private,:private,:private,:private,:private)*1000000) AS beginTime, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS endTime WHERE EXISTS ( SELECT id FROM moz_historyvisits WHERE visit_date >= (strftime(:private,:private,:private,:private,:private)*1000000) AND visit_date < (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_type NOT IN (0,4,8) LIMIT 1 ) UNION ALL SELECT :dayTitle4 AS dayTitle, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS beginTime, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS endTime WHERE EXISTS ( SELECT id FROM moz_historyvisits WHERE visit_date >= (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_date < (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_type NOT IN (0,4,8) LIMIT 1 ) UNION ALL SELECT :dayTitle5 AS dayTitle, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS beginTime, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS endTime WHERE EXISTS ( SELECT id FROM moz_historyvisits WHERE visit_date >= (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_date < (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_type NOT IN (0,4,8) LIMIT 1 ) UNION ALL SELECT :dayTitle6 AS dayTitle, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS beginTime, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS endTime WHERE EXISTS ( SELECT id FROM moz_historyvisits WHERE visit_date >= (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_date < (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_type NOT IN (0,4,8) LIMIT 1 ) UNION ALL SELECT :dayTitle7 AS dayTitle, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS beginTime, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS endTime WHERE EXISTS ( SELECT id FROM moz_historyvisits WHERE visit_date >= (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_date < (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_type NOT IN (0,4,8) LIMIT 1 ) UNION ALL SELECT :dayTitle8 AS dayTitle, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS beginTime, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS endTime WHERE EXISTS ( SELECT id FROM moz_historyvisits WHERE visit_date >= (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_date < (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_type NOT IN (0,4,8) LIMIT 1 ) UNION ALL SELECT :dayTitle9 AS dayTitle, (datetime(0, :private)*1000000) AS beginTime, (strftime(:private,:private,:private,:private,:private,:private)*1000000) AS endTime WHERE EXISTS ( SELECT id FROM moz_historyvisits WHERE visit_date >= (datetime(0, :private)*1000000) AND visit_date < (strftime(:private,:private,:private,:private,:private,:private)*1000000) AND visit_type NOT IN (0,4,8) LIMIT 1 ) ) /* places.sqlite */ 3 77 SELECT b.id, b.guid, b.parent, b.lastModified, t.guid, t.parent FROM moz_bookmarks b JOIN moz_bookmarks t on t.id = b.parent WHERE b.fk = (SELECT id FROM moz_places WHERE url = :page_url) ORDER BY b.lastModified DESC, b.id DESC /* places.sqlite */ Slow SQL Statements on Helper Threads Hits Avg. Time (ms) Statement 1 523 UPDATE moz_places SET frecency = CALCULATE_FRECENCY(id) WHERE frecency < 0 /* places.sqlite */ 6 452 ANALYZE moz_places /* places.sqlite */ 22 115 SELECT id, title, hidden, typed, guid FROM moz_places WHERE url = :page_url /* places.sqlite */ 24 122 UPDATE moz_places SET frecency = CALCULATE_FRECENCY(:page_id) WHERE id = :page_id /* places.sqlite */ 4 114 INSERT INTO moz_historyvisits (from_visit, place_id, visit_date, visit_type, session) VALUES (:from_visit, :page_id, :visit_date, :visit_type, :session) /* places.sqlite */ 6 113 UPDATE moz_places SET hidden = 0 WHERE id = :page_id AND frecency <> 0 /* places.sqlite */ 6 427 ANALYZE moz_historyvisits /* places.sqlite */ 13 132 COMMIT TRANSACTION /* places.sqlite */ 4 114 SELECT id, session, visit_date FROM moz_historyvisits WHERE place_id = (SELECT id FROM moz_places WHERE url = :page_url) AND visit_date = :visit_date /* places.sqlite */ 40 115 UPDATE moz_places SET title = :title, hidden = :hidden, typed = :typed, guid = :guid WHERE id = :page_id /* places.sqlite */ 1 2524 UPDATE moz_places SET frecency = ROUND(frecency * .975) WHERE frecency > 0 /* places.sqlite */ Even though the browser was hung and unresponsive, there was nothing listed under Browser Hangs, so I guess the browser didn't think it was hung?
which build was this one? I suspect bug 830423 may have helped here, the first 2 queries that are ran so often up there are updating the Library left pane, and I suspect it's what is causing the problem. For each visit that we add the left pane updates, bug 830423 improved that, but would be nice to remeasure that. We should probably also add some additional telemetry probes.
The telemetry data came from the 3/25 Nightly Build.
Ok, so looks like there may still be some space for improvements here, we should probably notify a batch to the view, somehow.
Keywords: perf
This is still a thing with today's Firefox Nightly 47.0a1 build (Built from https://hg.mozilla.org/mozilla-central/rev/5f9ba76eb3b1fd9377bbdb4cc2f98a7e75eabdfb).

Hi Marco!
It seems this bug is still active. Is there any ongoing investigation about this?
Thanks!

Flags: needinfo?(mak)

As far as I know there isn't active investigation at the moment.

I'm surprised that the migration time probes seem to be expired, and not even removed, see https://searchfox.org/mozilla-central/rev/f8576fec48d866c5f988baaf1fa8d2f8cce2a82f/toolkit/components/telemetry/Histograms.json#8049
I thought bugs would have been filed for that, the last bump happened in bug 1678204.

I think we can dupe this to bug 1332225 and I'll file a bug about telemetry being expired.

Status: NEW → RESOLVED
Closed: 3 years ago
Flags: needinfo?(mak)
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.