Here's a little patch which is useful for showing timing information for
kernel bootup activities.
This patch adds a new Kconfig option under "Kernel Hacking" and a new
option for the kernel command line. It also provides a script for
showing delta information.
Note that the timing data may not be correct on some platforms until
after time_init() is called.
Recently (as of about 2.6.10) I found that the message log produced by
dmesg is truncated when I use this feature. That is, the first few printk
messages of the boot sequence are not in the dmesg output, although
they are printed to console during startup. This is a new behavior -
dmesg output was fine as of 2.6.9. Increasing CONFIG_LOG_BUF_SHIFT
had no effect on the truncation.
Has something changed with printk recently?
For more information on this patch, see:
http://tree.celinuxforum.org/CelfPubWiki/InstrumentedPrintk
Here's some sample output:
...
[4294667.296000] Kernel command line: ro root=/dev/nfs ip=dhcp hdc=ide-scsi console=vga console=ttyS0,115200
[4294667.296000] ide_setup: hdc=ide-scsi
[4294667.296000] Initializing CPU#0
[4294667.296000] PID hash table entries: 512 (order: 9, 8192 bytes)
[ 0.000000] Detected 1995.620 MHz processor.
[ 21.397369] Using tsc for high-res timesource
[ 21.399820] Console: colour VGA+ 80x25
[ 21.537244] Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
[ 21.544547] Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
[ 21.555066] Memory: 125076k/130240k available (2002k kernel code, 4556k reserved, 1006k data, 140k init, 0k highmem)
[ 21.565775] Checking if this processor honours the WP bit even in supervisor mode... Ok.
[ 21.574089] Calibrating delay loop... 3940.35 BogoMIPS (lpj=1970176)
[ 21.596511] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
[ 21.603263] CPU: After generic identify, caps: bfebfbff 00000000 00000000 00000000 00004400 00000000 00000000
[ 21.603276] CPU: After vendor identify, caps: bfebfbff 00000000 00000000 00000000 00004400 00000000 00000000
[ 21.603287] CPU: Trace cache: 12K uops, L1 D cache: 8K
[ 21.608884] CPU: L2 cache: 128K
...
Output from diffinfo:
Documentation/kernel-parameters.txt | 2+ 0- (1 hunk)
kernel/printk.c | 54+ 4- (2 hunks)
lib/Kconfig.debug | 9+ 0- (1 hunk)
scripts/show_delta N 129+ 0- (1 hunk)
4 files changed, 194 insertions(+), 4 deletions(-), 5 hunks
And now the patch...
Signed-off-by: Tim Bird <tim.bird (at) am.sony.com>
----------------------------
diff -pruN linux-2.6.11-rc4.orig/Documentation/kernel-parameters.txt linux-2.6.11-rc4/Documentation/kernel-parameters.txt
--- linux-2.6.11-rc4.orig/Documentation/kernel-parameters.txt 2005-02-14 11:46:47.000000000 -0800
+++ linux-2.6.11-rc4/Documentation/kernel-parameters.txt 2005-02-14 13:14:13.000000000 -0800
@@ -1356,6 +1356,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.timeout= [HW,PPT]
Set communications timeout in tenths of a second
(default 15).
diff -pruN linux-2.6.11-rc4.orig/kernel/printk.c linux-2.6.11-rc4/kernel/printk.c
--- linux-2.6.11-rc4.orig/kernel/printk.c 2005-02-14 11:46:50.000000000 -0800
+++ linux-2.6.11-rc4/kernel/printk.c 2005-02-14 13:12:50.000000000 -0800
@@ -499,6 +499,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.
*
@@ -547,10 +563,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 linux-2.6.11-rc4.orig/lib/Kconfig.debug linux-2.6.11-rc4/lib/Kconfig.debug
--- linux-2.6.11-rc4.orig/lib/Kconfig.debug 2005-02-14 11:46:50.000000000 -0800
+++ linux-2.6.11-rc4/lib/Kconfig.debug 2005-02-14 13:12:50.000000000 -0800
@@ -27,6 +27,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 SCHEDSTATS
bool "Collect scheduler statistics"
depends on DEBUG_KERNEL && PROC_FS
diff -pruN linux-2.6.11-rc4.orig/scripts/show_delta linux-2.6.11-rc4/scripts/show_delta
--- linux-2.6.11-rc4.orig/scripts/show_delta 1969-12-31 16:00:00.000000000 -0800
+++ linux-2.6.11-rc4/scripts/show_delta 2005-02-14 13:12:50.000000000 -0800
@@ -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 [<options>] <filename>
+
+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 <base> Specify a base for time references.
+ <base> 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 <base> 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()
+
> Here's a little patch which is useful for showing timing information for
> kernel bootup activities.
>
> This patch adds a new Kconfig option under "Kernel Hacking" and a new
> option for the kernel command line. It also provides a script for
> showing delta information.
I'm seeing some odd output with CONFIG_PRINTK_TIME=y during boot. When
it is set to "no", I see this from "dmesg":
Total of 4 processors activated (7168.96 BogoMIPS).
CPU0 attaching sched-domain:
domain 0: span f
groups: 1 2 4 8
CPU1 attaching sched-domain:
domain 0: span f
groups: 2 4 8 1
CPU2 attaching sched-domain:
domain 0: span f
groups: 4 8 1 2
CPU3 attaching sched-domain:
domain 0: span f
groups: 8 1 2 4
Setting CONFIG_PRINTK_TIME=y I see (the "<NUL>" pieces are actually
each a single ASCII '\0' character):
[ 0.240887] Total of 4 processors activated (7168.96 BogoMIPS).
[ 0.240926] CPU0 attaching sched-domain:
[ 0.240930] <NUL>PU0 attaching sched-domain:
[ 0.240933] domain 0: span f
[ 0.240967] <NUL> f
[ 0.240969] groups: 1 2 4 8
[ 0.241024] CPU1 attaching sched-domain:
[ 0.241027] <NUL>PU1 attaching sched-domain:
[ 0.241030] domain 0: span f
[ 0.241063] <NUL> f
[ 0.241065] groups: 2 4 8 1
[ 0.241146] CPU2 attaching sched-domain:
[ 0.241149] <NUL>PU2 attaching sched-domain:
[ 0.241151] domain 0: span f
[ 0.241186] <NUL> f
[ 0.241188] groups: 4 8 1 2
[ 0.241267] CPU3 attaching sched-domain:
[ 0.241270] <NUL>PU3 attaching sched-domain:
[ 0.241273] domain 0: span f
[ 0.241307] <NUL> f
[ 0.241309] groups: 8 1 2 4
At first I thought that the lines that begin with whitespace were causing
the confusion, but there are other lines during boot that are ok.
[This is on an ia64 system ... but these messages come from generic kern/sched.c]
-Tony
Tony Luck wrote:
>>Here's a little patch which is useful for showing timing information for
>>kernel bootup activities.
>>
>>This patch adds a new Kconfig option under "Kernel Hacking" and a new
>>option for the kernel command line. It also provides a script for
>>showing delta information.
>
>
> I'm seeing some odd output with CONFIG_PRINTK_TIME=y during boot. When
> it is set to "no", I see this from "dmesg":
Thanks very much for the bug report. I had another report from Tom Zanussi
about possibly trying to print when at the end of the string. I think
it may be related, but in any event I'll look into it right away.
I appreciate your reporting it!
-- Tim
=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Electronics
=============================
Tony Luck wrote:
> Setting CONFIG_PRINTK_TIME=y I see (the "<NUL>" pieces are actually
> each a single ASCII '\0' character):
Tony,
Can you try the patch below? (inspired by a patch from Tom Zanussi -
gotta give credit where credit is due... :-)
This solves the problem for me but I'd like independent confirmation.
BTW, this also fixes a problem with the return value for printk,
which is supposed to be the actual amount printed. This was incorrect
in the printk-times=y case, but also in the '=n' case where a log-level
tag is inserted by printk automatically. This looks like a longstanding
bug. (Although I doubt a very important one, since no one appears
to ever look at the printk return value.)
Thanks,
-- Tim
Fix for null character processing with printk-times option on:
---------------------------------
diff -pruN printk-1/kernel/printk.c printk-fix1/kernel/printk.c
--- printk-1/kernel/printk.c 2005-03-09 15:42:04.550944124 -0800
+++ printk-fix1/kernel/printk.c 2005-03-09 15:36:18.928567360 -0800
@@ -579,6 +579,7 @@ asmlinkage int vprintk(const char *fmt,
p[1] <= '7' && p[2] == '>') {
loglev_char = p[1];
p += 3;
+ printed_len += 3;
} else {
loglev_char = default_message_loglevel
+ '0';
@@ -593,6 +594,7 @@ asmlinkage int vprintk(const char *fmt,
for (tp = tbuf; tp < tbuf + tlen; tp++)
emit_log_char (*tp);
+ printed_len += tlen - 3;
} else {
if (p[0] != '<' || p[1] < '0' ||
p[1] > '7' || p[2] != '>') {
@@ -601,8 +603,11 @@ asmlinkage int vprintk(const char *fmt,
+ '0');
emit_log_char('>');
}
+ printed_len += 3;
}
log_level_unknown = 0;
+ if (!*p)
+ break;
}
emit_log_char(*p);
if (*p == '\n')
On Wed, 09 Mar 2005 15:50:52 PST, Tim Bird said:
> Tony Luck wrote:
> > Setting CONFIG_PRINTK_TIME=y I see (the "<NUL>" pieces are actually
> > each a single ASCII '\0' character):
>
> Tony,
>
> Can you try the patch below? (inspired by a patch from Tom Zanussi -
> gotta give credit where credit is due... :-)
>
> This solves the problem for me but I'd like independent confirmation.
I was seeing this issue as well, and the patch clears it up here too....