Last Comment Bug 770993 - ConsoleAPI.js consumes excessive amounts of memory
: ConsoleAPI.js consumes excessive amounts of memory
Status: RESOLVED FIXED
[MemShrink:P1]
:
Product: Firefox
Classification: Client Software
Component: Developer Tools: Console (show other bugs)
: Trunk
: All All
: P1 major (vote)
: Firefox 16
Assigned To: Mihai Sucan [:msucan]
: developer.tools.console
Mentors:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2012-07-04 13:43 PDT by Nathan Froyd [:froydnj]
Modified: 2012-07-12 17:58 PDT (History)
14 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
fixed


Attachments
proposed patch (14.21 KB, patch)
2012-07-06 08:44 PDT, Mihai Sucan [:msucan]
rcampbell: review+
dbaron: review+
Details | Diff | Review
address review comments (14.72 KB, patch)
2012-07-07 03:57 PDT, Mihai Sucan [:msucan]
dbaron: review+
Details | Diff | Review
patch for aurora (14.21 KB, patch)
2012-07-08 03:22 PDT, Mihai Sucan [:msucan]
dbaron: review+
gavin.sharp: approval‑mozilla‑aurora+
Details | Diff | Review

Description Nathan Froyd [:froydnj] 2012-07-04 13:43:32 PDT
about:memory currently says:

2,900,670,167 B (100.0%) -- explicit
├──2,031,995,248 B (70.05%) -- js
│  ├──1,090,516,296 B (37.60%) -- compartment([System Principal], jar:file:///home/froydnj/firefox/omni.ja!/components/ConsoleAPI.js)
│  │  ├──1,088,821,072 B (37.54%) -- objects
│  │  │  ├──1,088,678,736 B (37.53%) ── elements
│  │  │  └────────142,336 B (00.00%) ── slots

which seems a tad over-the-top.  Not sure what's causing it; I haven't opened the Web Console this browser session.  This browser is Aurora from ~1 month ago.
Comment 1 Justin Lebar (not reading bugmail) 2012-07-04 18:44:28 PDT
I'd guess that this was caused by bug 722685, which batches up calls to the console API.  But looking through the code (there's not a lot), it seems correct, so long as our timers fire as often as they claim to...

Or perhaps this compartment counts memory allocated outside ConsoleAPI.js as well?
Comment 2 Nicholas Nethercote [:njn] 2012-07-04 18:59:20 PDT
This line:

> │  │  │  ├──1,088,678,736 B (37.53%) ── elements

indicates the presence of many array elements.  Perhaps a single huge one?
Comment 3 Mihai Sucan [:msucan] 2012-07-05 01:22:07 PDT
This is interesting. The _queuedCalls array is spliced for every timer call, until it's empty. I'm quite positive that the code correctly empties the queue.

The only problem could be with ConsoleAPIStorage which does actual storing of messages and keeps them around until the message-owning window is destroyed.

Did you notice this with a long running process? Do you have some steps to reproduce?
Comment 4 Nathan Froyd [:froydnj] 2012-07-05 03:36:54 PDT
(In reply to Mihai Sucan [:msucan] from comment #3)
> Did you notice this with a long running process? Do you have some steps to
> reproduce?

The firefox that I observed this in has 45 hours of CPU time, so yes, it's been up for a while.  I don't have good steps to reproduce.  I suppose I could restart with something newer, preferably with bug 722685 fixed, and let that go for another two weeks to see if the same thing happens...
Comment 5 Mihai Sucan [:msucan] 2012-07-05 03:57:21 PDT
Does that mean you did not have bug 722685 landed in the build you used?
Comment 6 Nathan Froyd [:froydnj] 2012-07-05 04:50:05 PDT
(In reply to Mihai Sucan [:msucan] from comment #5)
> Does that mean you did not have bug 722685 landed in the build you used?

Oops.  I do; my build is 15.0a2 (2012-06-09), which is definitely post bug 722685.
Comment 7 Mihai Sucan [:msucan] 2012-07-05 04:55:59 PDT
What kind of browsing do you do? Do you heavily exercise the console API hourly, daily? Do you visit specific sites? Please provide as much detail as you can. Thanks!

What kind of web apps do you build?

(i'm trying to determine if there's any pattern that would allow us to reproduce this issue quicker)
Comment 8 Justin Lebar (not reading bugmail) 2012-07-05 08:03:07 PDT
It seems quite likely to me that the STR here is "spam the console API".  It's not clear whether console.log would be sufficient, or whether you'd have to spam one of the other methods.

Can you try that, Mihai?

> The only problem could be with ConsoleAPIStorage which does actual storing of messages and keeps 
> them around until the message-owning window is destroyed.

Could be.  But I'd expect ConsoleAPIStorage to get its own compartment.  And if we were storing the messages themselves, that would show up as "strings" in about:memory, not "slots".
Comment 9 Mihai Sucan [:msucan] 2012-07-05 08:06:28 PDT
(In reply to Justin Lebar [:jlebar] from comment #8)
> It seems quite likely to me that the STR here is "spam the console API". 
> It's not clear whether console.log would be sufficient, or whether you'd
> have to spam one of the other methods.
> 
> Can you try that, Mihai?

Will do, as soon as possible. I know that was one of the main tests we did, and I didn't notice any such problems. Maybe I didn't "spam enough".
Comment 10 Nathan Froyd [:froydnj] 2012-07-05 20:01:10 PDT
(In reply to Mihai Sucan [:msucan] from comment #7)
> What kind of browsing do you do? Do you heavily exercise the console API
> hourly, daily? Do you visit specific sites? Please provide as much detail as
> you can. Thanks!
> 
> What kind of web apps do you build?
> 
> (i'm trying to determine if there's any pattern that would allow us to
> reproduce this issue quicker)

See, that's the funny thing.  I don't--so far as I know--exercise the console API at all; I'm not building web apps or anything that would touch the console API.  The browsing session on that computer has 4 windows with ~100 tabs, with a good chunk of those open-but-not-yet-restored.  I use Gmail, a couple of Github pages, Zimbra, a web page app for my music player, possibly Tinderbox pushlog...those are the only dynamic-ish sites that spring to mind.  I'm not near the browser session currently or I'd do a fuller inventory.

I think the only interesting addon I have is Download Statusbar; I'll double-check when I get back in touch with the computer.
Comment 11 Josh Matthews [:jdm] 2012-07-05 21:10:44 PDT
I saw this issue and commented about it on IRC no more than a week or two ago. I recall being confused because the web consoles in the tabs I had open didn't show anything particularly interesting.
Comment 12 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-05 22:05:52 PDT
I'm currently seeing:

4,415,361,485 B (100.0%) -- explicit
├──3,963,428,648 B (89.76%) -- js
│  ├──3,331,040,440 B (75.44%) -- compartment([System Principal], file:///home/dbaron/bin/running-firefox/components/ConsoleAPI.js)
│  │  ├──3,325,688,104 B (75.32%) -- objects
│  │  │  ├──3,325,250,864 B (75.31%) ── elements
│  │  │  ├────────428,888 B (00.01%) ── slots
│  │  │  └──────────8,352 B (00.00%) ── misc

in a Linux 64-bit debug build built off of https://hg.mozilla.org/mozilla-central/rev/e116a5da6ced plus the patch queue in https://hg.mozilla.org/users/dbaron_mozilla.com/patches/rev/e64ee438d582 pushed up to unitless-length-quirk.
Comment 13 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-05 22:06:51 PDT
(And I started this browser session at Wed Jun 20 10:12:54 PDT 2012, and I have all of its console output.)
Comment 14 Justin Lebar (not reading bugmail) 2012-07-05 22:36:34 PDT
Requesting tracking FF15 and FF16.  We don't know that this bug is present in FF15, but our guess is that this bug is a regression from bug 722685, which landed in FF15.  This is a /huge/ memory leak that will cause paging and OOM crashes for people on 32-bit builds.
Comment 15 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-05 23:19:31 PDT
So after looking at that patch, I started getting suspicious of the _destroyedWindows property.  Isn't that going to collect the ID of every destroyed window, ever?

And then I looked at my gc dump, and found there are 5156 distinct objects with a _destroyedWindows property, which also puzzles me, since I was expecting this thing to be a global based on the way the code works.

And then I started to read the code:  it looks like this isn't a system-wide global; instead a separate instance is the console property on each window object (or at least each window object on which code touches window.console), if I'm understanding correctly.  So it looks like *every* window's window.console object has an array of every window ID that was destroyed following the creation of that window's console object.  Given how frequently windows are created and destroyed on some pages (as a data point, there have been 394656 inner windows destroyed in my current browsing session, based on the --DOMWINDOW console output), this seems like it could add up to a *lot* of memory very quickly.  (I don't think these arrays are going to show up in the gc-edges-*.log output themselves, though, since they're integers and therefore not gc edges.)

If I assumed that every window.console had been around the entire life of the browser, and that theory is correct, then that would mean I'd have a little over 2 billion items in _destroyedWindows arrays.  That's obviously way too high, but I'd expect it to be since most windows haven't been around the whole lifetime of the browser.
Comment 16 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-05 23:23:04 PDT
So, to briefly sum up:  I think this is O(N^2) memory usage since every window's console object's _destroyedWindows property has a list of all windows destroyed after the creation of that window's console object.
Comment 17 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-05 23:32:10 PDT
Oh, and the other saving grace, memory-wise, is that we clear a page's list whenever it actually uses a window.console method.  But I'd expect many pages to use window.console methods quite infrequently, especially (and hopefully) when they're in a background tab.

Still, this code fails to make sense on a number of levels.
Comment 18 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-05 23:59:34 PDT
I guess I should be a little clearer about what I don't like about the code (in all cases, assuming I'm understanding it correctly):

 1) It should not have an "inner-window-destroyed" observer on *every* window's console object.  If console objects need to know about windows being destroyed, they should learn about their window being destroyed, or perhaps child windows as well.  This notification makes closing a single window O(N) in the number of windows, and makes shutting down O(N^2) in the number of windows.

 2) The O(N^2) storage problem described above.

 3) While I'm on the topic of (1), an object that's per window shouldn't have an "xpcom-shutdown" observer either.  If we're failing to destroy anything that's per-window by the time we hit XPCOM shutdown, there's no reason to believe that failure is due to recently-closed windows rather than long-since-closed windows for which the object should have been freed long ago.  The only thing such an observer can do is hide leaks from our leak tools.

 4) Worse, the addObserver calls tell the observer service to hold strong references and the removeObserver calls are in the xpcom-shutdown notification, so the ConsoleAPI object itself is in fact one of the leaks that (3) disguises.  If I'm reading this correctly, every ConsoleAPI object is leaked until XPCOM shutdown, including those that are for windows long-since closed.

Summary: per-window objects probably shouldn't be registering with the observer service at all, and definitely not this way
Comment 19 Mihai Sucan [:msucan] 2012-07-06 01:55:24 PDT
dbaron: thanks for your analysis. The xpcom-shutdown was the approach we used previously. I added tracking for inner-window-destroyed because we need to skip messages for windows that are already destroyed by when the timer executes.

I will look into writing a patch today to address your analysis.

Regarding point 4: how do you suggest we fix this issue?

Thank you again!
Comment 20 Justin Lebar (not reading bugmail) 2012-07-06 06:07:21 PDT
> Regarding point 4: how do you suggest we fix this issue?

You could use a weak map with the window as a key and the console API as the value.  Then have the observer service hold a weak reference to the console API object.  That will keep the console API object alive as long as the window is alive.
Comment 21 Mihai Sucan [:msucan] 2012-07-06 08:44:50 PDT
Created attachment 639691 [details] [diff] [review]
proposed patch

Did some testing and I was able to reproduce the excessive memory use.

STR:

1. open an empty page with <script>window.console;</script>
   (you need to access the console object to have our ConsoleAPI.init() method execute, otherwise, our code doesn't execute. Also, don't call any method, to avoid any cleanups)
2. refresh endlessly and see about:memory. You will notice how ConsoleAPI.js slowly uses more and more memory.

Also did some checks and I can confirm we've been long time leaking ConsoleAPI objects, even before bug 722685. It seems there is some confusion in the ConsoleAPI code regarding the lifetime of the object. Unfortunately, with bug 722685 I made the leak bigger - apologies for that!

Did some testing and I came to the conclusion that a new ConsoleAPI instance is created for every new inner window. Please correct me if I am wrong. With this in mind, I made changes to the code to be consistent throughout: we use the ConsoleAPI object instance to keep any information we want.

I still have an observer for the inner-window-destroyed topic, but this time it tracks the destruction of its own window. Based on testing, it seems this works - every new window is also destroyed at some later point in time and we can use that to cleanup.

With this patch I no longer have excessive memory use with the STR provided above. I also tried several hundreds of thousands of calls to the window.console API (both with simple string and objects) - memory use was not excessive in these cases either.

Justin: thanks for your reply and suggestion. I have already completed this patch by the time I saw your comment. Probably my solution is the best one, so please let me know if you want any changes. Thanks!
Comment 22 Rob Campbell [:rc] (:robcee) 2012-07-06 10:22:41 PDT
Comment on attachment 639691 [details] [diff] [review]
proposed patch

   _timerCallback: function CA__timerCallback()
   {
     this._queuedCalls.splice(0, MESSAGES_IN_INTERVAL)
       .forEach(this._processQueuedCall, this);
 
     if (!this._queuedCalls.length) {
       this._timerInitialized = false;
-      this._destroyedWindows = [];
-      gTimer.cancel();
+      this._timer.cancel();
+
+      if (this._windowDestroyed) {
+        ConsoleAPIStorage.clearEvents(this._innerID);
+        this._window = null;
+        this.timerRegistry = {};
+      }
     }

no way to abort running timers from the inner_window_destroyed observer? The timer.cancel() method looks like it should do the right thing, then you can move your tear-down code into the observer and not wait on the timer to complete or require the _windowDestroyed variable.

I'm ok with the rest of the changes, nothing leaps out at me, but I think dbaron should have the final review pass as he's already done the analysis here.
Comment 23 Mihai Sucan [:msucan] 2012-07-06 11:32:56 PDT
(In reply to Rob Campbell [:rc] (:robcee) from comment #22)
> Comment on attachment 639691 [details] [diff] [review]
> proposed patch
> 
>    _timerCallback: function CA__timerCallback()
>    {
>      this._queuedCalls.splice(0, MESSAGES_IN_INTERVAL)
>        .forEach(this._processQueuedCall, this);
>  
>      if (!this._queuedCalls.length) {
>        this._timerInitialized = false;
> -      this._destroyedWindows = [];
> -      gTimer.cancel();
> +      this._timer.cancel();
> +
> +      if (this._windowDestroyed) {
> +        ConsoleAPIStorage.clearEvents(this._innerID);
> +        this._window = null;
> +        this.timerRegistry = {};
> +      }
>      }
> 
> no way to abort running timers from the inner_window_destroyed observer? The
> timer.cancel() method looks like it should do the right thing, then you can
> move your tear-down code into the observer and not wait on the timer to
> complete or require the _windowDestroyed variable.

If we cancel the timer, we create unexpected behavior: the window.console API calls that are very close to (but before) window destroy will not show in the consumers of the console api notifications - eg. they wouldn't show in the Web Console. We need to ensure we process all of the console api calls, even if the window was destroyed.

(I saw web console tests breaking because of such behavior - not processing queued calls for already-destroyed windows.)

> I'm ok with the rest of the changes, nothing leaps out at me, but I think
> dbaron should have the final review pass as he's already done the analysis
> here.

Thank you! I hope I didn't miss anything.
Comment 24 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-06 13:38:45 PDT
Comment on attachment 639691 [details] [diff] [review]
proposed patch

Are these ConsoleAPI objects per-outer-window or per-inner-window?  That would help for understanding this patch.  (And also something that would probably be useful in a code comment.)

Using the observer service for inner-window-destroyed still is far from ideal (though this patch is still a big improvement on the situation, so I wouldn't block it on that basis).  It sort of seems like perhaps nsIDOMGlobalPropertyInitializer should offer a notification that the window is going away, but if that's hard jlebar's weak map suggestion seems good.

>     // Store non-private messages for which the inner window was not destroyed.
>-    if (!aMeta.isPrivate && this._destroyedWindows.indexOf(aMeta.innerID) == -1) {
>-      ConsoleAPIStorage.recordEvent(aMeta.innerID, consoleEvent);
>+    if (!aMeta.isPrivate) {
>+      ConsoleAPIStorage.recordEvent(this._innerID, consoleEvent);
>     }

This change seems problematic, since it means that the ConsoleAPIStorage code will now be storing these events forever.  (The reason for this check, I think, was that it's after the point at which ConsoleAPIStorage has cleared its list for that window.  Also the sort of thing that's useful to say in a code comment -- unlike the code comment that's there which only states what's obvious.)
Comment 25 Mihai Sucan [:msucan] 2012-07-06 14:09:07 PDT
(In reply to David Baron [:dbaron] from comment #24)
> Comment on attachment 639691 [details] [diff] [review]
> proposed patch
> 
> Are these ConsoleAPI objects per-outer-window or per-inner-window?  That
> would help for understanding this patch.  (And also something that would
> probably be useful in a code comment.)

Based on testing, it looked like they are per-inner-window. However, I am not 100% sure. Who can we ask about this?


> Using the observer service for inner-window-destroyed still is far from
> ideal (though this patch is still a big improvement on the situation, so I
> wouldn't block it on that basis).  It sort of seems like perhaps
> nsIDOMGlobalPropertyInitializer should offer a notification that the window
> is going away, but if that's hard jlebar's weak map suggestion seems good.

I wish we had a notification for when the object goes away. Who can tell us how hard is to have this capability?


> >     // Store non-private messages for which the inner window was not destroyed.
> >-    if (!aMeta.isPrivate && this._destroyedWindows.indexOf(aMeta.innerID) == -1) {
> >-      ConsoleAPIStorage.recordEvent(aMeta.innerID, consoleEvent);
> >+    if (!aMeta.isPrivate) {
> >+      ConsoleAPIStorage.recordEvent(this._innerID, consoleEvent);
> >     }
> 
> This change seems problematic, since it means that the ConsoleAPIStorage
> code will now be storing these events forever.  (The reason for this check,
> I think, was that it's after the point at which ConsoleAPIStorage has
> cleared its list for that window.  Also the sort of thing that's useful to
> say in a code comment -- unlike the code comment that's there which only
> states what's obvious.)

Good point, but do note that I call clearEvents(innerWindowID) when the timer callback ends, if the window is destroyed. So, this is no longer an issue - objects in ConsoleAPIStorage will be cleared.

Also, it would be expected that all console api calls go through the storage - we have notifications for each call object being stored. If we skip calls like this, we break the expected behavior.

If you believe it's better, I can add a check for this._windowDestroyed in the if condition - to skip sending the messages to console storage.

Thank you!
Comment 26 Justin Lebar (not reading bugmail) 2012-07-06 14:34:37 PDT
> I wish we had a notification for when the object goes away. Who can tell us how hard is to have this 
> capability?

You want something that's exactly like inner-window-destroyed, but instead of a global notification, you can subscribe to a notification just for one window?

That wouldn't be particularly hard.  But why not simply tie the lifetime of your ConsoleAPI object to the window itself (e.g. via a weakmap)?  Then you don't have to listen for anything; the GC can do the legwork for you.

Alternatively, you could catch "can't access dead object" errors which will occur when you try to touch a destroyed window, and kill the console object then.
Comment 27 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-06 14:36:13 PDT
(In reply to Justin Lebar [:jlebar] from comment #26)
> Alternatively, you could catch "can't access dead object" errors which will
> occur when you try to touch a destroyed window, and kill the console object
> then.

That assumes somebody tries to access it, which isn't necessarily the case.
Comment 28 Justin Lebar (not reading bugmail) 2012-07-06 14:53:20 PDT
> That assumes somebody tries to access it, which isn't necessarily the case.

Absolutely.  But I thought the problem we were trying to solve is: The console object has pending operations, set on a timer.  The timer fires.  Is the window still alive?  We're not sure, and we don't want to do the operations if the window is "dead".
Comment 29 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-06 14:54:06 PDT
(In reply to Mihai Sucan [:msucan] from comment #25)
> (In reply to David Baron [:dbaron] from comment #24)
> > Comment on attachment 639691 [details] [diff] [review]
> > proposed patch
> > 
> > Are these ConsoleAPI objects per-outer-window or per-inner-window?  That
> > would help for understanding this patch.  (And also something that would
> > probably be useful in a code comment.)
> 
> Based on testing, it looked like they are per-inner-window. However, I am
> not 100% sure. Who can we ask about this?

I asked mrbkap and he agreed they're per-inner-window.
Comment 30 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-06 15:04:32 PDT
Comment on attachment 639691 [details] [diff] [review]
proposed patch

> function ConsoleAPI() {}
> ConsoleAPI.prototype = {

Could you add a comment around here saying that ConsoleAPI objects are created (when needed, I think) for each inner window?

>     this._queuedCalls = [];
>-    this._destroyedWindows = [];
>+    this._timer = Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer);
>+    this._window = aWindow;
>+    this.timerRegistry = {};
> 
>     return contentObj;
>   },

I think you should put an _timer: null on the prototype.  At least that seems to be the convention.

>-  startTimer: function CA_startTimer(aWindowId, aName, aTimestamp) {
>+  startTimer: function CA_startTimer(aName, aTimestamp) {
...
>-    let key = aWindowId + "-" + aName.toString();
>+    let key = this._innerID + "-" + aName.toString();

Unless I'm missing something, it seems like there's no need to have the inner ID in the key anymore now that the timerRegistry is specific to a particular window.

>-  stopTimer: function CA_stopTimer(aWindowId, aName, aTimestamp) {
>+  stopTimer: function CA_stopTimer(aName, aTimestamp) {

>+    let key = this._innerID + "-" + aName.toString();
>-    let key = aWindowId + "-" + aName.toString();

and stopTimer would need to change to match.



r=dbaron with that
Comment 31 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-06 15:07:59 PDT
(I still think it would be good to follow up with a second patch to avoid the inner-window-destroyed observer.)
Comment 32 Nicholas Nethercote [:njn] 2012-07-06 20:08:16 PDT
> Also did some checks and I can confirm we've been long time leaking
> ConsoleAPI objects, even before bug 722685. It seems there is some confusion
> in the ConsoleAPI code regarding the lifetime of the object. Unfortunately,
> with bug 722685 I made the leak bigger - apologies for that!

Making it bigger has led to it being fixed, so that's good :)  CPG also helped immensely by making it obvious that it was ConsoleAPI.js at fault;  prior to CPG we just would have had a growing "[System Principal]" compartment and identifying the problem would have been very difficult.

I've barely understood the discussion in this bug.  Can someone explain to me, in short sentences, in what circumstances the leak manifests?  And did bug 722865 change those circumstances?  Thanks in advance.
Comment 33 Justin Lebar (not reading bugmail) 2012-07-06 20:25:25 PDT
> Can someone explain to me, in short sentences, in what circumstances the leak manifests?

If a page touches window.console, then

 * the window's console object (backed by ConsoleAPI.js) lives forever, and
 * the window's console object keeps an array containing the IDs of every destroyed inner window.

> And did bug 722865 change those circumstances?

AIUI we leaked the console object prior to bug 722865 but did not keep an array of the destroyed windows, so the leak should have been very small.
Comment 34 Justin Lebar (not reading bugmail) 2012-07-06 20:28:17 PDT
Did we leak anything other than the inner window IDs, I wonder?  1GB of inner window IDs seems pretty excessive, even assuming that the JS engine is quite inefficient at packing these arrays.  I guess if we had enough console API objects sitting around...
Comment 35 Nicholas Nethercote [:njn] 2012-07-06 20:30:12 PDT
> If a page touches window.console, then
> 
>  * the window's console object (backed by ConsoleAPI.js) lives forever, 

Thanks!  How common is it for a page to touch window.console?
Comment 36 Justin Lebar (not reading bugmail) 2012-07-06 20:54:00 PDT
> Thanks!  How common is it for a page to touch window.console?

It's a debugging feature, so presumably not all that common.
Comment 37 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-06 21:18:59 PDT
(In reply to Justin Lebar [:jlebar] from comment #34)
> Did we leak anything other than the inner window IDs, I wonder?  1GB of
> inner window IDs seems pretty excessive, even assuming that the JS engine is
> quite inefficient at packing these arrays.  I guess if we had enough console
> API objects sitting around...

It doesn't seem excessive given that the number of window IDs stored is O(N^2) in the number of windows.  See the numbers in comment 15.  (I'd consider that leak a bug independent of the prior one, as well.)
Comment 38 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-06 21:22:17 PDT
Strictly speaking, it's really O(N*M), where N is the total number of windows and M is the number of windows that use window.console.  In my 15 day session, N=394656 and M=5156.  (Some Web pages leave window.console stuff in the production Web sites, presumably.)
Comment 39 Mihai Sucan [:msucan] 2012-07-07 03:37:19 PDT
(In reply to Justin Lebar [:jlebar] from comment #26)
> > I wish we had a notification for when the object goes away. Who can tell us how hard is to have this 
> > capability?
> 
> You want something that's exactly like inner-window-destroyed, but instead
> of a global notification, you can subscribe to a notification just for one
> window?

Yes.

> That wouldn't be particularly hard.  But why not simply tie the lifetime of
> your ConsoleAPI object to the window itself (e.g. via a weakmap)?  Then you
> don't have to listen for anything; the GC can do the legwork for you.
> 
> Alternatively, you could catch "can't access dead object" errors which will
> occur when you try to touch a destroyed window, and kill the console object
> then.

As dbaron pointed out in comment 27, we cannot be sure anyone is going to access the console object again, so we can't do any cleanup if nothing happens.

(In reply to Justin Lebar [:jlebar] from comment #28)
> > That assumes somebody tries to access it, which isn't necessarily the case.
> 
> Absolutely.  But I thought the problem we were trying to solve is: The
> console object has pending operations, set on a timer.  The timer fires.  Is
> the window still alive?  We're not sure, and we don't want to do the
> operations if the window is "dead".

We don't always have the timer running. Plus, the timer can (and must, for reasons explained above) execute even when the window is dead. However, what we need to know *if* the timer executes is if the window was destroyed - in such cases we need to clear the consoleapistorage.

Also, is inner-window-destroyed == GC of the window object? Afaik, the answer is no, because GC takes its time - for performance reasons objects are not immediately GC'ed.
Comment 40 Mihai Sucan [:msucan] 2012-07-07 03:41:24 PDT
(In reply to David Baron [:dbaron] from comment #30)
> Comment on attachment 639691 [details] [diff] [review]
> proposed patch
> 
> > function ConsoleAPI() {}
> > ConsoleAPI.prototype = {
> 
> Could you add a comment around here saying that ConsoleAPI objects are
> created (when needed, I think) for each inner window?

Yes, will do. Thanks for letting me know this is really per inner window.

> >     this._queuedCalls = [];
> >-    this._destroyedWindows = [];
> >+    this._timer = Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer);
> >+    this._window = aWindow;
> >+    this.timerRegistry = {};
> > 
> >     return contentObj;
> >   },
> 
> I think you should put an _timer: null on the prototype.  At least that
> seems to be the convention.

Yep, I forgot that.


> >-  startTimer: function CA_startTimer(aWindowId, aName, aTimestamp) {
> >+  startTimer: function CA_startTimer(aName, aTimestamp) {
> ...
> >-    let key = aWindowId + "-" + aName.toString();
> >+    let key = this._innerID + "-" + aName.toString();
> 
> Unless I'm missing something, it seems like there's no need to have the
> inner ID in the key anymore now that the timerRegistry is specific to a
> particular window.

We still need to do this. The innerID prefix is there to avoid clashing with Object prototype names, like "toString" and other things. (this is explained in a comment)
Comment 41 Mihai Sucan [:msucan] 2012-07-07 03:57:39 PDT
Created attachment 639952 [details] [diff] [review]
address review comments

Patch interdiff:
https://github.com/mihaisucan/mozilla-patch-queue/commit/da87e1a7637ab95f6e0d2fde6e374ccb15ed3aec

Changes:
- added the ConsoleAPI object lifetime information (it is created lazily for every inner window).
- the nsiobserver is now a weakref for the service.
- this._window is now a weak ref as well.

I haven't previously used weakmaps and I just read their documentation on MDN. I am not sure how a weakmap would help in this case. I'm definitely missing something. Can you please explain how a weakmap would be better here than using the weakrefs?

In the timer callback I still use the this._windowDestroyed property that is set in the inner-window-destroyed notification, because I doubt this._window.get() always returns null. I'd gladly remove the notification observer, if you can confirm that we can always be sure that this._window.get() returns null. My previous experiences in the Web Console, with weak refs, was that objects are GCed at different times and you can never be sure exactly *when*. The timer executes every 15ms and we need to make sure that once inner-window-destroyed is fired we know of that. If this._window.get() becomes null immediately after that, then we don't need the observer.

Thank you!

Try run:
https://tbpl.mozilla.org/?tree=Try&rev=63637639a637
Comment 42 Justin Lebar (not reading bugmail) 2012-07-07 07:38:48 PDT
> Also, is inner-window-destroyed == GC of the window object? Afaik, the answer is no, because GC 
> takes its time - for performance reasons objects are not immediately GC'ed.

inner-window-destroyed happens when the inner window is "detached" from its docshell (search for it in nsGlobalWindow.cpp).  It happens before we GC the window, but while we're tearing it down.  Soon after that notification is sent, touching the window will cause a "can't access dead object" error.

I still think you can use a weakmap plus the "can't access dead object" error to detect when a window has gone away.  But we can figure that out, or whether you need a new event, in a separate bug.
Comment 43 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-07 10:27:09 PDT
(In reply to Mihai Sucan [:msucan] from comment #41)
> - the nsiobserver is now a weakref for the service.
> - this._window is now a weak ref as well.

I don't see how these changes improve anything relative to the previous patch.  You're still listening to inner-window-destroyed, but you've added weak-ref complexity.  I think I prefer the previous patch to this one, unless I'm missing something.
Comment 44 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-07 10:52:14 PDT
Comment on attachment 639952 [details] [diff] [review]
address review comments

Actually, I changed my mind; this is fine.  r=dbaron
Comment 45 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-07 22:33:11 PDT
I pushed this to: https://hg.mozilla.org/integration/mozilla-inbound/rev/07e36b94badd
Comment 46 Justin Lebar (not reading bugmail) 2012-07-07 22:50:40 PDT
We should either take this on Aurora or back out bug 722685.  What do you think?
Comment 47 Mihai Sucan [:msucan] 2012-07-08 01:52:47 PDT
(In reply to David Baron [:dbaron] from comment #43)
> (In reply to Mihai Sucan [:msucan] from comment #41)
> > - the nsiobserver is now a weakref for the service.
> > - this._window is now a weak ref as well.
> 
> I don't see how these changes improve anything relative to the previous
> patch.  You're still listening to inner-window-destroyed, but you've added
> weak-ref complexity.  I think I prefer the previous patch to this one,
> unless I'm missing something.

One of the requests in previous comments was to not store a strong reference to the consoleapi object in the observer service, hence these changes in the patch.

Thank you for the review+ and for pushing the patch to inbound.

(In reply to Justin Lebar [:jlebar] from comment #46)
> We should either take this on Aurora or back out bug 722685.  What do you
> think?

I would like this patch pushed to aurora, if that is ok with you? I feel bug 722685 is an important performance win for the web console and I'd like it to make it into the fx15 release. I believe this memleak fix is safe enough.

Thank you!
Comment 48 Mihai Sucan [:msucan] 2012-07-08 03:22:00 PDT
Created attachment 640041 [details] [diff] [review]
patch for aurora

Asking for review, to make sure this is fine with you.

An alternative would be to make a *minimal* patch that simply takes out the _destroyedWindows array. This would bring the memleak back to the original size. I would rather prefer we push this fix.

Thank you!
Comment 49 David Baron :dbaron: ⌚️UTC-7 (review requests must explain patch) 2012-07-08 09:19:18 PDT
Comment on attachment 640041 [details] [diff] [review]
patch for aurora

r=dbaron


One thing I probably should have asked about earlier (since it applies to both patches); it's not clear to me why you have a try-catch around:

      let windowUtils = aWindow.QueryInterface(Ci.nsIInterfaceRequestor)
                          .getInterface(Ci.nsIDOMWindowUtils);

      this._outerID = windowUtils.outerWindowID;
      this._innerID = windowUtils.currentInnerWindowID;

Is this needed?  If so, maybe a comment should explain why?
Comment 50 Ryan VanderMeulen [:RyanVM] 2012-07-08 10:51:14 PDT
https://hg.mozilla.org/mozilla-central/rev/07e36b94badd
Comment 51 Justin Lebar (not reading bugmail) 2012-07-08 11:11:32 PDT
> Is this needed?  If so, maybe a comment should explain why?

GetCurrentInnerWindowID throws an exception if there's no inner window.  outerWindowID never fails.
Comment 52 Mihai Sucan [:msucan] 2012-07-09 02:55:28 PDT
Comment on attachment 640041 [details] [diff] [review]
patch for aurora

dbaron: thanks for the r+!

[Approval Request Comment]
Bug caused by (feature/regressing bug #): memleak existed before bug 722685, but with that patch the data in the leaked ConsoleAPI objects increased a lot, causing the memleak to become a lot more obvious.
User impact if declined: much increased memory usage, for no obvious reasons.
Testing completed (on m-c, etc.): landed in inbound, then m-c, green try pushes.
Risk to taking this patch (and alternatives if risky): this should be a safe patch which eliminates a long-time memleak in the browser.
String or UUID changes made by this patch: none.
Comment 53 Mihai Sucan [:msucan] 2012-07-10 07:25:26 PDT
Comment on attachment 640041 [details] [diff] [review]
patch for aurora

Landed in aurora:
https://hg.mozilla.org/releases/mozilla-aurora/rev/7273537950b1

Thanks for the approval!

Note You need to log in before you can comment on or make changes to this bug.