Closed Bug 1649590 Opened 11 months ago Closed 4 months ago

XPIProvider.jsm imports OS.File during startup

Categories

(Toolkit :: OS.File, task)

Product:
Toolkit
Component:
OS.File
Type:
task

Tracking

()

Status:
RESOLVED FIXED
Milestone:
87 Branch
Tracking Flags:
Tracking Status
firefox87 --- fixed

People

(Reporter: barret, Assigned: michelle)

References

(Blocks 2 open bugs, Regressed 1 open bug)

Details

(Keywords: perf-alert)

Attachments

(1 file)

Bug 1649590 - Convert XPIProvider.jsm to use IOUtils r=emalysz
47 bytes, text/x-phabricator-request
Details | Review

According to this startup profile, XPIProvider.jsm runs during startup and imports osfile.jsm. We should migrate this to the new IOUtils replacement for osfile.jsm when possible.

Stack:

(root) []
XREMain::XRE_main []
XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) [libxul.so]
XREMain::XRE_mainRun() [libxul.so]
nsXREDirProvider::DoStartup() [libxul.so]
SharedStub [libxul.so]
PrepareAndDispatch [libxul.so]
XPCWrappedJS method call []
nsXPCWrappedJS::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) [libxul.so]
JS_CallFunctionValue(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) [libxul.so]
js::RunScript []
observe [resource://gre/modules/addonManager.js:84:9]
startup [resource://gre/modules/AddonManager.jsm:3461:9]
startup [resource://gre/modules/AddonManager.jsm:638:9]
_startProvider [resource://gre/modules/AddonManager.jsm:574:16]
callProvider [resource://gre/modules/AddonManager.jsm:206:21]
js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [libxul.so]
Interpret(JSContext*, js::RunState&) [libxul.so]
js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [libxul.so]
js::fun_apply(JSContext*, unsigned int, JS::Value*) [libxul.so]
js::RunScript []
startup [resource://gre/modules/addons/XPIProvider.jsm:2424:9]
js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [libxul.so]
Interpret(JSContext*, js::RunState&) [libxul.so]
setupInstallLocations [resource://gre/modules/addons/XPIProvider.jsm:2221:23]
0xff4eaa5dcb3 []
js::jit::DoSpreadCallFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICCall_Fallback*, JS::Value*, JS::MutableHandle<JS::Value>) [libxul.so]
js::SpreadCallOperation(JSContext*, JS::Handle<JSScript*>, unsigned char*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>) [libxul.so]
js::RunScript []
DirectoryLoc [resource://gre/modules/addons/XPIProvider.jsm:2222:25]
DirectoryLocation [resource://gre/modules/addons/XPIProvider.jsm:996:13]
> XPIStateLocation [resource://gre/modules/addons/XPIProvider.jsm:676:13]
js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [libxul.so]
Interpret(JSContext*, js::RunState&) [libxul.so]
js::NativeGetExistingProperty(JSContext*, JS::Handle<JSObject*>, JS::Handle<js::NativeObject*>, JS::Handle<js::Shape*>, JS::MutableHandle<JS::Value>) [libxul.so]
js::CallGetter(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>) [libxul.so]
js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [libxul.so]
mozilla::dom::module_getter::ModuleGetter(JSContext*, unsigned int, JS::Value*) [libxul.so]
mozJSComponentLoader::Import(JSContext*, nsTSubstring<char> const&, JS::MutableHandle<JSObject*>, JS::MutableHandle<JSObject*>, bool) [libxul.so]
profiler_get_backtrace() [libxul.so]
Registers::SyncPopulate() [libxul.so]
No longer depends on: 1649589

There's one usage of OS.File in XPIProvider.jsm here.

This particular usage is concerning to me because:

  • This is a side effect in a constructor
  • This is async code in a constructor which isn't thend or awaited on

I could replace the call to OS.File.mkDir with IOUtils.makeDirectory and leave the potentially uncaught promise exception, but refactoring this code to avoid this behaviour in the first place would be better (thought quite honestly, I'm a bit out of my depth trying to understand it).

Hey Kris, I was wondering if I could get some context about the XPIStateLocation ctor in question here. Right now this constructor is firing a promise off into the void and hoping it completes in time — otherwise, supposing the path doesn't exist by the time its required, an exception will be thrown elsewhere.

Since this code isn't broken, my current plan is to drop in replace OS.File.makeDir with a call to IOUtils.makeDirectory, and add a .catch for the returned promise that will log a warning if it fails. Is that ok?

It might be worth refactoring later though.

Flags: needinfo?(kmaglione+bmo)

That's fine.

Flags: needinfo?(kmaglione+bmo)
Depends on: 1671035
Depends on: 1674311
Assignee: nobody → michael
Status: NEW → ASSIGNED
Pushed by emalysz@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/3d61ae105362
Convert XPIProvider.jsm to use IOUtils r=emalysz,mixedpuppy
Backout by btara@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/f8d523ae0c5c
Backed out changeset 3d61ae105362 for browser_startup_mainthreadio & mRawPtr assertion failures CLOSED TREE

Backed out changeset 3d61ae105362 (bug 1649590) for browser_startup_mainthreadio failures.

Push with failures: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&fromchange=0a8c4664555a78bc5d44f1bc14db59ea175f3751&searchStr=windows%2C7%2Copt%2Cmochitests%2Ctest-windows7-32%2Fopt-mochitest-browser-chrome-e10s%2Cbc2&tochange=1e2b1c9b9c9e9283c22055cb5dfd003a061b878e&selectedTaskRun=N4mKwQLSQea74fCzAscCEQ.0

Backout link: https://hg.mozilla.org/integration/autoland/rev/f8d523ae0c5c8b6dd4b7be94149584a5c35292b7

Failure log: https://treeherder.mozilla.org/logviewer?job_id=322134985&repo=autoland&lineNumber=1830

...
[task 2020-11-18T02:34:55.565Z] 02:34:55     INFO - (PoisonIOInterposer) read - C:\Users\task_1605665346\AppData\Local\Temp\tmpcjk_gu.mozrunner\xulstore\data.mdb
[task 2020-11-18T02:34:55.565Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on C:\Users\task_1605665346\AppData\Local\Temp\tmpcjk_gu.mozrunner as many times as expected before opening first browser window - 
[task 2020-11-18T02:34:55.565Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on C:\Users\task_1605665346\AppData\Local\Temp\tmpcjk_gu.mozrunner\cookies.sqlite-journal as many times as expected before opening first browser window - 
[task 2020-11-18T02:34:55.566Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | write on C:\Users\task_1605665346\AppData\Local\Temp\tmpcjk_gu.mozrunner\cookies.sqlite-journal as many times as expected before opening first browser window - 
[task 2020-11-18T02:34:55.566Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on C:\Users\task_1605665346\AppData\Local\Temp\tmpcjk_gu.mozrunner\cookies.sqlite as many times as expected before opening first browser window - 
[task 2020-11-18T02:34:55.566Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | read on C:\Users\task_1605665346\AppData\Local\Temp\tmpcjk_gu.mozrunner\cookies.sqlite as many times as expected before opening first browser window - 
[task 2020-11-18T02:34:55.566Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | write on C:\Users\task_1605665346\AppData\Local\Temp\tmpcjk_gu.mozrunner\cookies.sqlite as many times as expected before opening first browser window - 
[task 2020-11-18T02:34:55.569Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on C:\Users\task_1605665346\AppData\Local\Temp\tmpcjk_gu.mozrunner\cookies.sqlite-wal as many times as expected before opening first browser window - 
[task 2020-11-18T02:34:55.569Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on C:\Users\task_1605665346\AppData\Local\Temp\tmpcjk_gu.mozrunner\extensions allowed 1 more times before opening first browser window - 
[task 2020-11-18T02:34:55.570Z] 02:34:55     INFO - Buffered messages finished
[task 2020-11-18T02:34:55.570Z] 02:34:55     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | no main thread IO when we expected some during before opening first browser window: C:\Users\task_1605665346\AppData\Local\Temp\tmpcjk_gu.mozrunner\extensions (ProfD:extensions) - 
[task 2020-11-18T02:34:55.570Z] 02:34:55     INFO - Stack trace:
[task 2020-11-18T02:34:55.570Z] 02:34:55     INFO - chrome://mochikit/content/browser-test.js:test_ok:1304
[task 2020-11-18T02:34:55.570Z] 02:34:55     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_mainthreadio.js:null:881
[task 2020-11-18T02:34:55.570Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_1605665346\AppData\Roaming\Mozilla\Firefox allowed 1 more times before opening first browser window - 
[task 2020-11-18T02:34:55.571Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | read on C:\Users\task_1605665346\AppData\Local\Temp\tmpcjk_gu.mozrunner\xulstore\data.mdb as many times as expected before opening first browser window - 
[task 2020-11-18T02:34:55.572Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_1605665346\build\application\firefox\browser\features\doh-rollout@mozilla.org.xpi allowed 1 more times before opening first browser window - 
[task 2020-11-18T02:34:55.573Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on Z:\task_1605665346\build\application\firefox\browser\features\doh-rollout@mozilla.org.xpi allowed 2 more times before opening first browser window - 
[task 2020-11-18T02:34:55.574Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_1605665346\build\application\firefox\browser\features\formautofill@mozilla.org.xpi allowed 1 more times before opening first browser window - 
[task 2020-11-18T02:34:55.574Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on Z:\task_1605665346\build\application\firefox\browser\features\formautofill@mozilla.org.xpi allowed 2 more times before opening first browser window - 
[task 2020-11-18T02:34:55.575Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_1605665346\build\application\firefox\browser\features\screenshots@mozilla.org.xpi allowed 1 more times before opening first browser window - 
[task 2020-11-18T02:34:55.576Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on Z:\task_1605665346\build\application\firefox\browser\features\screenshots@mozilla.org.xpi allowed 2 more times before opening first browser window - 
[task 2020-11-18T02:34:55.577Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_1605665346\build\application\firefox\browser\features\webcompat-reporter@mozilla.org.xpi allowed 1 more times before opening first browser window - 
[task 2020-11-18T02:34:55.577Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on Z:\task_1605665346\build\application\firefox\browser\features\webcompat-reporter@mozilla.org.xpi allowed 2 more times before opening first browser window - 
[task 2020-11-18T02:34:55.577Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_1605665346\build\application\firefox\browser\features\webcompat@mozilla.org.xpi allowed 1 more times before opening first browser window - 
[task 2020-11-18T02:34:55.578Z] 02:34:55     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on Z:\task_1605665346\build\application\firefox\browser\features\webcompat@mozilla.org.xpi allowed 2 more times before opening first browser window - 
[task 2020-11-18T02:34:55.581Z] 02:34:55     INFO - known main thread IO paths during before first paint:
[task 2020-11-18T02:34:55.581Z] 02:34:55     INFO -   Z:\task_1605665346\AppData\Local\Mozilla\updates\AF27AA334654FCD0 - condition: true, stat: 1, listedPath: OldUpdRootD:
[task 2020-11-18T02:34:55.581Z] 02:34:55     INFO -   C:\ProgramData\Mozilla\updates\AF27AA334654FCD0\updates\0\update.status - condition: true, stat: 1, listedPath: UpdRootD:updates/0/update.status
[task 2020-11-18T02:34:55.581Z] 02:34:55     INFO -   Z:\task_1605665346\AppData\Roaming\Mozilla - condition: true, stat: 1, listedPath: UserPlugins.parent:
[task 2020-11-18T02:34:55.581Z] 02:34:55     INFO -   Z:\task_1605665346\build\application\firefox\distribution\distribution.ini - condition: true, stat: 1, listedPath: XREAppDist:distribution.ini
[task 2020-11-18T02:34:55.581Z] 02:34:55     INFO -   *Fonts\StaticCache.dat - condition: true, ignoreIfUnused: true, read: 1, listedPath: *Fonts/StaticCache.dat
[task 2020-11-18T02:34:55.582Z] 02:34:55     INFO -   C:\windows\system32\spool\drivers\color\* - condition: true, read: 1, listedPath: SysD:spool/drivers/color/*
[task 2020-11-18T02:34:55.582Z] 02:34:55     INFO -   Z:\task_1605665346\AppData\Roaming\Mozilla\Firefox - ignoreIfUnused: true, condition: true, stat: 1, listedPath: UAppData:
...
Flags: needinfo?(michael)

Been working on the issue with mixedpuppy. Hopefully the new revision fixes it.

Flags: needinfo?(michael)
Pushed by scaraveo@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/cd968a980827
Convert XPIProvider.jsm to use IOUtils r=emalysz,mixedpuppy

https://hg.mozilla.org/mozilla-central/rev/cd968a980827

Status: ASSIGNED → RESOLVED
Closed: 6 months ago
status-firefox85: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 85 Branch

(In reply to Pulsebot from comment #5)

Pushed by emalysz@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/3d61ae105362
Convert XPIProvider.jsm to use IOUtils r=emalysz,mixedpuppy

== Change summary for alert #27823 (as of Mon, 23 Nov 2020 12:11:00 GMT) ==

Regressions:

Ratio Suite Test Platform Options Absolute values (old vs new)
10% ts_paint_webext ts_paint_webext windows10-64-shippable-qr e10s stylo webrender-sw 380.63 -> 418.08
6% ts_paint_webext ts_paint_webext windows10-64-shippable-qr e10s stylo webrender-sw 400.25 -> 423.92

For up to date results, see: https://treeherder.mozilla.org/perfherder/alerts?id=27823

(In reply to Bogdan Tara[:bogdan_tara | bogdant] from comment #7)

Backed out changeset 3d61ae105362 (bug 1649590) for browser_startup_mainthreadio failures.

Push with failures: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&fromchange=0a8c4664555a78bc5d44f1bc14db59ea175f3751&searchStr=windows%2C7%2Copt%2Cmochitests%2Ctest-windows7-32%2Fopt-mochitest-browser-chrome-e10s%2Cbc2&tochange=1e2b1c9b9c9e9283c22055cb5dfd003a061b878e&selectedTaskRun=N4mKwQLSQea74fCzAscCEQ.0

Backout link: https://hg.mozilla.org/integration/autoland/rev/f8d523ae0c5c8b6dd4b7be94149584a5c35292b7

== Change summary for alert #27824 (as of Mon, 23 Nov 2020 12:15:10 GMT) ==

Improvements:

Ratio Suite Test Platform Options Absolute values (old vs new)
7% ts_paint_webext ts_paint_webext windows10-64-shippable-qr e10s stylo webrender-sw 406.33 -> 379.42

For up to date results, see: https://treeherder.mozilla.org/perfherder/alerts?id=27824

Backed out for causing Bug 1679252

backout: https://hg.mozilla.org/integration/autoland/rev/a60fbae9e78163ee36e0c89efe704e22eebd3d72

Status: RESOLVED → REOPENED
status-firefox85: fixed → ---
Resolution: FIXED → ---
Target Milestone: 85 Branch → ---

(In reply to Natalia Csoregi [:nataliaCs] from comment #13)

Backed out for causing Bug 1679252

backout: https://hg.mozilla.org/integration/autoland/rev/a60fbae9e78163ee36e0c89efe704e22eebd3d72

== Change summary for alert #27886 (as of Sun, 29 Nov 2020 15:23:41 GMT) ==

Regressions:

Ratio Suite Test Platform Options Absolute values (old vs new)
16% ts_paint_webext ts_paint_webext linux64-shippable-qr e10s stylo webrender-sw 200.67 -> 232.42
15% ts_paint ts_paint linux64-shippable-qr e10s stylo webrender-sw 201.75 -> 232.75
13% ts_paint_webext ts_paint_webext linux64-shippable-qr e10s stylo webrender 219.17 -> 248.67
12% ts_paint ts_paint linux64-shippable-qr e10s stylo webrender 217.71 -> 243.92
4% startup_about_home_paint_realworld_webextensions startup_about_home_paint_realworld_webextensions linux64-shippable e10s stylo 555.50 -> 575.17

Improvements:

Ratio Suite Test Platform Options Absolute values (old vs new)
2% startup_about_home_paint_realworld_webextensions startup_about_home_paint_realworld_webextensions linux64-shippable-qr e10s stylo webrender 858.46 -> 840.25

For up to date results, see: https://treeherder.mozilla.org/perfherder/alerts?id=27886

Pushed by emalysz@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ee49da8ea890
Convert XPIProvider.jsm to use IOUtils r=emalysz,mixedpuppy,barret,gcp

Backed out for failures on browser_content_sandbox_fs.js

backout: https://hg.mozilla.org/integration/autoland/rev/642b19199dd4808ae90394b36ebeafd2d2a503d9

push: https://treeherder.mozilla.org/jobs?repo=autoland&selectedTaskRun=Ng4g0aLaSBqAs5une87w1A.0&searchStr=linux%2C18.04%2Cx64%2Cdebug%2Cmochitests%2Cwith%2Cfission%2Cenabled%2Ctest-linux1804-64%2Fdebug-mochitest-browser-chrome-fis-e10s%2Cbc10&revision=ee49da8ea8905e0626245725caa77e2c5fb37726

failure log: https://treeherder.mozilla.org/logviewer?job_id=328946371&repo=autoland&lineNumber=23221

[task 2021-02-05T02:11:49.952Z] 02:11:49 INFO - TEST-PASS | security/sandbox/test/browser_content_sandbox_fs.js | directory list is empty (/proc/self/fd) -
[task 2021-02-05T02:11:49.953Z] 02:11:49 INFO - Buffered messages finished
[task 2021-02-05T02:11:49.954Z] 02:11:49 INFO - TEST-UNEXPECTED-FAIL | security/sandbox/test/browser_content_sandbox_fs.js | reading extensions dir from a web process is allowed (/tmp/tmpjWBLbz.mozrunner/extensions) -
[task 2021-02-05T02:11:49.954Z] 02:11:49 INFO - Stack trace:
[task 2021-02-05T02:11:49.955Z] 02:11:49 INFO - chrome://mochikit/content/browser-test.js:test_ok:1323
[task 2021-02-05T02:11:49.955Z] 02:11:49 INFO - chrome://mochitests/content/browser/security/sandbox/test/browser_content_sandbox_fs.js:testFileAccess:626
[task 2021-02-05T02:11:49.956Z] 02:11:49 INFO - TEST-PASS | security/sandbox/test/browser_content_sandbox_fs.js | reading chrome dir from a web process is allowed (/tmp/tmpjWBLbz.mozrunner/chrome) -
[task 2021-02-05T02:11:49.957Z] 02:11:49 INFO - TEST-PASS | security/sandbox/test/browser_content_sandbox_fs.js | reading cookies file from a web process is blocked (/tmp/tmpjWBLbz.mozrunner/cookies.sqlite) -
[task 2021-02-05T02:11:49.960Z] 02:11:49 INFO - TEST-PASS | security/sandbox/test/browser_content_sandbox_fs.js | reading cookies file from a file process is allowed (/tmp/tmpjWBLbz.mozrunner/cookies.sqlite) -
[task 2021-02-05T02:11:49.961Z] 02:11:49 INFO - Leaving test bound testFileAccess

Flags: needinfo?(michelle)
Pushed by emalysz@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/19d5b4473e9e
Convert XPIProvider.jsm to use IOUtils r=emalysz,mixedpuppy,barret,gcp

https://hg.mozilla.org/mozilla-central/rev/19d5b4473e9e

Status: REOPENED → RESOLVED
Closed: 6 months ago → 4 months ago
status-firefox87: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 87 Branch
Flags: needinfo?(michelle)
Blocks: 1522925
You need to log in before you can comment on or make changes to this bug.