Magic-Mirror/gecko-dev
1
0
Fork 0
mirror of https://github.com/mozilla/gecko-dev.git synced 2024-10-15 06:15:43 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

Bug 1229379 - use mozlog in talos. r=jgraham,jmaher

Browse Source 
--HG--
extra : rebase_source : 45e9249ae9cb0e4ba084ac39bccc37d88ddeea24
This commit is contained in:
Julien Pagès 2015-12-17 12:11:28 +01:00
parent 5736e43d34
commit 0020f5aa6d
12 changed files with 117 additions and 81 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

13
testing/mozharness/mozharness/mozilla/testing/talos.py
View File

@ -382,7 +382,18 @@ class Talos(TestingMixin, MercurialScript, BlobUploadMixin):
output_timeout = self.config.get('talos_output_timeout', 3600)
# run talos tests
run_tests = os.path.join(self.talos_path, 'talos', 'run_tests.py')
command = [python, run_tests, '--debug'] + options
mozlog_opts = ['--log-tbpl-level=debug']
if not self.run_local and 'suite' in self.config:
fname_pattern = '%s_%%s.log' % self.config['suite']
mozlog_opts.append('--log-errorsummary=%s'
% os.path.join(env['MOZ_UPLOAD_DIR'],
fname_pattern % 'errorsummary'))
mozlog_opts.append('--log-raw=%s'
% os.path.join(env['MOZ_UPLOAD_DIR'],
fname_pattern % 'raw'))
command = [python, run_tests] + options + mozlog_opts
self.return_code = self.run_command(command, cwd=self.workdir,
output_timeout=output_timeout,
output_parser=parser,

1
testing/talos/requirements.txt
View File

@ -1,3 +1,4 @@
mozlog>=3.1
mozcrash>=0.15
mozfile>=1.2
mozhttpd>=0.7

6
testing/talos/talos/cmdline.py
View File

@ -5,6 +5,8 @@
import argparse
import os
from mozlog.commandline import add_logging_group
class _StopAction(argparse.Action):
def __init__(self, option_strings, dest=argparse.SUPPRESS,
@ -137,8 +139,8 @@ def create_parser(mach_interface=False):
help="print available tests")
add_arg('--print-suites', action=_ListSuite,
help="list available suites")
add_arg('--debug', action='store_true',
help='show debug information')
add_logging_group(parser)
return parser

6
testing/talos/talos/config.py
View File

@ -6,6 +6,8 @@ import sys
import os
import copy
from mozlog.commandline import setup_logging
from talos import utils, test
from talos.cmdline import parse_args
@ -448,12 +450,12 @@ def get_config(argv=None):
raise ConfigurationError('No such suite: %r' % cli_opts.suite)
argv += ['-a', ':'.join(suite_conf['tests'])]
argv += suite_conf.get('talos_options', [])
# and reparse the args
cli_opts = parse_args(argv=argv)
# args needs to be reparsed now
elif not cli_opts.activeTests:
raise ConfigurationError('--activeTests or --suite required!')
cli_opts = parse_args(argv=argv)
setup_logging("talos", cli_opts, {"tbpl": sys.stdout})
config = copy.deepcopy(DEFAULTS)
config.update(cli_opts.__dict__)
for validate in CONF_VALIDATORS:

28
testing/talos/talos/ffsetup.py
View File

@ -9,16 +9,20 @@ Set up a browser environment before running a test.
import os
import re
import tempfile
import logging
import mozfile
from mozprocess import ProcessHandler
from mozprofile.profile import Profile
from mozlog import get_proxy_logger
from talos import utils
from talos.utils import TalosError
from talos.sps_profile import SpsProfile
LOG = get_proxy_logger()
class FFSetup(object):
"""
Initialize the browser environment before running a test.
@ -111,30 +115,32 @@ class FFSetup(object):
)
def browser_log(line):
logging.debug('BROWSER_OUTPUT: %s', line)
LOG.process_output(browser.pid, line)
browser = ProcessHandler(command_args, env=self.env,
processOutputLine=browser_log)
browser.run()
LOG.process_start(browser.pid, ' '.join(command_args))
try:
browser.wait()
exit_code = browser.wait()
except KeyboardInterrupt:
browser.kill()
raise
LOG.process_exit(browser.pid, exit_code)
results_raw = '\n'.join(browser.output)
if not self.PROFILE_REGEX.search(results_raw):
logging.info("Could not find %s in browser output",
self.PROFILE_REGEX.pattern)
logging.info("Raw results:%s", results_raw)
LOG.info("Could not find %s in browser output"
% self.PROFILE_REGEX.pattern)
LOG.info("Raw results:%s" % results_raw)
raise TalosError("browser failed to close after being initialized")
def _init_sps_profile(self):
upload_dir = os.getenv('MOZ_UPLOAD_DIR')
if self.test_config.get('sps_profile') and not upload_dir:
logging.critical("Profiling ignored because MOZ_UPLOAD_DIR was not"
" set")
LOG.critical("Profiling ignored because MOZ_UPLOAD_DIR was not"
" set")
if upload_dir and self.test_config.get('sps_profile'):
self.sps_profile = SpsProfile(upload_dir,
self.browser_config,
@ -147,8 +153,8 @@ class FFSetup(object):
self.sps_profile.clean()
def __enter__(self):
logging.info('Initialising browser for %s test...',
self.test_config['name'])
LOG.info('Initialising browser for %s test...'
% self.test_config['name'])
self._init_env()
self._init_profile()
try:
@ -157,7 +163,7 @@ class FFSetup(object):
self.clean()
raise
self._init_sps_profile()
logging.info('Browser initialized.')
LOG.info('Browser initialized.')
return self
def __exit__(self, type, value, tb):

31
testing/talos/talos/output.py
View File

@ -7,15 +7,17 @@
import filter
import json
import logging
import post_file
import time
import utils
from StringIO import StringIO
from mozlog import get_proxy_logger
# NOTE: we have a circular dependecy with output.py when we import results
import results as TalosResults
from StringIO import StringIO
LOG = get_proxy_logger()
def filesizeformat(bytes):
@ -108,14 +110,14 @@ class Output(object):
def JS_Metric(cls, val_list):
"""v8 benchmark score"""
results = [i for i, j in val_list]
logging.info("javascript benchmark")
LOG.info("javascript benchmark")
return sum(results)
@classmethod
def CanvasMark_Metric(cls, val_list):
"""CanvasMark benchmark score (NOTE: this is identical to JS_Metric)"""
results = [i for i, j in val_list]
logging.info("CanvasMark benchmark")
LOG.info("CanvasMark benchmark")
return sum(results)
@ -150,7 +152,7 @@ class GraphserverOutput(Output):
)
for test in self.results.results:
logging.debug("Working with test: %s", test.name())
LOG.debug("Working with test: %s" % test.name())
# get full name of test
testname = test.name()
@ -161,7 +163,7 @@ class GraphserverOutput(Output):
# /run_tests.py#l176
testname += test.extension()
logging.debug("Generating results file: %s" % test.name())
LOG.debug("Generating results file: %s" % test.name())
# HACK: when running xperf, we upload xperf counters to the graph
# server but we do not want to
@ -184,7 +186,7 @@ class GraphserverOutput(Output):
self.shortName(counter_type))
if not values:
# failed to collect any data for this counter
logging.error(
LOG.error(
"No results collected for: " + counterName
)
# NOTE: we are not going to enforce this warning for now as this happens too
@ -218,7 +220,7 @@ class GraphserverOutput(Output):
info['testname'] = counterName
# append the counter string
logging.info(
LOG.info(
"Generating results file: %s" % counterName)
result_strings.append(self.construct_results(vals, **info))
@ -276,7 +278,7 @@ class GraphserverOutput(Output):
try:
buffer.write("%d,%.2f,%s\n" % (i, float(val), page))
except ValueError:
logging.info(
LOG.info(
"We expected a numeric value and recieved '%s' instead"
% val
)
@ -292,7 +294,7 @@ class GraphserverOutput(Output):
if line.find("RETURN\t") > -1:
line = line.replace("RETURN\t", "")
links += line + '\n'
logging.debug("process_Request line: %s", line)
LOG.debug("process_Request line: %s" % line)
if not links:
raise utils.TalosError("send failed, graph server says:\n%s"
% post)
@ -308,9 +310,10 @@ class GraphserverOutput(Output):
times = 0
msg = ""
while times < self.retries:
logging.info(
"Posting result %d of %d to %s://%s%s, attempt %d",
index, len(results), scheme, server, path, times)
LOG.info(
"Posting result %d of %d to %s://%s%s, attempt %d" % (
index, len(results), scheme, server, path, times)
)
try:
links.append(self.process_Request(
post_file.post_multipart(server, path,
@ -404,7 +407,7 @@ class PerfherderOutput(Output):
# This is the output that treeherder expects to find when parsing the
# log file
logging.info("PERFHERDER_DATA: %s" % json.dumps(results))
LOG.info("PERFHERDER_DATA: %s" % json.dumps(results))
if results_scheme in ('file'):
json.dump(results, file(results_path, 'w'), indent=2,
sort_keys=True)

23
testing/talos/talos/run_tests.py
View File

@ -5,7 +5,6 @@
# file, You can obtain one at http://mozilla.org/MPL/2.0/.
import mozversion
import logging
import os
import sys
import time
@ -14,6 +13,8 @@ import urllib
import utils
import mozhttpd
from mozlog import get_proxy_logger
from talos.results import TalosResults
from talos.ttest import TTest
from talos.utils import TalosError, TalosCrash, TalosRegression
@ -21,6 +22,7 @@ from talos.config import get_configs, ConfigurationError
# directory of this file
here = os.path.dirname(os.path.realpath(__file__))
LOG = get_proxy_logger()
def useBaseTestDefaults(base, tests):
@ -67,7 +69,7 @@ def buildCommandLine(test):
def setup_webserver(webserver):
"""use mozhttpd to setup a webserver"""
logging.info("starting webserver on %r" % webserver)
LOG.info("starting webserver on %r" % webserver)
host, port = webserver.split(':')
return mozhttpd.MozHttpd(host=host, port=int(port), docroot=here)
@ -153,8 +155,8 @@ def run_tests(config, browser_config):
'%a, %d %b %Y %H:%M:%S GMT')))
else:
date = int(time.time())
logging.debug("using testdate: %d", date)
logging.debug("actual date: %d", int(time.time()))
LOG.debug("using testdate: %d" % date)
LOG.debug("actual date: %d" % int(time.time()))
# results container
talos_results = TalosResults(title=title,
@ -185,20 +187,20 @@ def run_tests(config, browser_config):
try:
# run the tests
timer = utils.Timer()
logging.info("Starting test suite %s", title)
LOG.info("Starting test suite %s" % title)
for test in tests:
testname = test['name']
testtimer = utils.Timer()
logging.info("Starting test %s", testname)
LOG.info("Starting test %s" % testname)
mytest = TTest()
talos_results.add(mytest.runTest(browser_config, test))
logging.info("Completed test %s (%s)", testname,
testtimer.elapsed())
LOG.info("Completed test %s (%s)"
% (testname, testtimer.elapsed()))
except TalosRegression:
logging.error("Detected a regression for %s", testname)
LOG.error("Detected a regression for %s" % testname)
# by returning 1, we report an orange to buildbot
# http://docs.buildbot.net/latest/developer/results.html
return 1
@ -212,7 +214,7 @@ def run_tests(config, browser_config):
finally:
httpd.stop()
logging.info("Completed test suite (%s)", timer.elapsed())
LOG.info("Completed test suite (%s)" % timer.elapsed())
# output results
if results_urls:
@ -233,7 +235,6 @@ def main(args=sys.argv[1:]):
config, browser_config = get_configs()
except ConfigurationError, exc:
sys.exit("ERROR: %s" % exc)
utils.startLogger('debug' if config['debug'] else 'info')
sys.exit(run_tests(config, browser_config))

34
testing/talos/talos/sps_profile.py
View File

@ -8,14 +8,16 @@ module to handle sps profilling.
import os
import tempfile
import logging
import zipfile
import json
import mozfile
from mozlog import get_proxy_logger
from talos.profiler import symbolication, sps
LOG = get_proxy_logger()
class SpsProfile(object):
"""
@ -42,7 +44,7 @@ class SpsProfile(object):
self.upload_dir,
"profile_{0}.sps.zip".format(test_config['name'])
)
logging.info("Clearing archive {0}".format(self.profile_arcname))
LOG.info("Clearing archive {0}".format(self.profile_arcname))
mozfile.remove(self.profile_arcname)
self.symbol_paths = {
@ -51,11 +53,11 @@ class SpsProfile(object):
'WINDOWS': tempfile.mkdtemp()
}
logging.info("Activating Gecko Profiling. Temp. profile dir:"
" {0}, interval: {1}, entries: {2}"
.format(sps_profile_dir,
sps_profile_interval,
sps_profile_entries))
LOG.info("Activating Gecko Profiling. Temp. profile dir:"
" {0}, interval: {1}, entries: {2}"
.format(sps_profile_dir,
sps_profile_interval,
sps_profile_entries))
self.profiling_info = {
"sps_profile_interval": sps_profile_interval,
@ -94,15 +96,17 @@ class SpsProfile(object):
symbolicator.symbolicate_profile(profile)
sps.save_profile(profile, profile_path)
except MemoryError:
logging.exception(
LOG.critical(
"Ran out of memory while trying"
" to symbolicate profile {0} (cycle {1})"
.format(profile_path, cycle)
.format(profile_path, cycle),
exc_info=True
)
except Exception:
logging.exception("Encountered an exception during profile"
" symbolication {0} (cycle {1})"
.format(profile_path, cycle))
LOG.critical("Encountered an exception during profile"
" symbolication {0} (cycle {1})"
.format(profile_path, cycle),
exc_info=True)
def symbolicate(self, cycle):
"""
@ -182,14 +186,14 @@ class SpsProfile(object):
testname,
cycle_name
)
logging.info(
LOG.info(
"Adding profile {0} to archive {1}"
.format(path_in_zip, self.profile_arcname)
)
try:
arc.write(profile_path, path_in_zip)
except Exception:
logging.exception(
LOG.exception(
"Failed to copy profile {0} as {1} to"
" archive {2}".format(profile_path,
path_in_zip,

11
testing/talos/talos/startup_test/media/media_manager.py
View File

@ -6,11 +6,14 @@
import sys
import platform
import optparse
import logging
import mozhttpd
# media test utilities
import media_utils
from mozlog import get_proxy_logger
LOG = get_proxy_logger()
"""
MediaManager serves as entry point for running media performance tests.
It is responsible for the following
@ -134,9 +137,9 @@ def run_server(doc_root):
]
)
logging.info("Server %s at %s:%s",
httpd_server.docroot, httpd_server.host,
httpd_server.port)
LOG.info("Server %s at %s:%s" % (httpd_server.docroot,
httpd_server.host,
httpd_server.port))
ObjectDb.httpd_server = httpd_server
httpd_server.start()
return httpd_server

16
testing/talos/talos/talos_process.py
View File

@ -3,14 +3,17 @@
# You can obtain one at http://mozilla.org/MPL/2.0/.
import time
import logging
import psutil
import mozcrash
from mozprocess import ProcessHandler
from threading import Event
from mozlog import get_proxy_logger
from utils import TalosError
LOG = get_proxy_logger()
class ProcessContext(object):
"""
@ -26,7 +29,7 @@ class ProcessContext(object):
def kill_process(self):
if self.process and self.process.is_running():
logging.debug("Terminating %s", self.process)
LOG.debug("Terminating %s" % self.process)
self.process.terminate()
try:
self.process.wait(3)
@ -43,6 +46,7 @@ class Reader(object):
self.got_timeout = False
self.timeout_message = ''
self.event = event
self.proc = None
def __call__(self, line):
if line.find('__endTimestamp') != -1:
@ -55,7 +59,7 @@ class Reader(object):
if not (line.startswith('JavaScript error:') or
line.startswith('JavaScript warning:')):
logging.debug('BROWSER_OUTPUT: %s', line)
LOG.process_output(self.proc.pid, line)
self.output.append(line)
@ -94,7 +98,9 @@ def run_browser(command, minidump_dir, timeout=None, on_started=None,
kwargs['processOutputLine'] = reader
kwargs['onFinish'] = event.set
proc = ProcessHandler(command, **kwargs)
reader.proc = proc
proc.run()
LOG.process_start(proc.pid, ' '.join(command))
try:
context.process = psutil.Process(proc.pid)
if on_started:
@ -110,7 +116,7 @@ def run_browser(command, minidump_dir, timeout=None, on_started=None,
if proc.wait(1) is not None:
break
if proc.poll() is None:
logging.info(
LOG.info(
"Browser shutdown timed out after {0} seconds, terminating"
" process.".format(wait_for_quit_timeout)
)
@ -129,6 +135,6 @@ def run_browser(command, minidump_dir, timeout=None, on_started=None,
"__startAfterTerminationTimestamp%d__endAfterTerminationTimestamp"
% (int(time.time()) * 1000))
logging.info("Browser exited with error code: {0}".format(return_code))
LOG.process_exit(proc.pid, return_code)
context.output = reader.output
return context

17
testing/talos/talos/ttest.py
View File

@ -22,13 +22,16 @@ import mozcrash
import talosconfig
import shutil
import mozfile
import logging
from mozlog import get_proxy_logger
from talos.utils import TalosCrash, TalosRegression
from talos.talos_process import run_browser
from talos.ffsetup import FFSetup
from talos.cmanager import CounterManagement
LOG = get_proxy_logger()
class TTest(object):
platform_type = utils.PLATFORM_TYPE
@ -56,7 +59,7 @@ class TTest(object):
"""
logging.debug("operating with platform_type : %s", self.platform_type)
LOG.debug("operating with platform_type : %s" % self.platform_type)
with FFSetup(browser_config, test_config) as setup:
return self._runTest(browser_config, test_config, setup)
@ -103,8 +106,8 @@ class TTest(object):
)
for i in range(test_config['cycles']):
logging.info("Running cycle %d/%d for %s test...",
i+1, test_config['cycles'], test_config['name'])
LOG.info("Running cycle %d/%d for %s test..."
% (i+1, test_config['cycles'], test_config['name']))
# remove the browser error file
mozfile.remove(browser_config['error_filename'])
@ -116,8 +119,8 @@ class TTest(object):
origin = os.path.join(test_config['profile_path'],
keep)
dest = os.path.join(setup.profile_dir, keep)
logging.debug("Reinstalling %s on top of %s", origin,
dest)
LOG.debug("Reinstalling %s on top of %s"
% (origin, dest))
shutil.copy(origin, dest)
# Run the test
@ -245,7 +248,7 @@ class TTest(object):
)
for c in test_results.all_counter_results:
for key, value in c.items():
logging.debug("COUNTER %r: %s", key, value)
LOG.debug("COUNTER %r: %s" % (key, value))
# return results
return test_results

12
testing/talos/talos/utils.py
View File

@ -9,13 +9,15 @@ import time
import urlparse
import string
import urllib
import logging
import json
import re
import platform
from mozlog import get_proxy_logger
# directory of this file for use with interpolatePath()
here = os.path.dirname(os.path.realpath(__file__))
LOG = get_proxy_logger()
def _get_platform():
@ -53,13 +55,6 @@ class Timer(object):
return time.strftime("%H:%M:%S", time.gmtime(seconds))
def startLogger(levelChoice):
# declare and define global logger object to send logging messages to
log_levels = {'debug': logging.DEBUG, 'info': logging.INFO}
logging.basicConfig(format='%(asctime)-15s %(levelname)s : %(message)s',
level=log_levels[levelChoice])
class TalosError(Exception):
"Errors found while running the talos harness."
@ -179,7 +174,6 @@ def GenerateBrowserCommandLine(browser_path, extra_args, profile_dir,
if url.find('media_manager.py') != -1:
command_args = url.split(' ')
logging.debug("command line: %s", ' '.join(command_args))
return command_args