Note: There are a few cases of duplicates in user autocompletion which are being worked on.

[CC] add additional information to cycle collector's error console logging

RESOLVED FIXED in mozilla13

Status

()

Core
XPCOM
RESOLVED FIXED
6 years ago
6 years ago

People

(Reporter: mccr8, Assigned: mccr8)

Tracking

Trunk
mozilla13
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [MemShrink:P2])

Attachments

(1 attachment, 1 obsolete attachment)

(Assignee)

Description

6 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.
Assignee: nobody → continuation
Whiteboard: [MemShrink] → [MemShrink:P2]
(Assignee)

Comment 1

6 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.
(Assignee)

Comment 2

6 years ago
smaug suggests that additional timing information would be useful (total, initial graph creation, traverse, root, unlink, unroot).
Summary: add stats about cycle collector graph size to error console CC stats → [CC] add additional information to cycle collector's error console logging
(Assignee)

Updated

6 years ago
Depends on: 697134
(Assignee)

Comment 3

6 years ago
bz would like information about when the CC forces a GC.
(Assignee)

Comment 4

6 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.
Blocks: 727965
(Assignee)

Comment 5

6 years ago
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.
Attachment #598449 - Flags: feedback?(bugs)

Comment 6

6 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.
Attachment #598449 - Flags: feedback?(bugs) → feedback+
(Assignee)

Comment 7

6 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.
(Assignee)

Comment 8

6 years ago
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
Attachment #598449 - Attachment is obsolete: true
Attachment #599729 - Flags: review?(bugs)

Comment 9

6 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;
Attachment #599729 - Flags: review?(bugs) → review+
(Assignee)

Comment 10

6 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...
(Assignee)

Comment 11

6 years ago
Hmm.  Maybe it should be <=...?
Ah, yes <= looks right
(Assignee)

Comment 13

6 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/66a56113abeb
Target Milestone: --- → mozilla13
https://hg.mozilla.org/mozilla-central/rev/66a56113abeb
Status: NEW → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.