794420 - Win debug mochitest-other runtime increased from ~90mins to 115mins in the last 2 weeks

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Ed Morley [:emorley]]

WinXp debug m-oth runs are now taking 115-120 mins, whereas two weeks ago they were more like 88-90 mins.

Comment 1

[Ed Morley [:emorley]]

Last ~89 min WinXP run was:
https://tbpl.mozilla.org/?jobname=Rev3%20WINNT%205.1%20mozilla-central%20debug%20test%20mochitest-other&rev=710d9d21f533
-> https://tbpl.mozilla.org/php/getParsedLog.php?id=15241338&tree=Firefox

Then increased to ~95 mins in one of these pushes:
https://tbpl.mozilla.org/?jobname=mochitest-other&rev=fcd9acafa3ff
or
https://tbpl.mozilla.org/?jobname=mochitest-other&rev=f7c89de3ab43

Then increased to a whopping 112 mins in this push:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&jobname=mochitest-other&rev=633082d3e546

The first range might just be noise, but the latter seems excessive.

bholley, do you have any ideas? :-)
(Only seems to affect Windows, not

Comment 2

[Bobby Holley (:bholley)]

Seems pretty probably that it's related to the mega SpecialPowers testsuite fixup I pushed. I see two ways to narrow the problem down:

1 - Do some pushes and figure out which of those patches caused the regression. My money would be on dc84f6a237d7, a8583bee3c37, or 1f7c4fae49c0, so those are probably the only ones that we should check to start.

2 - Determine if one test (or a few tests) got a lot slower, or if the entire test suite just got slower across the board.

Ed, which do you think is easier? The first, I'd imagine?

Comment 3

[Ed Morley [:emorley]]

I've just looked at the WinXP debug m-oth logs of your push and the one prior, and get:

Prior:
mochitest-chrome: 23 mins, 26 secs
mochitest-browser-chrome: 1 hrs, 1 mins, 58 secs
mochitest-ally: 5 mins, 35 secs
mochitest-ipcplugins: 1 mins, 14 secs

After the SpecialPowers fixup:
mochitest-chrome: 39 mins, 13 secs
mochitest-browser-chrome: 1 hrs, 42 secs
mochitest-ally: 5 mins, 40 secs
mochitest-ipcplugins: 1 mins, 8 secs

Will attach the test runtimes for mochitest-chrome.

Comment 4

[Ed Morley [:emorley]]

Attachment: mochitest-chrome original

Comment 5

[Ed Morley [:emorley]]

Attachment: mochitest-chrome regressed

Comment 6

[Ed Morley [:emorley]]

Attachment: CSV with increases in descending order

Comment 7

[Bobby Holley (:bholley)]

Wow, awesome analysis Ed! Looks like the blame lies squarely with mochitest-chrome, which is lucky for our purposes, because most of the patches didn't touch mochitest-chrome at all. In fact, I'm pretty sure this was the only changeset that would have an affect on mochitest-chrome:

https://hg.mozilla.org/integration/mozilla-inbound/rev/1460d44ec8de

Comment 8

[Bobby Holley (:bholley)]

Investigating in a VM.

Comment 9

[Bobby Holley (:bholley)]

I've given up trying to reproduce this in a VM for the moment. Bisecting with some try pushes to test my theory about which commit we're dealing with:

https://tbpl.mozilla.org/?tree=Try&rev=00574bdb9666
https://tbpl.mozilla.org/?tree=Try&rev=2a2fd94ade0e
https://tbpl.mozilla.org/?tree=Try&rev=c2f895f02fed

Comment 10

[Bobby Holley (:bholley)]

Ok, the culprit patch was the one I predicted in comment 7. Subdividing that patch:

https://tbpl.mozilla.org/?tree=Try&rev=c4bcd76495b5
https://tbpl.mozilla.org/?tree=Try&rev=5bf9ad25c813
https://tbpl.mozilla.org/?tree=Try&rev=8fe5a715792b

Comment 11

[Bobby Holley (:bholley)]

Ok, so it looks like attaching the raw Components object is the culprit. That means either we're calling that function way too many times, or we're iterating over a gigantic number of scopes in FindInJSObjectScope. I added some logging that will tell us:

https://tbpl.mozilla.org/?tree=Try&rev=51f5b40ba655

Comment 12

[Bobby Holley (:bholley)]

Hm, looks like the issue _might_ be that we're iterating over a ton of scopes. I've fixed that over in my patches in bug 797821, so let's see if that fixes it:

https://tbpl.mozilla.org/?tree=Try&rev=6dfd704c8abb

Comment 13

[Ed Morley [:emorley]]

Just wanted to say thank you for your persistence with this! :-)

Comment 14

[Bobby Holley (:bholley)]

Ahah! I think I regressed bug 722428.

Comment 15

[Bobby Holley (:bholley)]

https://tbpl.mozilla.org/?tree=Try&rev=d8ca371a2e33

Comment 16

[Bobby Holley (:bholley)]

Attachment: Remove hard edge from SpecialPowers to window.Components. v1

Bingo. The hard edge here causes us to leak every window ever, a la bug 722428.

Kyle, did you ever figure out the pathology of this here? Why do we hold onto
the SpecialPowers object associated with the window after the window is gone?

It would be great if there was some way to test this...

Comment 17

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

No, I did not.

Comment 18

[Andrew McCreight [:mccr8]]

Sweet, now I have another hail-mary scapegoat for bug 792215!  Which leaks 20% of nsGlobalWindows, only on WinXP mochitest-chrome.  I'll see if that helps.

Comment 19

[Bobby Holley (:bholley)]

Attachment: Remove hard edge from SpecialPowers to window.Components. v2

Comment 20

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Comment on attachment 669739 [details] [diff] [review]
Remove hard edge from SpecialPowers to window.Components. v2

Review of attachment 669739 [details] [diff] [review]:
-----------------------------------------------------------------

I would be curious to know why Windows is more affected than the other platforms.

Comment 21

[Bobby Holley (:bholley)]

https://tbpl.mozilla.org/?tree=Try&rev=779d9b3290f4

Comment 22

[Bobby Holley (:bholley)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/3cb1f7ae777e

Comment 23

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/3cb1f7ae777e

Comment 24

[bhavana bajaj [:bajaj]]

Can this be uplifted to aurora as FF18 is affected and this may help us building faster :) ?

Comment 25

[Bobby Holley (:bholley)]

Comment on attachment 669739 [details] [diff] [review]
Remove hard edge from SpecialPowers to window.Components. v2

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 792036
User impact if declined: Mochitest-chrome runs take 20 minutes longer on win dbg.
Testing completed (on m-c, etc.): m-c
Risk to taking this patch (and alternatives if risky): extremely low risk. test only. 
String or UUID changes made by this patch: none

Comment 26

[bhavana bajaj [:bajaj]]

Comment on attachment 669739 [details] [diff] [review]
Remove hard edge from SpecialPowers to window.Components. v2

Approving on aurora as the patch is low risk and check comment 24

Comment 27

[Ed Morley [:emorley]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/62c040a3beba