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 majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
