Last Comment Bug 320192 - better way for users/testers to detect and isolate leaks of large object graphs
: better way for users/testers to detect and isolate leaks of large object graphs
: fixed1.8.0.2, fixed1.8.1
Product: Core
Classification: Components
Component: Layout (show other bugs)
: Trunk
: All All
: P1 normal with 1 vote (vote)
: mozilla1.9alpha1
Assigned To: David Baron :dbaron: ⌚️UTC-10
: Jet Villegas (:jet)
Depends on:
  Show dependency treegraph
Reported: 2005-12-13 17:46 PST by David Baron :dbaron: ⌚️UTC-10
Modified: 2006-03-22 04:16 PST (History)
31 users (show)
dbaron: blocking1.8.1?
dveditz: blocking1.8.0.2+
See Also:
Crash Signature:
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---

NSPR logging code (27.12 KB, patch)
2005-12-13 17:48 PST, David Baron :dbaron: ⌚️UTC-10
no flags Details | Diff | Splinter Review (9.12 KB, text/plain; charset=utf-8)
2005-12-13 17:48 PST, David Baron :dbaron: ⌚️UTC-10
no flags Details
NSPR logging code (28.03 KB, patch)
2005-12-13 20:44 PST, David Baron :dbaron: ⌚️UTC-10
no flags Details | Diff | Splinter Review (9.48 KB, text/plain; charset=utf-8)
2005-12-14 11:18 PST, David Baron :dbaron: ⌚️UTC-10
no flags Details
NSPR logging code (20.80 KB, patch)
2005-12-14 14:06 PST, David Baron :dbaron: ⌚️UTC-10
no flags Details | Diff | Splinter Review (7.47 KB, text/plain; charset=utf-8)
2005-12-14 14:06 PST, David Baron :dbaron: ⌚️UTC-10
no flags Details
NSPR logging code (20.79 KB, patch)
2005-12-22 07:30 PST, David Baron :dbaron: ⌚️UTC-10
jst: review+
darin.moz: superreview+
jst: approval‑branch‑1.8.1+
dveditz: approval1.8.0.2+
Details | Diff | Splinter Review (7.47 KB, text/plain; charset=utf-8)
2005-12-22 07:31 PST, David Baron :dbaron: ⌚️UTC-10
no flags Details

Description David Baron :dbaron: ⌚️UTC-10 2005-12-13 17:46:31 PST
At the Firefox Summit last week, in the session , 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-10 2005-12-13 17:48:19 PST
Created attachment 205780 [details] [diff] [review]
NSPR logging code
Comment 2 David Baron :dbaron: ⌚️UTC-10 2005-12-13 17:48:59 PST
Created attachment 205781 [details]

Kinda ugly, but it works...
Comment 3 David Baron :dbaron: ⌚️UTC-10 2005-12-13 20:44:01 PST
Created attachment 205796 [details] [diff] [review]
NSPR logging code
Comment 4 David Baron :dbaron: ⌚️UTC-10 2005-12-13 21:25:04 PST
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-10 2005-12-14 11:18:03 PST
Created attachment 205843 [details]
Comment 6 David Baron :dbaron: ⌚️UTC-10 2005-12-14 14:06:12 PST
Created attachment 205867 [details] [diff] [review]
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-10 2005-12-14 14:06:54 PST
Created attachment 205868 [details]
Comment 8 David Baron :dbaron: ⌚️UTC-10 2005-12-14 14:10:37 PST
I think the bug timeless was telling me about is bug 237326.
Comment 9 Darin Fisher 2005-12-15 18:36:29 PST
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 2005-12-15 18:37:17 PST
Perhaps your macros could also incorporate null checking gDocumentLeakPRLog :)
Comment 11 David Baron :dbaron: ⌚️UTC-10 2005-12-15 18:48:20 PST
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 2005-12-21 02:25:42 PST
The first time I tried to use this tool, it died :(

> cat nspr7-leaky.log | perl ~/trunk/mozilla/
URI expected at /Users/admin/trunk/mozilla/ 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 "

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) 2005-12-21 04:49:44 PST
(fixing nspr logging is bug 244478)
Comment 14 David Baron :dbaron: ⌚️UTC-10 2005-12-22 07:30:52 PST
Created attachment 206602 [details] [diff] [review]
NSPR logging code

without quotes
Comment 15 David Baron :dbaron: ⌚️UTC-10 2005-12-22 07:31:51 PST
Created attachment 206603 [details]

without quotes
Comment 16 Johnny Stenback (:jst, 2006-01-05 17:26:13 PST
Comment on attachment 206602 [details] [diff] [review]
NSPR logging code

Comment 17 Henrik Gemal 2006-01-06 00:01:45 PST
So I should be able to do:
and then start firefox, rite?
Comment 18 David Baron :dbaron: ⌚️UTC-10 2006-01-06 00:04:21 PST
Wrong.  See attachment 206603 [details], which I need to figure out where to check in...
Comment 19 Jesse Ruderman 2006-01-11 23:48:54 PST
Current version of the perl script:

Blog entry about how to file good mlk bugs:
Comment 20 Jesse Ruderman 2006-01-12 00:39:17 PST
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 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-10 2006-01-12 01:02:02 PST
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 2006-01-12 01:39:09 PST
Awesome.  It works well on Windows now.
Comment 23 dolphinling 2006-01-15 05:18:53 PST
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-10 2006-02-09 15:49:49 PST
Checked in to MOZILLA_1_8_BRANCH.
Comment 25 Daniel Veditz [:dveditz] 2006-02-22 00:48:45 PST
Comment on attachment 206602 [details] [diff] [review]
NSPR logging code

approved for 1.8.0 branch, a=dveditz
Comment 26 David Baron :dbaron: ⌚️UTC-10 2006-02-23 21:47:41 PST
Fix checked in to MOZILLA_1_8_0_BRANCH.

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