859912 - [meta] Cu.import() calls stat() excessively

Status: RESOLVED INACTIVE

(Core :: XPConnect, defect)

Description

[Gregory Szorc [:gps]]

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?

Comment 1

[Gregory Szorc [:gps]]

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.

Comment 2

[David Teller [:Yoric] - still alive but not very active]

I'll try and take a look at this.

Comment 3

[David Teller [:Yoric] - still alive but not very active]

Attachment: 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.

Comment 4

[Boris Zbarsky [:bzbarsky]]

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...

Comment 5

[David Teller [:Yoric] - still alive but not very active]

(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.

Comment 6

[Boris Zbarsky [:bzbarsky]]

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?

Comment 7

[David Teller [:Yoric] - still alive but not very active]

With the same binary, I can't seem to reproduce anymore. I guess I must have misobserved, sorry for the noise.

Comment 8

[David Teller [:Yoric] - still alive but not very active]

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.

Comment 9

[Boris Zbarsky [:bzbarsky]]

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.

Comment 10

[Nathan Froyd [:froydnj]]

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.

Comment 11

[David Teller [:Yoric] - still alive but not very active]

Let's turn this into a tracking bug.

Comment 12

[BMO Automation]

Per policy at https://wiki.mozilla.org/Bug_Triage/Projects/Bug_Handling/Bug_Husbandry#Inactive_Bugs. If this bug is not an enhancement request or a bug not present in a supported release of Firefox, then it may be reopened.