752259 - Huge, 100MB+ Memory Usage Regression In Recent Nightly

Status: RESOLVED FIXED

(Firefox :: Untriaged, defect)

Description

[d.a.]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:15.0) Gecko/15.0 Firefox/15.0a1
Build ID: 20120505030510

Steps to reproduce:

The memory usage jumped by over 100 MB just after browser start in the re-spin that came out before today's (2012-05-05) nightly build. This also happens on a completely fresh profile with no extensions. In fact the memory usage with the latest build is higher without any extensions than it is with a previous build with a dozen or extensions. On a clean profile that represents a memory usage regression of over 200%.

The rather large pushlog is here: http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=2db9df42823d&tochange=9ebf3dc839c5

I'll try a few hourly builds to see if I can narrow it down a little further.

Comment 1

[d.a.]

I've narrowed it down to this: http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=ac00c792933e&tochange=bed8c4e3dfdf

Looks like Compartment-Per-Global (bug 650353) is to blame.

Comment 2

[Bobby Holley (:bholley)]

CPG does impact memory, but should only do so at the level of 3-5%.

Memshrink guys, can you work with d.a. to get more data on precisely what's changing? I'm not an expert on that stuff, so I don't know what about:memory numbers to ask for.

Comment 3

[Andrew McCreight [:mccr8]]

Thanks for the report, d.a.  Could you attach the contents of about:memory?verbose from the above changeset where you are seeing the increase?  It also might help to attach one from before that.  about:memory was broken in there at some point, so if it isn't working there, just use about:memory from a recently nightly.  If you could past each into a file and attach it to this bug, that would be a little easier to deal with.  This is just startup memory?

Comment 4

[Justin Lebar (not reading bugmail)]

FWIW, I see only a small regression on AWSY (Linux64) [1].

There was a big jump in "RSS: After TP5, tabs closed [+30s]" (red line) -- zoom in to the RHS of the graph, around cset ec3c29434dee.  It appears to have come back down.  There isn't a corresponding jump in startup memory usage, though.

https://areweslimyet.com/

Comment 5

[Andrew McCreight [:mccr8]]

I thought CPG broke Mozmill, so I don't know if AWSY has actually updated properly.

Comment 6

[Justin Lebar (not reading bugmail)]

Of course we have no telemetry for MEMORY_RESIDENT for Darwin from the past week.  Naturally.  The data from Windows doesn't show a big spike.

My RSS is 200mb (10.7) on startup.  That does seem high, although I don't have a baseline.

Comment 7

[Justin Lebar (not reading bugmail)]

(In reply to Andrew McCreight [:mccr8] from comment #5)
> I thought CPG broke Mozmill, so I don't know if AWSY has actually updated
> properly.

Maybe it's wrong, but we do have data up to 5/5/12.

Comment 8

[John Schoenick [:johns]]

I had added a workaround for the broken mozmill functions to AWSY, so the data should be up to date

Comment 9

[Andrew McCreight [:mccr8]]

(In reply to John Schoenick [:johns] from comment #8)
> I had added a workaround for the broken mozmill functions to AWSY, so the
> data should be up to date
Awesome!

Comment 10

[Luke Wagner [:luke]]

Similar to previous comments, compared about:memory on membuster before/after and see only a 1.8% regression.

Comment 11

[d.a.]

Attachment: Good build about:memory

Here is the about:memory (verbose) of the good build (http://hg.mozilla.org/integration/mozilla-inbound/rev/ac00c792933e) and looking at the Activity Monitor it peaks at 250 MB and stabilizes at around 230 MB.

The bad build (http://hg.mozilla.org/integration/mozilla-inbound/rev/bed8c4e3dfdf) it peaks at 390 MB and stabilizes at 370 MB. Simply opening about:memory drops this down to 310 MB, so some 60 MB is de-allocated here.

Comment 12

[d.a.]

Attachment: Bad build about:memory

Comment 13

[d.a.]

Attachment: Bad build CPU usage spike

I don't know if this is related to this bug, but with the bad build I'm seeing a horrible performance regression, when loading pages. Activity Monitor shows Firefox using 110-120% (of 200%) of the CPU, if there are enough tabs being loaded Firefox becomes unresponsive for some time. With the good build this doesn't happen.

Comment 14

[SpeciesX]

Attachment: about:memory Changeset: 2db9df42823d

i have also a memory increase about 70-80% on clean Profile.

Comment 15

[SpeciesX]

Attachment: about:memory Bad build Changeset: 94ce5f33a9ea

Comment 16

[Andrew McCreight [:mccr8]]

I should write an about:memory diff script.  Anyways, here are a few before and after things I noticed that are pretty different. (ignore the ASCII art part of it)

Before:

177,353,368 B (100.0%) -- explicit
├──103,297,760 B (58.24%) -- js
│  ├───17,883,136 B (10.08%) ── gc-heap-decommitted
├───43,287,998 B (24.41%) ── heap-unclassified
├───17,352,632 B (09.78%) -- storage

After:

243,483,424 B (100.0%) -- explicit
├──153,701,920 B (63.13%) -- js
│  ├───40,005,632 B (16.43%) ── gc-heap-decommitted
├───68,668,300 B (28.20%) ── heap-unclassified
├────7,355,864 B (03.02%) -- storage

So, overall, there's 66mb more explicit memory used after.  There's about 50mb more of JS, and of that, about 22mb of this is decommitted.  The rest of the difference (about 28mb) looks like it is various system-compartment stuff.  As for the increased decomitted, maybe there's more memory used by JS during startup that is quickly thrown out?  There's 25mb more of heap-unclassified.  There's 10mb _less_ of storage, which is probably just noise?

Comment 17

[Justin Lebar (not reading bugmail)]

> Simply opening about:memory drops this down to 310 MB, so some 60 MB is de-allocated here.

On Mac, you cannot measure Firefox's memory from the activity monitor without first opening about:memory.  The drop you observe isn't us de-allocating memory -- it's us forcing the operating system to notice that memory we've already freed is, in fact, freed.  We do that when you open about:memory so we can get an accurate reading there.

But anyway, we're still looking at a sizable regression even with this effect accounted for.

Bobby, have a look at these about:memory?verbose results.  There are a bazillion system compartments there.  That looks pretty bad to me.

d.a. / SpeciesX -- Do you have a lot of tabs in your sessions?

Comment 18

[Andrew McCreight [:mccr8]]

heap-unused is also a lot higher.  from 38,585,376 B to 111,579,944 B.  You can look at the bottom to see which categories of memory (objects etc) have gone up.

Comment 19

[SpeciesX]

(In reply to Justin Lebar [:jlebar] from comment #17)
> d.a. / SpeciesX -- Do you have a lot of tabs in your sessions?

nope, only one about:memory tab on on clean profile.

Comment 20

[Justin Lebar (not reading bugmail)]

> d.a. / SpeciesX -- Do you have a lot of tabs in your sessions?

So every unloaded tab does get its own system compartment.  And that's going to hit users who have hundreds of unloaded tabs really hard.  I'll file a separate bug on that, since it sounds like it may not be the same thing we're observing here.

Comment 21

[d.a.]

> d.a. / SpeciesX -- Do you have a lot of tabs in your sessions?

Only 3 pages loaded in total, first http://www.google.com/, then about:blank and finally about:memory

> On Mac, you cannot measure Firefox's memory from the activity monitor
> without first opening about:memory.  The drop you observe isn't us
> de-allocating memory -- it's us forcing the operating system to notice that
> memory we've already freed is, in fact, freed.  We do that when you open
> about:memory so we can get an accurate reading there.

Would it be possible to make the OS aware of the actual memory usage before going to about:memory? I've noticed after browsing for quite some time opening about:memory will reduce the memory reported in Activity Monitor by a lot. Before I got 8 GB RAM I noticed that visiting about:memory would prevent a lot of paging by the OS because the memory usage the OS saw was so high.

Comment 22

[SpeciesX]

Attachment: memory @ProcessExplorer

Here compare from my main profile with 3 tabs, memory increase from 230MB to 368MB.

Comment 23

[Bobby Holley (:bholley)]

(In reply to Justin Lebar [:jlebar] from comment #20)
> So every unloaded tab does get its own system compartment.  And that's going
> to hit users who have hundreds of unloaded tabs really hard.  I'll file a
> separate bug on that, since it sounds like it may not be the same thing
> we're observing here.

I'd think not, since the reporters here say they're using clean profiles.

(In reply to Justin Lebar [:jlebar] from comment #17) 
> Bobby, have a look at these about:memory?verbose results.  There are a
> bazillion system compartments there.  That looks pretty bad to me.

I think a cold boot of firefox creates ~105 system globals, which translates to ~105 system compartments. This seems to be the same thing as reported in the log attached to this bug.

Theoretically, this definitely does leave us with some memory overhead, since things can be packed less tightly (we have the overhead of the minimum arena size, even if the compartment isn't allocating enough objects to fill it).

But IIUC, the minimum arena size is something on the order of 2-4k. If we're talking about a 100MB regression, then _each_ compartment would have an overhead on the order of 1MB, which is absurdly high. So there's clearly something fishy afoot here.

Comment 24

[Justin Lebar (not reading bugmail)]

> Before I got 8 GB RAM I noticed that visiting about:memory would prevent a lot of paging 
> by the OS because the memory usage the OS saw was so high.

Before you visit about:memory, the memory that's released when you open about:memory should be in a state such that the operating system will snatch it back before it starts paging.

So if you observed that your machine was paging, and then you opened about:memory, and then Firefox's memory usage decreased and the system immediately stopped paging because of the extra available memory, that would be a bug, either in Firefox or your operating system.  To be honest, I doubt that was what was happening -- I tested all this specifically on 10.6 -- but it's possible, and we can tackle it in another but if you can reproduce.

Comment 25

[Justin Lebar (not reading bugmail)]

(In reply to SpeciesX from comment #14)
> Created attachment 621420 [details]
> about:memory Changeset: 2db9df42823d
> 
> i have also a memory increase about 70-80% on clean Profile.

Resident before: 117mb
Resident after:  140mb

This isn't a 70-80% increase.  Am I misunderstanding something?

Comment 26

[Marco Castelluccio [:marco]]

(In reply to Justin Lebar [:jlebar] from comment #25)
> Resident before: 117mb
> Resident after:  140mb
> 
> This isn't a 70-80% increase.  Am I misunderstanding something?

Maybe he's referring to explicit.

Comment 27

[Justin Lebar (not reading bugmail)]

> Maybe he's referring to explicit.

FWIW, explicit is a bad number to look at because it includes memory that's decommitted -- it's taking up no space in physical memory.  (If you think that's unfortunate and confusing, don't blame me; we have a long-running spat over this. :)

I just realized that our Mac js gc heap code decommits incorrectly.  It should use MADV_FREE, not MADV_DONTNEED, and then we need to add the magic to kill the madvise'd pages, just like we do with jemalloc.  We may need similar code to make Windows report correctly, too.

I don't remember what MADV_DONTNEED does on Mac -- it may not free the memory at all.  :-/  I think at least the Windows code is freeing memory properly.

To analyze the situation as though this were fixed, look at heap-committed + js-gc-heap-committed instead of resident.

 heap-committed + js-gc-heap-committed in d.a.'s data:

   Good: 30mb +  8mb = 38mb
   Bad:  44mb + 12mb = 56mb

So there's still a sizable increase here.  We should try to reproduce this.

Comment 28

[SpeciesX]

(In reply to Justin Lebar [:jlebar] from comment #25)
> (In reply to SpeciesX from comment #14)
> > Created attachment 621420 [details]
> > about:memory Changeset: 2db9df42823d
> > 
> > i have also a memory increase about 70-80% on clean Profile.
> 
> Resident before: 117mb
> Resident after:  140mb
> 
> This isn't a 70-80% increase.  Am I misunderstanding something?

i compared explicit only.
the good build varies explicit only +/-3MB, but the bad build varies explicit from 58MB up to 72MB and i took the lowest.

Comment 29

[Justin Lebar (not reading bugmail)]

I filed bug 752339 and bug 752342 on the issues wrt the JS chunk allocator's decommit.  But that's not the whole story here.

Comment 30

[SpeciesX]

where i can find js-gc-heap-committed?

my main profile on the bad build

339.02 MB -- explicit
  0.13 MB -- gfx-d2d-surfacecache
 11.75 MB -- gfx-d2d-surfacevram
  0.19 MB -- gfx-surface-image
        0 -- ghost-windows
129.83 MB -- heap-allocated
166.07 MB -- heap-committed
   27.89% -- heap-committed-unused-ratio
  2.46 MB -- heap-dirty
124.16 MB -- heap-unused
  0.01 MB -- images-content-used-uncompressed
      193 -- js-compartments-system
       12 -- js-compartments-user
205.00 MB -- js-gc-heap
  3.77 MB -- js-main-runtime-analysis-temporary
 56.08 MB -- js-main-runtime-gc-heap-allocated
 32.81 MB -- js-main-runtime-gc-heap-arena-unused
 35.00 MB -- js-main-runtime-gc-heap-chunk-clean-unused
 81.12 MB -- js-main-runtime-gc-heap-chunk-dirty-unused
205.00 MB -- js-main-runtime-gc-heap-committed
148.92 MB -- js-main-runtime-gc-heap-committed-unused
  265.57% -- js-main-runtime-gc-heap-committed-unused-ratio
  0.00 MB -- js-main-runtime-gc-heap-decommitted
  0.29 MB -- js-main-runtime-mjit
 28.03 MB -- js-main-runtime-objects
  8.01 MB -- js-main-runtime-scripts
 16.90 MB -- js-main-runtime-shapes
 22.61 MB -- js-main-runtime-strings
  0.91 MB -- js-main-runtime-type-inference
419.41 MB -- private
456.85 MB -- resident
 10.55 MB -- storage-sqlite
840.58 MB -- vsize
  1.62 MB -- window-objects-dom
  1.75 MB -- window-objects-layout-arenas
  3.23 MB -- window-objects-layout-style-sets
  0.14 MB -- window-objects-layout-text-runs
  4.52 MB -- window-objects-style-sheets


same profile on the good build

184.90 MB -- explicit
  0.13 MB -- gfx-d2d-surfacecache
 11.75 MB -- gfx-d2d-surfacevram
  0.19 MB -- gfx-surface-image
        0 -- ghost-windows
101.40 MB -- heap-allocated
116.95 MB -- heap-committed
   15.32% -- heap-committed-unused-ratio
  3.57 MB -- heap-dirty
 38.59 MB -- heap-unused
  0.01 MB -- images-content-used-uncompressed
        7 -- js-compartments-system
       10 -- js-compartments-user
 78.00 MB -- js-gc-heap
  4.52 MB -- js-main-runtime-analysis-temporary
 43.85 MB -- js-main-runtime-gc-heap-allocated
 16.24 MB -- js-main-runtime-gc-heap-arena-unused
  1.00 MB -- js-main-runtime-gc-heap-chunk-clean-unused
 16.91 MB -- js-main-runtime-gc-heap-chunk-dirty-unused
 78.00 MB -- js-main-runtime-gc-heap-committed
 34.15 MB -- js-main-runtime-gc-heap-committed-unused
   77.87% -- js-main-runtime-gc-heap-committed-unused-ratio
  0.00 MB -- js-main-runtime-gc-heap-decommitted
  1.59 MB -- js-main-runtime-mjit
 19.08 MB -- js-main-runtime-objects
  6.70 MB -- js-main-runtime-scripts
 15.72 MB -- js-main-runtime-shapes
 20.83 MB -- js-main-runtime-strings
  0.78 MB -- js-main-runtime-type-inference
243.09 MB -- private
279.91 MB -- resident
 10.34 MB -- storage-sqlite
592.77 MB -- vsize
  1.62 MB -- window-objects-dom
  1.77 MB -- window-objects-layout-arenas
  3.23 MB -- window-objects-layout-style-sets
  0.14 MB -- window-objects-layout-text-runs
  4.52 MB -- window-objects-style-sheets

Comment 31

[Justin Lebar (not reading bugmail)]

It's the main-runtime numbers that you should look at.

I tried to reproduce this bug on my 10.7 box.  There's a lot of variance, but I wasn't able to get anywhere near the kind of blowup here.

The one thing I did see is that after forcing a bunch of minimize memory usage, the non-cpg build leveled off at 100mb, while cpg leveled off at 130mb RSS.  I owe you about:memory dumps, but those will have to wait.

Comment 32

[Justin Lebar (not reading bugmail)]

On my machine, all of the difference between CPG and non-CPG is apparently due to the overhead of loading about:memory?verbose, which is much larger post-CPG.  Non-verbose mode isn't any better: We still load everything; we just hide it by default.

Doing things which don't involve about:memory yields nearly identical memory usage with and without CPG.  Mac 10.7, measured via activity monitor (yes, I know I said not to do that, but desperate times... :)

 * Start up:                       100mb
 * Start up, load google.com:      130mb
 * Start up, load techcrunch.com:  205mb

Can you guys demonstrate a workload which doesn't involve about:memory which shows a repeatable, large difference in memory usage between CPG and non-CPG?  If not, we should close this an open a new bug on the about:memory overhead.  (We've looked at about:memory overhead before, but this is perhaps an unprecedented scale.)

Comment 33

[SpeciesX]

here i make a video. :)
http://youtu.be/aaq61Df9hEc

Comment 34

[Nicholas Nethercote [inactive]]

(In reply to Justin Lebar [:jlebar] from comment #32)
> On my machine, all of the difference between CPG and non-CPG is apparently
> due to the overhead of loading about:memory?verbose, which is much larger
> post-CPG.  Non-verbose mode isn't any better: We still load everything; we
> just hide it by default.

Yeah, I've filed bug 752381 to fix that;  fortunately it'll be easy.  I suspect that'll account for a lot of what d.a. is seeing.  about:memory isn't designed to handle so many reports for such a small session.

Comment 35

[Justin Lebar (not reading bugmail)]

(In reply to SpeciesX from comment #33)
> here i make a video. :)
> http://youtu.be/aaq61Df9hEc

There are a ton of extensions visible in this video.

Comment 36

[SpeciesX]

(In reply to Justin Lebar [:jlebar] from comment #35)
> There are a ton of extensions visible in this video.

only 14 :P

Adblock Plus is the cause.

ABP enabled

CPG build | non CPG build
442-467MB | 305-329MB

ABP disabled

CPG build | non CPG build
266-270MB | 236-246MB

Comment 37

[Justin Lebar (not reading bugmail)]

(In reply to SpeciesX from comment #36)
> (In reply to Justin Lebar [:jlebar] from comment #35)
> 
> Adblock Plus is the cause.
> 
> ABP enabled
> 
> CPG build | non CPG build
> 442-467MB | 305-329MB
> 
> ABP disabled
> 
> CPG build | non CPG build
> 266-270MB | 236-246MB

That sounds really important.  Can you file a new bug on this, please?

Comment 38

[SpeciesX]

(In reply to Justin Lebar [:jlebar] from comment #37)
> That sounds really important.  Can you file a new bug on this, please?

could you file, my english isn't really well.

Comment 39

[Luke Wagner [:luke]]

This may be related/caused by bug 752200 (where a change in RegExp statics with CPG broke ABP and apparently caused slowdown).  Bug 752200 comment 9 indicates that fixing the RegExp issue fixed the perf issue so perhaps this issue is fixed as well?

Comment 40

[SpeciesX]

I'm use the latest ABP dev build, performance is restored, but not the higher memory Usage.

Comment 41

[Wladimir Palant]

CPG caused 20 new compartments to be created in Adblock Plus core code - and lots of communication across compartments (with many wrappers being created I guess). This is likely the cause of this issue.

Comment 42

[Nicholas Nethercote [inactive]]

I'll be optimistic and assume that bug 752381 fixed d.a.'s problem.  d.a., please reopen if you try a recent Nightly and it's still a problem.

Comment 43

[d.a.]

Attachment: Clean profile

It seems like the memory usage has dropped a bit in recent nightly builds, but not to the level as before this change. Earlier builds with a clean profile the memory usage would be around 80-90 MB, now it's 110-120 MB. 

With my normal profile I could get memory usage down to about 190 MB, but now it seems to stay at around 250 MB.

Comment 44

[d.a.]

Attachment: Used profile