29063 - excessive stat() calls

Status: RESOLVED FIXED

(Core Graveyard :: Tracking, defect, P4)

Description

[Colin Blake]

Not sure which category to put this into. I think it should start life belonging 
to RDF, but there doesn't appear to be an RDF category. 

I originally posted this in a couple of n.p.m newsgroups, but got no response 
other than Dan Veditz saying "You are not being paranoid. These stats are 
killing us on the Mac as well."

M14 code, and I'm still seeing more local file accesses than I would 
expect/hope. Once the browser is up and running, I go to a page, and then hit 
the back button. These are the local file accesses I see. Note that these are 
real hard accesses.

Access a simple page:

stat /alpha$dka0/users/cblake/.mozilla/mozProfile
stat /alpha$dka0/users/cblake/.mozilla/mozProfile
stat /dkb100/work/m14opt/chrome/global/skin/default/animthrob.gif
open /dkb100/work/m14opt/chrome/global/skin/default/animthrob.gif
stat /alpha$dka0/users/cblake/.mozilla/mozProfile
stat /alpha$dka0/users/cblake/.mozilla/mozProfile
stat /dkb100/work/m14opt/chrome/global/skin/default/progressmeter-busy.gif
open /dkb100/work/m14opt/chrome/global/skin/default/progressmeter-busy.gif


Go back to previous page:

stat /alpha$dka0/users/cblake/.mozilla/mozProfile
stat /alpha$dka0/users/cblake/.mozilla/mozProfile
stat /dkb100/work/m14opt/chrome/global/skin/default/button32-bg-active.gif
open /dkb100/work/m14opt/chrome/global/skin/default/button32-bg-active.gif
stat /alpha$dka0/users/cblake/.mozilla/mozProfile
stat /alpha$dka0/users/cblake/.mozilla/mozProfile
stat /dkb100/work/m14opt/chrome/global/skin/default/animthrob.gif
open /dkb100/work/m14opt/chrome/global/skin/default/animthrob.gif
stat /alpha$dka0/users/cblake/.mozilla/mozProfile
stat /alpha$dka0/users/cblake/.mozilla/mozProfile
stat /dkb100/work/m14opt/chrome/global/skin/default/progressmeter-busy.gif
open /dkb100/work/m14opt/chrome/global/skin/default/progressmeter-busy.gif

Two questions:

1. Why do we keep stat'ing the profile directory all the time?

2. Why do we always seem to stat a file before opening it? To see if its there? 
Gee, the open call would tell us that.

The pairs of stat calls are coming from nsChromeRegistry::GetProfileRoot. We get 
two stat calls per time through this.

Does anyone else think this is excessive and I should file a bug? Or am I just 
being paranoid because I live on a system that has slow stat's and open's?

Colin.

Comment 1

[Colin Blake]

Forgot to say. I am seeing this on the OpenVMS platform, but that's built from 
the normal code base as if it were a UNIX derivative.

Comment 2

[chris hofmann]

lets start with waterson.  also adding dp, mcafee, pav, sspit, alecf,
sfraser as general unix/mac hacks to cc list to enjoin them in the hunt.
RELEASE THE HOUNDS!

Comment 3

[chris hofmann]

perf keyword

Comment 4

[Suresh Duddi (gone)]

Stat is certainly an issue. In xpt loading we found 10% of time reading in 
about 50 small xpt files was being spent on stat. Jband is looking into 
removing that.

I can add more info on this when I get to my office machine with quantify data. 
I think we need to fix many part of this.

Waterson, may I take this bug from you. This is a performance issue. Once we 
find the culprits I will cycle the bug or file individual bugs to try 
eliminating them.

Comment 5

[Chris Waterson]

all yours dp.

Comment 6

[Suresh Duddi (gone)]

Hooking into startup performance

Comment 7

[(not reading, please use [e-mail] instead)]

putterman was seeing the excessive stat calls, too.  cc'ing him.

Comment 8

[Suresh Duddi (gone)]

Stat timings on startup

Function			%	#call	Time(sec)
---------------------------------------------------------
stat				100	557	0.58
  nsFileSpec::IsFile		 45.32	185	0.26 (bug# 28964)
  nsFileSpec::Exists		 25.26	165	0.15
  nsFileSpec::GetFileSize	 20.91	 92	0.12
  nsFileSpec::IsDirectory	  8.50	115	0.05

All the 185 IsFile() calls are from xpt that are taken care in bug# 28964. So 
let us skip that. Looking at Exists().

Function				%	#call	Time(sec)
-----------------------------------------------------------------
nsFileSpec::Exists		 	100	165	0.15
  GetProfileDirectory			 74.74	 96	0.12 <got fix>
  nsChromeRegistry::			 12.93	 24	0.02
    CheckForProfileFile
  nsFileSpec::ResolveSymlink		  7.71	 28	0.01

GetProfileDirectory() and ChromeRegistry() look like they need to looked to see 
if they need to be doing this.

GetProfileDirectory() was simple enough to fix. Fixing chrome registry could 
give a bigger longer term yeild. Who want to take that ?

Comment 9

[Suresh Duddi (gone)]

With one ProfileDir fix and xpt file globbing, we have gotten rid of 280 out of 
550 calls.

What remains is:

  nsFileSpec::Exists             25.26   70     0.15
  nsFileSpec::GetFileSize        20.91   92     0.12
  nsFileSpec::IsDirectory         8.50  115     0.05

Comment 10

[Alec Flett]

do we have stack traces for each of these? even the top 4 frames would be great.

Comment 11

[Suresh Duddi (gone)]

The callers are not just one. So there would be more than one trace per 
category. I would just break in the debugger for say isDirectory() and see the 
stack.

Comment 12

[Alec Flett]

prefs calls nsFileSpec::Exists MANY times more than it needs (in fact, it never
needs to call it) - I have patches in my tree awaiting review which cleans up
25-30 of them from startup.

Comment 13

[Suresh Duddi (gone)]

Alec is your patch for pref checked in.

Comment 14

[Alec Flett]

yes - I had to put one back because it broke some stuff. But I got rid of all 
but that one.

Comment 15

[Suresh Duddi (gone)]

Hoping you would take care of this.

Comment 16

[Mike]

M16 has been out for a while now, these bugs target milestones need to be 
updated.

Comment 17

[Warren Harris]

Can somebody measure this again and report back? Things have changed a lot in 
the file transport.

Or maybe we should close/ignore this bug since everything will change when the 
chrome comes out of jar files.

Comment 18

[Colin Blake]

Its better (see below). mozProfile isn't being accessed all the time now. But 
we're still stat'ing a file before open'ing it. 

Is the plan to have all the chrome in a jar file AND have that jar file read 
permanently into memory?

FORWARD

stat /m16opt/chrome/skins/modern/global/skin/progressmeter-busy.gif
stat /m16opt/chrome/skins/modern/global/skin/animthrob.gif
open /m16opt/chrome/skins/modern/global/skin/animthrob.gif
open /m16opt/chrome/skins/modern/global/skin/progressmeter-busy.gif

BACKWARD

stat /m16opt/chrome/skins/modern/global/skin/progressmeter-busy.gif
stat /m16opt/chrome/skins/modern/global/skin/animthrob.gif
open /m16opt/chrome/skins/modern/global/skin/animthrob.gif
open /m16opt/chrome/skins/modern/global/skin/progressmeter-busy.gif

Comment 19

[Warren Harris]

This now just seems like a dup of the bug that the throbber hits the disk each 
time. Bug 41268.

Comment 20

[Doug Turner (:dougt)]

Warren, I am reassigning some bugs which you own over to me (dougt).  If you 
think that you will have time to address them please reassign them back to 
yourself.  This reassignment was suggested by choffman.

Comment 21

[Dawn Endico]

leger is no longer @netscape. changing qa contact to component's default

Comment 22

[Colin Blake]

I think someone needs to look at this issue again.

Last February Suresh reported that there were 557 stat calls at startup. Some
work was done to reduce this number quite considerably, and startup time 
improved.

I've noticed a slowdown at startup time and so I checked the number of stat
calls being made (now that we are using jar files I would have expected the
number to be small). We are making 744 stat calls to start up the browser and
display 'about:blank'. Whoa!!!

And add to that 215 access() calls, the majority of which I bet are just 
checking for the existance of a file before opening it. Talk about a waste
of cycles!

I can provide a list of the stat and access calls if required, but I think
the output that Suresh posted last time is much more meaningful.

Colin.

Comment 23

[chris hofmann]

anybody know how to run dp juju?   is it just some output from prlog?

Comment 24

[Doug Turner (:dougt)]

colin is that in a debug build?  Also, do you have jar packaging disabled?

Comment 25

[Colin Blake]

Yes, it is a debug build (from a few days ago). I can only trace the calls in a
debug build on OpenVMS.

jar packaging in certainly ON. My bin tree is void of all the files that make
up the jar files so I know its using the jar files.

Comment 26

[Alec Flett]

the dp juju look surprisingly familiar.. I want to say it's gprof - not sure.

Comment 27

[(not reading, please use [e-mail] instead)]

when I do this on linux:

strace -f mozilla -P seth about:blank |& tee ~/strace.txt

I see us making 286 stat calls.

I'll attach my strace log, for those are interested.  

Comment 28

[(not reading, please use [e-mail] instead)]

Attachment: strace log

Comment 29

[Colin Blake]

Seth, your trace is very interesting. More about that in a moment. First I 
should say that yesterday I found an RDF problem that was causing OpenVMS to 
always reinstall all the chrome upon startup. Now this is fixed my number of 
stat calls is down from 744 to 196, so that has helped a lot, but its still 
higher than your 119 (I was counting only stat, not fstat).

Comparing your trace and mine, they start out pretty much the same, but when 
yours stops mine continues. I see stat'ing of:

  rdf files in bin/chrome
  rdf files in user-profile/chrome
  css files in user-profile/chrome
  all the files in bin/searchplugins
  rdf files in user-profile/chrome/overlayinfo/xxx/xxx
  rdf files in bin/chrome/overlayino/xxx/xxx
  xml files in bin/res/builtin
  panels.rdf in user-profile

Any idea why OpenVMS is stat'ing all these files while UNIX is not?

Comment 30

[Colin Blake]

Attachment: Here's the trace of the OpenVMS stat calls

Comment 31

[Chris Waterson]

mcafee discovered some interesting stuff last night that I would've never 
thought of. Specifically, it looks like when you run strace on ``just an 
optimized build'', there is a significant amount of filesystem activity 
following symlinks from the ``dist'' directory to the actual files (duh!). So, 
be sure you're measuring on a ``real'' installation that doesn't symlink to 
files built in another directory.

Comment 32

[Chris McAfee]

Once I downloaded a build, I got a run similar to what sspitzer posted here.
But ! jprof isn't enabled by default.  We either need this on by-default,
or: what's the mechanism to package up a build on unix?

Comment 33

[Colin Blake]

You mean you're not seeing all the additional files getting stat'ed, like I am 
on OpenVMS? Damn. What is going on on OpenVMS???

Comment 34

[timeless]

see http://webtools.mozilla.org/build/config.cgi

Comment 35

[Alec Flett]

jprof will not find excessive stat() calls because it is a time-based sampling
profiler. only strace or gprof (which probably doesn't work with mozilla) will
count these.

Comment 36

[chris hofmann]

add topperf

Comment 37

[Mike Shaver (:shaver emeritus)]

Comment from Alan Stange ([e-mail]) in
news://news.mozilla.org/3A8CB264.3000804%40rentec.com :

> Typically, [open and stat calls] are paired up.  First stat the file, then 
> open it.  There is a very nice optimization here to open() the file, if that 
> works, then do an fstat().  The fstat() is essentially free once the 
> open() is done.  The idiom of stat() then open() shows up all over.

Comment 38

[chris hofmann]

dougt, are you working on this?  are you the right owner?

Comment 39

[Doug Turner (:dougt)]

chris,

no I am not actively looking at this bug.  I don't think that this bug will be
found in one central place, but rather it is a bunch of usage cases.

As a sidenote, the nsIFile caches stat info.  If you create one of these
objects, all sucessive getter() calls will result in only one stat every being
made.  

Briefly looking at the OpenVMS stat log, it looks like we can quickly identify
some problems, one of which we know about.  However, I am not really sure what
this output is.  I am guessing these are calls from the application to the os
|stat| api.  (for example, a stat then an open would only result in one stat
being logged, right??)

The first problem is that gif files are loading (or at least stat'ed) multiply
times.  This is a known problem which will go away when necko lands the new
image library.  

The second problem is that some rdf files are also loading multiple times.  For
example, the search.rdf file is stat'ed twice and localstore.rdf is being loaded
three times? Why is this?   

Another problem is that some js files are being loaded twice.  I think that I
spoke to waterson (or brendan) about this in the passed.  If you look at
security-prefs.js, it is being loaded twice.  I bet this is caused by it being
references twice from XUL.  Waterson, does your xul cache hold onto compiled js?

Prefernces looks like it is pounding stat second only to imagelib.  It stats
unix.js and initprefs.js three times, and the other prefs javascript files
twice.  Prefs io needs a enema.

But on the brigher side, I do not see any duplicates of jar files or libraries.

Comment 40

[Colin Blake]

The OpenVMS stat log is showing exactly what you say, Doug. That is, the calls 
from Mozilla to the O/S. So each stat you see is a real stat() call and NOT one 
that has been satisfied by the nsIFile stat cache.

If you see anything that looks like an OpenVMS specific problem (eg. other 
platforms only stat some file once but OpenVMS does it twice), please let me 
know!!

Comment 41

[timeless]

see also bug 69140

Comment 42

[chris hofmann]

kandrot is going to knock this one silly...

Comment 43

[Edward Kandrot]

On a current Linux build, I see about 250 stat() calls at startup, then no more.
 I used the PRE_LOAD to gather this info (then verified it by adding the same
code to XPCOM), overriding stat(), inserting a printf (or fprintf), then calling
the original stat().  I do not see the gifs and all, mentioned in previous posts
(though I do see the two stat() before an open, which I shall look into).

Comment 44

[chris hofmann]

looks like this should fall of the top perf list if
we are in good shape...  anyone have any evidence that
stat() call are killing startup?

Comment 45

[Edward Kandrot]

Marking this as 0.9.1, since I do not know if there is enough info yet to
complete this bug.

Comment 46

[Cathleen]

are we still seeing lots of stat() calls?  Is this still affecting the startup
performance?

Comment 47

[Cathleen]

forgot we decided in last performance meeting (3/9/01) that there doesn't appear 
to be any issues with stat() call, will take this off tracking list for now

Comment 48

[chris hofmann]

moving off the 0.9.1 radar

Comment 49

[timeless]

linux Bug 65845 incorporate code coverage info into link process 
esp Comments From Roger Chickering on:
2001-06-08 15:10, 2001-06-08 23:18, 2001-06-08 23:28 and 2001-06-08 23:54.
and the bug: 84871 Half of Linux cold start is spent stat()ing components files 

Comment 50

[Doug Turner (:dougt)]

reassigning kandrot bugs.

Comment 51

[Doug Turner (:dougt)]

to dp.

Comment 52

[Suresh Duddi (gone)]

Need to analyze this to figure out exactly what we should do about it.

Comment 53

[Suresh Duddi (gone)]

Analysis on stat calls:

Test case was

strace ./mozilla -P 'Default User' file:///usr/tmp/quit.html > trace.out

stat()
 86 .so
 47 .rdf
 34 .xpt
 31 .js
  6 .css
 24 searchplugin
 12 directory
----------------
240 total accounted
256 total

125 fstat()

Comments:
- 80 .so are comming from the prepopulation of registry code. We can cut this
down to 40
- 24 searchplugin : why are we loading the search plugin stuff
- 47 rdf files mmh!

Comment 54

[Suresh Duddi (gone)]

Attachment: xpcom patch to eliminate 86 stats

Comment 55

[Suresh Duddi (gone)]

Attachment: List of files we stat (in order) on startup - BEFORE above patch

Comment 56

[Chris Waterson]

Comment on attachment 50154 [details] [diff] [review]
xpcom patch to eliminate 86 stats

Looks good to me. r=waterson

Comment 57

[Alec Flett]

Comment on attachment 50154 [details] [diff] [review]
xpcom patch to eliminate 86 stats

awesome! So glad to see this part done. sr=alecf

Comment 58

[Suresh Duddi (gone)]

Attachment: stats after patch

Comment 59

[Suresh Duddi (gone)]

bug# 100834 eliminates the 24 stats from searchplugins and a directory enumeration

Will look into plugins next. Looks like we are enumerating (loading too ?)
plugins on startup.

Comment 60

[Suresh Duddi (gone)]

Checked in xpcom portions removing 86 stats (Patch 09/20/01 15:28) into trunk.

Comment 61

[Suresh Duddi (gone)]

Timings on these:

After fixing searchplugins and xpcom component stats, we have about 101 stats
taking 2.6msec out of 8000msec.

That is about 0.03% of startup. Not worth going after.