def test_write_results_to_disk(self, mock_platform,
no_results_instantiation_check):
config = Config("krun/tests/example.krun")
mock_platform.num_cpus = 4
mock_platform.num_per_core_measurements = mock_platform.num_cpus
out_file = "krun/tests/example_results.json.bz2"
results0 = Results(config, mock_platform)
results0.audit = dict()
results0.starting_temperatures = [4355, 9879]
results0.wallclock_times = {u"dummy:Java:default-java": [[1.000726]]}
results0.eta_estimates = {u"dummy:Java:default-java": [1.1]}
results0.core_cycle_counts = {
u"dummy:Java:default-java": [[[2], [3], [4], [5]]]
}
results0.aperf_counts = {
u"dummy:Java:default-java": [[[3], [4], [5], [6]]]
}
results0.mperf_counts = {
u"dummy:Java:default-java": [[[4], [5], [6], [7]]]
}
results0.reboots = 5
results0.error_flag = False
results0.write_to_file()
results1 = Results(config, None, results_file=out_file)
assert results0 == results1
# Clean-up generated file.
os.unlink(out_file)
def emulate_first_reboot(platform, config):
platform.starting_temperatures = platform.take_temperature_readings()
manifest = ManifestManager(config, platform, new_file=True)
manifest.set_starting_temperatures(platform.starting_temperatures)
results = Results(config, platform)
results.write_to_file()
return manifest
def test_audit_differs0001(self, monkeypatch, mock_platform, caplog,
no_results_instantiation_check):
"""Check that if the audit differs, a crash occurs"""
make_reboot_raise(monkeypatch)
no_envlogs(monkeypatch)
config = Config(os.path.join(TEST_DIR, "example.krun"))
krun.util.assign_platform(config, mock_platform)
emulate_first_reboot(mock_platform, config)
results_path = config.results_filename()
# mutate the audit, so it won't match later
results = Results(config, mock_platform, results_file=results_path)
results.audit._audit["wibble"] = "wut"
results.write_to_file()
sched = ExecutionScheduler(config,
mock_platform.mailer,
mock_platform,
dry_run=True)
with pytest.raises(krun.util.FatalKrunError):
sched.run()
expect = "This is only valid if the machine you are using is identical"
assert expect in caplog.text
os.unlink(sched.manifest.path)
os.unlink(results_path)
def test_audit_differs0001(self, monkeypatch, mock_platform, caplog):
"""Check that if the audit differs, a crash occurs"""
make_reboot_raise(monkeypatch)
no_envlogs(monkeypatch)
config = Config(os.path.join(TEST_DIR, "example.krun"))
krun.util.assign_platform(config, mock_platform)
emulate_first_reboot(mock_platform, config, monkeypatch)
results_path = config.results_filename()
# mutate the audit, so it won't match later
results = Results(config, mock_platform, results_file=results_path)
results.audit._audit["wibble"] = "wut"
results.write_to_file()
sched = ExecutionScheduler(config, mock_platform.mailer, mock_platform,
dry_run=True)
with pytest.raises(krun.util.FatalKrunError):
sched.run()
expect = "This is only valid if the machine you are using is identical"
assert expect in caplog.text()
os.unlink(sched.manifest.path)
os.unlink(results_path)
def emulate_first_reboot(platform, config, monkeypatch):
no_results_instantiation_check(monkeypatch)
platform.starting_temperatures = platform.take_temperature_readings()
manifest = ManifestManager(config, platform, new_file=True)
manifest.set_starting_temperatures(platform.starting_temperatures)
results = Results(config, platform)
results.write_to_file()
return manifest
def strip_results(config, key_spec):
from krun.platform import detect_platform
from krun.results import Results
platform = detect_platform(None)
results = Results(config, platform, results_file=config.results_filename())
n_removed = results.strip_results(key_spec)
if n_removed > 0:
results.write_to_file()
info("Removed %d result keys" % n_removed)
def strip_results(config, key_spec):
from krun.platform import detect_platform
from krun.results import Results
platform = detect_platform(None)
results = Results(config, platform,
results_file=config.results_filename())
n_removed = results.strip_results(key_spec)
if n_removed > 0:
results.write_to_file()
info("Removed %d result keys" % n_removed)
def test_write_results_to_disk(self, mock_platform):
config = Config("krun/tests/example.krun")
out_file = "krun/tests/example_results.json.bz2"
results0 = Results(config, mock_platform)
results0.audit = dict()
results0.starting_temperatures = [4355, 9879]
results0.data = {u"dummy:Java:default-java": [[1.000726]]}
results0.eta_estimates = {u"dummy:Java:default-java": [1.1]}
results0.reboots = 5
results0.error_flag = False
results0.write_to_file()
results1 = Results(config, None, results_file=out_file)
assert results0 == results1
# Clean-up generated file.
os.unlink(out_file)
def test_write_results_to_disk(self, mock_platform):
config = Config("krun/tests/example.krun")
out_file = "krun/tests/example_results.json.bz2"
results0 = Results(config, mock_platform)
results0.audit = dict()
results0.starting_temperatures = [4355, 9879]
results0.data = {u"dummy:Java:default-java": [[1.000726]]}
results0.eta_estimates = {u"dummy:Java:default-java": [1.1]}
results0.reboots = 5
results0.error_flag = False
results0.write_to_file()
results1 = Results(config, None, results_file=out_file)
assert results0 == results1
# Clean-up generated file.
os.unlink(out_file)
def test_write_results_to_disk(self, mock_platform,
no_results_instantiation_check):
config = Config("krun/tests/example.krun")
mock_platform.num_cpus = 4
mock_platform.num_per_core_measurements = mock_platform.num_cpus
out_file = "krun/tests/example_results.json.bz2"
results0 = Results(config, mock_platform)
results0.audit = dict()
results0.starting_temperatures = [4355, 9879]
results0.wallclock_times = {u"dummy:Java:default-java": [[1.000726]]}
results0.eta_estimates = {u"dummy:Java:default-java": [1.1]}
results0.core_cycle_counts = {u"dummy:Java:default-java": [[[2], [3], [4], [5]]]}
results0.aperf_counts = {u"dummy:Java:default-java": [[[3], [4], [5], [6]]]}
results0.mperf_counts = {u"dummy:Java:default-java": [[[4], [5], [6], [7]]]}
results0.reboots = 5
results0.error_flag = False
results0.write_to_file()
results1 = Results(config, None, results_file=out_file)
assert results0 == results1
# Clean-up generated file.
os.unlink(out_file)
def run(self):
"""Benchmark execution starts here"""
# In reboot mode, wait for the system to come up before we proceed
if self.platform.hardware_reboots:
debug("Waiting %s seconds for the system to come up." %
str(STARTUP_WAIT_SECONDS))
self.platform.sleep(STARTUP_WAIT_SECONDS)
# Important that the dmesg is collected after the above startup wait.
# Otherwise we get spurious dmesg changes.
self.platform.collect_starting_dmesg()
assert self.manifest.num_execs_left > 0
self.platform.wait_for_temperature_sensors()
bench, vm, variant = self.manifest.next_exec_key.split(":")
key_pexec_idx = self.manifest.next_exec_key_index()
job = ExecutionJob(self, vm, self.config.VMS[vm], bench, variant,
self.config.BENCHMARKS[bench], key_pexec_idx)
# Default to error state. This is the value the finally block will see
# if an exception is raised inside the try block, otherwise it is
# re-assigned based on the result of running the benchmark.
flag = 'E'
# Run the pre-exec commands, the benchmark and the post-exec commands.
# These are wrapped in a try/except, so that the post-exec commands
# are always executed, even if an exception has occurred. We only
# reboot /after/ the post-exec commands have completed.
results = None
try:
# Run the user's pre-process-execution commands. We can't put an
# ETA estimate in the environment for the pre-commands as we have
# not (and should not) load the results file into memory yet.
#
# It might seem tempting to move this outside the try block, to
# ensure that post-hooks are only run if pre-hooks ran. We don't,
# thus avoiding the case where only *part* of the pre-hooks run,
# but the post-hooks then don't run.
util.run_shell_cmd_list(self.config.PRE_EXECUTION_CMDS,)
# We collect rough execution times separate from real results. The
# reason for this is that, even if a benchmark crashes it takes
# time and we need to account for this when making estimates. A
# crashing benchmark will give an empty list of iteration times,
# meaning we can't use 'raw_exec_result' below for estimates.
exec_start_time = time.time()
measurements, instr_data, flag = job.run(self.mailer, self.dry_run)
exec_end_time = time.time()
# Only now is it OK to load the results file into memory.
Results.ok_to_instantiate = True
results = Results(self.config, self.platform,
results_file=self.config.results_filename())
# Bail early if the process execution needs to be re-run.
if flag == "O":
util.run_shell_cmd_list(
self.config.POST_EXECUTION_CMDS,
extra_env=self._make_post_cmd_env(results)
)
info("Rebooting to re-run previous process execution")
util.reboot(self.manifest, self.platform, update_count=False)
# reboot() does not return
raise RuntimeError("reached unreachable code!")
# Store new result.
results.append_exec_measurements(job.key, measurements, flag)
# Store instrumentation data in a separate file
if job.vm_info["vm_def"].instrument:
key_exec_num = self.manifest.completed_exec_counts[job.key]
util.dump_instr_json(job.key, key_exec_num, self.config, instr_data)
eta_info = exec_end_time - exec_start_time
if self.platform.hardware_reboots:
# Add time taken to wait for system to come up if we are in
# hardware-reboot mode.
eta_info += STARTUP_WAIT_SECONDS
results.eta_estimates[job.key].append(eta_info)
self.manifest.update(flag)
except Exception:
raise
finally:
# Run the user's post-process-execution commands with updated
# ETA estimates. Important that this happens *after* dumping
# results, as the user is likely copying intermediate results to
# another host.
# _make_post_cmd_env() needs the results to make an ETA. If an
# exception occurred in the above try block, there's a chance that
# they have not have been loaded.
if results is None:
Results.ok_to_instantiate = True
results = Results(self.config, self.platform,
results_file=self.config.results_filename())
# If errors occured, set error flag in results file
if self.platform.check_dmesg_for_changes(self.manifest) or \
flag == 'E':
results.error_flag = True
results.write_to_file()
util.run_shell_cmd_list(
self.config.POST_EXECUTION_CMDS,
extra_env=self._make_post_cmd_env(results)
)
tfmt = self.get_overall_time_estimate_formatter(results)
if self.manifest.eta_avail_idx == self.manifest.next_exec_idx:
# We just found out roughly how long the session has left, mail out.
msg = "ETA for current session now known: %s" % tfmt.finish_str
util.log_and_mail(self.mailer, debug,
"ETA for Current Session Available",
msg, bypass_limiter=True)
info("{:<25s}: {} ({} from now)".format(
"Estimated completion (whole session)", tfmt.finish_str,
tfmt.delta_str))
info("%d executions left in scheduler queue" % self.manifest.num_execs_left)
if self.manifest.num_execs_left > 0 and \
self.manifest.eta_avail_idx > self.manifest.next_exec_idx:
info("Executions until ETA known: %s" %
(self.manifest.eta_avail_idx -
self.manifest.next_exec_idx))
# Although it would have been nice to have checked this prior to
# running the execution, it depends on the results file, which we
# should not load prior to the process execution.
util.check_audit_unchanged(results, self.platform)
assert self.manifest.num_execs_left >= 0
if self.manifest.num_execs_left > 0:
# print info about the next job
benchmark, vm_name, variant = \
self.manifest.next_exec_key.split(":")
info("Next execution is '%s(%d)' (%s variant) under '%s'" %
(benchmark, self.config.BENCHMARKS[benchmark], variant, vm_name))
tfmt = self.get_exec_estimate_time_formatter(job.key, results)
info("{:<35s}: {} ({} from now)".format(
"Estimated completion (next execution)",
tfmt.finish_str,
tfmt.delta_str))
info("Reboot in preparation for next execution")
util.reboot(self.manifest, self.platform)
elif self.manifest.num_execs_left == 0:
self.platform.save_power()
if self.config.ENABLE_PINNING:
self.platform.clear_cpu_pinning()
info("Done: Results dumped to %s" % self.config.results_filename())
err_msg = "Errors/warnings occurred -- read the log!"
if results.error_flag:
warn(err_msg)
msg = "Session completed. Log file at: '%s'" % (self.log_path)
if results.error_flag:
msg += "\n\n%s" % err_msg
msg += "\n\nDon't forget to disable Krun at boot."
util.log_and_mail(self.mailer, info, "Benchmarks Complete", msg,
bypass_limiter=True)
def inner_main(mailer, on_first_invocation, config, args):
out_file = config.results_filename()
out_file_exists = os.path.exists(out_file)
instr_dir = util.get_instr_json_dir(config)
instr_dir_exists = os.path.exists(instr_dir)
envlog_dir = util.get_envlog_dir(config)
envlog_dir_exists = os.path.exists(envlog_dir)
if out_file_exists and not os.path.isfile(out_file):
util.fatal("Output file '%s' exists but is not a regular file" %
out_file)
if out_file_exists and on_first_invocation:
util.fatal("Output results file '%s' already exists. "
"Move the file away before running Krun." % out_file)
if instr_dir_exists and on_first_invocation:
util.fatal("Instrumentation dir '%s' exists." % instr_dir)
if envlog_dir_exists and on_first_invocation:
util.fatal("Env log dir '%s' exists." % envlog_dir)
if not out_file_exists and not on_first_invocation:
util.fatal("No results file to resume. Expected '%s'" % out_file)
# Initialise platform instance and assign to VM defs.
# This needs to be done early, so VM sanity checks can run.
platform = detect_platform(mailer, config)
platform.quick_mode = args.quick
platform.no_user_change = args.no_user_change
platform.no_tickless_check = args.no_tickless_check
platform.no_pstate_check = args.no_pstate_check
platform.hardware_reboots = args.hardware_reboots
# Create the instrumentation directory if required
if on_first_invocation:
# We only want make a dir if >=1 VM is in instrumentation mode.
for vm in config.VMS.itervalues():
if vm['vm_def'].instrument:
util.make_instr_dir(config)
break
debug("Checking platform preliminaries")
platform.check_preliminaries()
# Make a bit of noise if this is a virtualised environment
if platform.is_virtual():
warn(
"This appears to be a virtualised host. The results will be flawed. "
"Use bare-metal for reliable results!")
platform.collect_audit()
# At this point the config file is OK, and on-disk state is consistent,
# so let's daemonise (if requested).
if args.daemonise:
util.daemonise()
if not on_first_invocation:
# output file must exist, due to check above
assert (out_file_exists)
debug("Using pre-recorded initial temperature readings")
manifest = ManifestManager(config, platform)
platform_temps = {}
for sensor, tup in manifest.starting_temperatures.iteritems():
platform_temps[sensor] = tup[1]
platform.starting_temperatures = platform_temps
else:
manifest = ManifestManager(config, platform, new_file=True)
if manifest.num_execs_left == 0:
# No executions, or all skipped
fatal("Empty schedule!")
try:
info(("Wait %s secs to allow system to cool prior to "
"collecting initial temperature readings") %
config.TEMP_READ_PAUSE)
# This part is wrapped in hooks, so that if daemons or networking are
# taken down for process executions, then the initial temperature
# reading gets the same treatment.
util.run_shell_cmd_list(config.PRE_EXECUTION_CMDS, )
platform.sleep(config.TEMP_READ_PAUSE)
debug("Taking fresh initial temperature readings")
platform.starting_temperatures = platform.take_temperature_readings(
)
manifest.set_starting_temperatures(platform.starting_temperatures)
# Write out an empty results file. After the initial reboot Krun
# will expect this to exist.
Results.ok_to_instantiate = True
results = Results(config, platform)
results.write_to_file()
except:
raise
finally:
util.run_shell_cmd_list(config.POST_EXECUTION_CMDS, )
log_path = config.log_filename(resume=False)
util.log_and_mail(mailer,
debug,
"Benchmarking started",
"Benchmarking started.\nLogging to %s" % log_path,
bypass_limiter=True)
util.reboot(manifest, platform)
# Assign platform to VM defs -- needs to happen early for sanity checks
util.assign_platform(config, platform)
sanity_checks(config, platform)
# Build job queue -- each job is an execution
sched = ExecutionScheduler(config, mailer, platform, dry_run=args.dry_run)
sched.run()
class ExecutionScheduler(object):
"""Represents our entire benchmarking session"""
def __init__(self,
config,
mailer,
platform,
resume=False,
reboot=False,
dry_run=False,
started_by_init=False):
self.mailer = mailer
self.config = config
self.work_deque = deque()
self.eta_avail = 0
self.jobs_done = 0
self.platform = platform
self.resume = resume
self.reboot = reboot
self.dry_run = dry_run
self.started_by_init = started_by_init
if resume:
self.results = Results(self.config,
platform,
results_file=self.config.results_filename())
else:
self.results = Results(self.config, platform)
self.log_path = self.config.log_filename(self.resume)
def set_eta_avail(self):
"""call after adding job before eta should become available"""
self.eta_avail = len(self)
def jobs_until_eta_known(self):
return self.eta_avail - self.jobs_done
def add_job(self, job):
self.work_deque.append(job)
def remove_job_by_key(self, key):
for job in self.work_deque:
if job.key == key:
job_to_remove = job
break
else:
raise JobMissingError(key)
debug("Removed %s from schedule" % key)
self.work_deque.remove(job_to_remove)
def next_job(self, peek=False):
try:
job = self.work_deque.popleft()
if peek:
self.work_deque.appendleft(job)
return job
except IndexError:
raise ScheduleEmpty() # we are done
def __len__(self):
return len(self.work_deque)
def get_estimated_exec_duration(self, key):
previous_exec_times = self.results.eta_estimates.get(key)
if previous_exec_times:
return mean(previous_exec_times)
else:
return None # we don't know
def get_estimated_overall_duration(self):
etas = [j.get_estimated_exec_duration() for j in self.work_deque]
if None in etas:
return None # we don't know
return sum(etas)
def get_exec_estimate_time_formatter(self, key):
return TimeEstimateFormatter(self.get_estimated_exec_duration(key))
def get_overall_time_estimate_formatter(self):
return TimeEstimateFormatter(self.get_estimated_overall_duration())
def add_eta_info(self, key, exec_time):
self.results.eta_estimates[key].append(exec_time)
def build_schedule(self):
"""Builds a queue of process execution jobs.
Returns two sets: non_skipped_keys, skipped_keys"""
skipped_keys, non_skipped_keys = set(), set()
one_exec_scheduled = False
eta_avail_job = None
for exec_n in xrange(self.config.N_EXECUTIONS):
for vm_name, vm_info in self.config.VMS.items():
for bmark, param in self.config.BENCHMARKS.items():
for variant in vm_info["variants"]:
job = ExecutionJob(self, vm_name, vm_info, bmark,
variant, param)
if not self.config.should_skip(job.key):
non_skipped_keys |= set([job.key])
if one_exec_scheduled and not eta_avail_job:
# first job of second executions eta becomes known.
eta_avail_job = job
self.set_eta_avail()
self.add_job(job)
else:
skipped_keys |= set([job.key])
if not one_exec_scheduled:
debug("%s is in skip list. Not scheduling." %
job.key)
one_exec_scheduled = True
self.expected_reboots = len(self)
# Resume mode: if previous results are available, remove the
# jobs from the schedule which have already been executed, and
# add the results to this object, ready to be saved to a Json file.
if self.resume:
self._remove_previous_execs_from_schedule()
# Sanity check ETA estimates
for key, exec_data in self.results.data.iteritems():
got_len = len(self.results.eta_estimates[key])
expect_len = len(exec_data)
if expect_len != got_len:
msg = "ETA estimates didn't tally with results: "
msg += "key=%s, expect_len=%d, got_len=%d " % \
(key, expect_len, got_len)
msg += "data[%s]=%s; " % (key, str(self.results.data[key]))
msg += "eta[%s]=%s" % \
(key, str(self.results.eta_estimates[key]))
util.log_and_mail(self.mailer,
error,
"Fatal Krun Error",
msg,
bypass_limiter=True,
exit=True)
return non_skipped_keys, skipped_keys
def _remove_previous_execs_from_schedule(self):
for key in self.results.data:
num_completed_jobs = self.results.jobs_completed(key)
if num_completed_jobs > 0:
try:
debug("%s has already been run %d times." %
(key, num_completed_jobs))
for _ in range(num_completed_jobs):
self.remove_job_by_key(key)
self.jobs_done += 1
except JobMissingError as excn:
tup = (excn.key, self.config.filename,
self.config.results_filename())
msg = ("Failed to resume benchmarking session\n." +
"The execution %s appears in results " +
"file: %s, but not in config file: %s." % tup)
util.fatal(msg)
def _make_pre_post_cmd_env(self):
"""Prepare an environment dict for pre/post execution hooks"""
jobs_until_eta_known = self.jobs_until_eta_known()
if jobs_until_eta_known > 0:
eta_val = "Unknown. Known in %d process executions." % \
self.jobs_until_eta_known()
else:
eta_val = self.get_overall_time_estimate_formatter().finish_str
return {
"KRUN_RESULTS_FILE": self.config.results_filename(),
"KRUN_LOG_FILE": self.config.log_filename(resume=True),
"KRUN_ETA_DATUM": now_str(),
"KRUN_ETA_VALUE": eta_val,
}
def run(self):
"""Benchmark execution starts here"""
jobs_left = len(self)
if jobs_left == 0:
debug("Krun started with an empty queue of jobs")
if not self.started_by_init:
util.log_and_mail(self.mailer,
debug,
"Benchmarking started",
"Benchmarking started.\nLogging to %s" %
self.log_path,
bypass_limiter=True)
if self.reboot and not self.started_by_init:
# Reboot before first benchmark (dumps results file).
info("Reboot prior to first execution")
self._reboot()
if self.reboot and self.started_by_init and jobs_left > 0:
debug("Waiting %s seconds for the system to come up." %
str(STARTUP_WAIT_SECONDS))
if self.dry_run:
info("SIMULATED: time.sleep (would have waited %s seconds)." %
STARTUP_WAIT_SECONDS)
else:
time.sleep(STARTUP_WAIT_SECONDS)
# Important that the dmesg is collected after the above startup wait.
# Otherwise we get spurious dmesg changes.
self.platform.collect_starting_dmesg()
while True:
self.platform.wait_for_temperature_sensors()
jobs_left = len(self)
if jobs_left == 0:
break
# Run the user's pre-process-execution commands
util.run_shell_cmd_list(self.config.PRE_EXECUTION_CMDS,
extra_env=self._make_pre_post_cmd_env())
job = self.next_job()
# We collect rough execution times separate from real results. The
# reason for this is that, even if a benchmark crashes it takes
# time and we need to account for this when making estimates. A
# crashing benchmark will give an empty list of iteration times,
# meaning we can't use 'raw_exec_result' below for estimates.
exec_start_time = time.time()
raw_exec_result = job.run(self.mailer, self.dry_run)
exec_end_time = time.time()
exec_result = util.format_raw_exec_results(raw_exec_result)
if not exec_result and not self.dry_run:
self.results.error_flag = True
self.results.data[job.key].append(exec_result)
eta_info = exec_end_time - exec_start_time
if self.reboot:
# Add time taken to wait for system to come up if we are in
# reboot mode.
eta_info += STARTUP_WAIT_SECONDS
self.add_eta_info(job.key, eta_info)
info("%d executions left in scheduler queue" % (jobs_left - 1))
# We dump the json after each experiment so we can monitor the
# json file mid-run. It is overwritten each time.
self.results.write_to_file()
self.jobs_done += 1
# Run the user's post-process-execution commands with updated
# ETA estimates. Important that this happens *after* dumping
# results, as the user is likely copying intermediate results to
# another host.
util.run_shell_cmd_list(self.config.POST_EXECUTION_CMDS,
extra_env=self._make_pre_post_cmd_env())
tfmt = self.get_overall_time_estimate_formatter()
if self.eta_avail == self.jobs_done:
# We just found out roughly how long the session has left, mail out.
msg = "ETA for current session now known: %s" % tfmt.finish_str
util.log_and_mail(self.mailer,
debug,
"ETA for Current Session Available",
msg,
bypass_limiter=True)
info("{:<25s}: {} ({} from now)".format("Estimated completion",
tfmt.finish_str,
tfmt.delta_str))
try:
job = self.next_job(peek=True)
except ScheduleEmpty:
pass # no next job
else:
# print info about the next job
info("Next execution is '%s(%d)' (%s variant) under '%s'" %
(job.benchmark, job.parameter, job.variant, job.vm_name))
tfmt = self.get_exec_estimate_time_formatter(job.key)
info("{:<35s}: {} ({} from now)".format(
"Estimated completion (next execution)", tfmt.finish_str,
tfmt.delta_str))
if (self.eta_avail
is not None) and (self.jobs_done < self.eta_avail):
info("Executions until ETA known: %s" %
self.jobs_until_eta_known())
if self.platform.check_dmesg_for_changes():
self.results.error_flag = True
if self.reboot and len(self) > 0:
info("Reboot in preparation for next execution")
self._reboot()
self.platform.save_power()
info("Done: Results dumped to %s" % self.config.results_filename())
err_msg = "Errors/warnings occurred -- read the log!"
if self.results.error_flag:
warn(err_msg)
msg = "Session completed. Log file at: '%s'" % (self.log_path)
if self.results.error_flag:
msg += "\n\n%s" % err_msg
if self.reboot:
msg += "\n\nDon't forget to disable Krun at boot."
util.log_and_mail(self.mailer,
info,
"Benchmarks Complete",
msg,
bypass_limiter=True)
def _reboot(self):
self.results.reboots += 1
debug("About to execute reboot: %g, expecting %g in total." %
(self.results.reboots, self.expected_reboots))
# Dump the results file. This may already have been done, but we
# have changed self.nreboots, which needs to be written out.
self.results.write_to_file()
if self.results.reboots > self.expected_reboots:
util.fatal(("HALTING now to prevent an infinite reboot loop: " +
"INVARIANT num_reboots <= num_jobs violated. " +
"Krun was about to execute reboot number: %g. " +
"%g jobs have been completed, %g are left to go.") %
(self.results.reboots, self.jobs_done, len(self)))
if self.dry_run:
info("SIMULATED: reboot (restarting Krun in-place)")
args = sys.argv
if not self.started_by_init:
args.extend(["--resume", "--started-by-init"])
debug("Simulated reboot with args: " + " ".join(args))
os.execv(args[0], args) # replace myself
assert False # unreachable
else:
subprocess.call(self.platform.get_reboot_cmd())
class ExecutionScheduler(object):
"""Represents our entire benchmarking session"""
def __init__(self, config, mailer, platform,
resume=False, reboot=False, dry_run=False,
started_by_init=False):
self.mailer = mailer
self.config = config
self.work_deque = deque()
self.eta_avail = 0
self.jobs_done = 0
self.platform = platform
self.resume = resume
self.reboot = reboot
self.dry_run = dry_run
self.started_by_init = started_by_init
if resume:
self.results = Results(self.config, platform,
results_file=self.config.results_filename())
else:
self.results = Results(self.config, platform)
self.log_path = self.config.log_filename(self.resume)
def set_eta_avail(self):
"""call after adding job before eta should become available"""
self.eta_avail = len(self)
def jobs_until_eta_known(self):
return self.eta_avail - self.jobs_done
def add_job(self, job):
self.work_deque.append(job)
def remove_job_by_key(self, key):
for job in self.work_deque:
if job.key == key:
job_to_remove = job
break
else:
raise JobMissingError(key)
debug("Removed %s from schedule" % key)
self.work_deque.remove(job_to_remove)
def next_job(self, peek=False):
try:
job = self.work_deque.popleft()
if peek:
self.work_deque.appendleft(job)
return job
except IndexError:
raise ScheduleEmpty() # we are done
def __len__(self):
return len(self.work_deque)
def get_estimated_exec_duration(self, key):
previous_exec_times = self.results.eta_estimates.get(key)
if previous_exec_times:
return mean(previous_exec_times)
else:
return None # we don't know
def get_estimated_overall_duration(self):
etas = [j.get_estimated_exec_duration() for j in self.work_deque]
if None in etas:
return None # we don't know
return sum(etas)
def get_exec_estimate_time_formatter(self, key):
return TimeEstimateFormatter(self.get_estimated_exec_duration(key))
def get_overall_time_estimate_formatter(self):
return TimeEstimateFormatter(self.get_estimated_overall_duration())
def add_eta_info(self, key, exec_time):
self.results.eta_estimates[key].append(exec_time)
def build_schedule(self):
"""Builds a queue of process execution jobs.
Returns two sets: non_skipped_keys, skipped_keys"""
skipped_keys, non_skipped_keys = set(), set()
one_exec_scheduled = False
eta_avail_job = None
for exec_n in xrange(self.config.N_EXECUTIONS):
for vm_name, vm_info in self.config.VMS.items():
for bmark, param in self.config.BENCHMARKS.items():
for variant in vm_info["variants"]:
job = ExecutionJob(self, vm_name, vm_info, bmark, variant, param)
if not self.config.should_skip(job.key):
non_skipped_keys |= set([job.key])
if one_exec_scheduled and not eta_avail_job:
# first job of second executions eta becomes known.
eta_avail_job = job
self.set_eta_avail()
self.add_job(job)
else:
skipped_keys |= set([job.key])
if not one_exec_scheduled:
debug("%s is in skip list. Not scheduling." %
job.key)
one_exec_scheduled = True
self.expected_reboots = len(self)
# Resume mode: if previous results are available, remove the
# jobs from the schedule which have already been executed, and
# add the results to this object, ready to be saved to a Json file.
if self.resume:
self._remove_previous_execs_from_schedule()
# Sanity check ETA estimates
for key, exec_data in self.results.data.iteritems():
got_len = len(self.results.eta_estimates[key])
expect_len = len(exec_data)
if expect_len != got_len:
msg = "ETA estimates didn't tally with results: "
msg += "key=%s, expect_len=%d, got_len=%d " % \
(key, expect_len, got_len)
msg += "data[%s]=%s; " % (key, str(self.results.data[key]))
msg += "eta[%s]=%s" % \
(key, str(self.results.eta_estimates[key]))
util.log_and_mail(self.mailer, error,
"Fatal Krun Error",
msg, bypass_limiter=True, exit=True)
return non_skipped_keys, skipped_keys
def _remove_previous_execs_from_schedule(self):
for key in self.results.data:
num_completed_jobs = self.results.jobs_completed(key)
if num_completed_jobs > 0:
try:
debug("%s has already been run %d times." %
(key, num_completed_jobs))
for _ in range(num_completed_jobs):
self.remove_job_by_key(key)
self.jobs_done += 1
except JobMissingError as excn:
tup = (excn.key, self.config.filename,
self.config.results_filename())
msg = ("Failed to resume benchmarking session\n." +
"The execution %s appears in results " +
"file: %s, but not in config file: %s." % tup)
util.fatal(msg)
def _make_pre_post_cmd_env(self):
"""Prepare an environment dict for pre/post execution hooks"""
jobs_until_eta_known = self.jobs_until_eta_known()
if jobs_until_eta_known > 0:
eta_val = "Unknown. Known in %d process executions." % \
self.jobs_until_eta_known()
else:
eta_val = self.get_overall_time_estimate_formatter().finish_str
return {
"KRUN_RESULTS_FILE": self.config.results_filename(),
"KRUN_LOG_FILE": self.config.log_filename(resume=True),
"KRUN_ETA_DATUM": now_str(),
"KRUN_ETA_VALUE": eta_val,
}
def run(self):
"""Benchmark execution starts here"""
jobs_left = len(self)
if jobs_left == 0:
debug("Krun started with an empty queue of jobs")
if not self.started_by_init:
util.log_and_mail(self.mailer, debug,
"Benchmarking started",
"Benchmarking started.\nLogging to %s" %
self.log_path,
bypass_limiter=True)
if self.reboot and not self.started_by_init:
# Reboot before first benchmark (dumps results file).
info("Reboot prior to first execution")
self._reboot()
if self.reboot and self.started_by_init and jobs_left > 0:
debug("Waiting %s seconds for the system to come up." %
str(STARTUP_WAIT_SECONDS))
if self.dry_run:
info("SIMULATED: time.sleep (would have waited %s seconds)." %
STARTUP_WAIT_SECONDS)
else:
time.sleep(STARTUP_WAIT_SECONDS)
# Important that the dmesg is collected after the above startup wait.
# Otherwise we get spurious dmesg changes.
self.platform.collect_starting_dmesg()
while True:
self.platform.wait_for_temperature_sensors()
jobs_left = len(self)
if jobs_left == 0:
break
# Run the user's pre-process-execution commands
util.run_shell_cmd_list(
self.config.PRE_EXECUTION_CMDS,
extra_env=self._make_pre_post_cmd_env()
)
job = self.next_job()
# We collect rough execution times separate from real results. The
# reason for this is that, even if a benchmark crashes it takes
# time and we need to account for this when making estimates. A
# crashing benchmark will give an empty list of iteration times,
# meaning we can't use 'raw_exec_result' below for estimates.
exec_start_time = time.time()
raw_exec_result = job.run(self.mailer, self.dry_run)
exec_end_time = time.time()
exec_result = util.format_raw_exec_results(raw_exec_result)
if not exec_result and not self.dry_run:
self.results.error_flag = True
self.results.data[job.key].append(exec_result)
eta_info = exec_end_time - exec_start_time
if self.reboot:
# Add time taken to wait for system to come up if we are in
# reboot mode.
eta_info += STARTUP_WAIT_SECONDS
self.add_eta_info(job.key, eta_info)
info("%d executions left in scheduler queue" % (jobs_left - 1))
# We dump the json after each experiment so we can monitor the
# json file mid-run. It is overwritten each time.
self.results.write_to_file()
self.jobs_done += 1
# Run the user's post-process-execution commands with updated
# ETA estimates. Important that this happens *after* dumping
# results, as the user is likely copying intermediate results to
# another host.
util.run_shell_cmd_list(
self.config.POST_EXECUTION_CMDS,
extra_env=self._make_pre_post_cmd_env()
)
tfmt = self.get_overall_time_estimate_formatter()
if self.eta_avail == self.jobs_done:
# We just found out roughly how long the session has left, mail out.
msg = "ETA for current session now known: %s" % tfmt.finish_str
util.log_and_mail(self.mailer, debug,
"ETA for Current Session Available",
msg, bypass_limiter=True)
info("{:<25s}: {} ({} from now)".format(
"Estimated completion", tfmt.finish_str, tfmt.delta_str))
try:
job = self.next_job(peek=True)
except ScheduleEmpty:
pass # no next job
else:
# print info about the next job
info("Next execution is '%s(%d)' (%s variant) under '%s'" %
(job.benchmark, job.parameter, job.variant, job.vm_name))
tfmt = self.get_exec_estimate_time_formatter(job.key)
info("{:<35s}: {} ({} from now)".format(
"Estimated completion (next execution)",
tfmt.finish_str,
tfmt.delta_str))
if (self.eta_avail is not None) and (self.jobs_done < self.eta_avail):
info("Executions until ETA known: %s" % self.jobs_until_eta_known())
if self.platform.check_dmesg_for_changes():
self.results.error_flag = True
if self.reboot and len(self) > 0:
info("Reboot in preparation for next execution")
self._reboot()
self.platform.save_power()
info("Done: Results dumped to %s" % self.config.results_filename())
err_msg = "Errors/warnings occurred -- read the log!"
if self.results.error_flag:
warn(err_msg)
msg = "Session completed. Log file at: '%s'" % (self.log_path)
if self.results.error_flag:
msg += "\n\n%s" % err_msg
if self.reboot:
msg += "\n\nDon't forget to disable Krun at boot."
util.log_and_mail(self.mailer, info, "Benchmarks Complete", msg,
bypass_limiter=True)
def _reboot(self):
self.results.reboots += 1
debug("About to execute reboot: %g, expecting %g in total." %
(self.results.reboots, self.expected_reboots))
# Dump the results file. This may already have been done, but we
# have changed self.nreboots, which needs to be written out.
self.results.write_to_file()
if self.results.reboots > self.expected_reboots:
util.fatal(("HALTING now to prevent an infinite reboot loop: " +
"INVARIANT num_reboots <= num_jobs violated. " +
"Krun was about to execute reboot number: %g. " +
"%g jobs have been completed, %g are left to go.") %
(self.results.reboots, self.jobs_done, len(self)))
if self.dry_run:
info("SIMULATED: reboot (restarting Krun in-place)")
args = sys.argv
if not self.started_by_init:
args.extend(["--resume", "--started-by-init"])
debug("Simulated reboot with args: " + " ".join(args))
os.execv(args[0], args) # replace myself
assert False # unreachable
else:
subprocess.call(self.platform.get_reboot_cmd())
def inner_main(mailer, on_first_invocation, config, args):
out_file = config.results_filename()
out_file_exists = os.path.exists(out_file)
instr_dir = util.get_instr_json_dir(config)
instr_dir_exists = os.path.exists(instr_dir)
envlog_dir = util.get_envlog_dir(config)
envlog_dir_exists = os.path.exists(envlog_dir)
if out_file_exists and not os.path.isfile(out_file):
util.fatal(
"Output file '%s' exists but is not a regular file" % out_file)
if out_file_exists and on_first_invocation:
util.fatal("Output results file '%s' already exists. "
"Move the file away before running Krun." % out_file)
if instr_dir_exists and on_first_invocation:
util.fatal("Instrumentation dir '%s' exists." % instr_dir)
if envlog_dir_exists and on_first_invocation:
util.fatal("Env log dir '%s' exists." % envlog_dir)
if not out_file_exists and not on_first_invocation:
util.fatal("No results file to resume. Expected '%s'" % out_file)
# Initialise platform instance and assign to VM defs.
# This needs to be done early, so VM sanity checks can run.
platform = detect_platform(mailer, config)
platform.quick_mode = args.quick
platform.no_user_change = args.no_user_change
platform.no_tickless_check = args.no_tickless_check
platform.no_pstate_check = args.no_pstate_check
platform.hardware_reboots = args.hardware_reboots
# Create the instrumentation directory if required
if on_first_invocation:
# We only want make a dir if >=1 VM is in instrumentation mode.
for vm in config.VMS.itervalues():
if vm['vm_def'].instrument:
util.make_instr_dir(config)
break
debug("Checking platform preliminaries")
platform.check_preliminaries()
# Make a bit of noise if this is a virtualised environment
if platform.is_virtual():
warn("This appears to be a virtualised host. The results will be flawed. "
"Use bare-metal for reliable results!")
platform.collect_audit()
# At this point the config file is OK, and on-disk state is consistent,
# so let's daemonise (if requested).
if args.daemonise:
util.daemonise()
if not on_first_invocation:
# output file must exist, due to check above
assert(out_file_exists)
debug("Using pre-recorded initial temperature readings")
manifest = ManifestManager(config, platform)
platform_temps = {}
for sensor, tup in manifest.starting_temperatures.iteritems():
platform_temps[sensor] = tup[1]
platform.starting_temperatures = platform_temps
else:
manifest = ManifestManager(config, platform, new_file=True)
if manifest.num_execs_left == 0:
# No executions, or all skipped
fatal("Empty schedule!")
try:
info(("Wait %s secs to allow system to cool prior to "
"collecting initial temperature readings") %
config.TEMP_READ_PAUSE)
# This part is wrapped in hooks, so that if daemons or networking are
# taken down for process executions, then the initial temperature
# reading gets the same treatment.
util.run_shell_cmd_list(config.PRE_EXECUTION_CMDS,)
platform.sleep(config.TEMP_READ_PAUSE)
debug("Taking fresh initial temperature readings")
platform.starting_temperatures = platform.take_temperature_readings()
manifest.set_starting_temperatures(platform.starting_temperatures)
# Write out an empty results file. After the initial reboot Krun
# will expect this to exist.
Results.ok_to_instantiate = True
results = Results(config, platform)
results.write_to_file()
except:
raise
finally:
util.run_shell_cmd_list(config.POST_EXECUTION_CMDS,)
log_path = config.log_filename(resume=False)
util.log_and_mail(mailer, debug,
"Benchmarking started",
"Benchmarking started.\nLogging to %s" %
log_path, bypass_limiter=True)
util.reboot(manifest, platform)
# Assign platform to VM defs -- needs to happen early for sanity checks
util.assign_platform(config, platform)
sanity_checks(config, platform)
# Build job queue -- each job is an execution
sched = ExecutionScheduler(config,
mailer,
platform,
dry_run=args.dry_run)
sched.run()