[PANIC][2.5.66bk3+] run_timer_softirq - IRQ Mishandlings

[PANIC][2.5.66bk3+] run_timer_softirq - IRQ Mishandlings

[Shawn Starr]

Panic from 2.5.66-bk3 w/ ksymoops dump:

In both panics below c012e9b4 does not exist as a kernel symbol in
System.map:
=======================================================

Unable to handle kernel paging request at virtual address 6b6b6b6f
 printing eip:
c012e9b4
*pde = 00000000
Oops: 0002 [#1]
CPU:    0
EIP:    0060:[<c012e9b4>]    Not tainted
EFLAGS: 00010012
EIP is at run_timer_softirq+0xe4/0x3f0
eax: 6b6b6b6b   ebx: 6b6b6b6b   ecx: c2e7e150   edx: 6b6b6b6b
esi: 6b6b6b6b   edi: c114a000   ebp: c0419860   esp: c114bf0c
ds: 007b   es: 007b   ss: 0068
Process init (pid: 1, threadinfo=c114a000 task=c114e000)
Stack: c041a8b0 c011282e c114bf94 c114bf24 c114e5d4 c114bfc4 00000011
c114a000
       000000e7 00000092 00000001 c04c9c48 fffffffd 00000046 c012963a
c04c9c48
       c114a000 c114a000 00000000 c04183a0 c010cd75 00000000 c114bf94
c04183a0
Call Trace:
 [<c011282e>] timer_interrupt+0x19e/0x3f0
 [<c012963a>] do_softirq+0x9a/0xa0
 [<c010cd75>] do_IRQ+0x235/0x370
 [<c017a557>] sys_stat64+0x37/0x40
 [<c010ac18>] common_interrupt+0x18/0x20
 [<c010a2bb>] restore_all+0x1/0xe

Code: 89 50 04 89 02 c7 41 30 00 00 00 00 81 3d 60 98 41 c0 3c 4b
 kernel/timer.c:258: spin_lock(kernel/timer.c:c0419860) already locked by
kernel/timer.c/398
Kernel panic: Aiee, killing interrupt handler!
In interrupt handler - not syncing


ksymoops dump:

Code;  00000000 Before first symbol
00000000 <_EIP>:
Code;  00000000 Before first symbol
   0:   89 50 04                  mov    %edx,0x4(%eax)
Code;  00000003 Before first symbol
   3:   89 02                     mov    %eax,(%edx)
Code;  00000005 Before first symbol
   5:   c7 41 30 00 00 00 00      movl   $0x0,0x30(%ecx)
Code;  0000000c Before first symbol
   c:   81 3d 60 98 41 c0 3c      cmpl   $0x4b3c,0xc0419860
Code;  00000013 Before first symbol
  13:   4b 00 00


We know this is poisioned ('6b') EIP c012e9b4 is not present in System.map.
The machine was on for several hours 8+


----------------------------------------------------------------------------
--------------------------------------

Panic #2 (older) from 2.5.65:

Unable to handle kernel paging request at virtual address 6b6b6b6f
 printing eip:
c012e920
*pde = 00000000
Oops: 0002
CPU:    0
EIP:    0060:[<c012e920>]    Not tainted
EFLAGS: 00010016
EIP is at run_timer_softirq+0xd0/0x3f0
eax: 6b6b6b6b   ebx: c7de5150   ecx: 000000ee   edx: 6b6b6b6b
esi: 6b6b6b6b   edi: 6b6b6b6b   ebp: c0418bc0   esp: c117fe80
ds: 007b   es: 007b   ss: 0068
Process init (pid: 1, threadinfo=c117e000 task=c117c000)
Stack: c01127ae c117ff04 c117ff44 c0130249 c128423c c7fc2ac0 c117e000
c117e000
       c117e000 00000001 c04c5c48 fffffffd 00000046 c012960a c04c5c48
c117e000
       c117e000 00000000 c0417700 c010cd05 00000000 c117ff04 c0417700
fffffffe
Call Trace:
 [<c01127ae>] timer_interrupt+0x19e/0x3f0
 [<c0130249>] __dequeue_signal+0xc9/0x180
 [<c012960a>] do_softirq+0x9a/0xa0
 [<c010cd05>] do_IRQ+0x235/0x370
 [<c0180e37>] link_path_walk+0x247/0xdc0
 [<c010abf8>] common_interrupt+0x18/0x20
 [<c014007b>] sys_timer_delete+0x1db/0x210
 [<c014d756>] fprob+0x26/0x40
 [<c014d7ab>] check_poison_obj+0x3b/0x1b0
 [<c0181e6c>] __user_walk+0x5c/0x60
 [<c014f71c>] kmem_cache_alloc+0x12c/0x170
 [<c017f9c1>] getname+0x31/0xd0
 [<c017f9c1>] getname+0x31/0xd0
 [<c016b83b>] sys_open+0x1b/0x90
 [<c010a28b>] syscall_call+0x7/0xb

Code: 89 50 04 89 02 c7 43 30 00 00 00 00 81 3d c0 8b 41 c0 3c 4b
 <0>Kernel panic: Aiee, killing interrupt handler!
In interrupt handler - not syncing
 kernel/timer.c:251: spin_lock(kernel/timer.c:c0418bc0) already locked by
kernel/timer.
c/389

ksymoops zwane debugged showed garbage, also poisioned ('6b').

I can say none of these irq mishaps have happened in 2.4.xx so some driver
or resource is trying to reuse a timer that doesn't exist anymore (if thats
the case).

Shawn.

Re: [PANIC][2.5.66bk3+] run_timer_softirq - IRQ Mishandlings

[Robert Love]

On Sat, 2003-03-29 at 15:45, Shawn Starr wrote:

> In both panics below c012e9b4 does not exist as a kernel symbol in
> System.map:

The EIP need not exist itself in System.map.  System.map has the symbol
to initial address mapping.  For example,

	100	functionA
	200	functionB

If the EIP was "150" you would be 50 bytes into functionA().

> Code: 89 50 04 89 02 c7 41 30 00 00 00 00 81 3d 60 98 41 c0 3c 4b
>  kernel/timer.c:258: spin_lock(kernel/timer.c:c0419860) already locked by
> kernel/timer.c/398
> Kernel panic: Aiee, killing interrupt handler!
> In interrupt handler - not syncing

This is not a panic, just an oops.  And it was just a debugging check
from spin lock debugging, but unfortunately you were in an interrupt
handler so the machine went bye bye.

It is probably a simple double-lock deadlock, detected by spin lock
debugging.  Knowing the EIP would help... but timer_interrupt() is a
good first guess.

	Robert Love

Re: [OOPS][2.5.66bk3+] run_timer_softirq - IRQ Mishandlings

[Shawn Starr]

How can I go about debugging this? How can I find the path causing the
problem?

Shawn.

----- Original Message -----
From: "Robert Love" <rml@tech9.net>
To: "Shawn Starr" <spstarr@sh0n.net>
Cc: <linux-kernel@vger.kernel.org>
Sent: Saturday, March 29, 2003 4:15 PM
Subject: Re: [PANIC][2.5.66bk3+] run_timer_softirq - IRQ Mishandlings


> On Sat, 2003-03-29 at 15:45, Shawn Starr wrote:
>
> > In both panics below c012e9b4 does not exist as a kernel symbol in
> > System.map:
>
> The EIP need not exist itself in System.map.  System.map has the symbol
> to initial address mapping.  For example,
>
> 100 functionA
> 200 functionB
>
> If the EIP was "150" you would be 50 bytes into functionA().
>
> > Code: 89 50 04 89 02 c7 41 30 00 00 00 00 81 3d 60 98 41 c0 3c 4b
> >  kernel/timer.c:258: spin_lock(kernel/timer.c:c0419860) already locked
by
> > kernel/timer.c/398
> > Kernel panic: Aiee, killing interrupt handler!
> > In interrupt handler - not syncing
>
> This is not a panic, just an oops.  And it was just a debugging check
> from spin lock debugging, but unfortunately you were in an interrupt
> handler so the machine went bye bye.
>
> It is probably a simple double-lock deadlock, detected by spin lock
> debugging.  Knowing the EIP would help... but timer_interrupt() is a
> good first guess.
>
> Robert Love
>
>

Re: [OOPS][2.5.66bk3+] run_timer_softirq - IRQ Mishandlings

[Robert Love]

On Sat, 2003-03-29 at 16:42, Shawn Starr wrote:

> How can I go about debugging this? How can I find the path causing
> the problem?

Begin by finding out where the EIP is.  It should be a spin_lock().  The
oops says it is kernel/timer.c:258.

This line is a double locking of an already-locked lock.  So find where
the initial lock was.  The oops said that is kernel/timer.c:398.

Look at the call chain (from the oops) from the first to the second
lock.  Someone assumed it could not happen.  Obviously they were wrong.

	Robert Love

Re: [OOPS][2.5.66bk3+] run_timer_softirq - IRQ Mishandlings

[Andrew Morton]

"Shawn Starr" <spstarr@sh0n.net> wrote:
>
> How can I go about debugging this? How can I find the path causing the
> problem?
> 

Someone did

	kfree(foo);

insead of

	del_timer_sync(&foo->timer);
	kfree(foo);

so you have a freed-but-pending timer.


This is a horrid bug.  One way to find it would be to change
cache_free_debugcheck() to walk the just-freed-up memory looking for an
instance of TIMER_MAGIC.  If that is found and timer_pending() is true then
drop a backtrace and print out timer->function.

err....  Here you go, this may find it.



 fs/open.c             |   33 +++++++++++++++++++++++++++++++++
 include/linux/timer.h |    3 ++-
 mm/slab.c             |   30 ++++++++++++++++++++++++++++++
 3 files changed, 65 insertions(+), 1 deletion(-)

diff -puN include/linux/timer.h~freed-timer-finder include/linux/timer.h
--- 25/include/linux/timer.h~freed-timer-finder	2003-03-29 14:10:15.000000000 -0800
+++ 25-akpm/include/linux/timer.h	2003-03-29 14:10:26.000000000 -0800
@@ -8,11 +8,12 @@
 struct tvec_t_base_s;
 
 struct timer_list {
+	unsigned long magic;
+
 	struct list_head entry;
 	unsigned long expires;
 
 	spinlock_t lock;
-	unsigned long magic;
 
 	void (*function)(unsigned long);
 	unsigned long data;
diff -puN mm/slab.c~freed-timer-finder mm/slab.c
--- 25/mm/slab.c~freed-timer-finder	2003-03-29 14:10:30.000000000 -0800
+++ 25-akpm/mm/slab.c	2003-03-29 14:16:23.000000000 -0800
@@ -800,6 +800,35 @@ static void poison_obj(kmem_cache_t *cac
 	*(unsigned char *)(addr+size-1) = POISON_END;
 }
 
+static void timer_hunt(kmem_cache_t *cachep, void *addr)
+{
+	int size = cachep->objsize;
+	void *p;
+
+	if (cachep->flags & SLAB_RED_ZONE) {
+		addr += BYTES_PER_WORD;
+		size -= 2*BYTES_PER_WORD;
+	}
+	if (cachep->flags & SLAB_STORE_USER) {
+		size -= BYTES_PER_WORD;
+	}
+
+	for (p = addr; p < addr + size; p += sizeof(unsigned long)) {
+		unsigned long *laddr = p;
+
+		if (*laddr == TIMER_MAGIC) {
+			struct timer_list *timer;
+
+			timer = (struct timer_list *)laddr;
+			if (timer_pending(timer)) {
+				printk("free of pending timer at %p\n", timer);
+				printk("function=%p\n", timer->function);
+				dump_stack();
+			}
+		}
+	}
+}
+
 static void *fprob(unsigned char* addr, unsigned int size)
 {
 	unsigned char *end;
@@ -1603,6 +1632,7 @@ static inline void *cache_free_debugchec
 		else
 			cachep->dtor(objp, cachep, 0);
 	}
+	timer_hunt(cachep, objp);
 	if (cachep->flags & SLAB_POISON)
 		poison_obj(cachep, objp, POISON_AFTER);
 #endif
diff -puN fs/open.c~freed-timer-finder fs/open.c
--- 25/fs/open.c~freed-timer-finder	2003-03-29 14:17:32.000000000 -0800
+++ 25-akpm/fs/open.c	2003-03-29 14:21:20.000000000 -0800
@@ -793,11 +793,44 @@ void fd_install(unsigned int fd, struct 
 	write_unlock(&files->file_lock);
 }
 
+#include <linux/timer.h>
+
+struct foo_thing {
+	int a;
+	struct timer_list t;
+	int b;
+};
+
+static void my_foo(unsigned long data)
+{
+	printk("the handler\n");
+}
+
+static void timer_thing(void)
+{
+	static int did_it;
+	struct foo_thing *f;
+
+	if (did_it)
+		return;
+	did_it = 1;
+
+	f = kmalloc(sizeof(*f), GFP_KERNEL);
+	init_timer(&f->t);
+	f->t.expires = jiffies + HZ;
+	f->t.function = my_foo;
+	add_timer(&f->t);
+	kfree(f);
+}
+
 asmlinkage long sys_open(const char * filename, int flags, int mode)
 {
 	char * tmp;
 	int fd, error;
 
+	if (current->uid == 9999)
+		timer_thing();
+
 #if BITS_PER_LONG != 32
 	flags |= O_LARGEFILE;
 #endif

_

Re: [OOPS][2.5.66bk3+] run_timer_softirq - IRQ Mishandlings

[Shawn Starr]

Applying this now.

----- Original Message -----
From: "Andrew Morton" <akpm@digeo.com>
To: "Shawn Starr" <spstarr@sh0n.net>
Cc: <rml@tech9.net>; <linux-kernel@vger.kernel.org>
Sent: Saturday, March 29, 2003 5:28 PM
Subject: Re: [OOPS][2.5.66bk3+] run_timer_softirq - IRQ Mishandlings


> "Shawn Starr" <spstarr@sh0n.net> wrote:
> >
> > How can I go about debugging this? How can I find the path causing the
> > problem?
> >
>
> Someone did
>
> kfree(foo);
>
> insead of
>
> del_timer_sync(&foo->timer);
> kfree(foo);
>
> so you have a freed-but-pending timer.
>
>
> This is a horrid bug.  One way to find it would be to change
> cache_free_debugcheck() to walk the just-freed-up memory looking for an
> instance of TIMER_MAGIC.  If that is found and timer_pending() is true
then
> drop a backtrace and print out timer->function.
>
> err....  Here you go, this may find it.
>
>
>
>  fs/open.c             |   33 +++++++++++++++++++++++++++++++++
>  include/linux/timer.h |    3 ++-
>  mm/slab.c             |   30 ++++++++++++++++++++++++++++++
>  3 files changed, 65 insertions(+), 1 deletion(-)
>
> diff -puN include/linux/timer.h~freed-timer-finder include/linux/timer.h
> --- 25/include/linux/timer.h~freed-timer-finder 2003-03-29
14:10:15.000000000 -0800
> +++ 25-akpm/include/linux/timer.h 2003-03-29 14:10:26.000000000 -0800
> @@ -8,11 +8,12 @@
>  struct tvec_t_base_s;
>
>  struct timer_list {
> + unsigned long magic;
> +
>   struct list_head entry;
>   unsigned long expires;
>
>   spinlock_t lock;
> - unsigned long magic;
>
>   void (*function)(unsigned long);
>   unsigned long data;
> diff -puN mm/slab.c~freed-timer-finder mm/slab.c
> --- 25/mm/slab.c~freed-timer-finder 2003-03-29 14:10:30.000000000 -0800
> +++ 25-akpm/mm/slab.c 2003-03-29 14:16:23.000000000 -0800
> @@ -800,6 +800,35 @@ static void poison_obj(kmem_cache_t *cac
>   *(unsigned char *)(addr+size-1) = POISON_END;
>  }
>
> +static void timer_hunt(kmem_cache_t *cachep, void *addr)
> +{
> + int size = cachep->objsize;
> + void *p;
> +
> + if (cachep->flags & SLAB_RED_ZONE) {
> + addr += BYTES_PER_WORD;
> + size -= 2*BYTES_PER_WORD;
> + }
> + if (cachep->flags & SLAB_STORE_USER) {
> + size -= BYTES_PER_WORD;
> + }
> +
> + for (p = addr; p < addr + size; p += sizeof(unsigned long)) {
> + unsigned long *laddr = p;
> +
> + if (*laddr == TIMER_MAGIC) {
> + struct timer_list *timer;
> +
> + timer = (struct timer_list *)laddr;
> + if (timer_pending(timer)) {
> + printk("free of pending timer at %p\n", timer);
> + printk("function=%p\n", timer->function);
> + dump_stack();
> + }
> + }
> + }
> +}
> +
>  static void *fprob(unsigned char* addr, unsigned int size)
>  {
>   unsigned char *end;
> @@ -1603,6 +1632,7 @@ static inline void *cache_free_debugchec
>   else
>   cachep->dtor(objp, cachep, 0);
>   }
> + timer_hunt(cachep, objp);
>   if (cachep->flags & SLAB_POISON)
>   poison_obj(cachep, objp, POISON_AFTER);
>  #endif
> diff -puN fs/open.c~freed-timer-finder fs/open.c
> --- 25/fs/open.c~freed-timer-finder 2003-03-29 14:17:32.000000000 -0800
> +++ 25-akpm/fs/open.c 2003-03-29 14:21:20.000000000 -0800
> @@ -793,11 +793,44 @@ void fd_install(unsigned int fd, struct
>   write_unlock(&files->file_lock);
>  }
>
> +#include <linux/timer.h>
> +
> +struct foo_thing {
> + int a;
> + struct timer_list t;
> + int b;
> +};
> +
> +static void my_foo(unsigned long data)
> +{
> + printk("the handler\n");
> +}
> +
> +static void timer_thing(void)
> +{
> + static int did_it;
> + struct foo_thing *f;
> +
> + if (did_it)
> + return;
> + did_it = 1;
> +
> + f = kmalloc(sizeof(*f), GFP_KERNEL);
> + init_timer(&f->t);
> + f->t.expires = jiffies + HZ;
> + f->t.function = my_foo;
> + add_timer(&f->t);
> + kfree(f);
> +}
> +
>  asmlinkage long sys_open(const char * filename, int flags, int mode)
>  {
>   char * tmp;
>   int fd, error;
>
> + if (current->uid == 9999)
> + timer_thing();
> +
>  #if BITS_PER_LONG != 32
>   flags |= O_LARGEFILE;
>  #endif
>
> _
>
>

Re: [OOPS][2.5.66bk3+] run_timer_softirq - IRQ Mishandlings

[Shawn Starr]

Perhaps adding this to the kernel as a config option might be handy for
people looking for not freed timers?

Shawn.

----- Original Message -----
From: "Andrew Morton" <akpm@digeo.com>
To: "Shawn Starr" <spstarr@sh0n.net>
Cc: <rml@tech9.net>; <linux-kernel@vger.kernel.org>
Sent: Saturday, March 29, 2003 5:28 PM
Subject: Re: [OOPS][2.5.66bk3+] run_timer_softirq - IRQ Mishandlings


> "Shawn Starr" <spstarr@sh0n.net> wrote:
> >
> > How can I go about debugging this? How can I find the path causing the
> > problem?
> >
>
> Someone did
>
> kfree(foo);
>
> insead of
>
> del_timer_sync(&foo->timer);
> kfree(foo);
>
> so you have a freed-but-pending timer.
>
>
> This is a horrid bug.  One way to find it would be to change
> cache_free_debugcheck() to walk the just-freed-up memory looking for an
> instance of TIMER_MAGIC.  If that is found and timer_pending() is true
then
> drop a backtrace and print out timer->function.
>
> err....  Here you go, this may find it.
>
>
>
>  fs/open.c             |   33 +++++++++++++++++++++++++++++++++
>  include/linux/timer.h |    3 ++-
>  mm/slab.c             |   30 ++++++++++++++++++++++++++++++
>  3 files changed, 65 insertions(+), 1 deletion(-)
>
> diff -puN include/linux/timer.h~freed-timer-finder include/linux/timer.h
> --- 25/include/linux/timer.h~freed-timer-finder 2003-03-29
14:10:15.000000000 -0800
> +++ 25-akpm/include/linux/timer.h 2003-03-29 14:10:26.000000000 -0800
> @@ -8,11 +8,12 @@
>  struct tvec_t_base_s;
>
>  struct timer_list {
> + unsigned long magic;
> +
>   struct list_head entry;
>   unsigned long expires;
>
>   spinlock_t lock;
> - unsigned long magic;
>
>   void (*function)(unsigned long);
>   unsigned long data;
> diff -puN mm/slab.c~freed-timer-finder mm/slab.c
> --- 25/mm/slab.c~freed-timer-finder 2003-03-29 14:10:30.000000000 -0800
> +++ 25-akpm/mm/slab.c 2003-03-29 14:16:23.000000000 -0800
> @@ -800,6 +800,35 @@ static void poison_obj(kmem_cache_t *cac
>   *(unsigned char *)(addr+size-1) = POISON_END;
>  }
>
> +static void timer_hunt(kmem_cache_t *cachep, void *addr)
> +{
> + int size = cachep->objsize;
> + void *p;
> +
> + if (cachep->flags & SLAB_RED_ZONE) {
> + addr += BYTES_PER_WORD;
> + size -= 2*BYTES_PER_WORD;
> + }
> + if (cachep->flags & SLAB_STORE_USER) {
> + size -= BYTES_PER_WORD;
> + }
> +
> + for (p = addr; p < addr + size; p += sizeof(unsigned long)) {
> + unsigned long *laddr = p;
> +
> + if (*laddr == TIMER_MAGIC) {
> + struct timer_list *timer;
> +
> + timer = (struct timer_list *)laddr;
> + if (timer_pending(timer)) {
> + printk("free of pending timer at %p\n", timer);
> + printk("function=%p\n", timer->function);
> + dump_stack();
> + }
> + }
> + }
> +}
> +
>  static void *fprob(unsigned char* addr, unsigned int size)
>  {
>   unsigned char *end;
> @@ -1603,6 +1632,7 @@ static inline void *cache_free_debugchec
>   else
>   cachep->dtor(objp, cachep, 0);
>   }
> + timer_hunt(cachep, objp);
>   if (cachep->flags & SLAB_POISON)
>   poison_obj(cachep, objp, POISON_AFTER);
>  #endif
> diff -puN fs/open.c~freed-timer-finder fs/open.c
> --- 25/fs/open.c~freed-timer-finder 2003-03-29 14:17:32.000000000 -0800
> +++ 25-akpm/fs/open.c 2003-03-29 14:21:20.000000000 -0800
> @@ -793,11 +793,44 @@ void fd_install(unsigned int fd, struct
>   write_unlock(&files->file_lock);
>  }
>
> +#include <linux/timer.h>
> +
> +struct foo_thing {
> + int a;
> + struct timer_list t;
> + int b;
> +};
> +
> +static void my_foo(unsigned long data)
> +{
> + printk("the handler\n");
> +}
> +
> +static void timer_thing(void)
> +{
> + static int did_it;
> + struct foo_thing *f;
> +
> + if (did_it)
> + return;
> + did_it = 1;
> +
> + f = kmalloc(sizeof(*f), GFP_KERNEL);
> + init_timer(&f->t);
> + f->t.expires = jiffies + HZ;
> + f->t.function = my_foo;
> + add_timer(&f->t);
> + kfree(f);
> +}
> +
>  asmlinkage long sys_open(const char * filename, int flags, int mode)
>  {
>   char * tmp;
>   int fd, error;
>
> + if (current->uid == 9999)
> + timer_thing();
> +
>  #if BITS_PER_LONG != 32
>   flags |= O_LARGEFILE;
>  #endif
>
> _
>
>

Re: [PANIC][2.5.66bk3+] run_timer_softirq - IRQ Mishandlings

[Zwane Mwaikambo]

On Sat, 29 Mar 2003, Shawn Starr wrote:

> Code: 89 50 04 89 02 c7 43 30 00 00 00 00 81 3d c0 8b 41 c0 3c 4b
>  <0>Kernel panic: Aiee, killing interrupt handler!
> In interrupt handler - not syncing
>  kernel/timer.c:251: spin_lock(kernel/timer.c:c0418bc0) already locked by
> kernel/timer.
> c/389
> 
> ksymoops zwane debugged showed garbage, also poisioned ('6b').

Huh ?

-- 
function.linuxpower.ca