Closed Bug 1621231 Opened 5 years ago Closed 5 years ago

Intermittent test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.read_path_whitelist should be accessed at most 51 times. - 52 <= 51 - JS frame :: chrome://*/browser_preferences_usage.js :: checkPrefGetters :: line 63

Categories

(Firefox :: General, defect, P5)

defect

Tracking

()

RESOLVED FIXED
Firefox 79
Tracking Status
firefox79 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: Gijs)

References

Details

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

Attachments

(1 file)

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


...
[task 2020-03-10T09:48:35.612Z] 09:48:35     INFO - Navigating to http://example.com/...
[task 2020-03-10T09:48:35.612Z] 09:48:35     INFO - Buffered messages logged at 09:48:33
[task 2020-03-10T09:48:35.612Z] 09:48:35     INFO - Loaded http://example.com/.
[task 2020-03-10T09:48:35.612Z] 09:48:35     INFO - Navigating to https://example.com/...
[task 2020-03-10T09:48:35.613Z] 09:48:35     INFO - Buffered messages logged at 09:48:34
[task 2020-03-10T09:48:35.613Z] 09:48:35     INFO - Loaded https://example.com/.
[task 2020-03-10T09:48:35.614Z] 09:48:35     INFO - network.loadinfo.skip_type_assertion should not be accessed more than 40 times and was accessed 165 times.
[task 2020-03-10T09:48:35.614Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item browser.zoom.full should be accessed at least 100 times. - 100 <= 103 - 
[task 2020-03-10T09:48:35.614Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item browser.zoom.full should be accessed at most 110 times. - 103 <= 110 - 
[task 2020-03-10T09:48:35.615Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.read_path_whitelist should be accessed at least 50 times. - 50 <= 52 - 
[task 2020-03-10T09:48:35.615Z] 09:48:35     INFO - Buffered messages finished
[task 2020-03-10T09:48:35.618Z] 09:48:35     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.read_path_whitelist should be accessed at most 51 times. - 52 <= 51 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js :: checkPrefGetters :: line 63
[task 2020-03-10T09:48:35.619Z] 09:48:35     INFO - Stack trace:
[task 2020-03-10T09:48:35.619Z] 09:48:35     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:checkPrefGetters:63
[task 2020-03-10T09:48:35.619Z] 09:48:35     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:navigate_around:267
[task 2020-03-10T09:48:35.619Z] 09:48:35     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1062
[task 2020-03-10T09:48:35.620Z] 09:48:35     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
[task 2020-03-10T09:48:35.621Z] 09:48:35     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:925
[task 2020-03-10T09:48:35.621Z] 09:48:35     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:918
[task 2020-03-10T09:48:35.621Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.write_path_whitelist should be accessed at least 50 times. - 50 <= 52 - 
[task 2020-03-10T09:48:35.621Z] 09:48:35     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-10T09:48:35.621Z] 09:48:35     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.write_path_whitelist should be accessed at most 51 times. - 52 <= 51 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js :: checkPrefGetters :: line 63
[task 2020-03-10T09:48:35.621Z] 09:48:35     INFO - Stack trace:
[task 2020-03-10T09:48:35.622Z] 09:48:35     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:checkPrefGetters:63
[task 2020-03-10T09:48:35.622Z] 09:48:35     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:navigate_around:267
[task 2020-03-10T09:48:35.623Z] 09:48:35     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1062
[task 2020-03-10T09:48:35.623Z] 09:48:35     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
[task 2020-03-10T09:48:35.624Z] 09:48:35     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:925
[task 2020-03-10T09:48:35.624Z] 09:48:35     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:918
[task 2020-03-10T09:48:35.625Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.force-namespace should be accessed at least 50 times. - 50 <= 52 - 
[task 2020-03-10T09:48:35.625Z] 09:48:35     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-10T09:48:35.626Z] 09:48:35     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.force-namespace should be accessed at most 51 times. - 52 <= 51 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js :: checkPrefGetters :: line 63
[task 2020-03-10T09:48:35.626Z] 09:48:35     INFO - Stack trace:
[task 2020-03-10T09:48:35.627Z] 09:48:35     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:checkPrefGetters:63
[task 2020-03-10T09:48:35.634Z] 09:48:35     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:navigate_around:267
[task 2020-03-10T09:48:35.635Z] 09:48:35     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1062
[task 2020-03-10T09:48:35.635Z] 09:48:35     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
[task 2020-03-10T09:48:35.635Z] 09:48:35     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:925
[task 2020-03-10T09:48:35.636Z] 09:48:35     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:918
[task 2020-03-10T09:48:35.646Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item toolkit.cosmeticAnimations.enabled should be accessed at least 45 times. - 45 <= 50 - 
[task 2020-03-10T09:48:35.647Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item toolkit.cosmeticAnimations.enabled should be accessed at most 55 times. - 50 <= 55 - 
[task 2020-03-10T09:48:35.647Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item dom.ipc.processCount.webIsolated should be accessed at least 50 times. - 50 <= 50 - 
[task 2020-03-10T09:48:35.647Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item dom.ipc.processCount.webIsolated should be accessed at most 51 times. - 50 <= 51 - 
[task 2020-03-10T09:48:35.648Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item dom.ipc.keepProcessesAlive.webIsolated.perOrigin should be accessed at least 50 times. - 50 <= 50 - 
[task 2020-03-10T09:48:35.648Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item dom.ipc.keepProcessesAlive.webIsolated.perOrigin should be accessed at most 51 times. - 50 <= 51 - 
[task 2020-03-10T09:48:35.649Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | layout.css.dpi should not be accessed more than 40 times. - 18 <= 40 - 
[task 2020-03-10T09:48:35.649Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | browser.startup.record should not be accessed more than 40 times. - 10 <= 40 - 
[task 2020-03-10T09:48:35.649Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | browser.cache.disk.capacity should not be accessed more than 40 times. - 5 <= 40 - 
[task 2020-03-10T09:48:35.650Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | browser.privatebrowsing.autostart should not be accessed more than 40 times. - 4 <= 40 - 
[task 2020-03-10T09:48:35.650Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | dom.ipc.multiOptOut should not be accessed more than 40 times. - 3 <= 40 - 
[task 2020-03-10T09:48:35.655Z] 09:48:35     INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | dom.ipc.processCount should not be accessed more than 40 times. - 3 <= 40 - 
...
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Does the threshold of allowed sandbox pref reads need an adjustment or should this be regarded as regression?

Flags: needinfo?(gpascutto)

I honestly wouldn't even know why we're testing that.

Flags: needinfo?(gpascutto) → needinfo?(gijskruitbosch+bugs)

(In reply to Gian-Carlo Pascutto [:gcp] from comment #9)

why we're testing that.

Pref reads are not free, and StaticPrefs exists (and defineLazyPreferenceGetter in JS land) to reduce that cost for hot code. The test is meant to fail when people add expensive pref reads. There's a list of known issues, for which bugs are on file, which have lower and upper bounds associated with them so we notice if those issues go away or get worse. This failure indicates some of these prefs are now being accessed more often (albeit only slightly).

bug 1639242 recently touched this, but not recently enough to explain the timing of the spike in failures. If I had to guess, this is related to the preallocated fission process work jesup did, as the prefs are consulted when creating processes. All the failures are Fission-specific.

I think given the small difference, it's probably OK to increment the max to 52 or 55 or something without spending too much time trying to figure out the exact reason this has gone up by 1 or 2 - it'd be more useful to fix the underlying bugs, ie bug 1639494 and bug 1600189. Florian, does that sound right to you?

Flags: needinfo?(gijskruitbosch+bugs) → needinfo?(florian)

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

I think given the small difference, it's probably OK to increment the max to 52 or 55 or something without spending too much time trying to figure out the exact reason this has gone up by 1 or 2 - it'd be more useful to fix the underlying bugs, ie bug 1639494 and bug 1600189. Florian, does that sound right to you?

Yes, that sounds right.

Note: there are also Windows failures where the test reports that we are accessing the preference less than we expect: "Whitelist item gfx.canvas.azure.backends should be accessed at least 100 times. - 100 <= 98"

Flags: needinfo?(florian)

I have some refactoring I did as part of bug 1640345 that will cache more of the sandbox policy, including those prefs, so that should take care of this. (I plan to split it out into a separate bug and connect this one to it.)

In the past week there 38 failures on:
-linux1804-64 debug

Recent failure log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=306247708&repo=autoland&lineNumber=4509

[task 2020-06-13T17:43:41.418Z] 17:43:41 INFO - Loaded http://example.org/.
[task 2020-06-13T17:43:41.419Z] 17:43:41 INFO - Navigating to https://example.org/...
[task 2020-06-13T17:43:41.419Z] 17:43:41 INFO - Buffered messages logged at 17:43:38
[task 2020-06-13T17:43:41.420Z] 17:43:41 INFO - Loaded https://example.org/.
[task 2020-06-13T17:43:41.420Z] 17:43:41 INFO - Navigating to http://example.com/...
[task 2020-06-13T17:43:41.421Z] 17:43:41 INFO - Buffered messages logged at 17:43:39
[task 2020-06-13T17:43:41.426Z] 17:43:41 INFO - Loaded http://example.com/.
[task 2020-06-13T17:43:41.426Z] 17:43:41 INFO - Navigating to https://example.com/...
[task 2020-06-13T17:43:41.426Z] 17:43:41 INFO - Buffered messages logged at 17:43:40
[task 2020-06-13T17:43:41.427Z] 17:43:41 INFO - Loaded https://example.com/.
[task 2020-06-13T17:43:41.427Z] 17:43:41 INFO - network.loadinfo.skip_type_assertion should not be accessed more than 40 times and was accessed 165 times.
[task 2020-06-13T17:43:41.428Z] 17:43:41 INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item browser.zoom.full should be accessed at least 100 times. - 100 <= 103 -
[task 2020-06-13T17:43:41.428Z] 17:43:41 INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item browser.zoom.full should be accessed at most 110 times. - 103 <= 110 -
[task 2020-06-13T17:43:41.429Z] 17:43:41 INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.read_path_whitelist should be accessed at least 50 times. - 50 <= 54 -
[task 2020-06-13T17:43:41.430Z] 17:43:41 INFO - Buffered messages finished
[task 2020-06-13T17:43:41.431Z] 17:43:41 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.read_path_whitelist should be accessed at most 51 times. - 54 <= 51 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js :: checkPrefGetters :: line 63
[task 2020-06-13T17:43:41.431Z] 17:43:41 INFO - Stack trace:
[task 2020-06-13T17:43:41.432Z] 17:43:41 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:checkPrefGetters:63
[task 2020-06-13T17:43:41.433Z] 17:43:41 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:navigate_around:280
[task 2020-06-13T17:43:41.434Z] 17:43:41 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1064
[task 2020-06-13T17:43:41.435Z] 17:43:41 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1104
[task 2020-06-13T17:43:41.436Z] 17:43:41 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:927
[task 2020-06-13T17:43:41.436Z] 17:43:41 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:918
[task 2020-06-13T17:43:41.437Z] 17:43:41 INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.write_path_whitelist should be accessed at least 50 times. - 50 <= 54 -
[task 2020-06-13T17:43:41.438Z] 17:43:41 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-06-13T17:43:41.439Z] 17:43:41 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.write_path_whitelist should be accessed at most 51 times. - 54 <= 51 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js :: checkPrefGetters :: line 63
[task 2020-06-13T17:43:41.439Z] 17:43:41 INFO - Stack trace:
[task 2020-06-13T17:43:41.440Z] 17:43:41 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:checkPrefGetters:63
[task 2020-06-13T17:43:41.441Z] 17:43:41 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js:navigate_around:280
[task 2020-06-13T17:43:41.442Z] 17:43:41 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1064
[task 2020-06-13T17:43:41.442Z] 17:43:41 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1104
[task 2020-06-13T17:43:41.443Z] 17:43:41 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:927
[task 2020-06-13T17:43:41.444Z] 17:43:41 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:918
[task 2020-06-13T17:43:41.445Z] 17:43:41 INFO - TEST-PASS | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.force-namespace should be accessed at least 50 times. - 50 <= 54 -
[task 2020-06-13T17:43:41.445Z] 17:43:41 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-06-13T17:43:41.449Z] 17:43:41 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_preferences_usage.js | Whitelist item security.sandbox.content.force-namespace should be accessed at most 51 times. - 54 <= 51 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js :: checkPrefGetters :: line 63

Justin, could you take a look?

Flags: needinfo?(dolske)
Whiteboard: [stockwell needswork:owner]

A longer-term fix is being worked on in bug 1644917, but this will make life easier for sheriffs and on try.

Assignee: nobody → gijskruitbosch+bugs

I'll put up a patch to shut up the test failures while :jld gets a "real" fix together in bug 1644917.

Assignee: gijskruitbosch+bugs → nobody
Flags: needinfo?(dolske)
Keywords: leave-open
Assignee: nobody → gijskruitbosch+bugs
Pushed by gijskruitbosch@gmail.com: https://hg.mozilla.org/integration/autoland/rev/f78c743cce37 make sandbox prefs not trip browser_preferences_usage.js so much, r=florian

The intermittent is fixed, so I guess we can close this.

Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Keywords: leave-open
Resolution: --- → FIXED
Target Milestone: --- → Firefox 79

Instances of this since 2020-05-30 were probably caused by bug 1602757 (preallocated content processes for Fission) increasing the number of process launches by O(1).

See Also: → 1732447
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: