Bug 219220 - syscalls (ioctls) on USB devices are very slow
Summary: syscalls (ioctls) on USB devices are very slow
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: usb (show other bugs)
Version: CURRENT
Hardware: amd64 Any
: --- Affects Only Me
Assignee: freebsd-usb mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-05-11 11:35 UTC by Matthias Apitz
Modified: 2017-05-19 10:24 UTC (History)
2 users (show)

See Also:


Attachments
output of kdump -T (90.93 KB, text/plain)
2017-05-11 11:40 UTC, Matthias Apitz
no flags Details
output of: procstat -ak (33.86 KB, text/plain)
2017-05-11 11:47 UTC, Matthias Apitz
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Matthias Apitz 2017-05-11 11:35:18 UTC
I installed the port devel/pcsc-litepcsc-lite:

# pkg inf pcsc-lite
pcsc-lite-1.8.20,2
Name           : pcsc-lite
Version        : 1.8.20,2
Installed on   : Thu May 11 08:28:06 2017 CEST
Origin         : devel/pcsc-lite
Architecture   : freebsd:12:x86:64
...

and enabled the start of the 'pcscd' with

pcscd_enable="YES"

in /etc/rc.conf, but this would make hang the system on startup/boot:

> 25038  1  S+     0:00,02 /bin/sh /usr/local/etc/rc.d/pcscd start
> 25043  1  S+     0:00,01 /usr/local/sbin/pcscd
> 25044  1  S+     0:00,01 /usr/local/sbin/pcscd
> 


interestingly to note: I have the exact same system (12-CURRENT r314251 and with same ports
from my own pkg repository out of poudriere) in a VBOX machine; when I start there the pcscd
in foreground and with --debug it says:


root@r314251-amd64:~ # /usr/local/sbin/pcscd --debug --foreground
00000000 pcscdaemon.c:346:main() pcscd set to foreground with debug send to stdout
00000516 configfile.l:358:DBGetReaderList() Parsing conf file: /usr/local/etc/reader.conf.d
00000043 pcscdaemon.c:655:main() pcsc-lite 1.8.20 daemon ready.
00010018 hotplug_libusb.c:440:HPEstablishUSBNotifications() Driver ifd-ccid.bundle does not support IFD_GENERATE_HOTPLUG. Using active polling instead.
00000124 hotplug_libusb.c:449:HPEstablishUSBNotifications() Polling forced every 1 second(s)

and a truss on the PID shows that is is really polling once every second:

...
openat(AT_FDCWD,"/dev/ugen1.1",O_RDWR,00)	 = 7 (0x7)
openat(AT_FDCWD,"/dev/ugen1.1",O_RDWR,00)	 = 8 (0x8)
ioctl(8,USB_GET_PLUGTIME,0xdfdfcddc)		 = 0 (0x0)
ioctl(7,USB_GET_CONFIG,0xdfdfce44)		 = 0 (0x0)
close(8)					 = 0 (0x0)
close(7)					 = 0 (0x0)
openat(AT_FDCWD,"/dev/ugen1.1",O_RDWR,00)	 = 7 (0x7)
openat(AT_FDCWD,"/dev/ugen1.1",O_RDWR,00)	 = 8 (0x8)
...

On the system in question, an Acer C720 netbook, it says only:

root@c720-r314251:~ # /usr/local/sbin/pcscd --debug --foreground
00000000 pcscdaemon.c:346:main() pcscd set to foreground with debug send to stdout
00000550 configfile.l:358:DBGetReaderList() Parsing conf file: /usr/local/etc/reader.conf.d
00000049 pcscdaemon.c:655:main() pcsc-lite 1.8.20 daemon ready.

i.e. the line about hotplug_libusb.c:440:HPEstablishUSBNotifications()
does not show up; and a truss shows that is is doing/waiting on
something on a dev; it is very slow doing some ioctls:

openat(AT_FDCWD,"/dev/usbctl",O_RDONLY,00)	 = 11 (0xb)
ioctl(11,USB_READ_DIR,0xdfdfcb38)		 = 0 (0x0)
openat(AT_FDCWD,"/dev/ugen1.1",O_RDWR,00)	 = 12 (0xc)
ioctl(12,USB_GET_PLUGTIME,0xdfdfcb1c)		 = 0 (0x0)
ioctl(12,USB_GET_DEVICE_DESC,0xdfdfcb20)	 = 0 (0x0)
ioctl(12,USB_GET_DEVICEINFO,0xdfdfccb0)		 = 0 (0x0)

I will attach a ktrace/kdump output which shows that the problem is caused by *very*
slow sys calls on the USB bus.
Comment 1 Matthias Apitz 2017-05-11 11:40:18 UTC
Created attachment 182509 [details]
output of kdump -T
Comment 2 Hans Petter Selasky freebsd_committer 2017-05-11 11:41:05 UTC
The IOCTLs might be slow if another device is failing enumeration. Please check dmesg.

The output from "procstat -ak" might also be useful.

--HPS
Comment 3 Hans Petter Selasky freebsd_committer 2017-05-11 11:41:47 UTC
Also check if any processes are consuming 100% CPU.
Comment 4 Matthias Apitz 2017-05-11 11:47:50 UTC
Created attachment 182510 [details]
output of: procstat -ak

CPU is nearly idle (~95%) and no other proc is using USB
Comment 5 Matthias Apitz 2017-05-11 11:50:22 UTC
dmesg shows only attach and deattach of the mouse (which I inserted just to see if this would kick the pcscd proc forward):

ugen0.4: <Logitech USB Optical Mouse> at usbus0
ums0 on uhub1
ums0: <Logitech USB Optical Mouse, class 0/0, rev 2.00/63.00, addr 3> on usbus0
ums0: 3 buttons and [XYZ] coordinates ID=0
ugen0.4: <Logitech USB Optical Mouse> at usbus0 (disconnected)
ums0: at uhub1, port 5, addr 3 (disconnected)
ums0: detached
ugen0.4: <Logitech USB Optical Mouse> at usbus0
ums0 on uhub1
ums0: <Logitech USB Optical Mouse, class 0/0, rev 2.00/63.00, addr 4> on usbus0
ums0: 3 buttons and [XYZ] coordinates ID=0
ugen0.4: <Logitech USB Optical Mouse> at usbus0 (disconnected)
ums0: at uhub1, port 5, addr 4 (disconnected)
ums0: detached

nothing else after the boot messages;
Comment 6 Hans Petter Selasky freebsd_committer 2017-05-11 11:54:09 UTC
Are there any USB-errors in dmesg?

If you run "usbdump -i usbusX" on the bus where the device is connected, do you see any timeouts?

--HPS
Comment 7 Matthias Apitz 2017-05-11 12:14:21 UTC
root@c720-r314251:~ # usbdump -i usbus1
14:13:00.912954 usbus1.2 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=0,SLEN=0,IVAL=0,ERR=TIMEOUT
14:13:00.979775 usbus1.2 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
14:13:05.875133 usbus1.2 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=0,SLEN=0,IVAL=0,ERR=TIMEOUT
14:13:05.938475 usbus1.2 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
14:13:10.840123 usbus1.2 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=0,SLEN=0,IVAL=0,ERR=TIMEOUT
14:13:10.903602 usbus1.2 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
^C
6 packets captured
6 packets received by filter
0 packets dropped by kernel

root@c720-r314251:~ # usbdump -i usbus0

(hangs for ever)
Comment 8 Hans Petter Selasky freebsd_committer 2017-05-11 12:16:49 UTC
The USB log shows that the device has a timeout on one of the USB commands. That's the reason it is slow!

Wild guess: Try to set: UQ_NO_STRINGS using:

usbconfig -d X.Y add_quirk UQ_NO_STRINGS

--HPS
Comment 9 Matthias Apitz 2017-05-11 12:31:27 UTC
$ dmesg | grep usb
usbus0 on xhci0
usbus0: 5.0Gbps Super Speed USB v3.0
usbus1: EHCI version 1.0
usbus1 on ehci0
usbus1: 480Mbps High Speed USB v2.0
ugen1.1: <Intel EHCI root HUB> at usbus1
ugen0.1: <0x8086 XHCI root HUB> at usbus0
uhub0: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus1
uhub1: <0x8086 XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus0
ugen0.2: <SunplusIT Inc HD WebCam> at usbus0
ugen1.2: <vendor 0x8087 product 0x8000> at usbus1
uhub2: <vendor 0x8087 product 0x8000, class 9/0, rev 2.00/0.04, addr 2> on usbus1
ugen0.3: <vendor 0x0489 product 0xe056> at usbus0
ugen0.4: <Logitech USB Optical Mouse> at usbus0
ums0: <Logitech USB Optical Mouse, class 0/0, rev 2.00/63.00, addr 3> on usbus0
ugen0.4: <Logitech USB Optical Mouse> at usbus0 (disconnected)
ugen0.4: <Logitech USB Optical Mouse> at usbus0
ums0: <Logitech USB Optical Mouse, class 0/0, rev 2.00/63.00, addr 4> on usbus0
ugen0.4: <Logitech USB Optical Mouse> at usbus0 (disconnected)
Comment 10 Matthias Apitz 2017-05-11 12:32:10 UTC
they hang all:

root@c720-r314251:~ # ls -l /dev/ug*
lrwxr-xr-x  1 root  wheel  9 11 may.  06:57 /dev/ugen0.1 -> usb/0.1.0
lrwxr-xr-x  1 root  wheel  9 11 may.  06:57 /dev/ugen0.2 -> usb/0.2.0
lrwxr-xr-x  1 root  wheel  9 11 may.  06:57 /dev/ugen0.3 -> usb/0.3.0
lrwxr-xr-x  1 root  wheel  9 11 may.  06:57 /dev/ugen1.1 -> usb/1.1.0
lrwxr-xr-x  1 root  wheel  9 11 may.  06:57 /dev/ugen1.2 -> usb/1.2.0
root@c720-r314251:~ # usbconfig -d 0.1 add_quirk UQ_NO_STRINGS
^C^C^C
root@c720-r314251:~ # usbconfig -d 0.2 add_quirk UQ_NO_STRINGS
^C
root@c720-r314251:~ # usbconfig -d 0.3 add_quirk UQ_NO_STRINGS
^C
root@c720-r314251:~ # usbconfig -d 1.1 add_quirk UQ_NO_STRINGS
^C
root@c720-r314251:~ # usbconfig -d 1.2 add_quirk UQ_NO_STRINGS
^C
root@c720-r314251:~ #
Comment 11 Hans Petter Selasky freebsd_committer 2017-05-11 12:35:40 UTC
Did you replug the USB device after adding the quirk?
Comment 12 Hans Petter Selasky freebsd_committer 2017-05-11 12:37:33 UTC
Add -vvv to usbdump and send the output with USB_ERR_TIMEOUT to the PCSC USB driver developers. They might know why the device is hanging on the commands they are sending.

This does not look like a FreeBSD USB stack issue.

--HPS
Comment 13 Matthias Apitz 2017-05-11 12:43:43 UTC
(In reply to Hans Petter Selasky from comment #11)

appart of the test with the mouse (which now is not connected) I can not unplu any device; they are built-in in the Acer C720 netbook;
Comment 14 Matthias Apitz 2017-05-11 12:45:03 UTC
(In reply to Matthias Apitz from comment #13)

are you sure? why all the usbconfig commands are hanging? there is no pcscd software involved...
Comment 15 Hans Petter Selasky freebsd_committer 2017-05-11 12:49:10 UTC
Hi,

See "procstat -ak" and which thread is blocked inside USB.

When you have a non-behaving USB device which times out and never closes its USB handle from userspace, that will block the enumeration thread, which in turn will block usbconfig.

--HPS
Comment 16 Matthias Apitz 2017-05-11 13:26:29 UTC
(In reply to Hans Petter Selasky from comment #15)

procstat -ak | grep usb

only show system processes:

root@c720-r314251:/home/guru # procstat -ak | grep usb > /tmp/usb
root@c720-r314251:/home/guru # ps ax | grep '14 ' >> /tmp/usb
root@c720-r314251:/home/guru # cat /tmp/usb
   14 100030 usb                 usbus0              mi_switch sleepq_switch sleepq_wait _cv_wait usb_process fork_exit fork_trampoline 
   14 100031 usb                 usbus0              mi_switch sleepq_switch sleepq_wait _cv_wait usb_process fork_exit fork_trampoline 
   14 100032 usb                 usbus0              mi_switch sleepq_switch sleepq_wait _cv_wait usb_process fork_exit fork_trampoline 
   14 100033 usb                 usbus0              mi_switch sleepq_switch sleepq_wait _cv_wait usb_process fork_exit fork_trampoline 
   14 100034 usb                 usbus0              mi_switch sleepq_switch sleepq_wait _cv_wait usb_process fork_exit fork_trampoline 
   14 100041 usb                 usbus1              mi_switch sleepq_switch sleepq_wait _cv_wait usb_process fork_exit fork_trampoline 
   14 100042 usb                 usbus1              mi_switch sleepq_switch sleepq_wait _cv_wait usb_process fork_exit fork_trampoline 
   14 100043 usb                 usbus1              mi_switch sleepq_switch sleepq_wait _cv_wait usb_process fork_exit fork_trampoline 
   14 100044 usb                 usbus1              mi_switch sleepq_switch sleepq_wait _cv_wait usbd_do_request_flags usbd_req_get_port_status uhub_read_port_status uhub_explore uhub_explore usb_bus_explore usb_process fork_exit fork_trampoline 
   14 100045 usb                 usbus1              mi_switch sleepq_switch sleepq_wait _cv_wait usb_process fork_exit fork_trampoline 
  12  -  WL    0:05,14 [intr]
  14  -  DL    0:00,04 [usb]
 614  -  Is    0:00,00 /sbin/ipmon -Ds
2238  1  R+    0:00,00 grep 14 

I also have deactivated any access to usb, like webcamd, hals, ...

what else?
Comment 17 Hans Petter Selasky freebsd_committer 2017-05-11 13:29:04 UTC
Which USB device is ugen1.2 ? It is the one causing the TIMEOUT issue according to the usbdump log you sent.

--HPS
Comment 18 Matthias Apitz 2017-05-11 13:34:21 UTC
(In reply to Hans Petter Selasky from comment #17)

$ dmesg | grep ugen
ugen0.1: <0x8086 XHCI root HUB> at usbus0
ugen1.1: <Intel EHCI root HUB> at usbus1
ugen0.2: <SunplusIT Inc HD WebCam> at usbus0
ugen1.2: <vendor 0x8087 product 0x8000> at usbus1
ugen0.3: <vendor 0x0489 product 0xe056> at usbus0

I will invesrigate what this <vendor 0x8087 product 0x8000> is at all;
Comment 19 Hans Petter Selasky freebsd_committer 2017-05-11 13:38:08 UTC
Also the output "vmstat -i" might be interesting.

You can try to disable ugen1.1 like this:

usbconfig -d 1.1 set_config 255

And see if it helps.

--HPS
Comment 20 Matthias Apitz 2017-05-11 14:22:51 UTC
(In reply to Hans Petter Selasky from comment #19)

this hangs too :-(
Comment 21 Hans Petter Selasky freebsd_committer 2017-05-11 14:28:32 UTC
Try to put:

dev.uhub.2.disable_enumeration=1

In /boot/loader.conf or something like that and reboot.

--HPS
Comment 22 Matthias Apitz 2017-05-12 05:16:00 UTC
(In reply to Hans Petter Selasky from comment #21)

I did so but this does not give any visible change in the problem:

root@c720-r314251:/home/guru # sysctl -a | grep enumeration
hw.usb.disable_enumeration: 0
dev.uhub.2.disable_enumeration: 1
dev.uhub.1.disable_enumeration: 0
dev.uhub.0.disable_enumeration: 0

root@c720-r314251:/home/guru # usbdump -i usbus0
^C
0 packets captured
0 packets received by filter
0 packets dropped by kernel

root@c720-r314251:/home/guru # usbdump -i usbus1
07:13:47.895287 usbus1.2 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=0,SLEN=0,IVAL=0,ERR=TIMEOUT
07:13:47.962218 usbus1.2 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
07:13:52.863603 usbus1.2 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=0,SLEN=0,IVAL=0,ERR=TIMEOUT
07:13:52.926434 usbus1.2 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
^C
4 packets captured
4 packets received by filter
0 packets dropped by kernel
Comment 23 Hans Petter Selasky freebsd_committer 2017-05-12 06:36:26 UTC
Try to disable one of the other hubs in turn.

--HPS
Comment 24 Matthias Apitz 2017-05-12 07:21:41 UTC
(In reply to Hans Petter Selasky from comment #23)

I disabled all of them:

# grep enumer /boot/loader.conf
dev.uhub.0.disable_enumeration=1
dev.uhub.1.disable_enumeration=1
dev.uhub.2.disable_enumeration=1

with the following results:

usbdump stopped working on all usbusN:

root@c720-r314251:/home/guru # usbdump -i usbus0
^C
0 packets captured
0 packets received by filter
0 packets dropped by kernel
root@c720-r314251:/home/guru # usbdump -i usbus1
^C^C
0 packets captured
0 packets received by filter
0 packets dropped by kernel

the pcscd starts quickly up to polling:

# /usr/local/sbin/pcscd --debug --foreground 
00000000 pcscdaemon.c:346:main() pcscd set to foreground with debug send to stdout
00000567 configfile.l:358:DBGetReaderList() Parsing conf file: /usr/local/etc/reader.conf.d
00000057 pcscdaemon.c:655:main() pcsc-lite 1.8.20 daemon ready.
00015076 hotplug_libusb.c:440:HPEstablishUSBNotifications() Driver ifd-ccid.bundle does not support IFD_GENERATE_HOTPLUG. Using active polling instead.
00000711 hotplug_libusb.c:449:HPEstablishUSBNotifications() Polling forced every 1 second(s)


BUT none of the two USB plugin slots give any reaction in /var/log/messages on plugin USB devices and give not any light on the USB sticks itself;

We say in German (translated): Operation successful, patient is dead :-)
Comment 25 Matthias Apitz 2017-05-12 07:48:59 UTC
with only set

dev.uhub.1.disable_enumeration=1

in loader.conf the 'usbdump' are not working, but the pcscd is now booting
fast and fine; here is its log with time stamped each line; it does see the pull out
of the CCID stick at 09:44:40, but not any plug-in again (will investigate this):

09:44:26: 00000000 pcscdaemon.c:346:main() pcscd set to foreground with debug send to stdout
09:44:26: 00000554 configfile.l:358:DBGetReaderList() Parsing conf file: /usr/local/etc/reader.conf.d
09:44:26: 00000045 pcscdaemon.c:655:main() pcsc-lite 1.8.20 daemon ready.
09:44:26: 00015032 hotplug_libusb.c:536:HPAddHotPluggable() Adding USB device: 0:4:0
09:44:26: 00000122 readerfactory.c:1079:RFInitializeReader() Attempting startup of HID Global OMNIKEY 6121 Smart Card Reader 00 00 using /usr/local/lib/pcsc/drivers//ifd-ccid.bundle/Contents/FreeBSD/libccid.so
09:44:26: 00000245 readerfactory.c:954:RFBindFunctions() Loading IFD Handler 3.0
09:44:26: 00000048 ifdhandler.c:1953:init_driver() Driver version: 1.4.25
09:44:26: 00003965 ifdhandler.c:1970:init_driver() LogLevel: 0x0003
09:44:26: 00000013 ifdhandler.c:1981:init_driver() DriverOptions: 0x0000
09:44:26: 00002578 ifdhandler.c:110:CreateChannelByNameOrChannel() Lun: 0, device: usb:076b/6632:libusb-1.0:0:4:0
09:44:26: 00000053 ccid_usb.c:287:OpenUSBByName() Using: /usr/local/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
09:44:26: 00003592 ccid_usb.c:305:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
09:44:26: 00000011 ccid_usb.c:306:OpenUSBByName() ifdProductString: Generic CCID driver
09:44:26: 00000010 ccid_usb.c:307:OpenUSBByName() Copyright: This driver is protected by terms of the GNU Lesser General Public License version 2.1, or (at your option) any later version.
09:44:26: 00001580 ccid_usb.c:621:OpenUSBByName() Found Vendor/Product: 076B/6632 (HID Global OMNIKEY 6121 Smart Card Reader)
09:44:26: 00000011 ccid_usb.c:623:OpenUSBByName() Using USB bus/device: 0/4
09:44:27: 00012361 ccid_usb.c:1153:get_data_rates() Got 105 data rates but was expecting 96
09:44:27: 00000106 ccid_usb.c:1171:get_data_rates() declared: 10752 bps
09:44:27: 00000007 ccid_usb.c:1171:get_data_rates() declared: 21505 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 43010 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 86021 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 172043 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 344086 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 129032 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 215053 bps
09:44:27: 00000014 ccid_usb.c:1171:get_data_rates() declared: 12903 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 25806 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 51612 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 103225 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 206451 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 412903 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 154838 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 258064 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 7168 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 14336 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 28673 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 57347 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 114695 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 229390 bps
09:44:27: 00000004 ccid_usb.c:1171:get_data_rates() declared: 143369 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 8602 bps
09:44:27: 00000006 ccid_usb.c:1171:get_data_rates() declared: 17204 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 34408 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 68817 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 137634 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 275268 bps
09:44:27: 00000004 ccid_usb.c:1171:get_data_rates() declared: 5376 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 64516 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 107526 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 6451 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 77419 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 8064 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 16129 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 32258 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 96774 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 161290 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 3584 bps
09:44:27: 00000019 ccid_usb.c:1171:get_data_rates() declared: 4301 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 2688 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 53763 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 3225 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 38709 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 4032 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 48387 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 80645 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 2150 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 2580 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 5161 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 10322 bps
09:44:27: 00000004 ccid_usb.c:1171:get_data_rates() declared: 20645 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 41290 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 82580 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 30967 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 7812 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 15625 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 31250 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 62500 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 125000 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 250000 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 93750 bps
09:44:27: 00000004 ccid_usb.c:1171:get_data_rates() declared: 156250 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 9375 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 18750 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 37500 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 75000 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 150000 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 300000 bps
09:44:27: 00000008 ccid_usb.c:1171:get_data_rates() declared: 112500 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 187500 bps
09:44:27: 00000004 ccid_usb.c:1171:get_data_rates() declared: 5208 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 10416 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 20833 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 41666 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 83333 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 166666 bps
09:44:27: 00000004 ccid_usb.c:1171:get_data_rates() declared: 104166 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 6250 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 12500 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 25000 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 50000 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 100000 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 200000 bps
09:44:27: 00000004 ccid_usb.c:1171:get_data_rates() declared: 3906 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 46875 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 78125 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 4687 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 56250 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 5859 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 11718 bps
09:44:27: 00000004 ccid_usb.c:1171:get_data_rates() declared: 23437 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 70312 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 117187 bps
09:44:27: 00000005 ccid_usb.c:1171:get_data_rates() declared: 2604 bps
09:44:27: 00120240 ifdhandler.c:379:IFDHGetCapabilities() tag: 0xFB3, usb:076b/6632:libusb-1.0:0:4:0 (lun: 0)
09:44:27: 00000016 readerfactory.c:395:RFAddReader() Using the reader polling thread
09:44:27: 00000521 ifdhandler.c:379:IFDHGetCapabilities() tag: 0xFAE, usb:076b/6632:libusb-1.0:0:4:0 (lun: 0)
09:44:27: 00000010 ifdhandler.c:470:IFDHGetCapabilities() Reader supports 1 slot(s)
09:44:27: 00000095 readerfactory.c:1420:RFWaitForReaderInit() Waiting init for reader: HID Global OMNIKEY 6121 Smart Card Reader 00 00
09:44:27: 00000025 hotplug_libusb.c:440:HPEstablishUSBNotifications() Driver ifd-ccid.bundle does not support IFD_GENERATE_HOTPLUG. Using active polling instead.
09:44:27: 00000018 hotplug_libusb.c:449:HPEstablishUSBNotifications() Polling forced every 1 second(s)
09:44:40: 13099101 hotplug_libusb.c:626:HPRemoveHotPluggable() Removing USB device[0]: 0:4:0
09:44:40: 00002788 readerfactory.c:608:RFRemoveReader() UnrefReader() count was: 1
09:44:40: 00000012 eventhandler.c:176:EHDestroyEventHandler() Stomping thread.
09:44:40: 00000008 ifdhandler.c:379:IFDHGetCapabilities() tag: 0xFB1, usb:076b/6632:libusb-1.0:0:4:0 (lun: 0)
09:44:40: 00000006 ifdhandler.c:379:IFDHGetCapabilities() tag: 0xFB2, usb:076b/6632:libusb-1.0:0:4:0 (lun: 0)
09:44:40: 00000004 eventhandler.c:201:EHDestroyEventHandler() Request stopping of polling thread
09:44:40: 00000005 ifdhandler.c:344:IFDHStopPolling() usb:076b/6632:libusb-1.0:0:4:0 (lun: 0)
09:44:40: 00000013 ccid_usb.c:1337:InterruptStop() libusb_cancel_transfer failed: -5
Comment 26 Hans Petter Selasky freebsd_committer 2017-05-12 08:05:12 UTC
Try to figure out which one of them is the culpit :-)

--HPS
Comment 27 Matthias Apitz 2017-05-17 18:21:49 UTC
part of the problem (if not at all its base) seems to be that sometimes on boot (i.e. if the card is already connect before boot) or later the card plug-in is not seen; I have here the example of two boots:

egrep 'OMNIKEY|boot' /var/log/messages
...
May 17 19:58:48 c720-r314251 syslogd: kernel boot file is /boot/kernel/kernel
May 17 20:02:33 c720-r314251 syslogd: kernel boot file is /boot/kernel/kernel
May 17 20:02:33 c720-r314251 kernel: ugen0.2: <HID Global OMNIKEY 6121 Smart Card Reader> at usbus0
May 17 20:02:56 c720-r314251 kernel: ugen0.2: <HID Global OMNIKEY 6121 Smart Card Reader> at usbus0 (disconnected)
May 17 20:03:00 c720-r314251 kernel: ugen0.2: <HID Global OMNIKEY 6121 Smart Card Reader> at usbus0

the 1st boot at 19:48 did not see the card, the 2nd at 20:02 could see it and the kernel notes the withdraw and re-connect as well; when the card is not seen, only reboot helps to get it noticed;

when the card is seen fine, any start of the pcscd daemon as well works fine;

is this some kind of timing issue on the USB bus?
Comment 28 Hans Petter Selasky freebsd_committer 2017-05-18 07:16:27 UTC
What does "usbconfig" say when the card is not connected?

--HPS
Comment 29 Matthias Apitz 2017-05-18 07:31:46 UTC
(In reply to Hans Petter Selasky from comment #28)

when the card *is* connected and seen it says:

# usbconfig list
ugen0.1: <0x8086 XHCI root HUB> at usbus0, cfg=0 md=HOST spd=SUPER (5.0Gbps) pwr=SAVE (0mA)
ugen1.1: <Intel EHCI root HUB> at usbus1, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (0mA)
ugen0.2: <HID Global OMNIKEY 6121 Smart Card Reader> at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON (100mA)
ugen0.3: <SunplusIT Inc HD WebCam> at usbus0, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=ON (500mA)
ugen0.4: <vendor 0x0489 product 0xe056> at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON (100mA)

will add the requested information when it is *not* seen next time;
Comment 30 Matthias Apitz 2017-05-18 15:13:24 UTC
here is the 'usbconfig' output, when the card is not seen; it takes around 10 minutes to print the lines:

# usbconfig
ugen1.1: <Intel EHCI root HUB> at usbus1, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (0mA)
ugen0.1: <0x8086 XHCI root HUB> at usbus0, cfg=0 md=HOST spd=SUPER (5.0Gbps) pwr=SAVE (0mA)
ugen1.2: <vendor 0x8087 product 0x8000> at usbus1, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (0mA)
Comment 31 Hans Petter Selasky freebsd_committer 2017-05-18 16:39:33 UTC
This sounds like a bug in a user-space daemon which doesn't close its USB handles to the kernel. Can you also run "procstat -ak" when usbconfig doesn't print the device lines instantly.
Comment 32 Matthias Apitz 2017-05-18 18:49:54 UTC
(In reply to Hans Petter Selasky from comment #31)
(In reply to Hans Petter Selasky from comment #31)
I will do so. But doesn't this (delay of usbconfig) is some other other problem, maybe related to, but not the issue that on *boot* sometimes the card is seen, sometimes not?

I do use always the same USB 3.0 port of the C720 and I will try to gather information about, if the issue of not seeing the card depends on
1) card is allready pluged'in before power-on or not
2) AC power supply is connected or not
Comment 33 Hans Petter Selasky freebsd_committer 2017-05-18 20:17:25 UTC
The delay of usbconfig usually means that the enumeration lock is blocked.

a) when a device driver in userspace is not closing its handle
b) when there are too many explore events from the USB HUB.
Comment 34 Matthias Apitz 2017-05-19 09:41:56 UTC
(In reply to Hans Petter Selasky from comment #31)
Hans, what I do not understand is the problem with 'usbconfig' which, as you say maybe caused by any other proc blocking something, and the fact that the kernel on boot can not see the card sometimes;
Comment 35 Hans Petter Selasky freebsd_committer 2017-05-19 10:24:58 UTC
Hi,

Each USB device instance has a global SX lock. This lock is held during detach. usbconfig also acquire this lock. If the USB detach cannot complete, because character devices towards user-space cannot be destroyed, because user-space apps via libusb keep file /dev/ugenX.Y handles open, then enumeration will appear frozen until this situation is resolved?

Is that more clear?

--HPS