Hi folks! I have got a Canon LiDE 20 flatbed scanner ( ID 04a9:220d Canon, Inc. CanoScan N670U/N676U/LiDE 20). When I power up my PC and plug it in everything is fine, until I try to access it, and if it is only a "scanimage -L". To demonstrate the bug, I wrote a shell script (scandebug.sh) using some debugging hints from https://bugzilla.kernel.org/show_bug.cgi?id=202541 which seems related to this bug. #! /bin/bash echo 'module xhci_* =p' >/sys/kernel/debug/dynamic_debug/control echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control echo 81920 > /sys/kernel/debug/tracing/buffer_size_kb echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable echo Plug in scanner... sleep 20 echo Now doing first scanimage -L ... logger "Now doing first scanimage -L ..." time scanimage -L dmesg >/root/dmesg1.txt cp /sys/kernel/debug/tracing/trace /root/trace1.txt echo Now doing second scanimage -L ... logger "Now doing second scanimage -L ..." time scanimage -L dmesg >/root/dmesg2.txt cp /sys/kernel/debug/tracing/trace /root/trace2.txt lsusb -v >/root/lsusb.txt echo "module * =_" > /sys/kernel/debug/dynamic_debug/control echo 0 > /sys/kernel/debug/tracing/events/xhci-hcd/enable When it runs it outputs: [root@ping ~]# ./scandebug.sh Plug in scanner... Now doing first scanimage -L ... device `plustek:libusb:001:002' is a Canon CanoScan N670U/N676U/LiDE20 flatbed scanner real 0m45,313s user 0m0,036s sys 0m0,067s Now doing second scanimage -L ... device `plustek:libusb:001:002' is a Canon CanoScan N670U/N676U/LiDE20 flatbed scanner real 0m4,165s user 0m0,044s sys 0m0,070s As you can see, the first scanimage takes very long, in other tries it takes at least 25 seconds, while the second and any further always take around 4 s. After running the first scanimage I get the following errors/warnings: Jun 20 19:42:15 ping kernel: xhci_hcd 0000:01:00.0: // Ding dong! Jun 20 19:42:15 ping kernel: xhci_hcd 0000:01:00.0: Successful Set TR Deq Ptr cmd, deq = @d7615080 Jun 20 19:42:15 ping kernel: xhci_hcd 0000:01:00.0: // Ding dong! Jun 20 19:42:15 ping kernel: xhci_hcd 0000:01:00.0: Set TR Deq Ptr cmd, new deq seg = 00000000de74ec7f (0xd7615000 dma), new deq ptr = 00000000ff17b5e1 (0xd7615080 dma), new cycle = 1 Jun 20 19:42:15 ping kernel: xhci_hcd 0000:01:00.0: New dequeue pointer = 0xd7615080 (DMA) Jun 20 19:42:15 ping kernel: xhci_hcd 0000:01:00.0: New dequeue segment = 00000000de74ec7f (virtual) Jun 20 19:42:15 ping kernel: xhci_hcd 0000:01:00.0: Cycle state = 0x1 Jun 20 19:42:15 ping kernel: xhci_hcd 0000:01:00.0: Finding endpoint context Jun 20 19:42:15 ping kernel: xhci_hcd 0000:01:00.0: Removing canceled TD starting at 0xd7615070 (dma). Jun 20 19:42:15 ping kernel: xhci_hcd 0000:01:00.0: Stopped on Transfer TRB for slot 1 ep 4 Jun 20 19:42:15 ping kernel: xhci_hcd 0000:01:00.0: // Ding dong! Jun 20 19:42:15 ping kernel: xhci_hcd 0000:01:00.0: Cancel URB 00000000fa372bb8, dev 3, ep 0x82, starting at offset 0xd7615070 Jun 20 19:41:55 ping kernel: xhci_hcd 0000:01:00.0: AMD-Vi: Event logged [IO_PAGE_FAULT domain=0x000d address=0xdc707028 flags=0x0020] Jun 20 19:41:55 ping kernel: xhci_hcd 0000:01:00.0: Looking for event-dma 00000000d7615060 trb-start 00000000d7615070 trb-end 00000000d7615070 seg-start 00000000d7615000 seg-end 00000000d7615ff0 Jun 20 19:41:55 ping kernel: xhci_hcd 0000:01:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 4 comp_code 1 Jun 20 19:41:55 ping kernel: xhci_hcd 0000:01:00.0: AMD-Vi: Event logged [IO_PAGE_FAULT domain=0x000d address=0xc9b4c730 flags=0x0020] Jun 20 19:41:55 ping kernel: xhci_hcd 0000:01:00.0: ep 0x82 - asked for 1 bytes, 0 bytes untransferred Jun 20 19:41:55 ping kernel: xhci_hcd 0000:01:00.0: WARN Successful completion on short TX Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: // Ding dong! Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: // Ding dong! Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: Slot state = 3, EP state = 2 Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: WARN Set TR Deq Ptr cmd failed due to incorrect slot or ep state. Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: // Ding dong! Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: Set TR Deq Ptr cmd, new deq seg = 00000000de74ec7f (0xd7615000 dma), new deq ptr = 00000000f035f701 (0xd7615060 dma), new cycle = 1 Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: New dequeue pointer = 0xd7615060 (DMA) Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: New dequeue segment = 00000000de74ec7f (virtual) Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: Cycle state = 0x1 Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: Finding endpoint context Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: Removing canceled TD starting at 0xd7615050 (dma). Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: // Ding dong! Jun 20 19:41:54 ping kernel: xhci_hcd 0000:01:00.0: Cancel URB 000000002fee127b, dev 3, ep 0x82, starting at offset 0xd7615050 After the second scanimage -L I got no errors or warnings: Jun 20 19:42:33 ping kernel: xhci_hcd 0000:09:00.3: // Ding dong! Jun 20 19:42:33 ping kernel: xhci_hcd 0000:09:00.3: Cancel URB 00000000e5885748, dev 2, ep 0x0, starting at offset 0xfedf51c0 Jun 20 19:42:28 ping kernel: xhci_hcd 0000:09:00.3: Successful Set TR Deq Ptr cmd, deq = @fedf51c0 Jun 20 19:42:28 ping kernel: xhci_hcd 0000:09:00.3: // Ding dong! Jun 20 19:42:28 ping kernel: xhci_hcd 0000:09:00.3: Set TR Deq Ptr cmd, new deq seg = 00000000fcf95654 (0xfedf5000 dma), new deq ptr = 000000001c042f08 (0xfedf51c0 dma), new cycle = 1 Jun 20 19:42:28 ping kernel: xhci_hcd 0000:09:00.3: New dequeue pointer = 0xfedf51c0 (DMA) Jun 20 19:42:28 ping kernel: xhci_hcd 0000:09:00.3: New dequeue segment = 00000000fcf95654 (virtual) Jun 20 19:42:28 ping kernel: xhci_hcd 0000:09:00.3: Cycle state = 0x1 Jun 20 19:42:28 ping kernel: xhci_hcd 0000:09:00.3: Finding endpoint context Jun 20 19:42:28 ping kernel: xhci_hcd 0000:09:00.3: Removing canceled TD starting at 0xfedf5190 (dma). Jun 20 19:42:28 ping kernel: xhci_hcd 0000:09:00.3: Stopped on Transfer TRB for slot 1 ep 0 Jun 20 19:42:28 ping kernel: xhci_hcd 0000:09:00.3: // Ding dong! Jun 20 19:42:28 ping kernel: xhci_hcd 0000:09:00.3: Cancel URB 00000000e5885748, dev 2, ep 0x0, starting at offset 0xfedf5190 Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Successful Set TR Deq Ptr cmd, deq = @fede7830 Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Ignoring reset ep completion code of 1 Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Giveback URB 00000000e5885748, len = 0, expected = 4, status = -32 Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: // Ding dong! Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Set TR Deq Ptr cmd, new deq seg = 0000000035cbb6da (0xfede7000 dma), new deq ptr = 00000000c7b3bb41 (0xfede7830 dma), new cycle = 1 Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Queueing new dequeue state Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: New dequeue pointer = 0xfede7830 (DMA) Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: New dequeue segment = 0000000035cbb6da (virtual) Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Cycle state = 0x1 Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Finding endpoint context Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Cleaning up stalled endpoint ring Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Stalled endpoint for slot 2 ep 0 Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Successful Set TR Deq Ptr cmd, deq = @fede7800 Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Ignoring reset ep completion code of 1 Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Giveback URB 00000000e5885748, len = 0, expected = 10, status = -32 Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: // Ding dong! Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Set TR Deq Ptr cmd, new deq seg = 0000000035cbb6da (0xfede7000 dma), new deq ptr = 0000000025e70308 (0xfede7800 dma), new cycle = 1 Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Queueing new dequeue state Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: New dequeue pointer = 0xfede7800 (DMA) Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: New dequeue segment = 0000000035cbb6da (virtual) Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Cycle state = 0x1 Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Finding endpoint context Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Cleaning up stalled endpoint ring Jun 20 19:42:23 ping kernel: xhci_hcd 0000:09:00.3: Stalled endpoint for slot 2 ep 0 I got no warnings after startup related to IOMMU or AMD-Vi: [fabi@ping ~]$ dmesg|grep IOMMU [ 0.404420] pci 0000:00:00.2: AMD-Vi: IOMMU performance counters supported [ 0.408184] pci 0000:00:00.2: AMD-Vi: Found IOMMU cap 0x40 [ 0.409389] perf/amd_iommu: Detected AMD IOMMU #0 (2 banks, 4 counters/bank). [ 0.424729] AMD-Vi: AMD IOMMUv2 driver by Joerg Roedel <jroedel@xxxxxxx> [fabi@ping ~]$ dmesg|grep AMD-Vi [ 0.404420] pci 0000:00:00.2: AMD-Vi: IOMMU performance counters supported [ 0.408184] pci 0000:00:00.2: AMD-Vi: Found IOMMU cap 0x40 [ 0.408185] pci 0000:00:00.2: AMD-Vi: Extended features (0xf77ef22294ada): [ 0.408187] AMD-Vi: Interrupt remapping enabled [ 0.408188] AMD-Vi: Virtual APIC enabled [ 0.408283] AMD-Vi: Lazy IO/TLB flushing enabled [ 0.424729] AMD-Vi: AMD IOMMUv2 driver by Joerg Roedel <jroedel@xxxxxxx> Output of awk -f scripts/ver_linux: Linux ping 5.7.4 #1 SMP PREEMPT Sat Jun 20 14:34:20 CEST 2020 x86_64 GNU/Linux GNU C 10.1.0 GNU Make 4.3 Binutils 2.34.0 Util-linux 2.35.2 Mount 2.35.2 Module-init-tools 27 E2fsprogs 1.45.6 Jfsutils 1.1.15 Reiserfsprogs 3.6.27 Xfsprogs 5.6.0 PPP 2.4.7 Bison 3.6.3 Flex 2.6.4 Linux C++ Library 6.0.28 Linux C Library 2.31 Dynamic linker (ldd) 2.31 Procps 3.3.16 Net-tools 2.10 Kbd 2.2.0 Console-tools 2.2.0 Sh-utils 8.32 Udev 245 Modules Loaded 8021q acpi_cpufreq aesni_intel agpgart amdgpu asus_wmi battery ccp cdrom cec crc16 crc32c_generic crc32c_intel crc32_pclmul crct10dif_pclmul cryptd crypto_simd crypto_user dca drm drm_kms_helper edac_mce_amd eeepc_wmi evdev ext4 fat fb_sys_fops garp ghash_clmulni_intel glue_helper gpio_amdpt gpu_sched hid hid_generic hid_logitech_dj hid_logitech_hidpp i2c_algo_bit i2c_piix4 igb input_leds ip_tables irqbypass jbd2 joydev k10temp kvm kvm_amd ledtrig_audio libcrc32c llc mac_hid mbcache mousedev mrp mxm_wmi nf_conntrack nf_defrag_ipv4 nf_defrag_ipv6 nfnetlink nf_reject_ipv4 nf_reject_ipv6 nf_tables nft_ct nft_reject nft_reject_inet nls_cp437 nls_iso8859_1 pcspkr pinctrl_amd rc_core rfkill rng_core sg snd snd_hda_codec snd_hda_codec_generic snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_core snd_hda_intel snd_hwdep snd_intel_dspcfg snd_pcm snd_timer soundcore sp5100_tco sparse_keymap sr_mod stp syscopyarea sysfillrect sysimgblt tpm tpm_crb tpm_tis tpm_tis_core ttm usbhid usbip_core usbip_host vfat wmi wmi_bmof xhci_hcd xhci_pci x_tables CPU: AMD Ryzen 7 2700X Eight-Core Processor The complete output of the above script along lspci -vvv, lsusb -v and filtered journal (kernel messages and script markings) can be downloaded from http://fabi.bplaced.net/debuglogs1.tar.xz Greats Fabian Melzow
