[PATCH] printk.caller

[PATCH] printk.caller

[Roland McGrath]

This adds the printk.caller=[0|1] boot parameter, default setting
controlled by CONFIG_PRINTK_CALLER.  (This is modelled on printk.time
and CONFIG_PRINTK_TIME.)

When this is set, each printk line is automagically prefixed with
"{0x123abc} " giving the PC address of that printk call (actually
the PC address just after the call).

As a kernel hacker, I always hate having to grep for some fragment
of a message to find the code that generated it.  But I always have
my -g vmlinux handy, so:
	(gdb) info line *(0x123abc - 1)
is real handy (it pops the source up in an Emacs buffer).

Signed-off-by: Roland McGrath <roland@redhat.com>
---
 Documentation/kernel-parameters.txt |    3 ++
 include/linux/kernel.h              |    4 ++-
 kernel/printk.c                     |   38 +++++++++++++++++++++++++++++-----
 lib/Kconfig.debug                   |    9 ++++++++
 4 files changed, 47 insertions(+), 7 deletions(-)

diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
index 1150444..9f1e1b9 100644
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -1689,6 +1689,9 @@ and is between 256 and 4096 characters. It is defined in the file
 	printk.time=	Show timing data prefixed to each printk message line
 			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
 
+	printk.caller=	Show caller PC prefixed to each printk message line
+			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
+
 	profile=	[KNL] Enable kernel profiling via /proc/profile
 			Format: [schedule,]<number>
 			Param: "schedule" - profile schedule points.
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 2651f80..e03b475 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -191,7 +191,9 @@ struct pid;
 extern struct pid *session_of_pgrp(struct pid *pgrp);
 
 #ifdef CONFIG_PRINTK
-asmlinkage int vprintk(const char *fmt, va_list args)
+# define vprintk(fmt, args) \
+	vprintk_caller(fmt, args, __builtin_return_address(0))
+asmlinkage int vprintk_caller(const char *fmt, va_list args, void *caller)
 	__attribute__ ((format (printf, 1, 0)));
 asmlinkage int printk(const char * fmt, ...)
 	__attribute__ ((format (printf, 1, 2))) __cold;
diff --git a/kernel/printk.c b/kernel/printk.c
index b51b156..e4294c8 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -532,6 +532,12 @@ static void emit_log_char(char c)
 		logged_chars++;
 }
 
+static void emit_log_chars(const char *p, unsigned n)
+{
+	while (n-- > 0)
+		emit_log_char(*p++);
+}
+
 /*
  * Zap console related locks when oopsing. Only zap at most once
  * every 10 seconds, to leave time for slow consoles to print a
@@ -560,6 +566,13 @@ static int printk_time = 0;
 #endif
 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
 
+#if defined(CONFIG_PRINTK_CALLER)
+static int printk_caller = 1;
+#else
+static int printk_caller = 0;
+#endif
+module_param_named(caller, printk_caller, bool, S_IRUGO | S_IWUSR);
+
 /* Check if we have any console registered that can be called early in boot. */
 static int have_callable_console(void)
 {
@@ -662,7 +675,7 @@ static int recursion_bug;
 	static int new_text_line = 1;
 static char printk_buf[1024];
 
-asmlinkage int vprintk(const char *fmt, va_list args)
+asmlinkage int vprintk_caller(const char *fmt, va_list args, void *caller)
 {
 	int printed_len = 0;
 	int current_log_level = default_message_loglevel;
@@ -708,7 +721,6 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	printed_len += vscnprintf(printk_buf + printed_len,
 				  sizeof(printk_buf) - printed_len, fmt, args);
 
-
 	/*
 	 * Copy the output into log_buf.  If the caller didn't provide
 	 * appropriate log level tags, we insert them here
@@ -732,7 +744,7 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 
 			if (printk_time) {
 				/* Follow the token with the time */
-				char tbuf[50], *tp;
+				char tbuf[50];
 				unsigned tlen;
 				unsigned long long t;
 				unsigned long nanosec_rem;
@@ -743,11 +755,25 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 						(unsigned long) t,
 						nanosec_rem / 1000);
 
-				for (tp = tbuf; tp < tbuf + tlen; tp++)
-					emit_log_char(*tp);
+				emit_log_chars(tbuf, tlen);
 				printed_len += tlen;
 			}
 
+			if (caller && printk_caller) {
+				char pbuf[sizeof caller * 2 + sizeof "{0x} "];
+				unsigned plen;
+
+				if (sizeof caller > 4)
+					plen = sprintf(pbuf, "{0x%016lx} ",
+						       (unsigned long) caller);
+				else
+					plen = sprintf(pbuf, "{0x%08lx} ",
+						       (unsigned long) caller);
+
+				emit_log_chars(pbuf, plen);
+				printed_len += plen;
+			}
+
 			if (!*p)
 				break;
 		}
@@ -778,7 +804,7 @@ out_restore_irqs:
 	return printed_len;
 }
 EXPORT_SYMBOL(printk);
-EXPORT_SYMBOL(vprintk);
+EXPORT_SYMBOL(vprintk_caller);
 
 #else
 
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 0b50481..b90134e 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -9,6 +9,15 @@ config PRINTK_TIME
 	  operations.  This is useful for identifying long delays
 	  in kernel startup.
 
+config PRINTK_CALLER
+	bool "Show caller PC on printks"
+	depends on PRINTK
+	help
+	  Selecting this option causes printk output to include
+	  the PC address of the printk call.  This is useful for
+	  kernels hackers to quickly locate the source code that
+	  produced the message.
+
 config ENABLE_WARN_DEPRECATED
 	bool "Enable __deprecated logic"
 	default y

Re: [PATCH] printk.caller

[Andrew Morton]

On Thu,  2 Oct 2008 16:21:15 -0700 (PDT)
Roland McGrath <roland@redhat.com> wrote:

> This adds the printk.caller=[0|1] boot parameter, default setting
> controlled by CONFIG_PRINTK_CALLER.  (This is modelled on printk.time
> and CONFIG_PRINTK_TIME.)
> 
> When this is set, each printk line is automagically prefixed with
> "{0x123abc} " giving the PC address of that printk call (actually
> the PC address just after the call).
> 
> As a kernel hacker, I always hate having to grep for some fragment
> of a message to find the code that generated it.  But I always have
> my -g vmlinux handy, so:
> 	(gdb) info line *(0x123abc - 1)
> is real handy (it pops the source up in an Emacs buffer).
> 

hm.  What do others think?

>
> ...
>
> +config PRINTK_CALLER
> +	bool "Show caller PC on printks"
> +	depends on PRINTK
> +	help
> +	  Selecting this option causes printk output to include
> +	  the PC address of the printk call.  This is useful for
> +	  kernels hackers to quickly locate the source code that
> +	  produced the message.
> +

This is quite misleading.  The config help implies that
CONFIG_PRINTK_CALLER will enable the feature at compile time.  But it
doesn't - it just sets the boot-time enable/disable default.

If you do this:

#ifdef CONFIG_PRINTK_CALLER
static int printk_caller = 1;
#else
#define printk_caller 0
#endif

then the implementation would somewhat reflect the config option.


But I'd suggest that this thing is so small that it doesn't need a
config option to enable the presence of the code - just make it
unconditional.

Also, I guess that the boot-time option is useful, but a runtime /proc
knob might also be needed?

Re: [PATCH] printk.caller

[Roland McGrath]

I don't disagree with any of that.  
I followed the printk.time example closely.
All those things are equally true of that option.


Thanks,
Roland

Re: [PATCH] printk.caller

[Peter Zijlstra]

On Thu, 2008-10-02 at 16:31 -0700, Andrew Morton wrote:
> On Thu,  2 Oct 2008 16:21:15 -0700 (PDT)
> Roland McGrath <roland@redhat.com> wrote:
> 
> > This adds the printk.caller=[0|1] boot parameter, default setting
> > controlled by CONFIG_PRINTK_CALLER.  (This is modelled on printk.time
> > and CONFIG_PRINTK_TIME.)
> > 
> > When this is set, each printk line is automagically prefixed with
> > "{0x123abc} " giving the PC address of that printk call (actually
> > the PC address just after the call).
> > 
> > As a kernel hacker, I always hate having to grep for some fragment
> > of a message to find the code that generated it.  But I always have
> > my -g vmlinux handy, so:
> > 	(gdb) info line *(0x123abc - 1)
> > is real handy (it pops the source up in an Emacs buffer).
> > 
> 
> hm.  What do others think?

git grep is usually plenty fast for me, but I guess different people,
different tastes.

Also, I always use addr2line instead of gdb,.. another not-to-the-point
difference ;-)

The only real downside to this patch for me is that it potentially
increases the length of lines which means I;d have to stretch my serial
console window, but I guess others might object to the puny increase in
object size.

Flip a coin.

One tiny nit though:

> +                               char pbuf[sizeof caller * 2 + sizeof "{0x} "];

I thought we did sizeof() in-kernel.