summaryrefslogtreecommitdiffstats
path: root/testing/mozbase/mozleak/mozleak/leaklog.py
blob: 9688974d1c6fa825b2eb871f8063605c6987739a (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
# This Source Code Form is subject to the terms of the Mozilla Public
# License, v. 2.0. If a copy of the MPL was not distributed with this file,
# You can obtain one at http://mozilla.org/MPL/2.0/.


import os
import re


def _get_default_logger():
    from mozlog import get_default_logger
    log = get_default_logger(component='mozleak')

    if not log:
        import logging
        log = logging.getLogger(__name__)
    return log


def process_single_leak_file(leakLogFileName, processType, leakThreshold,
                             ignoreMissingLeaks, log=None,
                             stackFixer=None):
    """Process a single leak log.
    """

    #     |              |Per-Inst  Leaked|     Total  Rem|
    #   0 |TOTAL         |      17     192| 419115886    2|
    # 833 |nsTimerImpl   |      60     120|     24726    2|
    # 930 |Foo<Bar, Bar> |      32       8|       100    1|
    lineRe = re.compile(r"^\s*\d+ \|"
                        r"(?P<name>[^|]+)\|"
                        r"\s*(?P<size>-?\d+)\s+(?P<bytesLeaked>-?\d+)\s*\|"
                        r"\s*-?\d+\s+(?P<numLeaked>-?\d+)")
    # The class name can contain spaces. We remove trailing whitespace later.

    log = log or _get_default_logger()

    processString = "%s process:" % processType
    crashedOnPurpose = False
    totalBytesLeaked = None
    leakedObjectAnalysis = []
    leakedObjectNames = []
    recordLeakedObjects = False
    with open(leakLogFileName, "r") as leaks:
        for line in leaks:
            if line.find("purposefully crash") > -1:
                crashedOnPurpose = True
            matches = lineRe.match(line)
            if not matches:
                # eg: the leak table header row
                strippedLine = line.rstrip()
                log.info(stackFixer(strippedLine) if stackFixer else strippedLine)
                continue
            name = matches.group("name").rstrip()
            size = int(matches.group("size"))
            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":
                log.info(line.rstrip())
            # Analyse the leak log, but output later or it will interrupt the
            # leak table
            if name == "TOTAL":
                # Multiple default processes can end up writing their bloat views into a single
                # log, particularly on B2G. Eventually, these should be split into multiple
                # logs (bug 1068869), but for now, we report the largest leak.
                if totalBytesLeaked is not None:
                    log.warning("leakcheck | %s "
                                "multiple BloatView byte totals found"
                                % processString)
                else:
                    totalBytesLeaked = 0
                if bytesLeaked > totalBytesLeaked:
                    totalBytesLeaked = bytesLeaked
                    # Throw out the information we had about the previous bloat
                    # view.
                    leakedObjectNames = []
                    leakedObjectAnalysis = []
                    recordLeakedObjects = True
                else:
                    recordLeakedObjects = False
            if size < 0 or bytesLeaked < 0 or numLeaked < 0:
                log.error("TEST-UNEXPECTED-FAIL | leakcheck | %s negative leaks caught!"
                          % processString)
                continue
            if name != "TOTAL" and numLeaked != 0 and recordLeakedObjects:
                leakedObjectNames.append(name)
                leakedObjectAnalysis.append("TEST-INFO | leakcheck | %s leaked %d %s"
                                            % (processString, numLeaked, name))

    log.info('\n'.join(leakedObjectAnalysis))

    if totalBytesLeaked is None:
        # We didn't see a line with name 'TOTAL'
        if crashedOnPurpose:
            log.info("TEST-INFO | leakcheck | %s deliberate crash and thus no leak log"
                     % processString)
        elif ignoreMissingLeaks:
            log.info("TEST-INFO | leakcheck | %s ignoring missing output line for total leaks"
                     % processString)
        else:
            log.error("TEST-UNEXPECTED-FAIL | leakcheck | %s missing output line for total leaks!"
                      % processString)
            log.info("TEST-INFO | leakcheck | missing output line from log file %s"
                     % leakLogFileName)
        return

    if totalBytesLeaked == 0:
        log.info("TEST-PASS | leakcheck | %s no leaks detected!" %
                 processString)
        return

    # Create a comma delimited string of the first N leaked objects found,
    # to aid with bug summary matching in TBPL. Note: The order of the objects
    # had no significance (they're sorted alphabetically).
    maxSummaryObjects = 5
    leakedObjectSummary = ', '.join(leakedObjectNames[:maxSummaryObjects])
    if len(leakedObjectNames) > maxSummaryObjects:
        leakedObjectSummary += ', ...'

    message = "leakcheck | %s %d bytes leaked (%s)" % (
            processString, totalBytesLeaked, leakedObjectSummary)

    # totalBytesLeaked will include any expected leaks, so it can be off
    # by a few thousand bytes.
    if totalBytesLeaked > leakThreshold:
        log.error("TEST-UNEXPECTED-FAIL | %s" % message)
    else:
        log.warning(message)


def process_leak_log(leak_log_file, leak_thresholds=None,
                     ignore_missing_leaks=None, log=None,
                     stack_fixer=None):
    """Process the leak log, including separate leak logs created
    by child processes.

    Use this function if you want an additional PASS/FAIL summary.
    It must be used with the |XPCOM_MEM_BLOAT_LOG| environment variable.

    The base of leak_log_file for a non-default process needs to end with
      _proctype_pid12345.log
    "proctype" is a string denoting the type of the process, which should
    be the result of calling XRE_ChildProcessTypeToString(). 12345 is
    a series of digits that is the pid for the process. The .log is
    optional.

    All other file names are treated as being for default processes.

    leak_thresholds should be a dict mapping process types to leak thresholds,
    in bytes. If a process type is not present in the dict the threshold
    will be 0.

    ignore_missing_leaks should be a list of process types. If a process
    creates a leak log without a TOTAL, then we report an error if it isn't
    in the list ignore_missing_leaks.
    """

    log = log or _get_default_logger()

    leakLogFile = leak_log_file
    if not os.path.exists(leakLogFile):
        log.warning(
            "leakcheck | refcount logging is off, so leaks can't be detected!")
        return

    leakThresholds = leak_thresholds or {}
    ignoreMissingLeaks = ignore_missing_leaks or []

    # This list is based on kGeckoProcessTypeString. ipdlunittest processes likely
    # are not going to produce leak logs we will ever see.
    knownProcessTypes = ["default", "plugin", "tab", "geckomediaplugin", "gpu"]

    for processType in knownProcessTypes:
        log.info("TEST-INFO | leakcheck | %s process: leak threshold set at %d bytes"
                 % (processType, leakThresholds.get(processType, 0)))

    for processType in leakThresholds:
        if processType not in knownProcessTypes:
            log.error("TEST-UNEXPECTED-FAIL | leakcheck | "
                      "Unknown process type %s in leakThresholds" % processType)

    (leakLogFileDir, leakFileBase) = os.path.split(leakLogFile)
    if leakFileBase[-4:] == ".log":
        leakFileBase = leakFileBase[:-4]
        fileNameRegExp = re.compile(r"_([a-z]*)_pid\d*.log$")
    else:
        fileNameRegExp = re.compile(r"_([a-z]*)_pid\d*$")

    for fileName in os.listdir(leakLogFileDir):
        if fileName.find(leakFileBase) != -1:
            thisFile = os.path.join(leakLogFileDir, fileName)
            m = fileNameRegExp.search(fileName)
            if m:
                processType = m.group(1)
            else:
                processType = "default"
            if processType not in knownProcessTypes:
                log.error("TEST-UNEXPECTED-FAIL | leakcheck | "
                          "Leak log with unknown process type %s" % processType)
            leakThreshold = leakThresholds.get(processType, 0)
            process_single_leak_file(thisFile, processType, leakThreshold,
                                     processType in ignoreMissingLeaks,
                                     log=log, stackFixer=stack_fixer)