Bug 1091274 - Move leak log functions out of automationutils and into mozbase. r=jgriffin

This commit is contained in:
Julien Pagès 2015-07-03 07:04:22 +02:00
parent a0cea47270
commit 6a595c1c90
12 changed files with 270 additions and 217 deletions

View File

@ -16,8 +16,6 @@ import tempfile
import mozinfo import mozinfo
__all__ = [ __all__ = [
"dumpLeakLog",
"processLeakLog",
'dumpScreen', 'dumpScreen',
"setAutomationLog", "setAutomationLog",
] ]
@ -72,214 +70,6 @@ def printstatus(status, name = ""):
# This is probably a can't-happen condition on Unix, but let's be defensive # This is probably a can't-happen condition on Unix, but let's be defensive
print "TEST-INFO | %s: undecodable exit status %04x\n" % (name, status) print "TEST-INFO | %s: undecodable exit status %04x\n" % (name, status)
def dumpLeakLog(leakLogFile, filter = False):
"""Process the leak log, without parsing it.
Use this function if you want the raw log only.
Use it preferably with the |XPCOM_MEM_LEAK_LOG| environment variable.
"""
# Don't warn (nor "info") if the log file is not there.
if not os.path.exists(leakLogFile):
return
with open(leakLogFile, "r") as leaks:
leakReport = leaks.read()
# Only |XPCOM_MEM_LEAK_LOG| reports can be actually filtered out.
# Only check whether an actual leak was reported.
if filter and not "0 TOTAL " in leakReport:
return
# Simply copy the log.
log.info(leakReport.rstrip("\n"))
def processSingleLeakFile(leakLogFileName, processType, leakThreshold, ignoreMissingLeaks):
"""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.
processString = "%s process:" % processType
crashedOnPurpose = False
totalBytesLeaked = None
logAsWarning = False
leakAnalysis = []
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
log.info(line.rstrip())
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 != None:
leakAnalysis.append("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:
leakAnalysis.append("TEST-UNEXPECTED-FAIL | leakcheck | %s negative leaks caught!"
% processString)
logAsWarning = True
continue
if name != "TOTAL" and numLeaked != 0 and recordLeakedObjects:
leakedObjectNames.append(name)
leakedObjectAnalysis.append("TEST-INFO | leakcheck | %s leaked %d %s (%s bytes)"
% (processString, numLeaked, name, bytesLeaked))
leakAnalysis.extend(leakedObjectAnalysis)
if logAsWarning:
log.warning('\n'.join(leakAnalysis))
else:
log.info('\n'.join(leakAnalysis))
logAsWarning = False
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.info("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
# totalBytesLeaked was seen and is non-zero.
if totalBytesLeaked > leakThreshold:
logAsWarning = True
# Fail the run if we're over the threshold (which defaults to 0)
prefix = "TEST-UNEXPECTED-FAIL"
else:
prefix = "WARNING"
# 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 += ', ...'
if logAsWarning:
log.warning("%s | leakcheck | %s %d bytes leaked (%s)"
% (prefix, processString, totalBytesLeaked, leakedObjectSummary))
else:
log.info("%s | leakcheck | %s %d bytes leaked (%s)"
% (prefix, processString, totalBytesLeaked, leakedObjectSummary))
def processLeakLog(leakLogFile, options):
"""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 leakLogFile 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.
The options argument is checked for two optional attributes,
leakThresholds and ignoreMissingLeaks.
leakThresholds 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.
ignoreMissingLeaks 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 ignoreMissingLeaks.
"""
if not os.path.exists(leakLogFile):
log.info("WARNING | leakcheck | refcount logging is off, so leaks can't be detected!")
return
leakThresholds = getattr(options, 'leakThresholds', {})
ignoreMissingLeaks = getattr(options, 'ignoreMissingLeaks', [])
# 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"]
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 not processType in knownProcessTypes:
log.info("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 not processType in knownProcessTypes:
log.info("TEST-UNEXPECTED-FAIL | leakcheck | Leak log with unknown process type %s"
% processType)
leakThreshold = leakThresholds.get(processType, 0)
processSingleLeakFile(thisFile, processType, leakThreshold,
processType in ignoreMissingLeaks)
def dumpScreen(utilityPath): def dumpScreen(utilityPath):
"""dumps a screenshot of the entire screen to a directory specified by """dumps a screenshot of the entire screen to a directory specified by
the MOZ_UPLOAD_DIR environment variable""" the MOZ_UPLOAD_DIR environment variable"""

View File

@ -62,6 +62,7 @@ SEARCH_PATHS = [
'testing/mozbase/mozdevice', 'testing/mozbase/mozdevice',
'testing/mozbase/mozfile', 'testing/mozbase/mozfile',
'testing/mozbase/mozhttpd', 'testing/mozbase/mozhttpd',
'testing/mozbase/mozleak',
'testing/mozbase/mozlog', 'testing/mozbase/mozlog',
'testing/mozbase/moznetwork', 'testing/mozbase/moznetwork',
'testing/mozbase/mozprocess', 'testing/mozbase/mozprocess',

View File

@ -23,8 +23,7 @@ sys.path.insert(0, SCRIPT_DIRECTORY)
from automationutils import ( from automationutils import (
dumpScreen, dumpScreen,
printstatus, printstatus
processLeakLog
) )
import mozcrash import mozcrash
import mozdebug import mozdebug
@ -32,6 +31,7 @@ import mozinfo
import mozprocess import mozprocess
import mozprofile import mozprofile
import mozrunner import mozrunner
import mozleak
from mozrunner.utils import test_environment from mozrunner.utils import test_environment
here = os.path.abspath(os.path.dirname(__file__)) here = os.path.abspath(os.path.dirname(__file__))
@ -631,7 +631,11 @@ class RefTest(object):
symbolsPath=options.symbolsPath, symbolsPath=options.symbolsPath,
options=options, options=options,
debuggerInfo=debuggerInfo) debuggerInfo=debuggerInfo)
processLeakLog(self.leakLogFile, options) mozleak.process_leak_log(
self.leakLogFile,
leak_thresholds=options.leakThresholds,
log=log,
)
log.info("\nREFTEST INFO | runreftest.py | Running tests: end.") log.info("\nREFTEST INFO | runreftest.py | Running tests: end.")
finally: finally:
self.cleanup(profileDir) self.cleanup(profileDir)

View File

@ -6,6 +6,7 @@
../mozbase/mozhttpd ../mozbase/mozhttpd
../mozbase/mozinfo ../mozbase/mozinfo
../mozbase/mozinstall ../mozbase/mozinstall
../mozbase/mozleak
../mozbase/mozlog ../mozbase/mozlog
../mozbase/moznetwork ../mozbase/moznetwork
../mozbase/mozprocess ../mozbase/mozprocess

View File

@ -35,7 +35,6 @@ import zipfile
import bisection import bisection
from automationutils import ( from automationutils import (
processLeakLog,
dumpScreen, dumpScreen,
printstatus, printstatus,
setAutomationLog, setAutomationLog,
@ -59,6 +58,7 @@ from urllib import quote_plus as encodeURIComponent
from mozlog.structured.formatters import TbplFormatter from mozlog.structured.formatters import TbplFormatter
from mozlog.structured import commandline from mozlog.structured import commandline
from mozrunner.utils import test_environment from mozrunner.utils import test_environment
import mozleak
here = os.path.abspath(os.path.dirname(__file__)) here = os.path.abspath(os.path.dirname(__file__))
@ -2286,7 +2286,12 @@ class Mochitest(MochitestUtilsMixin):
self.stopVMwareRecording() self.stopVMwareRecording()
self.stopServers() self.stopServers()
processLeakLog(self.leak_report_file, options) mozleak.process_leak_log(
self.leak_report_file,
leak_thresholds=options.leakThresholds,
ignore_missing_leaks=options.ignoreMissingLeaks,
log=self.log,
)
if self.nsprLogs: if self.nsprLogs:
with zipfile.ZipFile("%s/nsprlog.zip" % self.browserEnv["MOZ_UPLOAD_DIR"], "w", zipfile.ZIP_DEFLATED) as logzip: with zipfile.ZipFile("%s/nsprlog.zip" % self.browserEnv["MOZ_UPLOAD_DIR"], "w", zipfile.ZIP_DEFLATED) as logzip:

View File

@ -14,7 +14,6 @@ import traceback
here = os.path.abspath(os.path.dirname(__file__)) here = os.path.abspath(os.path.dirname(__file__))
sys.path.insert(0, here) sys.path.insert(0, here)
from automationutils import processLeakLog
from runtests import Mochitest from runtests import Mochitest
from runtests import MochitestUtilsMixin from runtests import MochitestUtilsMixin
from mochitest_options import MochitestArgumentParser from mochitest_options import MochitestArgumentParser
@ -22,6 +21,7 @@ from marionette import Marionette
from mozprofile import Profile, Preferences from mozprofile import Profile, Preferences
from mozlog import structured from mozlog import structured
import mozinfo import mozinfo
import mozleak
class B2GMochitest(MochitestUtilsMixin): class B2GMochitest(MochitestUtilsMixin):
@ -274,7 +274,12 @@ class B2GMochitest(MochitestUtilsMixin):
local_leak_file.name) local_leak_file.name)
self.app_ctx.dm.removeFile(self.leak_report_file) self.app_ctx.dm.removeFile(self.leak_report_file)
processLeakLog(local_leak_file.name, options) mozleak.process_leak_log(
local_leak_file.name,
leak_thresholds=options.leakThresholds,
ignore_missing_leaks=options.ignoreMissingLeaks,
log=self.log,
)
except KeyboardInterrupt: except KeyboardInterrupt:
self.log.info("runtests.py | Received keyboard interrupt.\n") self.log.info("runtests.py | Received keyboard interrupt.\n")
status = -1 status = -1

View File

@ -17,6 +17,7 @@ python_modules = [
'mozhttpd', 'mozhttpd',
'mozinfo', 'mozinfo',
'mozinstall', 'mozinstall',
'mozleak',
'mozlog', 'mozlog',
'moznetwork', 'moznetwork',
'mozprocess', 'mozprocess',

View File

@ -0,0 +1,9 @@
# 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/.
"""
mozleak is a library for extracting memory leaks from leak logs files.
"""
from .leaklog import process_leak_log

View File

@ -0,0 +1,209 @@
# 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 _raw_log():
import logging
return logging.getLogger(__name__)
def process_single_leak_file(leakLogFileName, processType, leakThreshold,
ignoreMissingLeaks, log=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 _raw_log()
processString = "%s process:" % processType
crashedOnPurpose = False
totalBytesLeaked = None
logAsWarning = False
leakAnalysis = []
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
log.info(line.rstrip())
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 != None:
leakAnalysis.append("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:
leakAnalysis.append("TEST-UNEXPECTED-FAIL | leakcheck | %s negative leaks caught!"
% processString)
logAsWarning = True
continue
if name != "TOTAL" and numLeaked != 0 and recordLeakedObjects:
leakedObjectNames.append(name)
leakedObjectAnalysis.append("TEST-INFO | leakcheck | %s leaked %d %s (%s bytes)"
% (processString, numLeaked, name, bytesLeaked))
leakAnalysis.extend(leakedObjectAnalysis)
if logAsWarning:
log.warning('\n'.join(leakAnalysis))
else:
log.info('\n'.join(leakAnalysis))
logAsWarning = False
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.info("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
# totalBytesLeaked was seen and is non-zero.
if totalBytesLeaked > leakThreshold:
logAsWarning = True
# Fail the run if we're over the threshold (which defaults to 0)
prefix = "TEST-UNEXPECTED-FAIL"
else:
prefix = "WARNING"
# 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 += ', ...'
if logAsWarning:
log.warning("%s | leakcheck | %s %d bytes leaked (%s)"
% (prefix, processString, totalBytesLeaked, leakedObjectSummary))
else:
log.info("%s | leakcheck | %s %d bytes leaked (%s)"
% (prefix, processString, totalBytesLeaked, leakedObjectSummary))
def process_leak_log(leak_log_file, leak_thresholds=None,
ignore_missing_leaks=None, log=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 _raw_log()
leakLogFile = leak_log_file
if not os.path.exists(leakLogFile):
log.info(
"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"]
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 not processType in knownProcessTypes:
log.info("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 not processType in knownProcessTypes:
log.info("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)

View File

@ -0,0 +1,26 @@
# 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/.
from setuptools import setup
PACKAGE_NAME = 'mozleak'
PACKAGE_VERSION = '0.1'
setup(
name=PACKAGE_NAME,
version=PACKAGE_VERSION,
description="Library for extracting memory leaks from leak logs files",
long_description="see http://mozbase.readthedocs.org/",
classifiers=[], # Get strings from http://pypi.python.org/pypi?%3Aaction=list_classifiers
keywords='mozilla',
author='Mozilla Automation and Tools team',
author_email='tools@lists.mozilla.org',
url='https://wiki.mozilla.org/Auto-tools/Projects/Mozbase',
license='MPL',
packages=['mozleak'],
zip_safe=False,
install_requires=[],
)

View File

@ -7,6 +7,7 @@ mozfile.pth:testing/mozbase/mozfile
mozhttpd.pth:testing/mozbase/mozhttpd mozhttpd.pth:testing/mozbase/mozhttpd
mozinfo.pth:testing/mozbase/mozinfo mozinfo.pth:testing/mozbase/mozinfo
mozinstall.pth:testing/mozbase/mozinstall mozinstall.pth:testing/mozbase/mozinstall
mozleak.pth:testing/mozbase/mozleak
mozlog.pth:testing/mozbase/mozlog mozlog.pth:testing/mozbase/mozlog
moznetwork.pth:testing/mozbase/moznetwork moznetwork.pth:testing/mozbase/moznetwork
mozprocess.pth:testing/mozbase/mozprocess mozprocess.pth:testing/mozbase/mozprocess

View File

@ -17,6 +17,7 @@ SEARCH_PATHS = [
'mozbase/mozdevice', 'mozbase/mozdevice',
'mozbase/mozfile', 'mozbase/mozfile',
'mozbase/mozhttpd', 'mozbase/mozhttpd',
'mozbase/mozleak',
'mozbase/mozlog', 'mozbase/mozlog',
'mozbase/moznetwork', 'mozbase/moznetwork',
'mozbase/mozprocess', 'mozbase/mozprocess',