Closed Bug 1791940 Opened 2 years ago Closed 5 months ago

Intermittent browser/base/content/test/performance/browser_preferences_usage.js | single tracking bug

Categories

(Core :: Layout, defect)

Product:
Core
Component:
Layout
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, intermittent-testcase, Whiteboard: [retriggered][stockwell unknown])

Attachments

(2 files, 1 obsolete file)

Bug 1791940 - reduce sandbox pref lower limit in browser_preferences_usage.js to stop intermittents, r?rpl
48 bytes, text/x-phabricator-request
Details | Review
Bug 1791940 - drop sandbox pref 'minimum' usage still further, r?florian
48 bytes, text/x-phabricator-request
Details | Review

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

[task 2022-09-21T23:07:19.585Z] 23:07:19     INFO - TEST-START | browser/base/content/test/performance/browser_preferences_usage.js
[task 2022-09-21T23:07:21.561Z] 23:07:21     INFO - GECKO(8756) | [Child 1572: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 9fdfc00 == 1 [pid = 1572] [id = 0]
[task 2022-09-21T23:07:21.561Z] 23:07:21     INFO - GECKO(8756) | [Child 1572: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (50a58a0) [pid = 1572] [serial = 1] [outer = 0]
[task 2022-09-21T23:07:21.563Z] 23:07:21     INFO - GECKO(8756) | [Child 1572: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (9fe0b00) [pid = 1572] [serial = 2] [outer = 50a58a0]
[task 2022-09-21T23:07:21.567Z] 23:07:21     INFO - GECKO(8756) | [Child 2972, Main Thread] WARNING: '!CanHandleWith(aPresContext)', file /builds/worker/checkouts/gecko/dom/events/IMEStateManager.cpp:498
[task 2022-09-21T23:07:21.579Z] 23:07:21     INFO - GECKO(8756) | Waiting for browser load
[task 2022-09-21T23:07:21.581Z] 23:07:21     INFO - GECKO(8756) | Waiting for browser state change
[task 2022-09-21T23:07:21.603Z] 23:07:21     INFO - GECKO(8756) | Saw state f0001 and status 0

[task 2022-09-21T23:07:35.611Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | gfx.content.azure.backends should be accessed at least 90 times. - 90 <= 96 - 
[task 2022-09-21T23:07:35.612Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | gfx.content.azure.backends should be accessed at most 110 times. - 96 <= 110 - 
[task 2022-09-21T23:07:35.613Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | gfx.canvas.azure.backends should be accessed at least 90 times. - 90 <= 96 - 
[task 2022-09-21T23:07:35.614Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | gfx.canvas.azure.backends should be accessed at most 110 times. - 96 <= 110 - 
[task 2022-09-21T23:07:35.615Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | extensions.screenshots.disabled should be accessed at least 50 times. - 50 <= 51 - 
[task 2022-09-21T23:07:35.615Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | extensions.screenshots.disabled should be accessed at most 51 times. - 51 <= 51 - 
[task 2022-09-21T23:07:35.615Z] 23:07:35     INFO - toolkit.telemetry.cachedClientID should not be accessed more than 40 times and was accessed 50 times.
[task 2022-09-21T23:07:35.616Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | dom.ipc.keepProcessesAlive.webIsolated.perOrigin should be accessed at least 50 times. - 50 <= 50 - 
[task 2022-09-21T23:07:35.617Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | dom.ipc.keepProcessesAlive.webIsolated.perOrigin should be accessed at most 51 times. - 50 <= 51 - 
[task 2022-09-21T23:07:35.618Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | dom.ipc.processCount.webIsolated should be accessed at least 50 times. - 50 <= 50 - 
[task 2022-09-21T23:07:35.618Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | dom.ipc.processCount.webIsolated should be accessed at most 51 times. - 50 <= 51 - 
[task 2022-09-21T23:07:35.619Z] 23:07:35     INFO - Buffered messages finished
[task 2022-09-21T23:07:35.619Z] 23:07:35     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_preferences_usage.js | security.sandbox.content.read_path_whitelist should be accessed at least 49 times. - 49 <= 48 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js :: checkPrefGetters :: line 56
[task 2022-09-21T23:07:35.619Z] 23:07:35     INFO - Stack trace:
[task 2022-09-21T23:07:35.621Z] 23:07:35     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:checkPrefGetters:56
[task 2022-09-21T23:07:35.621Z] 23:07:35     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:navigate_around:296
[task 2022-09-21T23:07:35.621Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | security.sandbox.content.read_path_whitelist should be accessed at most 55 times. - 48 <= 55 - 
[task 2022-09-21T23:07:35.621Z] 23:07:35     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-09-21T23:07:35.622Z] 23:07:35     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_preferences_usage.js | security.sandbox.logging.enabled should be accessed at least 49 times. - 49 <= 48 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js :: checkPrefGetters :: line 56
[task 2022-09-21T23:07:35.622Z] 23:07:35     INFO - Stack trace:
[task 2022-09-21T23:07:35.623Z] 23:07:35     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:checkPrefGetters:56
[task 2022-09-21T23:07:35.623Z] 23:07:35     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:navigate_around:296
[task 2022-09-21T23:07:35.624Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | security.sandbox.logging.enabled should be accessed at most 55 times. - 48 <= 55 - 
[task 2022-09-21T23:07:35.624Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | browser.tabs.remote.logSwitchTiming should not be accessed more than 40 times. - 4 <= 40 - 
[task 2022-09-21T23:07:35.624Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | dom.security.https_first should not be accessed more than 40 times. - 2 <= 40 - 
[task 2022-09-21T23:07:35.625Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | dom.send_after_paint_to_content should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.625Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | image.animation_mode should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.626Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | layout.reflow.dumpframebyframecounts should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.627Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | browser.tabs.remote.separatedMozillaDomains should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.627Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | dom.ipc.tabs.disabled should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.628Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | layout.scrollbar.side should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.628Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | ui.highlighttext should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.629Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | browser.sessionhistory.contentViewerTimeout should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.629Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | layout.reflow.dumpframecounts should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.630Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | ui.highlight should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.630Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | browser.tabs.insertAfterCurrent should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.631Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | browser.display.auto_quality_min_font_size should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.631Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | layout.reflow.showframecounts should not be accessed more than 40 times. - 1 <= 40 - 
[task 2022-09-21T23:07:35.633Z] 23:07:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Should have accessed all known problematic prefs. Remaining:  - 
[task 2022-09-21T23:07:35.633Z] 23:07:35     INFO - Leaving test bound navigate_around

The Bugbug bot thinks this bug should belong to the 'Core::Layout' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Component: General → Layout
Product: Firefox → Core

All failures from the 4th of October onwards are actually perma and should be counted towards Bug 1793888

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered]

The spike in failures, indicate it started from this changeset

@Luca, can you check if these failures are related to bug 1794162 ?

First occurrence

Flags: needinfo?(lgreco)

(In reply to Sandor Molnar from comment #11)

The spike in failures, indicate it started from this changeset

@Luca, can you check if these failures are related to bug 1794162 ?

First occurrence

I just took a look to a sample of the last occurrence of this intermittent tracked on orangefactor and it seems that the failure is consistently triggered because the two prefs security.sandbox.content.read_path_whitelist and security.sandbox.logging.enabled are expected to be accessed at least 49 times but when the test fails they have been accessed only 48 times.

Bug 1794162 doesn't actually check those prefs and so it seems not very likely for Bug 1794162 to have affected that test, especially given that the patch should have changed how often or when during startup the module is used, it just ensures it stays inactive when not explicitly enabled by its related about:config pref (and so with Bug 1794162 the pref dom.sitepermsaddon-provider.enabled should be accessed one time more than it was before that patch, but the test failure is not listing that pref in those failure logs).

Looking to code accessing the two prefs security.sandbox.content.read_path_whitelist and security.sandbox.logging.enabled and changed recently, I see that GeckoChildProcessHost::PrepareLaunch is one of the two places where those prefs seems to be actually accessed, and the most recent change applied on ipc/glue/GeckoChildProcessHost.cpp is Bug 1792474 - Part 3: Stop using IPC::Channel to create the pipe for ForkServer which has been landed on 07 Oct 2022, but I'm not sure if it may have had this kind of side effect (accessing those prefs one time less then it used to be).

Also I noticed that we decremented the number of expected times these prefs are accessed before for similar intermittents, e.g. Bug 1621231

Flags: needinfo?(lgreco)

Hi Gijs,
what do you think about this intermittent? (See comment 12) could it be related to the changes introduced from Bug 1794162? (or from Bug 1792474?)

Based on your previous investigation from Bug 1621231 do you think that we should investigate this more or decrement the minimum number of expected access from 49 to 48?

Flags: needinfo?(gijskruitbosch+bugs)
See Also: → 1621231

In the meantime I filed Bug 1796578 as a followup to use a lazy pref getter for the pref being checked in the patch landed as part of Bug 1794162, as it seems a reasonable change to apply to it independently if it is actually related to this intermittent raising in frequency.

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered]

(In reply to Luca Greco [:rpl] [:luca] [:lgreco] from comment #13)

Hi Gijs,
what do you think about this intermittent? (See comment 12) could it be related to the changes introduced from Bug 1794162? (or from Bug 1792474?)

Based on your previous investigation from Bug 1621231 do you think that we should investigate this more or decrement the minimum number of expected access from 49 to 48?

I don't like not understanding why these pref accesses decreased but also I don't think it really warrants lots of investigation - we want the numbers to be lower than they are now, so decreasing the limit seems fine to me. Perhaps there's some kind of perf improvement in some of the earlier commits in the treeherder pushlog where content process startup is faster and so more preloaded processes start before the test starts recording or something? I dunno. We could ask Nika or :gcp to take a look if we really cared. But for right now, I think just decreasing the limit is fine.

Flags: needinfo?(gijskruitbosch+bugs)

(In reply to Sandor Molnar from comment #11)

The spike in failures, indicate it started from this changeset

I'm not sure there was really a spike? It failed 10 times the week preceding this comment, and 150 times the week before that (leading up to bug 1793888 being fixed, I guess). So not sure what "spike" really meant...

Assignee: nobody → gijskruitbosch+bugs
Status: NEW → ASSIGNED
Pushed by gijskruitbosch@gmail.com: https://hg.mozilla.org/integration/autoland/rev/0235b22842b4 reduce sandbox pref lower limit in browser_preferences_usage.js to stop intermittents, r=rpl
Assignee: gijskruitbosch+bugs → nobody
Status: ASSIGNED → NEW
Keywords: leave-open
Priority: P5 → --
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell needswork:owner]

A bunch of the increase here was the telemetry cachedClientID which was removed in bug 1810790. Some of them are us not reading the sandbox prefs quite as often (47 instead of 48 times) so I think dropping the minimum there would be fine.

A few failures are us reading the gfx colorspace pref a little more often (52 instead of 50) times; it's not clear to me what would cause that kind of raciness (perhaps to do with image loading and/or if we reuse things for that or something) so I figure to leave it alone for now also given the context in bug 1729080

Depends on: 1810790, 1729080

(In reply to :Gijs (he/him) from comment #16)

I don't like not understanding why these pref accesses decreased but also I don't think it really warrants lots of investigation - we want the numbers to be lower than they are now, so decreasing the limit seems fine to me. Perhaps there's some kind of perf improvement in some of the earlier commits in the treeherder pushlog where content process startup is faster and so more preloaded processes start before the test starts recording or something?

I agree that seeing a number that's almost the number of tabs we open but a little less sounds like we are seeing the number of preallocated content processes. I wonder if there's a pref somewhere that the test could read to make the minimum be <number of tabs we open> - <maximum number of preallocated content process we might have>.

Pushed by gijskruitbosch@gmail.com: https://hg.mozilla.org/integration/autoland/rev/130a982b035b drop sandbox pref 'minimum' usage still further, r=florian
Attachment #9383563 - Attachment is obsolete: true
See Also: → 1885993

Recent spike was from bug 1791940 which also adjusted the maximum for browser.startup.record.

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: NEW → RESOLVED
Closed: 5 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: