110355 - Regression in new mail compose window time caused by an 11/14 checkin

Status: VERIFIED WORKSFORME

(MailNews Core :: Composition, defect)

Description

[Scott MacGregor]

According to stephend, the time it takes for a new compose window almost
quadrupled in last nights builds. I think this is considered a stopper until we
at least understand what checkin caused the regression.

Here is what I've found so far.

This was Win98, PII 266, 128 megs of RAM.

                        BUILD DATE

Reply All/5 rcps 12      13     14      15
---------------------------------------------------
1st window     4.10     5.06    4.02   7.49      
2nd window     2.91     2.83    2.89   7.61
3rd window     2.89     2.85    2.87   7.68

Indeed, this is critical.  What is going on?  I'm going to start looking for
checkins that might have caused this.

Comment 1

[Scott MacGregor]

marking smoketest. I think we should at least understand what checkin is killing
us before we open the tree. We probably aren't the only window that's slower. 

Comment 2

[Akkana Peck]

Is this html compose, plaintext, or both?

Comment 3

[varada]

Stephen is planning to add the individual window startup time logs so that we
can spot the portion that is causing this increase.

Comment 4

[Charles Manske]

My checkin added a new JS file (editorUtilities.js) that loads with 
editorOverlay.xul. It is a very likely culprit. I'm investigating if we avoid 
loading this in HTML Compose

Comment 5

[Scott MacGregor]

another possibility is the smime overlay which is getting loaded with the
compose window. but that overlay is pretty small (just adds 3 menu items to the
Options menu). 

Comment 6

[[e-mail] (gone - use [e-mail] instead)]

Attachment: 14th build's results

Comment 7

[[e-mail] (gone - use [e-mail] instead)]

Attachment: 15 build's results

Comment 8

[[e-mail] (gone - use [e-mail] instead)]

Attachment: Compares plain text compose for 15th vs. 14th builds.

Comment 9

[[e-mail] (gone - use [e-mail] instead)]

All, the 1st two attachments were HTML compose, the last 
http://bugzilla.mozilla.org/attachment.cgi?id=58016&action=view was plaintext.

Comment 10

[Matthias Versen [:Matti]]

FYI: We have also bug 110340

Comment 11

[Charles Manske]

Attachment: Patch to use *only for testing* the effect of new editorUtilities.js on mail compose loading

Ok, I don't think all the editing commands will work correctly without loading
editorUtilities.js, but this patch will allow you to start the Mail Compose 
window without it, and thus test if it is the cause of the increased time to
load.
I really don't see how this could cause such a pronounced difference. Can one
more
JS file really cause that?

Comment 12

[Jean-Francois Ducarroz]

the problem is apparently during the first part when the window is loaded (new
window). the time jump from  2.7s to 5.6 for the first window and from 1.1 to
5.8 for the following one! Looks like the xul cache is off.

Comment 13

[Jean-Francois Ducarroz]

By experience, I would say that adding this JS file should not be the culprit,
especially it does not do much when it's loaded. Also, that would not explain
why the second window is slow as well. Adding JS doesn't not help performance
but it does not add couple second to the load time, should be more in the 1/10
of sec per 10K of JS.

Comment 14

[Scott MacGregor]

I went down to the slow machine in the QA lab and by hand "backed out" the
chrome registration code I added last night to mail.jst to register
messenger-smime chrome and load the overlay with the compose window. We still
saw the slow down on that release build when bringing up the compose window. The
overlay didn't appear to be getting loaded anymore and it was still slow.

However, I'd still be willing to back it out on the trunk, then have release
repackage a windows build so we can see if that makes a difference. Grasping at
straws but I'm willing to try.

Comment 15

[Scott MacGregor]

I just backed out my packaging changes to:
mozilla\xpinstall\packager\windows\mail.jst
AND
ns\xpinstall\packager\windows\mail.jst

Loan's going to repackage a windows build with this change so we can see if this
makes a difference.

Comment 16

[lpham]

Win32 respin is running now.

Loan

Comment 17

[Johnny Stenback (:jst)]

Why are we keeping the tree closed for a performance regression that doesn't
block anyone from testing anything!!!?!???

Comment 18

[Scott MacGregor]

I'm hoping johnny's just being funny. Please read my email in response to yours
about what's important for mozilla and netscape right now. thanks!

Comment 19

[Scott MacGregor]

Nothing on bonsaii is really jumping out at me. I agree with Charlie and JF that
adding his new editorUtilties.js file shouldn't be capable of slowing down new
compose as drastically as it is being slowed down. 

Comment 20

[Akkana Peck]

I checked in a small change to plaintext rewrap, but if this is showing up in
html compose as well, then it couldn't be that.

Comment 21

[Jean-Francois Ducarroz]

The slowdown is before we execute the onload handler, therefore before we
initialize the editor mode!

Comment 22

[[e-mail] (gone - use [e-mail] instead)]

With the respin build (2001-11-15-14), we're fine...

0[7b1eb0]: --------------------
0[7b1eb0]: [    0][    0] - Start opening the window, message size = 2941
0[7b1eb0]: [ 2203][ 2203] - Start initializing the compose window (ComposeLoad)
0[7b1eb0]: [ 2314][  111] - Done with the initialization (ComposeLoad). Waiting 
on editor to load about:blank
0[7b1eb0]: [ 2890][  576] - Editor is done loading about::blank. Now let mime 
do its job
0[7b1eb0]: [ 2968][   78] - done with mime. Lets update some UI element
0[7b1eb0]: [ 3891][  924] - addressing widget, windows title and focus are now 
set, time to insert the body
0[7b1eb0]: [ 4051][  160] - Finished inserting data into the editor. The window 
is finally ready!
0[7b1eb0]: --------------------
0[7b1eb0]: [    0][    0] - Start opening the window, message size = 2941
0[7b1eb0]: [ 1127][ 1127] - Start initializing the compose window (ComposeLoad)
0[7b1eb0]: [ 1216][   89] - Done with the initialization (ComposeLoad). Waiting 
on editor to load about:blank
0[7b1eb0]: [ 1755][  540] - Editor is done loading about::blank. Now let mime 
do its job
0[7b1eb0]: [ 1811][   55] - done with mime. Lets update some UI element
0[7b1eb0]: [ 2703][  893] - addressing widget, windows title and focus are now 
set, time to insert the body
0[7b1eb0]: [ 2861][  158] - Finished inserting data into the editor. The window 
is finally ready!
0[7b1eb0]: --------------------
0[7b1eb0]: [    0][    0] - Start opening the window, message size = 2941
0[7b1eb0]: [ 1132][ 1132] - Start initializing the compose window (ComposeLoad)
0[7b1eb0]: [ 1222][   90] - Done with the initialization (ComposeLoad). Waiting 
on editor to load about:blank
0[7b1eb0]: [ 1757][  535] - Editor is done loading about::blank. Now let mime 
do its job
0[7b1eb0]: [ 1813][   56] - done with mime. Lets update some UI element
0[7b1eb0]: [ 2715][  902] - addressing widget, windows title and focus are now 
set, time to insert the body
0[7b1eb0]: [ 2873][  157] - Finished inserting data into the editor. The window 
is finally ready!

Comment 23

[Scott MacGregor]

new builds are out and we're back to our usual times of roughly 2.8s for the 2nd
window and 4s for the first. 

marking fixed.

Comment 24

[Gilles Durys]

Could this have cause bug 110478 ?

Comment 25

[[e-mail] (gone - use [e-mail] instead)]

Re-opening.  I still see this on Win2k and Linux builds from 2001-11-16, with a
new profile.  Yesterday when Scott and I looked at this, we installed in a new
directory, and this worked fine (the results that I posted).  Creating a new
profile on the current directory still shows the slowness, but using the same
profile with a build installed in a new directory works fine.  I tried deleting
the xul.mfl, but to no avail.

Comment 26

[Scott MacGregor]

taking off the list. I don't see the slow down like I did in yesterdays build so
I don't think it's as prevelant as it was yesterday. We'll work with Stephen to
figure out the exact scenario under which he sees it. 

Comment 27

[[e-mail] (gone - use [e-mail] instead)]

Okay, for some reason the installed-chrome.txt wasn't getting replaced.  IE,
using the same builds, with the same profile, but in different directories (one
was installed over an older build which had the problem, the other was installed
in a brand new C:\Foo directory), we get different results.  The 16th build
installed over the 15th build still had the faulty menu and the perf
degredation, yet the one installed in a new directory C:\Foo worked fine with
regard to performance and menus.  Seems like the installer should be replacing
installed-chrome.txt, no?

Comment 28

[Blake Ross]

Glad to see this has been reopened.  As the person who originally mentioned the
noticeable slowdown to stephend, I came here to say that it still feels much
slower than it used to in an 11/16 nightly.  I use compose every day, obviously,
and I'd say the time to open the compose window is still approximately double
what it used to be, so I think we should keep the pressure on fixing this bug.

Comment 29

[[not reading bugmail]]

could this be related to seth's caching/hiding composer window change, which
should of brought down the opening window times.. 

Comment 30

[[not reading bugmail]]

which should be cached on a second window, maybe the check-in is not factoring
this in, or getting cached by seth's code, or even possibly going around it.

Comment 31

[[e-mail] (gone - use [e-mail] instead)]

No, that is not possible.  The code observes the max_recycled_windows pref 
value and works accordingly.  The pref, even if in some .js (all.js?) file has 
been set to 0, which disables the feature.

Comment 32

[[e-mail] (gone - use [e-mail] instead)]

Marking worksforme.  This was actually fixed when Scott re-landed his fix for 
S/MIME's chrome...  We're back to normal now.

Comment 33

[[e-mail] (gone - use [e-mail] instead)]

Verified, we're back down to pretty much normal now.