Andrew McCreight [:mccr8] Assignee
	Description • 13 years ago

The CC stats tell you how long the CC took, but not how large the CC graph is.  Presumably CC time is proportional to the size of the graph, but having confirmation of this would be nice, plus we could get the split of ref counted vs. GCed items in the graph, in case some JS change, for instance, makes that part of things blow up.  We're already computing these stats for telemetry, so it is probably just a matter of shoving the data into the right place.

	Andrew McCreight [:mccr8] Assignee
	Comment 1 • 13 years ago

More generally, we could probably collect and return more stats about what the cycle collector did.  One thing that might be interesting is to compute the number of JS objects the cycle collector "freed".  Right now, the triggers are based on the total number of objects the CC freed, but things in a pure DOM cycle should not make us more likely to do a GC.  However, this information is not currently collected, and would require a small amount of additional work on the part of the cycle collector.  Though we could avoid extra branches by somehow making the currently-pointless JS Unlink callback increment a count of freed JS objects.

	Andrew McCreight [:mccr8] Assignee
	Comment 2 • 13 years ago

smaug suggests that additional timing information would be useful (total, initial graph creation, traverse, root, unlink, unroot).

	Andrew McCreight [:mccr8] Assignee
	Comment 3 • 13 years ago

bz would like information about when the CC forces a GC.

	Andrew McCreight [:mccr8] Assignee
	Comment 4 • 13 years ago

I need to reconfigure how we pass information back to nsJSEnvironment anyways, so I might as well do this as part of that cleanup.

	Andrew McCreight [:mccr8] Assignee
	Comment 5 • 13 years ago

Currently, all we pass back from the CC is the number of objects that were collected.  This patch adds a new struct argument that is used to return various stats about the behavior of the CC.  Along with this, we compute a new piece of information, which is the split of collected objects between RCed and GCed, with a bit of a hack.  Then this new information is displayed in the error console.

With this patch, making waiting for GC be based on GCed objects is a one line change, but I want to split this out separately because it is a reasonably large refactoring that shouldn't have any impact on behavior.

	Olli Pettay [:smaug][bugs@pettay.fi]
	Comment 6 • 13 years ago

Comment on attachment 598449 [details] [diff] [review]
pass more results back, print them out


>+    nsString gcmsg;
>+    if (ccResults.mForcedGC) {
>+      gcmsg = NS_LITERAL_STRING(", Forced GC");
>+    } else {
>+      gcmsg = NS_LITERAL_STRING("");
>+    }
Strings are empty by default, and never use NS_LITERAL_STRING("") but EmptyString()
But in this case
nsAutoString gcmsg;
if (ccResults.mForcedGC) {
  gcmsg.AssignLiteral(", Forced GC");
}
Or you could use NS_NAMED_LITERAL_STRING(gcmsg, ", Forced GC") and
ccResults.mForcedGC ? gcmsg.get() : EmptyString().get()


>+
>     NS_NAMED_MULTILINE_LITERAL_STRING(kFmt,
>-      NS_LL("CC(T+%.1f) collected: %lu (%lu waiting for GC), suspected: %lu, duration: %llu ms.\n")
>+      NS_LL("CC(T+%.1f) Duration: %llums, Suspected: %lu, Visited: %lu RCed %lu GCed, Collected: %lu RCed %lu GCed (%lu waiting for GC)%s\n")
>       NS_LL("ForgetSkippable %lu times before CC, min: %lu ms, max: %lu ms, avg: %lu ms, total: %lu ms, removed: %lu"));
There is now inconsistency with capital letters. I'd prefer lowercase, but I don't know which one is more correct in English.
Does this change break memchaser? If so, could you try to not make changes which break it (like keep duration as it is now).
I don't know if memchaser actually uses this information.

	Andrew McCreight [:mccr8] Assignee
	Comment 7 • 13 years ago

(In reply to Olli Pettay [:smaug] from comment #6)
> Or you could use NS_NAMED_LITERAL_STRING(gcmsg, ", Forced GC") and
> ccResults.mForcedGC ? gcmsg.get() : EmptyString().get()

Thanks, I'm not familiar with all of the string stuff.

> There is now inconsistency with capital letters. I'd prefer lowercase, but I
> don't know which one is more correct in English.

I was trying to be consistent with the GC logging messages, but maybe that's not worthwhile.

> Does this change break memchaser? If so, could you try to not make changes
> which break it (like keep duration as it is now).
> I don't know if memchaser actually uses this information.

Good point.  I should coordinate with them.  It uses the duration information at least.

	Andrew McCreight [:mccr8] Assignee
	Comment 8 • 13 years ago

Here's what the output looks like:

CC(T+19.4) duration: 54ms, suspected: 16801, visited: 25263 RCed and 1980 GCed, collected: 19497 RCed and 544 GCed (20041 waiting for GC)
ForgetSkippable 35 times before CC, min: 0 ms, max: 6 ms, avg: 2 ms, total: 95 ms, removed: 41329

	Olli Pettay [:smaug][bugs@pettay.fi]
	Comment 9 • 13 years ago

Comment on attachment 599729 [details] [diff] [review]
pass more results, print them out

 
>+    nsString gcmsg;
>+    if (ccResults.mForcedGC) {
>+      gcmsg.AssignLiteral(", forced a GC");
>+    }
>+
nsAutoString gcmsg;

	Andrew McCreight [:mccr8] Assignee
	Comment 10 • 13 years ago

Hmm.  That's odd, I hit this assertion during build:
###!!! ASSERTION: More freed GCed nodes than total freed nodes.: 'numWhiteGCed < count',

but not all of the time...

	Andrew McCreight [:mccr8] Assignee
	Comment 11 • 13 years ago

Hmm.  Maybe it should be <=...?

	Olli Pettay [:smaug][bugs@pettay.fi]
	Comment 12 • 13 years ago

Ah, yes <= looks right

	Andrew McCreight [:mccr8] Assignee
	Comment 13 • 13 years ago

https://hg.mozilla.org/integration/mozilla-inbound/rev/66a56113abeb

	Marco Bonardo [:mak]
	Comment 14 • 13 years ago

https://hg.mozilla.org/mozilla-central/rev/66a56113abeb