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

[Michael Goldish <mgoldish@redhat.com>]

----- "Yolkfull Chow" <yzhou@redhat.com> wrote:

> On Mon, Jul 20, 2009 at 06:07:19PM +0300, 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()))
> > +
> > +    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))
> 
> Hi Machael, this test looks good for me, but I have a little
> suggestion:
> Why not write a common function to get guest time which really save
> many
> duplicate codes here? It could has four parameters and I would also
> help
> write it for you :-)
> 
> def get_guest_time(session, time_command, filter_re, format):
>     session.sendline(time_command)
>     (match, s) = session.read_up_to_prompt()
>     s = re.findall(filter_re, s)[0]
>     curr_time = time.mktime(time.strptime(s, format))
>     return curr_time

Thanks, makes perfect sense. The code seemed quite short already so I
didn't bother, but it should save quite a few lines.

While we're at it, maybe the function should return the host time as well:
(host_time_0, guest_time_0) = get_current_time(...)

Anyway, if it's OK with everyone, I think I'll do it in an additional
commit rather than re-post this one, because even a small change like
that needs to undergo some minimal testing.

> > +
> > +        # 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()
> > -- 
> > 1.5.4.1
> > 
> > _______________________________________________
> > Autotest mailing list
> > Autotest@test.kernel.org
> > http://test.kernel.org/cgi-bin/mailman/listinfo/autotest