1816572 - When the system or disk are busy the heuristic provider may easily timeout, causing unexpected searches

Status: VERIFIED FIXED

(Firefox :: Address Bar, defect, P2)

Description

[Steve Fink [:sfink] [:s:]]

I have a bookmark keyword "sf" for searchfox, so my workflow includes lots of Ctrl-L sf <space> searchterm <enter>

Fairly frequently, this ends up doing a search for "sf searchterm" in my default search engine rather than navigating to https://searchfox.org/mozilla-central/search?q=searchterm&path=. It appears to be a timing problem, where the keywords are applied asynchronously, and if <enter> is pressed before the keyword has been processed, the keyword never gets applied.

At least for my usage, it would be better if the final search always waited until the keywords were fully consulted. I wouldn't mind if the suggestions dropdown didn't display the keyword search URL in time, as long as the actual search ends up doing the right thing.

Comment 1

[Marco Bonardo [:mak]]

Steve, is this reproducible in the current Nightly/Beta version too?
Is the system particularly busy when the bug happens?

I wonder if the problem is this timer https://searchfox.org/mozilla-central/rev/6444ed17e9f5e0d4e7dabc13c930d46b529fca15/browser/components/urlbar/UrlbarProvidersManager.sys.mjs#624, for the heuristic provider it may be worth awaiting a bit more before notifying the result, otherwise we risk to return a search result, then timeout while waiting for the keyword result. Though if we make this too large, we risk to receive the heuristic after other results.

Could you please set browser.urlbar.loglevel to "All" and then when you reproduce the bug see if in the Browser Console there's any "SkippableTimer :: Heuristic provider timer - Timed out!" messages?

Comment 2

[Steve Fink [:sfink] [:s:]]

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

Steve, is this reproducible in the current Nightly/Beta version too?

I am running Nightly and have been observing it for some time, but I'm fairly out of date so I will update to check the current Nightly.

Is the system particularly busy when the bug happens?

It shouldn't be, since all of my heavy processing is on a remote vscode server. But I'm always surprised at how much CPU my laptop burns.

I have atop running, which logs many things including CPU utilization, so next time it happens I can go back in time and see how busy it was.

I wonder if the problem is this timer https://searchfox.org/mozilla-central/rev/6444ed17e9f5e0d4e7dabc13c930d46b529fca15/browser/components/urlbar/UrlbarProvidersManager.sys.mjs#624, for the heuristic provider it may be worth awaiting a bit more before notifying the result, otherwise we risk to return a search result, then timeout while waiting for the keyword result. Though if we make this too large, we risk to receive the heuristic after other results.

Yeah, I was guessing that this was going to be an annoying time-dependent thing that requires just the right magic value. :-(

Could you please set browser.urlbar.loglevel to "All" and then when you reproduce the bug see if in the Browser Console there's any "SkippableTimer :: Heuristic provider timer - Timed out!" messages?

Done, I'll let you know. Not clearing needinfo.

Comment 3

[Steve Fink [:sfink] [:s:]]

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

Is the system particularly busy when the bug happens?

Not the overall system, but there is a Firefox process burning about 50% of the CPU for some reason.

I wonder if the problem is this timer https://searchfox.org/mozilla-central/rev/6444ed17e9f5e0d4e7dabc13c930d46b529fca15/browser/components/urlbar/UrlbarProvidersManager.sys.mjs#624, for the heuristic provider it may be worth awaiting a bit more before notifying the result, otherwise we risk to return a search result, then timeout while waiting for the keyword result. Though if we make this too large, we risk to receive the heuristic after other results.

Could you please set browser.urlbar.loglevel to "All" and then when you reproduce the bug see if in the Browser Console there's any "SkippableTimer :: Heuristic provider timer - Timed out!" messages?

Yes. Filtering on "Skippable", I get the log below. I'll note that there is also a Provider.BookmarkKeywords timer that is started and immediately canceled at the very end.

09:18:38.739 1677172718739	urlbar	DEBUG	Provider.HeuristicFallback :: SkippableTimer :: Heuristic provider timer :: Started
09:18:38.739 1677172718739	urlbar	DEBUG	Provider.InputHistory :: SkippableTimer :: Query provider timer :: Started
09:18:38.986 1677172718986	urlbar	DEBUG	Provider.HeuristicFallback :: SkippableTimer :: Heuristic provider timer :: Timed out!
09:18:39.010 1677172719010	urlbar	DEBUG	Provider.InputHistory :: SkippableTimer :: Query provider timer :: Timed out!
09:18:39.015 1677172719015	urlbar	DEBUG	Provider.RemoteTabs :: SkippableTimer :: Query chunk timer :: Started
09:18:39.100 1677172719100	urlbar	DEBUG	Provider.RemoteTabs :: SkippableTimer :: Query chunk timer :: Canceling
09:18:39.103 1677172719103	urlbar	DEBUG	Provider.HeuristicFallback :: SkippableTimer :: Heuristic provider timer :: Started
09:18:39.103 1677172719103	urlbar	DEBUG	Provider.InputHistory :: SkippableTimer :: Query provider timer :: Started
09:18:39.181 1677172719181	urlbar	DEBUG	Provider.HeuristicFallback :: SkippableTimer :: Heuristic provider timer :: Canceling
09:18:39.181 1677172719181	urlbar	DEBUG	Provider.InputHistory :: SkippableTimer :: Query provider timer :: Skipped
09:18:39.184 1677172719184	urlbar	DEBUG	Provider.HeuristicFallback :: SkippableTimer :: Heuristic provider timer :: Started
09:18:39.184 1677172719184	urlbar	DEBUG	Provider.InputHistory :: SkippableTimer :: Query provider timer :: Started
09:18:39.262 1677172719262	urlbar	DEBUG	Provider.HeuristicFallback :: SkippableTimer :: Heuristic provider timer :: Canceling
09:18:39.262 1677172719262	urlbar	DEBUG	Provider.InputHistory :: SkippableTimer :: Query provider timer :: Skipped
09:18:39.265 1677172719265	urlbar	DEBUG	Provider.HeuristicFallback :: SkippableTimer :: Heuristic provider timer :: Started
09:18:39.266 1677172719266	urlbar	DEBUG	Provider.InputHistory :: SkippableTimer :: Query provider timer :: Started
09:18:39.463 1677172719463	urlbar	DEBUG	Provider.HeuristicFallback :: SkippableTimer :: Heuristic provider timer :: Canceling
09:18:39.463 1677172719463	urlbar	DEBUG	Provider.InputHistory :: SkippableTimer :: Query provider timer :: Skipped
09:18:39.466 1677172719466	urlbar	DEBUG	Provider.HeuristicFallback :: SkippableTimer :: Heuristic provider timer :: Started
09:18:39.466 1677172719466	urlbar	DEBUG	Provider.InputHistory :: SkippableTimer :: Query provider timer :: Started
09:18:39.669 1677172719669	urlbar	DEBUG	Provider.HeuristicFallback :: SkippableTimer :: Heuristic provider timer :: Timed out!
09:18:39.686 1677172719686	urlbar	DEBUG	Provider.InputHistory :: SkippableTimer :: Query provider timer :: Timed out!
09:18:39.694 1677172719694	urlbar	DEBUG	Provider.BookmarkKeywords :: SkippableTimer :: Heuristic provider timer :: Started
09:18:39.696 1677172719696	urlbar	DEBUG	Provider.BookmarkKeywords :: SkippableTimer :: Heuristic provider timer :: Canceling

Comment 4

[Marco Bonardo [:mak]]

Thanks, feel free to disable logging now, since it may impact performance.

I can confirm from the log that this problem is due to the heuristic provider taking too long to answer.
We could either try increasing _chunkResultsDelayMs, or change the logic to only increase the heuristic timeout, but ensure heuristics are done before proceeding with other results. Basically make _chunkTimer not notify if _heuristicProviderTimer is still pending.

It's also worth adding telemetry to check how often the heuristic timeout happens, that will allow us to pick a better value for the timer.

Comment 5

[Marco Bonardo [:mak]]

Attachment: Bug 1816572 - Allow more time for Address Bar heuristic results to be returned. r=adw

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/986f4f6398a4
Allow more time for Address Bar heuristic results to be returned. r=adw

Comment 7

[Atila Butkovits]

Backed out for causing failures at browser_search_bookmarks.js.

Backout link: https://hg.mozilla.org/integration/autoland/rev/b0b0ee92f2fe4e1b0fc78257f418d65078c80ba8

Push with failures: https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&revision=986f4f6398a43588b608413049dc185edb0d113f&selectedTaskRun=OQQ4XU_CT5i1-ZDH2ifzbQ.0

Failure log: https://treeherder.mozilla.org/logviewer?job_id=421429335&repo=autoland&lineNumber=3003

Comment 8

[Marco Bonardo [:mak]]

(In reply to Atila Butkovits from comment #7)

Backed out for causing failures at browser_search_bookmarks.js.

Is not that a frequent failure (bug 1840880)? Was it permanent after the landing?

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b965c70527de
Allow more time for Address Bar heuristic results to be returned. r=adw

Comment 10

[Iulian Moraru]

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

Comment 12

[Ardelean Oana, Desktop Test Engineering [:oardelean]]

Reproducible on a 2023-07-02 Nightly build on Ubuntu 22.
Verified as fixed on Firefox 117.0b4(build ID: 20230807001816) and Nightly 118.0a1(build ID: 20230805212033) on Ubuntu 22, Windows 10, macOS 12.