import logging import time import aexpect from avocado.utils import process from virttest import utils_test def run(test, params, env): """ Time drift test (mainly for Windows guests): 1) Log into a guest. 2) Take a time reading from the guest and host. 3) Run load on the guest and host. 4) Take a second time reading. 5) Stop the load and rest for a while. 6) Take a third time reading. 7) If the drift immediately after load is higher than a user- specified value (in %), fail. If the drift after the rest period is higher than a user-specified value, fail. :param test: QEMU test object. :param params: Dictionary with test parameters. :param env: Dictionary with the test environment. """ # Helper functions def set_cpu_affinity(pid, mask): """ Set the CPU affinity of all threads of the process with PID pid. Do this recursively for all child processes as well. :param pid: The process ID. :param mask: The CPU affinity mask. :return: A dict containing the previous mask for each thread. """ tids = process.system_output("ps -L --pid=%s -o lwp=" % pid, verbose=False, ignore_status=True).split() prev_masks = {} for tid in tids: prev_mask = process.system_output("taskset -p %s" % tid, verbose=False).split()[-1] prev_masks[tid] = prev_mask process.system("taskset -p %s %s" % (mask, tid), verbose=False) children = process.system_output("ps --ppid=%s -o pid=" % pid, verbose=False, ignore_status=True).split() for child in children: prev_masks.update(set_cpu_affinity(child, mask)) return prev_masks def restore_cpu_affinity(prev_masks): """ Restore the CPU affinity of several threads. :param prev_masks: A dict containing TIDs as keys and masks as values. """ for tid, mask in prev_masks.items(): process.system("taskset -p %s %s" % (mask, tid), verbose=False, ignore_status=True) vm = env.get_vm(params["main_vm"]) vm.verify_alive() boot_option_added = params.get("boot_option_added") boot_option_removed = params.get("boot_option_removed") if boot_option_added or boot_option_removed: utils_test.update_boot_option(vm, args_removed=boot_option_removed, args_added=boot_option_added) timeout = int(params.get("login_timeout", 360)) session = vm.wait_for_login(timeout=timeout) # Collect test parameters: # Command to run to get the current time time_command = params["time_command"] # Filter which should match a string to be passed to time.strptime() time_filter_re = params["time_filter_re"] # Time format for time.strptime() time_format = params["time_format"] guest_load_command = params["guest_load_command"] guest_load_stop_command = params["guest_load_stop_command"] host_load_command = params["host_load_command"] guest_load_instances = int(params.get("guest_load_instances", "1")) host_load_instances = int(params.get("host_load_instances", "0")) # CPU affinity mask for taskset cpu_mask = params.get("cpu_mask", "0xFF") load_duration = float(params.get("load_duration", "30")) rest_duration = float(params.get("rest_duration", "10")) drift_threshold = float(params.get("drift_threshold", "200")) drift_threshold_after_rest = float(params.get("drift_threshold_after_rest", "200")) test_duration = float(params.get("test_duration", "60")) interval_gettime = float(params.get("interval_gettime", "20")) guest_load_sessions = [] host_load_sessions = [] try: # Set the VM's CPU affinity prev_affinity = set_cpu_affinity(vm.get_shell_pid(), cpu_mask) try: # Open shell sessions with the guest logging.info("Starting load on guest...") for i in range(guest_load_instances): load_session = vm.login() # Set output func to None to stop it from being called so we # can change the callback function and the parameters it takes # with no problems load_session.set_output_func(None) load_session.set_output_params(()) load_session.set_output_prefix("(guest load %d) " % i) load_session.set_output_func(logging.debug) guest_load_sessions.append(load_session) # Get time before load # (ht stands for host time, gt stands for guest time) (ht0, gt0) = utils_test.get_time(session, time_command, time_filter_re, time_format) # Run some load on the guest for load_session in guest_load_sessions: load_session.sendline(guest_load_command) # Run some load on the host logging.info("Starting load on host...") for i in range(host_load_instances): load_cmd = aexpect.run_bg(host_load_command, output_func=logging.debug, output_prefix="(host load %d) " % i, timeout=0.5) host_load_sessions.append(load_cmd) # Set the CPU affinity of the load process pid = load_cmd.get_pid() set_cpu_affinity(pid, cpu_mask) # Sleep for a while (during load) logging.info("Sleeping for %s seconds...", load_duration) time.sleep(load_duration) start_time = time.time() while (time.time() - start_time) < test_duration: # Get time delta after load (ht1, gt1) = utils_test.get_time(session, time_command, time_filter_re, time_format) # Report results host_delta = ht1 - ht0 guest_delta = gt1 - gt0 drift = 100.0 * (host_delta - guest_delta) / host_delta logging.info("Host duration: %.2f", host_delta) logging.info("Guest duration: %.2f", guest_delta) logging.info("Drift: %.2f%%", drift) time.sleep(interval_gettime) finally: logging.info("Cleaning up...") # Restore the VM's CPU affinity restore_cpu_affinity(prev_affinity) # Stop the guest load if guest_load_stop_command: session.cmd_output(guest_load_stop_command) # Close all load shell sessions for load_session in guest_load_sessions: load_session.close() for load_session in host_load_sessions: load_session.close() # Sleep again (rest) logging.info("Sleeping for %s seconds...", rest_duration) time.sleep(rest_duration) # Get time after rest (ht2, gt2) = utils_test.get_time(session, time_command, time_filter_re, time_format) finally: session.close() # remove flags add for this test. if boot_option_added or boot_option_removed: utils_test.update_boot_option(vm, args_removed=boot_option_added, args_added=boot_option_removed) # Report results host_delta_total = ht2 - ht0 guest_delta_total = gt2 - gt0 drift_total = 100.0 * (host_delta_total - guest_delta_total) / host_delta logging.info("Total host duration including rest: %.2f", host_delta_total) logging.info( "Total guest duration including rest: %.2f", guest_delta_total) logging.info("Total drift after rest: %.2f%%", drift_total) # Fail the test if necessary if abs(drift) > drift_threshold: test.fail("Time drift too large: %.2f%%" % drift) if abs(drift_total) > drift_threshold_after_rest: test.fail("Time drift too large after rest period: %.2f%%" % drift_total)