Wayne Sierke
2008-Jan-24 07:30 UTC
Frequent USB mouse disconnections under load with RELENG_7
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? Wayne
Wayne Sierke
2008-Feb-01 03:30 UTC
Frequent USB mouse disconnections under load with RELENG_7
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 -------------- next part -------------- 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.