[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, 54 insertions, 4 deletions

diff --git a/kernel/printk.c b/kernel/printk.c
index d981e7e4153a..7e36204db952 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -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, va_list args)
 	 */
 	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;
 		}