1118852 - Report the pid and serial in the DOMWINDOW and DOCSHELL leak detector

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Andrew McCreight [:mccr8]]

This will make it much easier to investigate these leaks.  The PID should be reported on a separate INFO line in the log, so it doesn't interfere with starring.

Comment 1

[Andrew McCreight [:mccr8]]

I realized we should just print out the id for each leaking window and docshell as well.  This gives the following output:

TEST-UNEXPECTED-FAIL | browser/devtools/debugger/test/browser_dbg_e10s.js | leaked 3 window(s) until shutdown [url = about:blank]
TEST-UNEXPECTED-FAIL | browser/devtools/debugger/test/browser_dbg_e10s.js | leaked 2 window(s) until shutdown [url = chrome://mochitests/content/browser/browser/devtools/debugger/test/doc_e10s.html]
TEST-INFO | browser/devtools/debugger/test/browser_dbg_e10s.js | windows(s) leaked: [pid = 41842] [serial = 4], [pid = 41842] [serial = 5], [pid = 41842] [serial = 3], [pid = 41842] [serial = 6], [pid = 41842] [serial = 7]
TEST-UNEXPECTED-FAIL | browser/devtools/debugger/test/browser_dbg_e10s.js | leaked 2 docShell(s) until shutdown
TEST-INFO | browser/devtools/debugger/test/browser_dbg_e10s.js | docShell(s) leaked: [pid = 41842] [id = 3], [pid = 41842] [id = 2]

The format is the same as the original DOMWINDOW and DOCSHELL lines, so you can just search for "[pid = 41842] [serial = 4]" in the log and it will take you to exactly where the window was created and destroyed.

Comment 2

[Andrew McCreight [:mccr8]]

Attachment: Print out information about leaked DOM windows and doc shells.

I changed the key to a tuple instead of a string to make it easier to extract information from them later.

try run: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=064ca6424334

the DT failure is just a bogus test I added that isn't included in this patch.

Comment 3

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8546027 [details] [diff] [review]
Print out information about leaked DOM windows and doc shells.

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

::: build/automationutils.py
@@ +475,2 @@
>          self.logger.warning("TEST-UNEXPECTED-FAIL | %s | leaked %d window(s) until shutdown [url = %s]" % (test["fileName"], count, url))
> +      self.logger.info("TEST-INFO | %s | windows(s) leaked: %s" % (test["fileName"], test["leakedWindows"][1]))

Here and below I would put this in the same call to "warning" as the rest of the message (put a newline in the log message if that's more readable). The file name between two pipes should be enough to get a bug suggestion out of treeherder.

@@ +533,5 @@
>  
>      for test in self.tests:
> +      leakedWindows = [id for id in test["windows"] if id in self.leakedWindows]
> +      leakedWindowsString = ', '.join(["[pid = %s] [serial = %s]" % x for x in leakedWindows])
> +      test["leakedWindows"] = ([self.leakedWindows[id] for id in leakedWindows], leakedWindowsString)

len(test["leakedWindows"]) gets these appended to leakingTests, so in the try push there's an ominous "TEST-INFO | <file> | windows(s) leaked:" for each test that doesn't leak, too.

Comment 4

[Andrew McCreight [:mccr8]]

Attachment: interdiff

Comment 5

[Andrew McCreight [:mccr8]]

Attachment: Print out information about leaked DOM windows and doc shells.

Comment 6

[Andrew McCreight [:mccr8]]

(In reply to Chris Manchester [:chmanchester] from comment #3)
> Here and below I would put this in the same call to "warning" as the rest of
> the message (put a newline in the log message if that's more readable). The
> file name between two pipes should be enough to get a bug suggestion out of
> treeherder.

The added logging I put in is just showing the same information that we're already logging in the warning, just in a format that is appropriate for investigating the leak, not starring it on Treeherder, which is why I made it an info.  The serial numbers and process ids that this new logging adds are going to vary from run to run, so they are not appropriate as starring suggestions.  The idea is that you see the other warning, then go into the log, and use the new log information to figure out exactly where the leaking windows are created and go away.

> len(test["leakedWindows"]) gets these appended to leakingTests, so in the
> try push there's an ominous "TEST-INFO | <file> | windows(s) leaked:" for
> each test that doesn't leak, too.

Oops, good catch.  I have addressed that by adding a guard, as shown in the patch labelled interdiff.

Comment 7

[Chris Manchester (limited bugmail, email directly)]

(In reply to Andrew McCreight [:mccr8] from comment #6)
> (In reply to Chris Manchester [:chmanchester] from comment #3)
> > Here and below I would put this in the same call to "warning" as the rest of
> > the message (put a newline in the log message if that's more readable). The
> > file name between two pipes should be enough to get a bug suggestion out of
> > treeherder.
> 
> The added logging I put in is just showing the same information that we're
> already logging in the warning, just in a format that is appropriate for
> investigating the leak, not starring it on Treeherder, which is why I made
> it an info.  The serial numbers and process ids that this new logging adds
> are going to vary from run to run, so they are not appropriate as starring
> suggestions.  The idea is that you see the other warning, then go into the
> log, and use the new log information to figure out exactly where the leaking
> windows are created and go away.
I'm just thinking it might be even better for have "[url = about:blank] [pid = 5780] [serial = 85]" right there in the warning line, and I don't think that would interfere with starring. I'll leave it up to you. 
> 
> > len(test["leakedWindows"]) gets these appended to leakingTests, so in the
> > try push there's an ominous "TEST-INFO | <file> | windows(s) leaked:" for
> > each test that doesn't leak, too.
> 
> Oops, good catch.  I have addressed that by adding a guard, as shown in the
> patch labelled interdiff.

Comment 8

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8546748 [details] [diff] [review]
Print out information about leaked DOM windows and doc shells.

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

::: build/automationutils.py
@@ +539,2 @@
>        test["leakedDocShells"] = [id for id in test["docShells"] if id in self.leakedDocShells]
>        test["leakCount"] = len(test["leakedWindows"]) + len(test["leakedDocShells"])

Because leakCount is used to sort below, this can change the order of the windows printed. You can avoid this and the guard above by just making a new key for "leakedWindowsString" in "test".

Comment 9

[Andrew McCreight [:mccr8]]

(In reply to Chris Manchester [:chmanchester] from comment #8)
> Because leakCount is used to sort below, this can change the order of the
> windows printed. You can avoid this and the guard above by just making a new
> key for "leakedWindowsString" in "test".

Ah, that's a lot nicer anyways.

https://hg.mozilla.org/integration/mozilla-inbound/rev/0881f9a22f4a

Comment 10

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/0881f9a22f4a