Make automationutils.processLeakLog() output leaks in a TBPL compatible format

RESOLVED FIXED in Firefox 20

Status

RESOLVED FIXED
6 years ago
5 years ago

People

(Reporter: emorley, Assigned: emorley)

Tracking

Trunk
mozilla22
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite -

Firefox Tracking Flags

(firefox20 fixed, firefox21 fixed, firefox-esr17 fixed, b2g18 fixed)

Details

Attachments

(12 attachments)

4.35 KB, patch
ted
: review+
Details | Diff | Splinter Review
4.43 KB, patch
ted
: review+
Details | Diff | Splinter Review
2.26 KB, patch
ted
: review+
Details | Diff | Splinter Review
4.13 KB, patch
ted
: review+
Details | Diff | Splinter Review
3.62 KB, patch
ted
: review+
Details | Diff | Splinter Review
3.53 KB, patch
ted
: review+
Details | Diff | Splinter Review
4.98 KB, patch
ted
: review+
Details | Diff | Splinter Review
3.08 KB, patch
ted
: review+
Details | Diff | Splinter Review
3.19 KB, patch
ted
: review+
Details | Diff | Splinter Review
1.79 KB, patch
ted
: review+
Details | Diff | Splinter Review
6.68 KB, patch
ted
: review+
Details | Diff | Splinter Review
9.09 KB, patch
Details | Diff | Splinter Review
(Assignee)

Description

6 years ago
This bug is for the automationutils.py part of bug 850670.

See comments there for context.
(Assignee)

Comment 1

6 years ago
Created attachment 725514 [details] [diff] [review]
Part 1: s/automationutils.processLeakLog()/leakcheck/

Reduces the chance of line wrapping in the TBPL annotated summary, and makes
my eyes bleed less every time I see leak failures.
Attachment #725514 - Flags: review?(ted)
(Assignee)

Comment 2

6 years ago
Created attachment 725516 [details] [diff] [review]
Part 2: Move output of summary outside the loop

Wait until the full leak log has been processed before outputting the leak total. Will allow the addition of an overview of the leaked objects, in part 4.
Attachment #725516 - Flags: review?(ted)
(Assignee)

Comment 3

6 years ago
Created attachment 725517 [details] [diff] [review]
Part 3: Only use TEST-INFO for per-object log output

Output all of the leaked object lines as TEST-INFO rather than a combination of TEST-INFO and TEST-UNEXPECTED-FAIL.

Since the main leak summary will soon include an overview of the leaked objects,
we no longer need/want a subset of the individual leak lines showing up in
TBPL's annotated summary (TBPL's parser matches on 'TEST-UNEXPECTED-FAIL').
Attachment #725517 - Flags: review?(ted)
(Assignee)

Comment 4

6 years ago
Created attachment 725518 [details] [diff] [review]
Part 4: Add leaked objects list to leak summary

Add a partial list of leaked objects to the leak summary, to allow TBPL to make bug suggestions.

Current summary line:
TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 216 bytes during test execution

With patch parts 1-4:
TEST-UNEXPECTED-FAIL | leakcheck | 180 bytes leaked (Mutex, ReentrantMonitor, nsRunnable, nsTArray_base, nsThread)

...or with ellipses if more than 5 objects:
TEST-UNEXPECTED-FAIL | leakcheck | 3184 bytes leaked (BackstagePass, CondVar, Mutex, ReentrantMonitor, SharedScriptableHelperForJSIID, ...)
Attachment #725518 - Flags: review?(ted)
(Assignee)

Comment 5

6 years ago
Created attachment 725519 [details] [diff] [review]
Part 5: Clean up logging
Attachment #725519 - Flags: review?(ted)
(Assignee)

Comment 6

6 years ago
Created attachment 725522 [details] [diff] [review]
Part 6: More cleanup

* Clean up log parsing conditionals.
* Move the leak threshold reminder to the calling function. The same threshold is used for all leak logs processed from the test run, so unnecessary to repeat for each.
Attachment #725522 - Flags: review?(ted)
(Assignee)

Comment 7

6 years ago
Created attachment 725524 [details] [diff] [review]
Part 7: Improve log file handling

* Use the cleaner |with open() as foo| pattern.
* Don't close then reopen the same leak log unnecessarily.
Attachment #725524 - Flags: review?(ted)
(Assignee)

Comment 8

6 years ago
Created attachment 725525 [details] [diff] [review]
Part 8: Only parse the leak log once

The existing code parses the leak log twice - first time to output the raw log lines & and the second to output the analysis of them.

As much fun as it is to loop all the things (\o/), let's not.
Attachment #725525 - Flags: review?(ted)
(Assignee)

Comment 9

6 years ago
Created attachment 725526 [details] [diff] [review]
Part 9: Favour returning early

Now that we close the log file before summary generation (rather
than at the end of processSingleLeakFile()), we can return early in some cases during leak summary generation.
Attachment #725526 - Flags: review?(ted)
(Assignee)

Comment 10

6 years ago
Created attachment 725527 [details] [diff] [review]
Part 10: Tweak comments
Attachment #725527 - Flags: review?(ted)
(Assignee)

Comment 11

6 years ago
Created attachment 725528 [details] [diff] [review]
Part 11: Make output for subprocesses match typical logging format

* Move processString to the message part of log lines.
* Remove unhelpful process IDs

--

Our standing logging format is:
TEST-{INFO,UNEXPECTED-FAIL} | testName | message

For leak logs from processes other than the main process (eg plugin processes),
currently processSingleLeakFile outputs:
TEST-{INFO,UNEXPECTED-FAIL} | foo process 123 | testName | message

This patch turns these into:
TEST-{INFO,UNEXPECTED-FAIL} | testName | foo process: message

Note: The process ID is contained in the raw leak log (which gets printed to the
log anyway), so we don't need to repeat it in the main summary log lines. In
addition, the variable process ID often breaks TBPL bug suggestions, so should
be avoided where possible.
Attachment #725528 - Flags: review?(ted)
(Assignee)

Comment 12

6 years ago
Created attachment 725536 [details] [diff] [review]
Folded patchset
(Assignee)

Comment 13

6 years ago
Ignoring comments, this patchset removes ~20 lines whilst also adding support for TBPL compatible leaked object summaries - processSingleLeakFile() / processLeakLog() were clearly due for a spring clean :-)

(Annotate shows much of their contents came from automation.py.in and has remained largely untouched for 2-3 years)
(Assignee)

Comment 14

6 years ago
Example leak:
https://tbpl.mozilla.org/?tree=Try&rev=ceec35408c3c&onlyunstarred=1
https://tbpl.mozilla.org/php/getParsedLog.php?id=20697607&tree=Try

{
11:32:47  WARNING -  TEST-UNEXPECTED-FAIL | leakcheck | leaked 336 bytes (Mutex, ReentrantMonitor, nsRunnable, nsTArray_base, nsThread)
}
Comment on attachment 725514 [details] [diff] [review]
Part 1: s/automationutils.processLeakLog()/leakcheck/

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

We should make all these calls use a common method at some point to format the error message. I think we have that in moztest, but it wasn't quite satisfying last time I looked at it.
Attachment #725514 - Flags: review?(ted) → review+
Attachment #725516 - Flags: review?(ted) → review+
Attachment #725517 - Flags: review?(ted) → review+
Comment on attachment 725518 [details] [diff] [review]
Part 4: Add leaked objects list to leak summary

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

::: build/automationutils.py
@@ +379,5 @@
> +      maxSummaryObjects = 5
> +      leakedObjectSummary = ', '.join(leakedObjectNames[:maxSummaryObjects])
> +      # The leaked objects shown when above the maxSummaryObjects threshold has
> +      # been exceeded, has no significance (they're sorted alphabetically), so we
> +      # add a continuation ellipsis to at least indicate there are others.

Do we have a lot of leaks in practice where the set of objects changes? I'm wondering how variable this string is going to be.
Attachment #725518 - Flags: review?(ted) → review+
Attachment #725519 - Flags: review?(ted) → review+
Attachment #725522 - Flags: review?(ted) → review+
Attachment #725524 - Flags: review?(ted) → review+
Comment on attachment 725525 [details] [diff] [review]
Part 8: Only parse the leak log once

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

::: build/automationutils.py
@@ +328,5 @@
>        bytesLeaked = int(matches.group("bytesLeaked"))
>        numLeaked = int(matches.group("numLeaked"))
> +      # Output the raw line from the leak log table if it is the TOTAL row,
> +      # or is for an object row that has been leaked.
> +      if (numLeaked != 0 or name == "TOTAL"):

Don't need the parentheses here.
Attachment #725525 - Flags: review?(ted) → review+
Attachment #725526 - Flags: review?(ted) → review+
Comment on attachment 725527 [details] [diff] [review]
Part 10: Tweak comments

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

::: build/automationutils.py
@@ +358,5 @@
>    if totalBytesLeaked == 0:
>      log.info("TEST-PASS %s| leakcheck | no leaks detected!" % processString)
>      return
>  
> +  # else: (totalBytesLeaked was seen and is non-zero)

I would just state this as a sentence:
# totalBytesLeaked was seen and is non-zero.
Attachment #725527 - Flags: review?(ted) → review+
Comment on attachment 725528 [details] [diff] [review]
Part 11: Make output for subprocesses match typical logging format

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

I guess the PID doesn't really provide value here in the log messages. Thanks for moving it out of the test status part, that bugged me.

::: build/automationutils.py
@@ +334,5 @@
>        # Analyse the leak log, but output later or it will interrupt the leak table
>        if name == "TOTAL":
>          totalBytesLeaked = bytesLeaked
>        if size < 0 or bytesLeaked < 0 or numLeaked < 0:
> +        leakAnalysis.append("TEST-UNEXPECTED-FAIL | leakcheck |%s negative leaks caught!"

nit: I think it would look nicer if you left the leading space out of processString and put it in the individual log lines instead.
Attachment #725528 - Flags: review?(ted) → review+
Thanks for splitting this into such nice bite-sized pieces, it made reviewing it super-simple.
(Assignee)

Comment 21

6 years ago
(In reply to Ted Mielczarek [:ted.mielczarek] from comment #16)
> Do we have a lot of leaks in practice where the set of objects changes? I'm
> wondering how variable this string is going to be.

I had a look over some of the more recent leaks on http://bugzil.la/ALL%20leak bytes keywords%3Aintermittent-failure and they seemed to be pretty unique, so I'm hopeful there will be few false positives (and it will definitely help for many of the leak top oranges we have at the moment).

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #17)
> > +      if (numLeaked != 0 or name == "TOTAL"):
> 
> Don't need the parentheses here.

Good point - updated.

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #18)
> I would just state this as a sentence:
> # totalBytesLeaked was seen and is non-zero.

Done :-)

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #19)
> > +        leakAnalysis.append("TEST-UNEXPECTED-FAIL | leakcheck |%s negative leaks caught!"
> 
> nit: I think it would look nicer if you left the leading space out of
> processString and put it in the individual log lines instead.

Unfortunately that would leave a double space in the processString = '' case (which is the most common).

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #20)
> Thanks for splitting this into such nice bite-sized pieces, it made
> reviewing it super-simple.

No problem :-)
Depends on: 853712
(Assignee)

Updated

5 years ago
Duplicate of this bug: 783024
You need to log in before you can comment on or make changes to this bug.