Added sysinfo support to log pre and post iteration (currently it logs
the contents of /proc/schedstat). Added client.common_lib.test hooks to
call pre and post iteration. Used the hooks in client.bin.test.runtest()
for client tests. Refactored server.test and added wrappers for the
pre/post iteration logging and used them on the new pre/post iteration
hooks.
For each iteration there will be a
resultsdir/sysinfo/iteration.N/schedstat.after and schedstat.before.
If there are tests that override execute() and implement their own
iteration logic they need to be changed over to override run_once()
instead and take advantage of the default execute() that supports the
pre/post iteration hooks and other things.
Signed-off-by: Mihai Rusu <[email protected]>
git-svn-id: http://test.kernel.org/svn/autotest/trunk@2929 592f7852-d20e-0410-864c-8624ca9c26a4
diff --git a/client/bin/base_sysinfo.py b/client/bin/base_sysinfo.py
index d84be2e..48bb725 100644
--- a/client/bin/base_sysinfo.py
+++ b/client/bin/base_sysinfo.py
@@ -9,22 +9,31 @@
"lspci -vvn", "gcc --version", "ld --version", "mount", "hostname",
"uptime",
]
+_DEFAULT_COMMANDS_TO_LOG_BEFORE_ITERATION = []
+_DEFAULT_COMMANDS_TO_LOG_AFTER_ITERATION = []
_DEFAULT_FILES_TO_LOG_PER_TEST = []
_DEFAULT_FILES_TO_LOG_PER_BOOT = [
"/proc/pci", "/proc/meminfo", "/proc/slabinfo", "/proc/version",
"/proc/cpuinfo", "/proc/modules", "/proc/interrupts",
]
+_DEFAULT_FILES_TO_LOG_BEFORE_ITERATION = [
+ "/proc/schedstat"
+ ]
+_DEFAULT_FILES_TO_LOG_AFTER_ITERATION = [
+ "/proc/schedstat"
+ ]
class loggable(object):
""" Abstract class for representing all things "loggable" by sysinfo. """
- def __init__(self, log_in_keyval):
+ def __init__(self, logf, log_in_keyval):
+ self.logf = logf
self.log_in_keyval = log_in_keyval
def readline(self, logdir):
- path = os.path.join(logdir, self.logfile)
+ path = os.path.join(logdir, self.logf)
if os.path.exists(path):
return utils.read_one_line(path)
else:
@@ -32,19 +41,22 @@
class logfile(loggable):
- def __init__(self, path, log_in_keyval=False):
- super(logfile, self).__init__(log_in_keyval)
+ def __init__(self, path, logf=None, log_in_keyval=False):
+ if not logf:
+ logf = os.path.basename(path)
+ super(logfile, self).__init__(logf, log_in_keyval)
self.path = path
- self.logfile = os.path.basename(self.path)
def __repr__(self):
- return "sysinfo.logfile(%r, %r)" % (self.path, self.log_in_keyval)
+ r = "sysinfo.logfile(%r, %r, %r)"
+ r %= (self.path, self.logf, self.log_in_keyval)
+ return r
def __eq__(self, other):
if isinstance(other, logfile):
- return self.path == other.path
+ return (self.path, self.logf) == (other.path, other.logf)
elif isinstance(other, loggable):
return False
return NotImplemented
@@ -58,33 +70,31 @@
def __hash__(self):
- return hash(self.path)
+ return hash((self.path, self.logf))
def run(self, logdir):
if os.path.exists(self.path):
- shutil.copy(self.path, logdir)
+ shutil.copy(self.path, os.path.join(logdir, self.logf))
class command(loggable):
- def __init__(self, cmd, logfile=None, log_in_keyval=False):
- super(command, self).__init__(log_in_keyval)
+ def __init__(self, cmd, logf=None, log_in_keyval=False):
+ if not logf:
+ logf = cmd.replace(" ", "_")
+ super(command, self).__init__(logf, log_in_keyval)
self.cmd = cmd
- if logfile:
- self.logfile = logfile
- else:
- self.logfile = cmd.replace(" ", "_")
def __repr__(self):
r = "sysinfo.command(%r, %r, %r)"
- r %= (self.cmd, self.logfile, self.log_in_keyval)
+ r %= (self.cmd, self.logf, self.log_in_keyval)
return r
def __eq__(self, other):
if isinstance(other, command):
- return (self.cmd, self.logfile) == (other.cmd, other.logfile)
+ return (self.cmd, self.logf) == (other.cmd, other.logf)
elif isinstance(other, loggable):
return False
return NotImplemented
@@ -98,12 +108,12 @@
def __hash__(self):
- return hash((self.cmd, self.logfile))
+ return hash((self.cmd, self.logf))
def run(self, logdir):
stdin = open(os.devnull, "r")
- stdout = open(os.path.join(logdir, self.logfile), "w")
+ stdout = open(os.path.join(logdir, self.logf), "w")
stderr = open(os.devnull, "w")
env = os.environ.copy()
if "PATH" not in env:
@@ -132,12 +142,30 @@
for filename in _DEFAULT_FILES_TO_LOG_PER_BOOT:
self.boot_loggables.add(logfile(filename))
+ # pull in the pre test iteration logs to collect
+ self.before_iteration_loggables = set()
+ for cmd in _DEFAULT_COMMANDS_TO_LOG_BEFORE_ITERATION:
+ self.before_iteration_loggables.add(
+ command(cmd, logf=cmd.replace(" ", "_") + '.before'))
+ for fname in _DEFAULT_FILES_TO_LOG_BEFORE_ITERATION:
+ self.before_iteration_loggables.add(
+ logfile(fname, logf=os.path.basename(fname) + '.before'))
+
+ # pull in the post test iteration logs to collect
+ self.after_iteration_loggables = set()
+ for cmd in _DEFAULT_COMMANDS_TO_LOG_AFTER_ITERATION:
+ self.after_iteration_loggables.add(
+ command(cmd, logf=cmd.replace(" ", "_") + '.after'))
+ for fname in _DEFAULT_FILES_TO_LOG_AFTER_ITERATION:
+ self.after_iteration_loggables.add(
+ logfile(fname, logf=os.path.basename(fname) + '.after'))
+
# add in a couple of extra files and commands we want to grab
- self.test_loggables.add(command("df -mP", logfile="df"))
- self.test_loggables.add(command("dmesg -c", logfile="dmesg"))
+ self.test_loggables.add(command("df -mP", logf="df"))
+ self.test_loggables.add(command("dmesg -c", logf="dmesg"))
self.boot_loggables.add(logfile("/proc/cmdline",
log_in_keyval=True))
- self.boot_loggables.add(command("uname -a", logfile="uname",
+ self.boot_loggables.add(command("uname -a", logf="uname",
log_in_keyval=True))
@@ -176,6 +204,15 @@
return os.path.join(self.sysinfodir, boot_dir)
+ def _get_iteration_subdir(self, iteration):
+ iter_dir = "iteration.%d" % iteration
+
+ logdir = os.path.join(self.sysinfodir, iter_dir)
+ if not os.path.exists(logdir):
+ os.mkdir(logdir)
+ return logdir
+
+
@log.log_and_ignore_errors("post-reboot sysinfo error:")
def log_per_reboot_data(self):
""" Logging hook called whenever a job starts, and again after
@@ -220,6 +257,28 @@
test.write_test_keyval(keyval)
+ @log.log_and_ignore_errors("pre-test siteration sysinfo error:")
+ def log_before_each_iteration(self, test, iteration=None):
+ """ Logging hook called before a test iteration."""
+ if not iteration:
+ iteration = test.iteration
+ logdir = self._get_iteration_subdir(iteration)
+
+ for log in self.before_iteration_loggables:
+ log.run(logdir)
+
+
+ @log.log_and_ignore_errors("post-test siteration sysinfo error:")
+ def log_after_each_iteration(self, test, iteration=None):
+ """ Logging hook called after a test iteration."""
+ if not iteration:
+ iteration = test.iteration
+ logdir = self._get_iteration_subdir(iteration)
+
+ for log in self.after_iteration_loggables:
+ log.run(logdir)
+
+
def _log_messages(self, logdir):
""" Log all of the new data in /var/log/messages. """
try:
@@ -244,7 +303,7 @@
keyval = {}
for log in loggables:
if log.log_in_keyval:
- keyval["sysinfo-" + log.logfile] = log.readline(logdir)
+ keyval["sysinfo-" + log.logf] = log.readline(logdir)
return keyval
diff --git a/client/bin/job.py b/client/bin/job.py
index 4f29652..a2dd876 100755
--- a/client/bin/job.py
+++ b/client/bin/job.py
@@ -1019,7 +1019,7 @@
def add_sysinfo_command(self, command, logfile=None, on_every_test=False):
- self._add_sysinfo_loggable(sysinfo.command(command, logfile),
+ self._add_sysinfo_loggable(sysinfo.command(command, logf=logfile),
on_every_test)
diff --git a/client/bin/test.py b/client/bin/test.py
index acae8e3..ba51e56 100755
--- a/client/bin/test.py
+++ b/client/bin/test.py
@@ -32,4 +32,6 @@
def runtest(job, url, tag, args, dargs):
common_test.runtest(job, url, tag, args, dargs, locals(), globals(),
job.sysinfo.log_before_each_test,
- job.sysinfo.log_after_each_test)
+ job.sysinfo.log_after_each_test,
+ job.sysinfo.log_before_each_iteration,
+ job.sysinfo.log_after_each_iteration)
diff --git a/client/common_lib/test.py b/client/common_lib/test.py
index 72fd743..25d5aca 100644
--- a/client/common_lib/test.py
+++ b/client/common_lib/test.py
@@ -104,14 +104,23 @@
utils.drop_caches()
- def _call_run_once(self, args, dargs):
+ def _call_run_once(self, before_iteration_hook, after_iteration_hook,
+ args, dargs):
self.drop_caches_between_iterations()
+
+ # execute iteration hooks
+ if before_iteration_hook:
+ before_iteration_hook(self)
self.run_once(*args, **dargs)
+ if after_iteration_hook:
+ after_iteration_hook(self)
+
self.postprocess_iteration()
def execute(self, iterations=None, test_length=None, profile_only=False,
_get_time=time.time, postprocess_profiled_run=None,
+ before_iteration_hook=None, after_iteration_hook=None,
*args, **dargs):
"""
This is the basic execute method for the tests inherited from base_test.
@@ -166,7 +175,8 @@
logging.info(
'Executing iteration %d, time_elapsed %d s',
timed_counter, time_elapsed)
- self._call_run_once(args, dargs)
+ self._call_run_once(before_iteration_hook, after_iteration_hook,
+ args, dargs)
test_iteration_finish = _get_time()
time_elapsed = test_iteration_finish - test_start
logging.info('Test finished after %d iterations',
@@ -186,10 +196,11 @@
'Number of iterations: %d', iterations)
for self.iteration in xrange(1, iterations+1):
logging.info('Executing iteration %d of %d',
- self.iteration, iterations)
- self._call_run_once(args, dargs)
+ self.iteration, iterations)
+ self._call_run_once(before_iteration_hook,
+ after_iteration_hook, args, dargs)
logging.info('Test finished after %d iterations.',
- iterations)
+ iterations)
self.run_once_profiling(postprocess_profiled_run, *args, **dargs)
@@ -270,7 +281,7 @@
self.logger.addHandler(self.test_handler)
- def _exec(self, args, dargs):
+ def _exec(self, before_iteration_hook, after_iteration_hook, args, dargs):
self.job.stdout.tee_redirect(os.path.join(self.debugdir, 'stdout'))
self.job.stderr.tee_redirect(os.path.join(self.debugdir, 'stderr'))
@@ -309,6 +320,12 @@
# Execute:
os.chdir(self.outputdir)
+
+ # insert the iteration hooks arguments to be potentially
+ # passed over to self.execute() if it accepts them
+ dargs['before_iteration_hook'] = before_iteration_hook
+ dargs['after_iteration_hook'] = after_iteration_hook
+
if hasattr(self, 'run_once'):
p_args, p_dargs = _cherry_pick_args(self.run_once,
args, dargs)
@@ -493,7 +510,8 @@
def runtest(job, url, tag, args, dargs,
local_namespace={}, global_namespace={},
- before_test_hook=None, after_test_hook=None):
+ before_test_hook=None, after_test_hook=None,
+ before_iteration_hook=None, after_iteration_hook=None):
local_namespace = local_namespace.copy()
global_namespace = global_namespace.copy()
@@ -561,11 +579,14 @@
pwd = os.getcwd()
os.chdir(outputdir)
+
try:
mytest = global_namespace['mytest']
if before_test_hook:
before_test_hook(mytest)
- mytest._exec(args, dargs)
+ # args/dargs are the test arguments as given by the control file so
+ # we cannot put the iteration hooks inside the dictionary
+ mytest._exec(before_iteration_hook, after_iteration_hook, args, dargs)
finally:
os.chdir(pwd)
if after_test_hook:
diff --git a/client/common_lib/test_unittest.py b/client/common_lib/test_unittest.py
index d56a139..bb088ca 100644
--- a/client/common_lib/test_unittest.py
+++ b/client/common_lib/test_unittest.py
@@ -74,26 +74,41 @@
def setUp(self):
TestTestCase.setUp(self)
self.god.stub_function(self.test, 'warmup')
- self.god.stub_function(self.test, 'drop_caches_between_iterations')
- self.god.stub_function(self.test, 'run_once')
- self.god.stub_function(self.test, 'postprocess_iteration')
self.god.stub_function(self.test, 'run_once_profiling')
self.god.stub_function(self.test, 'postprocess')
self.test.warmup.expect_call()
+ def test_call_run_once(self):
+ # setup
+ self.god.stub_function(self.test, 'drop_caches_between_iterations')
+ self.god.stub_function(self.test, 'run_once')
+ self.god.stub_function(self.test, 'postprocess_iteration')
+ before_hook = self.god.create_mock_function('before_hook')
+ after_hook = self.god.create_mock_function('after_hook')
+
+ # tests the test._call_run_once implementation
+ self.test.drop_caches_between_iterations.expect_call()
+ before_hook.expect_call()
+ self.test.run_once.expect_call(1, 2, arg='val')
+ after_hook.expect_call()
+ self.test.postprocess_iteration.expect_call()
+ self.test._call_run_once(before_hook, after_hook, (1, 2),
+ {'arg': 'val'})
+
+
+ def _expect_call_run_once(self):
+ self.test._call_run_once.expect_call(None, None, (), {})
+
+
def test_execute_test_length(self):
# test that test_length overrides iterations and works.
- self.test.drop_caches_between_iterations.expect_call()
- self.test.run_once.expect_call()
- self.test.postprocess_iteration.expect_call()
- self.test.drop_caches_between_iterations.expect_call()
- self.test.run_once.expect_call()
- self.test.postprocess_iteration.expect_call()
- self.test.drop_caches_between_iterations.expect_call()
- self.test.run_once.expect_call()
- self.test.postprocess_iteration.expect_call()
+ self.god.stub_function(self.test, '_call_run_once')
+
+ self._expect_call_run_once()
+ self._expect_call_run_once()
+ self._expect_call_run_once()
self.test.run_once_profiling.expect_call(None)
self.test.postprocess.expect_call()
@@ -104,11 +119,11 @@
def test_execute_iterations(self):
# test that iterations works.
+ self.god.stub_function(self.test, '_call_run_once')
+
iterations = 2
for _ in range(iterations):
- self.test.drop_caches_between_iterations.expect_call()
- self.test.run_once.expect_call()
- self.test.postprocess_iteration.expect_call()
+ self._expect_call_run_once()
self.test.run_once_profiling.expect_call(None)
self.test.postprocess.expect_call()
@@ -139,9 +154,9 @@
def test_execute_postprocess_profiled_false(self):
# test that postprocess_profiled_run=False works
- self.test.drop_caches_between_iterations.expect_call()
- self.test.run_once.expect_call()
- self.test.postprocess_iteration.expect_call()
+ self.god.stub_function(self.test, '_call_run_once')
+
+ self._expect_call_run_once()
self.test.run_once_profiling.expect_call(False)
self.test.postprocess.expect_call()
@@ -151,9 +166,9 @@
def test_execute_postprocess_profiled_true(self):
# test that postprocess_profiled_run=True works
- self.test.drop_caches_between_iterations.expect_call()
- self.test.run_once.expect_call()
- self.test.postprocess_iteration.expect_call()
+ self.god.stub_function(self.test, '_call_run_once')
+
+ self._expect_call_run_once()
self.test.run_once_profiling.expect_call(True)
self.test.postprocess.expect_call()
diff --git a/server/server_job.py b/server/server_job.py
index 80306af..98e4ed1 100755
--- a/server/server_job.py
+++ b/server/server_job.py
@@ -564,7 +564,7 @@
def add_sysinfo_command(self, command, logfile=None, on_every_test=False):
- self._add_sysinfo_loggable(sysinfo.command(command, logfile),
+ self._add_sysinfo_loggable(sysinfo.command(command, logf=logfile),
on_every_test)
diff --git a/server/test.py b/server/test.py
index d1eecf9..00e81a7 100755
--- a/server/test.py
+++ b/server/test.py
@@ -12,7 +12,7 @@
pass
-_sysinfo_before_script = """\
+_sysinfo_before_test_script = """\
import pickle
from autotest_lib.client.bin import test
mytest = test.test(job, '', %r)
@@ -22,7 +22,7 @@
job.record('GOOD', '', 'sysinfo.before')
"""
-_sysinfo_after_script = """\
+_sysinfo_after_test_script = """\
import pickle
from autotest_lib.client.bin import test
mytest = test.test(job, '', %r)
@@ -34,6 +34,23 @@
job.record('GOOD', '', 'sysinfo.after')
"""
+# this script is ran after _sysinfo_before_test_script and before
+# _sysinfo_after_test_script which means the pickle file exists
+# already and should be dumped with updated state for
+# _sysinfo_after_test_script to pick it up later
+_sysinfo_iteration_script = """\
+import pickle
+from autotest_lib.client.bin import test
+mytest = test.test(job, '', %r)
+sysinfo_pickle = os.path.join(mytest.outputdir, 'sysinfo.pickle')
+if os.path.exists(sysinfo_pickle):
+ job.sysinfo = pickle.load(open(sysinfo_pickle))
+ job.sysinfo.__init__(job.resultdir)
+job.sysinfo.%s(mytest, iteration=%d)
+pickle.dump(job.sysinfo, open(sysinfo_pickle, 'w'))
+job.record('GOOD', '', 'sysinfo.iteration.%s')
+"""
+
class _sysinfo_logger(object):
def __init__(self, job):
@@ -53,38 +70,28 @@
return host, at
- @log.log_and_ignore_errors("pre-test server sysinfo error:")
- def before_hook(self, mytest):
- host, at = self._install()
- outputdir = host.get_tmp_dir()
-
- # run the pre-test sysinfo script
- at.run(_sysinfo_before_script % outputdir,
- results_dir=self.job.resultdir)
-
- # pull back the sysinfo pickle
+ def _pull_pickle(self, host, outputdir):
+ """Pulls from the client the pickle file with the saved sysinfo state.
+ """
fd, path = tempfile.mkstemp(dir=self.job.tmpdir)
os.close(fd)
host.get_file(os.path.join(outputdir, "sysinfo.pickle"), path)
self.pickle = path
- @log.log_and_ignore_errors("post-test server sysinfo error:")
- def after_hook(self, mytest):
- host, at = self._install()
- outputdir = host.get_tmp_dir()
-
- # push the sysinfo pickle out to the remote machine
+ def _push_pickle(self, host, outputdir):
+ """Pushes the server saved sysinfo pickle file to the client.
+ """
if self.pickle:
host.send_file(self.pickle,
os.path.join(outputdir, "sysinfo.pickle"))
os.remove(self.pickle)
self.pickle = None
- # run the post-test sysinfo script
- at.run(_sysinfo_after_script % outputdir,
- results_dir=self.job.resultdir)
+ def _pull_sysinfo_keyval(self, host, outputdir, mytest):
+ """Pulls sysinfo and keyval data from the client.
+ """
# pull the sysinfo data back on to the server
host.get_file(os.path.join(outputdir, "sysinfo"), mytest.outputdir)
@@ -97,10 +104,73 @@
mytest.write_test_keyval(keyval)
+ @log.log_and_ignore_errors("pre-test server sysinfo error:")
+ def before_hook(self, mytest):
+ host, at = self._install()
+ outputdir = host.get_tmp_dir()
+
+ # run the pre-test sysinfo script
+ at.run(_sysinfo_before_test_script % outputdir,
+ results_dir=self.job.resultdir)
+
+ self._pull_pickle(host, outputdir)
+
+
+ @log.log_and_ignore_errors("pre-test iteration server sysinfo error:")
+ def before_iteration_hook(self, mytest):
+ host, at = self._install()
+ outputdir = host.get_tmp_dir()
+
+ # this function is called after before_hook() se we have sysinfo state
+ # to push to the server
+ self._push_pickle(host, outputdir);
+ # run the pre-test iteration sysinfo script
+ at.run(_sysinfo_iteration_script %
+ (outputdir, 'log_before_each_iteration', mytest.iteration,
+ 'before'),
+ results_dir=self.job.resultdir)
+
+ # get the new sysinfo state from the client
+ self._pull_pickle(host, outputdir)
+
+
+ @log.log_and_ignore_errors("post-test iteration server sysinfo error:")
+ def after_iteration_hook(self, mytest):
+ host, at = self._install()
+ outputdir = host.get_tmp_dir()
+
+ # push latest sysinfo state to the client
+ self._push_pickle(host, outputdir);
+ # run the post-test iteration sysinfo script
+ at.run(_sysinfo_iteration_script %
+ (outputdir, 'log_after_each_iteration', mytest.iteration,
+ 'after'),
+ results_dir=self.job.resultdir)
+
+ # get the new sysinfo state from the client
+ self._pull_pickle(host, outputdir)
+ self._pull_sysinfo_keyval(host, outputdir, mytest)
+
+
+ @log.log_and_ignore_errors("post-test server sysinfo error:")
+ def after_hook(self, mytest):
+ host, at = self._install()
+ outputdir = host.get_tmp_dir()
+
+ self._push_pickle(host, outputdir);
+ # run the post-test sysinfo script
+ at.run(_sysinfo_after_test_script % outputdir,
+ results_dir=self.job.resultdir)
+
+ self._pull_sysinfo_keyval(host, outputdir, mytest)
+
+
def runtest(job, url, tag, args, dargs):
if not dargs.pop('disable_sysinfo', False):
logger = _sysinfo_logger(job)
- logging_args = [logger.before_hook, logger.after_hook]
+ logging_args = [logger.before_hook, logger.after_hook,
+ logger.before_iteration_hook,
+ logger.after_iteration_hook]
else:
logging_args = [None, None]
common_test.runtest(job, url, tag, args, dargs, locals(), globals(),
