Closed Bug 1677873 Opened 5 years ago Closed 5 years ago

Intermittent browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected write on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/places.sqlite-journal before handling user events -

Categories

(Toolkit :: Places, defect, P5)

Product:
Toolkit
Component:
Places
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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

...
[task 2020-11-17T22:52:06.076Z] 22:52:06     INFO - known main thread IO paths during before first paint:
[task 2020-11-17T22:52:06.076Z] 22:52:06     INFO -   /Users/cltbld/tasks/task_1605653336/build/application/Firefox Nightly.app/Contents/Resources/browser/features/formautofill@mozilla.org.xpi - condition: true, stat: 1, close: 1, listedPath: XREAppFeat:formautofill@mozilla.org.xpi
[task 2020-11-17T22:52:06.076Z] 22:52:06     INFO -   /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/xulstore/data.mdb - condition: true, write: 3, listedPath: ProfD:xulstore/data.mdb
[task 2020-11-17T22:52:06.076Z] 22:52:06     INFO -   /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/d3d11layers.guard - ignoreIfUnused: true, stat: 1, listedPath: ProfD:d3d11layers.guard
[task 2020-11-17T22:52:06.076Z] 22:52:06     INFO -   /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/d3d9video.guard - ignoreIfUnused: true, stat: 1, listedPath: ProfD:d3d9video.guard
[task 2020-11-17T22:52:06.076Z] 22:52:06     INFO -   /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/glcontext.guard - ignoreIfUnused: true, stat: 1, listedPath: ProfD:glcontext.guard
[task 2020-11-17T22:52:06.076Z] 22:52:06     INFO -   /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/d3d11video.guard - ignoreIfUnused: true, stat: 1, listedPath: ProfD:d3d11video.guard
[task 2020-11-17T22:52:06.076Z] 22:52:06     INFO -   /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/wmfvpxvideo.guard - ignoreIfUnused: true, stat: 1, listedPath: ProfD:wmfvpxvideo.guard
[task 2020-11-17T22:52:06.077Z] 22:52:06     INFO - (NSPRIOInterposer) stat - /Users/cltbld/tasks/task_1605653336/build/application/Firefox Nightly.app/Contents/Resources/browser/features/formautofill@mozilla.org.xpi
[task 2020-11-17T22:52:06.077Z] 22:52:06     INFO - (NSPRIOInterposer) close - /Users/cltbld/tasks/task_1605653336/build/application/Firefox Nightly.app/Contents/Resources/browser/features/formautofill@mozilla.org.xpi
[task 2020-11-17T22:52:06.077Z] 22:52:06     INFO - (PoisonIOInterposer) write - /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/xulstore/data.mdb
[task 2020-11-17T22:52:06.077Z] 22:52:06     INFO - (PoisonIOInterposer) write - /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/xulstore/data.mdb
[task 2020-11-17T22:52:06.077Z] 22:52:06     INFO - (PoisonIOInterposer) write - /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/xulstore/data.mdb
[task 2020-11-17T22:52:06.078Z] 22:52:06     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /Users/cltbld/tasks/task_1605653336/build/application/Firefox Nightly.app/Contents/Resources/browser/features/formautofill@mozilla.org.xpi as many times as expected before first paint - 
[task 2020-11-17T22:52:06.078Z] 22:52:06     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on /Users/cltbld/tasks/task_1605653336/build/application/Firefox Nightly.app/Contents/Resources/browser/features/formautofill@mozilla.org.xpi as many times as expected before first paint - 
[task 2020-11-17T22:52:06.078Z] 22:52:06     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | write on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/xulstore/data.mdb as many times as expected before first paint - 
[task 2020-11-17T22:52:06.078Z] 22:52:06     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/d3d11layers.guard allowed 1 more times before first paint - 
[task 2020-11-17T22:52:06.078Z] 22:52:06     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/d3d9video.guard allowed 1 more times before first paint - 
[task 2020-11-17T22:52:06.078Z] 22:52:06     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/glcontext.guard allowed 1 more times before first paint - 
[task 2020-11-17T22:52:06.078Z] 22:52:06     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/d3d11video.guard allowed 1 more times before first paint - 
[task 2020-11-17T22:52:06.079Z] 22:52:06     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/wmfvpxvideo.guard allowed 1 more times before first paint - 
[task 2020-11-17T22:52:06.079Z] 22:52:06     INFO - known main thread IO paths during before handling user events:
[task 2020-11-17T22:52:06.079Z] 22:52:06     INFO -   /Users/cltbld/tasks/task_1605653336/build/application/Firefox Nightly.app/Contents/Resources/browser/features/webcompat-reporter@mozilla.org.xpi - condition: true, ignoreIfUnused: true, stat: 1, close: 1, listedPath: XREAppFeat:webcompat-reporter@mozilla.org.xpi
[task 2020-11-17T22:52:06.079Z] 22:52:06     INFO - Buffered messages finished
[task 2020-11-17T22:52:06.080Z] 22:52:06     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected write on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/places.sqlite-journal before handling user events - 
[task 2020-11-17T22:52:06.080Z] 22:52:06     INFO - Stack trace:
[task 2020-11-17T22:52:06.081Z] 22:52:06     INFO -   Connection::stepStatement /* /builds/worker/checkouts/gecko/toolkit/components/places/Database.cpp */ PRAGMA journal_mode = wal
[task 2020-11-17T22:52:06.081Z] 22:52:06     INFO -   Statement::ExecuteStep
[task 2020-11-17T22:52:06.081Z] 22:52:06     INFO -   get (resource://gre/modules/PlacesUtils.jsm:1973:11)
[task 2020-11-17T22:52:06.081Z] 22:52:06     INFO -   get tagsFolderId (resource://gre/modules/PlacesUtils.jsm:1298:18)
[task 2020-11-17T22:52:06.081Z] 22:52:06     INFO -   telemetry (resource://gre/modules/PlacesDBUtils.jsm:1092:17)
[task 2020-11-17T22:52:06.081Z] 22:52:06     INFO -   PCS_observe/< (resource://gre/modules/PlacesCategoriesStarter.jsm:47:45)
[task 2020-11-17T22:52:06.081Z] 22:52:06     INFO -   XPCWrappedJS method call
[task 2020-11-17T22:52:06.081Z] 22:52:06     INFO -   nsAppShell::ProcessGeckoEvents
[task 2020-11-17T22:52:06.081Z] 22:52:06     INFO -   -[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]
[task 2020-11-17T22:52:06.081Z] 22:52:06     INFO -   XREMain::XRE_main
[task 2020-11-17T22:52:06.081Z] 22:52:06     INFO - (PoisonIOInterposer) write - /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/places.sqlite-journal
[task 2020-11-17T22:52:06.082Z] 22:52:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-17T22:52:06.082Z] 22:52:06     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected write on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/places.sqlite-journal before handling user events - 
[task 2020-11-17T22:52:06.082Z] 22:52:06     INFO - Stack trace:
[task 2020-11-17T22:52:06.082Z] 22:52:06     INFO -   get (resource://gre/modules/PlacesUtils.jsm:1973:11)
[task 2020-11-17T22:52:06.082Z] 22:52:06     INFO -   get tagsFolderId (resource://gre/modules/PlacesUtils.jsm:1298:18)
[task 2020-11-17T22:52:06.082Z] 22:52:06     INFO -   telemetry (resource://gre/modules/PlacesDBUtils.jsm:1092:17)
[task 2020-11-17T22:52:06.082Z] 22:52:06     INFO -   PCS_observe/< (resource://gre/modules/PlacesCategoriesStarter.jsm:47:45)
[task 2020-11-17T22:52:06.082Z] 22:52:06     INFO -   XPCWrappedJS method call
[task 2020-11-17T22:52:06.082Z] 22:52:06     INFO -   nsAppShell::ProcessGeckoEvents
[task 2020-11-17T22:52:06.082Z] 22:52:06     INFO -   -[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]
[task 2020-11-17T22:52:06.082Z] 22:52:06     INFO -   XREMain::XRE_main
[task 2020-11-17T22:52:06.087Z] 22:52:06     INFO - (PoisonIOInterposer) write - /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/places.sqlite-journal
[task 2020-11-17T22:52:06.087Z] 22:52:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-17T22:52:06.087Z] 22:52:06     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected write on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/places.sqlite before handling user events - 
[task 2020-11-17T22:52:06.087Z] 22:52:06     INFO - Stack trace:
[task 2020-11-17T22:52:06.087Z] 22:52:06     INFO -   get (resource://gre/modules/PlacesUtils.jsm:1973:11)
[task 2020-11-17T22:52:06.087Z] 22:52:06     INFO -   get tagsFolderId (resource://gre/modules/PlacesUtils.jsm:1298:18)
[task 2020-11-17T22:52:06.088Z] 22:52:06     INFO -   telemetry (resource://gre/modules/PlacesDBUtils.jsm:1092:17)
[task 2020-11-17T22:52:06.088Z] 22:52:06     INFO -   PCS_observe/< (resource://gre/modules/PlacesCategoriesStarter.jsm:47:45)
[task 2020-11-17T22:52:06.088Z] 22:52:06     INFO -   XPCWrappedJS method call
[task 2020-11-17T22:52:06.088Z] 22:52:06     INFO -   nsAppShell::ProcessGeckoEvents
[task 2020-11-17T22:52:06.088Z] 22:52:06     INFO -   -[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]
[task 2020-11-17T22:52:06.088Z] 22:52:06     INFO -   XREMain::XRE_main
[task 2020-11-17T22:52:06.088Z] 22:52:06     INFO - (PoisonIOInterposer) write - /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/places.sqlite
[task 2020-11-17T22:52:06.088Z] 22:52:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-17T22:52:06.089Z] 22:52:06     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected write on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/favicons.sqlite-journal before handling user events - 
[task 2020-11-17T22:52:06.089Z] 22:52:06     INFO - Stack trace:
[task 2020-11-17T22:52:06.089Z] 22:52:06     INFO -   Connection::executeSql PRAGMA auto_vacuum = INCREMENTAL
[task 2020-11-17T22:52:06.089Z] 22:52:06     INFO -   get (resource://gre/modules/PlacesUtils.jsm:1973:11)
[task 2020-11-17T22:52:06.089Z] 22:52:06     INFO -   get tagsFolderId (resource://gre/modules/PlacesUtils.jsm:1298:18)
[task 2020-11-17T22:52:06.089Z] 22:52:06     INFO -   telemetry (resource://gre/modules/PlacesDBUtils.jsm:1092:17)
[task 2020-11-17T22:52:06.089Z] 22:52:06     INFO -   PCS_observe/< (resource://gre/modules/PlacesCategoriesStarter.jsm:47:45)
[task 2020-11-17T22:52:06.089Z] 22:52:06     INFO -   XPCWrappedJS method call
[task 2020-11-17T22:52:06.089Z] 22:52:06     INFO -   nsAppShell::ProcessGeckoEvents
[task 2020-11-17T22:52:06.089Z] 22:52:06     INFO -   -[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]
[task 2020-11-17T22:52:06.089Z] 22:52:06     INFO -   XREMain::XRE_main
[task 2020-11-17T22:52:06.089Z] 22:52:06     INFO - (PoisonIOInterposer) write - /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/favicons.sqlite-journal
[task 2020-11-17T22:52:06.090Z] 22:52:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-17T22:52:06.090Z] 22:52:06     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected write on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/favicons.sqlite-journal before handling user events - 
[task 2020-11-17T22:52:06.090Z] 22:52:06     INFO - Stack trace:
[task 2020-11-17T22:52:06.090Z] 22:52:06     INFO -   Connection::executeSql PRAGMA auto_vacuum = INCREMENTAL
[task 2020-11-17T22:52:06.090Z] 22:52:06     INFO -   get (resource://gre/modules/PlacesUtils.jsm:1973:11)
[task 2020-11-17T22:52:06.090Z] 22:52:06     INFO -   get tagsFolderId (resource://gre/modules/PlacesUtils.jsm:1298:18)
[task 2020-11-17T22:52:06.090Z] 22:52:06     INFO -   telemetry (resource://gre/modules/PlacesDBUtils.jsm:1092:17)
[task 2020-11-17T22:52:06.090Z] 22:52:06     INFO -   PCS_observe/< (resource://gre/modules/PlacesCategoriesStarter.jsm:47:45)
[task 2020-11-17T22:52:06.090Z] 22:52:06     INFO -   XPCWrappedJS method call
[task 2020-11-17T22:52:06.090Z] 22:52:06     INFO -   nsAppShell::ProcessGeckoEvents
[task 2020-11-17T22:52:06.090Z] 22:52:06     INFO -   -[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]
[task 2020-11-17T22:52:06.090Z] 22:52:06     INFO -   XREMain::XRE_main
[task 2020-11-17T22:52:06.091Z] 22:52:06     INFO - (PoisonIOInterposer) write - /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/favicons.sqlite-journal
[task 2020-11-17T22:52:06.091Z] 22:52:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-17T22:52:06.091Z] 22:52:06     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected write on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/favicons.sqlite before handling user events - 
[task 2020-11-17T22:52:06.091Z] 22:52:06     INFO - Stack trace:
[task 2020-11-17T22:52:06.091Z] 22:52:06     INFO -   Connection::executeSql PRAGMA auto_vacuum = INCREMENTAL
[task 2020-11-17T22:52:06.091Z] 22:52:06     INFO -   get (resource://gre/modules/PlacesUtils.jsm:1973:11)
[task 2020-11-17T22:52:06.091Z] 22:52:06     INFO -   get tagsFolderId (resource://gre/modules/PlacesUtils.jsm:1298:18)
[task 2020-11-17T22:52:06.091Z] 22:52:06     INFO -   telemetry (resource://gre/modules/PlacesDBUtils.jsm:1092:17)
[task 2020-11-17T22:52:06.092Z] 22:52:06     INFO -   PCS_observe/< (resource://gre/modules/PlacesCategoriesStarter.jsm:47:45)
[task 2020-11-17T22:52:06.092Z] 22:52:06     INFO -   XPCWrappedJS method call
[task 2020-11-17T22:52:06.092Z] 22:52:06     INFO -   nsAppShell::ProcessGeckoEvents
[task 2020-11-17T22:52:06.092Z] 22:52:06     INFO -   -[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]
[task 2020-11-17T22:52:06.092Z] 22:52:06     INFO -   XREMain::XRE_main
[task 2020-11-17T22:52:06.092Z] 22:52:06     INFO - (PoisonIOInterposer) write - /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/favicons.sqlite
[task 2020-11-17T22:52:06.092Z] 22:52:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-17T22:52:06.092Z] 22:52:06     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected write on /private/var/folders/h0/h6p091850555b46cxzkwr27m000017/T/tmpllmQMm.mozrunner/favicons.sqlite-journal before handling user events - 
[task 2020-11-17T22:52:06.092Z] 22:52:06     INFO - Stack trace:
...```

Bugbug thinks this bug should belong to this component, but please revert this change in case of error.

Component: General → Places
Product: Firefox → Toolkit

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

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