GetUserDataDirectory is called too often and does suboptimal IO

RESOLVED FIXED in Firefox 69

Status

()

defect
P3
normal
RESOLVED FIXED
5 months ago
Last month

People

(Reporter: Gijs, Assigned: mcheang)

Tracking

(Blocks 2 bugs, {main-thread-io, perf})

Trunk
mozilla69
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox68 wontfix, firefox69 fixed)

Details

(Whiteboard: [fxperf:p2] [fxperfsize:S])

Attachments

(1 attachment, 1 obsolete attachment)

There are several problems here...

  1. we call this too often. 3 times on current startup (in the parent process). We should only call it once.
  2. there's some old debugging code for jungshik that we should probably just remove
  3. instead of calling ::Exists() and then ::Create(), we should just call ::Create() and deal with the error we'd get if the directory already exists.

This affects us in multiple places. A bit later in startup, we hit this again with this rather depressing stack:

get currentEnvironment [resource://gre/modules/TelemetryEnvironment.jsm:80:0]
getGlobal [resource://gre/modules/TelemetryEnvironment.jsm:72:0]
EnvironmentCache [resource://gre/modules/TelemetryEnvironment.jsm:907:0]
_getSystem [resource://gre/modules/TelemetryEnvironment.jsm:1808:0]
_getGFXData [resource://gre/modules/TelemetryEnvironment.jsm:1756:0]
getGfxField [resource://gre/modules/TelemetryEnvironment.jsm:406:0]
js::RunScript(JSContext *,js::RunState &) [xul.dll]
static bool Interpret(struct JSContext *, class js::RunState & const) [xul.dll]
js::NativeGetProperty(JSContext *,JS::Handle<js::NativeObject *>,JS::Handle<JS::Value>,JS::Handle<JS::PropertyKey>,JS::MutableHandle<JS::Value>) [xul.dll]
js::CallGetter(JSContext *,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::MutableHandle<JS::Value>) [xul.dll]
js::InternalCallOrConstruct(JSContext *,JS::CallArgs const &,js::MaybeConstruct) [xul.dll]
static bool XPC_WN_GetterSetter(struct JSContext *, unsigned int, union JS::Value *) [xul.dll]
static bool XPCWrappedNative::CallMethod(class XPCCallContext & const, XPCWrappedNative::CallMode) [xul.dll]
XPTC__InvokebyIndex [xul.dll]
nsresult mozilla::widget::GfxInfo::GetDWriteEnabled(bool *) [xul.dll]
gfxPlatform::GetPlatform() [xul.dll]
gfxPlatform::Init() [xul.dll]
mozilla::gfx::GPUProcessManager::LaunchGPUProcess() [xul.dll]
bool mozilla::gfx::GPUProcessHost::Launch(class std::vector<std::basic_string<char,std::char_traits<char>,std::allocator<char> >,std::allocator<std::basic_string<char,std::char_traits<char>,std::allocator<char> > > >) [xul.dll]
mozilla::ipc::GeckoChildProcessHost::AsyncLaunch(std::vector<std::basic_string<char,std::char_traits<char>,std::allocator<char> >,std::allocator<std::basic_string<char,std::char_traits<char>,std::allocator<char> > > >) [xul.dll]
void mozilla::ipc::GeckoChildProcessHost::PrepareLaunch() [xul.dll]
CrashReporter::OOPInit() [xul.dll]
static void CrashReporter::FindPendingDir() [xul.dll]
nsDirectoryService::Get(char const *,nsID const &,void * *) [xul.dll]
static bool FindProviderFile(class nsIDirectoryServiceProvider *, struct FileData *) [xul.dll]
nsXREDirProvider::GetFile(char const *,bool *,nsIFile * *) [xul.dll]
nsXREDirProvider::GetUserDataDirectory(nsIFile * *,bool) [xul.dll]
nsLocalFile::Exists(bool *) [xul.dll]
nsLocalFile::ResolveAndStat []
nsresult nsLocalFile::ResolveAndStat() [xul.dll]
static nsresult GetFileInfo(const class nsTString<char16_t> & const, struct PRFileInfo64 *) [xul.dll]
GetFileAttributesExW [KERNELBASE.dll]

(This is all in the parent process, though I wouldn't be surprised if we hit it again in the child)

Blocks: 1543203
Priority: -- → P3
Whiteboard: [fxperf] → [fxperf:p2]
Whiteboard: [fxperf:p2] → [fxperf:p2] [fxperfsize:S]

So I did some digging to find actual callpaths. These are from mainInit, so super early on startup, we actually seem to hit this twice:

https://searchfox.org/mozilla-central/rev/6c9f60f8cc064a1005cd8141ecd526578ae9da7a/toolkit/xre/nsAppRunner.cpp#3113

https://searchfox.org/mozilla-central/rev/6c9f60f8cc064a1005cd8141ecd526578ae9da7a/toolkit/xre/nsAppRunner.cpp#3163-3164

then twice more from init'ing the profile service:

  * frame #0: 0x00000001059209e1 XUL`nsXREDirProvider::GetUserDataDirectory(aFile=0x000000010182ea50, aLocal=false) at nsXREDirProvider.cpp:1505 [opt]
    frame #1: 0x00000001058cb88b XUL`nsToolkitProfileService::Init() [inlined] nsXREDirProvider::GetUserAppDataDirectory(aFile=<unavailable>) at nsXREDirProvider.h:64 [opt]
    frame #2: 0x00000001058cb881 XUL`nsToolkitProfileService::Init(this=0x000000010182ea00) at nsToolkitProfileService.cpp:697 [opt]
    frame #3: 0x00000001058cf698 XUL`NS_NewToolkitProfileService(aResult=0x00007ffeefbff1e8) at nsToolkitProfileService.cpp:1925 [opt]
    frame #4: 0x0000000105915412 XUL`XREMain::XRE_mainStartup(this=0x00007ffeefbff1e0, aExitFlag=0x00007ffeefbff120) at nsAppRunner.cpp:3872 [opt]
    frame #5: 0x000000010591ad05 XUL`XREMain::XRE_main(this=0x00007ffeefbff1e0, argc=<unavailable>, argv=<unavailable>, aConfig=0x00007ffeefbff350) at nsAppRunner.cpp:4680 [opt]
    frame #6: 0x000000010591b47b XUL`XRE_main(argc=<unavailable>, argv=<unavailable>, aConfig=<unavailable>) at nsAppRunner.cpp:4774 [opt]
    frame #7: 0x000000010000109a firefox`main [inlined] do_main(argc=<unavailable>, argv=<unavailable>, envp=<unavailable>) at nsBrowserApp.cpp:212 [opt]
    frame #8: 0x0000000100001080 firefox`main(argc=<unavailable>, argv=0x00007ffeefbff7a0, envp=0x00007ffeefbff7d0) at nsBrowserApp.cpp:291 [opt]
    frame #9: 0x00007fff7dcf0015 libdyld.dylib`start + 1
  * frame #0: 0x00000001059209e1 XUL`nsXREDirProvider::GetUserDataDirectory(aFile=0x000000010182ea58, aLocal=true) at nsXREDirProvider.cpp:1505 [opt]
    frame #1: 0x00000001058cb8b2 XUL`nsToolkitProfileService::Init() [inlined] nsXREDirProvider::GetUserLocalDataDirectory(aFile=<unavailable>) at nsXREDirProvider.h:67 [opt]
    frame #2: 0x00000001058cb8a5 XUL`nsToolkitProfileService::Init(this=0x000000010182ea00) at nsToolkitProfileService.cpp:700 [opt]
    frame #3: 0x00000001058cf698 XUL`NS_NewToolkitProfileService(aResult=0x00007ffeefbff1e8) at nsToolkitProfileService.cpp:1925 [opt]
    frame #4: 0x0000000105915412 XUL`XREMain::XRE_mainStartup(this=0x00007ffeefbff1e0, aExitFlag=0x00007ffeefbff120) at nsAppRunner.cpp:3872 [opt]
    frame #5: 0x000000010591ad05 XUL`XREMain::XRE_main(this=0x00007ffeefbff1e0, argc=<unavailable>, argv=<unavailable>, aConfig=0x00007ffeefbff350) at nsAppRunner.cpp:4680 [opt]
    frame #6: 0x000000010591b47b XUL`XRE_main(argc=<unavailable>, argv=<unavailable>, aConfig=<unavailable>) at nsAppRunner.cpp:4774 [opt]
    frame #7: 0x000000010000109a firefox`main [inlined] do_main(argc=<unavailable>, argv=<unavailable>, envp=<unavailable>) at nsBrowserApp.cpp:212 [opt]
    frame #8: 0x0000000100001080 firefox`main(argc=<unavailable>, argv=0x00007ffeefbff7a0, envp=0x00007ffeefbff7d0) at nsBrowserApp.cpp:291 [opt]
    frame #9: 0x00007fff7dcf0015 libdyld.dylib`start + 1

Mandy said she was looking at this next; happy to help dig more if that's helpful. :-)

Assignee: nobody → mcheang

Oh, and then OS.File needs this info too so we hit this again... JS stack:

0 lazyPathGetter/<() ["resource://gre/modules/osfile/osfile_async_front.jsm":67:29]
    this = [object Object]
1 _iterateAppDataPings() ["resource://gre/modules/TelemetryStorage.jsm":1437:8]
2 AsyncGeneratorNext(val = undefined) ["self-hosted":850:4]
    this = [object AsyncGenerator]
3 _migrateAppDataPings() ["resource://gre/modules/TelemetryStorage.jsm":1486:4]
    this = [object Object]
4 _scanPendingPings() ["resource://gre/modules/TelemetryStorage.jsm":1535:15]
    this = [object Object]
5 loadPendingPingList() ["resource://gre/modules/TelemetryStorage.jsm":1516:38]
    this = [object Object]
6 loadPendingPingList() ["resource://gre/modules/TelemetryStorage.jsm":290:32]
    this = [object Object]
7 _checkPendingPings() ["resource://gre/modules/TelemetrySend.jsm":715:39]
    this = [object Object]
8 setup(testing = false) ["resource://gre/modules/TelemetrySend.jsm":667:17]
    this = [object Object]
9 setup(testing = undefined) ["resource://gre/modules/TelemetrySend.jsm":190:29]
    this = [object Object]
10 setupTelemetry/this._delayedInitTask<() ["resource://gre/modules/TelemetryController.jsm":692:28]

which then hits:

  * frame #0: 0x00000001059209e1 XUL`nsXREDirProvider::GetUserDataDirectory(aFile=0x00007ffeefbfacf8, aLocal=false) at nsXREDirProvider.cpp:1505 [opt]
    frame #1: 0x0000000105920f7e XUL`nsXREDirProvider::GetFile(char const*, bool*, nsIFile**) [inlined] nsXREDirProvider::GetUserAppDataDirectory(aFile=<unavailable>) at nsXREDirProvider.h:64 [opt]
    frame #2: 0x0000000105920f74 XUL`nsXREDirProvider::GetFile(this=0x00007ffeefbff218, aProperty="UAppData", aPersistent=0x00007ffeefbfadd0, aFile=0x00007ffeefbfadc8) at nsXREDirProvider.cpp:377 [opt]
    frame #3: 0x0000000101ce5b29 XUL`FindProviderFile(aElement=<unavailable>, aData=<unavailable>) at nsDirectoryService.cpp:168 [opt]
    frame #4: 0x0000000101ce510c XUL`nsDirectoryService::Get(this=0x000000010185f6f0, aProp="UAppData", aUuid=<unavailable>, aResult=0x00007ffeefbfaf50) at nsDirectoryService.cpp:198 [opt]
    frame #5: 0x0000000101d3e6ae XUL`NS_InvokeByIndex at xptcinvoke_asm_x86_64_unix.S:106
Attachment #9068018 - Attachment description: Bug 1541226 - Cache GetUserDataDirectory to improve IO performance. r?Gijs!,mconley! → Bug 1541226 - Cache GetUserDataDirectory to improve IO performance
Attachment #9068712 - Attachment is obsolete: true
Pushed by mconley@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/abd13cb2e809
Cache GetUserDataDirectory to improve IO performance r=mconley
Status: NEW → RESOLVED
Closed: 3 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla69
Blocks: 1543096
You need to log in before you can comment on or make changes to this bug.