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 <[email protected]>
---
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
On Thu, 2 Oct 2008 16:21:15 -0700 (PDT)
Roland McGrath <[email protected]> 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?
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
On Thu, 2008-10-02 at 16:31 -0700, Andrew Morton wrote:
> On Thu, 2 Oct 2008 16:21:15 -0700 (PDT)
> Roland McGrath <[email protected]> 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.