320192 - better way for users/testers to detect and isolate leaks of large object graphs

Status: RESOLVED FIXED

(Core :: Layout, defect, P1)

Description

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

At the Firefox Summit last week, in the session http://wiki.mozilla.org/2005Offsite/Memory_Leaks , I discussed better ways for users/testers to find leaks and reduce testcases for leaks.  I'm attaching a way to do this that has some PR-logging code and a perl script to post-process the NSPR logs.  So far I'm just logging four classes.  One of those four is often entrained in leaks of large object graphs, and they all provide a good way to log URIs associated with the leaks.  This means a user can browse for a long time (as normal), run the perl script over the log, and then determine at least which pages were associated with leaks.  The user could then repeat the logging while testing those pages more carefully to get to exact steps to reproduce.

timeless says he has a patch that will allow multiple calls to PR_NewLogModule with the same string to work correctly.  That would make this a little cleaner...

Comment 1

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: NSPR logging code

Comment 2

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: leak-gauge.pl

Kinda ugly, but it works...

Comment 3

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: NSPR logging code

Comment 4

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

I should really log channel implementations instead of load groups.

Timeless, do you have a reference to that NSPR logging bug?

Comment 5

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: leak-gauge.pl

Comment 6

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: NSPR logging code

Without the nsLoadGroup stuff, since I decided it's probably not much use.  (I thought we cancel the loadgroup when we leave a page, which would remove most evidence of leaked channels, although I can't actually find any code that does that.)

Comment 7

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: leak-gauge.pl

Comment 8

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

I think the bug timeless was telling me about is bug 237326.

Comment 9

[Darin Fisher]

Comment on attachment 205867 [details] [diff] [review]
NSPR logging code

Can I encourage you to define LOG and LOG_TEST macros to clean up the code?

#define LOG(args) PR_LOG(gDocumentLeakPRLog, PR_LOG_DEBUG, args)
#define LOG_TEST() PR_LOG_TEST(gDocumentLeakPRLog, PR_LOG_DEBUG)

We do this in a bunch of other places, and IMO the result is a lot more friendly on the eyes ;-)

Comment 10

[Darin Fisher]

Perhaps your macros could also incorporate null checking gDocumentLeakPRLog :)

Comment 11

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

I tend to think it's not worth it since I'm using PR_LOG_TEST separately in about half the calls, and I couldn't use such a macro there without adding a larger performance cost to the non-logging case.

Comment 12

[Jesse Ruderman]

The first time I tried to use this tool, it died :(

> cat nspr7-leaky.log | perl ~/trunk/mozilla/leak-gauge.pl
URI expected at /Users/admin/trunk/mozilla/leak-gauge.pl line 130, <> line 767.

The perl script is trying to do:

                    $rest =~ /^ "(.*)"$/ || die "URI expected";

But the line in the log got cut off and doesn't have a closing quote:

-1610551960[1306bf0]: DOCUMENT 26b60400 StartDocumentLoad "https://bugzilla.mozilla.org/buglist.cgi?bug_status=UNCONFIRMED&bug_status=NEW&bug_status=ASSIGNED&bug_status=REOPENED&bug_status=RESOLVED&bug_status=VERIFIED&bug_status=CLOSED&field0-0-0=product&type0-0-0=substring&value0-0-0=access&field0-0-1=component&type0-0-1=substring&value0-0-1=access&field0-0-2=keywords&type0-0-2=substring&value0-0-2=access&field0-0-3=short_desc&type0-0-3=substring&value0-0-3=access&field0-0-4=status_whiteboard&type0-0-4=s

I think the problem is that PR_LogPrint uses a small, fixed-length buffer, presumably because snprintf requires a fixed-length buffer.

I guess you could either remove the quotes, make the perl script tolerate missing end-quotes, or fix  PR_LogPrint.

Comment 13

[Christian :Biesinger (don't email me, ping me on IRC)]

(fixing nspr logging is bug 244478)

Comment 14

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: NSPR logging code

without quotes

Comment 15

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: leak-gauge.pl

without quotes

Comment 16

[Johnny Stenback (:jst)]

Comment on attachment 206602 [details] [diff] [review]
NSPR logging code

r=jst

Comment 17

[Henrik Gemal]

So I should be able to do:
SET NSPR_LOG_MODULES=DOMLeak:5
and then start firefox, rite?

Comment 18

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Wrong.  See attachment 206603 [details], which I need to figure out where to check in...

Comment 19

[Jesse Ruderman]

Current version of the perl script:
http://lxr.mozilla.org/mozilla/source/tools/footprint/leak-gauge.pl?raw=1

Blog entry about how to file good mlk bugs:
http://dbaron.org/log/2006-01#e20060110a

Comment 20

[Jesse Ruderman]

Three more problems, then I think I'll stop whining:

* On Windows, each line of the log file starts with "0" rather than a large negative number.  Since the Perl script expects each line to start with a hyphen, this breaks it completely.  Suggested fix:

-    if (/^\-[0-9]*\[[0-9a-f]*\]: (\S*) (.*)$/) {
+    if (/^\-?[0-9]*\[[0-9a-f]*\]: (\S*) (.*)$/) {

* On Windows, if I don't run dos2unix on the log file before running leak-gauge, leak-gauge says "outer expected at leak-gauge.pl line 89, <> line 3" and dies.

* There are several situations in which the perl script doesn't print anything.  It should say "I can't make sense of this log file :(" or "No leaks of documents, docshells, or domwindows detected :)" instead of being silent and possibly misleading.

Comment 21

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Both windows bugs fixed (one based on your suggestion, one based on actual testing of a file with CR-LF line endings), and summary stats added at the end, whether or not there were leaks.  See revision 1.5.

Comment 22

[Jesse Ruderman]

Awesome.  It works well on Windows now.

Comment 23

[dolphinling]

It would be nice if this would rename the file at startup instead of clobbering it, so more than one run's worth of data can be processed at once. (And so you don't accidentally lose anything by restarting the browser.)

If this is done it would be good for the script to actually tell whether the browser crashed or it's a legitimate leak, as a human more than likely won't be able to remember what happened when in previous runs.

Comment 24

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Checked in to MOZILLA_1_8_BRANCH.

Comment 25

[Daniel Veditz [:dveditz]]

Comment on attachment 206602 [details] [diff] [review]
NSPR logging code

approved for 1.8.0 branch, a=dveditz

Comment 26

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Fix checked in to MOZILLA_1_8_0_BRANCH.