diff --git a/.travis.yml b/.travis.yml index 681d1ff4..c5420fe5 100644 --- a/.travis.yml +++ b/.travis.yml @@ -24,9 +24,8 @@ addons: - time install: + - pip install coveralls humanfriendly pylint - pip install . - - pip install coveralls - - pip install pylint # command to run tests script: diff --git a/rebench/configurator.py b/rebench/configurator.py index 1874c544..4b532892 100644 --- a/rebench/configurator.py +++ b/rebench/configurator.py @@ -17,10 +17,7 @@ # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. -import sys -import logging import subprocess -import traceback from os.path import dirname from .model.experiment import Experiment @@ -28,6 +25,7 @@ from .model.exp_variables import ExpVariables from .model.reporting import Reporting from .model.virtual_machine import VirtualMachine +from .ui import UIError, DETAIL_INDENT, error, set_verbose_debug_mode class _VMFilter(object): @@ -116,9 +114,12 @@ def load_config(file_name): """ import yaml from pykwalify.core import Core + from pykwalify.errors import SchemaError # Disable most logging for pykwalify - logging.getLogger('pykwalify').setLevel(logging.ERROR) + import logging + logging.getLogger('pykwalify').setLevel(logging.CRITICAL) + logging.getLogger('pykwalify').addHandler(logging.NullHandler()) try: with open(file_name, 'r') as conf_file: @@ -126,22 +127,23 @@ def load_config(file_name): validator = Core( source_data=data, schema_files=[dirname(__file__) + "/rebench-schema.yml"]) - validator.validate(raise_exception=False) - if validator.validation_errors and validator.validation_errors: - logging.error( - "Validation of " + file_name + " failed. " + - (" ".join(validator.validation_errors))) - sys.exit(-1) + try: + validator.validate(raise_exception=True) + except SchemaError as err: + raise UIError( + "Validation of " + file_name + " failed." + DETAIL_INDENT + + (DETAIL_INDENT.join(validator.validation_errors)), err) return data - except IOError: - logging.error("An error occurred on opening the config file (%s)." - % file_name) - logging.error(traceback.format_exc(0)) - sys.exit(-1) - except yaml.YAMLError: - logging.error("Failed parsing the config file (%s)." % file_name) - logging.error(traceback.format_exc(0)) - sys.exit(-1) + except IOError as err: + if err.errno == 2: + assert err.strerror == "No such file or directory" + raise UIError("The requested config file (%s) could not be opened. %s." + % (file_name, err.strerror), err) + else: + raise UIError(str(err), err) + except yaml.YAMLError as err: + raise UIError("Parsing of the config file " + + file_name + " failed.\nError " + str(err), err) class Configurator(object): @@ -157,13 +159,11 @@ def __init__(self, raw_config, data_store, cli_options=None, cli_reporter=None, self._root_run_details = ExpRunDetails.compile( raw_config.get('runs', {}), ExpRunDetails.default()) self._root_reporting = Reporting.compile( - raw_config.get('reporting', {}), Reporting.empty(), cli_options) + raw_config.get('reporting', {}), Reporting.empty(cli_reporter), cli_options) self._options = cli_options self._process_cli_options() - self._cli_reporter = cli_reporter - self._data_store = data_store self._build_commands = dict() @@ -184,26 +184,14 @@ def _process_cli_options(self): if self._options is None: return - if self._options.debug: - if self._options.verbose: - logging.basicConfig(level=logging.NOTSET) - logging.getLogger().setLevel(logging.NOTSET) - logging.debug("Enabled verbose debug output.") - else: - logging.basicConfig(level=logging.DEBUG) - logging.getLogger().setLevel(logging.DEBUG) - logging.debug("Enabled debug output.") - else: - logging.basicConfig(level=logging.ERROR) - logging.getLogger().setLevel(logging.ERROR) - - if self._options.use_nice: - if not can_set_niceness(): - logging.error("Process niceness cannot be set currently. " - "To execute benchmarks with highest priority, " - "you might need root/admin rights.") - logging.error("Deactivated usage of nice command.") - self._options.use_nice = False + set_verbose_debug_mode(self._options.verbose, self._options.debug) + + if self._options.use_nice and not can_set_niceness(): + error("Error: Process niceness could not be set. " + "To execute benchmarks with highest priority, " + "you might need root/admin rights.") + error("Deactivated usage of nice command.") + self._options.use_nice = False @property def use_nice(self): diff --git a/rebench/executor.py b/rebench/executor.py index 93043528..e71b4732 100644 --- a/rebench/executor.py +++ b/rebench/executor.py @@ -17,11 +17,10 @@ # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, # OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN # THE SOFTWARE. -from __future__ import with_statement, print_function +from __future__ import with_statement from collections import deque from math import floor -import logging from multiprocessing import cpu_count import os import pkgutil @@ -30,10 +29,14 @@ import subprocess import sys from threading import Thread, RLock +from time import time + +from humanfriendly import Spinner from . import subprocess_with_timeout as subprocess_timeout -from .statistics import StatisticProperties from .interop.adapter import ExecutionDeliveredNoResults +from .statistics import StatisticProperties, mean +from .ui import DETAIL_INDENT, error, verbose_output_info, warning, debug_output_info class FailedBuilding(Exception): @@ -48,6 +51,10 @@ class RunScheduler(object): def __init__(self, executor): self._executor = executor + self._runs_completed = 0 + self._progress_spinner = None + self._start_time = time() + self._total_num_runs = 0 @staticmethod def _filter_out_completed_runs(runs): @@ -61,9 +68,47 @@ def _process_remaining_runs(self, runs): """Abstract, to be implemented""" pass + def _estimate_time_left(self): + if self._runs_completed == 0: + return 0, 0, 0 + + current = time() + time_per_invocation = ((current - self._start_time) / self._runs_completed) + etl = time_per_invocation * (self._total_num_runs - self._runs_completed) + sec = etl % 60 + minute = (etl - sec) / 60 % 60 + hour = (etl - sec - minute) / 60 / 60 + return floor(hour), floor(minute), floor(sec) + + def _indicate_progress(self, completed_task, run): + if not self._progress_spinner: + return + + totals = run.get_total_values() + if completed_task: + self._runs_completed += 1 + + if totals: + art_mean = mean(run.get_total_values()) + else: + art_mean = 0 + + hour, minute, sec = self._estimate_time_left() + + label = "Running Benchmarks: %70s\tmean: %10.1f\ttime left: %02d:%02d:%02d" \ + % (run.as_simple_string(), art_mean, hour, minute, sec) + self._progress_spinner.step(self._runs_completed, label) + def execute(self): + self._total_num_runs = len(self._executor.runs) runs = self._filter_out_completed_runs(self._executor.runs) - self._process_remaining_runs(runs) + completed_runs = self._total_num_runs - len(runs) + self._runs_completed = completed_runs + + with Spinner(label="Running Benchmarks", total=self._total_num_runs) as spinner: + self._progress_spinner = spinner + spinner.step(completed_runs) + self._process_remaining_runs(runs) class BatchScheduler(RunScheduler): @@ -74,6 +119,7 @@ def _process_remaining_runs(self, runs): completed = False while not completed: completed = self._executor.execute_run(run_id) + self._indicate_progress(completed, run_id) except FailedBuilding: pass @@ -87,6 +133,7 @@ def _process_remaining_runs(self, runs): try: run = task_list.popleft() completed = self._executor.execute_run(run) + self._indicate_progress(completed, run) if not completed: task_list.append(run) except FailedBuilding: @@ -99,9 +146,10 @@ def _process_remaining_runs(self, runs): task_list = list(runs) while task_list: + run = random.choice(task_list) try: - run = random.choice(task_list) completed = self._executor.execute_run(run) + self._indicate_progress(completed, run) if completed: task_list.remove(run) except FailedBuilding: @@ -186,7 +234,6 @@ def _process_remaining_runs(self, runs): exceptions.append(thread.exception) if exceptions: - print(exceptions) if len(exceptions) == 1: raise exceptions[0] else: @@ -219,12 +266,12 @@ def acquire_work(self): class Executor(object): def __init__(self, runs, use_nice, do_builds, include_faulty=False, - verbose=False, scheduler=BatchScheduler, build_log=None): + debug=False, scheduler=BatchScheduler, build_log=None): self._runs = runs self._use_nice = use_nice self._do_builds = do_builds self._include_faulty = include_faulty - self._verbose = verbose + self._debug = debug self._scheduler = self._create_scheduler(scheduler) self._build_log = build_log @@ -283,6 +330,10 @@ def _execute_build_cmd(self, build_command, name, run_id): script = build_command.command + debug_output_info("Starting build" + + DETAIL_INDENT + "Cmd: " + script + + DETAIL_INDENT + "Cwd: " + path) + proc = subprocess.Popen('/bin/sh', stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.PIPE, cwd=path) @@ -299,11 +350,15 @@ def _execute_build_cmd(self, build_command, name, run_id): if file_no == proc.stdout.fileno(): read = self._read(proc.stdout) if read: + if self._debug: + sys.stdout.write(read) log_file.write(name + '|STD:') log_file.write(read) elif file_no == proc.stderr.fileno(): read = self._read(proc.stderr) if read: + if self._debug: + sys.stderr.write(read) log_file.write(name + '|ERR:') log_file.write(read) @@ -337,7 +392,6 @@ def _execute_build_cmd(self, build_command, name, run_id): def execute_run(self, run_id): termination_check = run_id.get_termination_check() - run_id.log() run_id.report_start_run() gauge_adapter = self._get_gauge_adapter_instance( @@ -355,12 +409,15 @@ def execute_run(self, run_id): if not terminate: terminate = self._generate_data_point(cmdline, gauge_adapter, run_id, termination_check) - stats = StatisticProperties(run_id.get_total_values()) - logging.debug("Run: #%d" % stats.num_samples) if terminate: run_id.report_run_completed(stats, cmdline) + if run_id.min_iteration_time and stats.mean < run_id.min_iteration_time: + warning( + ("Warning: The mean (%.1f) is lower than min_iteration_time (%d)" + "%sCmd: %s") + % (stats.mean, run_id.min_iteration_time, DETAIL_INDENT, cmdline)) return terminate @@ -384,22 +441,53 @@ def _get_gauge_adapter_instance(self, adapter_name): def _generate_data_point(self, cmdline, gauge_adapter, run_id, termination_check): - print(cmdline) # execute the external program here run_id.indicate_invocation_start() - (return_code, output, _) = subprocess_timeout.run( - cmdline, cwd=run_id.location, stdout=subprocess.PIPE, - stderr=subprocess.STDOUT, shell=True, verbose=self._verbose, - timeout=run_id.max_invocation_time) - output = output.decode('utf-8') + + try: + msg = "Starting run" + DETAIL_INDENT + "Cmd: " + cmdline + if run_id.location: + msg += DETAIL_INDENT + "Cwd: " + run_id.location + debug_output_info(msg) + + (return_code, output, _) = subprocess_timeout.run( + cmdline, cwd=run_id.location, stdout=subprocess.PIPE, + stderr=subprocess.STDOUT, shell=True, verbose=self._debug, + timeout=run_id.max_invocation_time) + output = output.decode('utf-8') + except OSError as err: + run_id.fail_immediately() + if err.errno == 2: + error( + ("Failed executing a run." + + DETAIL_INDENT + "It failed with: %s." + + DETAIL_INDENT + "File: %s") % (err.strerror, err.filename)) + else: + error(str(err)) + error((DETAIL_INDENT + "Cmd: %s" + + DETAIL_INDENT + "Cwd: %s") % (cmdline, run_id.location)) + return True if return_code != 0 and not self._include_faulty: run_id.indicate_failed_execution() run_id.report_run_failed(cmdline, return_code, output) if return_code == 126: - logging.error(("Could not execute %s. A likely cause is that " - "the file is not marked as executable.") - % run_id.benchmark.vm.name) + error(("Error: Could not execute %s. A likely cause is that " + "the file is not marked as executable. Return code: %d") + % (run_id.benchmark.vm.name, return_code)) + elif return_code == -9: + error("Run timed out. Return code: %d" % return_code) + error(DETAIL_INDENT + "max_invocation_time: %s" % run_id.max_invocation_time) + else: + error("Run failed. Return code: %d" % return_code) + + error((DETAIL_INDENT + "Cmd: %s" + + DETAIL_INDENT + "Cwd: %s") % (cmdline, run_id.location)) + + if output and output.strip(): + lines = output.split('\n') + error(DETAIL_INDENT + "Output: ") + error(DETAIL_INDENT + DETAIL_INDENT.join(lines) + "\n\n") else: self._eval_output(output, run_id, gauge_adapter, cmdline) @@ -413,21 +501,27 @@ def _eval_output(self, output, run_id, gauge_adapter, cmdline): num_points_to_show = 20 num_points = len(data_points) + + msg = "\nCompleted invocation of " + run_id.as_simple_string() + msg += DETAIL_INDENT + "Cmd: " + cmdline + if num_points > num_points_to_show: - logging.debug("Recorded %d data points, show last 20..." % num_points) + msg += DETAIL_INDENT + "Recorded %d data points, show last 20..." % num_points i = 0 for data_point in data_points: if warmup is not None and warmup > 0: warmup -= 1 + run_id.add_data_point(data_point, True) else: - run_id.add_data_point(data_point) + run_id.add_data_point(data_point, False) # only log the last num_points_to_show results if i >= num_points - num_points_to_show: - logging.debug("Run %s:%s result=%s" % ( - run_id.benchmark.suite.vm.name, run_id.benchmark.name, - data_point.get_total_value())) + msg += DETAIL_INDENT + "%4d\t%s%s" % ( + i + 1, data_point.get_total_value(), data_point.get_total_unit()) i += 1 + run_id.indicate_successful_execution() + verbose_output_info(msg) except ExecutionDeliveredNoResults: run_id.indicate_failed_execution() run_id.report_run_failed(cmdline, 0, output) diff --git a/rebench/interop/test_adapter.py b/rebench/interop/test_adapter.py index 17ca0cc0..f070c26e 100644 --- a/rebench/interop/test_adapter.py +++ b/rebench/interop/test_adapter.py @@ -34,7 +34,7 @@ class TestAdapter(GaugeAdapter): def parse_data(self, data, run_id): point = DataPoint(run_id) - point.add_measurement(Measurement(self.test_data[self.index], None, + point.add_measurement(Measurement(self.test_data[self.index], "ms", run_id)) self.index = (self.index + 1) % len(self.test_data) return [point] diff --git a/rebench/model/data_point.py b/rebench/model/data_point.py index 04bbf63c..668ee077 100644 --- a/rebench/model/data_point.py +++ b/rebench/model/data_point.py @@ -41,3 +41,6 @@ def get_measurements(self): def get_total_value(self): return self._total.value if self._total else None + + def get_total_unit(self): + return self._total.unit diff --git a/rebench/model/measurement.py b/rebench/model/measurement.py index 5c95af5a..550f6bc5 100644 --- a/rebench/model/measurement.py +++ b/rebench/model/measurement.py @@ -29,6 +29,7 @@ def __init__(self, value, unit, run_id, criterion='total', self._criterion = criterion self._value = value self._unit = unit + assert unit is not None self._timestamp = timestamp or datetime.now() self._line_number = line_number self._filename = filename diff --git a/rebench/model/reporting.py b/rebench/model/reporting.py index c03ea93a..5b9d5ecd 100644 --- a/rebench/model/reporting.py +++ b/rebench/model/reporting.py @@ -34,8 +34,8 @@ def compile(cls, reporting, root_reporting, options): return Reporting(codespeed, cli_reporter) @classmethod - def empty(cls): - return Reporting(None, None) + def empty(cls, cli_reporter): + return Reporting(None, cli_reporter) def __init__(self, codespeed_reporter, cli_reporter): self._codespeed_reporter = codespeed_reporter diff --git a/rebench/model/run_id.py b/rebench/model/run_id.py index 4f75a6f4..7e34132d 100644 --- a/rebench/model/run_id.py +++ b/rebench/model/run_id.py @@ -17,12 +17,11 @@ # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. -import logging import re -import sys from .benchmark import Benchmark from .termination_check import TerminationCheck +from ..ui import UIError, DETAIL_INDENT class RunId(object): @@ -53,6 +52,14 @@ def min_iteration_time(self): def max_invocation_time(self): return self._benchmark.run_details.max_invocation_time + @property + def iterations(self): + return self._benchmark.run_details.iterations + + @property + def invocations(self): + return self._benchmark.run_details.invocations + @property def execute_exclusively(self): return self._benchmark.run_details.execute_exclusively @@ -91,12 +98,6 @@ def location(self): return None return self._expand_vars(self._benchmark.suite.location) - def log(self): - msg = "Run Config: number of data points: %d" % self.get_number_of_data_points() - if self._benchmark.run_details.min_iteration_time: - msg += ", min_iteration_time: %dms" % self._benchmark.run_details.min_iteration_time - logging.debug(msg) - def requires_warmup(self): return self._benchmark.run_details.warmup > 0 @@ -148,8 +149,9 @@ def add_persistence(self, persistence): def loaded_data_point(self, data_point): self._data_points.append(data_point) - def add_data_point(self, data_point): - self._data_points.append(data_point) + def add_data_point(self, data_point, warmup): + if not warmup: + self._data_points.append(data_point) for persistence in self._persistence: persistence.persist_data_point(data_point) @@ -165,6 +167,11 @@ def discard_data_points(self): def get_total_values(self): return [dp.get_total_value() for dp in self._data_points] + def get_total_unit(self): + if not self._data_points: + return None + return self._data_points[0].get_total_unit() + def get_termination_check(self): if self._termination_check is None: self._termination_check = TerminationCheck(self._benchmark) @@ -188,11 +195,24 @@ def as_simple_string(self): self._cores, self._input_size, self._var_value) def _expand_vars(self, string): - return string % {'benchmark' : self._benchmark.command, - 'input' : self._input_size, - 'variable' : self._var_value, - 'cores' : self._cores, - 'warmup' : self._benchmark.run_details.warmup} + try: + return string % {'benchmark': self._benchmark.command, + 'input': self._input_size, + 'variable': self._var_value, + 'cores': self._cores, + 'warmup': self._benchmark.run_details.warmup} + except ValueError as err: + self._report_format_issue_and_exit(string, err) + except TypeError as err: + self._report_format_issue_and_exit(string, err) + except KeyError as err: + msg = ("The configuration of %s contains improper Python format strings." + % self._benchmark.name) + msg += DETAIL_INDENT + ("The command line configured is: %s" % string) + msg += DETAIL_INDENT + ("%s is not supported as key." % err) + msg += DETAIL_INDENT + msg += "Only benchmark, input, variable, cores, and warmup are supported." + raise UIError(msg, err) def cmdline(self): if self._cmdline: @@ -210,12 +230,7 @@ def cmdline(self): if self._benchmark.extra_args is not None: cmdline += " %s" % self._benchmark.extra_args - try: - cmdline = self._expand_vars(cmdline) - except ValueError: - self._report_cmdline_format_issue_and_exit(cmdline) - except TypeError: - self._report_cmdline_format_issue_and_exit(cmdline) + cmdline = self._expand_vars(cmdline) self._cmdline = cmdline.strip() return self._cmdline @@ -227,20 +242,21 @@ def __eq__(self, other): def __ne__(self, other): return not self.__eq__(other) - def _report_cmdline_format_issue_and_exit(self, cmdline): - logging.critical("The configuration of %s contains improper " - "Python format strings.", self._benchmark.name) + def _report_format_issue_and_exit(self, cmdline, err): + msg = ("The configuration of the benchmark %s contains an improper Python format string." + % self._benchmark.name) # figure out which format misses a conversion type + msg += DETAIL_INDENT + ("The command line configured is: %s" % cmdline) + msg += DETAIL_INDENT + ("Error: %s" % err) without_conversion_type = re.findall( r"%\(.*?\)(?![diouxXeEfFgGcrs%])", cmdline) - logging.error("The command line configured is: %s", cmdline) - logging.error("The following elements do not have conversion types: \"%s\"", - '", "'.join(without_conversion_type)) - logging.error("This can be fixed by replacing for instance %s with %ss", - without_conversion_type[0], - without_conversion_type[0]) - sys.exit(-1) + if without_conversion_type: + msg += DETAIL_INDENT + ("The following elements do not have conversion types: \"%s\"" + % '", "'.join(without_conversion_type)) + msg += DETAIL_INDENT + ("This can be fixed by replacing for instance %s with %ss" + % (without_conversion_type[0], without_conversion_type[0])) + raise UIError(msg, err) def as_str_list(self): result = self._benchmark.as_str_list() diff --git a/rebench/model/termination_check.py b/rebench/model/termination_check.py index 319fd501..d6d4335f 100644 --- a/rebench/model/termination_check.py +++ b/rebench/model/termination_check.py @@ -17,7 +17,7 @@ # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. -import logging +from ..ui import verbose_error_info class TerminationCheck(object): @@ -53,15 +53,17 @@ def has_too_many_failures(self, number_of_data_points): def should_terminate(self, number_of_data_points): if self._fail_immediately: - logging.info( + verbose_error_info( "%s was marked to fail immediately" % self._benchmark.name) if self.fails_consecutively(): - logging.error(("Three executions of %s have failed in a row, " + - "benchmark is aborted") % self._benchmark.name) + verbose_error_info( + ("Three executions of %s have failed in a row, " + "benchmark is aborted") % self._benchmark.name) return True elif self.has_too_many_failures(number_of_data_points): - logging.error("Many runs of %s are failing, benchmark is aborted." - % self._benchmark.name) + verbose_error_info( + "Many runs of %s are failing, benchmark is aborted." + % self._benchmark.name) return True elif self._num_invocations >= self._benchmark.run_details.invocations: return True diff --git a/rebench/persistence.py b/rebench/persistence.py index 2e23bc5e..acc655a5 100644 --- a/rebench/persistence.py +++ b/rebench/persistence.py @@ -19,7 +19,6 @@ # IN THE SOFTWARE. import os import sys -import logging import subprocess import shutil from threading import Lock @@ -28,6 +27,7 @@ from .model.data_point import DataPoint from .model.measurement import Measurement from .model.run_id import RunId +from .ui import debug_error_info, DETAIL_INDENT, error, DETAIL_INDENT_WON class DataStore(object): @@ -104,7 +104,8 @@ def discard_data_of_runs(cls, runs): with open(filename, 'r') as data_file: lines = data_file.readlines() except IOError: - logging.info("Failed to open data file: %s" % filename) + debug_error_info( + "Tried to discard old data, but file does not seem to exist: %s" % filename) continue for measure in measures: @@ -147,8 +148,8 @@ def _load_data(self): with open(self._data_filename, 'r') as data_file: self._process_lines(data_file) except IOError: - logging.info("No data loaded %s does not exist." - % self._data_filename) + debug_error_info("No data loaded, since %s does not exist." + % self._data_filename) def _process_lines(self, data_file): """ @@ -156,6 +157,7 @@ def _process_lines(self, data_file): measurement is always the last one serialized for a data point. """ errors = set() + data_point = None previous_run_id = None line_number = 0 @@ -182,9 +184,11 @@ def _process_lines(self, data_file): except ValueError as err: msg = str(err) + if not errors: + debug_error_info("Failed loading data from data file: " + data_file) if msg not in errors: # Configuration is not available, skip data point - logging.log(logging.DEBUG - 1, msg) + debug_error_info(DETAIL_INDENT_WON + msg) errors.add(msg) line_number += 1 @@ -218,8 +222,8 @@ def _insert_shebang_line(self): shutil.copyfileobj(open(renamed_file, 'r'), data_file) os.remove(renamed_file) except Exception as err: # pylint: disable=broad-except - logging.error("An error occurred " + - "while trying to insert a shebang line: %s", err) + error("Error: While inserting a shebang line into the data file.%s%s" + % (DETAIL_INDENT, err)) _SEP = "\t" # separator between serialized parts of a measurement diff --git a/rebench/rebench-schema.yml b/rebench/rebench-schema.yml index 067f9299..092a5b37 100644 --- a/rebench/rebench-schema.yml +++ b/rebench/rebench-schema.yml @@ -20,9 +20,8 @@ schema;runs_type: warmup: type: int desc: | - Consider the first N iterations as warmup. - This is used by reporters, for instance to discard these - N measurements before calculating statistics. + Consider the first N iterations as warmup and ignore them in summary + statistics. Note they are still persistet in the data file. min_iteration_time: type: int diff --git a/rebench/rebench.py b/rebench/rebench.py index 22e75487..115c986e 100755 --- a/rebench/rebench.py +++ b/rebench/rebench.py @@ -27,8 +27,8 @@ # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. -import logging import sys + from argparse import ArgumentParser, RawDescriptionHelpFormatter, SUPPRESS from .executor import Executor, BatchScheduler, RoundRobinScheduler, \ @@ -37,6 +37,7 @@ from .reporter import CliReporter from .configurator import Configurator, load_config from .configuration_error import ConfigurationError +from .ui import UIError, error, debug_error_info, verbose_output_info class ReBench(object): @@ -77,7 +78,7 @@ def shell_options(self): default=False, help='Enable debug output') basics.add_argument('-v', '--verbose', action='store_true', dest='verbose', default=False, - help='Output more details in the report.') + help='Output more details during execution.') execution = parser.add_argument_group( 'Execution Options', 'Adapt how ReBench executes benchmarks') @@ -185,13 +186,13 @@ def run(self, argv=None): cli_reporter, exp_name, args.data_file, args.build_log, exp_filter) except ConfigurationError as exc: - logging.error(exc.message) - sys.exit(-1) + raise UIError(exc.message, exc) + data_store.load_data() return self.execute_experiment() def execute_experiment(self): - logging.debug("execute experiment: %s" % self._config.experiment_name) + verbose_output_info("Execute experiment: %s" % self._config.experiment_name) # first load old data if available if self._config.options.clean: @@ -206,7 +207,7 @@ def execute_experiment(self): executor = Executor(runs, self._config.use_nice, self._config.do_builds, self._config.options.include_faulty, - self._config.options.verbose, + self._config.options.debug, scheduler_class, self._config.build_log) return executor.execute() @@ -216,7 +217,10 @@ def main_func(): try: return 0 if ReBench().run() else -1 except KeyboardInterrupt: - logging.info("Aborted by user request") + debug_error_info("Aborted by user request") + return -1 + except UIError as err: + error(err.message) return -1 diff --git a/rebench/reporter.py b/rebench/reporter.py index 3064f78b..cfb8d90e 100644 --- a/rebench/reporter.py +++ b/rebench/reporter.py @@ -17,15 +17,16 @@ # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, # OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN # THE SOFTWARE. -from __future__ import with_statement, print_function +from __future__ import with_statement -from datetime import datetime from time import time -from math import floor -import logging import json import re +from humanfriendly.tables import format_pretty_table + +from .ui import output, DETAIL_INDENT, verbose_error_info + try: from http.client import HTTPException from urllib.request import urlopen @@ -66,19 +67,6 @@ def start_run(self, run_id): class TextReporter(Reporter): - def _configuration_details(self, run_id, statistics=None): - result = ["\t".join(run_id.as_str_list()), " = "] - self._output_stats(result, run_id, statistics) - return result - - def _output_stats(self, output_list, _run_id, statistics): - if not statistics: - return - - for field, value in statistics.__dict__.iteritems(): - if not field.startswith('_'): - output_list.append("%s: %s " % (field, value)) - @staticmethod def _path_to_string(path): out = [path[0].as_simple_string()] @@ -87,24 +75,17 @@ def _path_to_string(path): out.append(str(item)) return " ".join(out) + " " - def _generate_all_output(self, run_ids): + @staticmethod + def _generate_all_output(run_ids): rows = [] - col_width = None for run_id in run_ids: stats = StatisticProperties(run_id.get_total_values()) out = run_id.as_str_list() - self._output_stats(out, run_id, stats) - if col_width is None: - col_width = [0] * len(out) + out.append(stats.mean) rows.append(out) - col_width = [max(len(col_content), col) - for col_content, col in zip(out, col_width)] - for row in rows: - result = " ".join([col.ljust(width) - for col, width in zip(row, col_width)]) - yield result + return rows class CliReporter(TextReporter): @@ -118,129 +99,23 @@ def __init__(self, executes_verbose): self._runs_remaining = 0 self._executes_verbose = executes_verbose - # TODO: re-add support, think, we need that based on the proper config, i.e., the run id -# self._min_iteration_time = configurator.statistics.min_iteration_time - - def run_failed(self, run_id, cmdline, return_code, output): - # Additional information in debug mode - result = "[%s] Run failed: %s\n" % ( - datetime.now(), - " ".join(self._configuration_details(run_id))) - logging.debug(result) - - # Standard error output - if return_code == -9: - log_msg = "Run timed out. return_code: %s" - else: - log_msg = "Run failed return_code: %s" - - print(log_msg % return_code) - - print("Cmd: %s\n" % cmdline) - - if run_id.benchmark.suite.has_max_invocation_time(): - logging.debug("max_invocation_time: %s" % run_id.benchmark.suite.max_invocation_time) - logging.debug("cwd: %s" % run_id.benchmark.suite.location) - - if not self._executes_verbose and output and output.strip(): - print("Output:\n%s\n" % output) + def run_failed(self, run_id, cmdline, return_code, cmd_output): + pass def run_completed(self, run_id, statistics, cmdline): - result = "[%s] Run completed: %s\n" % ( - datetime.now(), - " ".join(self._configuration_details(run_id, statistics))) - - logging.debug(result) - self._runs_completed += 1 self._runs_remaining -= 1 - if run_id.run_config.min_iteration_time: - if statistics.mean < run_id.run_config.min_iteration_time: - print(("WARNING: measured mean is lower than min_iteration_time (%s) " - "\t mean: %.1f\trun id: %s") - % (run_id.run_config.min_iteration_time, - statistics.mean, - run_id.as_simple_string())) - print("Cmd: %s" % cmdline) - def report_job_completed(self, run_ids): - print("[%s] Job completed" % datetime.now()) - for line in self._generate_all_output(run_ids): - print(line) + output(format_pretty_table( + self._generate_all_output(run_ids), + ['Benchmark', 'VM', 'Suite', 'Extra', 'Core', 'Size', 'Var', 'Mean'], + vertical_bar=' ')) def set_total_number_of_runs(self, num_runs): self._num_runs = num_runs self._runs_remaining = num_runs - def start_run(self, run_id): - if self._runs_completed > 0: - current = time() - data_points_per_run = run_id.run_config.number_of_data_points - data_points_completed = (self._runs_completed * - data_points_per_run + - len(run_id.get_data_points())) - data_points_remaining = (self._runs_remaining * - data_points_per_run - - len(run_id.get_data_points())) - time_per_data_point = ((current - self._start_time) / - data_points_completed) - etl = time_per_data_point * data_points_remaining - sec = etl % 60 - minute = (etl - sec) / 60 % 60 - hour = (etl - sec - minute) / 60 / 60 - print(("Run %s \t runs left: %00d \t " + - "time left: %02d:%02d:%02d") % (run_id.benchmark.name, - self._runs_remaining, - floor(hour), floor(minute), - floor(sec))) - else: - self._start_time = time() - print("Run %s \t runs left: %d" % (run_id.benchmark.name, - self._runs_remaining)) - - def _output_stats(self, output_list, run_id, statistics): - if not statistics: - return - - if run_id.run_failed(): - output_list.append("run failed.") - output_list.append("") - output_list.append("") - output_list.append("") - else: - output_list.append("mean:") - output_list.append(("%.1f" % statistics.mean).rjust(8)) - - -class FileReporter(TextReporter): - """ should be mainly a log file - data is the responsibility of the data_aggregator - """ - - def __init__(self, filename): - super(FileReporter, self).__init__() - self._file = open(filename, 'a+') - - def run_failed(self, run_id, _cmdline, _return_code, _output): - result = "[%s] Run failed: %s\n" % ( - datetime.now(), - " ".join(self._configuration_details(run_id))) - self._file.writelines(result) - - def run_completed(self, run_id, statistics, cmdline): - result = "[%s] Run completed: %s\n" % ( - datetime.now(), - " ".join(self._configuration_details(run_id, statistics))) - self._file.writelines(result) - - def report_job_completed(self, run_ids): - self._file.write("[%s] Job completed\n" % datetime.now()) - for line in self._generate_all_output(run_ids): - self._file.write(line + "\n") - - self._file.close() - class CodespeedReporter(Reporter): """ @@ -324,8 +199,7 @@ def _send_payload(self, payload): socket = urlopen(self._cfg.url, payload) response = socket.read() socket.close() - logging.info("Results were sent to Codespeed, response was: " - + response) + return response def _send_to_codespeed(self, results): payload = urlencode({'json': json.dumps(results)}) @@ -336,25 +210,28 @@ def _send_to_codespeed(self, results): # sometimes Codespeed fails to accept a request because something # is not yet properly initialized, let's try again for those cases try: - self._send_payload(payload) + response = self._send_payload(payload) + verbose_error_info("Sent %d results to Codespeed, response was: %s" + % (len(results), response)) except (IOError, HTTPException) as error: - logging.error(str(error) + " This is most likely caused by " - "either a wrong URL in the config file, or an " - "environment not configured in Codespeed. URL: " - + self._cfg.url) - envs = list(set([i['environment'] - for i in results])) - projects = list(set([i['project'] - for i in results])) - benchmarks = list(set([i['benchmark'] - for i in results])) - executables = list(set([i['executable'] - for i in results])) - logging.error("Sent data included environments: %s " - "projects: %s benchmarks: %s executables: %s" - % (envs, projects, benchmarks, executables)) - - logging.info("Sent %d results to Codespeed." % len(results)) + envs = list(set([i['environment'] for i in results])) + projects = list(set([i['project'] for i in results])) + benchmarks = list(set([i['benchmark'] for i in results])) + executables = list(set([i['executable'] for i in results])) + msg = ("Data" + + DETAIL_INDENT + "environments: %s" + + DETAIL_INDENT + "projects: %s" + + DETAIL_INDENT + "benchmarks: %s" + + DETAIL_INDENT + "executables: %s") % ( + envs, projects, benchmarks, executables) + + error("Error: Reporting to Codespeed failed." + + DETAIL_INDENT + str(error) + + DETAIL_INDENT + "This is most likely caused by " + "either a wrong URL in the config file, or an " + "environment not configured in Codespeed." + + DETAIL_INDENT + "URL: " + self._cfg.url + + DETAIL_INDENT + msg) def _prepare_result(self, run_id): stats = StatisticProperties(run_id.get_total_values()) diff --git a/rebench/subprocess_with_timeout.py b/rebench/subprocess_with_timeout.py index 24725ce3..04e1c26a 100644 --- a/rebench/subprocess_with_timeout.py +++ b/rebench/subprocess_with_timeout.py @@ -27,17 +27,25 @@ def __init__(self, binary_name, args, shell, cwd, verbose, stdout, stderr): self.stdout_result = None self.stderr_result = None self.returncode = None + self._exception = None - def run(self): - self._started_cv.acquire() - proc = Popen(self._args, shell=self._shell, cwd=self._cwd, - stdout=self._stdout, stderr=self._stderr) - self._pid = proc.pid - self._started_cv.notify() - self._started_cv.release() + @property + def exception(self): + return self._exception - self.process_output(proc) - self.returncode = proc.returncode + def run(self): + try: + self._started_cv.acquire() + proc = Popen(self._args, shell=self._shell, cwd=self._cwd, + stdout=self._stdout, stderr=self._stderr) + self._pid = proc.pid + self._started_cv.notify() + self._started_cv.release() + + self.process_output(proc) + self.returncode = proc.returncode + except Exception as err: # pylint: disable=broad-except + self._exception = err def get_pid(self): self._started_cv.acquire() @@ -111,6 +119,11 @@ def run(args, cwd=None, shell=False, kill_tree=True, timeout=-1, assert thread.get_pid() is not None return kill_process(thread.get_pid(), kill_tree, thread) + if not thread.is_alive(): + exp = thread.exception + if exp: + raise exp # pylint: disable=raising-bad-type + return thread.returncode, thread.stdout_result, thread.stderr_result diff --git a/rebench/tests/broken-schema.conf b/rebench/tests/broken-schema.conf new file mode 100644 index 00000000..dfb78de4 --- /dev/null +++ b/rebench/tests/broken-schema.conf @@ -0,0 +1,40 @@ +# Config file for ReBench +# Config format is YAML (see http://yaml.org/ for detailed spec) + +# this run definition will be chosen if no parameters are given to rebench.py +standard_experiment: Test +standard_data_file: 'tests/small.data' + +# general configuration for runs +runs: + invocations: 10 + +non_existing_attribute: foo bar + +benchmark_suites: + Suite: + gauge_adapter: TestVM + command: TestBenchMarks %(benchmark)s %(input)s %(variable)s + input_sizes: [2, 10] + variable_values: + - val1 + benchmarks: + - Bench1 + - Bench2 + +virtual_machines: + TestRunner1: + path: tests + binary: test-vm1.py %(cores)s + cores: [1] + TestRunner2: + path: tests + binary: test-vm2.py + +experiments: + Test: + benchmark: + - Suite + executions: + - TestRunner1 + - TestRunner2 diff --git a/rebench/tests/broken-yaml.conf b/rebench/tests/broken-yaml.conf new file mode 100644 index 00000000..03487171 --- /dev/null +++ b/rebench/tests/broken-yaml.conf @@ -0,0 +1,42 @@ +# Config file for ReBench +# Config format is YAML (see http://yaml.org/ for detailed spec) + +# this run definition will be chosen if no parameters are given to rebench.py +standard_experiment: Test +standard_data_file: 'tests/small.data' + +# general configuration for runs +runs: + invocations: 10 + +non_existing_attribute: foo bar + +- fsdfsd + +benchmark_suites: + Suite: + gauge_adapter: TestVM + command: TestBenchMarks %(benchmark)s %(input)s %(variable)s + input_sizes: [2, 10] + variable_values: + - val1 + benchmarks: + - Bench1 + - Bench2 + +virtual_machines: + TestRunner1: + path: tests + binary: test-vm1.py %(cores)s + cores: [1] + TestRunner2: + path: tests + binary: test-vm2.py + +experiments: + Test: + benchmark: + - Suite + executions: + - TestRunner1 + - TestRunner2 diff --git a/rebench/tests/configurator_test.py b/rebench/tests/configurator_test.py index 01b8c558..6d3bf561 100644 --- a/rebench/tests/configurator_test.py +++ b/rebench/tests/configurator_test.py @@ -18,7 +18,6 @@ # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. import unittest -import logging from ..configurator import Configurator, load_config from ..persistence import DataStore @@ -27,14 +26,6 @@ class ConfiguratorTest(ReBenchTestCase): - def setUp(self): - super(ConfiguratorTest, self).setUp() - self._logging_error = logging.error - - def tearDown(self): - super(ConfiguratorTest, self).tearDown() - logging.error = self._logging_error # restore normal logging - def test_experiment_name_from_cli(self): cnf = Configurator(load_config(self._path + '/test.conf'), DataStore(), None, 'Test') diff --git a/rebench/tests/executor_test.py b/rebench/tests/executor_test.py index f01b8ae3..16dc4c25 100644 --- a/rebench/tests/executor_test.py +++ b/rebench/tests/executor_test.py @@ -20,14 +20,14 @@ import unittest import subprocess import os -import sys -from ..executor import Executor, BenchmarkThreadExceptions +from .rebench_test_case import ReBenchTestCase +from .. import ReBench +from ..executor import Executor from ..configurator import Configurator, load_config from ..model.measurement import Measurement from ..persistence import DataStore -from .. import ReBench -from .rebench_test_case import ReBenchTestCase +from ..ui import UIError class ExecutorTest(ReBenchTestCase): @@ -61,13 +61,8 @@ def test_setup_and_run_benchmark(self): # self.assertAlmostEqual(45871.453514433859, i_high) # self.assertAlmostEqual(0.00450904792104, interval_percentage) - def test_broken_command_format(self): - def test_exit(val): - self.assertEqual(-1, val, "got the correct error code") - raise RuntimeError("TEST-PASSED") - sys.exit = test_exit - - try: + def test_broken_command_format_with_ValueError(self): + with self.assertRaises(UIError) as err: options = ReBench().shell_options().parse_args(['dummy']) cnf = Configurator(load_config(self._path + '/test.conf'), DataStore(), options, @@ -75,18 +70,10 @@ def test_exit(val): data_file=self._tmp_file) ex = Executor(cnf.get_runs(), cnf.use_nice, cnf.do_builds) ex.execute() - except RuntimeError as err: - self.assertEqual("TEST-PASSED", str(err)) - except BenchmarkThreadExceptions as err: - self.assertEqual("TEST-PASSED", str(err.exceptions[0])) + self.assertIsInstance(err.exception.source_exception, ValueError) def test_broken_command_format_with_TypeError(self): - def test_exit(val): - self.assertEqual(-1, val, "got the correct error code") - raise RuntimeError("TEST-PASSED") - sys.exit = test_exit - - try: + with self.assertRaises(UIError) as err: options = ReBench().shell_options().parse_args(['dummy']) cnf = Configurator(load_config(self._path + '/test.conf'), DataStore(), options, @@ -94,10 +81,7 @@ def test_exit(val): data_file=self._tmp_file) ex = Executor(cnf.get_runs(), cnf.use_nice, cnf.do_builds) ex.execute() - except RuntimeError as err: - self.assertEqual("TEST-PASSED", str(err)) - except BenchmarkThreadExceptions as err: - self.assertEqual("TEST-PASSED", str(err.exceptions[0])) + self.assertIsInstance(err.exception.source_exception, TypeError) def _basic_execution(self, cnf): runs = cnf.get_runs() diff --git a/rebench/tests/rebench_test_case.py b/rebench/tests/rebench_test_case.py index ecc9fd14..604decc7 100644 --- a/rebench/tests/rebench_test_case.py +++ b/rebench/tests/rebench_test_case.py @@ -17,6 +17,7 @@ # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. +import logging import os from os.path import dirname, realpath @@ -32,6 +33,8 @@ def _set_path(self, path): os.chdir(self._path) def setUp(self): + logging.getLogger('pykwalify').addHandler(logging.NullHandler()) + self._set_path(__file__) self._tmp_file = mkstemp()[1] # just use the file name diff --git a/rebench/tests/ui_test.py b/rebench/tests/ui_test.py new file mode 100644 index 00000000..bdd53959 --- /dev/null +++ b/rebench/tests/ui_test.py @@ -0,0 +1,25 @@ +from pykwalify.errors import SchemaError +from yaml import YAMLError + +from ..configurator import load_config +from ..ui import UIError + +from .rebench_test_case import ReBenchTestCase + + +class UITest(ReBenchTestCase): + + def test_missing_file(self): + with self.assertRaises(UIError) as err: + load_config("--file-that-does-not-exist") + self.assertIsInstance(err.exception.source_exception, IOError) + + def test_config_not_validating(self): + with self.assertRaises(UIError) as err: + load_config(self._path + '/broken-schema.conf') + self.assertIsInstance(err.exception.source_exception, SchemaError) + + def test_config_not_proper_yaml(self): + with self.assertRaises(UIError) as err: + load_config(self._path + '/broken-yaml.conf') + self.assertIsInstance(err.exception.source_exception, YAMLError) diff --git a/rebench/ui.py b/rebench/ui.py new file mode 100644 index 00000000..1cd32275 --- /dev/null +++ b/rebench/ui.py @@ -0,0 +1,92 @@ +# Copyright (c) 2018 Stefan Marr +# +# Permission is hereby granted, free of charge, to any person obtaining a copy +# of this software and associated documentation files (the "Software"), to +# deal in the Software without restriction, including without limitation the +# rights to use, copy, modify, merge, publish, distribute, sublicense, and/or +# sell copies of the Software, and to permit persons to whom the Software is +# furnished to do so, subject to the following conditions: +# +# The above copyright notice and this permission notice shall be included in +# all copies or substantial portions of the Software. +# +# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +# FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +# AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +# LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING +# FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS +# IN THE SOFTWARE. +import sys + +from humanfriendly.compat import coerce_string +from humanfriendly.terminal import terminal_supports_colors, ansi_wrap,\ + auto_encode, warning as hf_warning, output as hf_output + +DETAIL_INDENT = "\n " +DETAIL_INDENT_WON = " " + + +_verbose_output = False +_debug_output = False + + +def set_verbose_debug_mode(verbose, debug): + global _verbose_output, _debug_output # pylint: disable=global-statement + _verbose_output = verbose + _debug_output = debug + + +def output(text, *args, **kw): + hf_output(text, *args, **kw) + + +def warning(text, *args, **kw): + text = coerce_string(text) + if terminal_supports_colors(sys.stderr): + text = ansi_wrap(text, color='magenta') + auto_encode(sys.stderr, text + '\n', *args, **kw) + + +def error(text, *args, **kw): + return hf_warning(text, *args, **kw) + + +def verbose_output_info(text, *args, **kw): + if _verbose_output: + text = coerce_string(text) + auto_encode(sys.stdout, text + '\n', *args, **kw) + + +def verbose_error_info(text, *args, **kw): + if _verbose_output: + text = coerce_string(text) + auto_encode(sys.stderr, text + '\n', *args, **kw) + + +def debug_output_info(text, *args, **kw): + if _debug_output: + text = coerce_string(text) + auto_encode(sys.stdout, text + '\n', *args, **kw) + + +def debug_error_info(text, *args, **kw): + if _debug_output: + text = coerce_string(text) + auto_encode(sys.stderr, text + '\n', *args, **kw) + + +class UIError(Exception): + + def __init__(self, message, exception): + super(UIError, self).__init__() + self._message = message + self._exception = exception + + @property + def message(self): + return self._message + + @property + def source_exception(self): + return self._exception diff --git a/setup.py b/setup.py index f9b592be..7bef5b06 100644 --- a/setup.py +++ b/setup.py @@ -8,10 +8,10 @@ # rights to use, copy, modify, merge, publish, distribute, sublicense, and/or # sell copies of the Software, and to permit persons to whom the Software is # furnished to do so, subject to the following conditions: -# +# # The above copyright notice and this permission notice shall be included in # all copies or substantial portions of the Software. -# +# # THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR # IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, # FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE @@ -34,7 +34,8 @@ packages=find_packages(exclude=['*.tests']), install_requires=[ 'PyYAML>=3.12', - 'pykwalify>=1.6.1' + 'pykwalify>=1.6.1', + 'humanfriendly>=4.12' ], entry_points = { 'console_scripts' : ['rebench = rebench:main_func']