Last Comment Bug 697115 - [CC] add additional information to cycle collector's error console logging
: [CC] add additional information to cycle collector's error console logging
Status: RESOLVED FIXED
[MemShrink:P2]
:
Product: Core
Classification: Components
Component: XPCOM (show other bugs)
: Trunk
: All All
: -- normal (vote)
: mozilla13
Assigned To: Andrew McCreight [:mccr8]
:
Mentors:
Depends on: 697134
Blocks: 638299 727965
  Show dependency treegraph
 
Reported: 2011-10-25 08:04 PDT by Andrew McCreight [:mccr8]
Modified: 2012-02-24 02:47 PST (History)
10 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
pass more results back, print them out (19.19 KB, patch)
2012-02-17 17:21 PST, Andrew McCreight [:mccr8]
bugs: feedback+
Details | Diff | Splinter Review
pass more results, print them out (18.96 KB, patch)
2012-02-22 12:13 PST, Andrew McCreight [:mccr8]
bugs: review+
Details | Diff | Splinter Review

Description Andrew McCreight [:mccr8] 2011-10-25 08:04:53 PDT
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.
Comment 1 Andrew McCreight [:mccr8] 2011-10-31 08:54:34 PDT
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.
Comment 2 Andrew McCreight [:mccr8] 2011-11-25 14:35:33 PST
smaug suggests that additional timing information would be useful (total, initial graph creation, traverse, root, unlink, unroot).
Comment 3 Andrew McCreight [:mccr8] 2011-11-29 11:46:35 PST
bz would like information about when the CC forces a GC.
Comment 4 Andrew McCreight [:mccr8] 2012-02-16 15:50:44 PST
I need to reconfigure how we pass information back to nsJSEnvironment anyways, so I might as well do this as part of that cleanup.
Comment 5 Andrew McCreight [:mccr8] 2012-02-17 17:21:47 PST
Created attachment 598449 [details] [diff] [review]
pass more results back, print them out

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.
Comment 6 Olli Pettay [:smaug] (TPAC) 2012-02-18 03:58:47 PST
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.
Comment 7 Andrew McCreight [:mccr8] 2012-02-18 12:02:33 PST
(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.
Comment 8 Andrew McCreight [:mccr8] 2012-02-22 12:13:58 PST
Created attachment 599729 [details] [diff] [review]
pass more results, print them out

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
Comment 9 Olli Pettay [:smaug] (TPAC) 2012-02-22 12:23:17 PST
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;
Comment 10 Andrew McCreight [:mccr8] 2012-02-22 16:27:09 PST
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...
Comment 11 Andrew McCreight [:mccr8] 2012-02-22 16:27:49 PST
Hmm.  Maybe it should be <=...?
Comment 12 Olli Pettay [:smaug] (TPAC) 2012-02-22 16:29:51 PST
Ah, yes <= looks right
Comment 13 Andrew McCreight [:mccr8] 2012-02-23 20:19:22 PST
https://hg.mozilla.org/integration/mozilla-inbound/rev/66a56113abeb
Comment 14 Marco Bonardo [::mak] 2012-02-24 02:47:38 PST
https://hg.mozilla.org/mozilla-central/rev/66a56113abeb

Note You need to log in before you can comment on or make changes to this bug.