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. MatReceived on Wed Mar 18 2009 - 21:49:02 UTC
This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:39:44 UTC