Closed Bug 1069865 Opened 10 years ago Closed 10 years ago

Unified autocomplete performance issues

Categories

(Toolkit :: Places, defect)

Product:
Toolkit
Component:
Places
Platform:
x86_64
Windows 8.1
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: johnp, Unassigned)

References

Details

(Keywords: perf) 

STR: Type 'moz' in the urlbar and then randomly smash numbers.

Result: The dropdown menu with the old results is kept as long as we're still typing. It also doesn't immediately vanish when we stop typing but stays for ~3 seconds.

Expected Result: Just as with 'browser.urlbar.unifiedcomplete=false' the dropdown should vanish immediately after there's no suggestion possible.

Also note that this issue with the specific 'yet unknown input' may or may not be separate from general performance issues I'm experiencing with unified autocomplete that often result in Google redirects because the Awesomebar isn't fast enough and I just hit 'Enter', just because it previously worked without the unified complete, where the suggestions where coming in faster. I'm still trying out if 'unifiedcomplete=false' fixes all those performance issues occurring on 'in-history' input.
Needinfo? ::mak as per twitter conversation with :Unfocused.
Flags: needinfo?(mak77)
Keywords: perf
are you on the _latest_ (like yesterday's or today's) Nightly? A couple bugs have been fixed recently that could be involved.
Flags: needinfo?(mak77)
Yes, I'm on the latest nightly, but those problems (especially this far from reality STR) have been there for weeks/months. fwiw I have a pretty big history (>80k?), but as it works without unified autocomplete this shouldn't be the problem imho.
ok, sounds like we need to investigate that.
The problem with typing garbage is low priority since it's a not very compelling use-case.

I'd be mostly interested in the other problem, you said "the suggestions where coming in faster", I'd like to understand if you mean the autoFill (inline) suggestions or the suggestions in the popup.
Status: UNCONFIRMED → NEW
Ever confirmed: true
Hard to say, as it's very hard to measure (if I try one, flip the pref, then the next time trying the same string it will be faster (cached; higher frecency or so?)).
Most likely I meant autoFill, because that's the one I would normally use when typing part of an url or domain name and then press 'Enter', where previously the suggestion came fast enough and I was just redirected to the suggestion / wanted url, whereas now I have to wait sometimes up to a second or more before pressing 'Enter'. Which my muscle memory makes me kind of hard to do.
In any way, you're right about that typing garbage being a low prio issue, but I'm not so interested in the immediately clearing once there's no suggestion possible. I find that ~3 second delay after having stopped typing much more disturbing and it looks much more alike (just way exaggerated) to what I'm experiencing on shorter 'in-history' input.
So, a small autoFill slowdown can be explained by the fact now we try to do more and that adds up some work before we can return the result. Should still be largely inside the comfortable area for most users.
Fwiw we plan in future to add some key buffering so that we can handle your keypress after autocomplete got results.

Waiting up to a second or more is not expected though, we should investigate if your profile may have something slowing it down. you should not wait more than a few milliseconds. I cannot reproduce this slowdown.
Is that on any search, or just the first one after you open the browser?

yes, also those 3 seconds are suspect. I can reproduce this and I suspect it's because we wait for the last search to tell us it found nothing before wrapping up the popup. The last search is the broader one and it might take some time. We should check how the code behavior changed compared to the old code.
It happens while browsing, but mostly on typing parts of the url of sites I didn't visit for a couple days / a week or two. It may be more like half a second or so. As mentioned I'll try some browsing with and without unified autocomplete and keep an eye open to have a better estimation. In any way, if it'd only be in the lower millisecond range I wouldn't mention, but it's noticeable and even sometimes leads me to having to wait consciously which wasn't necessary before.

My first thought was that a longer search term shouldn't drastically increase the time to get an result (dunno what for algorithmic complexities there are involved), but probably even decrease. Ignoring that I tried just adding 2-3 numbers after something like 'moz' or 'goo' (even 1 number works), so it's not search string length that play a role here. Something is just slow. At least for empty result search strings, but this slowdown also occurs when doing sth like that with characters, so you may get some results.
This number/character distinction is just for decreasing/increasing the possibility to have a hit.
ahh, forgot half a sentence: "even 1 number works) and it still takes 3 seconds to wrap up the popup,"
Ok, I just found out that the 3 second delay is reproducible for me even with unifiedcomplete=false, although it seems to occur less often. Probably because we have this 'early abort' in that case that also shows up when not wrapping up the popup while still typing.
Note that with results, the delay is most times only in the 1/2-1 second range, but as far as I understand this is so "fast" because we're filling up the dropdown async (am I right?) and results get continuously added. Could be that it's just a big history that's causing those long delays (what should I look for in about:telemtry that shows autocomplete querys?) and that the other things (like probably slower autoFill and no early abort on no-result searches) are separate bugs. It's very hard for me to differentiate them correctly and not doing any false reports.
about:telemetry shows some long and complicated places.sqlite queries that take avg on 815 and 782 msecs.

Hits Avg.Time Statement

107 	815 	SELECT :query_type, h.url, h.title, f.url, EXISTS(SELECT 1 FROM moz_bookmarks WHERE fk = h.id) AS bookmarked, ( SELECT title FROM moz_bookmarks WHERE fk = h.id AND title NOTNULL ORDER BY lastModified DESC LIMIT 1 ) AS btitle, ( SELECT GROUP_CONCAT(t.title, :private) FROM moz_bookmarks b JOIN moz_bookmarks t ON t.id = +b.parent AND t.parent = :parent WHERE b.fk = h.id ) AS tags, h.visit_count, h.typed, h.id, t.open_count, h.frecency FROM moz_places h LEFT JOIN moz_favicons f ON f.id = h.favicon_id LEFT JOIN moz_openpages_temp t ON t.url = h.url WHERE h.frecency <> 0 AND AUTOCOMPLETE_MATCH(:searchString, h.url, IFNULL(btitle, h.title), tags, h.visit_count, h.typed, bookmarked, t.open_count, :matchBehavior, :searchBehavior) ORDER BY h.frecency DESC, h.id DESC LIMIT :maxResults /* places.sqlite */ 

85 	782 	SELECT h.url, h.title, f.url, EXISTS(SELECT 1 FROM moz_bookmarks WHERE fk = h.id) AS bookmarked, ( SELECT title FROM moz_bookmarks WHERE fk = h.id AND title NOTNULL ORDER BY lastModified DESC LIMIT 1 ) AS btitle, ( SELECT GROUP_CONCAT(t.title, :private) FROM moz_bookmarks b JOIN moz_bookmarks t ON t.id = +b.parent AND t.parent = :parent WHERE b.fk = h.id ) AS tags, h.visit_count, h.typed, h.id, :query_type, t.open_count FROM moz_places h LEFT JOIN moz_favicons f ON f.id = h.favicon_id LEFT JOIN moz_openpages_temp t ON t.url = h.url WHERE h.frecency <> 0 AND AUTOCOMPLETE_MATCH(:searchString, h.url, IFNULL(btitle, h.title), tags, h.visit_count, h.typed, bookmarked, t.open_count, ... /* places.sqlite */

some other places.sqlite queries are also in the 100-300ms range, but those two have the highest hit count (just below ~200 COMMIT /* places.sqlite */ taking an avg of 198ms).
I understand these queries are scaling badly on a bigger history?
This may be bug 873796. I should probably try with Win x32.
the queries didn't change from the old autocomplete.
But I did switch from x32 to x64 nightly. Probably the slowness I was talking about (not the 3s delay and the missing early abort, but the muscle memory thing) is caused by that slow sqlite queries as mentioned in bug 873796. I'd be interested if the collected telemtry backs up the single user report from bug 873796, that sqlite queries in x64 are just somehow slower than on x32. Meanwhile I'm trying things out on x32.
fwiw, those slow queries are not the ones populating autoFill, they are used for some results in the popup.
Ok. I'll still try x32 for some days. I'm getting such slow queries on x32 too, so bug 873796 does not seem to be specific to x64. Also comparing the user reports there it's just the query scaling badly with more entries.

Still, the 'early abort / popup wrap up' would be an improvement for unified autocomplete, although I'm not sure if its practical (how does the old autocomplete do that?)... (we do throw away / cancel the old suggestion search, do we? (only skipped through some of the code once))

As the 3s delay is not a unified autocomplete issue and I because can get the slow queries in telemetry by forcing this situation we most likely cannot improve that one. (sqlite is just slow :( )

To evaluate whether or not I can reproduce the slower autoFill issue on x32/non-unified-autocomplete I probably need some days.
it's not sqlite that is slow, it's the fact we don't have an FTS index.
ok, thanks for clearing that up.
So, after switching between enabled and disabled unified a couple days I'm pretty sure any slowness I felt is not reproducible anymore and was probably more related to the popup than to autoFill and merely a result of #c15 and a big history.
Feel free to close this bug and open separate bugs for the two other issues if you think that they should be tackled sometime.
Thanks for reporting back.

I'm not sure we can do anything for the delay before closing the popup, we must wait for the slowest query to return before knowing whether there were results or not, so at a maximum we should work on improving queries or history performance for which we have other bugs not just strictly related to this issue.
Regarding the other slowdown, I cannot reproduce so it's hard to have a bug without a good way to reproduce the problem.

If you think some specific slowdown is breaking your experience in a very bad way, please file a bug on that very specific thing, so we can investigate one thing at a time.
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → WORKSFORME
I don't know if its feasible, but how does just matching the new query string against the (probably outdated and still waiting for update) popup results (which are afaik limited in number by browser.urlbar.maxRichResults) sound to you? Remove those results which do not fit to the new search string in any way dynamically?
I'm not sure off-hand, must be verified on code, but we should compare to urls, titles, tags and in future there might be other matchings. plus searching in very long urls woulnd't be cheap.
I will file a minor bug to investigate whether there's some easy fix to close the popup sooner.
You need to log in before you can comment on or make changes to this bug.