All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH 1/2] vsprintf: Fix %ps on non symbols when using kallsyms
@ 2012-04-23 21:45 Stephen Boyd
  2012-04-23 21:45 ` [PATCH 2/2] spinlock_debug: Print kallsyms name for lock Stephen Boyd
  2012-04-23 21:55 ` [PATCH 1/2] vsprintf: Fix %ps on non symbols when using kallsyms Andrew Morton
  0 siblings, 2 replies; 8+ messages in thread
From: Stephen Boyd @ 2012-04-23 21:45 UTC (permalink / raw)
  To: Andrew Morton; +Cc: linux-kernel

Using %ps in a printk format will sometimes fail silently and
print the empty string if the address passed in does not match a
symbol that kallsyms knows about. But using %pS will fall back to
printing the full address if kallsyms can't find the symbol. Make
%ps act the same as %pS by falling back to printing the address.

While we're here also make %ps print the module that a symbol
comes from so that it matches what %pS already does. Take this
simple function for example (in a module):

	static void test_printk(void)
	{
		int test;
		pr_info("with pS: %pS\n", &test);
		pr_info("with ps: %ps\n", &test);
	}

Before this patch:

 with pS: 0xdff7df44
 with ps:

After this patch:

 with pS: 0xdff7df44
 with ps: 0xdff7df44

Signed-off-by: Stephen Boyd <sboyd@codeaurora.org>
---

The name is admittedly bad. Please suggest alternatives.

 include/linux/kallsyms.h |    7 +++++++
 kernel/kallsyms.c        |   32 ++++++++++++++++++++++++--------
 lib/vsprintf.c           |    2 +-
 3 files changed, 32 insertions(+), 9 deletions(-)

diff --git a/include/linux/kallsyms.h b/include/linux/kallsyms.h
index 3875719..6883e19 100644
--- a/include/linux/kallsyms.h
+++ b/include/linux/kallsyms.h
@@ -36,6 +36,7 @@ const char *kallsyms_lookup(unsigned long addr,
 
 /* Look up a kernel symbol and return it in a text buffer. */
 extern int sprint_symbol(char *buffer, unsigned long address);
+extern int sprint_symbol_no_offset(char *buffer, unsigned long address);
 extern int sprint_backtrace(char *buffer, unsigned long address);
 
 /* Look up a kernel symbol and print it to the kernel messages. */
@@ -80,6 +81,12 @@ static inline int sprint_symbol(char *buffer, unsigned long addr)
 	return 0;
 }
 
+static inline int sprint_symbol_no_offset(char *buffer, unsigned long addr)
+{
+	*buffer = '\0';
+	return 0;
+}
+
 static inline int sprint_backtrace(char *buffer, unsigned long addr)
 {
 	*buffer = '\0';
diff --git a/kernel/kallsyms.c b/kernel/kallsyms.c
index 079f1d3..2169fee 100644
--- a/kernel/kallsyms.c
+++ b/kernel/kallsyms.c
@@ -343,7 +343,7 @@ int lookup_symbol_attrs(unsigned long addr, unsigned long *size,
 
 /* Look up a kernel symbol and return it in a text buffer. */
 static int __sprint_symbol(char *buffer, unsigned long address,
-			   int symbol_offset)
+			   int symbol_offset, int add_offset)
 {
 	char *modname;
 	const char *name;
@@ -358,13 +358,13 @@ static int __sprint_symbol(char *buffer, unsigned long address,
 	if (name != buffer)
 		strcpy(buffer, name);
 	len = strlen(buffer);
-	buffer += len;
 	offset -= symbol_offset;
 
+	if (add_offset)
+		len += sprintf(buffer + len, "+%#lx/%#lx", offset, size);
+
 	if (modname)
-		len += sprintf(buffer, "+%#lx/%#lx [%s]", offset, size, modname);
-	else
-		len += sprintf(buffer, "+%#lx/%#lx", offset, size);
+		len += sprintf(buffer + len, " [%s]", modname);
 
 	return len;
 }
@@ -382,12 +382,28 @@ static int __sprint_symbol(char *buffer, unsigned long address,
  */
 int sprint_symbol(char *buffer, unsigned long address)
 {
-	return __sprint_symbol(buffer, address, 0);
+	return __sprint_symbol(buffer, address, 0, 1);
 }
-
 EXPORT_SYMBOL_GPL(sprint_symbol);
 
 /**
+ * sprint_symbol_no_offset - Look up a kernel symbol and return it in a text buffer
+ * @buffer: buffer to be stored
+ * @address: address to lookup
+ *
+ * This function looks up a kernel symbol with @address and stores its name
+ * and module name to @buffer if possible. If no symbol was found, just saves
+ * its @address as is.
+ *
+ * This function returns the number of bytes stored in @buffer.
+ */
+int sprint_symbol_no_offset(char *buffer, unsigned long address)
+{
+	return __sprint_symbol(buffer, address, 0, 0);
+}
+EXPORT_SYMBOL_GPL(sprint_symbol_no_offset);
+
+/**
  * sprint_backtrace - Look up a backtrace symbol and return it in a text buffer
  * @buffer: buffer to be stored
  * @address: address to lookup
@@ -403,7 +419,7 @@ EXPORT_SYMBOL_GPL(sprint_symbol);
  */
 int sprint_backtrace(char *buffer, unsigned long address)
 {
-	return __sprint_symbol(buffer, address, -1);
+	return __sprint_symbol(buffer, address, -1, 1);
 }
 
 /* Look up a kernel symbol and print it to the kernel messages. */
diff --git a/lib/vsprintf.c b/lib/vsprintf.c
index ba7bb1b..0b56d43 100644
--- a/lib/vsprintf.c
+++ b/lib/vsprintf.c
@@ -535,7 +535,7 @@ char *symbol_string(char *buf, char *end, void *ptr,
 	else if (ext != 'f' && ext != 's')
 		sprint_symbol(sym, value);
 	else
-		kallsyms_lookup(value, NULL, NULL, NULL, sym);
+		sprint_symbol_no_offset(sym, value);
 
 	return string(buf, end, sym, spec);
 #else
-- 
Sent by an employee of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum.


^ permalink raw reply related	[flat|nested] 8+ messages in thread

* [PATCH 2/2] spinlock_debug: Print kallsyms name for lock
  2012-04-23 21:45 [PATCH 1/2] vsprintf: Fix %ps on non symbols when using kallsyms Stephen Boyd
@ 2012-04-23 21:45 ` Stephen Boyd
  2012-04-23 21:54   ` Andrew Morton
  2012-04-23 21:55 ` [PATCH 1/2] vsprintf: Fix %ps on non symbols when using kallsyms Andrew Morton
  1 sibling, 1 reply; 8+ messages in thread
From: Stephen Boyd @ 2012-04-23 21:45 UTC (permalink / raw)
  To: Andrew Morton; +Cc: linux-kernel

When a spinlock warning is printed we usually get

 BUG: spinlock bad magic on CPU#0, modprobe/111
  lock: 0xdff09f38, .magic: 00000000, .owner: /0, .owner_cpu: 0

but it's nicer to print the symbol for the lock if we have it so
that we can avoid 'grep dff09f38 /proc/kallsyms' to find out
which lock it was. Use kallsyms to print the symbol name so we
get something a bit easier to read

 BUG: spinlock bad magic on CPU#0, modprobe/112
  lock: test_lock, .magic: 00000000, .owner: <none>/-1, .owner_cpu: 0

If the lock is not in kallsyms %ps will fall back to printing the address
directly.

Signed-off-by: Stephen Boyd <sboyd@codeaurora.org>
---
 lib/spinlock_debug.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/spinlock_debug.c b/lib/spinlock_debug.c
index 525d160..d0ec4f3 100644
--- a/lib/spinlock_debug.c
+++ b/lib/spinlock_debug.c
@@ -58,7 +58,7 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
 	printk(KERN_EMERG "BUG: spinlock %s on CPU#%d, %s/%d\n",
 		msg, raw_smp_processor_id(),
 		current->comm, task_pid_nr(current));
-	printk(KERN_EMERG " lock: %p, .magic: %08x, .owner: %s/%d, "
+	printk(KERN_EMERG " lock: %ps, .magic: %08x, .owner: %s/%d, "
 			".owner_cpu: %d\n",
 		lock, lock->magic,
 		owner ? owner->comm : "<none>",
-- 
Sent by an employee of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum.


^ permalink raw reply related	[flat|nested] 8+ messages in thread

* Re: [PATCH 2/2] spinlock_debug: Print kallsyms name for lock
  2012-04-23 21:45 ` [PATCH 2/2] spinlock_debug: Print kallsyms name for lock Stephen Boyd
@ 2012-04-23 21:54   ` Andrew Morton
  2012-04-24  3:17     ` Stephen Boyd
  0 siblings, 1 reply; 8+ messages in thread
From: Andrew Morton @ 2012-04-23 21:54 UTC (permalink / raw)
  To: Stephen Boyd; +Cc: linux-kernel

On Mon, 23 Apr 2012 14:45:25 -0700
Stephen Boyd <sboyd@codeaurora.org> wrote:

> When a spinlock warning is printed we usually get
> 
>  BUG: spinlock bad magic on CPU#0, modprobe/111
>   lock: 0xdff09f38, .magic: 00000000, .owner: /0, .owner_cpu: 0
> 
> but it's nicer to print the symbol for the lock if we have it so
> that we can avoid 'grep dff09f38 /proc/kallsyms' to find out
> which lock it was. Use kallsyms to print the symbol name so we
> get something a bit easier to read
> 
>  BUG: spinlock bad magic on CPU#0, modprobe/112
>   lock: test_lock, .magic: 00000000, .owner: <none>/-1, .owner_cpu: 0
> 
> If the lock is not in kallsyms %ps will fall back to printing the address
> directly.

hm.  Is this true?  From my reading of kallsyms_lookup(), it will fall
into module_address_lookup() whcih is a no-op if !CONFIG_MODULES.

> --- a/lib/spinlock_debug.c
> +++ b/lib/spinlock_debug.c
> @@ -58,7 +58,7 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
>  	printk(KERN_EMERG "BUG: spinlock %s on CPU#%d, %s/%d\n",
>  		msg, raw_smp_processor_id(),
>  		current->comm, task_pid_nr(current));
> -	printk(KERN_EMERG " lock: %p, .magic: %08x, .owner: %s/%d, "
> +	printk(KERN_EMERG " lock: %ps, .magic: %08x, .owner: %s/%d, "
>  			".owner_cpu: %d\n",
>  		lock, lock->magic,
>  		owner ? owner->comm : "<none>",

Maybe.  It will only do useful things for statically-allocated locks
which are rare and which we are unlikely to screw up as easily as locks
which lie in dynamically allocated memory.

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH 1/2] vsprintf: Fix %ps on non symbols when using kallsyms
  2012-04-23 21:45 [PATCH 1/2] vsprintf: Fix %ps on non symbols when using kallsyms Stephen Boyd
  2012-04-23 21:45 ` [PATCH 2/2] spinlock_debug: Print kallsyms name for lock Stephen Boyd
@ 2012-04-23 21:55 ` Andrew Morton
  2012-07-26  1:38   ` Stephen Boyd
  1 sibling, 1 reply; 8+ messages in thread
From: Andrew Morton @ 2012-04-23 21:55 UTC (permalink / raw)
  To: Stephen Boyd; +Cc: linux-kernel

On Mon, 23 Apr 2012 14:45:24 -0700
Stephen Boyd <sboyd@codeaurora.org> wrote:

> Using %ps in a printk format will sometimes fail silently and
> print the empty string if the address passed in does not match a
> symbol that kallsyms knows about.

Oh.  The stupid mails came in reverse order.

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH 2/2] spinlock_debug: Print kallsyms name for lock
  2012-04-23 21:54   ` Andrew Morton
@ 2012-04-24  3:17     ` Stephen Boyd
  2012-04-24 21:54       ` Andrew Morton
  0 siblings, 1 reply; 8+ messages in thread
From: Stephen Boyd @ 2012-04-24  3:17 UTC (permalink / raw)
  To: Andrew Morton; +Cc: linux-kernel

On 04/23/12 14:54, Andrew Morton wrote:
>
>> --- a/lib/spinlock_debug.c
>> +++ b/lib/spinlock_debug.c
>> @@ -58,7 +58,7 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
>>  	printk(KERN_EMERG "BUG: spinlock %s on CPU#%d, %s/%d\n",
>>  		msg, raw_smp_processor_id(),
>>  		current->comm, task_pid_nr(current));
>> -	printk(KERN_EMERG " lock: %p, .magic: %08x, .owner: %s/%d, "
>> +	printk(KERN_EMERG " lock: %ps, .magic: %08x, .owner: %s/%d, "
>>  			".owner_cpu: %d\n",
>>  		lock, lock->magic,
>>  		owner ? owner->comm : "<none>",
> Maybe.  It will only do useful things for statically-allocated locks
> which are rare and which we are unlikely to screw up as easily as locks
> which lie in dynamically allocated memory.

Agreed. It catches the really stupid stuff and that's about it. I was
thinking we could get more information about dynamic allocated locks by
adding some code to slab to find the slab that a pointer is allocated
in. Does that sound possible?

With stacktrace support in slub we could even find the caller who
allocated the storage for the spinlock. It might be useful but one could
argue the stacktrace from this function is already pretty useful for
tracking down which spinlock it is.

-- 
Sent by an employee of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum.


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH 2/2] spinlock_debug: Print kallsyms name for lock
  2012-04-24  3:17     ` Stephen Boyd
@ 2012-04-24 21:54       ` Andrew Morton
  2012-05-10 18:53         ` Stephen Boyd
  0 siblings, 1 reply; 8+ messages in thread
From: Andrew Morton @ 2012-04-24 21:54 UTC (permalink / raw)
  To: Stephen Boyd; +Cc: linux-kernel

On Mon, 23 Apr 2012 20:17:03 -0700
Stephen Boyd <sboyd@codeaurora.org> wrote:

> On 04/23/12 14:54, Andrew Morton wrote:
> >
> >> --- a/lib/spinlock_debug.c
> >> +++ b/lib/spinlock_debug.c
> >> @@ -58,7 +58,7 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
> >>  	printk(KERN_EMERG "BUG: spinlock %s on CPU#%d, %s/%d\n",
> >>  		msg, raw_smp_processor_id(),
> >>  		current->comm, task_pid_nr(current));
> >> -	printk(KERN_EMERG " lock: %p, .magic: %08x, .owner: %s/%d, "
> >> +	printk(KERN_EMERG " lock: %ps, .magic: %08x, .owner: %s/%d, "
> >>  			".owner_cpu: %d\n",
> >>  		lock, lock->magic,
> >>  		owner ? owner->comm : "<none>",
> > Maybe.  It will only do useful things for statically-allocated locks
> > which are rare and which we are unlikely to screw up as easily as locks
> > which lie in dynamically allocated memory.
> 
> Agreed. It catches the really stupid stuff and that's about it. I was
> thinking we could get more information about dynamic allocated locks by
> adding some code to slab to find the slab that a pointer is allocated
> in. Does that sound possible?

Well lockdep knows lots of things about the lock, including numerous
stack backtraces which can be used to identify the lock.  Making 
spinlock_debug use lockdep infrastructure seems a good fit.


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH 2/2] spinlock_debug: Print kallsyms name for lock
  2012-04-24 21:54       ` Andrew Morton
@ 2012-05-10 18:53         ` Stephen Boyd
  0 siblings, 0 replies; 8+ messages in thread
From: Stephen Boyd @ 2012-05-10 18:53 UTC (permalink / raw)
  To: Andrew Morton; +Cc: linux-kernel

On 04/24/12 14:54, Andrew Morton wrote:
> On Mon, 23 Apr 2012 20:17:03 -0700
> Stephen Boyd <sboyd@codeaurora.org> wrote:
>
>> On 04/23/12 14:54, Andrew Morton wrote:
>>>> --- a/lib/spinlock_debug.c
>>>> +++ b/lib/spinlock_debug.c
>>>> @@ -58,7 +58,7 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
>>>>  	printk(KERN_EMERG "BUG: spinlock %s on CPU#%d, %s/%d\n",
>>>>  		msg, raw_smp_processor_id(),
>>>>  		current->comm, task_pid_nr(current));
>>>> -	printk(KERN_EMERG " lock: %p, .magic: %08x, .owner: %s/%d, "
>>>> +	printk(KERN_EMERG " lock: %ps, .magic: %08x, .owner: %s/%d, "
>>>>  			".owner_cpu: %d\n",
>>>>  		lock, lock->magic,
>>>>  		owner ? owner->comm : "<none>",
>>> Maybe.  It will only do useful things for statically-allocated locks
>>> which are rare and which we are unlikely to screw up as easily as locks
>>> which lie in dynamically allocated memory.
>> Agreed. It catches the really stupid stuff and that's about it. I was
>> thinking we could get more information about dynamic allocated locks by
>> adding some code to slab to find the slab that a pointer is allocated
>> in. Does that sound possible?
> Well lockdep knows lots of things about the lock, including numerous
> stack backtraces which can be used to identify the lock.  Making 
> spinlock_debug use lockdep infrastructure seems a good fit.
>

I was thinking about this more. In the case of spinlock bad magic I want
to find out who freed this region of memory last because that code most
likely stomped all over my lock and corrupted the magic. With lockdep I
can't find that. I can only find out that the allocator of a lock did a
lock/unlock after a kfree() and I believe lockdep already checks to make
sure live locks are not being freed.

Enabling slub debugging might help, but I would have to get lucky and
allocate the lock after the previous user corrupted it. So I really want
a way to query slab/slub about who last allocated and free this memory
so I can find them when I detect magic corruption.

-- 
Sent by an employee of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum.


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH 1/2] vsprintf: Fix %ps on non symbols when using kallsyms
  2012-04-23 21:55 ` [PATCH 1/2] vsprintf: Fix %ps on non symbols when using kallsyms Andrew Morton
@ 2012-07-26  1:38   ` Stephen Boyd
  0 siblings, 0 replies; 8+ messages in thread
From: Stephen Boyd @ 2012-07-26  1:38 UTC (permalink / raw)
  To: Andrew Morton; +Cc: linux-kernel

Hi Andrew,

On 4/23/2012 2:55 PM, Andrew Morton wrote:
> On Mon, 23 Apr 2012 14:45:24 -0700
> Stephen Boyd <sboyd@codeaurora.org> wrote:
>
>> Using %ps in a printk format will sometimes fail silently and
>> print the empty string if the address passed in does not match a
>> symbol that kallsyms knows about.

A coworker pointed out that the second patch in this series now prints
the symbol closest to the address passed in if kallsyms sees the address
is between two symbols. So if I have a pointer to some member of a
structure %ps prints the symbol for the containing structure, which is
not really helpful.

For example

struct test {
  int i;
  int j;
} my_test;

printk("%ps\n", &my_test.j)


would print out "my_test" instead of "0xc4523400".

This is especially bad for the spinlock debugging case where there could
be two locks embedded in some static structure. I think it would be a
good idea to apply this patch so we get a good middle ground by printing
the name and the offset. Or we can revert the patch and I'll add more
info by printing lockdep information about the lock.

-----8<------

From: Stephen Boyd <sboyd@codeaurora.org>
Subject: [PATCH] spinlock_debug: Print offset in addition to symbol name

If there are two spinlocks embedded in a structure that kallsyms
knows about and one of the spinlocks locks up we will print the
name of the containing structure instead of the address of the
lock. This is quite bad, so let's use %pS instead of %ps so we
get an offset in addition to the symbol so we can determine which
particular lock is having problems.

Signed-off-by: Stephen Boyd <sboyd@codeaurora.org>
---
 lib/spinlock_debug.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/spinlock_debug.c b/lib/spinlock_debug.c
index e91fbc2..eb10578 100644
--- a/lib/spinlock_debug.c
+++ b/lib/spinlock_debug.c
@@ -58,7 +58,7 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
 	printk(KERN_EMERG "BUG: spinlock %s on CPU#%d, %s/%d\n",
 		msg, raw_smp_processor_id(),
 		current->comm, task_pid_nr(current));
-	printk(KERN_EMERG " lock: %ps, .magic: %08x, .owner: %s/%d, "
+	printk(KERN_EMERG " lock: %pS, .magic: %08x, .owner: %s/%d, "
 			".owner_cpu: %d\n",
 		lock, lock->magic,
 		owner ? owner->comm : "<none>",

-- 
Sent by an employee of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum.


^ permalink raw reply related	[flat|nested] 8+ messages in thread

end of thread, other threads:[~2012-07-26  1:38 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2012-04-23 21:45 [PATCH 1/2] vsprintf: Fix %ps on non symbols when using kallsyms Stephen Boyd
2012-04-23 21:45 ` [PATCH 2/2] spinlock_debug: Print kallsyms name for lock Stephen Boyd
2012-04-23 21:54   ` Andrew Morton
2012-04-24  3:17     ` Stephen Boyd
2012-04-24 21:54       ` Andrew Morton
2012-05-10 18:53         ` Stephen Boyd
2012-04-23 21:55 ` [PATCH 1/2] vsprintf: Fix %ps on non symbols when using kallsyms Andrew Morton
2012-07-26  1:38   ` Stephen Boyd

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.