USB2, mouse and X
Mattia Rossi
mrossi at swin.edu.au
Wed Mar 18 15:49:02 PDT 2009
Hans Petter Selasky wrote:
> On Wednesday 18 March 2009, Mattia Rossi wrote:
>
>> Hi,
>>
>> I've seen that there are a lot of issues with mice and the new USB2
>> stack, but as my problem is still not resolved with the current kernel,
>> i think it's time to report my problem:
>>
>> My mouse (or maybe keyboard?) issues regard only the X window system (I
>> tried fluxbox and KDE4). Mouse and keyboard are USB, attached via a USB
>> hub (integrated in my monitor). They both work without flaws in the
>> console, but it's a pain to write text in different windows in X. The
>> typed text just doesn't get displayed some times, unless the mouse
>> cursor is moved. Sometimes after typing some text, and moving the mouse
>> afterwards, the text gets written, but letters will be grouped together
>> and look like this:
>>
>>
>
> Hi,
>
> I think this might be an interrupt problem of the Host Controller or kernel in
> combination with your screen card. Is your screen card using the same
> interrupt like the USB controllers?
>
> What does "vmstat -i" output?
>
> Are any processes running high in "top" ?
>
> There are also some debugging sysctls:
>
> sysctl hw.usb2.ehci.debug=15
> sysctl hw.usb2.uhci.debug=15
>
> sysctl hw.usb2.ums.debug=15
> sysctl hw.usb2.ukbd.debug=15
>
> Warning: Can generate a lot of dmesg.
>
> When you don't see the text and press CTRL+ALT+F1 on the keyboard, do you get
> switched back to the console?
>
> Try to turn on "ums" and "ukbd" debugging first and see if the printouts to
> dmesg stop when you don't see anything in the X-window.
>
> --HPS
>
Okay here are the test results:
vmstat -i seems normal - an interrupt storm was my first doubt too:
vmstat -i
interrupt total rate
irq14: ata0 537721 8
irq15: ata1 490028 7
irq20: fxp0 uhci0* 160653 2
irq21: uhci1 uhci3 7924 0
irq22: ehci0 uhci4 1 0
cpu0: timer 123726882 1971
irq256: em0 10075932 160
irq257: hdac0 857 0
cpu1: timer 123717870 1971
irq258: vgapci0 109162 1
Total 258827030 4124
output of top:
last pid: 4696; load averages: 0.13, 0.10,
0.06
up 0+17:30:23 09:08:00
122 processes: 1 running, 119 sleeping, 2 zombie
CPU: 4.1% user, 0.0% nice, 2.6% system, 0.0% interrupt, 93.2% idle
Mem: 429M Active, 2263M Inact, 303M Wired, 39M Cache, 112M Buf, 462M Free
Swap: 4096M Total, 168K Used, 4096M Free
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU
COMMAND
1962 root 1 47 0 380M 362M select 0 43:15 5.08% Xorg
2045 mat 1 46 0 154M 35168K select 1 34:40 1.86%
kded4
2065 mat 4 76 0 261M 49400K ucond 1 12:01 0.00%
plasma
2092 mat 1 44 0 73160K 22656K select 1 1:36 0.00% kmix
2067 mat 1 44 0 54028K 20360K select 1 0:41 0.00%
nepomukservicestub
2085 mat 2 44 0 257M 39376K select 0 0:35 0.00%
krunner
2093 mat 1 44 0 232M 32884K select 1 0:35 0.00%
skype
2096 mat 3 45 0 114M 47376K select 1 0:21 0.00%
kopete
1384 root 1 44 0 3776K 1748K select 1 0:14 0.00%
hald-addon-storage
2064 mat 1 44 0 57532K 22976K select 1 0:09 0.00%
nepomukservicestub
4655 mat 13 44 0 106M 66832K ucond 1 0:08 0.00%
thunderbird-bin
1340 haldaemon 1 44 0 21560K 4976K select 1 0:07 0.00% hald
2098 mat 1 44 0 232M 32884K nanslp 0 0:05 0.00%
skype
2070 mat 1 44 0 3296K 1536K select 1 0:05 0.00%
ksysguardd
2037 mat 1 44 0 3472K 2300K select 0 0:05 0.00%
dbus-daemon
2142 mat 2 52 0 86088K 30136K select 0 0:04 0.00%
konsole
2097 mat 1 44 0 232M 32884K select 0 0:04 0.00%
skype
1842 root 1 44 0 3420K 1320K select 1 0:03 0.00%
moused
2057 mat 1 44 0 68136K 21496K select 1 0:03 0.00% kwin
2102 mat 1 44 0 67908K 19076K select 1 0:02 0.00%
klipper
1467 mat 1 44 0 150M 27368K ucond 1 0:02 0.00%
kded4
2061 mat 4 45 0 101M 31064K ucond 0 0:01 0.00%
knotify4
1259 root 1 44 0 6020K 3148K select 0 0:01 0.00%
sendmail
2056 mat 2 52 0 89068K 24576K select 1 0:00 0.00%
ksmserver
2043 mat 1 44 0 54224K 19872K select 1 0:00 0.00%
klauncher
1198 messagebus 1 44 0 3472K 2104K select 1 0:00 0.00%
dbus-daemon
2330 mat 1 44 0 3672K 1976K select 1 0:00 0.00%
screen
2069 mat 1 44 0 54144K 20116K select 0 0:00 0.00%
nepomukservicestub
2076 mat 1 44 0 65180K 17132K select 1 0:00 0.00%
kaccess
2068 mat 1 44 0 53984K 19708K select 1 0:00 0.00%
nepomukservicestub
Xorg puts always quite a high load on the system. The whole system is
also extremely slow and X can reach up to 30-40% CPU load..
That's why I tried to recompile X several times (about 10 times at least
in the last 2 weeks)..
This is a sample ums, ukbd enabled dmesg output. The ukbd part stopped
showing up until i moved the mouse cursor again. Its like the whole
system actually gets hold up. Actually waiting one or two seconds, lets
the text reappear sometimes too, which means that it switches also to
the console after a few seconds. But that doesn't work all the time.
This can be seen in the gap from 09:45:04 to 09:45:07. I continued
writing, waited a little bit, and the text showed up. At 09:45:08 i
moved the mouse.
Mar 19 09:45:04 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:04 mrossi kernel: ukbd_intr_callback:490: [0] =
19
Mar 19 09:45:04 mrossi kernel: ukbd_put_key:271: 0x13 (19)
pressed
Mar 19 09:45:04 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:04 mrossi kernel: ukbd_put_key:271: 0x413 (1043)
released
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
44
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x2c (44)
pressed
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x42c (1068)
released
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
4
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x04 (4)
pressed
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
4
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [1] =
22
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x16 (22)
pressed
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
22
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x404 (1028)
released
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
22
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [1] =
7
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x07 (7)
pressed
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
7
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x416 (1046)
released
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
9
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x407 (1031)
released
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x09 (9)
pressed
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
9
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [1] =
4
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x04 (4)
pressed
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
9
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [1] =
4
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [2] =
22
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x16 (22)
pressed
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
4
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [1] =
22
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x409 (1033)
released
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
4
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [1] =
22
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [2] =
9
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x09 (9)
pressed
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
22
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [1] =
9
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x404 (1028)
released
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:07 mrossi kernel: ukbd_intr_callback:490: [0] =
9
Mar 19 09:45:07 mrossi kernel: ukbd_put_key:271: 0x416 (1046)
released
Mar 19 09:45:08 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:08 mrossi kernel: ukbd_intr_callback:490: [0] =
9
Mar 19 09:45:08 mrossi kernel: ukbd_intr_callback:490: [1] =
7
Mar 19 09:45:08 mrossi kernel: ukbd_put_key:271: 0x07 (7)
pressed
Mar 19 09:45:08 mrossi kernel: ukbd_intr_callback:476: actlen=8
bytes
Mar 19 09:45:08 mrossi kernel: ukbd_put_key:271: 0x409 (1033)
released
Mar 19 09:45:08 mrossi kernel: ukbd_put_key:271: 0x407 (1031)
released
Mar 19 09:45:08 mrossi kernel: ums_intr_callback:181: sc=0xc6f56400
actlen=4
Mar 19 09:45:08 mrossi kernel: ums_intr_callback:198: data = 00 ff 00 00
00 00 00 00
Mar 19 09:45:08 mrossi kernel: ums_intr_callback:255: x:-1 y:0 z:0 t:0
w:0 buttons:0x00000000
Mar 19 09:45:08 mrossi kernel: ums_intr_callback:181: sc=0xc6f56400
actlen=4
Mar 19 09:45:08 mrossi kernel: ums_intr_callback:198: data = 00 ff 01 00
00 00 00 00
Mar 19 09:45:08 mrossi kernel: ums_intr_callback:255: x:-1 y:-1 z:0 t:0
w:0 buttons:0x00000000
Mar 19 09:45:08 mrossi kernel: ums_intr_callback:181: sc=0xc6f56400
actlen=4
Mar 19 09:45:08 mrossi kernel: ums_intr_callback:198: data = 00 fb 00 00
00 00 00 00
With the ehci, uhci debug enabled too I found one suspect part:
_ehci_append_qh:1032: 0xc79c7a00 to
0xc6f85700
ehci_check_transfer:1295: xfer=0xc6f578b8 checking
transfer
ehci_check_transfer:1400: xfer=0xc6f578b8 is still
active
uhci_interrupt:1453: uhci_interrupt: host controller
halted
uhci_dumpregs:691: usbus0 regs: cmd=0080, sts=0020, intr=000f,
frnum=00b6, flbase=01cd82d8, sof=0040, portsc1=0080, portsc2=0080
uhci_dump_qh:764: QH(0xc6ecea80) at 0x01acea82: h_next=0x01acea02
e_next=0x00000001
uhci_dump_qh:764: QH(0xc6ecea00) at 0x01acea02: h_next=0x01ace982
e_next=0x00000001
uhci_dump_qh:764: QH(0xc6ece980) at 0x01ace982: h_next=0x01ace902
e_next=0x00000001
uhci_dump_qh:764: QH(0xc6ece900) at 0x01ace902: h_next=0x00000001
e_next=0x01ace880
uhci_interrupt:1453: uhci_interrupt: host controller
halted
uhci_dumpregs:691: usbus3 regs: cmd=0080, sts=0020, intr=000f,
frnum=0750, flbase=01ce3d40, sof=0040, portsc1=0080, portsc2=0080
uhci_dump_qh:764: QH(0xc6f41d80) at 0x01b41d82: h_next=0x01b41d02
e_next=0x00000001
uhci_dump_qh:764: QH(0xc6f41d00) at 0x01b41d02: h_next=0x01b41c82
e_next=0x00000001
uhci_dump_qh:764: QH(0xc6f41c80) at 0x01b41c82: h_next=0x01b41c02
e_next=0x00000001
uhci_dump_qh:764: QH(0xc6f41c00) at 0x01b41c02: h_next=0x00000001
e_next=0x01b41b80
ehci_check_transfer:1295: xfer=0xc72924b8 checking
transfer
ehci_check_transfer:1400: xfer=0xc72924b8 is still
active
ehci_check_transfer:1295: xfer=0xc726c0b8 checking
transfer
ehci_check_transfer:1400: xfer=0xc726c0b8 is still
active
ehci_check_transfer:1295: xfer=0xc6f578b8 checking
transfer
ehci_non_isoc_done:1235: xfer=0xc6f578b8 pipe=0xc803b220 transfer
done
QTD(0xc840f280) at
0xad40f280:
next=0x00000001<T>
altnext=0x00000001<T>
status=0x80018d00: toggle=1 bytes=0x1 ioc=1
c_page=0x0
cerr=3 pid=1
stat=NOT_ACTIVE
buffer[0]=0x01b5796c
buffer[1]=0x01b57000
buffer[2]=0x00000000
buffer[3]=0x00000000
buffer[4]=0x00000000
buffer_hi[0]=0x00000000
buffer_hi[1]=0x00000000
buffer_hi[2]=0x00000000
buffer_hi[3]=0x00000000
buffer_hi[4]=0x00000000
dump aborted, too many TDs
Why does it halt the host controller?
uhci_interrupt:1453: uhci_interrupt: host controller halted
Then to the console switching part: It's not possible to switch to the
console until the text shows up again. As I said, it seems the system
gets blocked.
Mat
More information about the freebsd-current
mailing list