GC/CC responsiveness problems with Aurora builds

[Boris Zbarsky]

For a while now I've been having serious responsiveness problems with
nightlies: after running for a few days, they would start having lots of
GC/CC pauses, which interfered with typing and scrolling.

Long story short, I finally went back and browsed for a week with a
current Fx9 beta. The problem was NOT present.

Then I tried an Aurora build, and the problem _is_ present. Here is an
excerpt of the GC/CC event log from my error console from a few minutes
ago, with timestamps converted to ms from first event listed so they can
be compared to the durations:

GC mode: full, timestamp: 0, duration: 1064 ms.
CC timestamp: 6852, collected: 38 (38 waiting for GC), suspected: 173,
duration: 1851 ms.
GC mode: full, timestamp: 21641, duration: 1638 ms.
CC timestamp: 27133, collected: 400 (400 waiting for GC), suspected:
783, duration: 492 ms.
GC mode: full, timestamp: 32826, duration: 1692 ms.
CC timestamp: 38322, collected: 388 (388 waiting for GC), suspected:
578, duration: 494 ms.
GC mode: full, timestamp: 43309, duration: 987 ms.
CC timestamp: 48840, collected: 50 (50 waiting for GC), suspected: 189,
duration: 530 ms.

etc, etc.

So in other words, we're running both GC and CC every 10 seconds or so,
and they're taking about 1-3 seconds to run. This makes the chance of
me trying to so something while they're running pretty high.

The Fx9 beta had similar GC/CC times (possibly somewhat smaller,
actually), but just seemed to do it a lot less often, as far as I can
tell, on the same pageset.

Was there a known change in heuristics from Fx9 to Fx10 here?

-Boris

[smaug]

On 12/01/2011 09:43 PM, Boris Zbarsky wrote:
> For a while now I've been having serious responsiveness problems with
> nightlies: after running for a few days, they would start having lots of
> GC/CC pauses, which interfered with typing and scrolling.
>
> Long story short, I finally went back and browsed for a week with a
> current Fx9 beta. The problem was NOT present.

So, it sounds like strong parent node didn't cause the problem.
(FF8 has weak parents, FF9 has strong)

>
> Then I tried an Aurora build, and the problem _is_ present. Here is an
> excerpt of the GC/CC event log from my error console from a few minutes
> ago, with timestamps converted to ms from first event listed so they can
> be compared to the durations:
>
> GC mode: full, timestamp: 0, duration: 1064 ms.
> CC timestamp: 6852, collected: 38 (38 waiting for GC), suspected: 173,
> duration: 1851 ms.
> GC mode: full, timestamp: 21641, duration: 1638 ms.
> CC timestamp: 27133, collected: 400 (400 waiting for GC), suspected:
> 783, duration: 492 ms.
> GC mode: full, timestamp: 32826, duration: 1692 ms.
> CC timestamp: 38322, collected: 388 (388 waiting for GC), suspected:
> 578, duration: 494 ms.
> GC mode: full, timestamp: 43309, duration: 987 ms.
> CC timestamp: 48840, collected: 50 (50 waiting for GC), suspected: 189,
> duration: 530 ms.
>
> etc, etc.
>
> So in other words, we're running both GC and CC every 10 seconds or so,
> and they're taking about 1-3 seconds to run. This makes the chance of me
> trying to so something while they're running pretty high.
>
> The Fx9 beta had similar GC/CC times (possibly somewhat smaller,
> actually), but just seemed to do it a lot less often, as far as I can
> tell, on the same pageset.

Do you know if FF9 is worse than FF8?

>
> Was there a known change in heuristics from Fx9 to Fx10 here?

https://bugzilla.mozilla.org/show_bug.cgi?id=678830 caused some
problems, and I'm not sure which problems are fixed in which branch.


>
> -Boris

[Boris Zbarsky]

On 12/1/11 3:03 PM, smaug wrote:
> So, it sounds like strong parent node didn't cause the problem.
> (FF8 has weak parents, FF9 has strong)

Assuming that my (somewhat subjective) conclusion about Fx9 is correct, yes.

> Do you know if FF9 is worse than FF8?

Not offhand, but I don't recall any obvious "My browser suddenly sucks"
changes in nightlies until the last two months or so....

> https://bugzilla.mozilla.org/show_bug.cgi?id=678830 caused some
> problems

That claims to be fixed in 9 as well, right? As in, any problems it
caused would be present there....

-Boris

[Andrew McCreight]

----- Original Message -----
> > Was there a known change in heuristics from Fx9 to Fx10 here?
>
> https://bugzilla.mozilla.org/show_bug.cgi?id=678830 caused some
> problems, and I'm not sure which problems are fixed in which branch.

Bug 699796 landed in 10 and should have fixed one source of leaks. There is also bug 687857, which is an intermittent leak which started up with the landing of bug 678830 (which landed in 9). That intermittent leak went away for some reason on October 8th, I believe when 10 was on m-c, but before 699796 landed.

That's the only thing I can think of that should have affected CC behavior. But it seems like it should be worse in 9 than in 10!

Andrew

[Boris Zbarsky]

On 12/1/11 5:07 PM, Andrew McCreight wrote:
> Bug 699796 landed in 10 and should have fixed one source of leaks. There is also bug 687857, which is an intermittent leak which started up with the landing of bug 678830 (which landed in 9). That intermittent leak went away for some reason on October 8th, I believe when 10 was on m-c, but before 699796 landed.
>
> That's the only thing I can think of that should have affected CC behavior. But it seems like it should be worse in 9 than in 10!

To be clear, the main issue I'm seeing is that gc/cc are running more
often. In particular, they are running every 10s for me , more or less
like clockwork. If each run takes about a second (a best-case scenario
for my tab set, apparently), that still means that 10% of my wall-clock
time is spent off in gc+cc land.

-Boris

[Ehsan Akhgari]

I believe I have been seeing the same problem on trunk too.

Here's my log on nightly:

GC(T+0.0) Type:Glob, Total:1027.6, Wait:69.5, Mark:262.0, Sweep:694.3,
FinObj:3.1, FinStr:1.2, FinScr:1.2, FinShp:6.2, DisCod:2.5, DisAnl:668.2,
XPCnct:4.4, Destry:0.1, End:5.3, +Chu:0, -Chu:1, Reason: API
CC(T+0.5) collected: 20822 (20822 waiting for GC), suspected: 8784,
duration: 489 ms.
GC(T+4.9) Type:Glob, Total:369.4, Wait:4.2, Mark:259.5, Sweep:99.9,
FinObj:5.7, FinStr:1.3, FinScr:2.0, FinShp:6.1, DisCod:2.3, DisAnl:70.8,
XPCnct:3.9, Destry:0.1, End:8.8, +Chu:0, -Chu:0, Reason: API
CC(T+6.0) collected: 133 (133 waiting for GC), suspected: 261, duration:
492 ms.
CC(T+18.5) collected: 623 (756 waiting for GC), suspected: 3394, duration:
922 ms.
GC(T+23.5) Type:Glob, Total:734.1, Wait:1.2, Mark:379.1, Sweep:262.9,
FinObj:14.9, FinStr:10.6, FinScr:1.3, FinShp:22.8, DisCod:9.0,
DisAnl:191.9, XPCnct:4.4, Destry:0.1, End:94.3, +Chu:0, -Chu:0, Reason: API
CC(T+28.9) collected: 198 (198 waiting for GC), suspected: 1138, duration:
412 ms.
CC(T+40.1) collected: 740 (938 waiting for GC), suspected: 3272, duration:
2200 ms.
GC(T+44.1) Type:Glob, Total:611.3, Wait:3.6, Mark:254.6, Sweep:306.4,
FinObj:15.6, FinStr:3.1, FinScr:1.3, FinShp:7.4, DisCod:6.3, DisAnl:195.2,
XPCnct:4.4, Destry:65.6, End:50.1, +Chu:0, -Chu:0, Reason:Maybe
CC(T+45.8) collected: 2884 (2884 waiting for GC), suspected: 3438,
duration: 498 ms.
GC(T+50.3) Type:Glob, Total:479.9, Wait:2.5, Mark:254.2, Sweep:221.4,
FinObj:3.0, FinStr:1.2, FinScr:1.3, FinShp:6.1, DisCod:2.6, DisAnl:196.1,
XPCnct:3.7, Destry:0.1, End:4.4, +Chu:0, -Chu:0, Reason: API
...

The average interval for me is 5 seconds. If I can help with gathering
more useful information, please let me know how.

Cheers,
--
Ehsan
<http://ehsanakhgari.org/>

> ______________________________**_________________
> dev-platform mailing list
> dev-pl...@lists.mozilla.org
> https://lists.mozilla.org/**listinfo/dev-platform<https://lists.mozilla.org/listinfo/dev-platform>
>

[Andrew McCreight]

So GCs and CCs are about the same length as before, just more often?

And you are noticing an increased rate of both GCs and CCs, not just one or the other?

>
> -Boris
> _______________________________________________
> dev-platform mailing list
> dev-pl...@lists.mozilla.org
> https://lists.mozilla.org/listinfo/dev-platform

[Boris Zbarsky]

On 12/1/11 11:58 PM, Andrew McCreight wrote:
>> To be clear, the main issue I'm seeing is that gc/cc are running more
>> often. In particular, they are running every 10s for me , more or less
>> like clockwork. If each run takes about a second (a best-case scenario
>> for my tab set, apparently), that still means that 10% of my
>> wall-clock
>> time is spent off in gc+cc land.
>
> So GCs and CCs are about the same length as before, just more often?

It's a little hard to tell about the former because those lengths are so
variable.

But yes, in general I _think_ the lengths are about the same, maybe a
little longer, but the frequency is up.

There's a lot of noise in this data, both the timing and the durations,
and reproducing involves me browsing for a day or three; when I first
start the browser things are OK. Makes it hard to gather good data.

> And you are noticing an increased rate of both GCs and CCs, not just one or the other?

I always get them in pairs, basically. See the log fragment I pasted;
it all looks like that. A GC, then 5-6 seconds later a CC. Then
(usually within 5 seconds) a GC, then 5-6 seconds later a CC. And so
on. At least after a few days of browsing. If I just start up, I get
the "GC, then 5s later CC" pattern, but not as often.

For comparison, on the Fx9 beta on the same pageset, I often see two CC
calls in a row without a GC in between or two GC calls without a CC in
between. And it's not uncommon for the gaps between two such calls to
be on the order of a minute or more.

I really wish the error console would allow select+copy of more than one
item at a time; it'd make it a heck of a lot simpler to post logs. :(

-Boris

[smaug]

Based on the CC it looks like something is causing quite a bit real
garbage.

>
> The average interval for me is 5 seconds. If I can help with gathering
> more useful information, please let me know how.

I wonder what kinds of pages you're browsing.

[Boris Zbarsky]

On 12/2/11 3:37 AM, smaug wrote:
> I wonder what kinds of pages you're browsing.

Over here, right now, I'm looking at:

bugzilla.mozilla.org (25 tabs)
darklands.wikispaces.com (7 tabs)
treasurydirect.gov (5 tabs)
tbpl.mozilla.org (4 tabs)
mercurial.selenic.com (3 tabs)
mxr.mozilla.org (3 tabs)
stackoverflow.com (2 tabs)
www.python.org (2 tabs)
www.tomshardware.com (2 tabs)
news.ycombinator.com (2 tabs)
en.wikipedia.org (2 tabs)
www.projectorpeople.com (2 tabs)

That's 59 out of the 91 total tabs... the remainder are all one tab per
host, so about:tabs isn't telling me what the hostnames are. There's
certainly a google reader (but no other web apps like that), and a bunch
of blog posts; that may account for the majority of the remaining tabs.

I can send you my sessionstore file if you'd like.

-Boris

[Philip Chee]

On Fri, 02 Dec 2011 00:23:54 -0500, Boris Zbarsky wrote:

> I really wish the error console would allow select+copy of more than one
> item at a time; it'd make it a heck of a lot simpler to post logs. :(
>
> -Boris

Console² has multi-select and CTRL-A also works.
<http://console2.mozdev.org/#C_latest_dev>

Phil

--
Philip Chee <phi...@aleytys.pc.my>, <phili...@gmail.com>
http://flashblock.mozdev.org/ http://xsidebar.mozdev.org
Guard us from the she-wolf and the wolf, and guard us from the thief,
oh Night, and so be good for us to pass.

[Andrew McCreight]

----- Original Message -----
> But yes, in general I _think_ the lengths are about the same, maybe a
> little longer, but the frequency is up.

Okay, that's good to know.

> I always get them in pairs, basically. See the log fragment I pasted;
> it all looks like that. A GC, then 5-6 seconds later a CC. Then
> (usually within 5 seconds) a GC, then 5-6 seconds later a CC. And so
> on. At least after a few days of browsing. If I just start up, I get
> the "GC, then 5s later CC" pattern, but not as often.
>
> For comparison, on the Fx9 beta on the same pageset, I often see two
> CC
> calls in a row without a GC in between or two GC calls without a CC in
> between. And it's not uncommon for the gaps between two such calls to
> be on the order of a minute or more.

There are two ways the CC is triggered. One is that periodically it checks if there are more than 1000 suspected objects (in nsJSContext::MaybePokeCC). You'll notice that in your log this is never the case. The other way is that after a GC, it may decide to trigger a CC (in DOMGCCallback, which is also in nsJSEnvironment.cpp). What happens here is that 5 seconds after a full GC (non-compartmental), a CC is triggered. There's also the wrinkle that if we finished a compartmental GC, the CC timer is reset.

In 9 and 10, what happens is that 5 seconds after a full GC, a CC is triggered. The code has changed in 11, but should do the same thing. I think that the difference between 9 and 10 for this problem is that the GC is being triggered more often. I'm not sure what could have caused that. I filed Bug 707162 for that.

Do you have any logs from Nightly? That has slightly more detailed information about why the GC was triggered than Aurora.

At a glance, Ehsan's problem looks different. Most of the time when the CC fires, it has more than 1000 suspected objects, so the CC would probably trigger even without the GC.

> I really wish the error console would allow select+copy of more than
> one
> item at a time; it'd make it a heck of a lot simpler to post logs. :(

Yeah, that is a pain.


bz's log:

[Boris Zbarsky]

On 12/2/11 10:14 AM, Andrew McCreight wrote:
> In 9 and 10, what happens is that 5 seconds after a full GC, a CC is triggered. The code has changed in 11, but should do the same thing. I think that the difference between 9 and 10 for this problem is that the GC is being triggered more often. I'm not sure what could have caused that. I filed Bug 707162 for that.

That seems plausible.

> Do you have any logs from Nightly? That has slightly more detailed information about why the GC was triggered than Aurora.

I'll work on generating such a log. Give me a few days. ;)

-Boris

[Boris Zbarsky]

On 12/2/11 1:26 PM, Boris Zbarsky wrote:
> I'll work on generating such a log. Give me a few days. ;)

OK, until about 30 minutes ago things were looking OK (in that the GCs
were every 10 secs, but not too long and whatnot).

But now my log is looking like what I pasted below... and things are not
happy. See some of those CC durations.

There _might_ be a correlation with me reading comments on
ews.slashdot.org/story/11/12/05/1717201/will-firefox-lose-google-funding
and maybe making a few comments, then closing a bunch of those tabs.
Hard to tell... I did that about 10 minutes ago, but the CC times are
still sucking.

-Boris

GC(T+293191.9) Type:Glob, Total:670.1, Wait:4.5, Mark:450.2,
Sweep:212.0, FinObj:21.0, FinStr:1.1, FinScr:2.9, FinShp:11.7,
DisCod:7.5, DisAnl:127.1, XPCnct:13.7, Destry:18.8, End:14.2, +Chu:0,
-Chu:0, Reason:Maybe
----------
CC(T+293197.4) collected: 134 (134 waiting for GC), suspected: 616,
duration: 522 ms.
----------
GC(T+293202.0) Type:Glob, Total:1676.3, Wait:632.7, Mark:489.9,
Sweep:544.6, FinObj:45.7, FinStr:4.0, FinScr:6.7, FinShp:12.6,
DisCod:8.7, DisAnl:443.4, XPCnct:14.2, Destry:0.5, End:20.5, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293209.2) collected: 2317 (2317 waiting for GC), suspected: 7892,
duration: 4347 ms.
----------
GC(T+293211.7) Type:Glob, Total:1687.3, Wait:745.3, Mark:487.5,
Sweep:444.6, FinObj:36.4, FinStr:1.7, FinScr:5.0, FinShp:13.0,
DisCod:9.2, DisAnl:354.7, XPCnct:14.1, Destry:1.7, End:21.2, +Chu:3,
-Chu:0, Reason: API
----------
CC(T+293216.1) collected: 1512 (1512 waiting for GC), suspected: 7443,
duration: 472 ms.
----------
GC(T+293216.9) Type:Glob, Total:852.0, Wait:34.6, Mark:466.2,
Sweep:324.0, FinObj:84.9, FinStr:4.3, FinScr:4.3, FinShp:13.3,
DisCod:7.6, DisAnl:181.4, XPCnct:14.2, Destry:0.6, End:38.4, +Chu:0,
-Chu:0, Reason: API
----------
GC(T+293221.6) Type:Glob, Total:695.4, Wait:1.4, Mark:472.5,
Sweep:218.5, FinObj:5.5, FinStr:0.7, FinScr:3.0, FinShp:12.0,
DisCod:7.8, DisAnl:166.8, XPCnct:13.6, Destry:0.6, End:13.8, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293222.5) collected: 25826 (25826 waiting for GC), suspected: 1949,
duration: 548 ms.
----------
GC(T+293226.2) Type:Glob, Total:592.6, Wait:4.3, Mark:445.6,
Sweep:134.7, FinObj:6.4, FinStr:0.7, FinScr:5.8, FinShp:12.6,
DisCod:7.2, DisAnl:79.5, XPCnct:13.6, Destry:0.6, End:18.8, +Chu:0,
-Chu:0, Reason: API
----------
GC(T+293231.8) Type:Glob, Total:1586.3, Wait:791.8, Mark:470.1,
Sweep:319.7, FinObj:36.4, FinStr:0.9, FinScr:3.3, FinShp:12.5,
DisCod:8.0, DisAnl:235.1, XPCnct:13.8, Destry:1.2, End:15.7, +Chu:0,
-Chu:1, Reason: API
----------
CC(T+293232.4) collected: 4905 (4905 waiting for GC), suspected: 3091,
duration: 508 ms.
----------
GC(T+293236.6) Type:Glob, Total:649.4, Wait:4.4, Mark:446.6,
Sweep:181.7, FinObj:40.2, FinStr:4.1, FinScr:3.8, FinShp:13.4,
DisCod:7.2, DisAnl:89.2, XPCnct:14.3, Destry:0.6, End:27.5, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293239.1) collected: 3533 (3533 waiting for GC), suspected: 2511,
duration: 489 ms.
----------
GC(T+293241.2) Type:Glob, Total:642.9, Wait:2.1, Mark:455.8,
Sweep:137.3, FinObj:8.9, FinStr:0.7, FinScr:4.0, FinShp:15.2,
DisCod:7.3, DisAnl:72.9, XPCnct:16.1, Destry:0.6, End:60.3, +Chu:0,
-Chu:0, Reason: API
----------
GC(T+293245.9) Type:Glob, Total:651.8, Wait:2.9, Mark:454.4,
Sweep:173.7, FinObj:5.6, FinStr:0.7, FinScr:2.9, FinShp:11.8,
DisCod:7.2, DisAnl:123.1, XPCnct:13.6, Destry:0.5, End:31.7, +Chu:0,
-Chu:2, Reason: API
----------
CC(T+293246.7) collected: 113 (113 waiting for GC), suspected: 434,
duration: 449 ms.
----------
CC(T+293255.3) collected: 49 (162 waiting for GC), suspected: 1800,
duration: 450 ms.
----------
GC(T+293266.6) Type:Glob, Total:739.5, Wait:5.2, Mark:450.2,
Sweep:274.1, FinObj:37.8, FinStr:4.4, FinScr:2.9, FinShp:12.5,
DisCod:8.0, DisAnl:152.0, XPCnct:14.1, Destry:34.1, End:21.3, +Chu:0,
-Chu:0, Reason:Maybe
----------
CC(T+293276.1) collected: 57 (57 waiting for GC), suspected: 1517,
duration: 4488 ms.
----------
GC(T+293287.7) Type:Glob, Total:815.6, Wait:2.2, Mark:476.7,
Sweep:331.8, FinObj:7.5, FinStr:1.1, FinScr:3.0, FinShp:11.8,
DisCod:7.7, DisAnl:267.9, XPCnct:13.6, Destry:11.1, End:15.7, +Chu:0,
-Chu:0, Reason:Maybe
----------
GC(T+293288.6) Type:Comp, Total:38.5, Wait:0.2, Mark:18.4, Sweep:17.3,
FinObj:0.0, FinStr:0.0, FinScr:0.0, FinShp:0.0, DisCod:0.0, DisAnl:0.0,
XPCnct:13.8, Destry:0.0, End:13.9, +Chu:0, -Chu:0, Reason:Alloc
----------
GC(T+293293.5) Type:Glob, Total:948.7, Wait:1.1, Mark:443.9,
Sweep:343.3, FinObj:161.3, FinStr:6.5, FinScr:5.3, FinShp:17.2,
DisCod:10.2, DisAnl:83.9, XPCnct:16.1, Destry:0.8, End:172.9, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293294.2) collected: 26050 (26050 waiting for GC), suspected: 4811,
duration: 609 ms.
----------
GC(T+293298.9) Type:Glob, Total:602.5, Wait:4.6, Mark:434.8,
Sweep:153.4, FinObj:6.5, FinStr:0.8, FinScr:4.6, FinShp:13.1,
DisCod:7.8, DisAnl:93.5, XPCnct:13.6, Destry:3.5, End:20.5, +Chu:0,
-Chu:0, Reason: API
----------
GC(T+293304.7) Type:Glob, Total:1859.9, Wait:1033.8, Mark:454.9,
Sweep:365.7, FinObj:32.3, FinStr:0.9, FinScr:4.1, FinShp:12.4,
DisCod:7.9, DisAnl:285.0, XPCnct:13.6, Destry:1.0, End:16.4, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293305.4) collected: 3287 (3287 waiting for GC), suspected: 15394,
duration: 614 ms.
----------
GC(T+293309.3) Type:Glob, Total:621.2, Wait:4.9, Mark:441.7,
Sweep:162.0, FinObj:25.6, FinStr:4.3, FinScr:2.8, FinShp:12.1,
DisCod:7.2, DisAnl:83.3, XPCnct:13.6, Destry:1.4, End:23.4, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293312.0) collected: 81 (81 waiting for GC), suspected: 1471,
duration: 467 ms.
----------
GC(T+293314.1) Type:Glob, Total:578.4, Wait:4.6, Mark:434.9,
Sweep:135.7, FinObj:5.2, FinStr:0.7, FinScr:2.7, FinShp:12.3,
DisCod:6.7, DisAnl:84.8, XPCnct:14.8, Destry:0.5, End:15.3, +Chu:0,
-Chu:0, Reason: API
----------
GC(T+293318.8) Type:Glob, Total:619.2, Wait:1.3, Mark:435.9,
Sweep:178.9, FinObj:5.6, FinStr:0.7, FinScr:3.3, FinShp:11.8,
DisCod:6.8, DisAnl:128.8, XPCnct:13.2, Destry:0.5, End:13.6, +Chu:0,
-Chu:1, Reason: API
----------
CC(T+293319.6) collected: 3679 (3679 waiting for GC), suspected: 1480,
duration: 483 ms.
----------
GC(T+293323.4) Type:Glob, Total:643.6, Wait:5.3, Mark:463.6,
Sweep:133.5, FinObj:8.7, FinStr:4.2, FinScr:3.3, FinShp:12.1,
DisCod:6.9, DisAnl:76.0, XPCnct:13.7, Destry:0.6, End:52.1, +Chu:0,
-Chu:4, Reason: API
----------
CC(T+293328.2) collected: 98 (98 waiting for GC), suspected: 1249,
duration: 469 ms.
----------
GC(T+293342.2) Type:Glob, Total:1810.1, Wait:1059.8, Mark:457.9,
Sweep:281.7, FinObj:33.2, FinStr:3.7, FinScr:2.8, FinShp:11.7,
DisCod:7.7, DisAnl:199.3, XPCnct:13.5, Destry:0.5, End:21.5, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293347.4) collected: 1417 (1417 waiting for GC), suspected: 2868,
duration: 4870 ms.
----------
GC(T+293348.0) Type:Glob, Total:551.2, Wait:5.1, Mark:435.9,
Sweep:107.0, FinObj:5.2, FinStr:0.6, FinScr:2.7, FinShp:11.1,
DisCod:6.6, DisAnl:58.2, XPCnct:13.0, Destry:1.7, End:13.5, +Chu:0,
-Chu:0, Reason: API
----------
GC(T+293352.5) Type:Glob, Total:582.3, Wait:1.0, Mark:441.9,
Sweep:136.3, FinObj:5.2, FinStr:0.7, FinScr:2.7, FinShp:11.3,
DisCod:7.2, DisAnl:87.5, XPCnct:13.1, Destry:0.5, End:13.3, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293353.5) collected: 78 (78 waiting for GC), suspected: 375,
duration: 510 ms.
----------
GC(T+293357.1) Type:Glob, Total:582.9, Wait:4.3, Mark:435.1,
Sweep:140.5, FinObj:6.9, FinStr:0.9, FinScr:3.3, FinShp:12.7,
DisCod:7.6, DisAnl:84.9, XPCnct:15.1, Destry:0.7, End:15.4, +Chu:0,
-Chu:1, Reason: API
----------
CC(T+293362.7) collected: 1126 (1126 waiting for GC), suspected: 3131,
duration: 534 ms.
----------
GC(T+293365.5) Type:Glob, Total:1815.7, Wait:971.6, Mark:449.6,
Sweep:383.1, FinObj:30.8, FinStr:3.8, FinScr:3.3, FinShp:13.4,
DisCod:42.5, DisAnl:263.7, XPCnct:14.8, Destry:0.7, End:22.7, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293371.0) collected: 3790 (3790 waiting for GC), suspected: 916,
duration: 473 ms.
----------
GC(T+293375.7) Type:Glob, Total:674.1, Wait:43.1, Mark:458.6,
Sweep:165.3, FinObj:6.3, FinStr:0.9, FinScr:3.2, FinShp:11.3,
DisCod:7.2, DisAnl:115.0, XPCnct:13.1, Destry:0.5, End:17.5, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293381.1) collected: 52 (52 waiting for GC), suspected: 562,
duration: 457 ms.
----------
GC(T+293396.3) Type:Glob, Total:674.6, Wait:4.9, Mark:444.3,
Sweep:214.9, FinObj:8.6, FinStr:6.8, FinScr:2.8, FinShp:11.5,
DisCod:7.2, DisAnl:114.2, XPCnct:13.4, Destry:42.2, End:21.2, +Chu:0,
-Chu:0, Reason:Maybe
----------
CC(T+293401.8) collected: 52 (52 waiting for GC), suspected: 765,
duration: 491 ms.
----------
GC(T+293417.3) Type:Glob, Total:976.5, Wait:3.5, Mark:486.1,
Sweep:477.9, FinObj:14.6, FinStr:4.3, FinScr:3.0, FinShp:13.8,
DisCod:7.8, DisAnl:218.8, XPCnct:13.6, Destry:193.6, End:19.7, +Chu:0,
-Chu:0, Reason:Maybe
----------
CC(T+293427.0) collected: 52 (52 waiting for GC), suspected: 793,
duration: 4613 ms.
----------
CC(T+293433.9) collected: 23 (75 waiting for GC), suspected: 3175,
duration: 462 ms.
----------
GC(T+293439.4) Type:Glob, Total:1989.4, Wait:943.4, Mark:435.3,
Sweep:597.9, FinObj:22.5, FinStr:4.8, FinScr:3.2, FinShp:13.2,
DisCod:7.4, DisAnl:281.4, XPCnct:17.5, Destry:239.6, End:27.5, +Chu:0,
-Chu:0, Reason:Maybe
----------
CC(T+293445.1) collected: 1112 (1112 waiting for GC), suspected: 4433,
duration: 517 ms.
----------
GC(T+293450.1) Type:Glob, Total:1051.8, Wait:3.6, Mark:445.0,
Sweep:590.9, FinObj:32.4, FinStr:4.4, FinScr:2.8, FinShp:12.0,
DisCod:7.5, DisAnl:509.2, XPCnct:14.0, Destry:0.5, End:23.6, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293455.6) collected: 4421 (4421 waiting for GC), suspected: 2136,
duration: 468 ms.
----------
GC(T+293460.2) Type:Glob, Total:605.5, Wait:4.9, Mark:436.8,
Sweep:156.4, FinObj:6.1, FinStr:1.0, FinScr:3.2, FinShp:12.2,
DisCod:7.1, DisAnl:104.9, XPCnct:13.5, Destry:0.5, End:18.1, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293465.7) collected: 52 (52 waiting for GC), suspected: 458,
duration: 468 ms.
----------
GC(T+293480.9) Type:Glob, Total:666.6, Wait:19.2, Mark:436.5,
Sweep:208.0, FinObj:6.7, FinStr:1.0, FinScr:2.8, FinShp:11.3,
DisCod:7.2, DisAnl:139.9, XPCnct:13.2, Destry:18.0, End:13.5, +Chu:0,
-Chu:0, Reason:Maybe
----------
GC(T+293486.2) Type:Glob, Total:625.9, Wait:1.0, Mark:435.6,
Sweep:157.9, FinObj:7.0, FinStr:3.9, FinScr:3.1, FinShp:12.1,
DisCod:7.4, DisAnl:101.9, XPCnct:13.6, Destry:0.6, End:42.3, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293490.7) collected: 3489 (3489 waiting for GC), suspected: 1567,
duration: 4514 ms.
----------
GC(T+293495.3) Type:Glob, Total:638.3, Wait:2.2, Mark:449.0,
Sweep:181.4, FinObj:5.5, FinStr:0.7, FinScr:3.3, FinShp:11.6,
DisCod:6.7, DisAnl:131.8, XPCnct:13.1, Destry:0.5, End:16.0, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293500.8) collected: 142 (142 waiting for GC), suspected: 415,
duration: 456 ms.
----------
GC(T+293516.0) Type:Glob, Total:624.2, Wait:2.5, Mark:431.0,
Sweep:185.2, FinObj:8.2, FinStr:4.2, FinScr:2.7, FinShp:11.5,
DisCod:6.9, DisAnl:113.8, XPCnct:13.4, Destry:16.3, End:16.2, +Chu:0,
-Chu:0, Reason:Maybe
----------
CC(T+293521.5) collected: 94 (94 waiting for GC), suspected: 999,
duration: 504 ms.
----------
GC(T+293536.6) Type:Glob, Total:615.9, Wait:5.0, Mark:433.8,
Sweep:171.2, FinObj:23.1, FinStr:4.3, FinScr:2.8, FinShp:11.7,
DisCod:7.2, DisAnl:85.2, XPCnct:13.5, Destry:15.4, End:16.6, +Chu:0,
-Chu:0, Reason:Maybe
----------
CC(T+293542.1) collected: 52 (52 waiting for GC), suspected: 894,
duration: 459 ms.
----------
GC(T+293557.4) Type:Glob, Total:743.4, Wait:4.3, Mark:468.9,
Sweep:263.0, FinObj:54.5, FinStr:4.7, FinScr:2.9, FinShp:13.5,
DisCod:9.2, DisAnl:132.7, XPCnct:15.5, Destry:21.7, End:18.9, +Chu:0,
-Chu:0, Reason:Maybe
----------
CC(T+293567.0) collected: 109 (109 waiting for GC), suspected: 1746,
duration: 4676 ms.
----------
GC(T+293567.7) Type:Glob, Total:651.9, Wait:4.3, Mark:458.6,
Sweep:179.1, FinObj:20.1, FinStr:4.3, FinScr:2.8, FinShp:12.0,
DisCod:7.4, DisAnl:110.3, XPCnct:13.6, Destry:0.5, End:20.9, +Chu:0,
-Chu:0, Reason: API
----------
GC(T+293573.4) Type:Glob, Total:1144.9, Wait:1.4, Mark:430.9,
Sweep:708.0, FinObj:13.6, FinStr:0.9, FinScr:2.9, FinShp:13.6,
DisCod:9.0, DisAnl:644.3, XPCnct:13.8, Destry:1.4, End:15.7, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293574.0) collected: 876 (876 waiting for GC), suspected: 3310,
duration: 532 ms.
----------
statse.webtrendslive.com : server does not support RFC 5746, see
CVE-2009-3555
----------
statse.webtrendslive.com : server does not support RFC 5746, see
CVE-2009-3555
----------
GC(T+293578.7) Type:Glob, Total:658.4, Wait:4.9, Mark:436.5,
Sweep:207.6, FinObj:10.8, FinStr:4.2, FinScr:2.7, FinShp:11.6,
DisCod:7.2, DisAnl:148.0, XPCnct:13.8, Destry:1.4, End:20.4, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293580.0) collected: 199 (199 waiting for GC), suspected: 1478,
duration: 516 ms.
----------
statse.webtrendslive.com : server does not support RFC 5746, see
CVE-2009-3555
----------
statse.webtrendslive.com : server does not support RFC 5746, see
CVE-2009-3555
----------
GC(T+293588.0) Type:Glob, Total:1211.3, Wait:4.6, Mark:473.3,
Sweep:728.9, FinObj:7.1, FinStr:1.3, FinScr:3.0, FinShp:12.0,
DisCod:8.1, DisAnl:675.0, XPCnct:13.8, Destry:0.5, End:15.5, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293588.7) collected: 745 (745 waiting for GC), suspected: 7136,
duration: 604 ms.
----------
GC(T+293593.6) Type:Glob, Total:683.7, Wait:4.8, Mark:449.1,
Sweep:219.0, FinObj:8.3, FinStr:3.7, FinScr:2.9, FinShp:13.8,
DisCod:7.1, DisAnl:160.6, XPCnct:13.9, Destry:0.6, End:22.0, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293599.3) collected: 231 (231 waiting for GC), suspected: 2307,
duration: 2504 ms.
----------
CC(T+293609.2) collected: 68 (299 waiting for GC), suspected: 8283,
duration: 1799 ms.
----------
GC(T+293610.3) Type:Glob, Total:1022.2, Wait:3.5, Mark:454.4,
Sweep:559.6, FinObj:9.9, FinStr:320.5, FinScr:2.8, FinShp:11.4,
DisCod:7.1, DisAnl:184.9, XPCnct:13.3, Destry:1.4, End:15.3, +Chu:15,
-Chu:0, Reason: API
----------
GC(T+293614.9) Type:Glob, Total:589.7, Wait:1.3, Mark:437.3,
Sweep:142.6, FinObj:6.3, FinStr:3.4, FinScr:2.7, FinShp:11.6,
DisCod:6.8, DisAnl:89.0, XPCnct:13.5, Destry:1.4, End:19.3, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293615.8) collected: 1920 (1920 waiting for GC), suspected: 712,
duration: 478 ms.
----------
GC(T+293619.5) Type:Glob, Total:637.8, Wait:5.1, Mark:454.9,
Sweep:174.7, FinObj:5.0, FinStr:0.6, FinScr:2.7, FinShp:11.1,
DisCod:6.5, DisAnl:127.0, XPCnct:13.3, Destry:0.5, End:13.6, +Chu:0,
-Chu:0, Reason: API
----------
CC(T+293629.0) collected: 1403 (1403 waiting for GC), suspected: 12802,
duration: 6192 ms.
----------
GC(T+293629.7) Type:Glob, Total:591.4, Wait:3.6, Mark:464.5,
Sweep:120.4, FinObj:5.4, FinStr:0.7, FinScr:2.7, FinShp:11.0,
DisCod:6.7, DisAnl:72.2, XPCnct:13.4, Destry:0.5, End:13.7, +Chu:0,
-Chu:0, Reason: API
----------
GC(T+293634.4) Type:Glob, Total:647.6, Wait:1.5, Mark:438.2,
Sweep:205.0, FinObj:5.0, FinStr:0.6, FinScr:2.7, FinShp:11.1,
DisCod:6.8, DisAnl:156.8, XPCnct:13.4, Destry:0.5, End:13.6, +Chu:0,
-Chu:1, Reason: API
----------
CC(T+293635.2) collected: 78 (78 waiting for GC), suspected: 432,
duration: 502 ms.
----------
GC(T+293638.9) Type:Glob, Total:557.7, Wait:4.4, Mark:433.9,
Sweep:116.6, FinObj:4.9, FinStr:0.7, FinScr:2.7, FinShp:11.1,
DisCod:6.5, DisAnl:68.9, XPCnct:13.2, Destry:0.5, End:13.3, +Chu:0,
-Chu:12, Reason: API
----------
CC(T+293644.4) collected: 52 (52 waiting for GC), suspected: 308,
duration: 489 ms.
----------
GC(T+293659.6) Type:Glob, Total:650.8, Wait:4.9, Mark:463.8,
Sweep:179.1, FinObj:6.5, FinStr:0.9, FinScr:2.7, FinShp:11.1,
DisCod:7.1, DisAnl:95.9, XPCnct:13.4, Destry:33.0, End:13.6, +Chu:0,
-Chu:0, Reason:Maybe
----------
CC(T+293665.1) collected: 42 (42 waiting for GC), suspected: 303,
duration: 508 ms.
----------
GC(T+293680.2) Type:Glob, Total:618.6, Wait:4.7, Mark:437.8,
Sweep:173.2, FinObj:7.0, FinStr:1.0, FinScr:2.8, FinShp:11.2,
DisCod:7.2, DisAnl:112.6, XPCnct:13.3, Destry:10.2, End:13.5, +Chu:0,
-Chu:0, Reason:Maybe
----------
CC(T+293689.5) collected: 120 (120 waiting for GC), suspected: 341,
duration: 4288 ms.

[Boris Zbarsky]

On 12/5/11 11:10 PM, Boris Zbarsky wrote:
> On 12/2/11 1:26 PM, Boris Zbarsky wrote:
>> I'll work on generating such a log. Give me a few days. ;)
>
> OK, until about 30 minutes ago things were looking OK (in that the GCs
> were every 10 secs, but not too long and whatnot).
>
> But now my log is looking like what I pasted below... and things are not
> happy. See some of those CC durations.

And overnight things got worse. By morning, the browser was
consistently using 100-180% CPU (so a full core or two) and CC times
were up into the 8-20s range. At that point I just killed it. :(

-Boris

[Gian-Carlo Pascutto]

On 6/12/2011 18:43, Boris Zbarsky wrote:

> And overnight things got worse. By morning, the browser was
> consistently using 100-180% CPU (so a full core or two) and CC times
> were up into the 8-20s range. At that point I just killed it. :(

Is there a bug for this? I'm seeing this behavior too. Browser is
regularly using CPU in task manager, even though I only have "static"
tabs open, memory usage going 450M->550M and back, and occasionally is
very slow to respond to clicks.

--
GCP

[Andreas Gal]

On Dec 10, 2011, at 6:27 PM, Gian-Carlo Pascutto wrote:

> On 6/12/2011 18:43, Boris Zbarsky wrote:
>
>> And overnight things got worse. By morning, the browser was
>> consistently using 100-180% CPU (so a full core or two) and CC times

If you see > 100% CPU, this must be a dynamic leak (we are generating lots of garbage and are actually doing work to GC/CC it again, we aren't just scanning a heap where most stuff is alive). The 80% on top of a full CPU load is most likely the background free mechanism.

Andreas

>> were up into the 8-20s range. At that point I just killed it. :(
>
> Is there a bug for this? I'm seeing this behavior too. Browser is
> regularly using CPU in task manager, even though I only have "static"
> tabs open, memory usage going 450M->550M and back, and occasionally is
> very slow to respond to clicks.
>
> --
> GCP

> _______________________________________________
> dev-platform mailing list
> dev-pl...@lists.mozilla.org
> https://lists.mozilla.org/listinfo/dev-platform

[smaug]

On 12/06/2011 06:10 AM, Boris Zbarsky wrote:
> On 12/2/11 1:26 PM, Boris Zbarsky wrote:
>> I'll work on generating such a log. Give me a few days. ;)
>
> OK, until about 30 minutes ago things were looking OK (in that the GCs
> were every 10 secs, but not too long and whatnot).
>
> But now my log is looking like what I pasted below... and things are not
> happy. See some of those CC durations.
>
> There _might_ be a correlation with me reading comments on
> ews.slashdot.org/story/11/12/05/1717201/will-firefox-lose-google-funding
> and maybe making a few comments, then closing a bunch of those tabs.
> Hard to tell... I did that about 10 minutes ago, but the CC times are
> still sucking.

And GC times even more.

I _think_ there could be some bug which is triggered in some case, and
after that CC/GC get just a lot worse.
I've seen that happening once or twice with tbpl (I did have plenty of
tbpl tabs open).
First CC and GC times were <100ms, and suddenly they jumped to 500ms.

[smaug]

Here are some tryserver (FF10/Aurora) builds
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/ope...@mozilla.com-748377522c01/

Would be good if someone could try whether they help with CC time
problems in FF10.