116483 - 2-4% spike in startup time, after timer landed

Status: RESOLVED WONTFIX

(Core :: XPCOM, defect, P2)

Description

[Chris McAfee]

I cleaned up dist on a tbox Thursday, and much to everyone's surprise,
startup time went up not down.  I decided to do the same to my home
machine tbox, and found the same results.  This time I saved off the
old dist.  I can swap the two dists in/out interchangably.  Attaching
a diff of the ls -R1 output of the two directories:
diff -c slow-dist.1R fast-dist.1R

Comment 1

[Chris McAfee]

cathleen

Comment 2

[Chris McAfee]

Attachment: diff -c slow-dist.1R fast-dist.1R

Comment 3

[Chris McAfee]

Adding some people

Comment 4

[Chris McAfee]

Attachment: gzip of ls -1R slow-dist

Comment 5

[Chris McAfee]

Attachment: gzip of ls -1R fast-dist

Comment 6

[Chris McAfee]

Attachment: spike graph. slow-dist is new, rm'd dist build, the spike. swapping old dist back in dropped time back down

Comment 7

[Chris McAfee]

over to hewitt for a look

Comment 8

[John Morrison]

Hey, Chris. Can you try just swapping in the dist/bin/chrome directory from 
the fast(er) build into the slow build and seeing how the time changes.

Comment 9

[Chris McAfee]

pulled completely new tree, it matches slow-dist times.
I will try the chrome dir swap next.

Comment 10

[Chris McAfee]

I started to walk through these changes one by one to find out
where the time difference was coming from, and ! my first change
to yank the timer stuff was the culprit.  In my test slow-dist,
I removed the *timer* references from the first diff [attachment #1 [details] [diff] [review]]
and the startup time went back up to spike level.
Over to pavlov for a look.

Comment 11

[Chris McAfee]

specifically, adding this link back to the now-defunct libtimer_gtk.so
 
  dist/bin/components/libtimer_gtk.so ->
  ../../../widget/timer/src/unix/gtk/libtimer_gtk.so
makes startup time faster by 100ms, from about 4387ms to 4275ms
on my 2x400MHz machine here at home.  Depend builds still probably
all have this library just sitting there, since we don't prune removed
directories on cvs checkout.  I now have two questions:

  1) Does the new timer implementation share the same interfaces
     as the old implementation?  If so, we may have we been running
     the old timer stuff courtesy of the depend build leaving the
     old library in dist.  (tbox doesn't do a cvs -P to prune out
     stuff like this).

  2) What was the intention of the new timer?  Was this a speed thing?

If depend screwed up here, we should fix this, and should file a new
bug for that.

Comment 12

[Chris McAfee]

new timer went in last weekend, Sat 12/15 as the fix for bug 78611.
This is the thread-safe timer stuff, maybe this is just the price
we pay for being thread-safe?  Adding brendan.

Comment 13

[Chris McAfee]

I see similar numbers in the Txul window open times,
my box reported a change of 40ms out of 1040ms, or 3.8%.
Note: btek has not had dist cleared as far as I know,
so pageloader damage may be unknown.

Comment 14

[jag (Peter Annema)]

I strongly suspect this is the reason for the uptick covered by bug 115671. See
comment 10 in that bug for an explanation.

Comment 15

[Chris McAfee]

there is a 1290 to 1310 (1.5%) jump in btek numbers at the time
jag is talking about.

New bug re: depend tbox dist clearing is bug 116648.

Comment 16

[Cathleen]

up the severity to "critical".
pav is on vacation till mid Jan, I think.

Is this a price we have to pay by making timer thread safe??  brendan? waterson?
Or, can we make it better?  

Comment 17

[Chris McAfee]

I cleaned up dist on 10+ tinderboxes at 1pm today, some of the
times have jumped up as expected.

Comment 18

[Suresh Duddi (gone)]

I will look at this until pav comes back. I am planning on doing a quantify run
and seeing the breakdown of time spent on timers.

Comment 19

[jag (Peter Annema)]

*** Bug 115671 has been marked as a duplicate of this bug. ***

Comment 20

[Suresh Duddi (gone)]

back to pav. he is back.

Comment 21

[Stuart Parmenter]

Attachment: Patch to reduce logging overhead

Since timers currently dump out a lot of logging stuff, the double mults and
Interval related functions could be tossing a wrench in the debug numbers a
little.  This should cut down on the overhead somewhat, but probably not 100ms.

Comment 22

[Doug Turner (:dougt)]

Comment on attachment 64918 [details] [diff] [review]
Patch to reduce logging overhead

r=dougt

Comment 23

[Brendan Eich [:brendan]]

Comment on attachment 64918 [details] [diff] [review]
Patch to reduce logging overhead

sr=[e-mail], but why does all this DEBUG-only stuff affect optimized
builds that tinderbox now perf tests?

/be

Comment 24

[Stuart Parmenter]

it won't effect opt builds, but I never saw anyone say that these numbers were 
only on optimized builds.  This was just one of the first things I looked at 
when looking over the code to see what might be slow.

Comment 25

[Chris McAfee]

all tbox graphs use optimized builds to generate numbers.

Comment 26

[Stuart Parmenter]

ah, ok.  so this patch shouldn't have any effect on those numbers.

Comment 27

[scottputterman]

Moving Netscape owned 0.9.9 and 1.0 bugs that don't have an nsbeta1, nsbeta1+,
topembed, topembed+, Mozilla0.9.9+ or Mozilla1.0+ keyword.  Please send any
questions or feedback about this to [e-mail].  You can search for
"Moving bugs not scheduled for a project" to quickly delete this bugmail.

Comment 28

[jag (Peter Annema)]

nsbeta1, -> 1.0

Comment 29

[Gagan]

per adt, critical for nsbeta1. hence plus.

Comment 30

[Jaime Rodriguez, Jr.]

pav/gagan - what are the chnaces that we'd be able to get a fix for this before
06.14.2002? pls add eta. thanks!

Comment 31

[Markus Hübner]

Isn't this a XP issues (OS-->All) ?

Comment 32

[Doug Turner (:dougt)]

pavlov -> dougt

Comment 33

[Doug Turner (:dougt)]

we lost this one - no one ever verified these change.  I spoke with chris, and
we agreed to close this bug.