1603309 - Intermittent browser/base/content/test/performance/browser_startup_content_mainthreadio.js | unused whitelist entry WebExtensions: /builds/worker/workspace/build/application/firefox/browser/features/[e-mail] -

Status: RESOLVED FIXED

(Toolkit :: Form Autofill, defect, P5)

Description

[Treeherder Bug Filer]

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

---

INFO - TEST-START | browser/base/content/test/performance/browser_startup_content_mainthreadio.js
[task 2019-12-11T23:43:45.494Z] 23:43:45     INFO - TEST-INFO | started process screentopng
[task 2019-12-11T23:43:45.751Z] 23:43:45     INFO - TEST-INFO | screentopng: exit 0
[task 2019-12-11T23:43:45.751Z] 23:43:45     INFO - Buffered messages logged at 23:43:45
[task 2019-12-11T23:43:45.751Z] 23:43:45     INFO - Entering test bound 
[task 2019-12-11T23:43:45.752Z] 23:43:45     INFO - whitelisted paths for Web Content process:
[task 2019-12-11T23:43:45.752Z] 23:43:45     INFO -   /builds/worker/workspace/build/application/firefox/omni.ja - stat: 1
[task 2019-12-11T23:43:45.752Z] 23:43:45     INFO -   /builds/worker/workspace/build/application/firefox/browser/omni.ja - stat: 1
[task 2019-12-11T23:43:45.752Z] 23:43:45     INFO -   /builds/worker/workspace/build/application/firefox/browser/features/[e-mail] - stat: 1
[task 2019-12-11T23:43:45.752Z] 23:43:45     INFO -   /builds/worker/workspace/build/application/firefox/browser/features/[e-mail] - ignoreIfUnused: true, stat: 1
[task 2019-12-11T23:43:45.752Z] 23:43:45     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | Found profile for Web Content process - 
[task 2019-12-11T23:43:45.753Z] 23:43:45     INFO - (NSPRIOInterposer) stat - /builds/worker/workspace/build/application/firefox/omni.ja
[task 2019-12-11T23:43:45.753Z] 23:43:45     INFO - (NSPRIOInterposer) stat - /builds/worker/workspace/build/application/firefox/browser/omni.ja
[task 2019-12-11T23:43:45.754Z] 23:43:45     INFO - (NSPRIOInterposer) stat - /builds/worker/workspace/build/application/firefox/browser/features/[e-mail]
[task 2019-12-11T23:43:45.754Z] 23:43:45     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | Web Content startup profiles should have IO markers in builds that are not RELEASE_OR_BETA - 
[task 2019-12-11T23:43:45.755Z] 23:43:45     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | stat on /builds/worker/workspace/build/application/firefox/omni.ja as many times as expected in Web Content process - 
[task 2019-12-11T23:43:45.755Z] 23:43:45     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | stat on /builds/worker/workspace/build/application/firefox/browser/omni.ja as many times as expected in Web Content process - 
[task 2019-12-11T23:43:45.756Z] 23:43:45     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | stat on /builds/worker/workspace/build/application/firefox/browser/features/[e-mail] as many times as expected in Web Content process - 
[task 2019-12-11T23:43:45.756Z] 23:43:45     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | stat on /builds/worker/workspace/build/application/firefox/browser/features/[e-mail] allowed 1 more times in Web Content process - 
[task 2019-12-11T23:43:45.757Z] 23:43:45     INFO - whitelisted paths for Privileged Content process:
[task 2019-12-11T23:43:45.757Z] 23:43:45     INFO -   /builds/worker/workspace/build/application/firefox/omni.ja - stat: 1
[task 2019-12-11T23:43:45.757Z] 23:43:45     INFO -   /builds/worker/workspace/build/application/firefox/browser/omni.ja - stat: 1
[task 2019-12-11T23:43:45.758Z] 23:43:45     INFO -   /builds/worker/workspace/build/application/firefox/browser/features/[e-mail] - stat: 1
[task 2019-12-11T23:43:45.758Z] 23:43:45     INFO - TEST-FAIL | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | profile for Privileged Content process not found - 
[task 2019-12-11T23:43:45.758Z] 23:43:45     INFO - whitelisted paths for WebExtensions process:
[task 2019-12-11T23:43:45.758Z] 23:43:45     INFO -   /builds/worker/workspace/build/application/firefox/omni.ja - stat: 1
[task 2019-12-11T23:43:45.758Z] 23:43:45     INFO -   /builds/worker/workspace/build/application/firefox/browser/omni.ja - stat: 1
[task 2019-12-11T23:43:45.759Z] 23:43:45     INFO -   /builds/worker/workspace/build/application/firefox/browser/features/[e-mail] - stat: 1
[task 2019-12-11T23:43:45.759Z] 23:43:45     INFO -   /builds/worker/workspace/build/application/firefox/browser/features/[e-mail] - close: 1
[task 2019-12-11T23:43:45.759Z] 23:43:45     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | Found profile for WebExtensions process - 
[task 2019-12-11T23:43:45.760Z] 23:43:45     INFO - (NSPRIOInterposer) stat - /builds/worker/workspace/build/application/firefox/omni.ja
[task 2019-12-11T23:43:45.761Z] 23:43:45     INFO - (NSPRIOInterposer) stat - /builds/worker/workspace/build/application/firefox/browser/omni.ja
[task 2019-12-11T23:43:45.761Z] 23:43:45     INFO - (NSPRIOInterposer) stat - /builds/worker/workspace/build/application/firefox/browser/features/[e-mail]
[task 2019-12-11T23:43:45.761Z] 23:43:45     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | WebExtensions startup profiles should have IO markers in builds that are not RELEASE_OR_BETA - 
[task 2019-12-11T23:43:45.762Z] 23:43:45     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | stat on /builds/worker/workspace/build/application/firefox/omni.ja as many times as expected in WebExtensions process - 
[task 2019-12-11T23:43:45.762Z] 23:43:45     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | stat on /builds/worker/workspace/build/application/firefox/browser/omni.ja as many times as expected in WebExtensions process - 
[task 2019-12-11T23:43:45.763Z] 23:43:45     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | stat on /builds/worker/workspace/build/application/firefox/browser/features/[e-mail] as many times as expected in WebExtensions process - 
[task 2019-12-11T23:43:45.763Z] 23:43:45     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | close on /builds/worker/workspace/build/application/firefox/browser/features/[e-mail] allowed 1 more times in WebExtensions process - 
[task 2019-12-11T23:43:45.764Z] 23:43:45     INFO - Buffered messages finished
[task 2019-12-11T23:43:45.765Z] 23:43:45     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | unused whitelist entry WebExtensions: /builds/worker/workspace/build/application/firefox/browser/features/[e-mail] - 
[task 2019-12-11T23:43:45.765Z] 23:43:45     INFO - Stack trace:
[task 2019-12-11T23:43:45.765Z] 23:43:45     INFO - chrome://mochikit/content/browser-test.js:test_ok:1292
[task 2019-12-11T23:43:45.765Z] 23:43:45     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_content_mainthreadio.js:null:424
[task 2019-12-11T23:43:45.765Z] 23:43:45     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1062
[task 2019-12-11T23:43:45.765Z] 23:43:45     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
[task 2019-12-11T23:43:45.765Z] 23:43:45     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:925
[task 2019-12-11T23:43:45.765Z] 23:43:45     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:808
[task 2019-12-11T23:43:46.424Z] 23:43:46     INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-12-11T23:43:46.424Z] 23:43:46     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | Unexpected main thread I/O behavior during child process startup; open the profile_startup_content_mainthreadio.json artifact in the Firefox Profiler to see what happened - 
[task 2019-12-11T23:43:46.424Z] 23:43:46     INFO - Stack trace:
[task 2019-12-11T23:43:46.425Z] 23:43:46     INFO - chrome://mochikit/content/browser-test.js:test_ok:1292
[task 2019-12-11T23:43:46.425Z] 23:43:46     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_content_mainthreadio.js:null:443
[task 2019-12-11T23:43:46.425Z] 23:43:46     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1062
[task 2019-12-11T23:43:46.425Z] 23:43:46     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
[task 2019-12-11T23:43:46.425Z] 23:43:46     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:925
[task 2019-12-11T23:43:46.425Z] 23:43:46     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:808
[task 2019-12-11T23:43:46.425Z] 23:43:46     INFO - Leaving test bound 
[task 2019-12-11T23:43:46.425Z] 23:43:46     INFO - GECKO(25967) | [CodeCoverage] Requested flush for 25967.
[task 2019-12-11T23:43:46.682Z] 23:43:46     INFO - GECKO(25967) | [CodeCoverage] flush completed.
[task 2019-12-11T23:43:47.462Z] 23:43:47     INFO - GECKO(25967) | [CodeCoverage] JS flush completed.
[task 2019-12-11T23:43:47.462Z] 23:43:47     INFO - GECKO(25967) | [CodeCoverage] Requested flush for 26035.
[task 2019-12-11T23:43:47.462Z] 23:43:47     INFO - GECKO(25967) | [CodeCoverage] Requested flush for 26031.
[task 2019-12-11T23:43:47.462Z] 23:43:47     INFO - GECKO(25967) | [CodeCoverage] Requested flush for 26131.
[task 2019-12-11T23:43:47.699Z] 23:43:47     INFO - GECKO(25967) | [CodeCoverage] flush completed.
[task 2019-12-11T23:43:47.841Z] 23:43:47     INFO - GECKO(25967) | [CodeCoverage] JS flush completed.
[task 2019-12-11T23:43:48.099Z] 23:43:48     INFO - GECKO(25967) | [CodeCoverage] flush completed.
[task 2019-12-11T23:43:48.159Z] 23:43:48     INFO - GECKO(25967) | [CodeCoverage] JS flush completed.
[task 2019-12-11T23:43:48.281Z] 23:43:48     INFO - GECKO(25967) | [CodeCoverage] Setting handlers for process 26161.
[task 2019-12-11T23:43:48.402Z] 23:43:48     INFO - GECKO(25967) | [CodeCoverage] flush completed.
[task 2019-12-11T23:43:48.446Z] 23:43:48     INFO - GECKO(25967) | [CodeCoverage] JS flush completed.
[task 2019-12-11T23:43:48.473Z] 23:43:48     INFO - GECKO(25967) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2019-12-11T23:43:48.473Z] 23:43:48     INFO - GECKO(25967) | MEMORY STAT | vsize 3285MB | residentFast 614MB | heapAllocated 290MB
[task 2019-12-11T23:43:48.474Z] 23:43:48     INFO - TEST-OK | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | took 3021ms

Comment 1

[Dorel Luca [:dluca]]

This bug seems to be introduced by Bug 1595154 landing on central here: https://bugzilla.mozilla.org/show_bug.cgi?id=1595154#c15

Mike: Can you please take a look at this bug since Neil is going to be away for the next 8 days.

Comment 2

[Mike Conley (:mconley) (:⚙️)]

I think Neil's patch just changed some timings of things.

But upon deeper examination, it seems that the screenshots disk IO in the WebExtension process is normally coming from the shutdown of the Screenshots add-on when it's determined that the add-on is supposed to be disabled:

https://searchfox.org/mozilla-central/rev/923eec8d2fb8078ebc7a33a9e1ce73eac01f7446/browser/components/BrowserGlue.jsm#1879-1893

the add-on is disabled because of this: https://searchfox.org/mozilla-central/rev/923eec8d2fb8078ebc7a33a9e1ce73eac01f7446/testing/profiles/unittest-required/user.js#115

That's not super realistic - the Screenshots add-on is enabled by default for all users. So I'm going to see if I can get that pref flipped for just the performance tests.

Try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=53dba88ef9a00fff79d5e1552aca535f46e0c371

Comment 3

[Mike Conley (:mconley) (:⚙️)]

Attachment: Bug 1603309 - Make sure the Screenshots WebExtension is enabled during performance tests. r?florian

Comment 4

[Intermittent Failures Robot]

5 failures in 4867 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 5

Platform breakdown:

• linux64-ccov: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1603309&startday=2019-12-09&endday=2019-12-15&tree=all

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/5d45911e447f
Make sure the Screenshots WebExtension is enabled during performance tests. r=florian

Comment 6

[Cristina Coroiu [:ccoroiu]]

https://hg.mozilla.org/mozilla-central/rev/5d45911e447f