[PATCH] Fix print out of function which called WARN_ON()

[PATCH] Fix print out of function which called WARN_ON()

[Ian Campbell]

All WARN_ON()'s currently appear to come from warn_slowpath_null e.g.:
 WARNING: at kernel/softirq.c:143 warn_slowpath_null+0x1c/0x20()

This is because since:

  commit 57adc4d2dbf968fdbe516359688094eef4d46581
  Author: Andi Kleen <andi@firstfloor.org>
  Date:   Wed May 6 16:02:53 2009 -0700

      Eliminate thousands of warnings with gcc 3.2 build

the caller of warn_slowpath_fmt really is warn_flowpath_null not the
interesting caller next up the chain. Since __builtin_return_address(X) for X >
0 is not reliable, pass the real caller as an argument to warn_slowpath_fmt.

[If there was a __builtin_this_address() I would use that for the WARN() case
for consistency, I don't know of such a thing though]

Signed-off-by: Ian Campbell <ian.campbell@citrix.com>
Cc: Jesper Nilsson <jesper.nilsson@axis.com>
Cc: Johannes Weiner <hannes@cmpxchg.org>
Cc: Arjan van de Ven <arjan@linux.intel.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Hugh Dickins <hugh@veritas.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
---
 include/asm-generic/bug.h |    5 +++--
 kernel/panic.c            |   11 ++++++++---
 2 files changed, 11 insertions(+), 5 deletions(-)

diff --git a/include/asm-generic/bug.h b/include/asm-generic/bug.h
index 4f4f6e9..39d8dbd 100644
--- a/include/asm-generic/bug.h
+++ b/include/asm-generic/bug.h
@@ -59,12 +59,13 @@ struct bug_entry {
 #ifndef __WARN
 #ifndef __ASSEMBLY__
 extern void warn_slowpath_fmt(const char *file, const int line,
-		const char *fmt, ...) __attribute__((format(printf, 3, 4)));
+		unsigned long caller,
+		const char *fmt, ...) __attribute__((format(printf, 4, 5)));
 extern void warn_slowpath_null(const char *file, const int line);
 #define WANT_WARN_ON_SLOWPATH
 #endif
 #define __WARN()		warn_slowpath_null(__FILE__, __LINE__)
-#define __WARN_printf(arg...)	warn_slowpath_fmt(__FILE__, __LINE__, arg)
+#define __WARN_printf(arg...)	warn_slowpath_fmt(__FILE__, __LINE__, 0UL, arg)
 #else
 #define __WARN_printf(arg...)	do { printk(arg); __WARN(); } while (0)
 #endif
diff --git a/kernel/panic.c b/kernel/panic.c
index 874ecf1..4e1d746 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -340,13 +340,16 @@ void oops_exit(void)
 }
 
 #ifdef WANT_WARN_ON_SLOWPATH
-void warn_slowpath_fmt(const char *file, int line, const char *fmt, ...)
+void warn_slowpath_fmt(const char *file, int line, unsigned long caller,
+		       const char *fmt, ...)
 {
 	va_list args;
 	char function[KSYM_SYMBOL_LEN];
-	unsigned long caller = (unsigned long)__builtin_return_address(0);
 	const char *board;
 
+	if (!caller)
+		caller = (unsigned long)__builtin_return_address(0);
+
 	sprint_symbol(function, caller);
 
 	printk(KERN_WARNING "------------[ cut here ]------------\n");
@@ -372,7 +375,9 @@ EXPORT_SYMBOL(warn_slowpath_fmt);
 void warn_slowpath_null(const char *file, int line)
 {
 	static const char *empty = "";
-	warn_slowpath_fmt(file, line, empty);
+	warn_slowpath_fmt(file, line,
+			  (unsigned long)__builtin_return_address(0),
+			  empty);
 }
 EXPORT_SYMBOL(warn_slowpath_null);
 #endif
-- 
1.5.6.5

Re: [PATCH] Fix print out of function which called WARN_ON()

[Linus Torvalds]

[ Jakub - I added you to the participants list because it really looks 
  like this patch (without 'noinline') triggers a gcc bug.

  Or maybe gcc is truly smart enough to turn the "NULL arg pointer" case 
  into a "empty format" call, in which case we actually just solved the 
  original warning case in a _really_ subtle way. Somebody who understands 
  gcc varags should take a look.

  Regardless, even if the optimization happens to _work_, it seems bogus. 
  Even if "vprintk()" has been marked to have a printf-like format, that 
  doesn't mean that you can call it unconditionally by making the format 
  empty - it might have side effects.

  This is with 'gcc -v' reporting:

	gcc version 4.4.0 20090506 (Red Hat 4.4.0-4) (GCC) 

  and is the current fedora-11 compiler (as of a yum update yesterday or 
  the day before) on x86-64 ]

On Fri, 15 May 2009, Ian Campbell wrote:
>
> All WARN_ON()'s currently appear to come from warn_slowpath_null e.g.:
>  WARNING: at kernel/softirq.c:143 warn_slowpath_null+0x1c/0x20()
> 
> This is because since:
> 
>   commit 57adc4d2dbf968fdbe516359688094eef4d46581
>   Author: Andi Kleen <andi@firstfloor.org>
>   Date:   Wed May 6 16:02:53 2009 -0700
> 
>       Eliminate thousands of warnings with gcc 3.2 build
> 
> the caller of warn_slowpath_fmt really is warn_flowpath_null not the
> interesting caller next up the chain. Since __builtin_return_address(X) for X >
> 0 is not reliable, pass the real caller as an argument to warn_slowpath_fmt.

I'd actually much rather re-organize it so that there are the two exported 
functions (with the current interface) that use a common shared static 
function. Rather than passing in '0' in a macro.

IOW, something like this..

Btw, when doing this, it really looked to me like the "noinline" matters. 
I did it first to try to make the assembly clearer to read, but without it 
gcc-4.4 seems to actually generate the wrong code, and does an 
_unconditional_ call to vprintk().

Very odd. I've seen other bugs triggered by gcc-4.4 (alpine miscompiles), 
it all makes me very nervous about the compiler in current fedora-11.

Anybody want to double-check this?

		Linus

---
 kernel/panic.c |   35 ++++++++++++++++++++---------------
 1 files changed, 20 insertions(+), 15 deletions(-)

diff --git a/kernel/panic.c b/kernel/panic.c
index 874ecf1..3c8048d 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -340,39 +340,44 @@ void oops_exit(void)
 }
 
 #ifdef WANT_WARN_ON_SLOWPATH
-void warn_slowpath_fmt(const char *file, int line, const char *fmt, ...)
-{
+struct slowpath_args {
+	const char *fmt;
 	va_list args;
-	char function[KSYM_SYMBOL_LEN];
-	unsigned long caller = (unsigned long)__builtin_return_address(0);
-	const char *board;
+};
 
-	sprint_symbol(function, caller);
+static void noinline warn_slowpath_common(const char *file, int line, void *caller, struct slowpath_args *args)
+{
+	const char *board;
 
 	printk(KERN_WARNING "------------[ cut here ]------------\n");
-	printk(KERN_WARNING "WARNING: at %s:%d %s()\n", file,
-		line, function);
+	printk(KERN_WARNING "WARNING: at %s:%d %pS()\n", file, line, caller);
 	board = dmi_get_system_info(DMI_PRODUCT_NAME);
 	if (board)
 		printk(KERN_WARNING "Hardware name: %s\n", board);
 
-	if (*fmt) {
-		va_start(args, fmt);
-		vprintk(fmt, args);
-		va_end(args);
-	}
+	if (args)
+		vprintk(args->fmt, args->args);
 
 	print_modules();
 	dump_stack();
 	print_oops_end_marker();
 	add_taint(TAINT_WARN);
 }
+
+void warn_slowpath_fmt(const char *file, int line, const char *fmt, ...)
+{
+	struct slowpath_args args;
+
+	args.fmt = fmt;
+	va_start(args.args, fmt);
+	warn_slowpath_common(file, line, __builtin_return_address(0), &args);
+	va_end(args.args);
+}
 EXPORT_SYMBOL(warn_slowpath_fmt);
 
 void warn_slowpath_null(const char *file, int line)
 {
-	static const char *empty = "";
-	warn_slowpath_fmt(file, line, empty);
+	warn_slowpath_fmt(file, line, __builtin_return_address(0), NULL);
 }
 EXPORT_SYMBOL(warn_slowpath_null);
 #endif

Re: [PATCH] Fix print out of function which called WARN_ON()

[Andi Kleen]

Linus Torvalds wrote:
> [ Jakub - I added you to the participants list because it really looks 
>   like this patch (without 'noinline') triggers a gcc bug.

This whole thing seems to be much more problematic than I originally thought :-/

Maybe it's better to just give up on gcc 3.2 instead and forbid it and revert
my original patch. That would have the advantage that we wouldn't need
to worry about the inline heuristics on that old compiler too (that was
the reason I even tested it)

Given the smaller code size was a nice bonus, but it wasn't a big difference.

-Andi

Re: [PATCH] Fix print out of function which called WARN_ON()

[Linus Torvalds]

On Fri, 15 May 2009, Andi Kleen wrote:

> Linus Torvalds wrote:
> > [ Jakub - I added you to the participants list because it really looks
> > like this patch (without 'noinline') triggers a gcc bug.
> 
> This whole thing seems to be much more problematic than I originally thought
> :-/

No, sorry, it was my mistake. The code generated was indeed wrong, but it 
was because the source code was wrong (me calling the _fmt() function 
instead of the _common() function).

What's wrong with me that I can spot subtle errors in assembly language, 
but not the obvious ones in the source code?

Anyway, the proper patch is appended, and Jakub, you can ignore these 
things. gcc is fine.

This patch not only avoids the warnings and gets the right caller 
information, it cleans up the code too:

 - it uses '%pS' instead of of sprint_symbol

 - it avoids stupidly wasting stack space for varargs information in the 
   warn_slowpath_null case.

 - the code actually looks more readable too.

I'll commit it.

		Linus

---
 kernel/panic.c |   35 ++++++++++++++++++++---------------
 1 files changed, 20 insertions(+), 15 deletions(-)

diff --git a/kernel/panic.c b/kernel/panic.c
index 874ecf1..984b3ec 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -340,39 +340,44 @@ void oops_exit(void)
 }
 
 #ifdef WANT_WARN_ON_SLOWPATH
-void warn_slowpath_fmt(const char *file, int line, const char *fmt, ...)
-{
+struct slowpath_args {
+	const char *fmt;
 	va_list args;
-	char function[KSYM_SYMBOL_LEN];
-	unsigned long caller = (unsigned long)__builtin_return_address(0);
-	const char *board;
+};
 
-	sprint_symbol(function, caller);
+static void warn_slowpath_common(const char *file, int line, void *caller, struct slowpath_args *args)
+{
+	const char *board;
 
 	printk(KERN_WARNING "------------[ cut here ]------------\n");
-	printk(KERN_WARNING "WARNING: at %s:%d %s()\n", file,
-		line, function);
+	printk(KERN_WARNING "WARNING: at %s:%d %pS()\n", file, line, caller);
 	board = dmi_get_system_info(DMI_PRODUCT_NAME);
 	if (board)
 		printk(KERN_WARNING "Hardware name: %s\n", board);
 
-	if (*fmt) {
-		va_start(args, fmt);
-		vprintk(fmt, args);
-		va_end(args);
-	}
+	if (args)
+		vprintk(args->fmt, args->args);
 
 	print_modules();
 	dump_stack();
 	print_oops_end_marker();
 	add_taint(TAINT_WARN);
 }
+
+void warn_slowpath_fmt(const char *file, int line, const char *fmt, ...)
+{
+	struct slowpath_args args;
+
+	args.fmt = fmt;
+	va_start(args.args, fmt);
+	warn_slowpath_common(file, line, __builtin_return_address(0), &args);
+	va_end(args.args);
+}
 EXPORT_SYMBOL(warn_slowpath_fmt);
 
 void warn_slowpath_null(const char *file, int line)
 {
-	static const char *empty = "";
-	warn_slowpath_fmt(file, line, empty);
+	warn_slowpath_common(file, line, __builtin_return_address(0), NULL);
 }
 EXPORT_SYMBOL(warn_slowpath_null);
 #endif

Re: [PATCH] Fix print out of function which called WARN_ON()

[Hugh Dickins]

On Sat, 16 May 2009, Linus Torvalds wrote:
> 
> This patch not only avoids the warnings and gets the right caller 
> information, it cleans up the code too:
> 
>  - it uses '%pS' instead of of sprint_symbol

> -	char function[KSYM_SYMBOL_LEN];

This should be a big improvement, because that buffer on the stack
was netting lots of stale return addresses, printed out with ?s in
the warning's dump_stack().  I had been wanting to add a memset,
but your %pS should circumvent the need for that nicely.

Hugh

Re: [PATCH] Fix print out of function which called WARN_ON()

[Linus Torvalds]

On Sun, 17 May 2009, Hugh Dickins wrote:

> On Sat, 16 May 2009, Linus Torvalds wrote:
> > 
> > This patch not only avoids the warnings and gets the right caller 
> > information, it cleans up the code too:
> > 
> >  - it uses '%pS' instead of of sprint_symbol
> 
> > -	char function[KSYM_SYMBOL_LEN];
> 
> This should be a big improvement, because that buffer on the stack
> was netting lots of stale return addresses, printed out with ?s in
> the warning's dump_stack().  I had been wanting to add a memset,
> but your %pS should circumvent the need for that nicely.

Are you sure it was that function[] array?

The thing is, on at least x86-64, any function using va_start() will 
allocate something like 64 bytes of stack space for the reg-save area. I'm 
not quite sure _why_ it does that, but it's very irritating, and it showed 
up quite clearly in some of the stackspace usage things.

I even sent the gcc people a patch to fix the worst of it (gcc used to 
allocate about twice as much space because it also had a XMM save area 
even if you compiled without XMM support or something like that), but my 
point is, I'm afraid there is still a noticeable gap on the stack due to 
this, at least for the _fmt() case.

But yes, for the _null() case we now have neither that function buffer 
_nor_ the stupid va_list save area, so that case should be much better.

Of course, we could avoid that entirely if we were to just pass in the 
right stack pointer to dump_stack(), and the "warn_slowpath_xyz()" 
functions could just pass in the stack of their caller. Sadly, we 
currently have no way to do that :(

We could change the dump_stack() calling convention to give a stack 
pointer or NULL, and then use __builtin_frame_address(0) in the caller.. 
But we have a _lot_ of "dump_stack()" users.

		Linus

Re: [PATCH] Fix print out of function which called WARN_ON()

[David Miller]

From: Linus Torvalds <torvalds@linux-foundation.org>
Date: Sun, 17 May 2009 15:18:19 -0700 (PDT)

> The thing is, on at least x86-64, any function using va_start() will 
> allocate something like 64 bytes of stack space for the reg-save area. I'm 
> not quite sure _why_ it does that, but it's very irritating, and it showed 
> up quite clearly in some of the stackspace usage things.
> 
> I even sent the gcc people a patch to fix the worst of it (gcc used to 
> allocate about twice as much space because it also had a XMM save area 
> even if you compiled without XMM support or something like that), but my 
> point is, I'm afraid there is still a noticeable gap on the stack due to 
> this, at least for the _fmt() case.

I ran into this issue on sparc64 while helping someone investigate
stack usage there.

There is some strageness wrt. varargs in that it seems that the opaque
object used to reference varargs is effectively an array which
includes first the arguments passed in registers and then the
non-register stack args.

I never got down to the details yet, but on sparc64 currently we
always eat that extra space (in addition to the normal register window
stack space costs) and I had intended to look into eliminating the
varargs incoming argument save slots for cases where we are not doing
any varargs stuff at all.

Re: [PATCH] Fix print out of function which called WARN_ON()

[Hugh Dickins]

On Sun, 17 May 2009, Linus Torvalds wrote:
> On Sun, 17 May 2009, Hugh Dickins wrote:
> > On Sat, 16 May 2009, Linus Torvalds wrote:
> > > 
> > > This patch not only avoids the warnings and gets the right caller 
> > > information, it cleans up the code too:
> > > 
> > >  - it uses '%pS' instead of of sprint_symbol
> > 
> > > -	char function[KSYM_SYMBOL_LEN];
> > 
> > This should be a big improvement, because that buffer on the stack
> > was netting lots of stale return addresses, printed out with ?s in
> > the warning's dump_stack().  I had been wanting to add a memset,
> > but your %pS should circumvent the need for that nicely.
> 
> Are you sure it was that function[] array?

No, not sure at all, that was just a conclusion I jumped to.
Though I think I was seeing it on x86-32 too.

> 
> The thing is, on at least x86-64, any function using va_start() will 
> allocate something like 64 bytes of stack space for the reg-save area. I'm 
> not quite sure _why_ it does that, but it's very irritating, and it showed 
> up quite clearly in some of the stackspace usage things.
> 
> I even sent the gcc people a patch to fix the worst of it (gcc used to 
> allocate about twice as much space because it also had a XMM save area 
> even if you compiled without XMM support or something like that), but my 
> point is, I'm afraid there is still a noticeable gap on the stack due to 
> this, at least for the _fmt() case.
> 
> But yes, for the _null() case we now have neither that function buffer 
> _nor_ the stupid va_list save area, so that case should be much better.
> 
> Of course, we could avoid that entirely if we were to just pass in the 
> right stack pointer to dump_stack(), and the "warn_slowpath_xyz()" 
> functions could just pass in the stack of their caller. Sadly, we 
> currently have no way to do that :(
> 
> We could change the dump_stack() calling convention to give a stack 
> pointer or NULL, and then use __builtin_frame_address(0) in the caller.. 
> But we have a _lot_ of "dump_stack()" users.

Not to mention the astonishing array of dump_stack, show_stack,
show_trace, dump_trace, etc etc, layers we've now accumulated,
in x86 at least.  I ran away the last time I looked there.

Hugh

Re: [PATCH] Fix print out of function which called WARN_ON()

[Linus Torvalds]

On Sun, 17 May 2009, David Miller wrote:
> 
> There is some strageness wrt. varargs in that it seems that the opaque
> object used to reference varargs is effectively an array which
> includes first the arguments passed in registers and then the
> non-register stack args.

I forget what the exact details were, but I _think_ it boiled down to the 
varargs save area is always large enough for the maximum number of 
register arguments. Fair enough. It used to be that that means something 
like 216 bytes of stack-space with SSE registers (8*16 bytes for just 
that unused SSE register save).

So I reported that, and my fix got merged (or rather, I think somebody 
improved on my hacky one and that improved fix got merged).

But now it still generates a 88 byte stack frame, and only about half that 
seems to be used (six integer registers, but the "..." part can only be 
five, so you have 5*8=40 bytes save-space, and an additional pointer to 
the frame that contains the rest).

So the stack frame _should_ be just 48 bytes, but gcc always seems to 
generate either 80 or 88 bytes. I never bothered to try to chase it down, 
the code is rather obscure. I suspect it has some "current pointer" too 
etc, and there is probably some alignment as well. But I'm sure that there 
are entries on the stack frame that simply aren't filled in.

At least with the XMM fix, there's now just a _couple_ of such entries. 

> I never got down to the details yet, but on sparc64 currently we
> always eat that extra space

Ouch. On x86-64, it at least _only_ happens in the functions that do 
va_start().

				Linus

Re: [PATCH] Fix print out of function which called WARN_ON()

[Linus Torvalds]

On Sun, 17 May 2009, Hugh Dickins wrote:
> 
> No, not sure at all, that was just a conclusion I jumped to.
> Though I think I was seeing it on x86-32 too.

Ok, the 32-bit calling convention doesn't do any of that, even though we 
compile the kernel with -mregparm=3. Any function with varargs arguments 
gets all arguments passed on the stack, and we just pass the frame pointer 
along, so there's no extra buffers.

So if you saw it on x86-32, then I think the only empty hole is indeed 
due to that 'char function[KSYM_SYMBOL_LEN]' (and whatever stack alignment 
code gcc does). And yes, it should be much better now.

			Linus

Re: [PATCH] Fix print out of function which called WARN_ON()

[Ian Campbell]

On Sat, 2009-05-16 at 13:47 -0700, Linus Torvalds wrote:

>  - it uses '%pS' instead of of sprint_symbol
[...]
> -       printk(KERN_WARNING "WARNING: at %s:%d %s()\n", file,
> -               line, function);
> +	printk(KERN_WARNING "WARNING: at %s:%d %pS()\n", file, line, caller);

Those parens end up looking pretty odd to me with the %pS:
	WARNING: at [...] local_bh_enable+0x68/0x80()

Otherwise it works fine, thanks.

Ian.

Re: [PATCH] Fix print out of function which called WARN_ON()

[Arjan van de Ven]

Ian Campbell wrote:
> On Sat, 2009-05-16 at 13:47 -0700, Linus Torvalds wrote:
> 
>>  - it uses '%pS' instead of of sprint_symbol
> [...]
>> -       printk(KERN_WARNING "WARNING: at %s:%d %s()\n", file,
>> -               line, function);
>> +	printk(KERN_WARNING "WARNING: at %s:%d %pS()\n", file, line, caller);
> 
> Those parens end up looking pretty odd to me with the %pS:
> 	WARNING: at [...] local_bh_enable+0x68/0x80()

didn't we have a %pSomething that doesn't print those 2 hex parts ?
(It would allow us to keep the print format the same)