Re: [Autotest] [KVM-AUTOTEST PATCH 12/17] KVM test: add simple timedrift test (mainly for Windows)

[Dor Laor <dlaor@redhat.com>]

On 07/20/2009 06:07 PM, Michael Goldish wrote:
> 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.
>
> Signed-off-by: Michael Goldish<mgoldish@redhat.com>
> ---
>   client/tests/kvm/kvm.py       |    1 +
>   client/tests/kvm/kvm_tests.py |  161 ++++++++++++++++++++++++++++++++++++++++-
>   2 files changed, 160 insertions(+), 2 deletions(-)
>
> diff --git a/client/tests/kvm/kvm.py b/client/tests/kvm/kvm.py
> index b18b643..070e463 100644
> --- a/client/tests/kvm/kvm.py
> +++ b/client/tests/kvm/kvm.py
> @@ -55,6 +55,7 @@ class kvm(test.test):
>                   "kvm_install":  test_routine("kvm_install", "run_kvm_install"),
>                   "linux_s3":     test_routine("kvm_tests", "run_linux_s3"),
>                   "stress_boot":  test_routine("kvm_tests", "run_stress_boot"),
> +                "timedrift":    test_routine("kvm_tests", "run_timedrift"),
>                   }
>
>           # Make it possible to import modules from the test's bindir
> diff --git a/client/tests/kvm/kvm_tests.py b/client/tests/kvm/kvm_tests.py
> index 5991aed..ca0b8c0 100644
> --- a/client/tests/kvm/kvm_tests.py
> +++ b/client/tests/kvm/kvm_tests.py
> @@ -1,4 +1,4 @@
> -import time, os, logging
> +import time, os, logging, re, commands
>   from autotest_lib.client.common_lib import utils, error
>   import kvm_utils, kvm_subprocess, ppm_utils, scan_results
>
> @@ -529,7 +529,6 @@ def run_stress_boot(tests, params, env):
>       """
>       # boot the first vm
>       vm = kvm_utils.env_get_vm(env, params.get("main_vm"))
> -
>       if not vm:
>           raise error.TestError("VM object not found in environment")
>       if not vm.is_alive():
> @@ -586,3 +585,161 @@ def run_stress_boot(tests, params, env):
>           for se in sessions:
>               se.close()
>           logging.info("Total number booted: %d" % (num -1))
> +
> +
> +def run_timedrift(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: KVM test object.
> +    @param params: Dictionary with test parameters.
> +    @param env: Dictionary with the test environment.
> +    """
> +    vm = kvm_utils.env_get_vm(env, params.get("main_vm"))
> +    if not vm:
> +        raise error.TestError("VM object not found in environment")
> +    if not vm.is_alive():
> +        raise error.TestError("VM seems to be dead; Test requires a living VM")
> +
> +    logging.info("Waiting for guest to be up...")
> +
> +    session = kvm_utils.wait_for(vm.ssh_login, 240, 0, 2)
> +    if not session:
> +        raise error.TestFail("Could not log into guest")
> +
> +    logging.info("Logged in")
> +
> +    # Collect test parameters:
> +    # Command to run to get the current time
> +    time_command = params.get("time_command")
> +    # Filter which should match a string to be passed to time.strptime()
> +    time_filter_re = params.get("time_filter_re")
> +    # Time format for time.strptime()
> +    time_format = params.get("time_format")
> +    guest_load_command = params.get("guest_load_command")
> +    guest_load_stop_command = params.get("guest_load_stop_command")
> +    host_load_command = params.get("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"))
> +
> +    guest_load_sessions = []
> +    host_load_sessions = []
> +
> +    # Remember the VM's previous CPU affinity
> +    prev_cpu_mask = commands.getoutput("taskset -p %s" % vm.get_pid())
> +    prev_cpu_mask = prev_cpu_mask.split()[-1]
> +    # Set the VM's CPU affinity
> +    commands.getoutput("taskset -p %s %s" % (cpu_mask, vm.get_pid()))


Need to handle guest smp case where we want to pin the guest to several 
cpus.

Cheers for the test!


> +
> +    try:
> +        # Get time before load
> +        host_time_0 = time.time()
> +        session.sendline(time_command)
> +        (match, s) = session.read_up_to_prompt()
> +        s = re.findall(time_filter_re, s)[0]
> +        guest_time_0 = time.mktime(time.strptime(s, time_format))
> +
> +        # Run some load on the guest
> +        logging.info("Starting load on guest...")
> +        for i in range(guest_load_instances):
> +            load_session = vm.ssh_login()
> +            if not load_session:
> +                raise error.TestFail("Could not log into guest")
> +            load_session.set_output_prefix("(guest load %d) " % i)
> +            load_session.set_output_func(logging.debug)
> +            load_session.sendline(guest_load_command)
> +            guest_load_sessions.append(load_session)
> +
> +        # Run some load on the host
> +        logging.info("Starting load on host...")
> +        for i in range(host_load_instances):
> +            host_load_sessions.append(
> +                kvm_subprocess.run_bg(host_load_command,
> +                                      output_func=logging.debug,
> +                                      output_prefix="(host load %d) " % i,
> +                                      timeout=0.5))
> +            # Set the CPU affinity of the shell running the load process
> +            pid = host_load_sessions[-1].get_shell_pid()
> +            commands.getoutput("taskset -p %s %s" % (cpu_mask, pid))
> +            # Try setting the CPU affinity of the load process itself
> +            pid = host_load_sessions[-1].get_pid()
> +            if pid:
> +                commands.getoutput("taskset -p %s %s" % (cpu_mask, pid))
> +
> +        # Sleep for a while (during load)
> +        logging.info("Sleeping for %s seconds..." % load_duration)
> +        time.sleep(load_duration)
> +
> +        # Get time delta after load
> +        host_time_1 = time.time()
> +        session.sendline(time_command)
> +        (match, s) = session.read_up_to_prompt()
> +        s = re.findall(time_filter_re, s)[0]
> +        guest_time_1 = time.mktime(time.strptime(s, time_format))
> +
> +        # Report results
> +        host_delta = host_time_1 - host_time_0
> +        guest_delta = guest_time_1 - guest_time_0
> +        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)
> +
> +    finally:
> +        logging.info("Cleaning up...")
> +        # Restore the VM's CPU affinity
> +        commands.getoutput("taskset -p %s %s" % (prev_cpu_mask, vm.get_pid()))
> +        # Stop the guest load
> +        if guest_load_stop_command:
> +            session.get_command_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
> +    host_time_2 = time.time()
> +    session.sendline(time_command)
> +    (match, s) = session.read_up_to_prompt()
> +    s = re.findall(time_filter_re, s)[0]
> +    guest_time_2 = time.mktime(time.strptime(s, time_format))
> +
> +    # Report results
> +    host_delta_total = host_time_2 - host_time_0
> +    guest_delta_total = guest_time_2 - guest_time_0
> +    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 drift>  drift_threshold:
> +        raise error.TestFail("Time drift too large: %.2f%%" % drift)
> +    if drift>  drift_threshold_after_rest:
> +        raise error.TestFail("Time drift too large after rest period: %.2f%%"
> +                             % drift_total)
> +
> +    session.close()