Huge CC times due to very large JS heap

RESOLVED WORKSFORME

Status

()

--
major
RESOLVED WORKSFORME
6 years ago
2 years ago

People

(Reporter: wsmwk, Unassigned)

Tracking

({perf})

Trunk
x86_64
Windows 7
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [js:t][Snappy:P2])

Attachments

(4 attachments)

(Reporter)

Description

6 years ago
Created attachment 624897 [details]
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
(Reporter)

Comment 1

6 years ago
Created attachment 624899 [details]
troubleshooting info
(Reporter)

Comment 2

6 years ago
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)
(Reporter)

Comment 3

6 years ago
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
> 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.
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.
Depends on: 754771
Summary: huge CC times → Huge CC times due to very large JS heap
Whiteboard: [MemShrink][Snappy]
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.
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.
(Reporter)

Comment 8

6 years ago
(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?
( > > │  │  │  │  ├──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!
Ah, yeah, I'd say this is almost certainly the same thing as big 730546.
(Reporter)

Comment 11

6 years ago
(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
(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.
(Reporter)

Comment 13

6 years ago
(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
Status: UNCONFIRMED → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → DUPLICATE
Duplicate of bug: 730546
Thanks for investigating!
No longer depends on: 754771
(Reporter)

Comment 15

6 years ago
I'm seeing this again - 4sec CC
Readability is at v2.3
Firefox 20120517
(Reporter)

Comment 16

6 years ago
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.
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
Status: RESOLVED → REOPENED
Ever confirmed: true
Resolution: DUPLICATE → ---
Whiteboard: [MemShrink][Snappy] → [js:t][MemShrink][Snappy]
> > 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.
(Reporter)

Comment 19

6 years ago
Created attachment 628159 [details]
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
(Reporter)

Comment 20

6 years ago
Created attachment 628160 [details]
heap dump
(Reporter)

Comment 21

6 years ago
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
(Reporter)

Comment 22

6 years ago
p.s. i didn't time it, but it seemed like about 2 minutes to do about:memory verbose
(Reporter)

Updated

6 years ago
Attachment #628160 - Attachment mime type: text/plain → application/zip
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?
(Reporter)

Comment 24

6 years ago
(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 :)
Since the high CC times are the main problem, we decided to remove the MemShrink tag.
Whiteboard: [js:t][MemShrink][Snappy] → [js:t][Snappy]

Comment 26

6 years ago
Andrew, can you assign proper snappy priority here?
Whiteboard: [js:t][Snappy] → [js:t][Snappy:P2]
(Reporter)

Updated

4 years ago
See Also: → bug 743221
(Assignee)

Updated

4 years ago
Assignee: general → nobody
(Reporter)

Comment 27

3 years ago
suspect this is mitigated for me by e10s. but I think it is still an issue with high tab counts
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.
Flags: needinfo?(vseerror)
(Reporter)

Comment 29

3 years ago
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?
Flags: needinfo?(vseerror)
That works too, for non-e10s. 
Another option is to set javascript.options.mem.log true and look at browser console.
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.
(Reporter)

Comment 32

3 years ago
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
(Reporter)

Comment 33

2 years ago
It's unlikely I well retest non-e10s any time soon. So let's close on the basis of comment 38
Status: REOPENED → RESOLVED
Last Resolved: 6 years ago2 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.