123947 - startup (ts) and new window (txul) both increased 1.8%

Status: RESOLVED FIXED

(Core :: Networking: File, defect, P1)

Description

[Cathleen]

between 2/4 9:30pm and 2/5 4am, ts and txul increased about 1.8% each.

sleekstack tinderbox showed

                   startup (ts)      new window (txul)
                   -----------        ----------------
2/4 17:58-21:28       5404                 1418
2/4 21:28-00:47       5446                 1439
2/5 00:47-03:35       5491                 1444
2/5 03:35-04:10       5501                 1449


Here is a list of check-in during 21:28-00:47 build
http://tinderbox.mozilla.org/bonsai/cvsquery.cgi?module=MozillaTinderboxAll&date=explicit&mindate=1012873920&maxdate=1012886879

CC'ing everyone on the check-in log.  We need everyone to re-exame their
check-in, and let us know if you caused or didn't cause the regression.

Comment 1

[Blake Ross]

All I did was back out a fix I checked in the previous day, so not me.

Comment 2

[Boris Zbarsky [:bzbarsky]]

My change _could_ have made some string comparisons slower....  It would make it
faster to tell if A and B are different strings and a maybe a tiny bit slower to
tell that they are the same string.

Can someone run the performance tests with my changes in and out?  I don't
really have a way of testing that...

Comment 3

[Darin Fisher]

i recall checking ts and txul after my checkin, and it appeared to have no
visible effect.

Comment 4

[Johnny Stenback (:jst)]

I had a look at both my changes and AFAICT neither could impact performance in
any way what so ever. One of the checkins affect default values for a few
properties on some HTML elements that I doubt are even accessed when starting
mozilla, and the other one fixes up cloning of document fragments, which I also
doubt we ever do in mozilla.

Comment 5

[Boris Zbarsky [:bzbarsky]]

I tried backing out my patch locally.

Before my changes landed:

Startup (ms): 5437 3649 3827 3021 3078 2954 3650 3272 3383 3084
Average: 3535
Median:  ~3330

openingTimes=1056,1013,1025,1034,1034,1000,1033,1030,1033
avgOpenTime:1029
minOpenTime:1000
maxOpenTime:1056
medOpenTime:1033
__xulWinOpenTime:1033

After my changes landed:

Startup (ms): 4128 3708 3027 3361 3670 3611 3585 3067 3622 3554
Average:  3533
Median: ~3600

openingTimes=1044,1107,1069,1000,1038,1021,1054,1009,1019
avgOpenTime:1040
minOpenTime:1000
maxOpenTime:1107
medOpenTime:1038
__xulWinOpenTime:1038

It _looks_ like I may be the culprit but someone who is used to making sense of
this data should look.

Comment 6

[Boris Zbarsky [:bzbarsky]]

More testing for WindowOpen (3 tests each without my patch and with it) shows:  

Without my changes:

avgOpenTime:1029
minOpenTime:993
maxOpenTime:1067
medOpenTime:1042
----
avgOpenTime:1024
minOpenTime:993
maxOpenTime:1053
medOpenTime:1024
----
avgOpenTime:1037
minOpenTime:1010
maxOpenTime:1077
medOpenTime:1037

With my changes:

avgOpenTime:1027
minOpenTime:1000
maxOpenTime:1046
medOpenTime:1027
----
avgOpenTime:1034
minOpenTime:1002
maxOpenTime:1075
medOpenTime:1033
----
avgOpenTime:1032
minOpenTime:1020
maxOpenTime:1051
medOpenTime:1030

Conclusion:  My change does not affect window open significantly.
Off to test startup in more detail next.  

Comment 7

[Boris Zbarsky [:bzbarsky]]

More startup numbers _with_ my patch:  

3643 3689 3171 3336 2935 3675
Average: 3408
Median: ~3400

The noise in the data is so high, I'm not sure what to make of it.... :(

Comment 8

[Brian Ryner (not reading)]

There's no way it was my checkin, xbl form controls wouldn't affect startup.

Comment 9

[Chris McAfee]

I can run a tinderbox in test-mode for any set of changes;
if you have a patch you want to test send me some mail.

Comment 10

[Chris McAfee]

Attachment: graph of bz backout

middle hump is bz's changes backed out, so Ts looks like him.
Txul is mostly flat/noisy, too hard to conclude anything.

Comment 11

[Cathleen]

--> bz

based on mcafee's test data from tinderbox, looks like fix for bug 115289
Compare() to Equals() slowed down startup.

Comment 12

[Boris Zbarsky [:bzbarsky]]

I'm confused by the graph, actually... let me see if I get this straight:

1)  The part before about 02:45 on 02/08 is a build from _before_ I landed my
    string changes or a build with my string changes backed out.
2)  The part after that time/date includes my changes
3)  Things happening after noon on 02/08 are irrelevant

mcafee, that correct?

Comment 13

[Chris McAfee]

the graph has data in three spots, ABA.
A=trunk build, B=your backout.  B is the middle data.

Boris, can you attach a non-backout version of your patch?
I can try this again on another tbox if you like.

I think it would be just as fast for you to just back the stuff
out, see what all the numbers do, and possibly check it back 
in again if the numbers don't move.  We will have to do some of
this, I don't think this is such a bad thing.

Comment 14

[Boris Zbarsky [:bzbarsky]]

Attachment: Patch to apply to current trunk to back me out

OK, this is a patch to apply to the current trunk to back out my string
changes.

I'm going to try landing it in pieces over the weekend for a few cycles at a
time to see which part may be causing issues...

Comment 15

[Dawn Endico]

Backing out boris made no difference. I suggest trying danm's 14:27
checkin next. I've emailed him.

I allowed biesi to check in fix for Fabian's smoketest blocker since
his checkin didn't seem to be responsible for the slowdown and backing
out only from mozilla.org would break the commercial tree.

Comment 16

[Boris Zbarsky [:bzbarsky]]

OK, I've relanded my patch since backing it out did nothing.  Looking at the
checkin list the most likely next culprits are the nsFileChannel changes by
rpotts for Ts, I think.....

Comment 17

[Chris McAfee]

-> rpotts

Comment 18

[rpotts (gone)]

he nsFileChannel changes were backed out the next day... due to other
regressions :-(

So, if the startup time didn't get better the next day, it wasn't me ;-)

-- rick

Comment 19

[Blake Ross]

Umm...we seem to be out of candidates.

Comment 20

[rpotts (gone)]

-> cathleen (again)  sorry :-(

Comment 21

[Cathleen]

rpotts, what was the timeframe your backout happened?  
If it's late afternoon, there appear to be a drop in startup on most tinderboxes...

Comment 22

[rpotts (gone)]

The change was backed out in rev 1.117 at 16:28 pm

http://bonsai.mozilla.org/cvslog.cgi?file=mozilla/netwerk/protocol/file/src/nsFi
leChannel.cpp

Comment 23

[Cathleen]

the time frame sounds about right, correspond to tinderbox drop.  
I will verify.  :-)

Comment 24

[rpotts (gone)]

hey cathleen,

let me know if *all* the time was associated with the FileChannel change... 
cause i'm going to have to re-land it once i figure out why linux hung ;-)

-- rick

Comment 25

[Cathleen]

tinderbox doesn't display check-in logs for that many days back...  it's going
to be a hard one to figure out.  

(wish we had known about the backout, or rick had watched the numbers :-( )

mcafee, do you know any tinderbox trick that can help figure this one out?

Comment 26

[rpotts (gone)]

so are the current tinderbox numbers 'normal'?  or are we still slower than we
were before?

Comment 27

[Alec Flett]

bonsai can show you any checkins back to the beginning of time.. I seem to be
able to go back over a week with the "Show Previous 24 hours" link at the bottom
of tinderbox...

Comment 28

[rpotts (gone)]

so, can this bug be closed until i re-land my nsFileChannel changes ;-)

I promise to look into why more time is being spent on startup before they land
again :-)

-- rick

Comment 29

[Chris McAfee]

alecf: as you go back in time, tinderbox tends to lose the vertical
information and just lumps everyone into one checkin window.
It's probably a bug, or we're not keeping status somehow.

Comment 30

[Cathleen]

assuming this is fixed, since rpotts backed out around the time we saw a drop in
perf graph.