27510 - [tracking] Too much read from disk on startup

Status: RESOLVED FIXED

(Core :: XPCOM, defect, P3)

Description

[Daniel Bratell]

I looked at Windows 2000's "bytes read"-meter and noticed that Mozilla reads 
26,261,410 bytes just to open the "choose profile"-window. Then it goes up 
to 30,148,823 when opening the first browser window. That's a little too much I 
think. 

I had no idea where to send this performance bug, so please reassign it to 
whoever can have a look at this issue.

Comment 1

[Daniel Bratell]

Compare with Netscape 4.71 which reads less than 1 MB during startup. 600 KB 
something if I remember correctly.

My measurements where done with a debug build by the way, which probably added 
some MB to the numbers.

Comment 2

[selmer (gone)]

Chris, do you already have numbers that would narrow this down a bit?  I doubt 
that it's profile manager specific, we're just lucky enough to open the first 
window...

Comment 3

[Daniel Bratell]

I did an analyze with ntfilemon from http://www.sysinternals.com and then let 
the log go through a program that summarized the information. The result can 
be found in http://a27.ib.student.liu.se/mzbytes2.txt where the number is the 
number of read bytes.  The most interesting part I think is the top line:

FILE                                                         BYTES
G:\mozilla\\mozilla\dist\WIN32_D.OBJ\bin\component.reg      33718272
J:\WINNT\mozregistry.dat                                      380928
G:\mozilla\\mozilla\dist\WIN32_D.OBJ\bin\res\wincharset.properties 327680
J:\WINNT\nsreg.dat                                            253952

33 MB seems a little strange. Can that be true? In that case something must be 
really wrong. The lines in the log adding up to the 33 MB is lines like:
397 20:28:45 mozilla.exe:508 FASTIO_READ 
G:\mozilla\\mozilla\dist\WIN32_D.OBJ\bin\component.reg SUCCESS Offset: 262144 
Length: 65536

This analyze doesn't include anything loaded by the system by the way. I might 
do an analyze including system I/O tomorrow, but now it's getting late.

I'll change component to XPCOM Registry. It can't be more wrong than "Profile 
Manager".

Comment 4

[Chris Waterson]

This may be a known problem (I seem to remember there being some discussion
about the registry being read many times at startup).

Question: were these results collected on the "first run"? (During which
component autoregistration may have caused several passes through the registry?)
Or was it on a "subsequent run" (during which autoreg should have -not- been
performed)?

Comment 5

[Daniel Bratell]

It was a subsequent run. As if I could get it right the first time? :-)
Nothing in the debug console output that mentions any registration problems 
either.

Comment 6

[Daniel Veditz [:dveditz]]

AutoReg is run each time, only the SelfRegister step is skipped for already 
known .DLL's.  Beta bug 12817 deals with this.

That won't help *this* problem, though, because we always need to read the 
registry data. Beta bug 15115 covers this issue.

Comment 7

[Daniel Veditz [:dveditz]]

I'm NOT closing this as a duplicate of bug 15115, instead I'll make it a 
dependency. There is something else going on here too (the .properties file for 
one) that will probably be clearer once 15115 is out of the way. That one is 
definitely the bulk of the problem, though -- we need a different registry 
format.

Comment 8

[Daniel Bratell]

I've finally done a new measurement including system and it looks much better
now. The reading of the registry is down from more than 30 MB to "only" 11.5 MB.
The bad news is that still is too much too be good. A new offender is
history.dat that is read in full no more than six times (according to the amount
of data read).

The full list can be found at <http://a27.ib.student.liu.se/mzbytes3.txt>. The
top is:

%MOZROOT\component.reg                                     11526144
%MOZPROFILEROOT\Users50\mozProfile-1\history.dat             458752
%MOZROOT\res\wincharset.properties                           327680
%MOZROOT\chrome\navigator\locale\en-US\navigator.dtd         131072
%MOZROOT\chrome\global\skin\default\animthrob_single.gif     131072

Comment 9

[Mike]

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

Comment 10

[Eugene Savitsky]

[e-mail] can you test the newest build and post here the results? 

Comment 11

[Daniel Bratell]

Now I've tested a new build (from CVS this night) and things looks the same or 
even a little worse. We still read component.reg way too much. We are now at 15 
MB after being as low as 11 MB. The measurements were made on a run with no 
registration of components. If measuring the first run, things are way worse.

component.reg                                            15794176
mozregistry.dat                                            126976
packages\core\communicator\content\bookmarks\bookmarks.js   87862
components\xpti.dat                                         86522
chrome\skins\modern\global\skin\animthrob.gif               85842
chrome\packages\core\navigator\content\navigator.js         50594
...
TOTAL                                                    17417967

The full list is on <http://caesar.homeip.net/mzbytes4.txt> (the previous lists 
are now on <http://caesar.homeip.net/mzbytes2.txt> and 
<http://caesar.homeip.net/mzbytes3.txt>).

Also clearing milestone field since M16 is long since gone.

Comment 12

[leger]

dveditz...you'll need to mark verified if fixed.

Comment 13

[Daniel Veditz [:dveditz]]

Clearing verifyme keyword, this has not been fixed and thus cannot be verified.

kandrot is working on the component.reg part of the problem under another bug

Comment 14

[Brendan Eich [:brendan]]

Anyone want to work on this?  Cc'ing neo-dp.

/be

Comment 15

[Daniel Veditz [:dveditz]]

I'll be working on parts of this as well...

Comment 16

[Suresh Duddi]

Glad to help. May be Dan can direct/coordinate.

Comment 17

[Daniel Veditz [:dveditz]]

The old items mentioned here are more or less fixed (will look at bug 46707).
I'm sure more can be done but it's much better to identify individual items and
hang them off this one than to keep piling on. Calling this a meta bug.

Comment 18

[Daniel Veditz [:dveditz]]

The old items have been fixed, and the performance team has filed new bugs as
new things are found. FIXED