Closed Bug 1757664 Opened 2 years ago Closed 2 years ago

Intermittent browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected close on /builds/worker/workspace/build/application/firefox/browser/features/webcompat@mozilla.org.xpi before first paint -

Categories

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

defect

Tracking

()

RESOLVED DUPLICATE of bug 1784868

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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


[task 2022-03-01T23:36:03.551Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on /builds/worker/workspace/build/application/firefox/browser/features/webcompat@mozilla.org.xpi as many times as expected before opening first browser window - 
[task 2022-03-01T23:36:03.555Z] 23:36:03     INFO - known main thread IO paths during before first paint:
[task 2022-03-01T23:36:03.555Z] 23:36:03     INFO -   /builds/worker/workspace/build/application/firefox/browser/features/formautofill@mozilla.org.xpi - condition: true, stat: 1, close: 1, listedPath: XREAppFeat:formautofill@mozilla.org.xpi
[task 2022-03-01T23:36:03.555Z] 23:36:03     INFO -   *ld.so.conf* - condition: true, read: 22, close: 11, listedPath: *ld.so.conf*
[task 2022-03-01T23:36:03.555Z] 23:36:03     INFO -   /tmp/tmpixvzoknr.mozrunner/d3d11layers.guard - ignoreIfUnused: true, stat: 1, listedPath: ProfD:d3d11layers.guard
[task 2022-03-01T23:36:03.555Z] 23:36:03     INFO -   /tmp/tmpixvzoknr.mozrunner/glcontext.guard - ignoreIfUnused: true, stat: 1, listedPath: ProfD:glcontext.guard
[task 2022-03-01T23:36:03.555Z] 23:36:03     INFO -   /tmp/tmpixvzoknr.mozrunner/wmfvpxvideo.guard - ignoreIfUnused: true, stat: 1, listedPath: ProfD:wmfvpxvideo.guard
[task 2022-03-01T23:36:03.556Z] 23:36:03     INFO - Buffered messages finished
[task 2022-03-01T23:36:03.557Z] 23:36:03     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected close on /builds/worker/workspace/build/application/firefox/browser/features/webcompat@mozilla.org.xpi before first paint - 
[task 2022-03-01T23:36:03.558Z] 23:36:03     INFO - Stack trace:
[task 2022-03-01T23:36:03.558Z] 23:36:03     INFO -   Task nsJARChannel::ContinueOpenLocalFile
[task 2022-03-01T23:36:03.558Z] 23:36:03     INFO -   XREMain::XRE_main
[task 2022-03-01T23:36:03.559Z] 23:36:03     INFO - (NSPRIOInterposer) close - /builds/worker/workspace/build/application/firefox/browser/features/webcompat@mozilla.org.xpi
[task 2022-03-01T23:36:03.559Z] 23:36:03     INFO - (NSPRIOInterposer) stat - /builds/worker/workspace/build/application/firefox/browser/features/formautofill@mozilla.org.xpi
[task 2022-03-01T23:36:03.560Z] 23:36:03     INFO - (NSPRIOInterposer) close - /builds/worker/workspace/build/application/firefox/browser/features/formautofill@mozilla.org.xpi
[task 2022-03-01T23:36:03.561Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf
[task 2022-03-01T23:36:03.561Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf.d/libc.conf
[task 2022-03-01T23:36:03.562Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf.d/libc.conf
[task 2022-03-01T23:36:03.562Z] 23:36:03     INFO - (NSPRIOInterposer) close - /etc/ld.so.conf.d/libc.conf
[task 2022-03-01T23:36:03.562Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf.d/x86_64-linux-gnu.conf
[task 2022-03-01T23:36:03.563Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf.d/x86_64-linux-gnu.conf
[task 2022-03-01T23:36:03.563Z] 23:36:03     INFO - (NSPRIOInterposer) close - /etc/ld.so.conf.d/x86_64-linux-gnu.conf
[task 2022-03-01T23:36:03.564Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf.d/zz_i386-biarch-compat.conf
[task 2022-03-01T23:36:03.564Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf.d/zz_i386-biarch-compat.conf
[task 2022-03-01T23:36:03.565Z] 23:36:03     INFO - (NSPRIOInterposer) close - /etc/ld.so.conf.d/zz_i386-biarch-compat.conf
[task 2022-03-01T23:36:03.565Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf.d/i386-linux-gnu.conf
[task 2022-03-01T23:36:03.566Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf.d/i386-linux-gnu.conf
[task 2022-03-01T23:36:03.566Z] 23:36:03     INFO - (NSPRIOInterposer) close - /etc/ld.so.conf.d/i386-linux-gnu.conf
[task 2022-03-01T23:36:03.567Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf.d/zz_x32-biarch-compat.conf
[task 2022-03-01T23:36:03.568Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf.d/zz_x32-biarch-compat.conf
[task 2022-03-01T23:36:03.568Z] 23:36:03     INFO - (NSPRIOInterposer) close - /etc/ld.so.conf.d/zz_x32-biarch-compat.conf
[task 2022-03-01T23:36:03.569Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf.d/fakeroot-x86_64-linux-gnu.conf
[task 2022-03-01T23:36:03.570Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf.d/fakeroot-x86_64-linux-gnu.conf
[task 2022-03-01T23:36:03.570Z] 23:36:03     INFO - (NSPRIOInterposer) close - /etc/ld.so.conf.d/fakeroot-x86_64-linux-gnu.conf
[task 2022-03-01T23:36:03.571Z] 23:36:03     INFO - (NSPRIOInterposer) read - /etc/ld.so.conf
[task 2022-03-01T23:36:03.571Z] 23:36:03     INFO - (NSPRIOInterposer) close - /etc/ld.so.conf
[task 2022-03-01T23:36:03.572Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /builds/worker/workspace/build/application/firefox/browser/features/formautofill@mozilla.org.xpi as many times as expected before first paint - 
[task 2022-03-01T23:36:03.574Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on /builds/worker/workspace/build/application/firefox/browser/features/formautofill@mozilla.org.xpi as many times as expected before first paint - 
[task 2022-03-01T23:36:03.574Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | read on *ld.so.conf* allowed 8 more times before first paint - 
[task 2022-03-01T23:36:03.575Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on *ld.so.conf* allowed 4 more times before first paint - 
[task 2022-03-01T23:36:03.576Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /tmp/tmpixvzoknr.mozrunner/d3d11layers.guard allowed 1 more times before first paint - 
[task 2022-03-01T23:36:03.576Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /tmp/tmpixvzoknr.mozrunner/glcontext.guard allowed 1 more times before first paint - 
[task 2022-03-01T23:36:03.577Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /tmp/tmpixvzoknr.mozrunner/wmfvpxvideo.guard allowed 1 more times before first paint - 
[task 2022-03-01T23:36:03.577Z] 23:36:03     INFO - known main thread IO paths during before handling user events:
[task 2022-03-01T23:36:03.578Z] 23:36:03     INFO -   /builds/worker/workspace/build/application/firefox/update.test - ignoreIfUnused: true, condition: true, close: 1, listedPath: GreD:update.test
[task 2022-03-01T23:36:03.578Z] 23:36:03     INFO -   /builds/worker/workspace/build/application/firefox/browser/features/webcompat-reporter@mozilla.org.xpi - condition: true, ignoreIfUnused: true, stat: 1, close: 1, listedPath: XREAppFeat:webcompat-reporter@mozilla.org.xpi
[task 2022-03-01T23:36:03.579Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on /builds/worker/workspace/build/application/firefox/update.test allowed 1 more times before handling user events - 
[task 2022-03-01T23:36:03.580Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /builds/worker/workspace/build/application/firefox/browser/features/webcompat-reporter@mozilla.org.xpi allowed 1 more times before handling user events - 
[task 2022-03-01T23:36:03.580Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on /builds/worker/workspace/build/application/firefox/browser/features/webcompat-reporter@mozilla.org.xpi allowed 1 more times before handling user events - 
[task 2022-03-01T23:36:03.580Z] 23:36:03     INFO - known main thread IO paths during before becoming idle:
[task 2022-03-01T23:36:03.581Z] 23:36:03     INFO -   /builds/worker/workspace/build/application/firefox/browser/features/screenshots@mozilla.org.xpi - ignoreIfUnused: true, close: 1, listedPath: XREAppFeat:screenshots@mozilla.org.xpi
[task 2022-03-01T23:36:03.581Z] 23:36:03     INFO -   /builds/worker/workspace/build/application/firefox/browser/features/webcompat-reporter@mozilla.org.xpi - ignoreIfUnused: true, stat: 1, close: 1, listedPath: XREAppFeat:webcompat-reporter@mozilla.org.xpi
[task 2022-03-01T23:36:03.582Z] 23:36:03     INFO -   /tmp/tmpixvzoknr.mozrunner/places.sqlite-journal - ignoreIfUnused: true, fsync: 1, stat: 4, read: 1, write: 2, listedPath: ProfD:places.sqlite-journal
[task 2022-03-01T23:36:03.582Z] 23:36:03     INFO -   /tmp/tmpixvzoknr.mozrunner/places.sqlite-wal - ignoreIfUnused: true, stat: 4, fsync: 3, read: 51, write: 178, listedPath: ProfD:places.sqlite-wal
[task 2022-03-01T23:36:03.583Z] 23:36:03     INFO -   /tmp/tmpixvzoknr.mozrunner/places.sqlite - ignoreIfUnused: true, fsync: 2, read: 4, stat: 3, write: 1324, listedPath: ProfD:places.sqlite
[task 2022-03-01T23:36:03.583Z] 23:36:03     INFO -   /tmp/tmpixvzoknr.mozrunner/favicons.sqlite-journal - ignoreIfUnused: true, fsync: 2, stat: 7, read: 2, write: 7, listedPath: ProfD:favicons.sqlite-journal
[task 2022-03-01T23:36:03.584Z] 23:36:03     INFO -   /tmp/tmpixvzoknr.mozrunner/favicons.sqlite-wal - ignoreIfUnused: true, fsync: 2, stat: 7, read: 7, write: 15, listedPath: ProfD:favicons.sqlite-wal
[task 2022-03-01T23:36:03.584Z] 23:36:03     INFO -   /tmp/tmpixvzoknr.mozrunner/favicons.sqlite - ignoreIfUnused: true, fsync: 3, read: 8, stat: 4, write: 1300, listedPath: ProfD:favicons.sqlite
[task 2022-03-01T23:36:03.585Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on /builds/worker/workspace/build/application/firefox/browser/features/screenshots@mozilla.org.xpi allowed 1 more times before becoming idle - 
[task 2022-03-01T23:36:03.585Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /builds/worker/workspace/build/application/firefox/browser/features/webcompat-reporter@mozilla.org.xpi allowed 1 more times before becoming idle - 
[task 2022-03-01T23:36:03.586Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on /builds/worker/workspace/build/application/firefox/browser/features/webcompat-reporter@mozilla.org.xpi allowed 1 more times before becoming idle - 
[task 2022-03-01T23:36:03.586Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | fsync on /tmp/tmpixvzoknr.mozrunner/places.sqlite-journal allowed 1 more times before becoming idle - 
[task 2022-03-01T23:36:03.587Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /tmp/tmpixvzoknr.mozrunner/places.sqlite-journal allowed 4 more times before becoming idle - 
[task 2022-03-01T23:36:03.587Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | read on /tmp/tmpixvzoknr.mozrunner/places.sqlite-journal allowed 1 more times before becoming idle - 
[task 2022-03-01T23:36:03.588Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | write on /tmp/tmpixvzoknr.mozrunner/places.sqlite-journal allowed 2 more times before becoming idle - 
[task 2022-03-01T23:36:03.588Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /tmp/tmpixvzoknr.mozrunner/places.sqlite-wal allowed 4 more times before becoming idle - 
[task 2022-03-01T23:36:03.589Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | fsync on /tmp/tmpixvzoknr.mozrunner/places.sqlite-wal allowed 3 more times before becoming idle - 
[task 2022-03-01T23:36:03.590Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | read on /tmp/tmpixvzoknr.mozrunner/places.sqlite-wal allowed 51 more times before becoming idle - 
[task 2022-03-01T23:36:03.592Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | write on /tmp/tmpixvzoknr.mozrunner/places.sqlite-wal allowed 178 more times before becoming idle - 
[task 2022-03-01T23:36:03.593Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | fsync on /tmp/tmpixvzoknr.mozrunner/places.sqlite allowed 2 more times before becoming idle - 
[task 2022-03-01T23:36:03.595Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | read on /tmp/tmpixvzoknr.mozrunner/places.sqlite allowed 4 more times before becoming idle - 
[task 2022-03-01T23:36:03.595Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /tmp/tmpixvzoknr.mozrunner/places.sqlite allowed 3 more times before becoming idle - 
[task 2022-03-01T23:36:03.597Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | write on /tmp/tmpixvzoknr.mozrunner/places.sqlite allowed 1324 more times before becoming idle - 
[task 2022-03-01T23:36:03.598Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | fsync on /tmp/tmpixvzoknr.mozrunner/favicons.sqlite-journal allowed 2 more times before becoming idle - 
[task 2022-03-01T23:36:03.598Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /tmp/tmpixvzoknr.mozrunner/favicons.sqlite-journal allowed 7 more times before becoming idle - 
[task 2022-03-01T23:36:03.599Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | read on /tmp/tmpixvzoknr.mozrunner/favicons.sqlite-journal allowed 2 more times before becoming idle - 
[task 2022-03-01T23:36:03.600Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | write on /tmp/tmpixvzoknr.mozrunner/favicons.sqlite-journal allowed 7 more times before becoming idle - 
[task 2022-03-01T23:36:03.601Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | fsync on /tmp/tmpixvzoknr.mozrunner/favicons.sqlite-wal allowed 2 more times before becoming idle - 
[task 2022-03-01T23:36:03.601Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /tmp/tmpixvzoknr.mozrunner/favicons.sqlite-wal allowed 7 more times before becoming idle - 
[task 2022-03-01T23:36:03.603Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | read on /tmp/tmpixvzoknr.mozrunner/favicons.sqlite-wal allowed 7 more times before becoming idle - 
[task 2022-03-01T23:36:03.604Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | write on /tmp/tmpixvzoknr.mozrunner/favicons.sqlite-wal allowed 15 more times before becoming idle - 
[task 2022-03-01T23:36:03.604Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | fsync on /tmp/tmpixvzoknr.mozrunner/favicons.sqlite allowed 3 more times before becoming idle - 
[task 2022-03-01T23:36:03.605Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | read on /tmp/tmpixvzoknr.mozrunner/favicons.sqlite allowed 8 more times before becoming idle - 
[task 2022-03-01T23:36:03.606Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /tmp/tmpixvzoknr.mozrunner/favicons.sqlite allowed 4 more times before becoming idle - 
[task 2022-03-01T23:36:03.606Z] 23:36:03     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | write on /tmp/tmpixvzoknr.mozrunner/favicons.sqlite allowed 1300 more times before becoming idle - 
[task 2022-03-01T23:36:03.607Z] 23:36:03     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-03-01T23:36:03.608Z] 23:36:03     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | Unexpected main thread I/O behavior during startup; open the profile_startup_mainthreadio.json artifact in the Firefox Profiler to see what happened - 
[task 2022-03-01T23:36:03.608Z] 23:36:03     INFO - Stack trace:
[task 2022-03-01T23:36:03.609Z] 23:36:03     INFO - chrome://mochikit/content/browser-test.js:test_ok:1394
[task 2022-03-01T23:36:03.609Z] 23:36:03     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_mainthreadio.js:null:845
[task 2022-03-01T23:36:03.610Z] 23:36:03     INFO - Leaving test bound 
[task 2022-03-01T23:36:03.610Z] 23:36:03     INFO - GECKO(1567) | MEMORY STAT | vsize 11295MB | residentFast 372MB | heapAllocated 220MB
[task 2022-03-01T23:36:03.611Z] 23:36:03     INFO - TEST-OK | browser/base/content/test/performance/browser_startup_mainthreadio.js | took 158ms
[task 2022-03-01T23:36:03.612Z] 23:36:03     INFO - checking window state
[task 2022-03-01T23:36:03.612Z] 23:36:03     INFO - TEST-START | browser/base/content/test/performance/browser_startup_syncIPC.js
Summary: Intermittent [tier 2] browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected close on /builds/worker/workspace/build/application/firefox/browser/features/webcompat@mozilla.org.xpi before first paint - → Intermittent browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected close on /builds/worker/workspace/build/application/firefox/browser/features/webcompat@mozilla.org.xpi before first paint -

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

Component: General → Performance
Product: Firefox → Core
Component: Performance → DOM: Performance
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.