Re: 2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

Re: 2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[Duncan Sands]

On Wednesday 10 April 2002 5:41 pm, you wrote:
> On Wed, Apr 10, 2002, Duncan Sands <duncan.sands@math.u-psud.fr> wrote:
> > UP x86 K6 system running 2.5.8-pre3 with preemption.
> > Using usb-uhci.  I got the following bug when powering off:
> >
> > usb.c: USB disconnect on device 3
> > kernel BUG at usb.c:849!
> > invalid operand: 0000
> > CPU:    0
> > EIP:    0010:[<cc8babe2>]    Not tainted
> > EFLAGS: 00010246
> > eax: 00000000   ebx: cb8e2800   ecx: cb8e2550   edx: 00000002
> > esi: cbc75d88   edi: cc8c7a20   ebp: ffffffff   esp: cab5ff24
> > ds: 0018   es: 0018   ss: 0018
> > Process rmmod (pid: 1787, threadinfo=cab5e000 task=c952a6a0)
> > Stack: cb8e29f8 cc8bbafe cb8e2800 cb8e25bc cb796180 cc8c79a0 0000000e
> > 0000024c cb8e2800 cc8bbaad cb8e25bc cb796080 cc8ce600 c71a5000 cc8c9000
> > 000000c4 cb8e2400 cc8ccc7a cab5ff74 c12dc800 00000000 c01cf07f c12dc800
> > cc8c9000 Call Trace: [<cc8bbafe>] [<cc8c79a0>] [<cc8bbaad>] [<cc8ce600>]
> > [<cc8ccc7a>] [pci_unregister_driver+51/76] [<cc8cd176>] [<cc8ce600>]
> > [free_module+23/192] [sys_delete_module+292/628] [syscall_call+7/11]
> > Code: 0f 0b 51 03 94 42 8c cc 8b 83 cc 00 00 00 8b 40 18 53 8b 40
>
> Could you run this through ksymoops?

I did but it didn't give any more info.  The problem is that I had no
 /var/log/ksymoops directory (used for automatic dumping of symbol info), so
 after the reboot I couldn't tell ksymoops where the modules were loaded... 
 I am now trying to reproduce the oops and get more info.

> >  <3>error: rmmod[1787] exited with preempt_count 1
>
> I don't like the looks of that.
>
> JE

It suggests a locking problem, but it may be misleading: imagine the oops
came when a spin lock was held, then couldn't you get this message?

All the best,

Duncan.

2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[Duncan Sands]

UP x86 K6 system running 2.5.8-pre3 with preemption.
Using usb-uhci.  I got the following bug when powering off:

usb.c: USB disconnect on device 3
kernel BUG at usb.c:849!
invalid operand: 0000
CPU:    0
EIP:    0010:[<cc8babe2>]    Not tainted
EFLAGS: 00010246
eax: 00000000   ebx: cb8e2800   ecx: cb8e2550   edx: 00000002
esi: cbc75d88   edi: cc8c7a20   ebp: ffffffff   esp: cab5ff24
ds: 0018   es: 0018   ss: 0018
Process rmmod (pid: 1787, threadinfo=cab5e000 task=c952a6a0)
Stack: cb8e29f8 cc8bbafe cb8e2800 cb8e25bc cb796180 cc8c79a0 0000000e 0000024c
       cb8e2800 cc8bbaad cb8e25bc cb796080 cc8ce600 c71a5000 cc8c9000 000000c4
       cb8e2400 cc8ccc7a cab5ff74 c12dc800 00000000 c01cf07f c12dc800 cc8c9000
Call Trace: [<cc8bbafe>] [<cc8c79a0>] [<cc8bbaad>] [<cc8ce600>] [<cc8ccc7a>]
   [pci_unregister_driver+51/76] [<cc8cd176>] [<cc8ce600>] [free_module+23/192] [sys_delete_module+292/628] [syscall_call+7/11]
Code: 0f 0b 51 03 94 42 8c cc 8b 83 cc 00 00 00 8b 40 18 53 8b 40
 <3>error: rmmod[1787] exited with preempt_count 1

Re: 2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[Johannes Erdfelt]

On Wed, Apr 10, 2002, Duncan Sands <duncan.sands@math.u-psud.fr> wrote:
> UP x86 K6 system running 2.5.8-pre3 with preemption.
> Using usb-uhci.  I got the following bug when powering off:
> 
> usb.c: USB disconnect on device 3
> kernel BUG at usb.c:849!
> invalid operand: 0000
> CPU:    0
> EIP:    0010:[<cc8babe2>]    Not tainted
> EFLAGS: 00010246
> eax: 00000000   ebx: cb8e2800   ecx: cb8e2550   edx: 00000002
> esi: cbc75d88   edi: cc8c7a20   ebp: ffffffff   esp: cab5ff24
> ds: 0018   es: 0018   ss: 0018
> Process rmmod (pid: 1787, threadinfo=cab5e000 task=c952a6a0)
> Stack: cb8e29f8 cc8bbafe cb8e2800 cb8e25bc cb796180 cc8c79a0 0000000e 0000024c
>        cb8e2800 cc8bbaad cb8e25bc cb796080 cc8ce600 c71a5000 cc8c9000 000000c4
>        cb8e2400 cc8ccc7a cab5ff74 c12dc800 00000000 c01cf07f c12dc800 cc8c9000
> Call Trace: [<cc8bbafe>] [<cc8c79a0>] [<cc8bbaad>] [<cc8ce600>] [<cc8ccc7a>]
>    [pci_unregister_driver+51/76] [<cc8cd176>] [<cc8ce600>] [free_module+23/192] [sys_delete_module+292/628] [syscall_call+7/11]
> Code: 0f 0b 51 03 94 42 8c cc 8b 83 cc 00 00 00 8b 40 18 53 8b 40

Could you run this through ksymoops?

>  <3>error: rmmod[1787] exited with preempt_count 1

I don't like the looks of that.

JE

Re: 2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[Robert Love]

On Wed, 2002-04-10 at 11:41, Johannes Erdfelt wrote:

> >  <3>error: rmmod[1787] exited with preempt_count 1
> 
> I don't like the looks of that.

That error means a task exited with a nonzero preempt_count, in this
case 1.  This means a lock was held after exit (or, a lock was never
unlocked - e.g. it was dynamic and just deleted, but the lock counting
code can't know that).

In this case it may just be because the task oopsed while holding the
lock and then exited.  This may point to the lock being the BKL since it
would be trivial to have it reschedule and then die while holding it.

While the main point of that error is to point out code that does rude
things with preemption, in this case we probably just have another
problem and this is another sign of it.

	Robert Love

Re: 2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[Duncan Sands]

Ok, I got a new oops, which I could decode:

ksymoops 2.4.5 on i586 2.5.8-pre3.  Options used
     -V (default)
     -k /var/log/ksymoops/20020410185940.ksyms (specified)
     -l /var/log/ksymoops/20020410185940.modules (specified)
     -o /lib/modules/2.5.8-pre3/ (specified)
     -m /boot/System.map-2.5.8-pre3 (specified)

kernel BUG at usb.c:849!
invalid operand: 0000
CPU:    0
EIP:    0010:[<cc8babe2>]    Not tainted
Using defaults from ksymoops -t elf32-i386 -a i386
EFLAGS: 00010246
eax: 00000000   ebx: cb987800   ecx: cb987550   edx: 00000002
esi: c962c588   edi: cc8c7a20   ebp: ffffffff   esp: c93bff24
ds: 0018   es: 0018   ss: 0018
Stack: cb9879f8 cc8bbafe cb987800 cb9875bc cb763180 cc8c79a0 0000000e 0000024c 
       cb987800 cc8bbaad cb9875bc cb763080 cc8ce600 c991e000 cc8c9000 000000c4 
       cb987400 cc8ccc7a c93bff74 c12dc800 00000000 c01cf07f c12dc800 cc8c9000 
Call Trace: [<cc8bbafe>] [<cc8c79a0>] [<cc8bbaad>] [<cc8ce600>] [<cc8ccc7a>] 
Code: 0f 0b 51 03 94 42 8c cc 8b 83 cc 00 00 00 8b 40 18 53 8b 40 


>>EIP; cc8babe2 <[usbcore]usb_free_dev+26/5c>   <=====

>>ebx; cb987800 <_end+b6a64e0/c589ce0>
>>ecx; cb987550 <_end+b6a6230/c589ce0>
>>esi; c962c588 <_end+934b268/c589ce0>
>>edi; cc8c7a20 <[usbcore]usbdevfs_driver+20/40>
>>ebp; ffffffff <END_OF_CODE+337319bc/????>
>>esp; c93bff24 <_end+90dec04/c589ce0>

Trace; cc8bbafe <[usbcore]usb_disconnect+156/160>
Trace; cc8c79a0 <[usbcore]hub_driver+20/40>
Trace; cc8bbaad <[usbcore]usb_disconnect+105/160>
Trace; cc8ce600 <[usb-uhci]uhci_pci_driver+0/3f>
Trace; cc8ccc7a <[usb-uhci]uhci_pci_remove+2a/c0>

Code;  cc8babe2 <[usbcore]usb_free_dev+26/5c>
00000000 <_EIP>:
Code;  cc8babe2 <[usbcore]usb_free_dev+26/5c>   <=====
   0:   0f 0b                     ud2a      <=====
Code;  cc8babe4 <[usbcore]usb_free_dev+28/5c>
   2:   51                        push   %ecx
Code;  cc8babe5 <[usbcore]usb_free_dev+29/5c>
   3:   03 94 42 8c cc 8b 83      add    0x838bcc8c(%edx,%eax,2),%edx
Code;  cc8babec <[usbcore]usb_free_dev+30/5c>
   a:   cc                        int3   
Code;  cc8babed <[usbcore]usb_free_dev+31/5c>
   b:   00 00                     add    %al,(%eax)
Code;  cc8babef <[usbcore]usb_free_dev+33/5c>
   d:   00 8b 40 18 53 8b         add    %cl,0x8b531840(%ebx)
Code;  cc8babf5 <[usbcore]usb_free_dev+39/5c>
  13:   40                        inc    %eax