On Sun, Nov 26, 2017 at 07:05:12PM +0100, Nikola Ciprich wrote:
> Hello dear linux USB users and developers,
>
> I've got a bit desperate question, but maybe somebody will have
> some idea on what to try..
>
> we're migrating lots (thousands) of users from very old opensuse running
> 2.6.13 kernel to new centos based system running 4.4.52 kernel.
That's a huge jump :)
> There are security tokens in use on desktops - Ikey 4000. They work,
> but on new system initialisation of token and reading certificates is taking
> very long, slowing firefox (and other pkcs11 users) start by ~20seconds. Since
> users are running those token using apps very often, this is causing lots of hassle..
>
> The problem is, that token support is proprietary, I don't have any sources, just
> those arcane opensc + openct binaries built for opensuse I'm forced to on new system
> (therefore I'm also using 32bit firefox). Since the switch to new tokens with better
> support is planned on next year, I'd really love to resolve this issue.
So is it using libusb to talk to the device, or a kernel module?
If libusb, you can use usbmon to see the data being sent to/from the
device, to see where the stalls are, and hopefully compare the two
systems to see what the difference is.
> I've tried tracing all related binaries, and I think the problem is in ifdhandler
> slow access to device..
>
> sample ifdhandler debug output is here:
>
> Debug: ifdhandler_process: ifdhandler_process(cmd=CT_CMD_TRANSACT, unit=0)
> Debug: ifd_protocol_transceive: cmd: 00 b0 04 ec dd
> Debug: t1_xcv: sending 00 00 05 00 b0 04 ec dd 80
> Debug: ifd_usb_control: usb req type=x41 req=x17 val=x0000 ind=x0005 len=5
> Debug: ifd_usb_control: send b0 04 ec dd 80
> Debug: ifd_usb_control: usb req type=xc1 req=x01 val=x0000 ind=x0000 len=255
> Debug: ifd_usb_control: recv 00 c3 01 26 e4 04 ec dd 80 02 10 00 34 8b 9f 8e 07 f4 22 de bc 60 fb a8 a0 8a a4 0c 11 0f 33 90 00 01 1c ad 80 1b 84 31 2a 40 11 fe 4d 18 23 08 c6 cd 90 b5 44 01 21 24 88 a6 0b 40 94 21 78 78 b0 95 72 19 20 e0 1a a6 07 e3 69 c4 41 4c 00 66 04 a3 01 b2 d0 c1 32 0a 60 05 56 d8 16 d1 b4 04 10 05 80 c4 87 8c 61 12 73 5a fa a8 61 b4 28 25 ba 4c 24 92 c9 28 9a 84 49 0b 00 4a 27 94 45 02 81 11 ed 42 a2 90 c0 aa b0 91 59 04 6a 20 a1 2b 40 c3 27 3c 05 a9 4a 2d 05 00 02 87 91 28 10 17 16 ad 00 41 42 92 20 94 18 20 83 cb ae 42 0e 58 52 d1 00 29 41 12 3c 40 00 c3 01 26 e4 04 ec dd 80 02 10 00 34 8b 9f 8e 07 f4 22 de bc 60 fb a8 a0 8a a4 0c 11 0f 33 90 00 01 1c ad 80 1b 84 31 2a 40 11 fe 4d 18 23 08 c6 cd 90 b5 44 01 21 24 88 a6 0b 40 94 21 78 78 b0 95 72 19 20 e0 1a
> Debug: t1_xcv: received 00 c3 01 26 e4
> Debug: t1_transceive: CT sent S-block with wtx=38
> Debug: t1_xcv: sending 00 e3 01 26 c4
> Debug: ifd_usb_control: usb req type=x41 req=x17 val=xe300 ind=x2601 len=1
> Debug: ifd_usb_control: send c4
> Debug: ifd_usb_control: usb req type=xc1 req=x01 val=x0000 ind=x0000 len=255
> Debug: ifd_usb_control: recv 00 60 20 35 9c b6 98 cd e1 e2 18 08 f0 8b 42 8d c9 b2 3f f7 09 35 29 dc 95 cf 58 f5 91 c1 2d 86 37 2a dc 1a 80 1b 84 31 2a 40 11 fe 4d 18 23 08 c6 cd 90 b5 44 01 21 24 88 a6 0b 40 94 21 78 78 b0 95 72 19 20 e0 1a a6 07 e3 69 c4 41 4c 00 66 04 a3 01 b2 d0 c1 32 0a 60 05 56 d8 16 d1 b4 04 10 05 80 c4 87 8c 61 12 73 5a fa a8 61 b4 28 25 ba 4c 24 92 c9 28 9a 84 49 0b 00 4a 27 94 45 02 81 11 ed 42 a2 90 c0 aa b0 91 59 04 6a 20 a1 2b 40 c3 27 3c 05 a9 4a 2d 05 00 02 87 91 28 10 17 16 ad 00 41 42 92 20 94 18 20 83 cb ae 42 0e 58 52 d1 00 29 41 12 3c 40 00 60 20 35 9c b6 98 cd e1 e2 18 08 f0 8b 42 8d c9 b2 3f f7 09 35 29 dc 95 cf 58 f5 91 c1 2d 86 37 2a dc 1a 80 1b 84 31 2a 40 11 fe 4d 18 23 08 c6 cd 90 b5 44 01 21 24 88 a6 0b 40 94 21 78 78 b0 95 72 19 20 e0 1a
>
> (repeats many times).
>
> strace of the same process:
>
> 18:27:24 poll([{fd=3, events=POLLHUP}, {fd=4, events=POLLIN}, {fd=6, events=POLLOUT}], 3, 1000) = 1 ([{fd=6, revents=POLLOUT}])
> 18:27:24 time(NULL) = 1511717244
> 18:27:24 rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
> 18:27:24 write(6, "\v\0\0\0\0\0\0\0\0\0)\0E\0&P1\t\355\17\17\17\17\17\17\0\0\1\0\0\0\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\0\0\1\0\220\0", 53) = 53
> 18:27:24 rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
> 18:27:24 time(NULL) = 1511717244
> 18:27:24 poll([{fd=3, events=POLLHUP}, {fd=4, events=POLLIN}, {fd=6, events=POLLOUT}], 3, 1000) = 1 ([{fd=6, revents=POLLOUT}])
> 18:27:24 time(NULL) = 1511717244
> 18:27:24 rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
> 18:27:24 rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
> 18:27:24 time(NULL) = 1511717244
> 18:27:24 poll([{fd=3, events=POLLHUP}, {fd=4, events=POLLIN}, {fd=6, events=POLLIN}], 3, 1000) = 1 ([{fd=6, revents=POLLIN}])
> 18:27:24 time(NULL) = 1511717244
> 18:27:24 read(6, "\f\0\0\0\0\0\0\0\0\0\n\0!\0\304\0\5\0\260\0\0\374", 3857) = 22
> 18:27:24 time(NULL) = 1511717244
> 18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 5
> 18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
> 18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 1
> 18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
> 18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
> 18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
> 18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
> 18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
> 18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
> 18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
> 18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
> 18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
> 18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
> 18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
> 18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
> 18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
> 18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
> 18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
> 18:27:25 time(NULL) = 1511717245
>
> I have to admit I don't have much clue of what does ifdhandler mean, and also wasn't
> able to find much about mentioned syscalls..
I don't know what ifdhandler is, but the usbdevfs calls are userspace
calls to the usb device.
> I know that I'm probably providing insufficient information here, but does
> somebody have some Idea on what I should check or how to better debug this?
Get the company you bought the device from to support it as you paid for
it? :)
Sorry, other than that, try usbmon, and see if you can see any timing
differences.
good luck!
greg k-h
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
