============================================= printk-times-04.12.10.patch: This patch adds support for printk to output a timestamp. Signed-off-by: Geoff Levand for CELF --- Documentation/kernel-parameters.txt | 2 arch/ppc/kernel/time.c | 6 + kernel/printk.c | 58 +++++++++++++++- lib/Kconfig.debug | 9 ++ scripts/show_delta | 129 ++++++++++++++++++++++++++++++++++++ 5 files changed, 200 insertions(+), 4 deletions(-) diff -pruN -X ../cvs-admin/dontdiff tag_LINUX_2_6_9/arch/ppc/kernel/time.c branch_PRINTK_TIMES/arch/ppc/kernel/time.c --- tag_LINUX_2_6_9/arch/ppc/kernel/time.c 2004-10-22 14:40:38.000000000 -0700 +++ branch_PRINTK_TIMES/arch/ppc/kernel/time.c 2004-11-01 11:52:30.000000000 -0800 @@ -85,7 +85,13 @@ time_t last_rtc_update; unsigned tb_ticks_per_jiffy; unsigned tb_to_us; unsigned tb_last_stamp; +#if defined(CONFIG_KFI_STATIC_RUN) || defined(CONFIG_PRINTK_TIME) +/* preset value so sched_clock() works immediately at startup */ +//unsigned long tb_to_ns_scale = 2559; /* value for ebony board */ +unsigned long tb_to_ns_scale = 0; /* default value, change for your board */ +#else unsigned long tb_to_ns_scale; +#endif extern unsigned long wall_jiffies; diff -pruN -X ../cvs-admin/dontdiff tag_LINUX_2_6_9/Documentation/kernel-parameters.txt branch_PRINTK_TIMES/Documentation/kernel-parameters.txt --- tag_LINUX_2_6_9/Documentation/kernel-parameters.txt 2004-10-22 14:38:41.000000000 -0700 +++ branch_PRINTK_TIMES/Documentation/kernel-parameters.txt 2004-11-01 11:50:48.000000000 -0800 @@ -1277,6 +1277,8 @@ running once the system is up. thash_entries= [KNL,NET] Set number of hash buckets for TCP connection + time Show timing data prefixed to each printk message line + tipar= [HW] See header of drivers/char/tipar.c. diff -pruN -X ../cvs-admin/dontdiff tag_LINUX_2_6_9/kernel/printk.c branch_PRINTK_TIMES/kernel/printk.c --- tag_LINUX_2_6_9/kernel/printk.c 2004-10-22 14:39:55.000000000 -0700 +++ branch_PRINTK_TIMES/kernel/printk.c 2004-11-01 11:59:31.000000000 -0800 @@ -494,6 +494,22 @@ static void zap_locks(void) init_MUTEX(&console_sem); } +#if defined(CONFIG_PRINTK_TIME) +static int printk_time = 1; +#else +static int printk_time = 0; +#endif + +static int __init printk_time_setup(char *str) +{ + if (*str) + return 0; + printk_time = 1; + return 1; +} + +__setup("time", printk_time_setup); + /* * This is printk. It can be called from any context. We want it to work. * @@ -542,10 +558,44 @@ asmlinkage int vprintk(const char *fmt, */ for (p = printk_buf; *p; p++) { if (log_level_unknown) { - if (p[0] != '<' || p[1] < '0' || p[1] > '7' || p[2] != '>') { - emit_log_char('<'); - emit_log_char(default_message_loglevel + '0'); - emit_log_char('>'); + /* log_level_unknown signals the start of a new line */ + if (printk_time) { + int loglev_char; + char tbuf[50], *tp; + unsigned tlen; + unsigned long long t; + unsigned long nanosec_rem; + + /* + * force the log level token to be + * before the time output. + */ + if (p[0] == '<' && p[1] >='0' && + p[1] <= '7' && p[2] == '>') { + loglev_char = p[1]; + p += 3; + } else { + loglev_char = default_message_loglevel + + '0'; + } + t = sched_clock(); + nanosec_rem = do_div(t, 1000000000); + tlen = sprintf(tbuf, + "<%c>[%5lu.%06lu] ", + loglev_char, + (unsigned long)t, + nanosec_rem/1000); + + for (tp = tbuf; tp< tbuf + tlen; tp++) + emit_log_char (*tp); + } else { + if (p[0] != '<' || p[1] < '0' || + p[1] > '7' || p[2] != '>') { + emit_log_char('<'); + emit_log_char(default_message_loglevel + + '0'); + emit_log_char('>'); + } } log_level_unknown = 0; } diff -pruN -X ../cvs-admin/dontdiff tag_LINUX_2_6_9/lib/Kconfig.debug branch_PRINTK_TIMES/lib/Kconfig.debug --- tag_LINUX_2_6_9/lib/Kconfig.debug 2004-10-22 14:38:59.000000000 -0700 +++ branch_PRINTK_TIMES/lib/Kconfig.debug 2004-11-01 11:59:35.000000000 -0800 @@ -28,6 +28,15 @@ config MAGIC_SYSRQ Enables console device to interpret special characters as commands to dump state information. +config PRINTK_TIME + bool "Show timing information on printks" + help + Selecting this option causes timing information to be + included in printk output. This allows you to measure + the interval between kernel operations, including bootup + operations. This is useful for identifying long delays + in kernel startup. + config DEBUG_SLAB bool "Debug memory allocations" depends on DEBUG_KERNEL && (ALPHA || ARM || X86 || IA64 || M68K || MIPS || PARISC || PPC32 || PPC64 || ARCH_S390 || SPARC32 || SPARC64 || USERMODE || X86_64) diff -pruN -X ../cvs-admin/dontdiff tag_LINUX_2_6_9/scripts/show_delta branch_PRINTK_TIMES/scripts/show_delta --- tag_LINUX_2_6_9/scripts/show_delta 1969-12-31 16:00:00.000000000 -0800 +++ branch_PRINTK_TIMES/scripts/show_delta 2004-09-16 16:38:41.000000000 -0700 @@ -0,0 +1,129 @@ +#!/usr/bin/env python +# +# show_deltas: Read list of printk messages instrumented with +# time data, and format with time deltas. +# +# Also, you can show the times relative to a fixed point. +# +# Copyright 2003 Sony Corporation +# +# GPL 2.0 applies. + +import sys +import string + +def usage(): + print """usage: show_delta [] + +This program parses the output from a set of printk message lines which +have time data prefixed because the CONFIG_PRINTK_TIME option is set, or +the kernel command line option "time" is specified. When run with no +options, the time information is converted to show the time delta between +each printk line and the next. When run with the '-b' option, all times +are relative to a single (base) point in time. + +Options: + -h Show this usage help. + -b Specify a base for time references. + can be a number or a string. + If it is a string, the first message line + which matches (at the beginning of the + line) is used as the time reference. + +ex: $ dmesg >timefile + $ show_delta -b NET4 timefile + +will show times relative to the line in the kernel output +starting with "NET4". +""" + sys.exit(1) + +# returns a tuple containing the seconds and text for each message line +# seconds is returned as a float +# raise an exception if no timing data was found +def get_time(line): + if line[0]!="[": + raise ValueError + + # split on closing bracket + (time_str, rest) = string.split(line[1:],']',1) + time = string.atof(time_str) + + #print "time=", time + return (time, rest) + + +# average line looks like: +# [ 0.084282] VFS: Mounted root (romfs filesystem) readonly +# time data is expressed in seconds.useconds, +# convert_line adds a delta for each line +last_time = 0.0 +def convert_line(line, base_time): + global last_time + + try: + (time, rest) = get_time(line) + except: + # if any problem parsing time, don't convert anything + return line + + if base_time: + # show time from base + delta = time - base_time + else: + # just show time from last line + delta = time - last_time + last_time = time + + return ("[%5.6f < %5.6f >]" % (time, delta)) + rest + +def main(): + base_str = "" + filein = "" + for arg in sys.argv[1:]: + if arg=="-b": + base_str = sys.argv[sys.argv.index("-b")+1] + elif arg=="-h": + usage() + else: + filein = arg + + if not filein: + usage() + + try: + lines = open(filein,"r").readlines() + except: + print "Problem opening file: %s" % filein + sys.exit(1) + + if base_str: + print 'base= "%s"' % base_str + # assume a numeric base. If that fails, try searching + # for a matching line. + try: + base_time = float(base_str) + except: + # search for line matching string + found = 0 + for line in lines: + try: + (time, rest) = get_time(line) + except: + continue + if string.find(rest, base_str)==1: + base_time = time + found = 1 + # stop at first match + break + if not found: + print 'Couldn\'t find line matching base pattern "%s"' % base_str + sys.exit(1) + else: + base_time = 0.0 + + for line in lines: + print convert_line(line, base_time), + +main() +