Closed Bug 903131 Opened 6 years ago Closed 6 years ago

Add buttons to dump gc/cc logs to about:memory

Categories

(Toolkit :: about:memory, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla29

People

(Reporter: justin.lebar+bug, Assigned: erahm)

Details

(Whiteboard: [MemShrink:P3][good first verify])

Attachments

(1 file, 4 obsolete files)

Can we add a button to do an all-traces gc/cc log and another button to do a non-all-traces gc/cc log to about:memory?  This seems a lot easier than asking people to copy/paste something into the error console.

The main trick would be that I'd like to print the paths of the log files out to about:memory.  To get this to work, we might have to change the CC interface a bit.
Whiteboard: [MemShrink]
Whiteboard: [MemShrink] → [MemShrink:P2]
mccr8, do you think this is still useful?
Yeah, it would be handy, but not essential.
Whiteboard: [MemShrink:P2] → [MemShrink:P3]
Assignee: nobody → erahm
- Added out params to return log paths
- Added attributes to cycle collector interface to export log paths
Attachment #8367001 - Flags: feedback?(n.nethercote)
Attachment #8367001 - Flags: feedback?(continuation)
Initial thoughts on implementing this feature request, any and all feedback welcomed on the approach/style/etc.
Comment on attachment 8367001 [details] [diff] [review]
Add GC/CC logs button to about:memory- Added buttons, JS to trigger logs to be generated

Review of attachment 8367001 [details] [diff] [review]:
-----------------------------------------------------------------

This is a pretty good start! It's non-trivial to get things working across the JS/C++ divide, so you've done on that front.

AIUI, this dumps two files: the GC log and the CC log. But much of the patch only talks about CC logs. It should mention both for consistency and to avoid confusion.

W.r.t the commit message, people occasionally use the "b=903131 Msg" form, but "Bug 903131 - Msg" is more common and probably better.

::: dom/ipc/ContentChild.cpp
@@ +549,2 @@
>      dumper->DumpGCAndCCLogsToFile(aIdentifier, aDumpAllTraces,
> +                                  aDumpChildProcesses, gcLogPath, ccLogPath);

Args need the 'a' prefix -- use |aGCLogPath| and |aCCLogPath|.

::: toolkit/components/aboutmemory/content/aboutMemory.js
@@ +283,5 @@
>                   "process to reduce memory usage in other ways, e.g. by " +
>                   "flushing various caches.";
>  
> +  const CCLogDesc = "Dump cycle collection log";
> +  const CCAllLogDesc = "Dump all cycle collection log";

Should be "garbage collection and cycle collection logs", or similar. And "Save" is better than "Dump" (and will match my other suggestions below).

@@ +313,5 @@
>  
>    appendElementWithText(row2, "div", "opsRowLabel", "Save memory reports");
>    appendButton(row2, SvDesc, saveReportsToFile, "Measure and save" + kEllipsis);
> +  appendButton(row2, CCLogDesc, dumpCCLogsNoAllTraces, "Dump CC logs");
> +  appendButton(row2, CCAllLogDesc, dumpCCLogsAllTraces, "Dump all CC logs");

Should be "GC & CC".

Also the new buttons don't really belong in the "Save memory reports" box. Perhaps a new box, at the end called "Save GC && CC logs", is best. The buttons could be "Save normal" and "Save all". (Though those labels aren't great, partly because our names for these actions aren't great. mccr8 might have ideas.)

@@ +400,5 @@
> +{
> +  dumpCCLogs(true);
> +}
> +
> +function dumpCCLogs(allTraces)

Should be |aAllTraces|.

@@ +403,5 @@
> +
> +function dumpCCLogs(allTraces)
> +{
> +  let gcLogPath = "";
> +  let ccLogPath = {};

Using "" for gcLogPath caused my opt build to crash (and I guess that's the assertion you saw in debug builds that you told me about on IRC).

@@ +408,5 @@
> +
> +  let dumper = Cc["@mozilla.org/memory-info-dumper;1"]
> +                .getService(Ci.nsIMemoryInfoDumper);
> +
> +  dumper.dumpGCAndCCLogsToFile("", allTraces, false, gcLogPath, ccLogPath);

For non-descript bool and integer arguments I like to add a comment, e.g. |/* dumpChildProcesses = */ false|.

Also, it should probably be |true| instead, so that child processes get dumped.

@@ +412,5 @@
> +  dumper.dumpGCAndCCLogsToFile("", allTraces, false, gcLogPath, ccLogPath);
> +
> +  let logString = "Garbage collector log: " + gcLogPath.value + "\n" +
> +                  "Cycle collector log:" + ccLogPath.value;
> +  updateMainAndFooter(logString, HIDE_FOOTER);

The "\n" has no effect so they both end up on the same line, which looks ugly. Off the top of my head, I'm not sure how to force a newline in there...

::: xpcom/base/nsICycleCollectorListener.idl
@@ +50,5 @@
>      // This string will appear somewhere in the log's filename.
>      attribute AString filenameIdentifier;
>  
> +    // This string will indicate the full path of the GC log if enabled.
> +    readonly attribute AString gcLogPath;

So this stores the name of the last file that we dumped to, and in practice we write this and then read it very shortly after. It feels clunky to store that in a data member; it would be better if it could be immediately returned from one of the methods being called. For nsCycleCollectorLogger that method is begin(), and it seems to be the only implementation of nsICycleCollectorListener, so maybe changing it would be ok. mccr8 might have suggestions here.
Attachment #8367001 - Flags: feedback?(n.nethercote) → feedback+
Comment on attachment 8367001 [details] [diff] [review]
Add GC/CC logs button to about:memory- Added buttons, JS to trigger logs to be generated

Review of attachment 8367001 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/ipc/ContentChild.cpp
@@ +549,2 @@
>      dumper->DumpGCAndCCLogsToFile(aIdentifier, aDumpAllTraces,
> +                                  aDumpChildProcesses, gcLogPath, ccLogPath);

These aren't args, they're dummy params. Although they could be args if we want to support dumping child processes.

::: toolkit/components/aboutmemory/content/aboutMemory.js
@@ +283,5 @@
>                   "process to reduce memory usage in other ways, e.g. by " +
>                   "flushing various caches.";
>  
> +  const CCLogDesc = "Dump cycle collection log";
> +  const CCAllLogDesc = "Dump all cycle collection log";

Will fix.

@@ +313,5 @@
>  
>    appendElementWithText(row2, "div", "opsRowLabel", "Save memory reports");
>    appendButton(row2, SvDesc, saveReportsToFile, "Measure and save" + kEllipsis);
> +  appendButton(row2, CCLogDesc, dumpCCLogsNoAllTraces, "Dump CC logs");
> +  appendButton(row2, CCAllLogDesc, dumpCCLogsAllTraces, "Dump all CC logs");

Will move to new section, I'll use the proposed naming for now.

@@ +400,5 @@
> +{
> +  dumpCCLogs(true);
> +}
> +
> +function dumpCCLogs(allTraces)

Will fix.

@@ +403,5 @@
> +
> +function dumpCCLogs(allTraces)
> +{
> +  let gcLogPath = "";
> +  let ccLogPath = {};

Good catch, accidentally committed while reproducing that issue.

@@ +408,5 @@
> +
> +  let dumper = Cc["@mozilla.org/memory-info-dumper;1"]
> +                .getService(Ci.nsIMemoryInfoDumper);
> +
> +  dumper.dumpGCAndCCLogsToFile("", allTraces, false, gcLogPath, ccLogPath);

Will add comment.

re: dumping child processes. That will make this more complicated than it already is. Each process will have it's own logs, so we won't be able to just use 2 new params. We could possibly change this take an array, but in that case I could use some pointers on how to do an out array of strings in XPIDL (without knowing the size ahead of time).

@@ +412,5 @@
> +  dumper.dumpGCAndCCLogsToFile("", allTraces, false, gcLogPath, ccLogPath);
> +
> +  let logString = "Garbage collector log: " + gcLogPath.value + "\n" +
> +                  "Cycle collector log:" + ccLogPath.value;
> +  updateMainAndFooter(logString, HIDE_FOOTER);

I'll convert it to a list and add the elements after calling updateMainAndFooter.

::: xpcom/base/nsICycleCollectorListener.idl
@@ +50,5 @@
>      // This string will appear somewhere in the log's filename.
>      attribute AString filenameIdentifier;
>  
> +    // This string will indicate the full path of the GC log if enabled.
> +    readonly attribute AString gcLogPath;

My main issue is that we care about 2 logs (GC & CC), we'll only be able to return GC here (and only if logging is enabled). So we'd still need the ccLogPath attribute which makes it kind of a non-win.
aboutMemory.js cleanup
Attachment #8367096 - Flags: feedback?(n.nethercote)
Attachment #8367096 - Flags: feedback?(continuation)
Attachment #8367001 - Attachment is obsolete: true
Attachment #8367001 - Flags: feedback?(continuation)
> These aren't args, they're dummy params. Although they could be args if we
> want to support dumping child processes.

Oh, duh. My bad.

> re: dumping child processes. That will make this more complicated than it
> already is. Each process will have it's own logs, so we won't be able to
> just use 2 new params. We could possibly change this take an array, but in
> that case I could use some pointers on how to do an out array of strings in
> XPIDL (without knowing the size ahead of time).

Arrays of strings in XPIDL are... difficult. I'm happy to let child processes slide for the moment. Desktop Firefox is currently mostly one process, and a second process is in the works (see https://wiki.mozilla.org/Electrolysis and http://billmccloskey.wordpress.com/2013/12/05/multiprocess-firefox/) but it's still a way off. And GC/CC dumps are done in a different way that already works for multiple processes.

Alternatively, we could chop off the filenames and just print the directory where the files get printed. It's not as informative, but might be good enough.
Comment on attachment 8367096 [details] [diff] [review]
Add GC/CC logs button to about:memory- Added buttons, JS to trigger logs to be generated

Review of attachment 8367096 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks for the updates. Apologies for the pedantry; I spend a lot of time interacting with about:memory so I'm kinda picky about it :)

::: toolkit/components/aboutmemory/content/aboutMemory.js
@@ +284,5 @@
>                   "flushing various caches.";
>  
> +  const GCAndCCLogDesc = "Save garbage collection and cycle collection logs";
> +  const GCAndCCAllLogDesc = "Save all garbage collection and cycle " +
> +                            "collection logs";

Our crappy names for these logs strike again... the "all" is in the wrong place here.  How about "Save garbage collection and cycle collection logs (normal)" and "Save garbage collection and cycle collection logs (all traces)"?

@@ +323,5 @@
>    appendButton(row3, MMDesc, doMMU, "Minimize memory usage");
>  
> +  let row4 = appendElement(ops, "div", "opsRow");
> +
> +  appendElementWithText(row4, "div", "opsRowLabel", "Save GC && CC logs");

One '&' is enough :)

@@ +325,5 @@
> +  let row4 = appendElement(ops, "div", "opsRow");
> +
> +  appendElementWithText(row4, "div", "opsRowLabel", "Save GC && CC logs");
> +  appendButton(row4, CCLogDesc, saveGCAndCCLogsNoAllTraces, "Save normal");
> +  appendButton(row4, CCAllLogDesc, saveGCAndCCLogsAllTraces, "Save all");

And here: "Save (normal)" and "Save (all traces)"?

(Apologies for my evolving suggestions here.)

Also, you're using the old variable names here, which causes the buttons to not show up in the page. (You can probably guess that I tried out the patch myself. I don't usually do this, but in patches involving UI it's worthwhile because imagining what it looks like from the code can be difficult.)

@@ +394,5 @@
>  {
>    updateAboutMemoryFromReporters();
>  }
>  
> +function saveGCAndCCLogsNoAllTraces()

s/NoAllTraces/Normal/ to go with the above changes?

@@ +423,5 @@
> +  let list = appendElement(section, "ul", "");
> +  appendElementWithText(list, 'li', "",
> +                        "Garbage collector log: " + gcLogPath.value);
> +  appendElementWithText(list, 'li', "",
> +                        "Cycle collector log: " + ccLogPath.value);

How about this?

  let section = appendElement(gMain, "div", "section");
  appendElementWithText(section, 'div', "",
                        "Garbage collector log: " + gcLogPath.value);
  appendElementWithText(section, 'div', "",
                        "Cycle collector log: " + ccLogPath.value);

Shorter, and doesn't introduce list bullets, which makes it consistent with the messages printed after pressing the other buttons.

Also, if you make it "Saved {GC,CC} log to ..." it'll be consistent with the output wording from the "Measure and save..." button.
Attachment #8367096 - Flags: feedback?(n.nethercote) → feedback+
More aboutMemory.js cleanup
Attachment #8367471 - Flags: feedback?(n.nethercote)
Attachment #8367471 - Flags: feedback?(continuation)
Attachment #8367096 - Attachment is obsolete: true
Attachment #8367096 - Flags: feedback?(continuation)
Comment on attachment 8367471 [details] [diff] [review]
Add GC/CC logs button to about:memory

Review of attachment 8367471 [details] [diff] [review]:
-----------------------------------------------------------------

This looks good to me.  I just have a few comments on the descriptions.

::: toolkit/components/aboutmemory/content/aboutMemory.js
@@ +282,5 @@
>                   "collection followed by a cycle collection, and causes the " +
>                   "process to reduce memory usage in other ways, e.g. by " +
>                   "flushing various caches.";
>  
> +  const GCAndCCLogDesc = "Save garbage collection and cycle collection logs " +

So, the all-traces thing only affects the CC logs. Maybe something like "Save garbage collection and optimized cycle collection logs"?  What setting all-traces does is disable a bunch of CC optimizations we do to make the CC much faster, but if you are investigating a leak, getting that extra information is useful.

@@ +285,5 @@
>  
> +  const GCAndCCLogDesc = "Save garbage collection and cycle collection logs " +
> +                         "(normal)";
> +  const GCAndCCAllLogDesc = "Save garbage collection and cycle " +
> +                            "collection logs (all traces)";

The button already says "all traces", which is fine because that's the term we use, but it would be nice for this to be more descriptive.  Maybe something like "Save garbage collection and complete cycle collector logs"?  "complete" or "unoptimized" or "detailed" or something.

@@ +326,5 @@
> +  let row4 = appendElement(ops, "div", "opsRow");
> +
> +  appendElementWithText(row4, "div", "opsRowLabel", "Save GC & CC logs");
> +  appendButton(row4, GCAndCCLogDesc,
> +               saveGCAndCCLogsNormal, "Save (normal)");

I think it is okay here to just say "Save".
Attachment #8367471 - Flags: feedback?(continuation) → feedback+
Comment on attachment 8367471 [details] [diff] [review]
Add GC/CC logs button to about:memory

I've removed the f? request in order to wait for the next version (with updated terminology for button labels/titles and a test), as discussed on IRC.
Attachment #8367471 - Flags: feedback?(n.nethercote)
Cleaned up wording, added IDs for testing, added mochitest
Attachment #8368754 - Flags: review?(n.nethercote)
Attachment #8368754 - Flags: review?(continuation)
Attachment #8367471 - Attachment is obsolete: true
Comment on attachment 8368754 [details] [diff] [review]
Add save GC/CC logs buttons to about:memory

Review of attachment 8368754 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good, thanks!

I didn't review the aboutMemory.js changes, aside from the descriptions.

::: toolkit/components/aboutmemory/content/aboutMemory.js
@@ +285,5 @@
>                   "flushing various caches.";
>  
> +  const GCAndCCLogDesc = "Save garbage collection and concise cycle " +
> +                         "collection logs\n" +
> +                         "WARNING: These logs may be large (+1G)";

+1G isn't super clear to me.  "possibly 1GB or more" or something?  Maybe that's just me.
Attachment #8368754 - Flags: review?(continuation) → review+
Comment on attachment 8368754 [details] [diff] [review]
Add save GC/CC logs buttons to about:memory

Review of attachment 8368754 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good! I have a few nits below, but nothing big. Nice job getting the mochitest working; they can be fiddly.

Once mccr8 gives r+ and you've addressed the final comments, please upload a final version and I will do a try server run for you, and if that goes well I will land it.

BTW, most patches don't have this many review iterations, but it's not uncommon for someone's first patch :) Especially for a non-trivial patch like this one.

::: toolkit/components/aboutmemory/content/aboutMemory.js
@@ +285,5 @@
>                   "flushing various caches.";
>  
> +  const GCAndCCLogDesc = "Save garbage collection and concise cycle " +
> +                         "collection logs\n" +
> +                         "WARNING: These logs may be large (+1G)";

Nit: "Save garbage collection log and concise cycle collection log" -- makes it clear that there's one of each, and not multiple CC logs.

Nit: use "GB" for consistency with "MB" used elsewhere in about:memory. And I'd write "1GB+" or ">1GB".

@@ +288,5 @@
> +                         "collection logs\n" +
> +                         "WARNING: These logs may be large (+1G)";
> +  const GCAndCCAllLogDesc = "Save garbage collection and verbose cycle " +
> +                            "collection logs\n" +
> +                            "WARNING: These logs may be large (+1G)";

Ditto x 2

@@ +337,4 @@
>    // Generate the main div, where content ("section" divs) will go.  It's
>    // hidden at first.
>  
> +  gMain = appendElement(document.body, 'div', '', 'mainDiv');

appendElement() only takes 3 args, AFAICT. Is this left-over code that can be removed?

@@ +400,5 @@
>  {
>    updateAboutMemoryFromReporters();
>  }
>  
> +function saveGCAndCCLogsNormal()

Rename as saveGCLogAndConciseCCLog().

@@ +405,5 @@
> +{
> +  dumpGCAndCCLogs(false);
> +}
> +
> +function saveGCAndCCLogsAllTraces()

Rename as saveGCLogAndVerboseCCLog().

@@ +410,5 @@
> +{
> +  dumpGCAndCCLogs(true);
> +}
> +
> +function dumpGCAndCCLogs(aAllTraces)

Rename as dumpGCLogAndCCLog(), and the arg as |aVerbose|.

@@ +428,5 @@
> +  let section = appendElement(gMain, 'div', "section");
> +  appendElementWithText(section, 'div', "",
> +                        "Saved GC log to " + gcLogPath.value);
> +  appendElementWithText(section, 'div', "",
> +                        "Saved CC log to " + ccLogPath.value);

Is it worth adding "concise" or "verbose" before "CC log"? That way, the message makes it clear which one you've done, so you don't have to remember.

::: toolkit/components/aboutmemory/tests/test_aboutmemory6.xul
@@ +25,5 @@
> +    let frame = document.getElementById("amFrame");
> +    frame.focus();
> +
> +    // checks that a file exists on the local file system and optionaly
> +    // removes it

Upper-case letter at start and period at end of sentences, please :) Here and below.

Also: "optionally".

@@ +26,5 @@
> +    frame.focus();
> +
> +    // checks that a file exists on the local file system and optionaly
> +    // removes it
> +    function checkForFileAndRemove(aFilename, aRemoveFile) {

|aRemoveFile| is always true, so just remove it.

@@ +40,5 @@
> +      return exists;
> +    }
> +
> +    // given a save log button triggers the action and checks if both CC & GC
> +    // logs were written to disk

Add a comma after "button".

@@ +55,5 @@
> +      let logNodes = mainDiv.childNodes[0];
> +
> +      // we expect 2 logs listed
> +      let numOfLogs = logNodes.childNodes.length;
> +      ok(numOfLogs == 2, "two logs entries generated")

s/logs/log/

@@ +61,5 @@
> +      // grab the path portion of the text
> +      let gcLogPath = logNodes.childNodes[0].textContent
> +                        .replace("Saved GC log to ", "");
> +      let ccLogPath = logNodes.childNodes[1].textContent
> +                        .replace("Saved CC log to ", "");

If you add the "verbose"/"concise" to the message, you'll need to update this too.
Attachment #8368754 - Flags: review?(n.nethercote)
Attachment #8368754 - Flags: review?(continuation)
Attachment #8368754 - Flags: review+
Comment on attachment 8368754 [details] [diff] [review]
Add save GC/CC logs buttons to about:memory

I already r+ed it. ;)
Attachment #8368754 - Flags: review?(continuation) → review+
> I already r+ed it. ;)

And you made me click through an "invalid token" warning in Bugzilla... you monster. :P
Cleaned up comments, updated names, fixed setting gMain id
Attachment #8368754 - Attachment is obsolete: true
Try push:
https://tbpl.mozilla.org/?tree=Try&rev=ebd2ec1a3afd

I chose to build on all platforms, because it's always a good idea to check if you haven't broken compilation on any platforms. And I chose to test only the mochitest-o suite, because that's the one that contains the about:memory tests.

BTW, I added periods to the titles of the new buttons, because I realized that the titles of the other buttons had them. And I added "r=njn,mccr8." to the log message, because that's required for patches that are landed.
Also, it is usual to, when uploading a revised patch to address review comments, to r+ the patch yourself, and then have a comment like "Carrying forward r+ from njn and mccr8".  That makes it clearer that it is a patch that has been reviewed, and not just something random.
(In reply to Andrew McCreight [:mccr8] from comment #20)
> Also, it is usual to, when uploading a revised patch to address review
> comments, to r+ the patch yourself, and then have a comment like "Carrying
> forward r+ from njn and mccr8".  That makes it clearer that it is a patch
> that has been reviewed, and not just something random.

... that's assuming the previous patch got r+ :)

BTW, it's common to give r+ while also making some comments; it basically means "I trust you to fix these before landing, and I don't need to see it again".
Landed!
https://hg.mozilla.org/integration/mozilla-inbound/rev/ea871fc76f16

Congratulations.

The try run looked good. There were two oranges (test failures), which I starred because they were known intermittent failures unrelated to your patch. And there was an odd Windows red (build failure) which looked bogus and when I re-triggered it was green, so it must have been an infrastructure problem or something.

One of the sheriffs will merge it from mozilla-inbound to mozilla-central in the next day or so, and when they do that they will mark the bug as RESOLVED FIXED.

Oh, one last thing: can you please update https://wiki.mozilla.org/Performance:Leak_Tools#Cycle_collector_heap_dump to mention the new buttons. Say something like "If you are using FF29 or later, use the buttons; otherwise <the old instructions>". Thanks!
Flags: needinfo?(erahm)
All green on try, but five crashes when landing on m-i? So much for due diligence. Very strange.
Oh, I think I know what happened: the patch changed two IDL interfaces but I failed to notice in my review that their uuids hadn't been changed, as they should have ben. So everything worked on try because try always does a full clobber build, but m-i does an incremental build and the lack of uuid updates caused bustage.

I'll try again with updated uuids on Monday morning.
Oops!  Yeah, sorry about that.
> try always does a full clobber build, but m-i does an incremental build

Why is that, BTW? Lately it's caused me problems about once a month. If try did incremental builds these problems would be much more likely to manifest there.
Because who knows what state the object directory was left in after the last try build?
To test incremental builds, you'd have to do something like, do a clobber build of the revision previous to the revision you pushed, then do an incremental build of what you actually pushed.  It might be worth it for some cases where you already know there's a problem with incremental builds, but I don't know that the extra time would be worth it in general.
Re-landed with updated uuids:
https://hg.mozilla.org/integration/mozilla-inbound/rev/a9aa058ce0af

erahm, FYI: every IDL interface has a uuid which identifies it and needs to be changed if the interface changes. You can generate a new uuid easily with |mach uuid|.
Thanks for patching it up! It seems like a simple precommit hook could catch things like this (.idl changed, but uuid didn't), but at least now I know what needs to be done.
Flags: needinfo?(erahm)
> It seems like a simple precommit hook could catch
> things like this (.idl changed, but uuid didn't)

It's a good idea, though I'm not sure if it's so simple... you'd have to be careful to correctly identify changes that don't affect interfaces (e.g. comment-only changes, or changes to the |%{C++ ... %}| section).

But if you can see a way to do it, please feel free to file a new bug (bug 938419 and bug 938416 are similar ones you could copy) and even implement it :)
(I'm reinstating the NEEDINFO request as a reminder to update the docs as per comment 22. Thanks.)
Flags: needinfo?(erahm)
There's been some work on a precommit hook.  I know we check something like that on branches.
https://hg.mozilla.org/mozilla-central/rev/a9aa058ce0af
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla29
Wiki has been updated.
Flags: needinfo?(erahm)
Whiteboard: [MemShrink:P3] → [MemShrink:P3][good first verify]
You need to log in before you can comment on or make changes to this bug.