1842500 - Perma /navigation-timing/prefetch-transfer-size-executor.html | single tracking bug

Status: RESOLVED FIXED

(Core :: DOM: Performance, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2023-07-09T22:15:29.497Z] 22:15:29     INFO - TEST-START | /navigation-timing/prefetch-transfer-size-executor.html
[task 2023-07-09T22:15:29.522Z] 22:15:29     INFO - Closing window f42335a2-99d5-416b-bece-d155591b7e3b
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - 
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - TEST-PASS | /navigation-timing/nav2-test-redirect-chain-xserver-final-original-origin.html | Navigation Timing 2 WPT 
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - TEST-PASS | /navigation-timing/nav2-test-redirect-chain-xserver-partial-opt-in.html | Navigation Timing 2 WPT 
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - TEST-PASS | /navigation-timing/nav2-test-redirect-none.html | Naivation without redirects. 
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - TEST-PASS | /navigation-timing/nav2-test-redirect-server.html | Navigation Timing 2 WPT 
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - TEST-PASS | /navigation-timing/nav2-test-redirect-xserver.html | Navigation Timing 2 WPT 
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - TEST-FAIL | /navigation-timing/nav2-test-response-end-and-duration-before-during-and-after-load-event.html | Check that performance.getEntriesByType('navigation')[0].responseEnd has reasonable values before and after the load has finished - assert_equals: PerformanceNavigationTiming.responseEnd == 0 before load event expected 0 but got 23.88
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - @http://web-platform.test:8000/navigation-timing/nav2-test-response-end-and-duration-before-during-and-after-load-event.html:17:18
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:2599:25
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - Test.prototype.step_func_done/<@http://web-platform.test:8000/resources/testharness.js:2674:32
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - TEST-PASS | /navigation-timing/nav2-test-unique-nav-instances.html | Each window has a unique nav timing 2 instance. 
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - TEST-PASS | /navigation-timing/navigation-type-post-backforward.html | Navigation type after posting and navigating away and back should be back_forward. 
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - TEST-PASS | /navigation-timing/nested-unload-timing.html | Navigation Timing: unload event with nested contexts 
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - TEST-PASS | /navigation-timing/po-navigation.html | navigation entry is observable 
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - TEST-UNEXPECTED-PASS | /navigation-timing/prefetch-transfer-size-executor.html | Navigation timing transfer size for a prefetched navigation should be 0. - expected TIMEOUT
[task 2023-07-09T22:15:31.148Z] 22:15:31     INFO - TEST-INFO | expected TIMEOUT
[task 2023-07-09T22:15:31.222Z] 22:15:31     INFO - TEST-UNEXPECTED-OK | /navigation-timing/prefetch-transfer-size-executor.html | expected TIMEOUT

Comment 1

[Noemi Erli[:noemi_erli]]

There is also this kind of tier2 failure: https://treeherder.mozilla.org/logviewer?job_id=422076857&repo=mozilla-central&lineNumber=3582
Emilio, could you please take a look at this?

Comment 2

[Intermittent Failures Robot]

13 failures in 2956 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 13

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 10
  • debug: 10
• linux1804-32-shippable-qr: 1
  • opt: 1
• android-em-7-0-x86_64-shippable-qr: 1
  • opt: 1
• android-em-7-0-x86_64-shippable-lite-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1842500&startday=2023-07-03&endday=2023-07-09&tree=all

Comment 3

[Emilio Cobos Álvarez (:emilio)]

Attachment: Bug 1842500 - Annotate prefetch-transfer-size-executor.html as passing on android now. r=TYLin,#layout

My theory is that something about how the accessible caret etc was built
before the regressing bug was affecting the load event timing somehow...

But anyways given it's an unexpected pass I didn't debug it too deeply.

Comment 4

[Emilio Cobos Álvarez (:emilio)]

(In reply to Noemi Erli[:noemi_erli] from comment #1)

There is also this kind of tier2 failure: https://treeherder.mozilla.org/logviewer?job_id=422076857&repo=mozilla-central&lineNumber=3582
Emilio, could you please take a look at this?

So comment 0 makes some amount of sense, in so far I changed the setup of an android-only thing in the regressing bug and caused that test to pass. However I'm a bit confused about comment 1. That failure is:

[task 2023-07-09T23:24:25.866Z] 23:24:25     INFO - TEST-START | /navigation-timing/po-navigation.html
[task 2023-07-09T23:24:25.888Z] 23:24:25     INFO - Closing window e72fad8d-3190-4bc0-bfdf-dcb766a5b80b
[task 2023-07-09T23:24:25.923Z] 23:24:25     INFO - PID 19236 | JavaScript error: resource:///modules/AsyncTabSwitcher.sys.mjs, line 1187: TypeError: can't access property "spec", tab.linkedBrowser.currentURI is null
[task 2023-07-09T23:24:25.934Z] 23:24:25     INFO - PID 19236 | JavaScript error: chrome://global/content/elements/browser-custom-element.js, line 1168: TypeError: can't access property "_currentURI", this._remoteWebNavigation is undefined
[task 2023-07-09T23:24:25.934Z] 23:24:25     INFO - PID 19236 | JavaScript error: chrome://browser/content/tabbrowser.js, line 1704: TypeError: can't access property "displaySpec", browser.currentURI is null
[task 2023-07-09T23:24:25.947Z] 23:24:25     INFO - PID 19236 | JavaScript error: chrome://extensions/content/parent/ext-tabs-base.js, line 198: TypeError: can't access property "spec", this.browser.currentURI is null
[task 2023-07-09T23:24:25.952Z] 23:24:25     INFO - PID 19236 | JavaScript error: chrome://global/content/elements/browser-custom-element.js, line 1168: TypeError: can't access property "_currentURI", this._remoteWebNavigation is undefined
[task 2023-07-09T23:24:25.952Z] 23:24:25     INFO - PID 19236 | JavaScript error: chrome://browser/content/tabbrowser.js, line 1704: TypeError: can't access property "displaySpec", browser.currentURI is null
[task 2023-07-09T23:24:25.953Z] 23:24:25     INFO - PID 19236 | JavaScript error: chrome://browser/content/tabbrowser.js, line 1704: TypeError: can't access property "displaySpec", browser.currentURI is null
[task 2023-07-09T23:24:25.955Z] 23:24:25     INFO - PID 19236 | JavaScript error: chrome://extensions/content/parent/ext-tabs-base.js, line 198: TypeError: can't access property "spec", this.browser.currentURI is null
[task 2023-07-09T23:24:29.098Z] 23:24:29     INFO - PID 19236 | console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 324))
[task 2023-07-09T23:24:50.865Z] 23:24:50     INFO - Got timeout in harness
[task 2023-07-09T23:24:50.866Z] 23:24:50     INFO - TEST-UNEXPECTED-TIMEOUT | /navigation-timing/po-navigation.html | TestRunner hit external timeout (this may indicate a hang)

The test is timing out, but the test is rather simple, just checks for a PerformanceObserver for a navigation entry. And we create that unconditionally here (and here), so it's unclear how it can possibly be a regression from my changes...

Olli (since you reviewed that PerformanceNavigationTiming stuff), do you have any idea how that could happen, and somehow only on linux32?

The other thing is that somehow that error before the timeout or something ended up triggering this, but I don't see how either... I can try to repro locally but I don't think it's worth spending too much time on it otherwise...

Comment 5

[Emilio Cobos Álvarez (:emilio)]

How sure are we about comment 1 being a regression from bug 1824886?

Comment 6

[Olli Pettay [:smaug][[e-mail]]]

Somehow we run the script too late? Does passing buffered: true to the observe() help?

Comment 7

[Serban Stanca [:SerbanS]]

That kind of failures from comment 1 are related with another bug.

Comment 8

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1824886

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3db83186cb0f
Annotate prefetch-transfer-size-executor.html as passing on android now. r=TYLin

Comment 10

[Intermittent Failures Robot]

16 failures in 647 pushes (0.025 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 12
• try: 4

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 6
  • debug: 6
• android-em-7-0-x86_64-shippable-qr: 5
  • opt: 5
• android-em-7-0-x86_64-shippable-lite-qr: 5
  • opt: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1842500&startday=2023-07-11&endday=2023-07-11&tree=all

Comment 11

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/3db83186cb0f

Comment 12

[Intermittent Failures Robot]

26 failures in 3309 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 20
• try: 6

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 10
  • debug: 10
• android-em-7-0-x86_64-shippable-qr: 8
  • opt: 8
• android-em-7-0-x86_64-shippable-lite-qr: 8
  • opt: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1842500&startday=2023-07-10&endday=2023-07-16&tree=all