I was running some xpcshell tests under OS X's fs_usage program and noticed that we seem to call lstat64() multiple times on some imported modules. Here is where we first import XPCOMUtils.jsm (it's a symlink back to /js/xpconnect/loader/XPCOMUtils.jsm): 10:42:16.098129 lstat64 /Users/gps/src/firefox/obj-firefox.noindex/dist/bin/modules/XPCOMUtils.jsm 0.000007 xpcshell.12423142 10:42:16.098131 lstat64 /Users/gps/src/firefox/obj-firefox.noindex/dist/bin/modules/XPCOMUtils.jsm 0.000003 xpcshell.12423142 10:42:16.098134 readlink /Users/gps/src/firefox/obj-firefox.noindex/dist/bin/modules/XPCOMUtils.jsm 0.000003 xpcshell.12423142 10:42:16.098139 lstat64 /Users/gps/src/firefox/js/xpconnect/loader/XPCOMUtils.jsm 0.000005 xpcshell.12423142 10:42:16.098144 stat64 /Users/gps/src/firefox/js/xpconnect/loader/XPCOMUtils.jsm 0.000003 xpcshell.12423142 10:42:16.098271 stat64 /Users/gps/src/firefox/js/xpconnect/loader/XPCOMUtils.jsm 0.000005 xpcshell.12423142 10:42:16.098277 open F=7 (R_____) /Users/gps/src/firefox/js/xpconnect/loader/XPCOMUtils.jsm 0.000005 xpcshell.12423142 10:42:16.098279 fstat64 F=7 0.000001 xpcshell.12423142 10:42:16.098654 close F=7 0.000004 xpcshell.12423142 And a few imports later we appear to do the same dance modulo the file open: 10:42:16.109046 lstat64 /Users/gps/src/firefox/obj-firefox.noindex/dist/bin/modules/XPCOMUtils.jsm 0.000006 xpcshell.12423142 10:42:16.109049 lstat64 /Users/gps/src/firefox/obj-firefox.noindex/dist/bin/modules/XPCOMUtils.jsm 0.000002 xpcshell.12423142 10:42:16.109052 readlink /Users/gps/src/firefox/obj-firefox.noindex/dist/bin/modules/XPCOMUtils.jsm 0.000003 xpcshell.12423142 10:42:16.109055 lstat64 /Users/gps/src/firefox/js/xpconnect/loader/XPCOMUtils.jsm 0.000003 xpcshell.12423142 10:42:16.109060 stat64 /Users/gps/src/firefox/js/xpconnect/loader/XPCOMUtils.jsm 0.000002 xpcshell.12423142 10:42:16.109416 lstat64 /Users/gps/src/firefox/obj-firefox.noindex/dist/bin/modules/XPCOMUtils.jsm 0.000005 xpcshell.12423142 10:42:16.109419 lstat64 /Users/gps/src/firefox/obj-firefox.noindex/dist/bin/modules/XPCOMUtils.jsm 0.000003 xpcshell.12423142 10:42:16.109422 readlink /Users/gps/src/firefox/obj-firefox.noindex/dist/bin/modules/XPCOMUtils.jsm 0.000003 xpcshell.12423142 10:42:16.109424 lstat64 /Users/gps/src/firefox/js/xpconnect/loader/XPCOMUtils.jsm 0.000003 xpcshell.12423142 10:42:16.109429 stat64 /Users/gps/src/firefox/js/xpconnect/loader/XPCOMUtils.jsm It seems to me that we call stat() way too often when importing JSMs. First there is the double lstat64(). You could also ask "why lstat instead of just stat (which follows symlinks)?" (I'm assuming there is a security consideration here.) Finally, is that 2nd block of stat() (after initial import) even necessary?
The problem isn't nearly as bad inside Nightly proper (as opposed to xpcshell): 13:10:24.440063 lstat64 /Users/gps/src/firefox/obj-firefox.noindex/dist/Nightly.app/Contents/MacOS/modules/HealthReport.jsm 0.000010 firefox.12651795 13:10:24.440391 stat64 /Users/gps/src/firefox/obj-firefox.noindex/dist/Nightly.app/Contents/MacOS/modules/HealthReport.jsm 0.000011 firefox.12651795 13:10:24.440409 open F=27 (R_____) /Users/gps/src/firefox/obj-firefox.noindex/dist/Nightly.app/Contents/MacOS/modules/HealthReport.jsm 0.000017 firefox.12651795 13:10:24.440416 fstat64 F=27 0.000003 firefox.12651795 13:10:24.451234 close F=27 Although, I'm still confused as to why we have all 3 variations of stat in use. I reckon this problem is further marginalized on official builds where JSMs are inside omni.jar (as opposed to local builds where I have been doing all this). The issue in xpcshell *may* result in slower test runs. More testing is needed.
I'll try and take a look at this.
Assignee: nobody → dteller
Created attachment 8380905 [details] stacks.txt At first glance, I see the following issues: 1. a single call to import() seems to call three times fstat/lstat on the same file (see attachment); a. nsIOService::NewFileURI calls stat() once to check whether the file is a directory (I'll file a bug on that topic); b. mozJSComponentLoader::ObjectForLocation calls stat() again to find the size of the file; c. mozJSComponentLoader::ObjectForLocation then calls PR_CreateFileMap(), which takes as argument the size of the file but calls |stat|. 2. successive calls to import() with the same URI call these functions again. I believe that we can get rid of 1a and merge 1b. and 1c. However, I believe that the real deal is 2. I have no idea why successive calls to import() don't hit immediately in a hashtable and stop there. Let's ask bz whether he has an idea.
import() ends up calling mozJSComponentLoader::ImportInto, which does a newURI, creates a channel, gets the channel's URI, and uses its spec as the hashtable key. It also does some work like walking through jar URIs, etc, even on a cache hit, apparently; that should just move into the cache miss case... The channel bit is from bug 552121 but it was mostly just preserving the old behavior of us using the actual file as the key, afaict. In any case, I would expect that today successive calls to import() do the NewFileURI bit but NOT call ObjectForLocation, since they should in fact get a cache hit...
(In reply to Boris Zbarsky [:bz] (reviews will be slow; ask someone else) from comment #4) > In any case, I would expect that today successive calls to import() do the > NewFileURI bit but NOT call ObjectForLocation, since they should in fact get > a cache hit... Well, I just tested it with a build only a few days old. STR: 1. ./mach xpcshell-test -i toolkit/components/osfile/tests/xpcshell/test_exceptions.js (arbitrary test); 2. break on fstat, stat; 3. sudo fs_usage <pid> -f filesys | grep XPCOMUtils.jsm (helps filtering out the interesting breaks); 4. _execute_test(); I keep encountering the sequence mentioned in Comment 3.
OK, step through ImportInto to see what's going on? In particular, what the key string is and whether we end up putting things in the hashtable?
With the same binary, I can't seem to reproduce anymore. I guess I must have misobserved, sorry for the noise.
However, would there be any drawback to using the raw path as key? This would still let us avoid many calls to stat/fstat/readlink.
That, I don't know. I'm not sure what sort of paths we have coming through here and when two different ones would get canonicalized to the same thing... and what the drawbacks of loading the module twice in the latter case would be. One thing we could probably do without breaking compat is have a hashtable based on raw path and another based on resolved path and add to _both_ hashtables using the right keys. Then look up in the raw path table, and on hit we're done. On miss, resolve the path and look up in the other table.
I continue to see three calls to stat() for imported modules using something like comment 5. Spinning off a new bug to fix the stat coming from PR_CreateFileMap.
Let's turn this into a tracking bug.
Assignee: dteller → nobody
Summary: Cu.import() calls stat() excessively → [meta] Cu.import() calls stat() excessively
You need to log in before you can comment on or make changes to this bug.