Difference between revisions of "Lab Test Printk Times"

From eLinux.org
Jump to: navigation, search
m (Bot (Edward's framework))
 
m (Add categories)
 
(One intermediate revision by one user not shown)
Line 24: Line 24:
 
== Download ==
 
== Download ==
 
Here is the test script:
 
Here is the test script:
−
* [[Media:printk-times-test-0.8.py]]
+
* printk-times-test-0.8.py
 +
 
 +
<pre>
 +
#!/usr/bin/python
 +
#
 +
# printk-times-test.py - python routine to test printk-times
 +
#
 +
# To Do for printk-times-test.py
 +
#
 +
# To Do for test framework:
 +
#  (see preset-test.py)
 +
#
 +
# BUGS:
 +
#
 +
import os, sys
 +
import commands
 +
import re
 +
import time
 +
 
 +
MAJOR_VERSION = 0
 +
MINOR_VERSION = 8
 +
 
 +
######################################
 +
# Define some globals for this test suite
 +
 
 +
test_suite_name="PRINTK_TIMES"
 +
src_dir = "test-linux"
 +
test_data_dir = "../test-data"
 +
 
 +
# FIXTHIS - following attributes should be detected automatically (per board)?
 +
# (use 'target info -n <attribute>' ???)
 +
 
 +
# indicate if target board needs manual reset
 +
# board reset must be one of: "manual", "console reboot", and "hardware"
 +
# uncomment the appropriate line for the board
 +
# FIXTHIS - should detect this from 'target info -n reset_type'
 +
#board_reset = "manual"
 +
board_reset = "console reboot"
 +
#board_reset = "hardware"
 +
# number of seconds to wait for board to reset
 +
reset_sleep = 30
 +
 
 +
######################################
 +
# Define some convience classes and functions
 +
 
 +
def usage():
 +
print """Usage: %s [-h] <target>
 +
 
 +
where <target> is the name of the target to be used with
 +
the 'target' command.
 +
 
 +
-h show this usage help
 +
-V show version information
 +
""" % os.path.basename(sys.argv[0])
 +
 
 +
class test_run_class:
 +
def __init__(self, suite_name):
 +
self.suite_name = suite_name
 +
self.set_id('001')
 +
self.results_list = []
 +
 
 +
def set_id(self, id):
 +
self.id = self.suite_name+"-"+id
 +
 
 +
def show_results(self, format='text'):
 +
for (rtype, result, extra_data) in self.results_list:
 +
# FIXTHIS - rtype is just thrown away right now
 +
# FIXTHIS - should vary output depending on format arg
 +
print result
 +
 
 +
def result_out(test_run, msg, extra_data=''):
 +
out_msg = "[TEST: %s] Result - %s" % (test_run.id, msg)
 +
print out_msg
 +
test_run.results_list.append(("result", out_msg, extra_data))
 +
 
 +
def success(test_run, msg, extra_data=''):
 +
out_msg = "[TEST: %s] Success - %s" % (test_run.id, msg)
 +
print out_msg
 +
test_run.results_list.append(("success", out_msg, extra_data))
 +
 
 +
def failure(test_run, msg, extra_data=''):
 +
out_msg = "[TEST: %s] Failure - %s" % (test_run.id, msg)
 +
print out_msg
 +
test_run.results_list.append(("failure", out_msg, extra_data))
 +
 
 +
def do_command(cmd, exception_on_error=0):
 +
print "  Executing '%s'" % cmd
 +
(rcode, result) = commands.getstatusoutput(cmd)
 +
if rcode:
 +
err_str = 'Error running cmd "%s"' % cmd
 +
print err_str
 +
print 'command output=%s' % result
 +
if exception_on_error:
 +
raise ValueError, err_str
 +
return rcode
 +
 
 +
# unused right now - may use later to get value for manual_reset
 +
def get_target_value(target, var_name):
 +
cmd = "target %s info -n %s" % (target, var_name)
 +
(rcode, result) = commands.getstatusoutput(cmd)
 +
if rcode:
 +
err_str = 'Error running cmd "%s"' % cmd
 +
raise ValueError, err_str
 +
value = result
 +
return value
 +
 
 +
def reset_target(target, reset_type):
 +
# perform the operation, supported by the target, for restarting the board
 +
if reset_type == "hardware":
 +
rcode = do_command("target %s reset" % target)
 +
elif reset_type == "console reboot":
 +
rcode = do_command("target %s run reboot" % target)
 +
elif reset_type == "manual":
 +
print "*** Manual reset required - please reset the board and hit <enter>"
 +
sys.stdin.readline()
 +
else:
 +
print "Unsupported board_reset value - %s" % reset_type
 +
 
 +
# wait a bit
 +
print "Sleeping %d seconds to wait for board to reset" % reset_sleep
 +
time.sleep(reset_sleep)
 +
 +
def test_setup(target, test_run):
 +
# prepare for a test run
 +
# 1. get kernel
 +
# 1.1 make build dir
 +
# 1.2 make test data dir
 +
# 2. get default config
 +
 
 +
print "Doing test preparation for %s tests..." % test_run.suite_name
 +
 
 +
# auto-detect that kernel is already present in src_dir
 +
# and skip the get_kernel automatically
 +
rcode = do_command('test -f %s/gk_marker' % src_dir)
 +
if rcode:
 +
do_command("target %s get_kernel -o %s" % (target, src_dir), 1)
 +
do_command('echo "get_kernel completed" >%s/gk_marker' % src_dir)
 +
else:
 +
print "*** Skipping get_kernel (get_kernel marker found)"
 +
 
 +
os.chdir(src_dir)
 +
build_dir = "../build/%s" % target
 +
do_command("install -d %s" % build_dir, 1)
 +
do_command("install -d %s" % test_data_dir, 1)
 +
do_command("target %s get_config" % target, 1)
 +
 
 +
#############################################
 +
# PRINTK_TIMES-001
 +
def test_001(target, test_run):
 +
test_run.set_id("001")
 +
print "Running test %s..." % test_run.id
 +
 
 +
# set specific configuration values
 +
#    * PRINTK_TIMES=n
 +
#    * LOG_BUF_SHIFT=17
 +
#    * quiet
 +
 
 +
rcode = do_command("target %s set_config CONFIG_PRINTK_TIME=n" % target, 1)
 +
rcode = do_command("target %s set_config CONFIG_LOG_BUF_SHIFT=17" % target, 1)
 +
rcode = do_command('target %s set_config "CONFIG_CMDLINE+=\\" quiet time\\""' % target, 1)
 +
 
 +
# FIXTHIS - verify these configs were accepted
 +
 
 +
# 4. build kernel
 +
rcode = do_command("target %s kbuild" % target)
 +
if rcode:
 +
failure(test_run, "Could not build kernel")
 +
return
 +
 
 +
# FIXTHIS - verify that the kernel built OK
 +
 
 +
# 5. install kernel
 +
rcode = do_command("target %s kinstall" % target, 1)
 +
if rcode:
 +
failure(test_run, "Could not install kernel")
 +
return
 +
 
 +
# 6. reset target
 +
reset_target(target, board_reset)
 +
 
 +
# FIXTHIS - verify that the running kernel is the one just built
 +
 
 +
# 7. run dmesg
 +
cmd = 'target %s run "dmesg -s 64000 "' % target
 +
print "  Executing '%s'" % cmd
 +
(rcode, result) = commands.getstatusoutput(cmd)
 +
if rcode:
 +
print "Error collecting results from dmesg"
 +
print "result=", result
 +
 
 +
#print "result=\n", result
 +
lines = result.split('\n')
 +
 
 +
# check for timing data starting after line starting
 +
# with "Kernel command line:"
 +
cmdline_pat = ".*Kernel command line:"
 +
time_pat = "^\[[ .0-9]*\] (.*)"
 +
found = 0
 +
i = 0
 +
match_line = ""
 +
while not found and i<len(lines):
 +
m = re.match(cmdline_pat, lines[i])
 +
if m:
 +
found = 1
 +
match_line = lines[i]
 +
if i+1<len(lines):
 +
next_line = lines[i+1]
 +
else:
 +
next_line = "(after last dmesg line - no more lines)"
 +
break
 +
i += 1
 +
 
 +
 
 +
m = re.match(time_pat, next_line)
 +
if not found:
 +
failure(test_run, "Could not find line with kernel command line in dmesg output", result)
 +
 
 +
# check for no time output on Kernel command line
 +
elif not match_line.startswith("Kernel command line:"):
 +
failure(test_run, "Could not find line starting with 'Kernel command line:'", "matching line was: '%s'" % match_line)
 +
 
 +
# check for correct time pattern on next_line
 +
elif not m:
 +
failure(test_run, "No time pattern found for line: '%s'" % next_line)
 +
else:
 +
success(test_run, "Found printk time on line after kernel command line: '%s'" % next_line, result)
 +
 +
 
 +
#############################################
 +
# PRINTK_TIMES-002
 +
def test_002(target, test_run):
 +
test_run.set_id("002")
 +
print "Running test %s..." % test_run.id
 +
 
 +
# 3. set specific configuration values
 +
# first, reset to generic config again
 +
do_command("target %s get_config" % target, 1)
 +
 
 +
do_command("target %s set_config CONFIG_PRINTK_TIME=y" % target, 1)
 +
do_command("target %s set_config CONFIG_LOG_BUF_SHIFT=17" % target, 1)
 +
do_command('target %s set_config "CONFIG_CMDLINE+=\\" quiet\\""' % target, 1)
 +
 
 +
# 4. build kernel
 +
rcode = do_command("target %s kbuild" % target)
 +
#print "*** Skipping kbuild"
 +
if rcode:
 +
failure(test_run, "Could not build kernel")
 +
return
 +
 
 +
# 5. install kernel
 +
rcode = do_command("target %s kinstall" % target, 1)
 +
if rcode:
 +
failure(test_run, "Could not install kernel")
 +
return
 +
 
 +
# 6. reset target
 +
reset_target(target, board_reset)
 +
 
 +
# 7. run dmesg
 +
cmd = 'target %s run "dmesg -s 64000 >/tmp/time_data.txt ; cat /tmp/time_data.txt"' % target
 +
print "  Executing '%s'" % cmd
 +
(rcode, result) = commands.getstatusoutput(cmd)
 +
if rcode:
 +
print "Error collecting results from dmesg"
 +
print "result=", result
 +
 
 +
print "result=\n", result
 +
lines = result.split('\n')
 +
 
 +
# copy time_data to host
 +
cmd = 'target %s cp target:/tmp/time_data.txt %s' % (target, test_data_dir)
 +
print "  Executing '%s'" % cmd
 +
(rcode, result) = commands.getstatusoutput(cmd)
 +
if rcode:
 +
print "Error copying time_data.txt from target"
 +
print "result=", result
 +
 
 +
time_pat = "^\[([ .0-9]*)\] (.*)"
 +
zero_time_pat = "^\[([ .0]*)\] (.*)"
 +
lines_ok = 1
 +
first_nonzero_line = ""
 +
first_nonzero_line_index = 999
 +
i = 0
 +
while i<len(lines):
 +
line = lines[i]
 +
# skip lines from test system
 +
if line.startswith("cmd=") or line.startswith("result="):
 +
i += 1
 +
continue
 +
 
 +
m = re.match(time_pat, line)
 +
if not m:
 +
failure(test_run, "No time pattern found for line: '%s'" % line)
 +
lines_ok = 0
 +
break
 +
if not first_nonzero_line:
 +
m = re.match(zero_time_pat, line)
 +
if not m:
 +
first_nonzero_line = line
 +
first_nonzero_line_index = i
 +
i += 1
 +
 
 +
if lines_ok:
 +
success(test_run, "Printk lines have timing data")
 +
 
 +
# FIXTHIS - should do additional checks for line data sanity
 +
# possible tests:
 +
#  * is the data monotonically increasing?
 +
#  * is the data within 5 seconds for each entry?
 +
if first_nonzero_line == 999:
 +
failure(test_run, "All lines had zero time!!")
 +
else:
 +
result_out(test_run, "First line with nonzero data is %d. '%s'" % (first_nonzero_line_index, first_nonzero_line))
 +
 
 +
#############################################
 +
# PRINTK_TIMES-003
 +
def test_003(target, test_run):
 +
 
 +
test_run.set_id("003")
 +
print "Running test %s..." % test_run.id
 +
 
 +
# run show_delta command and verify that deltas are printed
 +
cmd = 'scripts/show_delta %s/time_data.txt' % test_data_dir
 +
print "  Executing '%s'" % cmd
 +
(rcode, result) = commands.getstatusoutput(cmd)
 +
if rcode:
 +
print "Error collecting results from show_delta"
 +
print "result=", result
 +
 
 +
print "result=\n", result
 +
lines = result.split('\n')
 +
 
 +
# check for properly formatted time-delta in lines
 +
# checks:
 +
#  * each line shows absolute and relative time
 +
#  * for each line, the relative valus is the difference
 +
#  between this line and the next line
 +
delta_time_pat = "^\[([ .0-9]*) \< ([ \-.0-9]*) \>\] (.*)"
 +
lines_ok = 1
 +
deltas_ok = 1
 +
i = 0
 +
last_abs_time = 999
 +
last_delta_time = 999
 +
while i<len(lines):
 +
m = re.match(delta_time_pat, lines[i])
 +
if not m:
 +
failure(test_run, "No delta time pattern found for line: '%s'" % line)
 +
lines_ok = 0
 +
break
 +
abs_time = float(m.group(1))
 +
delta_time = float(m.group(2))
 +
if last_abs_time != 999:
 +
# NOTE: have to use str() comparison here because
 +
# comparison of raw floats didn't work (it might be a python
 +
# bug - but I don't have time to figure it out)
 +
if str(last_abs_time + delta_time) != str(abs_time):
 +
failure(test_run, "Delta time incorrect for lines: '%s' and\n '%s'" % (lines[i-1], lines[i]))
 +
deltas_ok = 0
 +
 
 +
last_abs_time = abs_time
 +
i += 1
 +
 
 +
if lines_ok:
 +
success(test_run, "All lines have delta time values")
 +
 
 +
if deltas_ok:
 +
success(test_run, "All delta time values are correct")
 +
 
 +
#############################################
 +
# PRINTK_TIMES-004
 +
def test_004(target, test_run):
 +
test_run.set_id("004")
 +
print "Running test %s..." % test_run.id
 +
 
 +
# run show_delta command with times relative to a base
 +
cmd = 'scripts/show_delta -b Calib %s/time_data.txt | grep -3 Calib' % test_data_dir
 +
print "  Executing '%s'" % cmd
 +
(rcode, result) = commands.getstatusoutput(cmd)
 +
if rcode:
 +
print "Error collecting results from show_delta"
 +
print "result=", result
 +
 
 +
#print "result=\n", result
 +
lines = result.split('\n')
 +
 
 +
# checks:
 +
#  * relative time is 0.00000 on 'Calibrating delay loop' line
 +
#  * line prior to 'Calibrating' line has negative delta
 +
#  * line after 'Calibrating' line has positive delta
 +
calib_pat = ".*Calibrating delay.*"
 +
 
 +
# find "Calibrating delay" line
 +
calib_line = ""
 +
calib_i = 999
 +
i = 0
 +
while i<len(lines):
 +
m = re.match(calib_pat, lines[i])
 +
if m:
 +
calib_line = lines[i]
 +
calib_i = i
 +
break
 +
i += 1
 +
 +
print "calib_line = ", calib_line
 +
print "calib_i = ", calib_i
 +
if not calib_line:
 +
failure(test_run, 'Could not find "Calibrating delay" line in dmesg output')
 +
return
 +
 
 +
delta_time_pat = "^\[([ .0-9]*) \< ([ \-.0-9]*) \>\] (.*)"
 +
m = re.match(delta_time_pat, calib_line)
 +
delta_time = float(m.group(2))
 +
if str(delta_time) != "0.0":
 +
failure(test_run, "Delta time incorrect for line: '%s' - should be 0" % calib_line)
 +
else:
 +
success(test_run, "Delta time value is correct for line: '%s' - should be 0" % calib_line)
 +
 +
# check line before 'Calibrating' line
 +
line = lines[calib_i-1]
 +
print "line=", line
 +
m = re.match(delta_time_pat, line)
 +
delta_time = float(m.group(2))
 +
if delta_time >= 0.0:
 +
failure(test_run, "Delta time incorrect for line: '%s' - should be < 0" % line)
 +
else:
 +
success(test_run, "Delta time value correct for line: '%s' - should be < 0" % line)
 +
 
 +
# check line after 'Calibrating' line
 +
line = lines[calib_i+1]
 +
m = re.match(delta_time_pat, line)
 +
delta_time = float(m.group(2))
 +
if delta_time <= 0.0:
 +
failure(test_run, "Delta time incorrect for line: '%s' - should be > 0" % line)
 +
else:
 +
success(test_run, "Delta time value correct for line: '%s' - should be > 0" % line)
 +
 
 +
#############################################
 +
# PRINTK_TIMES-005
 +
# test timing resolution and accuracy
 +
#
 +
def test_005(target, test_run):
 +
test_run.set_id("005")
 +
print "Running test %s..." % test_run.id
 +
 
 +
# 3. set specific configuration values
 +
# first, reset to generic config again
 +
rcode = do_command("target %s get_config" % target, 1)
 +
 
 +
rcode = do_command("target %s set_config CONFIG_PRINTK_TIME=y" % target, 1)
 +
rcode = do_command("target %s set_config CONFIG_LOG_BUF_SHIFT=17" % target, 1)
 +
rcode = do_command('target %s set_config "CONFIG_CMDLINE+=\\" quiet\\""' % target, 1)
 +
rcode = do_command('target %s set_config "CONFIG_ALP_TIMING_TEST=y"' % target, 1)
 +
 
 +
# 4. build kernel
 +
rcode = do_command("target %s kbuild" % target)
 +
#print "*** Skipping kbuild"
 +
if rcode:
 +
failure(test_run, "Could not build kernel")
 +
 
 +
# 5. install kernel
 +
if not rcode:
 +
rcode = do_command("target %s kinstall" % target, 1)
 +
if rcode:
 +
failure(test_run, "Could not install kernel")
 +
 
 +
 
 +
# 6. reset target
 +
if not rcode:
 +
reset_target(target, board_reset)
 +
 
 +
# 7. run dmesg
 +
if not rcode:
 +
cmd = 'target %s run "dmesg -s 64000 | grep ALP >/tmp/alp-delays.txt"' % target
 +
print "  Executing '%s'" % cmd
 +
(rcode, result) = commands.getstatusoutput(cmd)
 +
if rcode:
 +
print "Error collecting results from dmesg"
 +
print "result=", result
 +
 
 +
# copy time_data to host
 +
cmd = 'target %s cp target:/tmp/alp-delays.txt %s' % (target, test_data_dir)
 +
print "  Executing '%s'" % cmd
 +
(rcode, result) = commands.getstatusoutput(cmd)
 +
if rcode:
 +
print "Error copying alp-delays.txt from target"
 +
print "result=", result
 +
 
 +
# get lines with delta values
 +
 
 +
# run show_delta command on data
 +
cmd = 'scripts/show_delta %s/alp-delays.txt' % test_data_dir
 +
print "  Executing '%s'" % cmd
 +
(rcode, result) = commands.getstatusoutput(cmd)
 +
if rcode:
 +
print "Error collecting results from show_delta"
 +
print "result=", result
 +
 
 +
#print "result=\n", result
 +
lines = result.split('\n')
 +
 
 +
# check for time1 delta within 5 percent of requested time
 +
delta_time_pat = "^\[([ .0-9]*) \< ([ \-.0-9]*) \>\] (.*)"
 +
line = lines[1]
 +
value = 12345.0 # usecs
 +
m = re.match(delta_time_pat, line)
 +
delta_time = float(m.group(2))*1000000
 +
 
 +
# FIXTHIS - would be nice to compare with usec value in line itself
 +
epsilon = .05 * value
 +
if (delta_time < value - epsilon) or (delta_time > value + epsilon):
 +
failure(test_run, "Delta time incorrect for line: '%s' - should be within 5% of %f usecs" % (line, value))
 +
else:
 +
success(test_run, "Delta time value is correct for line: '%s'" % line)
 +
 
 +
# check for time2 delta within 5 percent of requested time
 +
line = lines[2]
 +
value = 1234567 # usecs
 +
m = re.match(delta_time_pat, line)
 +
delta_time = float(m.group(2))*1000000
 +
 
 +
# FIXTHIS - would be nice to compare with usec value in line itself
 +
epsilon = .05 * value
 +
if (delta_time < value - epsilon) or (delta_time > value + epsilon):
 +
failure(test_run, "Delta time incorrect for line: '%s' - should be within 5% of %f usecs" % (line, value))
 +
else:
 +
success(test_run, "Delta time value is correct for line: '%s'" % line)
 +
 +
# FIXTHIS - should also check resolution of timing clock
 +
# how?? - see if microseconds portion of times are zeros
 +
 
 +
def main():
 +
# Parse the command line
 +
if len(sys.argv)<2:
 +
print "Error: missing target to run test on."
 +
usage()
 +
sys.exit(1)
 +
 
 +
if '-h' in sys.argv:
 +
usage()
 +
sys.exit(1)
 +
 
 +
if '-V' in sys.argv:
 +
print "printk-times-test.py Version %d.%d" % (MAJOR_VERSION, MINOR_VERSION)
 +
sys.exit(1)
 +
 
 +
target = sys.argv[1]
 +
 
 +
# verify that target is supported by 'target'
 +
(rcode, result) = commands.getstatusoutput('target list -q')
 +
if rcode:
 +
print "Error: Problem running 'target list'"
 +
sys.exit(1)
 +
 
 +
tlist = result.split("\n");
 +
if target not in tlist:
 +
print "Error: target '%s' not supported on this host." % target
 +
print "Available targets are:"
 +
for t in tlist:
 +
print "  %s" % t
 +
print
 +
usage()
 +
sys.exit(1)
 +
 
 +
#################################################
 +
# Here is the actual testing
 +
test_run = test_run_class(test_suite_name)
 +
 
 +
print "Running tests on target: %s" % target
 +
test_setup(target, test_run)
 +
test_001(target, test_run)
 +
test_002(target, test_run)
 +
test_003(target, test_run)
 +
test_004(target, test_run)
 +
test_005(target, test_run)
 +
 
 +
print "\n###########################################"
 +
print "Results summary:"
 +
test_run.show_results()
 +
 
 +
if __name__=="__main__":
 +
main()
 +
 
 +
</pre>
  
 
== To Do ==
 
== To Do ==
Line 32: Line 614:
 
== Notes ==
 
== Notes ==
 
[put miscellaneous notes here]
 
[put miscellaneous notes here]
 +
 +
[[Category:Open Test Lab]]
 +
[[Category:Printk]]

Latest revision as of 22:40, 27 October 2011

This page describes a test developed for use with the CELF Open Test Lab. See Open Test Lab for details.

Table Of Contents:


Contents

Description

This test validates whether a kernel supports the printk-times feature, which is to append a timestamp to each line of kernel printk output. Printk-times is a valuable tool for measuring the (macro-level) timing of kernel events during bootup.

This test determines whether printk-times can be used from the kernel command line or as a compile-time configuration option. Also, the test verifies the output of the show_delta command (used to calculate relative times in the printk output). Finally, the test validates the timing values produced by the kernel for the timestamps.

For more information about printk-times, see Printk Times

Pre-requisites

This test needs 'target' to be installed and correctly configured in order to operate.

Please see Target Program Usage Guide for instructions for installing, configuring and using that program.

Download

Here is the test script:

  • printk-times-test-0.8.py 
#!/usr/bin/python
#
# printk-times-test.py - python routine to test printk-times
#
# To Do for printk-times-test.py
#
# To Do for test framework:
#  (see preset-test.py)
#
# BUGS:
#
import os, sys
import commands
import re
import time

MAJOR_VERSION = 0
MINOR_VERSION = 8

######################################
# Define some globals for this test suite

test_suite_name="PRINTK_TIMES"
src_dir = "test-linux"
test_data_dir = "../test-data"

# FIXTHIS - following attributes should be detected automatically (per board)?
# (use 'target info -n <attribute>' ???)

# indicate if target board needs manual reset
# board reset must be one of: "manual", "console reboot", and "hardware"
# uncomment the appropriate line for the board
# FIXTHIS - should detect this from 'target info -n reset_type'
#board_reset = "manual"
board_reset = "console reboot"
#board_reset = "hardware"
# number of seconds to wait for board to reset
reset_sleep = 30

######################################
# Define some convience classes and functions

def usage():
	print """Usage: %s [-h] <target>

where <target> is the name of the target to be used with
the 'target' command.

-h	show this usage help
-V	show version information
""" % os.path.basename(sys.argv[0])

class test_run_class:
	def __init__(self, suite_name):
		self.suite_name = suite_name
		self.set_id('001')
		self.results_list = []

	def set_id(self, id):
		self.id = self.suite_name+"-"+id

	def show_results(self, format='text'):
		for (rtype, result, extra_data) in self.results_list:
			# FIXTHIS - rtype is just thrown away right now
			# FIXTHIS - should vary output depending on format arg
			print result

def result_out(test_run, msg, extra_data=''):
	out_msg = "[TEST: %s] Result - %s" % (test_run.id, msg)
	print out_msg
	test_run.results_list.append(("result", out_msg, extra_data))

def success(test_run, msg, extra_data=''):
	out_msg = "[TEST: %s] Success - %s" % (test_run.id, msg)
	print out_msg
	test_run.results_list.append(("success", out_msg, extra_data))

def failure(test_run, msg, extra_data=''):
	out_msg = "[TEST: %s] Failure - %s" % (test_run.id, msg)
	print out_msg
	test_run.results_list.append(("failure", out_msg, extra_data))

def do_command(cmd, exception_on_error=0):
	print "  Executing '%s'" % cmd
	(rcode, result) = commands.getstatusoutput(cmd)
	if rcode:
		err_str = 'Error running cmd "%s"' % cmd
		print err_str
		print 'command output=%s' % result
		if exception_on_error:
			raise ValueError, err_str
	return rcode

# unused right now - may use later to get value for manual_reset
def get_target_value(target, var_name):
	cmd = "target %s info -n %s" % (target, var_name)
	(rcode, result) = commands.getstatusoutput(cmd)
	if rcode:
		err_str = 'Error running cmd "%s"' % cmd
		raise ValueError, err_str
	value = result
	return value

def reset_target(target, reset_type):
	# perform the operation, supported by the target, for restarting the board
	if reset_type == "hardware":
		rcode = do_command("target %s reset" % target)
	elif reset_type == "console reboot":
		rcode = do_command("target %s run reboot" % target)
	elif reset_type == "manual":
		print "*** Manual reset required - please reset the board and hit <enter>"
		sys.stdin.readline()
	else:
		print "Unsupported board_reset value - %s" % reset_type

	# wait a bit
	print "Sleeping %d seconds to wait for board to reset" % reset_sleep
	time.sleep(reset_sleep)
	
def test_setup(target, test_run):
	# prepare for a test run
	# 1. get kernel
	# 1.1 make build dir
	# 1.2 make test data dir
	# 2. get default config

	print "Doing test preparation for %s tests..." % test_run.suite_name

	# auto-detect that kernel is already present in src_dir
	# and skip the get_kernel automatically
	rcode = do_command('test -f %s/gk_marker' % src_dir)
	if rcode:
		do_command("target %s get_kernel -o %s" % (target, src_dir), 1)
		do_command('echo "get_kernel completed" >%s/gk_marker' % src_dir)
	else:
		print "*** Skipping get_kernel (get_kernel marker found)"

	os.chdir(src_dir)
	build_dir = "../build/%s" % target
	do_command("install -d %s" % build_dir, 1)
	do_command("install -d %s" % test_data_dir, 1)
	do_command("target %s get_config" % target, 1)

#############################################
# PRINTK_TIMES-001
def test_001(target, test_run):
	test_run.set_id("001")
	print "Running test %s..." % test_run.id

	# set specific configuration values
	#    * PRINTK_TIMES=n
	#    * LOG_BUF_SHIFT=17
	#    * quiet

	rcode = do_command("target %s set_config CONFIG_PRINTK_TIME=n" % target, 1)
	rcode = do_command("target %s set_config CONFIG_LOG_BUF_SHIFT=17" % target, 1)
	rcode = do_command('target %s set_config "CONFIG_CMDLINE+=\\" quiet time\\""' % target, 1)

	# FIXTHIS - verify these configs were accepted

	# 4. build kernel
	rcode = do_command("target %s kbuild" % target)
	if rcode:
		failure(test_run, "Could not build kernel")
		return

	# FIXTHIS - verify that the kernel built OK

	# 5. install kernel
	rcode = do_command("target %s kinstall" % target, 1)
	if rcode:
		failure(test_run, "Could not install kernel")
		return

	# 6. reset target
	reset_target(target, board_reset)

	# FIXTHIS - verify that the running kernel is the one just built

	# 7. run dmesg
	cmd = 'target %s run "dmesg -s 64000 "' % target
	print "  Executing '%s'" % cmd
	(rcode, result) = commands.getstatusoutput(cmd)
	if rcode:
		print "Error collecting results from dmesg"
		print "result=", result

	#print "result=\n", result
	lines = result.split('\n')

	# check for timing data starting after line starting
	# with "Kernel command line:"
	cmdline_pat = ".*Kernel command line:"
	time_pat = "^\[[ .0-9]*\] (.*)"
	found = 0
	i = 0
	match_line = ""
	while not found and i<len(lines):
		m = re.match(cmdline_pat, lines[i])
		if m:
			found = 1
			match_line = lines[i]
			if i+1<len(lines):
				next_line = lines[i+1]
			else:
				next_line = "(after last dmesg line - no more lines)"
			break
		i += 1


	m = re.match(time_pat, next_line)
	if not found:
		failure(test_run, "Could not find line with kernel command line in dmesg output", result)

	# check for no time output on Kernel command line
	elif not match_line.startswith("Kernel command line:"):
		failure(test_run, "Could not find line starting with 'Kernel command line:'", "matching line was: '%s'" % match_line)

	# check for correct time pattern on next_line
	elif not m:
		failure(test_run, "No time pattern found for line: '%s'" % next_line)
	else:
		success(test_run, "Found printk time on line after kernel command line: '%s'" % next_line, result)
			

#############################################
# PRINTK_TIMES-002
def test_002(target, test_run):
	test_run.set_id("002")
	print "Running test %s..." % test_run.id

	# 3. set specific configuration values
	# first, reset to generic config again
	do_command("target %s get_config" % target, 1)

	do_command("target %s set_config CONFIG_PRINTK_TIME=y" % target, 1)
	do_command("target %s set_config CONFIG_LOG_BUF_SHIFT=17" % target, 1)
	do_command('target %s set_config "CONFIG_CMDLINE+=\\" quiet\\""' % target, 1)

	# 4. build kernel
	rcode = do_command("target %s kbuild" % target)
	#print "*** Skipping kbuild"
	if rcode:
		failure(test_run, "Could not build kernel")
		return

	# 5. install kernel
	rcode = do_command("target %s kinstall" % target, 1)
	if rcode:
		failure(test_run, "Could not install kernel")
		return

	# 6. reset target
	reset_target(target, board_reset)

	# 7. run dmesg
	cmd = 'target %s run "dmesg -s 64000 >/tmp/time_data.txt ; cat /tmp/time_data.txt"' % target
	print "  Executing '%s'" % cmd
	(rcode, result) = commands.getstatusoutput(cmd)
	if rcode:
		print "Error collecting results from dmesg"
		print "result=", result

	print "result=\n", result
	lines = result.split('\n')

	# copy time_data to host
	cmd = 'target %s cp target:/tmp/time_data.txt %s' % (target, test_data_dir)
	print "  Executing '%s'" % cmd
	(rcode, result) = commands.getstatusoutput(cmd)
	if rcode:
		print "Error copying time_data.txt from target"
		print "result=", result

	time_pat = "^\[([ .0-9]*)\] (.*)"
	zero_time_pat = "^\[([ .0]*)\] (.*)"
	lines_ok = 1
	first_nonzero_line = ""
	first_nonzero_line_index = 999
	i = 0
	while i<len(lines):
		line = lines[i]
		# skip lines from test system
		if line.startswith("cmd=") or line.startswith("result="):
			i += 1
			continue

		m = re.match(time_pat, line)
		if not m:
			failure(test_run, "No time pattern found for line: '%s'" % line)
			lines_ok = 0
			break
		if not first_nonzero_line:
			m = re.match(zero_time_pat, line)
			if not m:
				first_nonzero_line = line
				first_nonzero_line_index = i
		i += 1

	if lines_ok:
		success(test_run, "Printk lines have timing data")

	# FIXTHIS - should do additional checks for line data sanity
	# possible tests:
	#  * is the data monotonically increasing?
	#  * is the data within 5 seconds for each entry?
	if first_nonzero_line == 999:
		failure(test_run, "All lines had zero time!!")
	else:
		result_out(test_run, "First line with nonzero data is %d. '%s'" % (first_nonzero_line_index, first_nonzero_line))

#############################################
# PRINTK_TIMES-003
def test_003(target, test_run):

	test_run.set_id("003")
	print "Running test %s..." % test_run.id

	# run show_delta command and verify that deltas are printed
	cmd = 'scripts/show_delta %s/time_data.txt' % test_data_dir
	print "  Executing '%s'" % cmd
	(rcode, result) = commands.getstatusoutput(cmd)
	if rcode:
		print "Error collecting results from show_delta"
		print "result=", result

	print "result=\n", result
	lines = result.split('\n')

	# check for properly formatted time-delta in lines
	# checks:
	#  * each line shows absolute and relative time
	#  * for each line, the relative valus is the difference
	#  between this line and the next line
	delta_time_pat = "^\[([ .0-9]*) \< ([ \-.0-9]*) \>\] (.*)"
	lines_ok = 1
	deltas_ok = 1
	i = 0
	last_abs_time = 999
	last_delta_time = 999
	while i<len(lines):
		m = re.match(delta_time_pat, lines[i])
		if not m:
			failure(test_run, "No delta time pattern found for line: '%s'" % line)
			lines_ok = 0
			break
		abs_time = float(m.group(1))
		delta_time = float(m.group(2))
		if last_abs_time != 999:
			# NOTE: have to use str() comparison here because
			# comparison of raw floats didn't work (it might be a python
			# bug - but I don't have time to figure it out)
			if str(last_abs_time + delta_time) != str(abs_time):
				failure(test_run, "Delta time incorrect for lines: '%s' and\n '%s'" % (lines[i-1], lines[i]))
				deltas_ok = 0

		last_abs_time = abs_time
		i += 1

	if lines_ok:
		success(test_run, "All lines have delta time values")

	if deltas_ok:
		success(test_run, "All delta time values are correct")

#############################################
# PRINTK_TIMES-004
def test_004(target, test_run):
	test_run.set_id("004")
	print "Running test %s..." % test_run.id

	# run show_delta command with times relative to a base
	cmd = 'scripts/show_delta -b Calib %s/time_data.txt | grep -3 Calib' % test_data_dir
	print "  Executing '%s'" % cmd
	(rcode, result) = commands.getstatusoutput(cmd)
	if rcode:
		print "Error collecting results from show_delta"
		print "result=", result

	#print "result=\n", result
	lines = result.split('\n')

	# checks:
	#  * relative time is 0.00000 on 'Calibrating delay loop' line
	#  * line prior to 'Calibrating' line has negative delta
	#  * line after 'Calibrating' line has positive delta
	calib_pat = ".*Calibrating delay.*"

	# find "Calibrating delay" line
	calib_line = ""
	calib_i = 999
	i = 0
	while i<len(lines):
		m = re.match(calib_pat, lines[i])
		if m:
			calib_line = lines[i]
			calib_i = i
			break
		i += 1
	
	print "calib_line = ", calib_line
	print "calib_i = ", calib_i
	if not calib_line:
		failure(test_run, 'Could not find "Calibrating delay" line in dmesg output')
		return

	delta_time_pat = "^\[([ .0-9]*) \< ([ \-.0-9]*) \>\] (.*)"
	m = re.match(delta_time_pat, calib_line)
	delta_time = float(m.group(2))
	if str(delta_time) != "0.0":
		failure(test_run, "Delta time incorrect for line: '%s' - should be 0" % calib_line)
	else:
		success(test_run, "Delta time value is correct for line: '%s' - should be 0" % calib_line)
		
	# check line before 'Calibrating' line
	line = lines[calib_i-1]
	print "line=", line
	m = re.match(delta_time_pat, line)
	delta_time = float(m.group(2))
	if delta_time >= 0.0:
		failure(test_run, "Delta time incorrect for line: '%s' - should be < 0" % line)
	else:
		success(test_run, "Delta time value correct for line: '%s' - should be < 0" % line)

	# check line after 'Calibrating' line
	line = lines[calib_i+1]
	m = re.match(delta_time_pat, line)
	delta_time = float(m.group(2))
	if delta_time <= 0.0:
		failure(test_run, "Delta time incorrect for line: '%s' - should be > 0" % line)
	else:
		success(test_run, "Delta time value correct for line: '%s' - should be > 0" % line)

#############################################
# PRINTK_TIMES-005
# test timing resolution and accuracy
#
def test_005(target, test_run):
	test_run.set_id("005")
	print "Running test %s..." % test_run.id

	# 3. set specific configuration values
	# first, reset to generic config again
	rcode = do_command("target %s get_config" % target, 1)

	rcode = do_command("target %s set_config CONFIG_PRINTK_TIME=y" % target, 1)
	rcode = do_command("target %s set_config CONFIG_LOG_BUF_SHIFT=17" % target, 1)
	rcode = do_command('target %s set_config "CONFIG_CMDLINE+=\\" quiet\\""' % target, 1)
	rcode = do_command('target %s set_config "CONFIG_ALP_TIMING_TEST=y"' % target, 1)

	# 4. build kernel
	rcode = do_command("target %s kbuild" % target)
	#print "*** Skipping kbuild"
	if rcode:
		failure(test_run, "Could not build kernel")

	# 5. install kernel
	if not rcode:
		rcode = do_command("target %s kinstall" % target, 1)
		if rcode:
			failure(test_run, "Could not install kernel")


	# 6. reset target
	if not rcode:
		reset_target(target, board_reset)

	# 7. run dmesg
	if not rcode:
		cmd = 'target %s run "dmesg -s 64000 | grep ALP >/tmp/alp-delays.txt"' % target
		print "  Executing '%s'" % cmd
		(rcode, result) = commands.getstatusoutput(cmd)
		if rcode:
			print "Error collecting results from dmesg"
			print "result=", result

		# copy time_data to host
		cmd = 'target %s cp target:/tmp/alp-delays.txt %s' % (target, test_data_dir)
		print "  Executing '%s'" % cmd
		(rcode, result) = commands.getstatusoutput(cmd)
		if rcode:
			print "Error copying alp-delays.txt from target"
			print "result=", result

		# get lines with delta values

	# run show_delta command on data
	cmd = 'scripts/show_delta %s/alp-delays.txt' % test_data_dir
	print "  Executing '%s'" % cmd
	(rcode, result) = commands.getstatusoutput(cmd)
	if rcode:
		print "Error collecting results from show_delta"
		print "result=", result

	#print "result=\n", result
	lines = result.split('\n')

	# check for time1 delta within 5 percent of requested time 
	delta_time_pat = "^\[([ .0-9]*) \< ([ \-.0-9]*) \>\] (.*)"
	line = lines[1]	
	value = 12345.0 # usecs
	m = re.match(delta_time_pat, line)
	delta_time = float(m.group(2))*1000000

	# FIXTHIS - would be nice to compare with usec value in line itself
	epsilon = .05 * value
	if (delta_time < value - epsilon) or (delta_time > value + epsilon):
		failure(test_run, "Delta time incorrect for line: '%s' - should be within 5% of %f usecs" % (line, value))
	else:
		success(test_run, "Delta time value is correct for line: '%s'" % line)

	# check for time2 delta within 5 percent of requested time
	line = lines[2]	
	value = 1234567 # usecs
	m = re.match(delta_time_pat, line)
	delta_time = float(m.group(2))*1000000

	# FIXTHIS - would be nice to compare with usec value in line itself
	epsilon = .05 * value
	if (delta_time < value - epsilon) or (delta_time > value + epsilon):
		failure(test_run, "Delta time incorrect for line: '%s' - should be within 5% of %f usecs" % (line, value))
	else:
		success(test_run, "Delta time value is correct for line: '%s'" % line)
		
	# FIXTHIS - should also check resolution of timing clock
	# how?? - see if microseconds portion of times are zeros

def main():
	# Parse the command line
	if len(sys.argv)<2:
		print "Error: missing target to run test on."
		usage()
		sys.exit(1)

	if '-h' in sys.argv:
		usage()
		sys.exit(1)

	if '-V' in sys.argv:
		print "printk-times-test.py Version %d.%d" % (MAJOR_VERSION, MINOR_VERSION)
		sys.exit(1)

	target = sys.argv[1]

	# verify that target is supported by 'target'
	(rcode, result) = commands.getstatusoutput('target list -q')
	if rcode:
		print "Error: Problem running 'target list'"
		sys.exit(1)

	tlist = result.split("\n");
	if target not in tlist:
		print "Error: target '%s' not supported on this host." % target
		print "Available targets are:"
		for t in tlist:
			print "   %s" % t
		print
		usage()
		sys.exit(1)

	#################################################
	# Here is the actual testing
	test_run = test_run_class(test_suite_name)

	print "Running tests on target: %s" % target
	test_setup(target, test_run)
	test_001(target, test_run)
	test_002(target, test_run)
	test_003(target, test_run)
	test_004(target, test_run)
	test_005(target, test_run)

	print "\n###########################################"
	print "Results summary:"
	test_run.show_results()

if __name__=="__main__":
	main()

To Do

Things to work on:

  • [item 1...]

Notes

[put miscellaneous notes here]

Retrieved from "http://elinux.org/index.php?title=Lab_Test_Printk_Times&oldid=72637"