756261 - Huge CC times due to very large JS heap

Status: RESOLVED WORKSFORME

(Core :: JavaScript Engine, defect)

Description

[Wayne Mery (:wsmwk)]

Attachment: memchaser log

Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:15.0) Gecko/15.0 Firefox/15.0a1

horrible performance.
~200 tabs. saved sessionstore.js
GC time in 2-4 sec range, which isn't abnormal for me.
but CC time has gone through the roof, to 2-4 sec.

steps
no specific steps. firefox has been running for a few days I think. 
performance was already not good, then I clicked "restore" for a previously saved session of about 200 tabs

Comment 1

[Wayne Mery (:wsmwk)]

Attachment: troubleshooting info

Comment 2

[Wayne Mery (:wsmwk)]

about:memory times out. here's a partial result

"Exception thrown within memory multi-reporter: window-objects: [Exception... \"Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIMemoryMultiReporter.collectReports]\"  nsresult: \"0x80004005 (NS_ERROR_FAILURE)\"  location: \"JS frame :: chrome://global/content/aboutMemory.js :: processMemoryReporters :: line 236\"  data: no]"Main Process

Explicit Allocations
6,148.13 MB (100.0%) -- explicit
├──4,633.50 MB (75.36%) -- js
│  ├──2,983.98 MB (48.53%) -- compartment([System Principal])
│  │  ├──2,339.23 MB (38.05%) -- gc-heap
│  │  │  ├──2,163.60 MB (35.19%) -- objects
│  │  │  │  ├──1,774.74 MB (28.87%) ── non-function [511]
│  │  │  │  └────388.85 MB (06.32%) ── function [506]
│  │  │  ├─────94.06 MB (01.53%) ++ arena
│  │  │  └─────81.57 MB (01.33%) ++ (5 tiny)
│  │  ├────402.89 MB (06.55%) -- objects
│  │  │    ├──377.35 MB (06.14%) ── slots [511]
│  │  │    └───25.53 MB (00.42%) ++ (2 tiny)
│  │  ├────153.14 MB (02.49%) ── string-chars [220]
│  │  └─────88.72 MB (01.44%) ++ (5 tiny)
│  ├──1,054.58 MB (17.15%) ++ (663 tiny)

Comment 3

[Wayne Mery (:wsmwk)]

after closing ~40 tabs and iterating unresponsive script more times...

Main Process

Explicit Allocations
5,666.11 MB (100.0%) -- explicit
├──4,407.87 MB (77.79%) -- js
│  ├──2,919.95 MB (51.53%) -- compartment([System Principal])
│  │  ├──2,334.45 MB (41.20%) -- gc-heap
│  │  │  ├──2,171.32 MB (38.32%) -- objects
│  │  │  │  ├──1,782.17 MB (31.45%) ── non-function [462]
│  │  │  │  └────389.14 MB (06.87%) ── function [457]
│  │  │  ├─────91.52 MB (01.62%) ++ arena
│  │  │  └─────71.61 MB (01.26%) ++ (5 tiny)
│  │  ├────400.40 MB (07.07%) -- objects
│  │  │    ├──375.36 MB (06.62%) ── slots [462]
│  │  │    └───25.05 MB (00.44%) ++ (2 tiny)
│  │  ├────100.38 MB (01.77%) ── string-chars [219]
│  │  └─────84.72 MB (01.50%) ++ (5 tiny)
│  ├────772.70 MB (13.64%) ++ (511 tiny)
│  ├────479.36 MB (08.46%) ── xpconnect
│  └────235.86 MB (04.16%) ── gc-heap-decommitted
├────750.52 MB (13.25%) ── heap-unclassified
├────394.62 MB (06.96%) ++ window-objects
└────113.09 MB (02.00%) ++ (11 tiny)

Other Measurements
   73.70 MB ── canvas-2d-pixel-bytes
5,666.12 MB ── explicit
   29.82 MB ── gfx-d2d-surfacecache
  266.24 MB ── gfx-d2d-surfacevram
   41.85 MB ── gfx-surface-image
          0 ── ghost-windows
2,634.96 MB ── heap-allocated
2,956.64 MB ── heap-committed
     12.20% ── heap-committed-unused-ratio
    2.24 MB ── heap-dirty
  744.03 MB ── heap-unused
   28.99 MB ── images-content-used-uncompressed
        540 ── js-compartments-system
        858 ── js-compartments-user
3,025.00 MB ── js-gc-heap
   61.93 MB ── js-main-runtime-analysis-temporary
2,609.69 MB ── js-main-runtime-gc-heap-allocated
  152.65 MB ── js-main-runtime-gc-heap-arena-unused
    0.02 MB ── js-main-runtime-gc-heap-chunk-clean-unused
   26.78 MB ── js-main-runtime-gc-heap-chunk-dirty-unused
2,789.14 MB ── js-main-runtime-gc-heap-committed
  179.44 MB ── js-main-runtime-gc-heap-committed-unused
      6.87% ── js-main-runtime-gc-heap-committed-unused-ratio
  235.86 MB ── js-main-runtime-gc-heap-decommitted
    0.37 MB ── js-main-runtime-mjit
2,700.90 MB ── js-main-runtime-objects
  251.11 MB ── js-main-runtime-scripts
  213.94 MB ── js-main-runtime-shapes
  132.37 MB ── js-main-runtime-strings
   42.81 MB ── js-main-runtime-type-inference
6,262.79 MB ── private
5,383.45 MB ── resident
    0.00 MB ── shmem-allocated
    0.00 MB ── shmem-mapped
   22.46 MB ── storage-sqlite
7,477.94 MB ── vsize
   94.05 MB ── window-objects-dom
   92.10 MB ── window-objects-layout-arenas
  105.45 MB ── window-objects-layout-style-sets
    0.06 MB ── window-objects-layout-text-runs
  102.96 MB ── window-objects-style-sheets

Comment 4

[Nicholas Nethercote [inactive]]

> about:memory times out. here's a partial result
> 
> "Exception thrown within memory multi-reporter: window-objects:
> [Exception... \"Component returned failure code: 0x80004005
> (NS_ERROR_FAILURE) [nsIMemoryMultiReporter.collectReports]\"  nsresult:
> \"0x80004005 (NS_ERROR_FAILURE)\"  location: \"JS frame ::
> chrome://global/content/aboutMemory.js :: processMemoryReporters :: line
> 236\"  data: no]"Main Process

Hmm, that's unusual.

> 6,148.13 MB (100.0%) -- explicit
> ├──4,633.50 MB (75.36%) -- js
> │  ├──2,983.98 MB (48.53%) -- compartment([System Principal])
> │  │  ├──2,339.23 MB (38.05%) -- gc-heap
> │  │  │  ├──2,163.60 MB (35.19%) -- objects
> │  │  │  │  ├──1,774.74 MB (28.87%) ── non-function [511]
> │  │  │  │  └────388.85 MB (06.32%) ── function [506]
> │  │  │  ├─────94.06 MB (01.53%) ++ arena
> │  │  │  └─────81.57 MB (01.33%) ++ (5 tiny)
> │  │  ├────402.89 MB (06.55%) -- objects
> │  │  │    ├──377.35 MB (06.14%) ── slots [511]
> │  │  │    └───25.53 MB (00.42%) ++ (2 tiny)

That's a lot of JS objects.  What date is this FF15 build from?  It looks like it predates compartment-per-global (bug 650353).

Do you have add-ons installed?  That could be a factor.

If it's not related to an add-on, diagnosing this build will be hard.  The good news is that once bug 754771 lands it'll be a lot easier, because that gives a much more detailed breakdown of System Principal memory consumption.

Comment 5

[Nicholas Nethercote [inactive]]

Just to clarify:  the high GC and CC times are caused by the very large JS heap.  Working out why it's so large is the real question with this bug.  That'll have to wait on bug 754771 -- which hopefully will only be a few days! -- unless you can find an add-on that's at fault before then.

Comment 6

[Andrew McCreight (out until 2026) [:mccr8]]

The CC is slow because the CC graph is gigantic:
"visited":{"RCed":2828399,"GCed":2821904}

About 2.8 million ref counted and 2.8 million JS nodes.  The similarity of those numbers is suspicious.  Looking at a CC dump may give an idea of what is wrong, but it is probably going to be too large to do anything useful with.

Comment 7

[Nicholas Nethercote [inactive]]

Wayne, are you seeing the bad CC and GC times only after running for a few days?
If so, it's probably because something (Firefox, or a site, or an addon) is leaking.

If you're seeing them immediately after restarting, then that is stranger, and sounds like maybe a session restore problem.

Comment 8

[Wayne Mery (:wsmwk)]

(In reply to Nicholas Nethercote [:njn] from comment #4)
> > about:memory times out. here's a partial result
> > 
> > "Exception thrown within memory multi-reporter: window-objects:
> > [Exception... \"Component returned failure code: 0x80004005
> > (NS_ERROR_FAILURE) [nsIMemoryMultiReporter.collectReports]\"  nsresult:
> > \"0x80004005 (NS_ERROR_FAILURE)\"  location: \"JS frame ::
> > chrome://global/content/aboutMemory.js :: processMemoryReporters :: line
> > 236\"  data: no]"Main Process
> 
> Hmm, that's unusual.
> 
> > 6,148.13 MB (100.0%) -- explicit
> > ├──4,633.50 MB (75.36%) -- js
> > │  ├──2,983.98 MB (48.53%) -- compartment([System Principal])
> > │  │  ├──2,339.23 MB (38.05%) -- gc-heap
> > │  │  │  ├──2,163.60 MB (35.19%) -- objects
> > │  │  │  │  ├──1,774.74 MB (28.87%) ── non-function [511]
> > │  │  │  │  └────388.85 MB (06.32%) ── function [506]
> > │  │  │  ├─────94.06 MB (01.53%) ++ arena
> > │  │  │  └─────81.57 MB (01.33%) ++ (5 tiny)
> > │  │  ├────402.89 MB (06.55%) -- objects
> > │  │  │    ├──377.35 MB (06.14%) ── slots [511]
> > │  │  │    └───25.53 MB (00.42%) ++ (2 tiny)
> 
> That's a lot of JS objects.  What date is this FF15 build from?  It looks
> like it predates compartment-per-global (bug 650353).
FF 15.0a1 2012-05-08, which should include bug 650353

> Do you have add-ons installed?  That could be a factor.
yes - attachment 624899 [details]

In the past, I've been unsuccessful pinning blame any of my installed addons.
FWIW, of any of them, I'd most suspect tree style tabs.

> If it's not related to an add-on, diagnosing this build will be hard.  The
> good news is that once bug 754771 lands it'll be a lot easier, because that
> gives a much more detailed breakdown of System Principal memory consumption.

I look forward to it.


(In reply to Nicholas Nethercote [:njn] from comment #7)
> Wayne, are you seeing the bad CC and GC times only after running for a few
> days?
> If so, it's probably because something (Firefox, or a site, or an addon) is
> leaking.
> 
> If you're seeing them immediately after restarting, then that is stranger,
> and sounds like maybe a session restore problem.

This was not immediately after restarting. But it was immediately after doing session restore from an about:sessionstore.  In other words, I had been running for some time already from a restored session for a couple days. It's performance was not great, but tolerable. Then, I did a restore from a tab that had about:sessionstore  (I have a couple sessions nested) - soon after CC went through the roof.

I'll reemphasize that the llong GC times are normal for me (though not welcome). However, I think this is the first time I've ever had CC time in the thousands - so a definite fluke for me.

Anything else I can help with, other than try to reproduce from my saved session?

Comment 9

[Nicholas Nethercote [inactive]]

( > > │  │  │  │  ├──1,774.74 MB (28.87%) ── non-function [511]
> > 
> > That's a lot of JS objects.  What date is this FF15 build from?  It looks
> > like it predates compartment-per-global (bug 650353).
> FF 15.0a1 2012-05-08, which should include bug 650353

You're right, the [511] indicates there are lots of System Principal compartments, as you'd expect with bug 650353.  I should have noticed that earlier.


> > Do you have add-ons installed?  That could be a factor.
> yes - attachment 624899 [details]

Wow, 19 enabled add-ons.  Historically, when someone with that many installed has high memory usage it's *very* likely to be an add-on at fault.  


> In the past, I've been unsuccessful pinning blame any of my installed addons.
> FWIW, of any of them, I'd most suspect tree style tabs.

I use Tree Style Tabs myself and have never had problems with it.  One thing I've learned is that any add-on can cause memory problems, even the most innocuous ones.

Readability could be to blame, it's known to leak in this manner -- see bug 730546.  Version 2.3, which fixes the leak, is available at http://www.readability.com/addons.  I'd try that!

Comment 10

[Andrew McCreight (out until 2026) [:mccr8]]

Ah, yeah, I'd say this is almost certainly the same thing as big 730546.

Comment 11

[Wayne Mery (:wsmwk)]

(In reply to Nicholas Nethercote [:njn] from comment #9)

>>> Do you have add-ons installed?  That could be a factor.
>> yes - attachment 624899 [details]
> Wow, 19 enabled add-ons.  Historically, when someone with that
> many installed has high memory usage it's *very* likely to be an add-on at
> fault.  

Indeed. I do try to keep it low - and use reliable, narrowly scoped addons for just that reason. It's still a crap shoot, so it's really nice to see reliability and memory issues being driven down to the addon level, like in bug 754711!

>>> FWIW, of any of them, I'd most suspect tree style tabs.
>> I use Tree Style Tabs myself and have never had problems with it.  One thing
>> I've learned is that any add-on can cause memory problems, even the most
>> innocuous ones.

I can't say how pleased I am that someone says they haven't seen problems with Tree Style, because that's the indespencible one of the bunch.


> Readability could be to blame, it's known to leak in this
> manner -- see bug 730546.  Version 2.3, which fixes the leak, is available
> at http://www.readability.com/addons.  I'd try that!

I'd happily agree bug 730546 is related, except that I don't actively use Readability. Can the leak happen even if not actively using that addon?

What I DID use in this "bad period" was Read It Later. And I don't normally use it, so I wonder if that was at fault.  But I haven't had trouble with it in the past.

I'm now on Readability 2.3 now that I restarted Fx

Comment 12

[Andrew McCreight (out until 2026) [:mccr8]]

(In reply to Wayne Mery (:wsmwk) from comment #11)
> I'd happily agree bug 730546 is related, except that I don't actively use
> Readability. Can the leak happen even if not actively using that addon?

Yes, I think so.  It kept references to every page you opened or something awful along those lines.

Comment 13

[Wayne Mery (:wsmwk)]

(In reply to Andrew McCreight [:mccr8] from comment #12)
> (In reply to Wayne Mery (:wsmwk) from comment #11)
> I'd happily agree bug
> 730546 is related, except that I don't actively use
> Readability. Can the
> leak happen even if not actively using that addon?

Yes, I think so.  It
> kept references to every page you opened or something awful along those
> lines.

In that case - dupe

Comment 14

[Andrew McCreight (out until 2026) [:mccr8]]

Thanks for investigating!

Comment 15

[Wayne Mery (:wsmwk)]

I'm seeing this again - 4sec CC
Readability is at v2.3
Firefox 20120517

Comment 16

[Wayne Mery (:wsmwk)]

I failed to get a memchaser log or a minidump.

i clicked "trigger cc" in memchaser and then quickly did a break in windbg and windbg virtually hung.

Comment 17

[Andrew McCreight (out until 2026) [:mccr8]]

Oh, sorry, I didn't mean a minidump, I meant a cycle collector graph dump:
https://wiki.mozilla.org/Performance:Leak_Tools#Cycle_collector_heap_dump

Comment 18

[Nicholas Nethercote [inactive]]

> > If it's not related to an add-on, diagnosing this build will be hard.  The
> > good news is that once bug 754771 lands it'll be a lot easier, because that
> > gives a much more detailed breakdown of System Principal memory consumption.
> 
> I look forward to it.

It landed a few days ago.  Wayne, can you look at about:memory in a recent Nightly and see if that identifies any compartments as using excessive amounts of memory?  Thanks.

Comment 19

[Wayne Mery (:wsmwk)]

Attachment: about:memory verbose

coincidentally, I have a high CC in progress - though not as high as originally reported. CC ~400ms, GC ~2-3000ms 
20120524 build 

edges log coming up

Comment 20

[Wayne Mery (:wsmwk)]

Attachment: heap dump

Comment 21

[Wayne Mery (:wsmwk)]

I don't know that it is relevant, but 
* readability 2.3 addon is enabled
* I have a continuous stream of ...

Timestamp: 5/29/2012 8:38:40 PM
Warning: Error in parsing value for 'filter'.  Declaration dropped.
Source File: http://www.trychips.com/
Line: 0

Comment 22

[Wayne Mery (:wsmwk)]

p.s. i didn't time it, but it seemed like about 2 minutes to do about:memory verbose

Comment 23

[Nicholas Nethercote [inactive]]

Looking at the latest about:memory, here are the notable things:

Explicit Allocations
1,592,637,405 B (100.0%) -- explicit
+----893,414,436 B (56.10%) -- js
¦    +---66,318,720 B (04.16%) -- compartment([System Principal], about:sessionrestore)
¦    ¦   +--50,913,920 B (03.20%) -- string-chars [2]
...
¦    +---57,516,320 B (03.61%) -- compartment([System Principal], about:blank) [38]
...
¦    +---46,645,648 B (02.93%) -- compartment([System Principal], resource:///modules/sessionstore/SessionStore.jsm)
¦    ¦   +--33,953,616 B (02.13%) -- string-chars
...
¦    +---21,795,680 B (01.37%) -- compartment([System Principal]) [154]


8MB+ of MemChaser system compartments.


9 browser.xul windows are present -- you had 9 windows open, I guess?


The sessionrestore/SessionStore compartments are big, but relative to total size, not ridiculous.  It kind just looks like about:memory for a browser session with 100s of tabs open.  I don't see excessive memory consumption in System Principal compartments like we saw in comment 8.

I'm not sure where to go from here.  Maybe you can watch about:memory some more and maybe at some point you'll see a System Principal compartment behaving more badly?

Comment 24

[Wayne Mery (:wsmwk)]

(In reply to Nicholas Nethercote [:njn] from comment #23)
> Looking at the latest about:memory, here are the notable things:
> 
> Explicit Allocations
> 1,592,637,405 B (100.0%) -- explicit
> +----893,414,436 B (56.10%) -- js
> ¦    +---66,318,720 B (04.16%) -- compartment([System Principal],
> about:sessionrestore)
> ¦    ¦   +--50,913,920 B (03.20%) -- string-chars [2]
> ...
> ¦    +---57,516,320 B (03.61%) -- compartment([System Principal],
> about:blank) [38]
> ...
> ¦    +---46,645,648 B (02.93%) -- compartment([System Principal],
> resource:///modules/sessionstore/SessionStore.jsm)
> ¦    ¦   +--33,953,616 B (02.13%) -- string-chars
> ...
> ¦    +---21,795,680 B (01.37%) -- compartment([System Principal]) [154]
> 
> 
> 8MB+ of MemChaser system compartments.
> 
> 
> 9 browser.xul windows are present -- you had 9 windows open, I guess?

yes

> The sessionrestore/SessionStore compartments are big, but relative to total
> size, not ridiculous.  It kind just looks like about:memory for a browser
> session with 100s of tabs open.  I don't see excessive memory consumption in
> System Principal compartments like we saw in comment 8.

~150

> I'm not sure where to go from here.  Maybe you can watch about:memory some
> more and maybe at some point you'll see a System Principal compartment
> behaving more badly?

correct, it's currently not debilitating.  It was just very bad typing - which is how I first noticed the slowness today.  it came on rather suddenly and I don't know what provoked it.  5-10 seconds before my characters would show up. Now, it's just tolerable typing, with CC at ~130ms 

perhaps I should try doing more with readability addon :)

Comment 25

[Nicholas Nethercote [inactive]]

Since the high CC times are the main problem, we decided to remove the MemShrink tag.

Comment 26

[(dormant account)]

Andrew, can you assign proper snappy priority here?

Comment 27

[Wayne Mery (:wsmwk)]

suspect this is mitigated for me by e10s. but I think it is still an issue with high tab counts

Comment 28

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

Wayne, do you still see this in non-e10s (or e10s child process). Since this was file in 2012 and since then there has been lots of optimizations to CC, like incremental CC and tons of cases where we optimize out certainly alive objects from CC graph.

I do have ~500 tabs open and haven't had any particular bad CCs pauses.

Comment 29

[Wayne Mery (:wsmwk)]

Is memchaser the best way to measure it and does it work?  
If not, what to use? 
And, what kind of times should we be seeing?

Comment 30

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

That works too, for non-e10s. 
Another option is to set javascript.options.mem.log true and look at browser console.

Comment 31

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

well, median max CC pause time is 5-6ms and 95th percentile on Nightly is 75ms, which is too high.
That has regressed. It used to be 55ms.

Comment 32

[Wayne Mery (:wsmwk)]

I set javascript.options.mem.log true on  work PC and I'm not seeing gc log entries.  

current nightly win64 build. All javascript.options items are at defaults. dom.ipc.processCount is 4

Comment 33

[Wayne Mery (:wsmwk)]

It's unlikely I well retest non-e10s any time soon. So let's close on the basis of comment 38