1741538 - Intermittent browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected read on C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\key4.db before becoming idle -

Status: RESOLVED DUPLICATE of bug 1761475

(Core :: Performance, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2021-11-17T02:09:20.208Z] 02:09:20     INFO - TEST-START | browser/base/content/test/performance/browser_startup_mainthreadio.js
[task 2021-11-17T02:09:20.336Z] 02:09:20     INFO - TEST-INFO | started process screenshot
[task 2021-11-17T02:09:20.468Z] 02:09:20     INFO - TEST-INFO | screenshot: exit 0
[task 2021-11-17T02:09:20.470Z] 02:09:20     INFO - <snipped 96 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2021-11-17T02:09:20.471Z] 02:09:20     INFO - Buffered messages logged at 02:09:20
[task 2021-11-17T02:09:20.471Z] 02:09:20     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on Z:\task_163711225166691\build\application\firefox\browser\features\[e-mail] allowed 2 more times before opening first browser window - 
<...>
[task 2021-11-17T02:09:20.561Z] 02:09:20     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_163711225166691\build\application\firefox\browser\features\[e-mail] allowed 1 more times before handling user events - 
[task 2021-11-17T02:09:20.565Z] 02:09:20     INFO - known main thread IO paths during before becoming idle:
[task 2021-11-17T02:09:20.566Z] 02:09:20     INFO -   Z:\task_163711225166691\build\application\firefox\browser\features\[e-mail] - ignoreIfUnused: true, close: 1, listedPath: XREAppFeat:[e-mail]
[task 2021-11-17T02:09:20.566Z] 02:09:20     INFO -   Z:\task_163711225166691\build\application\firefox\browser\features\[e-mail] - ignoreIfUnused: true, stat: 1, close: 1, listedPath: XREAppFeat:[e-mail]
[task 2021-11-17T02:09:20.566Z] 02:09:20     INFO -   C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\places.sqlite-journal - ignoreIfUnused: true, fsync: 1, stat: 4, read: 1, write: 2, listedPath: ProfD:places.sqlite-journal
[task 2021-11-17T02:09:20.566Z] 02:09:20     INFO -   C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\places.sqlite-wal - ignoreIfUnused: true, stat: 4, fsync: 3, read: 47, write: 170, listedPath: ProfD:places.sqlite-wal
[task 2021-11-17T02:09:20.566Z] 02:09:20     INFO -   C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\places.sqlite-shm - condition: true, ignoreIfUnused: true, stat: 1, listedPath: ProfD:places.sqlite-shm
[task 2021-11-17T02:09:20.566Z] 02:09:20     INFO -   C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\places.sqlite - ignoreIfUnused: true, fsync: 2, read: 4, stat: 3, write: 1320, listedPath: ProfD:places.sqlite
[task 2021-11-17T02:09:20.567Z] 02:09:20     INFO -   C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\favicons.sqlite-journal - ignoreIfUnused: true, fsync: 2, stat: 7, read: 2, write: 7, listedPath: ProfD:favicons.sqlite-journal
[task 2021-11-17T02:09:20.567Z] 02:09:20     INFO -   C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\favicons.sqlite-wal - ignoreIfUnused: true, fsync: 2, stat: 7, read: 7, write: 15, listedPath: ProfD:favicons.sqlite-wal
[task 2021-11-17T02:09:20.567Z] 02:09:20     INFO -   C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\favicons.sqlite-shm - condition: true, ignoreIfUnused: true, stat: 2, listedPath: ProfD:favicons.sqlite-shm
[task 2021-11-17T02:09:20.567Z] 02:09:20     INFO -   C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\favicons.sqlite - ignoreIfUnused: true, fsync: 3, read: 8, stat: 4, write: 1300, listedPath: ProfD:favicons.sqlite
[task 2021-11-17T02:09:20.567Z] 02:09:20     INFO -   C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\key4.db-journal - condition: true, canonicalize: true, stat: 2, listedPath: ProfD:key4.db-journal
[task 2021-11-17T02:09:20.567Z] 02:09:20     INFO -   C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\key4.db-wal - condition: true, canonicalize: true, stat: 2, listedPath: ProfD:key4.db-wal
[task 2021-11-17T02:09:20.567Z] 02:09:20     INFO -   C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner - condition: true, ignoreIfUnused: true, stat: 3, listedPath: ProfD:
[task 2021-11-17T02:09:20.568Z] 02:09:20     INFO - (PoisonIOInterposer) stat - C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\key4.db-journal
[task 2021-11-17T02:09:20.568Z] 02:09:20     INFO - Buffered messages finished
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected read on C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\key4.db before becoming idle - 
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO - Stack trace:
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   nsIPK11TokenDB.getInternalKeyToken
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   init (resource://gre/modules/crypto-SDR.js:51:6)
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   LoginManagerCrypto_SDR (resource://gre/modules/crypto-SDR.js:16:31)
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   GetServiceByContractID @mozilla.org/login-manager/crypto/SDR;1
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   get _crypto (resource://gre/modules/storage-json.js:55:13)
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   initialize (resource://gre/modules/storage-json.js:81:12)
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   XPCWrappedJS method call
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   nsILoginManagerStorage.initialize
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   _initStorage (resource://gre/modules/LoginManager.jsm:93:14)
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   init (resource://gre/modules/LoginManager.jsm:80:6)
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   LoginManager (resource://gre/modules/LoginManager.jsm:42:21)
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   Services_Resolve logins
[task 2021-11-17T02:09:20.571Z] 02:09:20     INFO -   task (resource:///modules/BrowserGlue.jsm:2424:14)
[task 2021-11-17T02:09:20.572Z] 02:09:20     INFO -   _scheduleStartupIdleTasks/< (resource:///modules/BrowserGlue.jsm:2743:8)
[task 2021-11-17T02:09:20.572Z] 02:09:20     INFO -   ChromeUtils::IdleDispatch handler
[task 2021-11-17T02:09:20.572Z] 02:09:20     INFO -   Task ChromeUtils::IdleDispatch
[task 2021-11-17T02:09:20.572Z] 02:09:20     INFO -   XREMain::XRE_main
[task 2021-11-17T02:09:20.572Z] 02:09:20     INFO - (PoisonIOInterposer) read - C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\key4.db
[task 2021-11-17T02:09:20.573Z] 02:09:20     INFO - (PoisonIOInterposer) stat - C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\key4.db-wal
[task 2021-11-17T02:09:20.574Z] 02:09:20     INFO - (PoisonIOInterposer) stat - C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\key4.db-journal
[task 2021-11-17T02:09:20.574Z] 02:09:20     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-11-17T02:09:20.575Z] 02:09:20     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected read on C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\key4.db before becoming idle - 
[task 2021-11-17T02:09:20.575Z] 02:09:20     INFO - Stack trace:
[task 2021-11-17T02:09:20.575Z] 02:09:20     INFO -   nsIPK11TokenDB.getInternalKeyToken
[task 2021-11-17T02:09:20.575Z] 02:09:20     INFO -   isMasterPasswordSet (resource://gre/modules/LoginHelper.jsm:1573:21)
<...>
task 2021-11-17T02:09:20.599Z] 02:09:20     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\key4.db-journal as many times as expected before becoming idle - 
[task 2021-11-17T02:09:20.599Z] 02:09:20     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner\key4.db-wal as many times as expected before becoming idle - 
[task 2021-11-17T02:09:20.600Z] 02:09:20     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on C:\Users\task_163711225166691\AppData\Local\Temp\tmp8mp8jwp0.mozrunner allowed 3 more times before becoming idle - 
[task 2021-11-17T02:09:20.601Z] 02:09:20     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-11-17T02:09:20.602Z] 02:09:20     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 2021-11-17T02:09:20.602Z] 02:09:20     INFO - Stack trace:
[task 2021-11-17T02:09:20.602Z] 02:09:20     INFO - chrome://mochikit/content/browser-test.js:test_ok:1336
[task 2021-11-17T02:09:20.602Z] 02:09:20     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_mainthreadio.js:null:875
[task 2021-11-17T02:09:20.602Z] 02:09:20     INFO - Leaving test bound 
[task 2021-11-17T02:09:20.603Z] 02:09:20     INFO - GECKO(8144) | MEMORY STAT | vsize 2104208MB | vsizeMaxContiguous 71233027MB | residentFast 301MB | heapAllocated 135MB
[task 2021-11-17T02:09:20.603Z] 02:09:20     INFO - TEST-OK | browser/base/content/test/performance/browser_startup_mainthreadio.js | took 215ms
[task 2021-11-17T02:09:20.603Z] 02:09:20     INFO - checking window state
[task 2021-11-17T02:09:20.604Z] 02:09:20     INFO - TEST-START | browser/base/content/test/performance/browser_startup_syncIPC.js

Comment 1

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

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

Comment 2

[Intermittent Failures Robot]

1 failures in 3259 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-2004-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1741538&startday=2021-11-15&endday=2021-11-21&tree=all

Comment 3

[Intermittent Failures Robot]

1 failures in 2819 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1741538&startday=2021-11-22&endday=2021-11-28&tree=all

Comment 4

[Intermittent Failures Robot]

1 failures in 3319 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-2004-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1741538&startday=2021-12-06&endday=2021-12-12&tree=all

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1741538&startday=2021-12-27&endday=2022-01-02&tree=all

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 2
• autoland: 1

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 1
  • opt: 1
• windows10-64-2004-ccov-qr: 1
  • opt: 1
• windows10-64-2004-qr: 1
  • opt: 1

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

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows10-64-2004-qr: 1
  • opt: 1
• windows10-64-2004-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1741538&startday=2022-01-17&endday=2022-01-23&tree=all

Comment 8

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

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

Comment 9

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=368943042&repo=autoland

Comment 10

[Atila Butkovits]

Started failing on t1 jobs: https://treeherder.mozilla.org/logviewer?job_id=369330442&repo=autoland&lineNumber=2625

Comment 11

[Intermittent Failures Robot]

17 failures in 2992 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 14
• mozilla-central: 3

Platform and build breakdown:

• windows10-64-2004-qr: 14
  • opt: 14
• windows10-64-2004-shippable-qr: 2
  • opt: 2
• windows10-64-2004-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1741538&startday=2022-02-21&endday=2022-02-27&tree=all

Comment 12

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

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

Comment 13

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=384440158&repo=autoland

Comment 14

[Intermittent Failures Robot]

1 failures in 3341 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-2004-qr: 1
  • opt: 1

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

Comment 15

[Intermittent Failures Robot]

1 failures in 3497 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-2004-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1741538&startday=2022-07-18&endday=2022-07-24&tree=all