Lab Test Printk Times

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

import os, sys import commands import re import time
 * 1) !/usr/bin/python
 * 2) printk-times-test.py - python routine to test printk-times
 * 3) To Do for printk-times-test.py
 * 4) To Do for test framework:
 * 5)  (see preset-test.py)
 * 6) BUGS:
 * 1) To Do for test framework:
 * 2)  (see preset-test.py)
 * 3) BUGS:
 * 1) BUGS:

MAJOR_VERSION = 0 MINOR_VERSION = 8


 * 1) Define some globals for this test suite
 * 1) Define some globals for this test suite

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


 * 1) FIXTHIS - following attributes should be detected automatically (per board)?
 * 2) (use 'target info -n ' ???)

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


 * 1) Define some convience classes and functions
 * 1) Define some convience classes and functions

def usage: print """Usage: %s [-h]

where 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

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
 * 1) unused right now - may use later to get value for manual_reset

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 " 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)

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

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

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

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

def test_003(target, test_run):
 * 1) PRINTK_TIMES-003
 * 1) PRINTK_TIMES-003

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")

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

# 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\] (.*)" 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)

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

# 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...]