[PATCH] add timing information to printk messages

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

And now the patch...

Signed-off-by: Tim Bird <tim.bird@am.sony.com>
Signed-off-by: Andrew Morton <akpm@osdl.org>
Signed-off-by: Linus Torvalds <torvalds@osdl.org>

1 files changed, 9 insertions, 0 deletions

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 388af7c97927..f771806bbfd4 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -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