Re: 9.1: no wsmouse events...sometimes.

To: tech-kern%netbsd.org@localhost
Subject: Re: 9.1: no wsmouse events...sometimes.
From: Mouse <mouse%Rodents-Montreal.ORG@localhost>
Date: Tue, 9 Mar 2021 10:30:03 -0500 (EST)
Back on 2021-02-23, I wrote of issues getting mouse events via wsmux on
a turnkey product built on 9.1/amd64.

Besides Brian Buhrow's helpful remarks on the list, one person sent
mail off-list quoting my

> The only thing I can think of is the time delay between the X server
> starting and the application opening /dev/wsmux2.

and suggesting introducing a sleep, something so obvious I feel stupid
for not thinking of it myself.  I've also got some other observations
which look relevant to me.

I introduced two sleeps, each ten seconds long: one after the
application starts before forking the X server, the other after the X
server is accepting connections but before doing other things, in
particular before opening /dev/wsmux2.

This did not help directly.  But I did notice, during the second sleep,
that the mouse was responsive in X.  This says, to me, that something
is wrong with the wsmouse or wsmux code, because (I captured dmesg
again) the mouse attached "mux 2" but the X server saw mouse events
anyway.  Also, under a full install, the "working" state, the mouse is
not responsive in X at the analogous time.

I also compared the captured dmesg against dmesg from a "normal"
multi-user boot (under which the mouse works as it's supposed to: the X
server gets nothing and the application gets events), and see some
possibly relevant differences.

On the multi-user boot, dmesg says things attach in this order:

[...]
[     1.047065] xhci0 at pci0 dev 20 function 0: vendor 8086 product a12f (rev. 0x31)
[     1.047065] xhci0: interrupting at msi0 vec 0
[     1.047065] xhci0: xHCI version 1.0
[     1.047065] usb0 at xhci0: USB revision 3.0
[     1.047065] usb1 at xhci0: USB revision 2.0
[     1.047065] vendor 8086 product a131 (miscellaneous DASP, revision 0x31) at pci0 dev 20 function 2 not configured
[     1.047065] vendor 8086 product a13a (miscellaneous communications, revision 0x31) at pci0 dev 22 function 0 not configured
[     1.047065] ahcisata0 at pci0 dev 23 function 0: vendor 8086 product a102 (rev. 0x31)
[     1.047065] ahcisata0: 64-bit DMA
[     1.047065] ahcisata0: AHCI revision 1.31, 4 ports, 32 slots, CAP 0xe734ff43<EMS,PSC,SSC,PMD,SAM,ISS=0x3=Gen3,SCLO,SAL,SALP,SSNTF,SNCQ,S64A>
[     1.047065] ahcisata0: interrupting at msi1 vec 0
[     1.047065] atabus0 at ahcisata0 channel 0
[     1.047065] atabus1 at ahcisata0 channel 1
[     1.047065] atabus2 at ahcisata0 channel 2
[     1.047065] atabus3 at ahcisata0 channel 3
[...assorted other stuff...]
[     1.252958] cpu1: CPU base freq 3400000000 Hz
[     1.252958] cpu1: CPU max freq 3400000000 Hz
[     1.252958] cpu1: TSC freq CPUID 3408000000 Hz
[     1.254197] cpu2: CPU base freq 3400000000 Hz
[     1.254197] cpu2: CPU max freq 3400000000 Hz
[     1.254197] cpu2: TSC freq CPUID 3408000000 Hz
[     1.255335] cpu3: CPU base freq 3400000000 Hz
[     1.255335] cpu3: CPU max freq 3400000000 Hz
[     1.255335] cpu3: TSC freq CPUID 3408000000 Hz
[     1.255335] timecounter: Timecounter "TSC" frequency 3408000000 Hz quality 3000
[     1.255681] uhub0 at usb0: NetBSD (0000) xHCI root hub (0000), class 9/0, rev 3.00/1.00, addr 0
[     1.255681] uhub0: 10 ports with 10 removable, self powered
[     1.255681] uhub1 at usb1: NetBSD (0000) xHCI root hub (0000), class 9/0, rev 2.00/1.00, addr 0
[     1.255681] uhub1: 16 ports with 16 removable, self powered
[     1.259317] IPsec: Initialized Security Association Processing.
[     1.355317] ahcisata0 port 1: device present, speed: 6.0Gb/s
[     2.355317] ahcisata0 port 0: PHY offline
[     2.355317] ahcisata0 port 3: PHY offline
[     2.355317] ahcisata0 port 2: PHY offline
[     2.895317] wd0 at atabus1 drive 0
[     2.895317] wd0: <WDC WD20EFRX-68EUZN0>
[     2.895317] wd0: drive supports 16-sector PIO transfers, LBA48 addressing
[     2.895317] wd0: 1863 GB, 3876021 cyl, 16 head, 63 sec, 512 bytes/sect x 3907029168 sectors (0 bytes/physsect; first aligned sector: 8)
[     2.937317] wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133), NCQ (32 tags) w/PRIO
[     2.937317] wd0(ahcisata0:1:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133) (using DMA), NCQ (31 tags) w/PRIO
[     3.007317] uhub1: autoconfiguration error: port 1 reset failed
[     3.871317] uhidev0 at uhub1 port 2 configuration 1 interface 0
[     3.871317] uhidev0: Gaming KB (0x258a) Gaming KB (0x1006), rev 1.10/1.05, addr 1, iclass 3/1
[     3.873317] ukbd0 at uhidev0
[     4.273317] wskbd0 at ukbd0: console keyboard
[     4.273317] uhidev1 at uhub1 port 2 configuration 1 interface 1
[     4.273317] uhidev1: Gaming KB (0x258a) Gaming KB (0x1006), rev 1.10/1.05, addr 1, iclass 3/1
[     4.275317] uhidev1: 8 report ids
[     4.275317] uhid0 at uhidev1 reportid 1: input=1, output=0, feature=0
[     4.276317] uhid1 at uhidev1 reportid 2: input=2, output=0, feature=0
[     4.276317] uhid2 at uhidev1 reportid 5: input=0, output=0, feature=5
[     4.276317] ukbd1 at uhidev1 reportid 6
[     4.276317] ukbd1: autoconfiguration error: attach failed, key code size != 8
[     4.276317] ukbd2 at uhidev1 reportid 7
[     4.676317] wskbd1 at ukbd2 mux 1
[     4.676317] ukbd3 at uhidev1 reportid 8
[     5.076317] wskbd2 at ukbd3 mux 1
[     5.943317] uhidev2 at uhub1 port 1 configuration 1 interface 0
[     5.943317] uhidev2: vendor 0000 (0000) USB OPTICAL MOUSE (0x538), rev 1.10/1.00, addr 2, iclass 3/1
[     5.945317] uhidev2: 1 report ids
[     5.945317] ums0 at uhidev2 reportid 1: 3 buttons and Z dir
[     5.945317] wsmouse0 at ums0 mux 2

In contrast, captured dmesg indicates that the standalone run looks
more like

[...]
[   1.0463033] xhci0 at pci0 dev 20 function 0: vendor 8086 product a12f (rev. 0x31)
[   1.0463033] xhci0: interrupting at msi0 vec 0
[   1.0463033] xhci0: xHCI version 1.0
[   1.0463033] usb0 at xhci0: USB revision 3.0
[   1.0463033] usb1 at xhci0: USB revision 2.0
[   1.0463033] vendor 8086 product a131 (miscellaneous DASP, revision 0x31) at pci0 dev 20 function 2 not configured
[   1.0463033] vendor 8086 product a13a (miscellaneous communications, revision 0x31) at pci0 dev 22 function 0 not configured
[   1.0463033] ahcisata0 at pci0 dev 23 function 0: vendor 8086 product a102 (rev. 0x31)
[   1.0463033] ahcisata0: 64-bit DMA
[   1.0463033] ahcisata0: AHCI revision 1.31, 4 ports, 32 slots, CAP 0xe734ff43<EMS,PSC,SSC,PMD,SAM,ISS=0x3=Gen3,SCLO,SAL,SALP,SSNTF,SNCQ,S64A>
[   1.0463033] ahcisata0: interrupting at msi1 vec 0
[   1.0463033] atabus0 at ahcisata0 channel 0
[   1.0463033] atabus1 at ahcisata0 channel 1
[   1.0463033] atabus2 at ahcisata0 channel 2
[   1.0463033] atabus3 at ahcisata0 channel 3
[...assorted other stuff...]
[   1.9852502] cpu1: CPU base freq 3400000000 Hz
[   1.9852502] cpu1: CPU max freq 3400000000 Hz
[   1.9852502] cpu1: TSC freq CPUID 3408000000 Hz
[   1.9865047] cpu2: CPU base freq 3400000000 Hz
[   1.9865047] cpu2: CPU max freq 3400000000 Hz
[   1.9865047] cpu2: TSC freq CPUID 3408000000 Hz
[   1.9876169] cpu3: CPU base freq 3400000000 Hz
[   1.9876169] cpu3: CPU max freq 3400000000 Hz
[   1.9876169] cpu3: TSC freq CPUID 3408000000 Hz
[   1.9876169] timecounter: Timecounter "TSC" frequency 3408000000 Hz quality 3000
[   1.9879771] uhub0 at usb0: NetBSD (0000) xHCI root hub (0000), class 9/0, rev 3.00/1.00, addr 0
[   1.9879771] uhub0: 10 ports with 10 removable, self powered
[   1.9879771] uhub1 at usb1: NetBSD (0000) xHCI root hub (0000), class 9/0, rev 2.00/1.00, addr 0
[   1.9879771] uhub1: 16 ports with 16 removable, self powered
<3>[   1.9879771] rn_init: radix functions require max_keylen be set
[   1.9886124] WARNING: module error: built-in module spkr can't find builtin dependency `audio'
[   1.9886124] WARNING: module error: built-in module spkr prerequisite audio failed, error 2
[   2.0876117] ahcisata0 port 1: device present, speed: 3.0Gb/s
[   3.0876117] ahcisata0 port 0: PHY offline
[   3.0876117] ahcisata0 port 2: PHY offline
[   3.0876117] ahcisata0 port 3: PHY offline
[   3.5546117] uhidev0 at uhub1 port 1 configuration 1 interface 0
[   3.5546117] uhidev0: vendor 0000 (0000) USB OPTICAL MOUSE (0x538), rev 1.10/1.00, addr 1, iclass 3/1
[   3.5566117] uhidev0: 1 report ids
[   3.5566117] ums0 at uhidev0 reportid 1: 3 buttons and Z dir
[   3.5566117] wsmouse0 at ums0 mux 2
[   3.6276117] wd0 at atabus1 drive 0
[   3.6286117] wd0: <WDC WD1600BEVT-00A23T0>
[   3.6286117] wd0: drive supports 16-sector PIO transfers, LBA48 addressing
[   3.6286117] wd0: 149 GB, 310101 cyl, 16 head, 63 sec, 512 bytes/sect x 312581808 sectors
[   3.6986117] wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133), WRITE DMA FUA, NCQ (32 tags) w/PRIO
[   3.6986117] wd0(ahcisata0:1:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133) (using DMA), NCQ (31 tags) w/PRIO
[   4.4216117] uhidev1 at uhub1 port 2 configuration 1 interface 0
[   4.4216117] uhidev1: Gaming KB (0x258a) Gaming KB (0x1006), rev 1.10/1.05, addr 2, iclass 3/1
[   4.4226117] ukbd0 at uhidev1
[   4.8226117] wskbd0 at ukbd0: console keyboard
[   4.8226117] uhidev2 at uhub1 port 2 configuration 1 interface 1
[   4.8226117] uhidev2: Gaming KB (0x258a) Gaming KB (0x1006), rev 1.10/1.05, addr 2, iclass 3/1
[   4.8256117] uhidev2: 8 report ids
[   4.8256117] uhid0 at uhidev2 reportid 1: input=1, output=0, feature=0
[   4.8256117] uhid1 at uhidev2 reportid 2: input=2, output=0, feature=0
[   4.8256117] uhid2 at uhidev2 reportid 5: input=0, output=0, feature=5
[   4.8256117] ukbd1 at uhidev2 reportid 6
[   4.8256117] ukbd1: autoconfiguration error: attach failed, key code size != 8
[   4.8256117] ukbd2 at uhidev2 reportid 7
[   5.2256117] wskbd1 at ukbd2 mux 1
[   5.2256117] ukbd3 at uhidev2 reportid 8
[   5.6266117] wskbd2 at ukbd3 mux 1

(I conjecture the rn_init message appears because that kernel is
configured with neither INET nor INET6.)

In particular, I note that the "broken" boot attaches "wsmouse0 at
wsmux0 mux 2" before any other "ws* at ... mux ..." devices, whereas
the "working" boot attaches wskbd0 mux 1 before wsmouse0 mux 2.  Upon
unplugging and replugging the mouse, of course, we have a mux 2
attachment happening after the wskbd attachment.

I'm going to be experimenting to see if I can change this or find an
explanation for how it might affect things.  (Of course, all of the
above, except the unplug/replug, happens before either the X server
start or the /dev/wsmux2 open, in their respective runs.)

/~\ The ASCII				  Mouse
\ / Ribbon Campaign
 X  Against HTML		mouse%rodents-montreal.org@localhost
/ \ Email!	     7D C8 61 52 5D E7 2D 39  4E F1 31 3E E8 B3 27 4B
Follow-Ups:
- Re: 9.1: no wsmouse events...sometimes.
  - From: Mouse
References:
- 9.1: no wsmouse events...sometimes.
  - From: Mouse
Prev by Date: Re: GSOC ZFS root support (bootloader and mount_root)
Next by Date: Re: 9.1: no wsmouse events...sometimes.
Previous by Thread: Re: 9.1: no wsmouse events...sometimes.
Next by Thread: Re: 9.1: no wsmouse events...sometimes.
Indexes:
Home | Main Index | Thread Index | Old Index