def run(self, mailer, dry_run=False): """Runs this job (execution)""" entry_point = self.sched.config.VARIANTS[self.variant] vm_def = self.vm_info["vm_def"] vm_def.dry_run = dry_run # Set heap limit heap_limit_kb = self.sched.config.HEAP_LIMIT stack_limit_kb = self.sched.config.STACK_LIMIT stdout, stderr, rc = vm_def.run_exec( entry_point, self.benchmark, self.vm_info["n_iterations"], self.parameter, heap_limit_kb, stack_limit_kb) if not dry_run: try: iterations_results = util.check_and_parse_execution_results(stdout, stderr, rc) except util.ExecutionFailed as e: util.log_and_mail(mailer, error, "Benchmark failure: %s" % self.key, e.message) iterations_results = [] else: iterations_results = [] # We print the status *after* benchmarking, so that I/O cannot be # commited during benchmarking. In production, we will be rebooting # before the next execution, so we are grand. info("Finished '%s(%d)' (%s variant) under '%s'" % (self.benchmark, self.parameter, self.variant, self.vm_name)) return iterations_results
def run(self, mailer, dry_run=False): """Runs this job (execution)""" entry_point = self.sched.config.VARIANTS[self.variant] vm_def = self.vm_info["vm_def"] vm_def.dry_run = dry_run # Set heap limit heap_limit_kb = self.sched.config.HEAP_LIMIT stack_limit_kb = self.sched.config.STACK_LIMIT stdout, stderr, rc = vm_def.run_exec(entry_point, self.benchmark, self.vm_info["n_iterations"], self.parameter, heap_limit_kb, stack_limit_kb) if not dry_run: try: iterations_results = util.check_and_parse_execution_results( stdout, stderr, rc) except util.ExecutionFailed as e: util.log_and_mail(mailer, error, "Benchmark failure: %s" % self.key, e.message) iterations_results = [] else: iterations_results = [] # We print the status *after* benchmarking, so that I/O cannot be # commited during benchmarking. In production, we will be rebooting # before the next execution, so we are grand. info("Finished '%s(%d)' (%s variant) under '%s'" % (self.benchmark, self.parameter, self.variant, self.vm_name)) return iterations_results
def test_log_and_mail(): log_fn = lambda s: None log_and_mail(MockMailer(), log_fn, "subject", "msg", exit=False, bypass_limiter=False) with pytest.raises(FatalKrunError): log_and_mail(MockMailer(), log_fn, "", "", exit=True, bypass_limiter=False) assert True
def test_log_and_mail(mock_manifest, mock_mailer): log_fn = lambda s: None log_and_mail(mock_mailer, log_fn, "subject", "msg", exit=False, bypass_limiter=False, manifest=mock_manifest) with pytest.raises(FatalKrunError): log_and_mail(MockMailer(), log_fn, "", "", exit=True, bypass_limiter=False, manifest=mock_manifest) assert True
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 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 check_dmesg_for_changes(self): new_dmesg_time = localtime() new_dmesg = self._collect_dmesg_lines() old_fn = self._timestamp_to_str(self.last_dmesg_time) new_fn = self._timestamp_to_str(new_dmesg_time) lines = [x for x in difflib.unified_diff( self.last_dmesg, new_dmesg, old_fn, new_fn, lineterm="")] if lines: # dmesg changed! diff = "\n".join(lines) warn_s = "dmesg seems to have changed! Diff follows:\n" + diff log_and_mail(self.mailer, warn, "dmesg changed", warn_s) self.last_dmesg = new_dmesg self.last_dmesg_time = new_dmesg_time return True # i.e. a (potential) error occurred return False
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 run(self, mailer, dry_run=False): """Runs this job (execution)""" flag = None entry_point = self.sched.config.VARIANTS[self.variant] vm_def = self.vm_info["vm_def"] vm_def.dry_run = dry_run # Set heap limit heap_limit_kb = self.sched.config.HEAP_LIMIT stack_limit_kb = self.sched.config.STACK_LIMIT in_proc_iters = self.vm_info["n_iterations"] if not dry_run: self.sched.platform.collect_starting_throttle_counts() stdout, stderr, rc, envlog_filename, timed_out = \ vm_def.run_exec(entry_point, in_proc_iters, self.parameter, heap_limit_kb, stack_limit_kb, self.key, self.key_pexec_idx) if timed_out: measurements = self.empty_measurements instr_data = {} flag = "T" elif not dry_run: try: self.sched.platform.check_throttle_counts(self.sched.manifest) measurements = util.check_and_parse_execution_results( stdout, stderr, rc, self.sched.config, self.key, instrument=vm_def.instrument) flag = "C" except util.RerunExecution as e: subject = ("Benchmark needs to be re-run: %s (exec_idx=%s)" % (self.key, self.sched.manifest.next_exec_idx)) util.log_and_mail(mailer, warn, subject, e.message, manifest=self.sched.manifest, bypass_limiter=True) measurements = self.empty_measurements flag = "O" # i.e. still outstanding except util.ExecutionFailed as e: util.log_and_mail(mailer, error, "Benchmark failure: %s" % self.key, e.message, manifest=self.sched.manifest) measurements = self.empty_measurements flag = "E" # Collect instrumentation data if vm_def.instrument and flag == "C": instr_data = vm_def.get_instr_data() for k, v in instr_data.iteritems(): assert len(instr_data[k]) == in_proc_iters else: # The benchmark either failed, needs to be re-run, or had # instrumentation turned off. instr_data = {} else: measurements = self.empty_measurements instr_data = {} flag = "C" # We print the status *after* benchmarking, so that I/O cannot be # committed during benchmarking. In production, we will be rebooting # before the next execution, so we are grand. info("Finished '%s(%d)' (%s variant) under '%s'" % (self.benchmark, self.parameter, self.variant, self.vm_name)) # Move the environment log out of /tmp. # # We don't do this for re-runs (O) as the log for the re-run pexec is # the one we want. # # We don't do this for timeouts (T) because the wrapper script is # killed upon timeout, and thus doesn't get a chance to log the # environment. if not dry_run and flag not in ("O", "T"): key_exec_num = self.sched.manifest.completed_exec_counts[self.key] util.stash_envlog(envlog_filename, self.sched.config, self.sched.platform, self.key, key_exec_num) assert flag is not None return measurements, instr_data, flag
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()
def main(parser): args = parser.parse_args() if args.dump is not None: if not args.filename.endswith(".json.bz2"): usage(parser) else: Results.ok_to_instantiate = True results = Results(None, None, results_file=args.filename) text = results.dump(args.dump) # String data read in from JSON are unicode objects. This matters # for us as some data in the audit includes unicode characters. # If it does, a simple print no longer suffices if the system # locale is (e.g.) ASCII. In this case print will raise an # exception. The correct thing to do is to encode() the unicode to # the system locale. print(text.encode(locale.getpreferredencoding())) sys.exit(0) if not args.filename.endswith(".krun"): usage(parser) try: if os.stat(args.filename).st_size <= 0: util.fatal('Krun configuration file %s is empty.' % args.filename) except OSError: util.fatal('Krun configuration file %s does not exist.' % args.filename) config = Config(args.filename) if args.info: # Info mode doesn't run the experiment. # Just prints some metrics and exits. util.print_session_info(config) return manifest_filename = ManifestManager.get_filename(config) on_first_invocation = not (os.path.isfile(manifest_filename) and os.stat(manifest_filename).st_size > 0) log_file = config.log_filename() if on_first_invocation and os.path.exists(log_file): util.fatal("Log file '%s' already exists. " "Move the file away before running Krun." % log_file) attach_log_file(config, not on_first_invocation) debug("Krun invoked with arguments: %s" % sys.argv) mail_recipients = config.MAIL_TO if type(mail_recipients) is not list: util.fatal("MAIL_TO config should be a list") mailer = Mailer(mail_recipients, max_mails=config.MAX_MAILS) try: inner_main(mailer, on_first_invocation, config, args) except Exception as exn: error_info = sys.exc_info() subject = "Fatal Krun Exception" lines = ["Fatal Krun error: %s\n" % str(error_info[1])] for frame in traceback.format_tb(error_info[2]): lines.append(frame) msg = "".join(lines) util.log_and_mail(mailer, debug, subject, msg, bypass_limiter=True) raise exn
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 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 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()
def main(parser): args = parser.parse_args() if args.dump is not None: if not args.filename.endswith(".json.bz2"): usage(parser) else: Results.ok_to_instantiate = True results = Results(None, None, results_file=args.filename) text = results.dump(args.dump) # String data read in from JSON are unicode objects. This matters # for us as some data in the audit includes unicode characters. # If it does, a simple print no longer suffices if the system # locale is (e.g.) ASCII. In this case print will raise an # exception. The correct thing to do is to encode() the unicode to # the system locale. print(text.encode(locale.getpreferredencoding())) sys.exit(0) if not args.filename.endswith(".krun"): usage(parser) try: if os.stat(args.filename).st_size <= 0: util.fatal('Krun configuration file %s is empty.' % args.filename) except OSError: util.fatal('Krun configuration file %s does not exist.' % args.filename) config = Config(args.filename) if args.info: # Info mode doesn't run the experiment. # Just prints some metrics and exits. util.print_session_info(config) return manifest_filename = ManifestManager.get_filename(config) on_first_invocation = not (os.path.isfile(manifest_filename) and os.stat(manifest_filename).st_size > 0) log_file = config.log_filename() if on_first_invocation and os.path.exists(log_file): util.fatal("Log file '%s' already exists. " "Move the file away before running Krun." % log_file) attach_log_file(config, not on_first_invocation) debug("Krun invoked with arguments: %s" % sys.argv) mail_recipients = config.MAIL_TO if type(mail_recipients) is not list: util.fatal("MAIL_TO config should be a list") mailer = Mailer(mail_recipients, max_mails=config.MAX_MAILS) try: inner_main(mailer, on_first_invocation, config, args) except Exception as exn: error_info = sys.exc_info() subject = "Fatal Krun Exception" lines = ["Fatal Krun error: %s\n" % str(error_info[1])] for frame in traceback.format_tb(error_info[2]): lines.append(frame) msg = "".join(lines) util.log_and_mail(mailer, debug, subject, msg, bypass_limiter=True) raise exn