OpenNSPRFileDesc() should fail more quickly when opening non-existant files

RESOLVED WONTFIX

Status

()

Core
XPCOM
RESOLVED WONTFIX
16 years ago
15 years ago

People

(Reporter: Pierre Saslawsky, Assigned: Conrad Carlen (not reading bugmail))

Tracking

({perf})

Trunk
mozilla1.0.1
PowerPC
Mac System 9.x
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(4 attachments, 1 obsolete attachment)

(Reporter)

Description

16 years ago
Tested with relatively recent debug build on the Mac.

We call nsLocalFile::OpenNSPRFileDesc() 115 times at startup.  Out of these, 44 
fail because the files don't exist.  See the attached log for more info.

A first problem is that OpenNSPRFileDesc() doesn't return immediately when 
ResolveAndStat() fails.  It calls ResolveAliasFile() and FSpOpenDF() with an 
empty FSSpec.name.  This represents a small waste of time, around 9 or 10 
milliseconds.  I'll attach a small patch.

The main problem, though, is that we probably waste much more time in other file 
IO and XPCOM functions to build the URLs and access files that we don't need.  
Many of these are stylesheets.rdf and overlays.rdf files for modules such as 
help, wallet, cookie, venkman, cview and chatzilla.
(Reporter)

Comment 1

16 years ago
Created attachment 58353 [details]
Log of OpenNSPRFileDesc at startup
(Reporter)

Comment 2

16 years ago
Created attachment 58354 [details] [diff] [review]
small, limited and temporary patch
(Reporter)

Updated

16 years ago
Keywords: perf
related to bug 109590 ?

Comment 4

16 years ago
Many of these are non-existent .rdf files. cc hyatt.
(Assignee)

Comment 5

16 years ago
That's good to know. In bug 100828, which is about to go in, OpenNSPRFileDesc()
was also changed to do less work before possibly failing.

Comment 6

16 years ago
conrad, is this yours?
Assignee: dougt → ccarlen

Comment 7

16 years ago
is this mac specific or do we have the same problems on other platforms?
(Assignee)

Comment 8

16 years ago
> conrad, is this yours?

No. I just pointed out that I had a change which did a similar thing to the
patch here. Neither of them address the root of the problem given in the bug
summary. I would think this problem is all platforms - just most painful on the Mac.

Comment 9

16 years ago
The wasted calls is a covered by bug 109590
(Reporter)

Comment 10

16 years ago
Bug 109590 can be closed as dup, I think.  It says that the time spent in these 
opening these files is 0.3% of startup time but what I'm seeing points to a 
higher number.  Yesterday I did the measurements in 
nsLocalFile::OpenNSPRFileDesc() but I noticed that all the calls that fail 
originate from nsFileChannel::Open() and the large majority of them have the 
following stack trace:
    nsChromeRegistry::GetOverlays()
    nsChromeRegistry::GetDynamicInfo()
    nsChromeRegistry::GetDynamicDataSource()
    nsChromeRegistry::LoadDataSource()
    RDFXMLDataSourceImpl::Refresh()   //--- return code ignored in LoadDataSource
    RDFXMLDataSourceImpl::BlockingParse()
    nsFileChannel::Open()             //--- return code ignored in BlockingParse
    nsFileTransport::OpenInputStream()
    nsFileIO::GetInputStream()
    nsFileInputStream::Init()
    nsLocalFile::OpenNSPRFileDesc()

I could not measure the entire time wasted in nsChromeRegistry::GetOverlays() 
because if BlockingParse() and LoadDataSource() don't ignore the error code, the 
application doesn't launch.  So I did new measurements in nsFileChannel::Open().  
It appears that we spend about 400ms to open 22 files that exist and we waste 
140ms opening 43 files that don't exist (on a cold start).  See the attached log.

In nsLocalFile::OpenNSPRFileDesc(), the wasted time was 9 or 10ms.  In 
nsFileChannel::Open(), it is 140ms.  If we could measure it higher in the stack, 
the value would no doubt be higher.

The measurements were taken on a debug build but they should be fairly accurate: 
we don't seem to have debug functions in that code.  Higher in the stack, we do 
have some debug code and the measurements could be less accurate in absolute 
value (or they should be done with an optimized build).
(Reporter)

Comment 11

16 years ago
Created attachment 58499 [details]
Log of nsFileChannel::Open() at startup
(Reporter)

Comment 12

16 years ago
Note that on a packaged build, the time to open the files that exist would 
probably be smaller because we wouldn't have the resolve the aliases in the 
'dist' directory.  For the files that don't exist, the value should remain 
unchanged: 0.14s in nsFileChannel::Open(), and more higher up in the stack.
(Reporter)

Comment 13

16 years ago
I just took new measurements one step higher in the stack, in 
RDFXMLDataSourceImpl::Refresh() instead of RDFXMLDataSourceImpl::BlockingParse().

Results:
  opened: 12 files in 776 ms
  wasted: 43 files in 168 ms

We have less "good" files to open and they take much more time, I guess because 
of the XML parsing.  The wasted time increases from 0.14s to approx 0.17s.
Why should the earlier bug be the dup merely because its summary states the
costs differently, and not with the worst-case platform % of startup?  It's
pretty clear from reading that bug that dp wasn't measuring on Mac, and we know
Mac file operations cost more.

IOW, why not use this bug to get the patch attached here in?  It seems like a
good patch in its own right.

I'm not bugged too much, but "forward dups" seem like the wrong thing, usually
-- and is this bug well-assigned?

/be
(Reporter)

Comment 15

16 years ago
I have no strong opinion regarding which bugs should be duped or reassigned.  
I'll leave it to the persons working on performance, XPCOM, native file i/o, RDF 
and Chrome Registry to decide what to do.  The important thing is that they all 
see the data.

Some measurements in nsChromeRegistry::GetOverlays() confirm what was seen in 
RDFXMLDataSourceImpl::BlockingParse().  On my machine, it causes a slowdown of 
around 170ms out of which only 9 or 10ms are from the Mac low-level file 
operations (which means 94% XP and 6% Mac)

Almost all the wasted calls come from nsChromeRegistry::GetOverlays().  The 
function is called 49 times but only 11 of these calls cause some attempts to 
open a file (4 attempts each: 2 for "stylesheets.rdf" and 2 for "overlays.rdf" in 
both the app's Chrome directory and in the user's Chrome directory).

These 4 files are responsible for 1 hit and 3 misses each (the hit is always for 
the "overlays.rdf" file in the app's Chrome directory):
  /content/navigator.xul
  /content/mailNavigatorOverlay.xul
  /content/editorNavigatorOverlay.xul
  /content/utilityOverlay.xul

These 7 files are responsible for 4 misses each:
  /content/hiddenWindow.xul
  /content/helpMenuOverlay.xul
  /content/walletNavigatorOverlay.xul
  /content/cookieTasksOverlay.xul
  /content/venkman-overlay.xul
  /content/cviewOverlay.xul
  /content/chatzillaOverlay.xul

As a summary, when nsChromeRegistry::GetOverlays() is called at startup, we 
attempt to open 44 files but we succeed only 4 times.
(Reporter)

Comment 16

16 years ago
Created attachment 58520 [details]
Log of nsChromeRegistry::GetOverlays() at startup

Comment 17

16 years ago
I have a bug to just combine all the chrome registry RDF files into one big file.
(Assignee)

Comment 18

16 years ago
Things in nsLocalFileMac have changed a lot since the original patch was made.
The problem it addresses is improved. Although, looking at it again, it's not
quite improved enough so I have a new patch. Since this is just a Mac-specific
aspect of bug 109590, changing summary to reflect the patches here.
Status: NEW → ASSIGNED
Summary: 38% of the files we attempt to open at startup don't exist → OpenNSPRFileDesc() should fail more quickly when opening non-existant files
Target Milestone: --- → mozilla1.0.1
(Assignee)

Comment 19

16 years ago
Created attachment 65247 [details] [diff] [review]
patch to slightly improve OpenNSPRFileDesc
Attachment #58354 - Attachment is obsolete: true
(Assignee)

Comment 20

15 years ago
OS9-only. Dead.
Status: ASSIGNED → RESOLVED
Last Resolved: 15 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.