Closed Bug 1579334 Opened 5 years ago Closed 5 years ago

Slow appearance of suggestions in address bar

Categories

(Firefox :: Address Bar, defect, P3)

defect
Points:
2

Tracking

()

VERIFIED FIXED
Firefox 72
Iteration:
72.1 - Oct 21 - Nov 3
Tracking Status
firefox71 --- verified
firefox72 --- fixed

People

(Reporter: yoasif, Assigned: adw)

References

Details

(Whiteboard: [fxperf:p3])

Attachments

(2 files)

See profile: https://perfht.ml/2ZTdIb0

STR:

  1. control-l, waited a couple of seconds
  2. type a search query.

What happens:

Suggestions appear, but took about 4 seconds, which is not normal. "Visit" comes up basically immediately, however.

This occurs repeatedly.

Attached file about:support
Component: Performance → Address Bar
Product: Core → Firefox
Whiteboard: [fxperf]

mstange and I looked at the profile, and we're janking the main thread in the parent process for ~4 seconds processing results for a UnifiedComplete query. That's pretty bad.

This seems like it's processing a lot more results than it can reasonably display.

It may be a query string that doesn't find matches, and then we have to linearly scan the whole database because we dont' have a fulltext index.
Though, it should all happen on the async thread in a read only connection, unless something fancy is blocking the db, or the db is corrupt.

Could you please run Places database integrity check from about:support, and post the output log here?
I also wonder what happens if you temporarily disable some of those history/bookmarks add-ons.

Flags: needinfo?(yoasif)
Attachment #9090922 - Attachment description: about:config → about:support
Flags: needinfo?(yoasif)

I can't reproduce this issue on the latest nightly anymore, so that is good news.

Posting the output of places integrity check here:

Task: checkIntegrity

  • The places.sqlite database is sane
  • The favicons.sqlite database is sane

Task: invalidateCaches

  • The caches have been invalidated

Task: checkCoherence

  • The database is coherent

Task: expire

  • Database cleaned up

Task: originFrecencyStats

  • Recalculated origin frecency stats

Task: vacuum

  • Initial database size is 51200KiB
  • The database has been vacuumed
  • Final database size is 46080KiB

Task: stats

  • Places.sqlite size is 46080KiB
  • Favicons.sqlite size is 28992KiB
  • pragma_user_version is 53
  • pragma_page_size is 32768
  • pragma_cache_size is -2048
  • pragma_journal_mode is wal
  • pragma_synchronous is 1
  • History can store a maximum of 139935 unique pages
  • Table moz_origins has 5553 records
  • Table moz_places has 86295 records
  • Table moz_historyvisits has 136054 records
  • Table moz_inputhistory has 328 records
  • Table moz_bookmarks has 4719 records
  • Table moz_bookmarks_deleted has 0 records
  • Table moz_keywords has 4 records
  • Table sqlite_sequence has 1 records
  • Table moz_anno_attributes has 3 records
  • Table moz_annos has 311 records
  • Table moz_items_annos has 0 records
  • Table moz_meta has 8 records
  • Table sqlite_stat1 has 20 records
  • Index sqlite_autoindex_moz_origins_1
  • Index sqlite_autoindex_moz_inputhistory_1
  • Index sqlite_autoindex_moz_bookmarks_deleted_1
  • Index sqlite_autoindex_moz_keywords_1
  • Index sqlite_autoindex_moz_anno_attributes_1
  • Index moz_places_url_hashindex
  • Index moz_places_hostindex
  • Index moz_places_visitcount
  • Index moz_places_frecencyindex
  • Index moz_places_lastvisitdateindex
  • Index moz_places_guid_uniqueindex
  • Index moz_places_originidindex
  • Index moz_historyvisits_placedateindex
  • Index moz_historyvisits_fromindex
  • Index moz_historyvisits_dateindex
  • Index moz_bookmarks_itemindex
  • Index moz_bookmarks_parentindex
  • Index moz_bookmarks_itemlastmodifiedindex
  • Index moz_bookmarks_dateaddedindex
  • Index moz_bookmarks_guid_uniqueindex
  • Index moz_keywords_placepostdata_uniqueindex
  • Index moz_annos_placeattributeindex
  • Index moz_items_annos_itemattributeindex

Task: _refreshUI

Whiteboard: [fxperf] → [fxperf:p3]

The priority flag is not set for this bug.
:adw, could you have a look please?

For more information, please visit auto_nag documentation.

Flags: needinfo?(adw)

Nothing looks out of place in the integrity check. It's a big database but not particularly big. I don't see where the profile indicates that 4s are being spent in UnifiedCompleted-related code or that the main thread is janking. There are a lot of extensions running, so as Marco said, it would be good to test with them disabled.

Flags: needinfo?(adw)
Priority: -- → P5

(In reply to Marco Bonardo [::mak] from comment #3)

It may be a query string that doesn't find matches, and then we have to linearly scan the whole database because we dont' have a fulltext index.
Though, it should all happen on the async thread in a read only connection, unless something fancy is blocking the db, or the db is corrupt.

The profile shows us being blocked on displaying results (eg. 25% is setting img src attributes, which triggers image load requests, ...), not on querying the db.

(In reply to Drew Willcoxon :adw from comment #6)

Nothing looks out of place in the integrity check. It's a big database but not particularly big. I don't see where the profile indicates that 4s are being spent in UnifiedCompleted-related code or that the main thread is janking.

The main thread is blocked on this part of the profile: https://perfht.ml/2MYBrlB

The _addMatch function from UnifiedComplete.jsm seems to be called about 100 times in a row. I think that's what Mike was talking about when he said "This seems like it's processing a lot more results than it can reasonably display." in comment 2.

I assume there's somewhere a limit to the number of results we display in the awesomebar. Could there be a race condition in the code that would make it ignore the limit? Or is there an about:config pref that might have been tweaked accidentally? In the about:support dump in comment 2 I see "browser.urlbar.matchBuckets": "general:5,suggestion:Infinity",, what does this mean?

Flags: needinfo?(adw)

Something else I noticed in the profile: this line https://searchfox.org/mozilla-central/rev/d7537a9cd2974efa45141d974e5fc7c727f1a78f/browser/components/urlbar/UrlbarMuxerUnifiedComplete.jsm#87 makes the JS engine fail to use JITed code, see bug 1590120. I'm not sure how much this affects the actual performance here, but it seems worth working around.

See Also: → 1590120

(In reply to Florian Quèze [:florian] from comment #7)

I assume there's somewhere a limit to the number of results we display in the awesomebar. Could there be a race condition in the code that would make it ignore the limit? Or is there an about:config pref that might have been tweaked accidentally?

I suspect it's just a result of typing, every char may return results, we clear the previous query but it may have already returned results.
We don't fetch more than a small amount of results, it should be 10-20 results per query.

It's worth investigating regardless.

(In reply to Marco Bonardo [::mak] from comment #9)

(In reply to Florian Quèze [:florian] from comment #7)

I assume there's somewhere a limit to the number of results we display in the awesomebar. Could there be a race condition in the code that would make it ignore the limit? Or is there an about:config pref that might have been tweaked accidentally?

I suspect it's just a result of typing, every char may return results,

Looking at the DOMEvent markers in the profile, I see only 3 keypress events in the few seconds before we display results: https://perfht.ml/2MZclTM

That "Infinity" doesn't count, it just says we can fill up any remaining space with suggestions. additionally here suggestions are disabled (browser.urlbar.suggest.searches) so we should even return LESS results. There's surely something fishy ongoing.

Flags: needinfo?(adw)
Priority: P5 → P3

The _addMatch that comes up on the profiler link in comment 7, the one whose running time is 1980ms, is under _matchRemoteTabs.

It looks like we limit search suggestions and SQL row fetches to _maxResults, but there's no limit at all placed on remote tabs? We just call _addMatch on every remote tab returned by PlacesRemoteTabsAutocompleteProvider. Is it as simple as that, am I reading that right?

(In reply to Drew Willcoxon :adw from comment #13)

It looks like we limit search suggestions and SQL row fetches to _maxResults, but there's no limit at all placed on remote tabs? We just call _addMatch on every remote tab returned by PlacesRemoteTabsAutocompleteProvider. Is it as simple as that, am I reading that right?

that's right, the remote tabs query seems unbound, good catch. It should be limited to maxRichResults.

Edit: and likely the provider itself should not lose time fetching things we don't care about, we could change its fetch method to take a maxResults

This should be pretty straightforward to fix, I can take a look.

Assignee: nobody → adw
Status: NEW → ASSIGNED
Iteration: --- → 72.1 - Oct 21 - Nov 3

This is a narrow patch that simply adds a maxMatches param to PlacesRemoteTabsAutocompleteProvider.getMatches. There's other room for improvement around maxResults handling in UnifiedComplete that this does not address.

(In reply to Drew Willcoxon :adw from comment #16)

There's other room for improvement around maxResults handling in UnifiedComplete that this does not address.

Like, we can end up with more results than maxResults specifies, as the test task that I added in the patch shows. It seems like _addMatch should stop the search once maxResults results are added.

(In reply to Drew Willcoxon :adw from comment #17)

It seems like _addMatch should stop the search once maxResults results are added.

I wrote a patch for this, but test_search_suggestions.js fails because the history query ends up finishing before the search suggestions fetch, and the history query returns enough results to meet maxResults, so the search is stopped, but there would have been search suggestions with higher frecency than some of the history results.

IOW we can call _addMatch more than maxResults times, and later calls can add results with higher frecencies than earlier calls, and _addMatch takes care to inserts results in order of frecency. Which is right and proper and obvious in hindsight. So that idea is no good.

(In reply to Drew Willcoxon :adw from comment #17)

Like, we can end up with more results than maxResults specifies, as the test task that I added in the patch shows. It seems like _addMatch should stop the search once maxResults results are added.

Probably not, we want to return a bit more results, so that the Muxer can eventually remove unwanted things, or sort things differently, without causing us to not fill up the required 10 results. When we'll split the provider that will be more common, each provider will likely return maxResults results and the Muxer will decide how to mix them up.

Pushed by dwillcoxon@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/28daae14f90c
Properly limit remote tab matches in the quantumbar. r=mak
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 72

please ask for uplift when possible.

Flags: needinfo?(adw)

Comment on attachment 9103155 [details]
Bug 1579334 - Properly limit remote tab matches in the quantumbar.

Beta/Release Uplift Approval Request

  • User impact if declined: This fixes a performance problem (hang) in the urlbar when the user has many remote tabs.
  • Is this code covered by automated tests?: Yes
  • Has the fix been verified in Nightly?: No
  • Needs manual test from QE?: No
  • If yes, steps to reproduce:
  • List of other uplifts needed: None
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): This is a small patch that's unlikely to affect anything other than the number of remote tabs returned by the urlbar's back-end. Comes with tests.
  • String changes made/needed:
Flags: needinfo?(adw)
Attachment #9103155 - Flags: approval-mozilla-beta?

Comment on attachment 9103155 [details]
Bug 1579334 - Properly limit remote tab matches in the quantumbar.

Perf fix in our primary UI, has tests and we are in early betas, uplift approved for 71 beta 4, thanks.

Attachment #9103155 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Flags: qe-verify+
QA Whiteboard: [qa-triaged]

I’ve tried to reproduce this issue on Ubuntu 18.04 with Fx 71.0a1 (2019-09-05) with the information from comment 1. I can observe only a very slightly delay, but not that much as 4 seconds (also probably influenced by the “heavy” profile).
Asif Youssuff, if time permits, can you confirm this issue is fixed on you side with the latest Beta? Otherwise maybe is safe to remove the qa+ flag, since this is also covered by automated tests.

Flags: needinfo?(yoasif)
Points: --- → 2

It seems fine in the latest beta - nothing like 4 seconds, at any rate.

Flags: needinfo?(yoasif)

(In reply to Asif Youssuff from comment #27)

It seems fine in the latest beta - nothing like 4 seconds, at any rate.

Thank you for your time! Based on comment 27, I will mark this issue as verified fixed and remove the qe+ flag.

Status: RESOLVED → VERIFIED
Flags: qe-verify+
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: