1888594 - Intermittent browser/components/urlbar/tests/quicksuggest/browser/browser_quicksuggest_mdn.js | single tracking bug

Status: RESOLVED FIXED

(Firefox :: Address Bar, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=452745178&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YTjtkYQCTLyyv1yybWW0Bw/runs/0/artifacts/public/logs/live_backing.log

---

[task 2024-03-29T00:06:06.093Z] 00:06:06     INFO - TEST-PASS | browser/components/urlbar/tests/quicksuggest/browser/browser_quicksuggest_mdn.js | true == true - 
[task 2024-03-29T00:06:06.094Z] 00:06:06     INFO - add_tasks_with_rust: Done calling original task function: notRelevant
[task 2024-03-29T00:06:06.094Z] 00:06:06     INFO - add_tasks_with_rust: Clearing rustEnabled
[task 2024-03-29T00:06:06.096Z] 00:06:06     INFO - add_tasks_with_rust: Done clearing rustEnabled
[task 2024-03-29T00:06:06.096Z] 00:06:06     INFO - add_tasks_with_rust: Forcing sync
[task 2024-03-29T00:06:06.097Z] 00:06:06     INFO - QuickSuggestTestUtils.forceSync Started
[task 2024-03-29T00:06:06.098Z] 00:06:06     INFO - QuickSuggestTestUtils.forceSync Syncing Rust backend
[task 2024-03-29T00:06:06.100Z] 00:06:06     INFO - Buffered messages logged at 00:06:02
[task 2024-03-29T00:06:06.100Z] 00:06:06     INFO - QuickSuggestTestUtils.forceSync Done syncing Rust backend
[task 2024-03-29T00:06:06.101Z] 00:06:06     INFO - QuickSuggestTestUtils.forceSync Done
[task 2024-03-29T00:06:06.101Z] 00:06:06     INFO - add_tasks_with_rust: Done forcing sync
[task 2024-03-29T00:06:06.102Z] 00:06:06     INFO - Leaving test bound notRelevant_rustEnabled
[task 2024-03-29T00:06:06.103Z] 00:06:06     INFO - Closing the view directly
[task 2024-03-29T00:06:06.103Z] 00:06:06     INFO - Waiting for the view to close
[task 2024-03-29T00:06:06.104Z] 00:06:06     INFO - Urlbar view closed
[task 2024-03-29T00:06:06.104Z] 00:06:06     INFO - Buffered messages finished
[task 2024-03-29T00:06:06.106Z] 00:06:06     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/quicksuggest/browser/browser_quicksuggest_mdn.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - 
[task 2024-03-29T00:06:06.106Z] 00:06:06     INFO - GECKO(9324) | MEMORY STAT | vsize 2104277MB | vsizeMaxContiguous 64988861MB | residentFast 307MB | heapAllocated 142MB
[task 2024-03-29T00:06:06.107Z] 00:06:06     INFO - TEST-OK | browser/components/urlbar/tests/quicksuggest/browser/browser_quicksuggest_mdn.js | took 78753ms
[task 2024-03-29T00:06:06.108Z] 00:06:06     INFO - checking window state
[task 2024-03-29T00:06:06.108Z] 00:06:06     INFO - TEST-START | browser/components/urlbar/tests/quicksuggest/browser/browser_quicksuggest_merinoSessions.js

Comment 1

[Intermittent Failures Robot]

1 failures in 3590 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows11-64-2009-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1888594&startday=2024-03-25&endday=2024-03-31&tree=all

Comment 2

[Drew Willcoxon :adw]

The logs indicate that the test finishes, it just takes too long. It's strange because this test doesn't do a whole lot.

tl;dr

During this test, a long URL is loaded in the default tab. The URL is longer than the urlbar can show at once. This seems to cause Gecko to create one or more ScrollFrameActivityTracker timers, which remain running at the end of the test. The browser-test harness waits for them to fire before moving on to the next test, and sometimes that can take a while.

How I found this

I noticed that this test often hangs for a few seconds for me locally at the very end. First, I verified that all the test code finishes running, including the code in the test itself, cleanup functions, and all helpers like QuickSuggestTestUtils, the mock RemoteSettingsServer, UrlbarTestUtils, etc. Even with all that ruled out, the test still hung at the end, which led me to suspect something outside the test: the test harness, Gecko, GC, etc.

I commented out most of the test and started uncommenting parts one at a time to see which parts might be triggering the hang. I found that gURLBar.handleRevert() was the problem, here. With that commented out, the hang never happened.

At this point, I had commented out everything after the revert plus the entire notRelevant() task so that when the hang happened, the urlbar was showing the long URL that this test loads.

Once, while the test was hung and showing this long URL, I happened to hit some arrow keys, which moved the caret and scrolled the urlbar. That caused the test to outright fail:

  FAIL waiting for new repeating timers to be cancelled - timed out after 50 tries. - false == true <snip>
  FAIL test left unexpected repeating timer ScrollFrameActivityTracker (duration: 1000ms) - false == true <snip>

These failures come from the browser-test.js harness, and that's how I started to figure out that this ScrollFrameActivityTracker timer was the problem. When a test finishes, before moving on to the next test browser-test waits for all short-lived repeating timers to finish. I added some logging to getNewRepeatingTimers() (names and durations of timers) and found that when the hang happens, it's waiting on a timer named ScrollFrameActivityTracker, which looks like something related to layout or gfx.

Conclusions

Normally the test finishes with "array" in the urlbar, not the long URL, because it calls UrlbarTestUtils.promiseAutocompleteResultPopup() with a value of "array" after loading the URL. But even then, browser-test is stuck waiting for this timer to fire (which I verified through logging). So it might seem that simply loading a long URL at any point during the test is enough to trigger the hang. I don't think so though. This test loads the long URL in the default tab (the one that's always open in browser tests). When I modify it to load the URL in a new tab and then close the tab, the hang doesn't happen. And there are probably lots of other tests that load long URLs and (presumably) don't have similar timeout failures.

So what's special about loading the long URL in the default tab? If that's the last URL that was loaded in the tab (i.e., browser.currentURI), any time the urlbar is reverted the URL will be put back into the urlbar and presumably the ScrollFrameActivityTracker timer(s) will start again. That's not great for the default tab, where most test activity probably happens. In contrast, if the URL is loaded in a new tab and then that tab is closed, the URL is irrelevant for later reverts.

We should avoid loading long URLs in the default tab in browser tests.

Comment 3

[Drew Willcoxon :adw]

Attachment: Bug 1888594 - Fix browser_quicksuggest_mdn.js intermittent timeouts.

To fix this, we should load the long URL in a new tab. I left a big comment in
the bug with details.

The URL is:

https://example.com/array-filter?utm_medium=firefox-desktop&utm_source=firefox-suggest&utm_campaign=firefox-mdn-web-docs-suggestion-experiment&utm_content=treatment

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b16de7cd0bbc
Fix browser_quicksuggest_mdn.js intermittent timeouts. r=daisuke

Comment 5

[Serban Stanca [:SerbanS]]

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