Difference between revisions of "Lab Test Printk Times"
m (Bot (Edward's framework)) |
m (Add categories) |
||
(One intermediate revision by one other user not shown) | |||
Line 24: | Line 24: | ||
== Download == | == Download == | ||
Here is the test script: | Here is the test script: | ||
− | * [[ | + | * 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 15: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:
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]