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
On Wed, Apr 10, 2002, Duncan Sands <[email protected]> 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
> > 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
> > ...
Does the same BUG happen with "uhci"?
And what usb device driver(s) were supposed to have stopped
using "device 3"? I've only noticed such device refcounting bugs
being caused by the USB device drivers with bad disconnect()
routines, not usbcore or any of the host controller drivers, but of
course that can change.
- Dave
On Wednesday 10 April 2002 5:41 pm, you wrote:
> On Wed, Apr 10, 2002, Duncan Sands <[email protected]> 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.
On Wednesday 10 April 2002 6:40 pm, you 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
> > > ...
>
> Does the same BUG happen with "uhci"?
I haven't been able to reproduce it yet with usb-uhci... I will try uhci
also.
> And what usb device driver(s) were supposed to have stopped
> using "device 3"? I've only noticed such device refcounting bugs
> being caused by the USB device drivers with bad disconnect()
> routines, not usbcore or any of the host controller drivers, but of
> course that can change.
Ha!
$ cat /proc/bus/usb/drivers
usbfs
hub
There are no other drivers! I have a USB webcam and a modem
attached. I didn't compile the driver for the webcam, and the modem
has a user space driver that works via usbfs.
Duncan.
T: Bus=01 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=12 MxCh= 2
B: Alloc= 0/900 us ( 0%), #Int= 0, #Iso= 0
D: Ver= 1.00 Cls=09(hub ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=0000 ProdID=0000 Rev= 0.00
S: Product=USB UHCI Root Hub
S: SerialNumber=b800
C:* #Ifs= 1 Cfg#= 1 Atr=40 MxPwr= 0mA
I: If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 8 Ivl=255ms
T: Bus=01 Lev=01 Prnt=01 Port=00 Cnt=01 Dev#= 2 Spd=12 MxCh= 0
D: Ver= 1.00 Cls=ff(vend.) Sub=ff Prot=ff MxPS= 8 #Cfgs= 1
P: Vendor=046d ProdID=0840 Rev= 1.00
S: Product=Camera
C:* #Ifs= 1 Cfg#= 1 Atr=80 MxPwr=500mA
I: If#= 0 Alt= 0 #EPs= 2 Cls=ff(vend.) Sub=ff Prot=ff Driver=(none)
E: Ad=81(I) Atr=01(Isoc) MxPS= 0 Ivl=1ms
E: Ad=82(I) Atr=03(Int.) MxPS= 1 Ivl=16ms
I: If#= 0 Alt= 1 #EPs= 2 Cls=ff(vend.) Sub=ff Prot=ff Driver=(none)
E: Ad=81(I) Atr=01(Isoc) MxPS=1023 Ivl=1ms
E: Ad=82(I) Atr=03(Int.) MxPS= 1 Ivl=16ms
T: Bus=01 Lev=01 Prnt=01 Port=01 Cnt=02 Dev#= 3 Spd=12 MxCh= 0
D: Ver= 1.10 Cls=ff(vend.) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=06b9 ProdID=4061 Rev= 0.00
S: Manufacturer=ALCATEL
S: Product=Speed Touch USB
S: SerialNumber=0090D02C2C5A
C:* #Ifs= 3 Cfg#= 1 Atr=80 MxPwr=500mA
I: If#= 0 Alt= 0 #EPs= 1 Cls=ff(vend.) Sub=00 Prot=00 Driver=usbfs
E: Ad=81(I) Atr=03(Int.) MxPS= 16 Ivl=50ms
I: If#= 1 Alt= 0 #EPs= 0 Cls=ff(vend.) Sub=00 Prot=00 Driver=usbfs
I: If#= 1 Alt= 1 #EPs= 3 Cls=ff(vend.) Sub=00 Prot=00 Driver=usbfs
E: Ad=06(O) Atr=02(Bulk) MxPS= 64 Ivl=0ms
E: Ad=07(O) Atr=02(Bulk) MxPS= 64 Ivl=0ms
E: Ad=87(I) Atr=02(Bulk) MxPS= 64 Ivl=0ms
I: If#= 1 Alt= 2 #EPs= 3 Cls=ff(vend.) Sub=00 Prot=00 Driver=usbfs
E: Ad=06(O) Atr=02(Bulk) MxPS= 32 Ivl=0ms
E: Ad=07(O) Atr=02(Bulk) MxPS= 32 Ivl=0ms
E: Ad=87(I) Atr=02(Bulk) MxPS= 64 Ivl=0ms
I: If#= 1 Alt= 3 #EPs= 3 Cls=ff(vend.) Sub=00 Prot=00 Driver=usbfs
E: Ad=06(O) Atr=02(Bulk) MxPS= 16 Ivl=0ms
E: Ad=07(O) Atr=02(Bulk) MxPS= 16 Ivl=0ms
E: Ad=87(I) Atr=02(Bulk) MxPS= 64 Ivl=0ms
I: If#= 2 Alt= 0 #EPs= 2 Cls=ff(vend.) Sub=00 Prot=00 Driver=(none)
E: Ad=05(O) Atr=02(Bulk) MxPS= 8 Ivl=0ms
E: Ad=85(I) Atr=02(Bulk) MxPS= 8 Ivl=0ms
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
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
> > And what usb device driver(s) were supposed to have stopped
> > using "device 3"? I've only noticed such device refcounting bugs
> > being caused by the USB device drivers with bad disconnect()
> > routines, not usbcore or any of the host controller drivers, but of
> > course that can change.
>
> Ha!
>
> $ cat /proc/bus/usb/drivers
> usbfs
> hub
>
> There are no other drivers! I have a USB webcam and a modem
> ... has a user space driver that works via usbfs.
... OK, this is sounding familiar. "usbfs" has some recently noted
bugs in its disconnect() routine. That SpeedTouch driver seems to
be triggering them with regularity, though more often with usb-ohci.
The ksymoops info you sent is compatible with the bug being in
the usbfs code: exactly what I'd expect such a BUG() to show.
I hate to send around untested patches, but I think the one I've
attached is at least in the right direction. (Attachment, to avoid
mangling by mailers...) It's an update of what I sent around late
last month to address someone's SpeedTouch oopsing with
usb-ohci (!) on 2.4.19-pre2, redone against 2.5.8-pre3, which
compiles. I hope it doesn't create new oopses.
If it works for you, let us know ...
- Dave
On Wednesday 10 April 2002 7:23 pm, David Brownell wrote:
> > > And what usb device driver(s) were supposed to have stopped
> > > using "device 3"? I've only noticed such device refcounting bugs
> > > being caused by the USB device drivers with bad disconnect()
> > > routines, not usbcore or any of the host controller drivers, but of
> > > course that can change.
> >
> > Ha!
> >
> > $ cat /proc/bus/usb/drivers
> > usbfs
> > hub
> >
> > There are no other drivers! I have a USB webcam and a modem
> > ... has a user space driver that works via usbfs.
>
> ... OK, this is sounding familiar. "usbfs" has some recently noted
> bugs in its disconnect() routine. That SpeedTouch driver seems to
> be triggering them with regularity, though more often with usb-ohci.
>
> The ksymoops info you sent is compatible with the bug being in
> the usbfs code: exactly what I'd expect such a BUG() to show.
>
> I hate to send around untested patches, but I think the one I've
> attached is at least in the right direction. (Attachment, to avoid
> mangling by mailers...) It's an update of what I sent around late
> last month to address someone's SpeedTouch oopsing with
> usb-ohci (!) on 2.4.19-pre2, redone against 2.5.8-pre3, which
> compiles. I hope it doesn't create new oopses.
>
> If it works for you, let us know ...
>
> - Dave
It seems to work - thanks! I will test more, but so far so good.
System shutdown still completes with "preempt_count = 1"
though.
All the best,
Duncan.