650350 - A combination of several specific extensions causes memory deallocation to be delayed by 3+ minutes in firefox 4 when closing tabs

Status: RESOLVED INCOMPLETE

(Core :: JavaScript Engine, defect)

Description

[Danial Horton]

User-Agent:       Mozilla/5.0 (Windows NT 6.1; WOW64; rv:2.0.1) Gecko/20100101 Firefox/4.0.1
Build Identifier: 

When the following extensions are used alongside one another

Adblock Plus + Flashblock

Default Full Zoom + Image toolbar
Image Zoom + ???? (probably ABP)

It can take up to 3 minutes for Firefox to release the memory used by an heavy site (the demo url is the best source, as an example of the worst site code on the planet).

Reproducible: Always

Steps to Reproduce:
1. load the demo url in a fresh profile till it finishes loading
2. open an empty tab and close the sites tab
3. closing the tab should drop the usage from roughly 900MB's down to 140ish on a clean profile.

1. Now install a combination of the above plugins into that fresh profile (subscription NOT required for ABP)
2. load the demo site (it should be instant if you didn't clear the cache prior, but this does not affect the results)
3. open a blank tab and close the loaded tab.
Actual Results:  
If you time how long it takes for the memory to drop back to the 140ish mark, it should be between 3 and 4 minutes.

Expected Results:  
Well... since it didn't happen in firefox 3, that'd be nice but 4 is a different beast so its expected that there would be extension teething problems.

i don't expect a fix in firefox itself, I just felt i should get feedback from the mozdevs on particular causes of this before i go and tell a bunch of extension devs their extensions are conflicting.

Comment 1

[Alice0775 White]

Image Toolbar + Clean profile : reproduced the issue.
Default FullZoom Level + Clean profile : cannot reproduce.
Image Toolbar + Default FullZoom Level + Clean profile : reproduced.

So, I suspect Image Toolbar itself.

Comment 2

[Boris Zbarsky [:bzbarsky]]

Can you please set "javascript.options.mem.log" to true in about:config, open the error console to the "Messages" tab, and then reproduce the issue?  If so, do you see any "GC mode" messages during those 3-4 minutes?

Comment 3

[Alice0775 White]

(In reply to comment #2)
> Can you please set "javascript.options.mem.log" to true in about:config, open
> the error console to the "Messages" tab, and then reproduce the issue?

Same result as I described in comment #1

> If so,
> do you see any "GC mode" messages during those 3-4 minutes?

in the case of Image Toolbar + Clean profile,

GC mode: full, timestamp: 1302916118068000, duration: 13 ms.
CC timestamp: 1302916119103000, collected: 391 (391 waiting for GC), suspected: 4401, duration: 8 ms.
GC mode: full, timestamp: 1302916123114000, duration: 11 ms.
CC timestamp: 1302916128120000, collected: 0 (0 waiting for GC), suspected: 102, duration: 6 ms.

Comment 4

[Boris Zbarsky [:bzbarsky]]

Right,  but when did those messages come, in that 3-4 minute timeframe?  That is, is the real issue here that it takes us 3-4 minutes to run a GC?

Comment 5

[Alice0775 White]

(In reply to comment #3)
> (In reply to comment #2)
> > Can you please set "javascript.options.mem.log" to true in about:config, open
> > the error console to the "Messages" tab, and then reproduce the issue?
> 
> Same result as I described in comment #1
> 
> > If so,
> > do you see any "GC mode" messages during those 3-4 minutes?
> 
> in the case of Image Toolbar + Clean profile,
> 
> GC mode: full, timestamp: 1302916118068000, duration: 13 ms.
> CC timestamp: 1302916119103000, collected: 391 (391 waiting for GC), suspected:
> 4401, duration: 8 ms.
> GC mode: full, timestamp: 1302916123114000, duration: 11 ms.
> CC timestamp: 1302916128120000, collected: 0 (0 waiting for GC), suspected:
> 102, duration: 6 ms.

The above messages appear after I closed the tab, the masages appears within about 5 sec.
No message in that 3-4 minute timeframe.

I think that xbl binding to img elements of document causes the problem,


Image Toolbar binds like this.

img,
object[type^="image/"]
{
  -moz-binding: url("chrome://imagetoolbar/content/imagetoolbar.xml#img") !important;
}

Comment 6

[Boris Zbarsky [:bzbarsky]]

So after 3-4 minutes the memory usage goes down _without_ a CC or GC happening?

Comment 7

[Alice0775 White]

in the case of Image Toolbar + Clean profile,
Regression window:
Works(memory deduction within 5-20sec):
http://hg.mozilla.org/mozilla-central/rev/10d5ec16577a
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:2.0b12pre) Gecko/20110215 Firefox/4.0b12pre ID:20110215133930
Fails:
http://hg.mozilla.org/mozilla-central/rev/9685f88199a6
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:2.0b12pre) Gecko/20110215 Firefox/4.0b12pre ID:20110215134830
Pushlog:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=10d5ec16577a&tochange=9685f88199a6
Suspected:
b4f2b87f03a0	Bobby Holley — Bug 593426 - Increase image discard timer to two minutes. r,a2.0=joe

Comment 8

[Alice0775 White]

(In reply to comment #6)
> So after 3-4 minutes the memory usage goes down _without_ a CC or GC happening?
Yes, Memory usage decreased without CC/GC messages.

Comment 9

[Alice0775 White]

And I confirmed that
the problem was gone if I set image.mem.min_discard_timeout_ms to 10000.

Comment 10

[Boris Zbarsky [:bzbarsky]]

Oh.  So the image element is still alive, but the image data is what's getting discarded.

Hmm.  I wonder how long that image element stays alive for.  I'll take a look at that when I get back next week.  That's the real issue here.

Comment 11

[RNicoletto]

Marked as NEW as per comment 10.

Comment 12

[Nicholas Nethercote [inactive]]

So bug 664290, which reduces the image.mem.min_discard_timeout_ms to 10000, should fix this.

Daniel, can you confirm if the problem is fixed in a Nightly build, from nightly.mozilla.org?  Thanks!

Comment 13

[Dão Gottwald [:dao]]

(In reply to comment #12)
> So bug 664290, which reduces the image.mem.min_discard_timeout_ms to 10000,
> should fix this.

Not quite, see comment 10.

Comment 14

[Nicholas Nethercote [inactive]]

(In reply to comment #13)
> 
> Not quite, see comment 10.

Which contradicts comment 9, seemingly.

Comment 15

[Ed Morley [:emorley]]

The way I read it was that the image.mem.min_discard_timeout_ms change merely highlighted an underlying bug, rather than being the actual cause. So whilst the timeout has now been lowered meaning the symptoms will disappear; the image element is still being kept alive when it shouldn't be.

Comment 16

[Nicholas Nethercote [inactive]]

I'm downgrading this to MemShrink:P3, because that's the priority level we normally use for bugs relating to add-ons.

Comment 17

[Florian Bender]

Is this still valid with the recent refactoring of image decoding/handling?

Comment 18

[Nicholas Nethercote [inactive]]

Danial, can you try again to see if it's still a problem?

Comment 19

[Danial Horton]

Couldn't tell you, I haven't upgraded past Firefox 16 because of Bug 781414 and the blatantly anti-user DPI behaviour changes that cannot be disabled.

That said, i don't think this has been a problem since before firefox 10, or earlier.