Date: Fri, 01 Feb 2008 22:00:11 +1030 From: Wayne Sierke <ws@au.dyndns.ws> To: stable@freebsd.org Subject: Re: Frequent USB mouse disconnections under load with RELENG_7 Message-ID: <1201865411.5350.12.camel@predator-ii.buffyverse> In-Reply-To: <1201188590.2075.4.camel@predator-ii.buffyverse> References: <1201188590.2075.4.camel@predator-ii.buffyverse>
next in thread | previous in thread | raw e-mail | index | archive | help
--=-iUk6jcsZDhtDUUBY2wdN
Content-Type: text/plain
Content-Transfer-Encoding: 7bit
On Fri, 2008-01-25 at 01:59 +1030, Wayne Sierke wrote:
> I'm getting a lot of USB mouse disconnects on RELENG_7. I wondered
> whether they might have been due to running with a KTR-enabled kernel
> but in just the last 7 hours I've been running on stock GENERIC and
> they're still happening.
>
> I get this set of messages for each disconnect:
> Jan 24 15:40:13 predator-ii kernel: ums0: at uhub0 port 2 (addr 2) disconnected
> Jan 24 15:40:13 predator-ii kernel: ums0: detached
> Jan 24 15:40:14 predator-ii root: Unknown USB device: vendor 0x046d product 0xc025 bus uhub0
> Jan 24 15:40:14 predator-ii kernel: ums0: <B16_b_02 USB-PS/2 Optical Mouse, class 0/0, rev 2.00/98.02, addr 2> on uhub0
> Jan 24 15:40:14 predator-ii kernel: ums0: 8 buttons and Z dir.
>
> Rarely, twice that I can recall over the course of a couple of weeks,
> the mouse fails to reconnect but comes good with a physical
> disconnect/reconnect.
>
> Here's a recent (condensed) history running with stock GENERIC:
>
> Jan 24 15:47:04 predator-ii kernel: ums0: at uhub0 port 2 (addr 2) disconnected
> Jan 24 16:15:53 predator-ii kernel: ums0: at uhub0 port 2 (addr 2) disconnected
> Jan 24 16:21:46 predator-ii kernel: ums0: at uhub0 port 2 (addr 2) disconnected
> Jan 24 16:25:42 predator-ii kernel: ums0: at uhub0 port 2 (addr 2) disconnected
> Jan 24 16:26:17 predator-ii kernel: ums0: at uhub0 port 2 (addr 2) disconnected
> Jan 24 16:37:01 predator-ii kernel: ums0: at uhub0 port 2 (addr 2) disconnected
> Jan 24 16:39:22 predator-ii kernel: ums0: at uhub0 port 2 (addr 2) disconnected
> Jan 24 16:56:28 predator-ii kernel: ums0: at uhub0 port 2 (addr 2) disconnected
> Jan 24 17:06:36 predator-ii kernel: ums0: at uhub0 port 2 (addr 2) disconnected
> Jan 24 19:20:58 predator-ii kernel: ums0: at uhub0 port 2 (addr 2) disconnected
> Jan 24 21:17:30 predator-ii kernel: ums0: at uhub0 port 2 (addr 2) disconnected
>
> Sometime during 16:00-17:00 I was running a couple of cpu-intensive
> tasks (glxgears plus for brief periods a cpu-intensive script). I wasn't
> at the computer much during the 17:30-21:00 interval. So it seems like
> this gets exacerbated by high cpu load. I counted another 12 in the hour
> following on from the above list.
>
> I don't recall seeing these at all under RELENG_6. If they ever did
> occur they certainly weren't anywhere nearly as prolific.
>
> A copy of /var/log/messages from boot until the first disconnection is
> attached. Any ideas?
Just a follow-up and bump as I recently realised that the listserver
rejected the attachment on the previous message because evolution set
its MIME type to text/x-log.
Some other information and observations that might help:
- the mouse is a wired Logitech MX-500
- it's more prevalent under high cpu load
- it happens when the computer is unattended, so it's not tied in with
active use of the mouse
- I've also just noticed that I'm getting these messages on startup
under 7.x:
kernel: Starting devd.
kernel: Starting ums0 moused:
kernel: Starting default moused:
moused: unable to open /dev/ums0: Device busy
but I can't now recall whether I was seeing those under 6.x. Has devd
changed with 7.x? I've got a feeling that I'd tried to get devd in 6.x
to handle the USB mouse on startup, but that I'd found it necessary to
configure moused explicitly (i.e. with moused_port) in rc.conf as listed
below. However my memory of it now is hazy at best. In any case,
disconnections aside, I've not noticed any change in mouse behaviour
since moving to 7.x either in console or xorg.
moused_enable="YES"
moused_port="/dev/ums0"
I'm getting quite anxious for some pointers to resolving this as it's
both highly annoying and is also frustrating my efforts in pursuing some
of the other performance problems I've written about.
Wayne
--=-iUk6jcsZDhtDUUBY2wdN
Content-Disposition: attachment; filename=messages-boot-20080201_1
Content-Type: text/plain; name=messages-boot-20080201_1; charset=ASCII
Content-Transfer-Encoding: 7bit
kernel boot file is /boot/kernelktr0x2000/kernel
Copyright (c) 1992-2008 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 7.0-PRERELEASE #1: Fri Jan 25 01:08:47 CST 2008
root@freebsd7stable-1.vmware:/usr/obj/usr/src/sys/GENERIC-KTR-0x2000
Timecounter "i8254" frequency 1193182 Hz quality 0
CPU: Intel(R) Pentium(R) 4 CPU 2.40GHz (2411.61-MHz 686-class CPU)
Origin = "GenuineIntel" Id = 0xf27 Stepping = 7
Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
Features2=0x4400<CNXT-ID,xTPR>
real memory = 1610547200 (1535 MB)
avail memory = 1551495168 (1479 MB)
ACPI APIC Table: <GBT AWRDACPI>
ioapic0: Changing APIC ID to 2
ioapic0 <Version 1.4> irqs 0-23 on motherboard
kbd1 at kbdmux0
ath_hal: 0.9.20.3 (AR5210, AR5211, AR5212, RF5111, RF5112, RF2413, RF5413)
hptrr: HPT RocketRAID controller driver v1.1 (Jan 25 2008 01:08:23)
acpi0: <GBT AWRDACPI> on motherboard
acpi0: [ITHREAD]
acpi0: Power Button (fixed)
Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x1008-0x100b on acpi0
cpu0: <ACPI CPU> on acpi0
p4tcc0: <CPU Frequency Thermal Control> on cpu0
acpi_button0: <Power Button> on acpi0
acpi_button1: <Sleep Button> on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff,0x480-0x48f,0x1000-0x107f,0x1080-0x10ff,0x1400-0x147f on acpi0
pci0: <ACPI PCI bus> on pcib0
pcib1: <PCI-PCI bridge> at device 1.0 on pci0
pci1: <PCI bus> on pcib1
nvidia0: <GeForce4 MX 440> mem 0xf8000000-0xf8ffffff,0xe8000000-0xefffffff,0xf0000000-0xf007ffff irq 16 at device 0.0 on pci1
nvidia0: [GIANT-LOCKED]
nvidia0: [ITHREAD]
isab0: <PCI-ISA bridge> at device 2.0 on pci0
isa0: <ISA bus> on isab0
fwohci0: <SiS 7007> mem 0xfb000000-0xfb000fff irq 17 at device 2.3 on pci0
fwohci0: [FILTER]
fwohci0: OHCI version 1.0 (ROM=1)
fwohci0: No. of Isochronous channels is 4.
fwohci0: EUI64 00:00:20:ed:00:75:43:34
fwohci0: Phy 1394a available S400, 3 ports.
fwohci0: Link S400, max_rec 2048 bytes.
firewire0: <IEEE1394(FireWire) bus> on fwohci0
fwe0: <Ethernet over FireWire> on firewire0
if_fwe0: Fake Ethernet address: 02:00:20:75:43:34
fwe0: Ethernet address: 02:00:20:75:43:34
fwip0: <IP over FireWire> on firewire0
fwip0: Firewire address: 00:00:20:ed:00:75:43:34 @ 0xfffe00000000, S400, maxrec 2048
sbp0: <SBP-2/SCSI over FireWire> on firewire0
dcons_crom0: <dcons configuration ROM> on firewire0
dcons_crom0: bus_addr 0x211c000
fwohci0: Initiate bus reset
fwohci0: BUS reset
fwohci0: node_id=0xc000ffc0, gen=1, CYCLEMASTER mode
atapci0: <SiS 962/963 UDMA133 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xf000-0xf00f at device 2.5 on pci0
ata0: <ATA channel 0> on atapci0
ata0: [ITHREAD]
ata1: <ATA channel 1> on atapci0
ata1: [ITHREAD]
pcm0: <SiS 7012> port 0xe000-0xe0ff,0xe400-0xe47f irq 18 at device 2.7 on pci0
pcm0: [ITHREAD]
pcm0: <Avance Logic ALC650 AC97 Codec>
ohci0: <SiS 5571 USB controller> mem 0xfb001000-0xfb001fff irq 20 at device 3.0 on pci0
ohci0: [GIANT-LOCKED]
ohci0: [ITHREAD]
usb0: OHCI version 1.0, legacy support
usb0: <SiS 5571 USB controller> on ohci0
usb0: USB revision 1.0
uhub0: <SiS OHCI root hub, class 9/0, rev 1.00/1.00, addr 1> on usb0
uhub0: 2 ports with 2 removable, self powered
ohci1: <SiS 5571 USB controller> mem 0xfb002000-0xfb002fff irq 21 at device 3.1 on pci0
ohci1: [GIANT-LOCKED]
ohci1: [ITHREAD]
usb1: OHCI version 1.0, legacy support
usb1: <SiS 5571 USB controller> on ohci1
usb1: USB revision 1.0
uhub1: <SiS OHCI root hub, class 9/0, rev 1.00/1.00, addr 1> on usb1
uhub1: 2 ports with 2 removable, self powered
ohci2: <SiS 5571 USB controller> mem 0xfb003000-0xfb003fff irq 22 at device 3.2 on pci0
ohci2: [GIANT-LOCKED]
ohci2: [ITHREAD]
usb2: OHCI version 1.0, legacy support
usb2: <SiS 5571 USB controller> on ohci2
usb2: USB revision 1.0
uhub2: <SiS OHCI root hub, class 9/0, rev 1.00/1.00, addr 1> on usb2
uhub2: 2 ports with 2 removable, self powered
ehci0: <EHCI (generic) USB 2.0 controller> mem 0xfb004000-0xfb004fff irq 23 at device 3.3 on pci0
ehci0: [GIANT-LOCKED]
ehci0: [ITHREAD]
usb3: EHCI version 1.0
usb3: companion controllers, 2 ports each: usb0 usb1 usb2
usb3: <EHCI (generic) USB 2.0 controller> on ehci0
usb3: USB revision 2.0
uhub3: <SiS EHCI root hub, class 9/0, rev 2.00/1.00, addr 1> on usb3
uhub3: 6 ports with 6 removable, self powered
ahc0: <Adaptec 2940 SCSI adapter> port 0xe800-0xe8ff mem 0xfb005000-0xfb005fff irq 18 at device 10.0 on pci0
ahc0: [ITHREAD]
aic7870: Single Channel A, SCSI Id=7, 16/253 SCBs
rl0: <D-Link DFE-530TX+ 10/100BaseTX> port 0xec00-0xecff mem 0xfb006000-0xfb0060ff irq 19 at device 11.0 on pci0
miibus0: <MII bus> on rl0
rlphy0: <RealTek internal media interface> PHY 0 on miibus0
rlphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
rl0: Ethernet address: 00:40:05:10:b9:79
rl0: [ITHREAD]
fdc0: <floppy drive controller> port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0
fdc0: [FILTER]
fd0: <1440-KB 3.5" drive> on fdc0 drive 0
sio0: <16550A-compatible COM port> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
sio0: type 16550A
sio0: [FILTER]
sio1: <16550A-compatible COM port> port 0x2f8-0x2ff irq 3 on acpi0
sio1: type 16550A
sio1: [FILTER]
atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
atkbd0: [ITHREAD]
pmtimer0 on isa0
orm0: <ISA Option ROM> at iomem 0xd0000-0xd07ff pnpid ORM0000 on isa0
ppc0: <Parallel port> at port 0x378-0x37f irq 7 on isa0
ppc0: Generic chipset (ECP/PS2/NIBBLE) in COMPATIBLE mode
ppc0: FIFO with 16/16/16 bytes threshold
ppbus0: <Parallel port bus> on ppc0
ppbus0: [ITHREAD]
plip0: <PLIP network interface> on ppbus0
lpt0: <Printer> on ppbus0
lpt0: Interrupt-driven port
ppi0: <Parallel I/O> on ppbus0
ppc0: [GIANT-LOCKED]
ppc0: [ITHREAD]
sc0: <System console> at flags 0x100 on isa0
sc0: VGA <16 virtual consoles, flags=0x300>
vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
ums0: <B16_b_02 USB-PS/2 Optical Mouse, class 0/0, rev 2.00/98.02, addr 2> on uhub0
ums0: 8 buttons and Z dir.
Timecounter "TSC" frequency 2411605152 Hz quality 800
Timecounters tick every 1.000 msec
hptrr: no controller detected.
Waiting 5 seconds for SCSI devices to settle
firewire0: 1 nodes, maxhop <= 0, cable IRM = 0 (me)
firewire0: bus manager 0 (me)
ad0: 76319MB <Seagate ST380024A 3.33> at ata0-master UDMA100
ad1: 76319MB <Seagate ST380011A 8.01> at ata0-slave UDMA100
acd0: DVDR <PIONEER DVD-RW DVR-111D/1.29> at ata1-master UDMA33
GEOM_LABEL: Label for provider ad0s1 is msdosfs/POOH.
GEOM_LABEL: Label for provider ad1s1 is msdosfs/DOSBOOT.
GEOM_LABEL: Label for provider ad0s5 is ntfs/Win2kPro.
GEOM_LABEL: Label for provider ad0s6 is msdosfs/RECOVERED8G.
GEOM_LABEL: Label for provider ad0s7 is msdosfs/ .
Trying to mount root from ufs:/dev/ad1s3a
no dumps found
lpd startup: logging=0
ntpd 4.2.0-a Mon Jan 14 16:50:12 CST 2008 (1)
/etc/rc: WARNING: $dbus_enable is not set properly - see rc.conf(5).
/etc/rc: WARNING: $dbus_enable is not set properly - see rc.conf(5).
/etc/rc: WARNING: $polkitd_enable is not set properly - see rc.conf(5).
WARNING: No NSS support for mDNS detected, consider installing nss-mdns!
time reset -0.465924 s
kernel time sync disabled 2041
kernel time sync enabled 2001
ums0: at uhub0 port 2 (addr 2) disconnected
ums0: detached
Unknown USB device: vendor 0x046d product 0xc025 bus uhub0
ums0: <B16_b_02 USB-PS/2 Optical Mouse, class 0/0, rev 2.00/98.02, addr 2> on uhub0
ums0: 8 buttons and Z dir.
--=-iUk6jcsZDhtDUUBY2wdN--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?1201865411.5350.12.camel>