Re: [Autotest] [KVM-AUTOTEST PATCH 15/17] KVM test: add timedrift test to kvm_tests.cfg.sample

Re: [Autotest] [KVM-AUTOTEST PATCH 15/17] KVM test: add timedrift test to kvm_tests.cfg.sample

[Michael Goldish]

----- "Dor Laor" <dlaor@redhat.com> wrote:

> On 07/20/2009 06:07 PM, Michael Goldish wrote:
> > Currently the test will only run on Windows.
> > It should be able to run on Linux just as well, but if I understand
> correctly,
> > testing time drift on Linux is less interesting.
> 
> Linux is interesting too. The problem is more visible on windows
> since
> it uses 1000hz frequency when it plays multimedia. It makes timer irq
> injection harder.

If I understand correctly, most Linuxes don't use RTC at all (please
correct me if I'm wrong). This means there's no point in testing
time drift on Linux, because even if there's any drift, it won't get
corrected by -rtc-td-hack. And it's pretty hard to get a drift on
RHEL-3.9 for example -- at least it was very hard for me.

> Does the test fail without the rtc-td-hack?

The problem with the test is that it's hard to decide on the drift
thresholds for failure, because the more load you use, the larger the
drift you get.
-rtc-td-hack makes it harder to get a drift -- you need to add more load
in order to get the same drift.
However, in my experiments, when I got a drift, it was not corrected when
the load stopped. If I get 5 seconds of drift during load, and then I
stop the load and wait, the drift remains 5 seconds, which makes me think
I may be doing something wrong. I never got to see the cool fast rotating
clock either.
Another weird thing I noticed was that the drift was much larger when the
VM and load were NOT pinned to a single CPU. It could cause a leap from 5%
to 30%. (my office desktop has 2 CPUs.)
I used Vista with kvm-85 I think. I tried both video load (VLC) and dir /s.
Even if I did something wrong, I hope the test itself is OK, because its
behavior is completely configurable.

> >
> > Also make some tiny cosmetic changes (spacing), and move the
> stress_boot test
> > before the shutdown test (shutdown should be last).
> >
> > Signed-off-by: Michael Goldish<mgoldish@redhat.com>
> > ---
> >   client/tests/kvm/kvm_tests.cfg.sample |   46
> ++++++++++++++++++++++++++------
> >   1 files changed, 37 insertions(+), 9 deletions(-)
> >
> > diff --git a/client/tests/kvm/kvm_tests.cfg.sample
> b/client/tests/kvm/kvm_tests.cfg.sample
> > index 1288952..2d75a66 100644
> > --- a/client/tests/kvm/kvm_tests.cfg.sample
> > +++ b/client/tests/kvm/kvm_tests.cfg.sample
> > @@ -92,20 +92,33 @@ variants:
> >                   test_name = disktest
> >                   test_control_file = disktest.control
> >
> > -    - linux_s3:      install setup
> > +    - linux_s3:     install setup
> >           type = linux_s3
> >
> > -    - shutdown:      install setup
> > +    - timedrift:    install setup
> > +        type = timedrift
> > +        extra_params += " -rtc-td-hack"
> > +        # Pin the VM and host load to CPU #0
> > +        cpu_mask = 0x1
> > +        # Set the load and rest durations
> > +        load_duration = 20
> > +        rest_duration = 20
> > +        # Fail if the drift after load is higher than 50%
> > +        drift_threshold = 50
> > +        # Fail if the drift after the rest period is higher than
> 10%
> > +        drift_threshold_after_rest = 10
> > +
> > +    - stress_boot:  install setup
> > +        type = stress_boot
> > +        max_vms = 5
> > +        alive_test_cmd = ps aux
> > +
> > +    - shutdown:     install setup
> >           type = shutdown
> >           kill_vm = yes
> >           kill_vm_gracefully = no
> >
> >
> > -    - stress_boot:
> > -        type = stress_boot
> > -        max_vms = 5
> > -        alive_test_cmd = ps aux
> > -
> >   # NICs
> >   variants:
> >       - @rtl8139:
> > @@ -121,6 +134,7 @@ variants:
> >   variants:
> >       # Linux section
> >       - @Linux:
> > +        no timedrift
> >           cmd_shutdown = shutdown -h now
> >           cmd_reboot = shutdown -r now
> >           ssh_status_test_command = echo $?
> > @@ -303,8 +317,6 @@ variants:
> >                              
> md5sum=bf4635e4a4bd3b43838e72bc8c329d55
> >                              
> md5sum_1m=18ecd37b639109f1b2af05cfb57dfeaf
> >
> > -
> > -
> >       # Windows section
> >       - @Windows:
> >           no autotest
> > @@ -318,6 +330,21 @@ variants:
> >               migration_test_command = ver&&  vol
> >           stress_boot:
> >               alive_test_cmd = systeminfo
> > +        timedrift:
> > +            # For this to work, the ISO should contain vlc
> (vlc.exe) and a video (ED_1024.avi)
> > +            cdrom = windows/vlc.iso
> > +            time_command = "echo TIME: %date% %time%"
> > +            time_filter_re = "(?<=TIME: \w\w\w ).{19}(?=\.\d\d)"
> > +            time_format = "%m/%d/%Y %H:%M:%S"
> > +            guest_load_command = 'cmd /c "d:\vlc -f --loop
> --no-qt-privacy-ask --no-qt-system-tray d:\ED_1024.avi"'
> > +            # Alternative guest load:
> > +            #guest_load_command = "(dir /s&&  dir /s&&  dir /s&& 
> dir /s)>  nul"
> > +            guest_load_stop_command = "taskkill /F /IM vlc.exe"
> > +            guest_load_instances = 2
> > +            host_load_command = "bzip2 -c --best /dev/urandom> 
> /dev/null"
> > +            # Alternative host load:
> > +            #host_load_command = "dd if=/dev/urandom of=/dev/null"
> > +            host_load_instances = 8
> >
> >           variants:
> >               - Win2000:
> > @@ -582,5 +609,6 @@ variants:
> >           only
> qcow2.*ide.*default.*up.*Ubuntu-8.10-server.*(autotest.sleeptest)
> >           only rtl8139
> >
> > +
> >   # Choose your test list
> >   only fc8_quick

Re: [Autotest] [KVM-AUTOTEST PATCH 15/17] KVM test: add timedrift test to kvm_tests.cfg.sample

[Marcelo Tosatti]

On Tue, Jul 21, 2009 at 06:41:09AM -0400, Michael Goldish wrote:
> 
> ----- "Dor Laor" <dlaor@redhat.com> wrote:
> 
> > On 07/20/2009 06:07 PM, Michael Goldish wrote:
> > > Currently the test will only run on Windows.
> > > It should be able to run on Linux just as well, but if I understand
> > correctly,
> > > testing time drift on Linux is less interesting.
> > 
> > Linux is interesting too. The problem is more visible on windows
> > since
> > it uses 1000hz frequency when it plays multimedia. It makes timer irq
> > injection harder.
> 
> If I understand correctly, most Linuxes don't use RTC at all (please
> correct me if I'm wrong). This means there's no point in testing
> time drift on Linux, because even if there's any drift, it won't get
> corrected by -rtc-td-hack. And it's pretty hard to get a drift on
> RHEL-3.9 for example -- at least it was very hard for me.

https://bugzilla.redhat.com/show_bug.cgi?id=507834 for example.

Also we'd like to test different clocks. For example with RHEL5 you can
choose, via a kernel boot parameter the following clocks:

        clock=          [BUGS=IA-32, HW] gettimeofday clocksource override.
                        [Deprecated]
                        Forces specified clocksource (if avaliable) to be used
                        when calculating gettimeofday(). If specified
                        clocksource is not avalible, it defaults to PIT.
                        Format: { pit | tsc | cyclone | pmtmr }

>From Documentation/kernel-parameters.txt file of the 2.6.18 kernel.

Passing options to the guest kernel is also required for other things,
and perhaps there should be a generic mechanism to do it.

> > Does the test fail without the rtc-td-hack?
> 
> The problem with the test is that it's hard to decide on the drift
> thresholds for failure, because the more load you use, the larger the
> drift you get.
> -rtc-td-hack makes it harder to get a drift -- you need to add more load
> in order to get the same drift.
> However, in my experiments, when I got a drift, it was not corrected when
> the load stopped. If I get 5 seconds of drift during load, and then I
> stop the load and wait, the drift remains 5 seconds, which makes me think
> I may be doing something wrong. I never got to see the cool fast rotating
> clock either.
> Another weird thing I noticed was that the drift was much larger when the
> VM and load were NOT pinned to a single CPU. It could cause a leap from 5%
> to 30%. (my office desktop has 2 CPUs.)
> I used Vista with kvm-85 I think. I tried both video load (VLC) and dir /s.
> Even if I did something wrong, I hope the test itself is OK, because its
> behavior is completely configurable.
> 
> > >
> > > Also make some tiny cosmetic changes (spacing), and move the
> > stress_boot test
> > > before the shutdown test (shutdown should be last).
> > >
> > > Signed-off-by: Michael Goldish<mgoldish@redhat.com>
> > > ---
> > >   client/tests/kvm/kvm_tests.cfg.sample |   46
> > ++++++++++++++++++++++++++------
> > >   1 files changed, 37 insertions(+), 9 deletions(-)
> > >
> > > diff --git a/client/tests/kvm/kvm_tests.cfg.sample
> > b/client/tests/kvm/kvm_tests.cfg.sample
> > > index 1288952..2d75a66 100644
> > > --- a/client/tests/kvm/kvm_tests.cfg.sample
> > > +++ b/client/tests/kvm/kvm_tests.cfg.sample
> > > @@ -92,20 +92,33 @@ variants:
> > >                   test_name = disktest
> > >                   test_control_file = disktest.control
> > >
> > > -    - linux_s3:      install setup
> > > +    - linux_s3:     install setup
> > >           type = linux_s3
> > >
> > > -    - shutdown:      install setup
> > > +    - timedrift:    install setup
> > > +        type = timedrift
> > > +        extra_params += " -rtc-td-hack"
> > > +        # Pin the VM and host load to CPU #0
> > > +        cpu_mask = 0x1
> > > +        # Set the load and rest durations
> > > +        load_duration = 20
> > > +        rest_duration = 20
> > > +        # Fail if the drift after load is higher than 50%
> > > +        drift_threshold = 50
> > > +        # Fail if the drift after the rest period is higher than
> > 10%
> > > +        drift_threshold_after_rest = 10
> > > +
> > > +    - stress_boot:  install setup
> > > +        type = stress_boot
> > > +        max_vms = 5
> > > +        alive_test_cmd = ps aux
> > > +
> > > +    - shutdown:     install setup
> > >           type = shutdown
> > >           kill_vm = yes
> > >           kill_vm_gracefully = no
> > >
> > >
> > > -    - stress_boot:
> > > -        type = stress_boot
> > > -        max_vms = 5
> > > -        alive_test_cmd = ps aux
> > > -
> > >   # NICs
> > >   variants:
> > >       - @rtl8139:
> > > @@ -121,6 +134,7 @@ variants:
> > >   variants:
> > >       # Linux section
> > >       - @Linux:
> > > +        no timedrift
> > >           cmd_shutdown = shutdown -h now
> > >           cmd_reboot = shutdown -r now
> > >           ssh_status_test_command = echo $?
> > > @@ -303,8 +317,6 @@ variants:
> > >                              
> > md5sum=bf4635e4a4bd3b43838e72bc8c329d55
> > >                              
> > md5sum_1m=18ecd37b639109f1b2af05cfb57dfeaf
> > >
> > > -
> > > -
> > >       # Windows section
> > >       - @Windows:
> > >           no autotest
> > > @@ -318,6 +330,21 @@ variants:
> > >               migration_test_command = ver&&  vol
> > >           stress_boot:
> > >               alive_test_cmd = systeminfo
> > > +        timedrift:
> > > +            # For this to work, the ISO should contain vlc
> > (vlc.exe) and a video (ED_1024.avi)
> > > +            cdrom = windows/vlc.iso
> > > +            time_command = "echo TIME: %date% %time%"
> > > +            time_filter_re = "(?<=TIME: \w\w\w ).{19}(?=\.\d\d)"
> > > +            time_format = "%m/%d/%Y %H:%M:%S"
> > > +            guest_load_command = 'cmd /c "d:\vlc -f --loop
> > --no-qt-privacy-ask --no-qt-system-tray d:\ED_1024.avi"'
> > > +            # Alternative guest load:
> > > +            #guest_load_command = "(dir /s&&  dir /s&&  dir /s&& 
> > dir /s)>  nul"
> > > +            guest_load_stop_command = "taskkill /F /IM vlc.exe"
> > > +            guest_load_instances = 2
> > > +            host_load_command = "bzip2 -c --best /dev/urandom> 
> > /dev/null"
> > > +            # Alternative host load:
> > > +            #host_load_command = "dd if=/dev/urandom of=/dev/null"
> > > +            host_load_instances = 8
> > >
> > >           variants:
> > >               - Win2000:
> > > @@ -582,5 +609,6 @@ variants:
> > >           only
> > qcow2.*ide.*default.*up.*Ubuntu-8.10-server.*(autotest.sleeptest)
> > >           only rtl8139
> > >
> > > +
> > >   # Choose your test list
> > >   only fc8_quick
> --
> To unsubscribe from this list: send the line "unsubscribe kvm" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

[KVM-AUTOTEST PATCH 0/17] kvm_subprocess, guestwizard improvements, timedrift and other small things

[Michael Goldish]

The following patch series includes all the patches I sent that have not been
applied yet. They are all rebased against the latest HEAD (including the recent
UUID patch).

Some new things are included too, such as a simple time drift test for Windows.

Sorry for posting so many commits at once.

[KVM-AUTOTEST PATCH 05/17] Remove kvm_spawn and run_bg() from kvm_utils.py.

[Michael Goldish]

These are now provided by kvm_subprocess.py.

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/tests/kvm/kvm_utils.py |  477 +----------------------------------------
 1 files changed, 2 insertions(+), 475 deletions(-)

diff --git a/client/tests/kvm/kvm_utils.py b/client/tests/kvm/kvm_utils.py
index fb587c5..9391874 100644
--- a/client/tests/kvm/kvm_utils.py
+++ b/client/tests/kvm/kvm_utils.py
@@ -227,390 +227,8 @@ def check_kvm_source_dir(source_dir):
         raise error.TestError("Unknown source dir layout, cannot proceed.")
 
 
-# The following are a class and functions used for SSH, SCP and Telnet
-# communication with guests.
-
-class kvm_spawn:
-    """
-    This class is used for spawning and controlling a child process.
-    """
-
-    def __init__(self, command, linesep="\n"):
-        """
-        Initialize the class and run command as a child process.
-
-        @param command: Command that will be run.
-        @param linesep: Line separator for the given platform.
-        """
-        self.exitstatus = None
-        self.linesep = linesep
-        (pid, fd) = pty.fork()
-        if pid == 0:
-            os.execv("/bin/sh", ["/bin/sh", "-c", command])
-        else:
-            self.pid = pid
-            self.fd = fd
-
-
-    def set_linesep(self, linesep):
-        """
-        Sets the line separator string (usually "\\n").
-
-        @param linesep: Line separator character.
-        """
-        self.linesep = linesep
-
-
-    def is_responsive(self, timeout=5.0):
-        """
-        Return True if the session is responsive.
-
-        Send a newline to the child process (e.g. SSH or Telnet) and read some
-        output using read_nonblocking.
-        If all is OK, some output should be available (e.g. the shell prompt).
-        In that case return True. Otherwise return False.
-
-        @param timeout: Timeout that will happen before we consider the
-                process unresponsive
-        """
-        self.read_nonblocking(timeout=0.1)
-        self.sendline()
-        output = self.read_nonblocking(timeout=timeout)
-        if output.strip():
-            return True
-        return False
-
-
-    def poll(self):
-        """
-        If the process exited, return its exit status. Otherwise return None.
-        The exit status is stored for use in subsequent calls.
-        """
-        if self.exitstatus != None:
-            return self.exitstatus
-        pid, status = os.waitpid(self.pid, os.WNOHANG)
-        if pid:
-            self.exitstatus = os.WEXITSTATUS(status)
-            return self.exitstatus
-        else:
-            return None
-
-
-    def close(self):
-        """
-        Close the session (close the process filedescriptors and kills the
-        process ID), and return the exit status.
-        """
-        try:
-            os.close(self.fd)
-            os.kill(self.pid, signal.SIGTERM)
-        except OSError:
-            pass
-        return self.poll()
-
-
-    def sendline(self, str=""):
-        """
-        Sends a string followed by a line separator to the child process.
-
-        @param str: String that will be sent to the child process.
-        """
-        try:
-            os.write(self.fd, str + self.linesep)
-        except OSError:
-            pass
-
-
-    def read_nonblocking(self, timeout=1.0):
-        """
-        Read from child until there is nothing to read for timeout seconds.
-
-        @param timeout: Time (seconds) of wait before we give up reading from
-                the child process.
-        """
-        data = ""
-        while True:
-            r, w, x = select.select([self.fd], [], [], timeout)
-            if self.fd in r:
-                try:
-                    data += os.read(self.fd, 1024)
-                except OSError:
-                    return data
-            else:
-                return data
-
-
-    def match_patterns(self, str, patterns):
-        """
-        Match str against a list of patterns.
-
-        Return the index of the first pattern that matches a substring of str.
-        None and empty strings in patterns are ignored.
-        If no match is found, return None.
-
-        @param patterns: List of strings (regular expression patterns).
-        """
-        for i in range(len(patterns)):
-            if not patterns[i]:
-                continue
-            exp = re.compile(patterns[i])
-            if exp.search(str):
-                return i
-
-
-    def read_until_output_matches(self, patterns, filter=lambda(x):x,
-                                  timeout=30.0, internal_timeout=1.0,
-                                  print_func=None):
-        """
-        Read using read_nonblocking until a match is found using match_patterns,
-        or until timeout expires. Before attempting to search for a match, the
-        data is filtered using the filter function provided.
-
-        @brief: Read from child using read_nonblocking until a pattern
-                matches.
-        @param patterns: List of strings (regular expression patterns)
-        @param filter: Function to apply to the data read from the child before
-                attempting to match it against the patterns (should take and
-                return a string)
-        @param timeout: The duration (in seconds) to wait until a match is
-                found
-        @param internal_timeout: The timeout to pass to read_nonblocking
-        @param print_func: A function to be used to print the data being read
-                (should take a string parameter)
-        @return: Tuple containing the match index (or None if no match was
-                found) and the data read so far.
-        """
-        match = None
-        data = ""
-
-        end_time = time.time() + timeout
-        while time.time() < end_time:
-            # Read data from child
-            newdata = self.read_nonblocking(internal_timeout)
-            # Print it if necessary
-            if print_func and newdata:
-                map(print_func, newdata.splitlines())
-            data += newdata
-
-            done = False
-            # Look for patterns
-            match = self.match_patterns(filter(data), patterns)
-            if match != None:
-                done = True
-            # Check if child has died
-            if self.poll() != None:
-                logging.debug("Process terminated with status %d", self.poll())
-                done = True
-            # Are we done?
-            if done: break
-
-        # Print some debugging info
-        if match == None and self.poll() != 0:
-            logging.debug("Timeout elapsed or process terminated. Output: %s",
-                          format_str_for_message(data.strip()))
-
-        return (match, data)
-
-
-    def get_last_word(self, str):
-        """
-        Return the last word in str.
-
-        @param str: String that will be analyzed.
-        """
-        if str:
-            return str.split()[-1]
-        else:
-            return ""
-
-
-    def get_last_line(self, str):
-        """
-        Return the last non-empty line in str.
-
-        @param str: String that will be analyzed.
-        """
-        last_line = ""
-        for line in str.splitlines():
-            if line != "":
-                last_line = line
-        return last_line
-
-
-    def read_until_last_word_matches(self, patterns, timeout=30.0,
-                                     internal_timeout=1.0, print_func=None):
-        """
-        Read using read_nonblocking until the last word of the output matches
-        one of the patterns (using match_patterns), or until timeout expires.
-
-        @param patterns: A list of strings (regular expression patterns)
-        @param timeout: The duration (in seconds) to wait until a match is
-                found
-        @param internal_timeout: The timeout to pass to read_nonblocking
-        @param print_func: A function to be used to print the data being read
-                (should take a string parameter)
-        @return: A tuple containing the match index (or None if no match was
-                found) and the data read so far.
-        """
-        return self.read_until_output_matches(patterns, self.get_last_word,
-                                              timeout, internal_timeout,
-                                              print_func)
-
-
-    def read_until_last_line_matches(self, patterns, timeout=30.0,
-                                     internal_timeout=1.0, print_func=None):
-        """
-        Read using read_nonblocking until the last non-empty line of the output
-        matches one of the patterns (using match_patterns), or until timeout
-        expires. Return a tuple containing the match index (or None if no match
-        was found) and the data read so far.
-
-        @brief: Read using read_nonblocking until the last non-empty line
-                matches a pattern.
-
-        @param patterns: A list of strings (regular expression patterns)
-        @param timeout: The duration (in seconds) to wait until a match is
-                found
-        @param internal_timeout: The timeout to pass to read_nonblocking
-        @param print_func: A function to be used to print the data being read
-                (should take a string parameter)
-        """
-        return self.read_until_output_matches(patterns, self.get_last_line,
-                                              timeout, internal_timeout,
-                                              print_func)
-
-
-    def set_prompt(self, prompt):
-        """
-        Set the prompt attribute for later use by read_up_to_prompt.
-
-        @param: String that describes the prompt contents.
-        """
-        self.prompt = prompt
-
-
-    def read_up_to_prompt(self, timeout=30.0, internal_timeout=1.0,
-                          print_func=None):
-        """
-        Read using read_nonblocking until the last non-empty line of the output
-        matches the prompt regular expression set by set_prompt, or until
-        timeout expires.
-
-        @brief: Read using read_nonblocking until the last non-empty line
-                matches the prompt.
-
-        @param timeout: The duration (in seconds) to wait until a match is
-                found
-        @param internal_timeout: The timeout to pass to read_nonblocking
-        @param print_func: A function to be used to print the data being
-                read (should take a string parameter)
-
-        @return: A tuple containing True/False indicating whether the prompt
-                was found, and the data read so far.
-        """
-        (match, output) = self.read_until_last_line_matches([self.prompt],
-                                                            timeout,
-                                                            internal_timeout,
-                                                            print_func)
-        if match == None:
-            return (False, output)
-        else:
-            return (True, output)
-
-
-    def set_status_test_command(self, status_test_command):
-        """
-        Set the command to be sent in order to get the last exit status.
-
-        @param status_test_command: Command that will be sent to get the last
-                exit status.
-        """
-        self.status_test_command = status_test_command
-
-
-    def get_command_status_output(self, command, timeout=30.0,
-                                  internal_timeout=1.0, print_func=None):
-        """
-        Send a command and return its exit status and output.
-
-        @param command: Command to send
-        @param timeout: The duration (in seconds) to wait until a match is
-                found
-        @param internal_timeout: The timeout to pass to read_nonblocking
-        @param print_func: A function to be used to print the data being read
-                (should take a string parameter)
-
-        @return: A tuple (status, output) where status is the exit status or
-                None if no exit status is available (e.g. timeout elapsed), and
-                output is the output of command.
-        """
-        # Print some debugging info
-        logging.debug("Sending command: %s" % command)
-
-        # Read everything that's waiting to be read
-        self.read_nonblocking(0.1)
-
-        # Send the command and get its output
-        self.sendline(command)
-        (match, output) = self.read_up_to_prompt(timeout, internal_timeout,
-                                                 print_func)
-        if not match:
-            return (None, "\n".join(output.splitlines()[1:]))
-        output = "\n".join(output.splitlines()[1:-1])
-
-        # Send the 'echo ...' command to get the last exit status
-        self.sendline(self.status_test_command)
-        (match, status) = self.read_up_to_prompt(10.0, internal_timeout)
-        if not match:
-            return (None, output)
-        status = int("\n".join(status.splitlines()[1:-1]).strip())
-
-        # Print some debugging info
-        if status != 0:
-            logging.debug("Command failed; status: %d, output:%s", status,
-                          format_str_for_message(output.strip()))
-
-        return (status, output)
-
-
-    def get_command_status(self, command, timeout=30.0, internal_timeout=1.0,
-                           print_func=None):
-        """
-        Send a command and return its exit status.
-
-        @param command: Command to send
-        @param timeout: The duration (in seconds) to wait until a match is
-                found
-        @param internal_timeout: The timeout to pass to read_nonblocking
-        @param print_func: A function to be used to print the data being read
-                (should take a string parameter)
-
-        @return: Exit status or None if no exit status is available (e.g.
-                timeout elapsed).
-        """
-        (status, output) = self.get_command_status_output(command, timeout,
-                                                          internal_timeout,
-                                                          print_func)
-        return status
-
-
-    def get_command_output(self, command, timeout=30.0, internal_timeout=1.0,
-                           print_func=None):
-        """
-        Send a command and return its output.
-
-        @param command: Command to send
-        @param timeout: The duration (in seconds) to wait until a match is
-                found
-        @param internal_timeout: The timeout to pass to read_nonblocking
-        @param print_func: A function to be used to print the data being read
-                (should take a string parameter)
-        """
-        (status, output) = self.get_command_status_output(command, timeout,
-                                                          internal_timeout,
-                                                          print_func)
-        return output
-
+# The following are functions used for SSH, SCP and Telnet communication with
+# guests.
 
 def remote_login(command, password, prompt, linesep="\n", timeout=10):
     """
@@ -810,97 +428,6 @@ def telnet(host, port, username, password, prompt, timeout=10):
     return remote_login(command, password, prompt, "\r\n", timeout)
 
 
-# The following are functions used for running commands in the background.
-
-def track_process(sub, status_output=None, term_func=None, stdout_func=None,
-                  prefix=""):
-    """
-    Read lines from the stdout pipe of the subprocess. Pass each line to
-    stdout_func prefixed by prefix. Place the lines in status_output[1].
-    When the subprocess exits, call term_func. Place the exit status in
-    status_output[0].
-
-    @brief Track a subprocess and report its output and termination.
-
-    @param sub: An object returned by subprocess.Popen
-    @param status_output: A list in which the exit status and output are to be
-            stored.
-    @param term_func: A function to call when the process terminates
-            (should take no parameters)
-    @param stdout_func: A function to call with each line of output from the
-            subprocess (should take a string parameter)
-
-    @param prefix -- a string to pre-pend to each line of the output, before
-            passing it to stdout_func
-    """
-    while True:
-        # Read a single line from stdout
-        text = sub.stdout.readline()
-        # If the subprocess exited...
-        if text == "":
-            # Get exit code
-            status = sub.wait()
-            # Report it
-            if status_output:
-                status_output[0] = status
-            # Call term_func
-            if term_func:
-                term_func()
-            return
-        # Report the text
-        if status_output:
-            status_output[1] += text
-        # Call stdout_func with the returned text
-        if stdout_func:
-            text = prefix + text.strip()
-            # We need to sanitize the text before passing it to the logging
-            # system
-            text = text.decode('utf-8', 'replace')
-            stdout_func(text)
-
-
-def run_bg(command, term_func=None, stdout_func=None, prefix="", timeout=1.0):
-    """
-    Run command as a subprocess. Call stdout_func with each line of output from
-    the subprocess (prefixed by prefix). Call term_func when the subprocess
-    terminates. If timeout expires and the subprocess is still running, return.
-
-    @brief: Run a subprocess in the background and collect its output and
-            exit status.
-
-    @param command: The shell command to execute
-    @param term_func: A function to call when the process terminates
-            (should take no parameters)
-    @param stdout_func: A function to call with each line of output from
-            the subprocess (should take a string parameter)
-    @param prefix: A string to pre-pend to each line of the output, before
-            passing it to stdout_func
-    @param timeout: Time duration (in seconds) to wait for the subprocess to
-            terminate before returning
-
-    @return: A 3-tuple containing the exit status (None if the subprocess is
-            still running), the PID of the subprocess (None if the subprocess
-            terminated), and the output collected so far.
-    """
-    # Start the process
-    sub = subprocess.Popen(command, shell=True, stdout=subprocess.PIPE,
-                           stderr=subprocess.STDOUT)
-    # Start the tracking thread
-    status_output = [None, ""]
-    thread.start_new_thread(track_process, (sub, status_output, term_func,
-                                            stdout_func, prefix))
-    # Wait up to timeout secs for the process to exit
-    end_time = time.time() + timeout
-    while time.time() < end_time:
-        # If the process exited, return
-        if status_output[0] != None:
-            return (status_output[0], None, status_output[1])
-        # Otherwise, sleep for a while
-        time.sleep(0.1)
-    # Report the PID and the output collected so far
-    return (None, sub.pid, status_output[1])
-
-
 # The following are utility functions related to ports.
 
 def is_sshd_running(host, port, timeout=10.0):
-- 
1.5.4.1

[KVM-AUTOTEST PATCH 06/17] kvm_guest_wizard: rename output_dir to debug_dir in barrier_2()

[Michael Goldish]

The name 'debug_dir' makes it clearer that it corresponds to test.debugdir.

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/tests/kvm/kvm_guest_wizard.py |   20 ++++++++++----------
 1 files changed, 10 insertions(+), 10 deletions(-)

diff --git a/client/tests/kvm/kvm_guest_wizard.py b/client/tests/kvm/kvm_guest_wizard.py
index 2dd9be5..143e61e 100644
--- a/client/tests/kvm/kvm_guest_wizard.py
+++ b/client/tests/kvm/kvm_guest_wizard.py
@@ -18,7 +18,7 @@ def handle_var(vm, params, varname):
 
 
 def barrier_2(vm, words, fail_if_stuck_for, stuck_detection_history,
-              output_dir, data_scrdump_filename, current_step_num):
+              debug_dir, data_scrdump_filename, current_step_num):
     if len(words) < 7:
         logging.error("Bad barrier_2 command line")
         return False
@@ -34,12 +34,12 @@ def barrier_2(vm, words, fail_if_stuck_for, stuck_detection_history,
     if sleep_duration < 1.0: sleep_duration = 1.0
     if sleep_duration > 10.0: sleep_duration = 10.0
 
-    scrdump_filename = os.path.join(output_dir, "scrdump.ppm")
-    cropped_scrdump_filename = os.path.join(output_dir, "cropped_scrdump.ppm")
-    expected_scrdump_filename = os.path.join(output_dir, "scrdump_expected.ppm")
-    expected_cropped_scrdump_filename = os.path.join(output_dir,
+    scrdump_filename = os.path.join(debug_dir, "scrdump.ppm")
+    cropped_scrdump_filename = os.path.join(debug_dir, "cropped_scrdump.ppm")
+    expected_scrdump_filename = os.path.join(debug_dir, "scrdump_expected.ppm")
+    expected_cropped_scrdump_filename = os.path.join(debug_dir,
                                                  "cropped_scrdump_expected.ppm")
-    comparison_filename = os.path.join(output_dir, "comparison.ppm")
+    comparison_filename = os.path.join(debug_dir, "comparison.ppm")
 
     end_time = time.time() + timeout
     end_time_stuck = time.time() + fail_if_stuck_for
@@ -99,7 +99,7 @@ def barrier_2(vm, words, fail_if_stuck_for, stuck_detection_history,
         prev_whole_image_md5sums.insert(0, whole_image_md5sum)
         # Limit queue length to stuck_detection_history
         prev_whole_image_md5sums = \
-        prev_whole_image_md5sums[:stuck_detection_history]
+                prev_whole_image_md5sums[:stuck_detection_history]
 
         # Sleep for a while
         time.sleep(sleep_duration)
@@ -113,12 +113,12 @@ def barrier_2(vm, words, fail_if_stuck_for, stuck_detection_history,
         logging.info(message)
         return False
     else:
-        # Collect information and put it in output_dir
+        # Collect information and put it in debug_dir
         if data_scrdump_filename and os.path.exists(data_scrdump_filename):
             # Read expected screendump image
             (ew, eh, edata) = \
             ppm_utils.image_read_from_ppm_file(data_scrdump_filename)
-            # Write it in output_dir
+            # Write it in debug_dir
             ppm_utils.image_write_to_ppm_file(expected_scrdump_filename,
                                               ew, eh, edata)
             # Write the cropped version as well
@@ -131,7 +131,7 @@ def barrier_2(vm, words, fail_if_stuck_for, stuck_detection_history,
                 ppm_utils.image_write_to_ppm_file(comparison_filename, w, h,
                                                   data)
         # Print error messages and fail the test
-        long_message = message + "\n(see analysis at %s)" % output_dir
+        long_message = message + "\n(see analysis at %s)" % debug_dir
         logging.error(long_message)
         raise error.TestFail, message
 
-- 
1.5.4.1

[KVM-AUTOTEST PATCH 07/17] kvm_guest_wizard: pass 'params' directly to barrier_2()

[Michael Goldish]

Currently parameters for barrier_2() are extracted from 'params' in the main
run_steps() test routine, and then passed to barrier_2().
Instead, let barrier_2() extract parameters from 'params' as it sees fit.
This will make adding new parameters slightly easier and cleaner.

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/tests/kvm/kvm_guest_wizard.py |   37 ++++++++++++++++-----------------
 1 files changed, 18 insertions(+), 19 deletions(-)

diff --git a/client/tests/kvm/kvm_guest_wizard.py b/client/tests/kvm/kvm_guest_wizard.py
index 143e61e..eb0e2d5 100644
--- a/client/tests/kvm/kvm_guest_wizard.py
+++ b/client/tests/kvm/kvm_guest_wizard.py
@@ -17,8 +17,8 @@ def handle_var(vm, params, varname):
     return True
 
 
-def barrier_2(vm, words, fail_if_stuck_for, stuck_detection_history,
-              debug_dir, data_scrdump_filename, current_step_num):
+def barrier_2(vm, words, params, debug_dir, data_scrdump_filename,
+              current_step_num):
     if len(words) < 7:
         logging.error("Bad barrier_2 command line")
         return False
@@ -41,6 +41,18 @@ def barrier_2(vm, words, fail_if_stuck_for, stuck_detection_history,
                                                  "cropped_scrdump_expected.ppm")
     comparison_filename = os.path.join(debug_dir, "comparison.ppm")
 
+    fail_if_stuck_for = params.get("fail_if_stuck_for")
+    if fail_if_stuck_for:
+        fail_if_stuck_for = float(fail_if_stuck_for)
+    else:
+        fail_if_stuck_for = 1e308
+
+    stuck_detection_history = params.get("stuck_detection_history")
+    if stuck_detection_history:
+        stuck_detection_history = int(stuck_detection_history)
+    else:
+        stuck_detection_history = 2
+
     end_time = time.time() + timeout
     end_time_stuck = time.time() + fail_if_stuck_for
     start_time = time.time()
@@ -151,18 +163,6 @@ def run_steps(test, params, env):
     if not os.path.exists(steps_filename):
         raise error.TestError("Steps file not found: %s" % steps_filename)
 
-    fail_if_stuck_for = params.get("fail_if_stuck_for")
-    if fail_if_stuck_for:
-        fail_if_stuck_for = float(fail_if_stuck_for)
-    else:
-        fail_if_stuck_for = 1e308
-
-    stuck_detection_history = params.get("stuck_detection_history")
-    if stuck_detection_history:
-        stuck_detection_history = int(stuck_detection_history)
-    else:
-        stuck_detection_history = 2
-
     sf = open(steps_filename, "r")
     lines = sf.readlines()
     sf.close()
@@ -201,13 +201,12 @@ def run_steps(test, params, env):
                 logging.error("Variable not defined: %s" % words[1])
         elif words[0] == "barrier_2":
             if current_screendump:
-                scrdump_filename = (
-                os.path.join(ppm_utils.get_data_dir(steps_filename),
-                             current_screendump))
+                scrdump_filename = os.path.join(
+                    ppm_utils.get_data_dir(steps_filename),
+                    current_screendump)
             else:
                 scrdump_filename = None
-            if not barrier_2(vm, words, fail_if_stuck_for,
-                             stuck_detection_history, test.debugdir,
+            if not barrier_2(vm, words, params, test.debugdir,
                              scrdump_filename, current_step_num):
                 skip_current_step = True
         else:
-- 
1.5.4.1

[KVM-AUTOTEST PATCH 08/17] kvm_guest_wizard: allow keeping screendump history for debugging purposes

[Michael Goldish]

Add two new step file test parameters:
- keep_screendump_history: if equals 'yes', screendump history is saved in
  test.debugdir/barrier_history in JPG format.  Each screendump taken by the
  test is saved if it differs from the previous screendump.  By default, when
  a barrier succeeds all history is removed, so eventually the remaining files
  are only those of the (last) failed barrier, if any.
- keep_all_history: if equals 'yes', screendump history is not removed upon
  barrier success.  The test leaves behind all the collected screendump history.

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/tests/kvm/kvm_guest_wizard.py |   38 ++++++++++++++++++++++++++++-----
 1 files changed, 32 insertions(+), 6 deletions(-)

diff --git a/client/tests/kvm/kvm_guest_wizard.py b/client/tests/kvm/kvm_guest_wizard.py
index eb0e2d5..73b830e 100644
--- a/client/tests/kvm/kvm_guest_wizard.py
+++ b/client/tests/kvm/kvm_guest_wizard.py
@@ -1,6 +1,6 @@
 import os, time, md5, re, shutil, logging
 from autotest_lib.client.common_lib import utils, error
-import kvm_utils, ppm_utils
+import kvm_utils, ppm_utils, kvm_subprocess
 
 """
 Utilities to perform automatic guest installation using step files.
@@ -53,6 +53,11 @@ def barrier_2(vm, words, params, debug_dir, data_scrdump_filename,
     else:
         stuck_detection_history = 2
 
+    keep_screendump_history = params.get("keep_screendump_history") == "yes"
+    if keep_screendump_history:
+        keep_all_history = params.get("keep_all_history") == "yes"
+        history_dir = os.path.join(debug_dir, "barrier_history")
+
     end_time = time.time() + timeout
     end_time_stuck = time.time() + fail_if_stuck_for
     start_time = time.time()
@@ -91,21 +96,42 @@ def barrier_2(vm, words, params, debug_dir, data_scrdump_filename,
         # Read image file
         (w, h, data) = ppm_utils.image_read_from_ppm_file(scrdump_filename)
 
+        # Compute md5sum of whole image
+        whole_image_md5sum = ppm_utils.image_md5sum(w, h, data)
+
+        # Write screendump to history_dir (as JPG) if requested
+        # and if the screendump differs from the previous one
+        if (keep_screendump_history and
+            whole_image_md5sum not in prev_whole_image_md5sums[:1]):
+            try:
+                os.makedirs(history_dir)
+            except:
+                pass
+            history_scrdump_filename = os.path.join(history_dir,
+                    "scrdump-step_%s-%s.jpg" % (current_step_num,
+                                                time.strftime("%Y%m%d-%H%M%S")))
+            kvm_subprocess.run_fg("convert -quality 30 %s %s" %
+                                  (scrdump_filename, history_scrdump_filename),
+                                  logging.debug, "(convert) ", timeout=30)
+
         # Compare md5sum of barrier region with the expected md5sum
         calced_md5sum = ppm_utils.get_region_md5sum(w, h, data, x1, y1, dx, dy,
                                                     cropped_scrdump_filename)
         if calced_md5sum == md5sum:
+            # Success -- remove screendump history unless requested not to
+            if keep_screendump_history and not keep_all_history:
+                kvm_subprocess.run_fg("rm -rvf %s" % history_dir,
+                                      logging.debug, "(rm) ", timeout=30)
+            # Report success
             return True
 
-        # Compute md5sum of whole image in order to compare it with
-        # previous ones
-        whole_image_md5sum = ppm_utils.image_md5sum(w, h, data)
+        # Insert image md5sum into queue of last seen images:
         # If md5sum is already in queue...
         if whole_image_md5sum in prev_whole_image_md5sums:
             # Remove md5sum from queue
             prev_whole_image_md5sums.remove(whole_image_md5sum)
         else:
-            # Extend 'stuck' timeout
+            # Otherwise extend 'stuck' timeout
             end_time_stuck = time.time() + fail_if_stuck_for
         # Insert md5sum at beginning of queue
         prev_whole_image_md5sums.insert(0, whole_image_md5sum)
@@ -129,7 +155,7 @@ def barrier_2(vm, words, params, debug_dir, data_scrdump_filename,
         if data_scrdump_filename and os.path.exists(data_scrdump_filename):
             # Read expected screendump image
             (ew, eh, edata) = \
-            ppm_utils.image_read_from_ppm_file(data_scrdump_filename)
+                    ppm_utils.image_read_from_ppm_file(data_scrdump_filename)
             # Write it in debug_dir
             ppm_utils.image_write_to_ppm_file(expected_scrdump_filename,
                                               ew, eh, edata)
-- 
1.5.4.1

[KVM-AUTOTEST PATCH 09/17] kvm_tests.cfg.sample: add 'keep_screendump_history = yes' to step file tests

[Michael Goldish]

This should be rather harmless because the history does not take up much space,
and is only kept for the failed barriers in failed tests, by default.
It should significantly ease debugging of failed step file tests.

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/tests/kvm/kvm_tests.cfg.sample |    2 ++
 1 files changed, 2 insertions(+), 0 deletions(-)

diff --git a/client/tests/kvm/kvm_tests.cfg.sample b/client/tests/kvm/kvm_tests.cfg.sample
index 5bd6eb8..02112b7 100644
--- a/client/tests/kvm/kvm_tests.cfg.sample
+++ b/client/tests/kvm/kvm_tests.cfg.sample
@@ -30,6 +30,7 @@ variants:
         type = steps
         fail_if_stuck_for = 300
         stuck_detection_history = 2
+        keep_screendump_history = yes
         force_create_image = yes
         kill_vm = yes
         kill_vm_timeout = 60
@@ -40,6 +41,7 @@ variants:
         fail_if_stuck_for = 300
         stuck_detection_history = 2
         kill_vm_on_error = yes
+        keep_screendump_history = yes
 
     - boot:         install setup
         type = boot
-- 
1.5.4.1

[KVM-AUTOTEST PATCH 10/17] KVM test: optionally convert PPM files to PNG format after test

[Michael Goldish]

This is intended to save disk space.  Requires ImageMagick (uses mogrify).

To enable:
convert_ppm_files_to_png = yes

To enable only for failed tests:
convert_ppm_files_to_png_on_error = yes

Reminder: by default PPM files are removed after the test (and after the
conversion, if requested).  To keep them specify:
keep_ppm_files = yes

To keep them only for failed tests:
keep_ppm_files_on_error = yes

A reasonable choice would be to keep PNG files for failed tests, and never
keep PPM files.  To do this specify
convert_ppm_files_to_png_on_error = yes
without specifying 'keep_ppm_files = yes' or 'keep_ppm_files_on_error = yes'
(or explicitly set to 'no', if it was set to 'yes' on a higher level in the
config hierarchy).

This patch also makes small cosmetic changes to the 'keep_ppm_files' feature.

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/tests/kvm/kvm_preprocessing.py |   16 ++++++++++++----
 1 files changed, 12 insertions(+), 4 deletions(-)

diff --git a/client/tests/kvm/kvm_preprocessing.py b/client/tests/kvm/kvm_preprocessing.py
index 7b97f00..71f7a6b 100644
--- a/client/tests/kvm/kvm_preprocessing.py
+++ b/client/tests/kvm/kvm_preprocessing.py
@@ -264,11 +264,19 @@ def postprocess(test, params, env):
     """
     process(test, params, env, postprocess_image, postprocess_vm)
 
-    # See if we should get rid of all PPM files
-    if not params.get("keep_ppm_files") == "yes":
-        # Remove them all
+    # Should we convert PPM files to PNG format?
+    if params.get("convert_ppm_files_to_png") == "yes":
+        logging.debug("'convert_ppm_files_to_png' specified; converting PPM"
+                      " files to PNG format...")
+        mogrify_cmd = ("mogrify -format png %s" %
+                       os.path.join(test.debugdir, "*.ppm"))
+        kvm_subprocess.run_fg(mogrify_cmd, logging.debug, "(mogrify) ",
+                              timeout=30.0)
+
+    # Should we keep the PPM files?
+    if params.get("keep_ppm_files") != "yes":
         logging.debug("'keep_ppm_files' not specified; removing all PPM files"
-                      " from results dir...")
+                      " from debug dir...")
         rm_cmd = "rm -vf %s" % os.path.join(test.debugdir, "*.ppm")
         kvm_subprocess.run_fg(rm_cmd, logging.debug, "(rm) ", timeout=5.0)
 
-- 
1.5.4.1

[KVM-AUTOTEST PATCH 11/17] KVM test: kvm_tests.cfg.sample: convert PPM files to PNG by default

[Michael Goldish]

By default, always remove PPM files, and keep PNG files only for failed tests.
This shouldn't do much harm, because while PPMs can be incorporated directly
into step files, PNGs can be converted back to PPMs easily, and take less disk
space.
(PNG is a lossless compression format.)

The 'keep_ppm_files' and 'keep_ppm_files_on_error' settings are commented out
so the user can easily enable them if desired.

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/tests/kvm/kvm_tests.cfg.sample |    5 +++--
 1 files changed, 3 insertions(+), 2 deletions(-)

diff --git a/client/tests/kvm/kvm_tests.cfg.sample b/client/tests/kvm/kvm_tests.cfg.sample
index 02112b7..1288952 100644
--- a/client/tests/kvm/kvm_tests.cfg.sample
+++ b/client/tests/kvm/kvm_tests.cfg.sample
@@ -8,8 +8,9 @@ main_vm = vm1
 
 # Some preprocessor/postprocessor params
 start_vm = yes
-keep_ppm_files = no
-keep_ppm_files_on_error = yes
+convert_ppm_files_to_png_on_error = yes
+#keep_ppm_files = yes
+#keep_ppm_files_on_error = yes
 kill_vm = no
 kill_vm_gracefully = yes
 
-- 
1.5.4.1

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

[Michael Goldish]

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))
+
+        # 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

[KVM-AUTOTEST PATCH 13/17] KVM test: fix a parsing problem in kvm_config.py

[Michael Goldish]

Allow kvm_config to parse weird lines that seem to contain several operators,
such as:
time_filter_re = "(?<=TIME: ...)"

The '?<=' is recognized as the operator instead of the '='.
To fix this, select the operator closest to the beginning of the line.

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/tests/kvm/kvm_config.py |    6 ++++--
 1 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/client/tests/kvm/kvm_config.py b/client/tests/kvm/kvm_config.py
index 95eefcb..99ccb2a 100755
--- a/client/tests/kvm/kvm_config.py
+++ b/client/tests/kvm/kvm_config.py
@@ -294,10 +294,12 @@ class config:
             # Look for a known operator in the line
             operators = ["?+=", "?<=", "?=", "+=", "<=", "="]
             op_found = None
+            op_pos = len(line)
             for op in operators:
-                if op in line:
+                pos = line.find(op)
+                if pos >= 0 and pos < op_pos:
                     op_found = op
-                    break
+                    op_pos = pos
 
             # Found an operator?
             if op_found:
-- 
1.5.4.1

[KVM-AUTOTEST PATCH 15/17] KVM test: add timedrift test to kvm_tests.cfg.sample

[Michael Goldish]

Currently the test will only run on Windows.
It should be able to run on Linux just as well, but if I understand correctly,
testing time drift on Linux is less interesting.

Also make some tiny cosmetic changes (spacing), and move the stress_boot test
before the shutdown test (shutdown should be last).

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/tests/kvm/kvm_tests.cfg.sample |   46 ++++++++++++++++++++++++++------
 1 files changed, 37 insertions(+), 9 deletions(-)

diff --git a/client/tests/kvm/kvm_tests.cfg.sample b/client/tests/kvm/kvm_tests.cfg.sample
index 1288952..2d75a66 100644
--- a/client/tests/kvm/kvm_tests.cfg.sample
+++ b/client/tests/kvm/kvm_tests.cfg.sample
@@ -92,20 +92,33 @@ variants:
                 test_name = disktest
                 test_control_file = disktest.control
 
-    - linux_s3:      install setup
+    - linux_s3:     install setup
         type = linux_s3
 
-    - shutdown:      install setup
+    - timedrift:    install setup
+        type = timedrift
+        extra_params += " -rtc-td-hack"
+        # Pin the VM and host load to CPU #0
+        cpu_mask = 0x1
+        # Set the load and rest durations
+        load_duration = 20
+        rest_duration = 20
+        # Fail if the drift after load is higher than 50%
+        drift_threshold = 50
+        # Fail if the drift after the rest period is higher than 10%
+        drift_threshold_after_rest = 10
+
+    - stress_boot:  install setup
+        type = stress_boot
+        max_vms = 5    
+        alive_test_cmd = ps aux
+
+    - shutdown:     install setup
         type = shutdown
         kill_vm = yes
         kill_vm_gracefully = no
 
 
-    - stress_boot:
-        type = stress_boot
-        max_vms = 5    
-        alive_test_cmd = ps aux
-
 # NICs
 variants:
     - @rtl8139:
@@ -121,6 +134,7 @@ variants:
 variants:
     # Linux section
     - @Linux:
+        no timedrift
         cmd_shutdown = shutdown -h now
         cmd_reboot = shutdown -r now
         ssh_status_test_command = echo $?
@@ -303,8 +317,6 @@ variants:
                             md5sum=bf4635e4a4bd3b43838e72bc8c329d55
                             md5sum_1m=18ecd37b639109f1b2af05cfb57dfeaf
 
-
-
     # Windows section
     - @Windows:
         no autotest
@@ -318,6 +330,21 @@ variants:
             migration_test_command = ver && vol
         stress_boot:
             alive_test_cmd = systeminfo
+        timedrift:
+            # For this to work, the ISO should contain vlc (vlc.exe) and a video (ED_1024.avi)
+            cdrom = windows/vlc.iso
+            time_command = "echo TIME: %date% %time%"
+            time_filter_re = "(?<=TIME: \w\w\w ).{19}(?=\.\d\d)"
+            time_format = "%m/%d/%Y %H:%M:%S"
+            guest_load_command = 'cmd /c "d:\vlc -f --loop --no-qt-privacy-ask --no-qt-system-tray d:\ED_1024.avi"'
+            # Alternative guest load:
+            #guest_load_command = "(dir /s && dir /s && dir /s && dir /s) > nul"
+            guest_load_stop_command = "taskkill /F /IM vlc.exe"
+            guest_load_instances = 2
+            host_load_command = "bzip2 -c --best /dev/urandom > /dev/null"
+            # Alternative host load:
+            #host_load_command = "dd if=/dev/urandom of=/dev/null"
+            host_load_instances = 8
 
         variants:
             - Win2000:
@@ -582,5 +609,6 @@ variants:
         only qcow2.*ide.*default.*up.*Ubuntu-8.10-server.*(autotest.sleeptest)
         only rtl8139
 
+
 # Choose your test list
 only fc8_quick
-- 
1.5.4.1

Re: [Autotest] [KVM-AUTOTEST PATCH 15/17] KVM test: add timedrift test to kvm_tests.cfg.sample

[Dor Laor]

On 07/20/2009 06:07 PM, Michael Goldish wrote:
> Currently the test will only run on Windows.
> It should be able to run on Linux just as well, but if I understand correctly,
> testing time drift on Linux is less interesting.

Linux is interesting too. The problem is more visible on windows since
it uses 1000hz frequency when it plays multimedia. It makes timer irq 
injection harder.

Does the test fail without the rtc-td-hack?

>
> Also make some tiny cosmetic changes (spacing), and move the stress_boot test
> before the shutdown test (shutdown should be last).
>
> Signed-off-by: Michael Goldish<mgoldish@redhat.com>
> ---
>   client/tests/kvm/kvm_tests.cfg.sample |   46 ++++++++++++++++++++++++++------
>   1 files changed, 37 insertions(+), 9 deletions(-)
>
> diff --git a/client/tests/kvm/kvm_tests.cfg.sample b/client/tests/kvm/kvm_tests.cfg.sample
> index 1288952..2d75a66 100644
> --- a/client/tests/kvm/kvm_tests.cfg.sample
> +++ b/client/tests/kvm/kvm_tests.cfg.sample
> @@ -92,20 +92,33 @@ variants:
>                   test_name = disktest
>                   test_control_file = disktest.control
>
> -    - linux_s3:      install setup
> +    - linux_s3:     install setup
>           type = linux_s3
>
> -    - shutdown:      install setup
> +    - timedrift:    install setup
> +        type = timedrift
> +        extra_params += " -rtc-td-hack"
> +        # Pin the VM and host load to CPU #0
> +        cpu_mask = 0x1
> +        # Set the load and rest durations
> +        load_duration = 20
> +        rest_duration = 20
> +        # Fail if the drift after load is higher than 50%
> +        drift_threshold = 50
> +        # Fail if the drift after the rest period is higher than 10%
> +        drift_threshold_after_rest = 10
> +
> +    - stress_boot:  install setup
> +        type = stress_boot
> +        max_vms = 5
> +        alive_test_cmd = ps aux
> +
> +    - shutdown:     install setup
>           type = shutdown
>           kill_vm = yes
>           kill_vm_gracefully = no
>
>
> -    - stress_boot:
> -        type = stress_boot
> -        max_vms = 5
> -        alive_test_cmd = ps aux
> -
>   # NICs
>   variants:
>       - @rtl8139:
> @@ -121,6 +134,7 @@ variants:
>   variants:
>       # Linux section
>       - @Linux:
> +        no timedrift
>           cmd_shutdown = shutdown -h now
>           cmd_reboot = shutdown -r now
>           ssh_status_test_command = echo $?
> @@ -303,8 +317,6 @@ variants:
>                               md5sum=bf4635e4a4bd3b43838e72bc8c329d55
>                               md5sum_1m=18ecd37b639109f1b2af05cfb57dfeaf
>
> -
> -
>       # Windows section
>       - @Windows:
>           no autotest
> @@ -318,6 +330,21 @@ variants:
>               migration_test_command = ver&&  vol
>           stress_boot:
>               alive_test_cmd = systeminfo
> +        timedrift:
> +            # For this to work, the ISO should contain vlc (vlc.exe) and a video (ED_1024.avi)
> +            cdrom = windows/vlc.iso
> +            time_command = "echo TIME: %date% %time%"
> +            time_filter_re = "(?<=TIME: \w\w\w ).{19}(?=\.\d\d)"
> +            time_format = "%m/%d/%Y %H:%M:%S"
> +            guest_load_command = 'cmd /c "d:\vlc -f --loop --no-qt-privacy-ask --no-qt-system-tray d:\ED_1024.avi"'
> +            # Alternative guest load:
> +            #guest_load_command = "(dir /s&&  dir /s&&  dir /s&&  dir /s)>  nul"
> +            guest_load_stop_command = "taskkill /F /IM vlc.exe"
> +            guest_load_instances = 2
> +            host_load_command = "bzip2 -c --best /dev/urandom>  /dev/null"
> +            # Alternative host load:
> +            #host_load_command = "dd if=/dev/urandom of=/dev/null"
> +            host_load_instances = 8
>
>           variants:
>               - Win2000:
> @@ -582,5 +609,6 @@ variants:
>           only qcow2.*ide.*default.*up.*Ubuntu-8.10-server.*(autotest.sleeptest)
>           only rtl8139
>
> +
>   # Choose your test list
>   only fc8_quick