835515 - Nightly becomes unresponsive when importing months of history from Chrome

Status: RESOLVED DUPLICATE of bug 1332225

(Firefox :: Migration, defect)

Description

[Brian Carpenter [:geeknik]]

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?

Comment 1

[Marco Bonardo [:mak]]

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...

Comment 2

[Brian Carpenter [:geeknik]]

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.

Comment 3

[Brian Carpenter [:geeknik]]

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?

Comment 4

[Marco Bonardo [:mak]]

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.

Comment 5

[Brian Carpenter [:geeknik]]

The telemetry data came from the 3/25 Nightly Build.

Comment 6

[Marco Bonardo [:mak]]

Ok, so looks like there may still be some space for improvements here, we should probably notify a batch to the view, somehow.

Comment 7

[Brian Carpenter [:geeknik]]

This is still a thing with today's Firefox Nightly 47.0a1 build (Built from https://hg.mozilla.org/mozilla-central/rev/5f9ba76eb3b1fd9377bbdb4cc2f98a7e75eabdfb).

Comment 8

[Marcela (Please NI request to Brindusa Tot)]

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

Comment 9

[Marco Bonardo [: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.