1467537 - Long beach ball hang when opening History menu caused by slow SQL: DELETE FROM moz_updateoriginsinsert_temp

Status: RESOLVED FIXED

(Toolkit :: Places, defect, P1)

Description

[Chris Peterson [:cpeterson]]

Firefox Nightly on macOS has been frequently hanging for me since mid-May, particularly when my MacBook Pro wakes from hibernation. With today's Nightly build (2018-06-05), however, the hangs are much worse.

STR seems to be to enable one or more extensions and then open Firefox's History menu. I tried bisecting the hangs with mozregression, which pointed to autofill bug 1239708.

Here are some slow SQL queries logged after I reproduced the (~70 second) beach ball hang.

Slow SQL Statements on Main Thread Hits 	Avg. Time (ms) 	Statement

1 	75231 	SELECT h.id, h.url, h.title AS page_title, h.rev_host, h.visit_count, h.last_visit_date, null, null, null, null, null, null AS tags , h.frecency, h.hidden, h.guid, null, null, null FROM moz_places h WHERE h.hidden = 0 AND EXISTS (SELECT id FROM moz_historyvisits WHERE place_id = h.id AND visit_type NOT IN (0,4,8) LIMIT 1) ORDER BY last_visit_date DESC LIMIT 15 /* places.sqlite */

Slow SQL Statements on Helper Threads Hits 	Avg. Time (ms) 	Statement

2 	39383 	DELETE FROM moz_updateoriginsinsert_temp /* places.sqlite */ 

I can usually reproduce the hang after enabling one or both of the following simple extensions (and the opening the History menu). Enabling almost any extension will do, but these are two trivial extensions that consistently reproduced the problem for me.

https://addons.mozilla.org/en-US/firefox/addon/always-right/
https://addons.mozilla.org/en-US/firefox/addon/in-page-pop-up-reporter/


In bug 1462046 comment 26, Marco asks:

(In reply to Marco Bonardo [::mak] from comment #26)
> the second statement took an unexpected long time to
> run (40s) and due to legacy architectural problem we didn't solve yet (UI
> queries are on the main-thread yet), the main-thread tries to run a query in
> the meanwhile, and locks on the connection mutex.

> Honestly I don't think the add-ons have any relation with this, or at least
> I can't see one.

I agree that the particular add-ons don't seem related, but but the hangs really do seem to happen only when add-ons are enabled. Perhaps it is just coincidental timing or maybe enabling an add-on causes some Sync activity the contends with populating the History menu?

I can only repro this hang on my MacBook Pro. My Windows 10 laptop syncs with the same Firefox account, but doesn't hang.

> Is the disk particularly busy and loud (if mechanical) before these lock-ups
> happen?

N/A because I have a MacBook Pro with an SSD.

> Did you enable the new Sync mirroring?

I have Sync enabled, but I haven't flipped any experimental Sync prefs.

Comment 1

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

I'll do some investigation and see if we have options to debug/reduce this one.
We surely can't completely resolve it unless we rearchitecture all the views.

Comment 2

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

Could you please also get a log from places database maintenance in about:support?

Comment 3

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

I think I may have found a big inefficiency.

Comment 4

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

Attachment: Bug 1467537 - The delete trigger on moz_updateoriginsinsert_temp is recalculating the whole table every time.

The trigger is missing a WHERE clause, and as such it ends up doing a lot more work than necessary.

Review commit: https://reviewboard.mozilla.org/r/250206/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/250206/

Comment 5

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

Thanks Chris, I can't express how important is this fix.

Comment 6

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

This is not easily testable by QE, thus minusing. Hopefully Chris will be able to check the improvement here.

Comment 7

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

The test failure is trivially due to the fact we were not calculating things quickly enough before, the test doesn't expect autofill to happen, but it happens with the patch.
This actually exposed a possible bug in the autocomplete controller I'm looking into.

Comment 8

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

Comment on attachment 8984385 [details]
Bug 1467537 - The delete trigger on moz_updateoriginsinsert_temp is recalculating the whole table every time.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/250206/diff/1-2/

Comment 9

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=d236c1a998f73aa0e0e776ddc2439b92440a124e

Comment 10

[Drew Willcoxon :adw]

Comment on attachment 8984385 [details]
Bug 1467537 - The delete trigger on moz_updateoriginsinsert_temp is recalculating the whole table every time.

https://reviewboard.mozilla.org/r/250206/#review256742

Thanks Marco, really good catch.

Comment 11

[Drew Willcoxon :adw]

Could you please also describe the controller fix, here and/or in the commit message, mostly for posterity?

Comment 12

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

Comment on attachment 8984385 [details]
Bug 1467537 - The delete trigger on moz_updateoriginsinsert_temp is recalculating the whole table every time.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/250206/diff/2-3/

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d30ccb8af2fe
The delete trigger on moz_updateoriginsinsert_temp is recalculating the whole table every time. r=adw

Comment 14

[Bogdan Tara[:bogdan_tara | bogdant]]

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