728294 - Analyze cycle collection logs after test runs to detect leaks

Status: RESOLVED FIXED

(Testing :: General, defect)

Description

[Olli Pettay [:smaug][[e-mail]]]

Bug 726346 adds a way to analyze cycle collection logs in JS.
We could use that in testing so that we could detect if there are
(runtime) memory leak regressions.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1]]

For MemCaser I have filed an internal issue:
https://github.com/whimboo/memchaser/issues/73

Comment 2

[Marco Castelluccio [:marco]]

This could be useful also for Snappy, less leaks means more responsiveness.

Comment 3

[Nicholas Nethercote [inactive]]

Smaug, do you have any more specific ideas about how this would be done?  Would this be done in an add-on?

Comment 4

[Olli Pettay [:smaug][[e-mail]]]

An addon should work ok. It could run CC after each test and analyze the log to see if there are zombie documents - as an example

Comment 5

[Tim Taubert [:ttaubert] (inactive)]

Attachment: WIP

I started to write a patch for this some weeks ago but didn't find the time to continue/finish it. Maybe someone is willing to pick up the work.

Comment 6

[Tim Taubert [:ttaubert] (inactive)]

A good next step for the attached patch would be to track the creation of nsDocuments, assign those to the tests that created them. So we know which test leaked and can make them fail when printing the reports.

Comment 7

[Olli Pettay [:smaug][[e-mail]]]

CC log knows the URI of the documents.

Comment 8

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 1 - Remove old debug log parser

Comment 9

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 2 - Add GetOuterWindowAddress() to nsIDOMWindowUtils

Comment 10

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 3 - Add last opened URI to a refCounted node's description in debug mode

Comment 11

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 4 - Analyze cycle collection logs on testsuite shutdown to detected leaked windows

Comment 12

[Dão Gottwald [:dao]]

Comment on attachment 642547 [details] [diff] [review]
Part 4 - Analyze cycle collection logs on testsuite shutdown to detected leaked windows

>+const TODO_PERMANENT_LEAKS = {
>+  "chrome://mochitests/content/browser/browser/base/content/test/browser_pageInfo.js":
>+    "nsGlobalWindow chrome://browser/content/pageinfo/pageInfo.xul",
>+  "chrome://mochitests/content/browser/browser/components/places/tests/browser/browser_views_liveupdate.js":
>+    "nsGlobalWindow chrome://browser/content/bookmarks/bookmarksPanel.xul"

I disabled browser_pageInfo.js. Bug 759709 claims that browser_views_liveupdate.js leaks intermittently. If it's permanent, we should probably disable that test too.

By the way, does this roughly detect the same leaks that the previous logger did? Do you see the same amount of intermittent leaks?

Comment 13

[Tim Taubert [:ttaubert] (inactive)]

(In reply to Dão Gottwald [:dao] from comment #12)
> I disabled browser_pageInfo.js.

Ok, thank you for the hint.

> Bug 759709 claims that
> browser_views_liveupdate.js leaks intermittently. If it's permanent, we
> should probably disable that test too.

Looking at all the TBPL bot comments in bug 759711 it seems permanent to me. But I'm not totally sure about that. Couldn't reproduce it locally when running the test standalone.

> By the way, does this roughly detect the same leaks that the previous logger
> did? Do you see the same amount of intermittent leaks?

I don't know for sure, that's why I didn't ask for review, yet :) I pushed to try and hope to catch some intermittent leaks so that we'll see if this produces the same results as before just without blaming tests creating the tabview window or the preloaded new tab.

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

Comment 14

[Olli Pettay [:smaug][[e-mail]]]

Disabling tests? That doesn't sounds like a good idea. There has been times when some test has been
disabled and then before re-enabling it there were regressions which the test would have caught.
(But I'm not a browser/toolkit peer so if you think that won't be a problem, then ok :) )

Comment 15

[Dão Gottwald [:dao]]

browser_pageInfo.js doesn't cover anything important. I don't know about browser_views_liveupdate.js. Ideally whoever feels responsible for that code would care about the regression risk enough to invest in getting the test to run properly.

Comment 16

[Tim Taubert [:ttaubert] (inactive)]

So, even after quite a lot of m-oth try runs there was only one intermittent leak:

TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_sanitizeDialog.js | leaked window until shutdown [nsGlobalWindow chrome://browser/content/bookmarks/bookmarksPanel.xul]

That's actually the intermittent leak from browser/components/places/tests/browser/browser_views_liveupdate.js. I assigned it to the wrong test because my patch didn't assume that window addresses can be re-used, which I fixed now.

I actually hunted down the re-used address in the build log to confirm it's really this leak. We now know it's intermittent, too.

Comment 17

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 4 - Analyze cycle collection logs on testsuite shutdown to detected leaked windows

Patch takes now into account that window addresses can be re-used. Removed the todo leaks because there shouldn't be any permanent leaks left.

Comment 18

[Dão Gottwald [:dao]]

(In reply to Tim Taubert [:ttaubert] from comment #16)
> So, even after quite a lot of m-oth try runs there was only one intermittent
> leak:

So, will your changes cause us to miss things we don't want to miss or are the current intermittent leaks false reports?

Comment 19

[Tim Taubert [:ttaubert] (inactive)]

(In reply to Dão Gottwald [:dao] from comment #18)
> So, will your changes cause us to miss things we don't want to miss or are
> the current intermittent leaks false reports?

I pushed to try again because I think the current reports aren't false. I was only listening to "domwindowopened" which only fires for 'real windows' being opened.

The patch does now register observers for "{chrome,content}-document-global-created" which should cover every nsGlobalWindow instance created, including iframes and inner windows when navigating to a different page.

I'll expect more intermittent leaks to appear because some of them are not about the whole window but only an inner window.

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

Comment 20

[Olli Pettay [:smaug][[e-mail]]]

(In reply to Tim Taubert [:ttaubert] from comment #16)
> So, even after quite a lot of m-oth try runs there was only one intermittent
> leak:
> 
> TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/browser/browser/base/content/test/
> browser_sanitizeDialog.js | leaked window until shutdown [nsGlobalWindow
> chrome://browser/content/bookmarks/bookmarksPanel.xul
Is this Bug 728426 ?

Comment 21

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 642544 [details] [diff] [review]
Part 2 - Add GetOuterWindowAddress() to nsIDOMWindowUtils

You should put IsUniversalXPConnectCapable() check to nsDOMWindowUtils::GetOuterWindowAddress

Comment 22

[Tim Taubert [:ttaubert] (inactive)]

(In reply to Olli Pettay [:smaug] from comment #20)
> Is this Bug 728426 ?

Possibly? It's definitely bug 759709 which no one took care of so far. They should probably depend on each other.

(In reply to Olli Pettay [:smaug] from comment #21)
> You should put IsUniversalXPConnectCapable() check to
> nsDOMWindowUtils::GetOuterWindowAddress

Thanks, will do!

Comment 23

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 2 - Add GetOuterWindowAddress() to nsIDOMWindowUtils

Added a IsUniversalXPConnectCapable() check at the top of GetOuterWindowAddress().

Comment 24

[Tim Taubert [:ttaubert] (inactive)]

> TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_breakpoint-new-script.js | leaked window until shutdown [nsGlobalWindow http://example.com/browser/browser/devtools/debugger/test/browser_dbg_breakpoint-new-script.html]

> TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_urlbarCopying.js | leaked window until shutdown [nsGlobalWindow chrome://browser/content/bookmarks/bookmarksPanel.xul]

That's browser_views_liveupdate.js again, dammit.

> TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_tab_dragdrop.js | leaked window until shutdown [nsGlobalWindow chrome://browser/content/bookmarks/bookmarksPanel.xul]

Also browser_views_liveupdate.js.


All of these bookmarksPanel.xul leaks were inner windows that re-used addresses from outer windows and that's why there were assigned to the wrong tests. That means we should also be missing some other leaks here that didn't re-use an outer window's address. Still need to figure this out but everything else looks like we have the same intermittent leaks as before just without the false positives. Hooray.

Comment 25

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 2 - Add inner-window-created notification for debug builds

Mapping windows to addresses is hard, they're re-used. We should instead use the window's id and listen for inner windows, only. Outer windows will only be kept alive by inner windows and inner windows have URLs that we can use for debugging and fixing those leaks.

Comment 26

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 3 - Add last opened URI and windowID to a refCounted node's description in debug mode

We need the leaked url and the window id as well.

Comment 27

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 4 - Analyze cycle collection logs on testsuite shutdown to detected leaked windows

Comment 28

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 1 - Remove old debug log parser

This removes the old leak analyzer that parses stdout in debug builds.

Comment 29

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 2 - Add global-window-created notification for debug builds

We currently have {outer,inner}-window-destroyed notifications but there's no similar thing when windows are created.

The leak detection does not differentiate between outer and inner windows, that's why there's only a "global-window-created" notification and it's only fired in debug mode.

Do you think we should have {outer,inner}-window-created notifications for opt and dbg builds or would it be fine to leave it as is? I'm not sure that having a notification debug-only is a good thing :)

Comment 30

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 2 - Add last opened URI and windowID to a refCounted node's description in debug mode

Debug info, yay!

Comment 31

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 4 - Analyze cycle collection logs on testsuite shutdown to detected leaked windows

Comment 32

[Olli Pettay [:smaug][[e-mail]]]

There is chrome/content-document-global-created

Comment 33

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 644884 [details] [diff] [review]
Part 2 - Add last opened URI and windowID to a refCounted node's description in debug mode

"chrome-document-global-created"/"content-document-global-created"
should be enough.
Subject is the window and you can get inner/outerwindow id using
the methods in DOMWindowUtils, IIRC.

Comment 34

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 644884 [details] [diff] [review]
Part 2 - Add last opened URI and windowID to a refCounted node's description in debug mode

Er, I managed to r- wrong patch.

Comment 35

[Tim Taubert [:ttaubert] (inactive)]

Comment on attachment 644883 [details] [diff] [review]
Part 2 - Add global-window-created notification for debug builds

(In reply to Olli Pettay [:smaug] from comment #33)
> "chrome-document-global-created"/"content-document-global-created"
> should be enough.
> Subject is the window and you can get inner/outerwindow id using
> the methods in DOMWindowUtils, IIRC.

That's easier. We don't need this patch.

Comment 36

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 3 - Analyze cycle collection logs on testsuite shutdown to detected leaked windows

Using {chrome,content}-document-global-created now.

Comment 37

[Tim Taubert [:ttaubert] (inactive)]

I'm still working on this. Trying to sort out a problem with patch 2 where it doesn't always show the right URL - it's sometimes "(null)" - which is quite tedious with the current try situation and given that all those leaks are of course intermittent...

Comment 38

[(not currently active) Ted Mielczarek]

Comment on attachment 644909 [details] [diff] [review]
Part 3 - Analyze cycle collection logs on testsuite shutdown to detected leaked windows

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

::: testing/mochitest/browser-test.js
@@ +61,5 @@
>               getService(Ci.nsIWindowMediator);
>    this._fm = Cc["@mozilla.org/focus-manager;1"].
>               getService(Ci.nsIFocusManager);
> +  this._os = Cc["@mozilla.org/observer-service;1"].
> +             getService(Ci.nsIObserverService);

We could probably switch some of these to use Services.jsm.

@@ +212,5 @@
> +    let utils = aWindow.QueryInterface(Ci.nsIInterfaceRequestor)
> +                       .getInterface(Ci.nsIDOMWindowUtils);
> +
> +    let outerID = utils.outerWindowID;
> +    if (!this.openedWindows.hasOwnProperty(outerID))

Is hasOwnPropery overkill here, can't you just use "outerID in this.openedWindows"?

Alternately, if you wanted to be more bleeding-edge you could use Map.

::: testing/mochitest/cc-analyzer.js
@@ +1,5 @@
> +/* This Source Code Form is subject to the terms of the Mozilla Public
> + * License, v. 2.0. If a copy of the MPL was not distributed with this file,
> + * You can obtain one at http://mozilla.org/MPL/2.0/. */
> +
> +function CCAnalyzer() {

I don't really have the brain cycles to figure out how this CCAnalyzer works. Can you have someone who knows the CC review this bit?

Comment 39

[Andrew McCreight [:mccr8]]

Yeah, smaug or I can probably review the CCAnalyzer.

Comment 40

[(not currently active) Ted Mielczarek]

Comment on attachment 644909 [details] [diff] [review]
Part 3 - Analyze cycle collection logs on testsuite shutdown to detected leaked windows

Just marking this for r? so it doesn't get forgotten.

Comment 41

[Tim Taubert [:ttaubert] (inactive)]

Ok, here's a question that I wanted to ask mccr8 yesterday but I figured more people CC'ed here might answer this:

I'm having quite a hard time with part 2 of this bug. All we need to have is the windowID (which works fine) and the last opened URL as the description for the refcounted node.

Now, when running these patches on try I sometimes get a correct url and sometimes I just get "(null)" which doesn't really make sense because nsGlobalWindow::mLastOpenedURI is never set to null anywhere and we're cycle collecting even before nsGlobalWindow's destructor is called (that is able to print the correct url).

https://tbpl.mozilla.org/php/getParsedLog.php?id=13878699&tree=Try&full=1

If you search for "serial = 10148" in the build log you see the debug output we get from nsGlobalWindow's constructor and its destructor. Both show the correct URL. The refcounted node's description contains "(null)" for whatever reason:

> TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/social/test/browser/browser_workerAPI.js | leaked until shutdown [nsGlobalWindow #10148 (null)]

Another thing I don't understand is, that the window is clearly an inner window when created:

> ++DOMWINDOW == 93 (0xf0dd484) [serial = 10148] [outer = 0xb12c9b0]

When destroyed it seems like mOuterWindow is null:

> --DOMWINDOW == 3 (0xf0dd484) [serial = 10148] [outer = (nil)] [url = https://motown-dev.mozillalabs.com/social/sidebar]

although we never explicitly set it to null. If someone has any idea what's going on I'd really appreciate some help as that is the last part we need for this bug to be fixed. We can't land this without proper URLs to debug the leaks.

Comment 42

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 644909 [details] [diff] [review]
Part 3 - Analyze cycle collection logs on testsuite shutdown to detected leaked windows

>+  runCC: function (aCounter) {
>+    let utils = window.QueryInterface(Ci.nsIInterfaceRequestor).
>+        getInterface(Ci.nsIDOMWindowUtils);
>+
>+    if (aCounter > 1) {
>+      utils.garbageCollect();
>+      setTimeout(this.runCC.bind(this, aCounter - 1), 125);
Why 125? If this needs to be async, wouldn't 0 be just fine?


>+  processLog: function () {
>+    // Process entire heap step by step in 5K chunks
>+    for (let i = 0; i < 5000; i++) {
>+      if (!this.listener.processNext(this)) {
>+        this.callback();
>+        this.clear();
>+        return;
>+      }
>+    }
>+
>+    // Next chunk on timeout.
>+    setTimeout(this.processLog.bind(this), 125);
Same here

Not all the stuff in the analyzer is needed by the patch, but they can be useful for debugging.

Comment 43

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 2 - Add windowID to a refCounted node's description

As stated in comment #41, printing the mLastOpenedURI isn't reliable for some reason. The new solution is to record window.location.href on "chrome-document-global-created" and "content-document-global-created" which is implemented in part 3.

mLastOpenedURI was debug-only, so the good thing now is that we have leak detection for opt builds as well!

Comment 44

[Tim Taubert [:ttaubert] (inactive)]

Attachment: Part 3 - Analyze cycle collection logs on testsuite shutdown to detected leaked windows

Addresses all comments and using Services.jsm now where possible. Recording the window's location on "chrome-document-global-created" and "content-document-global-created" to have reliable debug URLs.

Comment 45

[Tim Taubert [:ttaubert] (inactive)]

After a couple of test runs I found six instances of

browser_workerAPI.js | leaked until shutdown [nsGlobalWindow #10396 https://motown-dev.mozillalabs.com/social/sidebar]

always with the right URL assigned to it which means that the patch works as expected.

Comment 46

[Olli Pettay [:smaug][[e-mail]]]

Do we actually need to remove the old leak detector? It can, as far as I know, detect different kinds 
of problems. Cycle collector graph tells what ends up being traversed during CC
(so it affects especially to responsiveness), but if a leaked global window doesn't end up to
cc graph, the leak won't be noticed. (I don't know whether it is in practice possible to
get globalwindow leaks which don't show up in the cc graph)

Comment 47

[Tim Taubert [:ttaubert] (inactive)]

I don't know about the different kinds of leaks it can detect and whether it's in practice possible to get globalwindow leaks which then don't show up in the cc graph. But the old leak detector causes quite some trouble with its false-positives. We'd need to introduce some kind of exclusion list for every new feature that expectedly "leaks" like bug 753448 or anything touching the sidebar that then leaks the outer window.

Comment 48

[Olli Pettay [:smaug][[e-mail]]]

Ah, I see.

Comment 49

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 648307 [details] [diff] [review]
Part 3 - Analyze cycle collection logs on testsuite shutdown to detected leaked windows

I guess this could work well enough.
There are cases when we reuse innerwindow, hopefully they
don't affect to output badly.

Comment 50

[Tim Taubert [:ttaubert] (inactive)]

Thank you, reviewers!

https://hg.mozilla.org/integration/fx-team/rev/c10c3ac392d5
https://hg.mozilla.org/integration/fx-team/rev/80367942e54c
https://hg.mozilla.org/integration/fx-team/rev/c3b7cfd70d37

Comment 51

[Rob Campbell [:rc] (:robcee)]

https://hg.mozilla.org/mozilla-central/rev/c10c3ac392d5
https://hg.mozilla.org/mozilla-central/rev/80367942e54c
https://hg.mozilla.org/mozilla-central/rev/c3b7cfd70d37

Comment 52

[Ed Morley [:emorley]]

Aurora/beta are affected by the steady stream of false positives from the old ShutdownLeakLogger. Is this something you would be happy to backport to one or both, or should I file a bug to raise the MAX_LEAK_COUNT on them, now that we know most of the leaking tests are false positives?

Comment 53

[Tim Taubert [:ttaubert] (inactive)]

Attachment: patch for aurora

Consolidated patches for Aurora.

Comment 54

[Tim Taubert [:ttaubert] (inactive)]

Attachment: patch for beta

Consolidated patches for Beta.

Comment 55

[Tim Taubert [:ttaubert] (inactive)]

Comment on attachment 649104 [details] [diff] [review]
patch for aurora

[Approval Request Comment]
Bug caused by (feature/regressing bug #): None.
User impact if declined: None.
Testing completed (on m-c, etc.): Landed on m-c.
Risk to taking this patch (and alternatives if risky): Very low risk, affects mochitest suite only.
String or UUID changes made by this patch: None.

We have quite a few false positives on Beta/Aurora. Applying those patches would certainly take some load off of the tree maintainers.

Comment 56

[Tim Taubert [:ttaubert] (inactive)]

Comment on attachment 649105 [details] [diff] [review]
patch for beta

[Approval Request Comment]
Bug caused by (feature/regressing bug #): None.
User impact if declined: None.
Testing completed (on m-c, etc.): Landed on m-c.
Risk to taking this patch (and alternatives if risky): Very low risk, affects mochitest suite only.
String or UUID changes made by this patch: None.

We have quite a few false positives on Beta/Aurora. Applying those patches would certainly take some load off of the tree maintainers.

Comment 57

[Lukas Blakk [:lsblakk] use ?needinfo]

Comment on attachment 649105 [details] [diff] [review]
patch for beta

low risk, glad it helps with tree maintenance too, approving.

Comment 58

[Tim Taubert [:ttaubert] (inactive)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/60af41022814
https://hg.mozilla.org/releases/mozilla-beta/rev/74e523bf1a7d

Comment 59

[Tim Taubert [:ttaubert] (inactive)]

Backed out :/

https://hg.mozilla.org/releases/mozilla-aurora/rev/59cd03317e0b
https://hg.mozilla.org/releases/mozilla-beta/rev/078ece5918e2

I totally forgot about bug 728426 which turned perma-orange. We need to wait until this has approval as well.

Comment 60

[Jordan Lund (:jlund)]

thought it worth mentioning even if you are all more familiar then me. Currently, buildbot will append a tinderboxprint line to each unittest logs which is parsed by the tbpl web interface and provides summaries like if a test leaked or not. (note this is not for setting the appropriate result colour)

Our regex looks like(for mochitest and others): 

harnessErrorsRe = re.compile(r"TEST-UNEXPECTED-FAIL \| .* \| (Browser crashed \(minidump found\)|missing output line for total leaks!|negative leaks caught!|leaked \d+ bytes during test execution)")

if this is out of date with any new changes, I would be happy to help make sure we stay current on our end.

this code is from summarizeLog():
http://mxr.mozilla.org/build/source/buildbotcustom/steps/unittest.py#77

Comment 61

[Serge Gautherie (:sgautherie)]

(In reply to Jordan Lund (:jlund) from comment #60)
> harnessErrorsRe = re.compile(r"TEST-UNEXPECTED-FAIL \| .* \| (Browser
> crashed \(minidump found\)|missing output line for total leaks!|negative
> leaks caught!|leaked \d+ bytes during test execution)")

Iirc, (the end of) this regex is related to --enable-logrefcnt.
New cc-analyzer is something different, as removed ShutdownLeakLogger was.
I don't know whether new strings should be added, but none should be removed (wrt this bug).

Comment 62

[Tim Taubert [:ttaubert] (inactive)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/72fbc3c75407
https://hg.mozilla.org/releases/mozilla-beta/rev/e6e93246223e