printk-times-04.09.02.patch: 

This patch adds support for printk to output a timestamp.

Signed-off-by: Geoff Levand <geoffrey.levand@am.sony.com> for CELF
---

 arch/i386/Kconfig      |    9 +++++++
 arch/ppc/Kconfig       |   10 ++++++++
 arch/ppc/kernel/time.c |    5 ++++
 kernel/printk.c        |   58 +++++++++++++++++++++++++++++++++++++++++++++----
 4 files changed, 78 insertions(+), 4 deletions(-)


diff -ruN -X ./dontdiff tag_LINUX_2_6_8_1/arch/i386/Kconfig branch_PRINTK_TIMES/arch/i386/Kconfig
--- tag_LINUX_2_6_8_1/arch/i386/Kconfig	2004-09-02 15:25:55.000000000 -0700
+++ branch_PRINTK_TIMES/arch/i386/Kconfig	2004-09-02 16:26:28.000000000 -0700
@@ -1188,6 +1188,15 @@
 
 menu "Kernel hacking"
 
+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_KERNEL
 	bool "Kernel debugging"
 	help
diff -ruN -X ./dontdiff tag_LINUX_2_6_8_1/arch/ppc/Kconfig branch_PRINTK_TIMES/arch/ppc/Kconfig
--- tag_LINUX_2_6_8_1/arch/ppc/Kconfig	2004-09-02 15:26:37.000000000 -0700
+++ branch_PRINTK_TIMES/arch/ppc/Kconfig	2004-09-02 16:26:36.000000000 -0700
@@ -1224,12 +1224,22 @@
 
 endmenu
 
+
 source "lib/Kconfig"
 
 source "arch/ppc/oprofile/Kconfig"
 
 menu "Kernel hacking"
 
+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_KERNEL
 	bool "Kernel debugging"
 
diff -ruN -X ./dontdiff tag_LINUX_2_6_8_1/arch/ppc/kernel/time.c branch_PRINTK_TIMES/arch/ppc/kernel/time.c
--- tag_LINUX_2_6_8_1/arch/ppc/kernel/time.c	2004-09-02 15:26:38.000000000 -0700
+++ branch_PRINTK_TIMES/arch/ppc/kernel/time.c	2004-09-02 16:26:37.000000000 -0700
@@ -85,7 +85,12 @@
 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 */
+#else
 unsigned long tb_to_ns_scale;
+#endif
 
 extern unsigned long wall_jiffies;
 
diff -ruN -X ./dontdiff tag_LINUX_2_6_8_1/kernel/printk.c branch_PRINTK_TIMES/kernel/printk.c
--- tag_LINUX_2_6_8_1/kernel/printk.c	2004-09-02 15:27:20.000000000 -0700
+++ branch_PRINTK_TIMES/kernel/printk.c	2004-09-02 16:27:43.000000000 -0700
@@ -492,6 +492,22 @@
 	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.
  * 
@@ -531,10 +547,44 @@
 	 */
 	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;
 		}