* USB ExpressCard makes kworker process utilise 72-75% CPU infinitely
@ 2017-01-12 20:36 Christoph Anton Mitterer
0 siblings, 0 replies; only message in thread
From: Christoph Anton Mitterer @ 2017-01-12 20:36 UTC (permalink / raw)
To: linux-acpi
[-- Attachment #1: Type: text/plain, Size: 15229 bytes --]
Hi.
This is basically from:
https://bugzilla.kernel.org/show_bug.cgi?id=108341
and
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=805903
respectively
https://www.spinics.net/lists/linux-usb/msg151899.html
the later in which Grek KH recommended me to ping linux-acpi as
well.
I bought a USB3.0 ExpressCard from StarTech[0] which is apparently[1]
based on the NEC uPD720200.
Using a kernel 4.2.6 (see further below for the same on a more recent
kernel version) on amd64, the System is Debian sid, the following
happens when I plug the card:
kernel logs show:
Nov 21 17:15:22 heisenberg kernel: [ 102.387452] pci 0000:01:00.0: [1033:0194] type 00 class 0x0c0330
Nov 21 17:15:22 heisenberg kernel: [ 102.387545] pci 0000:01:00.0: reg 0x10: [mem0x00000000-0x00001fff 64bit]
Nov 21 17:15:22 heisenberg kernel: [ 102.387723] pci 0000:01:00.0: PME# supported from D0 D3hot
Nov 21 17:15:22 heisenberg kernel: [ 102.394689] pci 0000:01:00.0: BAR 0: assigned [mem0xf0d00000-0xf0d01fff 64bit]
Nov 21 17:15:22 heisenberg kernel: [ 102.394750] pci 0000:01:00.0: enabling device (0000 -> 0002)
Nov 21 17:15:22 heisenberg kernel: [ 102.395178] xhci_hcd 0000:01:00.0: xHCI Host Controller
Nov 21 17:15:22 heisenberg kernel: [ 102.395192] xhci_hcd 0000:01:00.0: new USB bus registered,assigned bus number 5
Nov 21 17:15:22 heisenberg kernel: [ 102.395418] xhci_hcd 0000:01:00.0: hcc params 0x014042cb hciversion 0x96 quirks 0x00000004
Nov 21 17:15:22 heisenberg kernel: [ 102.395892] usb usb5: New USB device found, idVendor=1d6b, idProduct=0002
Nov 21 17:15:22 heisenberg kernel: [ 102.395896] usb usb5: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Nov 21 17:15:22 heisenberg kernel: [ 102.395899] usb usb5: Product: xHCI Host Controller
Nov 21 17:15:22 heisenberg kernel: [ 102.395902] usb usb5: Manufacturer: Linux 4.2.0-1-amd64 xhci-hcd
Nov 21 17:15:22 heisenberg kernel: [ 102.395905] usb usb5: SerialNumber: 0000:01:00.0
Nov 21 17:15:22 heisenberg kernel: [ 102.396308] hub 5-0:1.0: USB hub found
Nov 21 17:15:22 heisenberg kernel: [ 102.396331] hub 5-0:1.0: 2 ports detected
Nov 21 17:15:22 heisenberg kernel: [ 102.396591] xhci_hcd 0000:01:00.0: xHCI Host Controller
Nov 21 17:15:22 heisenberg kernel: [ 102.396599] xhci_hcd 0000:01:00.0: new USB bus registered,assigned bus number 6
Nov 21 17:15:22 heisenberg kernel: [ 102.398835] usb usb6: We don't know the algorithms for LPM forthis host, disabling LPM.
Nov 21 17:15:22 heisenberg kernel: [ 102.398883] usb usb6: New USB device found, idVendor=1d6b, idProduct=0003
Nov 21 17:15:22 heisenberg kernel: [ 102.398887] usb usb6: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Nov 21 17:15:22 heisenberg kernel: [ 102.398890] usb usb6: Product: xHCI Host Controller
Nov 21 17:15:22 heisenberg kernel: [ 102.398892] usb usb6: Manufacturer: Linux 4.2.0-1-amd64 xhci-hcd
Nov 21 17:15:22 heisenberg kernel: [ 102.398895] usb usb6: SerialNumber: 0000:01:00.0
Nov 21 17:15:22 heisenberg kernel: [ 102.399272] hub 6-0:1.0: USB hub found
Nov 21 17:15:22 heisenberg kernel: [ 102.399294] hub 6-0:1.0: 2 ports detected
and when removing:
Nov 21 17:15:40 heisenberg kernel: [ 120.541515] xhci_hcd 0000:01:00.0: remove, state 4
Nov 21 17:15:40 heisenberg kernel: [ 120.544671] usb usb6: USB disconnect, device number 1
Nov 21 17:15:40 heisenberg kernel: [ 120.546683] xhci_hcd 0000:01:00.0: Host not halted after 16000 microseconds.
Nov 21 17:15:40 heisenberg kernel: [ 120.547611] xhci_hcd 0000:01:00.0: USB bus 6 deregistered
Nov 21 17:15:40 heisenberg kernel: [ 120.547618] xhci_hcd 0000:01:00.0: remove, state 4
Nov 21 17:15:40 heisenberg kernel: [ 120.547622] usb usb5: USB disconnect, device number 1
Nov 21 17:15:40 heisenberg kernel: [ 120.547735] xhci_hcd 0000:01:00.0: USB bus 5 deregistered
Now the problem is that immediately when I attach the card, a kworker
process starts to utilise the CPU to always around 72%.
And it never stops again until I shutdown; removing the card doesn't
help.
On a more recent:
$ uname -a
Linux heisenberg 4.8.0-2-amd64 #1 SMP Debian 4.8.15-2 (2017-01-04) x86_64 GNU/Linux
kernel log for the inserted USB3.0 ExpressCard from StarTech:
Jan 12 14:15:13 heisenberg kernel: pci 0000:01:00.0: [1033:0194] type 00 class 0x0c0330
Jan 12 14:15:13 heisenberg kernel: pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00001fff 64bit]
Jan 12 14:15:13 heisenberg kernel: pci 0000:01:00.0: PME# supported from D0 D3hot
Jan 12 14:15:13 heisenberg kernel: pci 0000:01:00.0: BAR 0: assigned [mem 0xf0d00000-0xf0d01fff 64bit]
Jan 12 14:15:13 heisenberg kernel: pci 0000:01:00.0: enabling device (0000 -> 0002)
Jan 12 14:15:13 heisenberg kernel: xhci_hcd 0000:01:00.0: xHCI Host Controller
Jan 12 14:15:13 heisenberg kernel: xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 5
Jan 12 14:15:13 heisenberg kernel: xhci_hcd 0000:01:00.0: hcc params 0x014042cb hci version 0x96 quirks 0x00000004
Jan 12 14:15:13 heisenberg kernel: usb usb5: New USB device found, idVendor=1d6b, idProduct=0002
Jan 12 14:15:13 heisenberg kernel: usb usb5: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Jan 12 14:15:13 heisenberg kernel: usb usb5: Product: xHCI Host Controller
Jan 12 14:15:13 heisenberg kernel: usb usb5: Manufacturer: Linux 4.8.0-2-amd64 xhci-hcd
Jan 12 14:15:13 heisenberg kernel: usb usb5: SerialNumber: 0000:01:00.0
Jan 12 14:15:13 heisenberg kernel: hub 5-0:1.0: USB hub found
Jan 12 14:15:13 heisenberg kernel: hub 5-0:1.0: 2 ports detected
Jan 12 14:15:13 heisenberg kernel: xhci_hcd 0000:01:00.0: xHCI Host Controller
Jan 12 14:15:13 heisenberg kernel: xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 6
Jan 12 14:15:13 heisenberg kernel: usb usb6: We don't know the algorithms for LPM for this host, disabling LPM.
Jan 12 14:15:13 heisenberg kernel: usb usb6: New USB device found, idVendor=1d6b, idProduct=0003
Jan 12 14:15:13 heisenberg kernel: usb usb6: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Jan 12 14:15:13 heisenberg kernel: usb usb6: Product: xHCI Host Controller
Jan 12 14:15:13 heisenberg kernel: usb usb6: Manufacturer: Linux 4.8.0-2-amd64 xhci-hcd
Jan 12 14:15:13 heisenberg kernel: usb usb6: SerialNumber: 0000:01:00.0
Jan 12 14:15:13 heisenberg kernel: hub 6-0:1.0: USB hub found
Jan 12 14:15:13 heisenberg kernel: hub 6-0:1.0: 2 ports detected
Jan 12 14:15:15 heisenberg kernel: hub 6-0:1.0: USB hub found
Jan 12 14:15:15 heisenberg kernel: hub 6-0:1.0: 2 ports detected
Jan 12 14:15:15 heisenberg kernel: usb usb6: authorized to connect
Jan 12 14:15:16 heisenberg kernel: hub 5-0:1.0: USB hub found
Jan 12 14:15:16 heisenberg kernel: hub 5-0:1.0: 2 ports detected
Jan 12 14:15:16 heisenberg kernel: usb usb5: authorized to connect
then top shows this kworker, which remains at ~75% CPU until reboot:
2359 root 20 0 0 0 0 R 74,8 0,0 0:46.82 kworker/0:3
# perf top -p 2359 gives something like that:
Samples: 64K of event 'cycles:ppp', Event count (approx.): 19127246624
Overhead Shared Object Symbol
19,91% [kernel] [k] acpi_ns_search_one_scope
11,18% [kernel] [k] acpi_os_write_port
8,51% [kernel] [k] pci_conf1_read
7,59% [kernel] [k] acpi_ex_system_memory_space_handler
3,57% [kernel] [k] acpi_os_read_port
2,84% [kernel] [k] kmem_cache_alloc
2,27% [kernel] [k] acpi_ut_get_next_predefined_method
1,96% [kernel] [k] nmi
1,95% [kernel] [k] kmem_cache_free
1,73% [kernel] [k] ___cache_free
1,33% [kernel] [k] acpi_ut_match_predefined_method
1,10% [kernel] [k] perf_pmu_sched_task
1,09% [kernel] [k] acpi_ns_lookup
0,99% [kernel] [k] _raw_spin_lock_irqsave
0,97% [kernel] [k] acpi_ns_build_normalized_path
0,92% [kernel] [k] acpi_ps_parse_loop
0,87% [kernel] [k] native_write_msr
0,83% [kernel] [k] memset_erms
0,82% [kernel] [k] acpi_ns_search_and_enter
0,79% [kernel] [k] acpi_ut_update_object_reference
0,71% [kernel] [k] acpi_ps_get_opcode_info
0,70% [kernel] [k] kfree
0,69% [kernel] [k] acpi_ps_create_op
0,64% [kernel] [k] _raw_spin_unlock_irqrestore
0,63% [kernel] [k] process_one_work
0,59% [kernel] [k] __kmalloc
0,56% [kernel] [k] acpi_ds_exec_end_op
0,53% [kernel] [k] kmem_cache_alloc_trace
0,50% [kernel] [k] acpi_ut_update_ref_count
0,48% [kernel] [k] acpi_ut_repair_name
0,47% [kernel] [k] acpi_hw_validate_io_request
0,40% [kernel] [k] acpi_ds_create_operand
0,39% [kernel] [k] acpi_ex_resolve_operands
0,38% [kernel] [k] acpi_ut_valid_name_char
0,36% [kernel] [k] acpi_ut_acquire_mutex
0,35% [kernel] [k] _cond_resched
0,35% [kernel] [k] acpi_ut_create_internal_object_dbg
0,35% [kernel] [k] __schedule
0,34% [kernel] [k] acpi_ex_resolve_to_value
0,33% [kernel] [k] acpi_ex_name_segment
0,31% [kernel] [k] _raw_spin_lock
0,31% [kernel] [k] acpi_os_wait_semaphore
0,31% [kernel] [k] memcg_kmem_put_cache
0,31% [kernel] [k] strcat
0,30% [kernel] [k] acpi_ps_alloc_op
0,29% [kernel] [k] acpi_ex_access_region
0,29% [kernel] [k] acpi_ex_read_data_from_field
0,29% [kernel] [k] acpi_ex_extract_from_field
0,28% [kernel] [k] acpi_ut_create_generic_state
0,27% [kernel] [k] finish_task_switch
during the perf, the max sample rate is lowered (which is however normal I'd guess):
Jan 12 14:17:01 heisenberg kernel: perf: interrupt took too long (2502 > 2500), lowering kernel.perf_event_max_sample_rate to 79750
Jan 12 14:17:01 heisenberg kernel: perf: interrupt took too long (3130 > 3127), lowering kernel.perf_event_max_sample_rate to 63750
Jan 12 14:17:01 heisenberg kernel: perf: interrupt took too long (3913 > 3912), lowering kernel.perf_event_max_sample_rate to 51000
Jan 12 14:17:01 heisenberg kernel: perf: interrupt took too long (4909 > 4891), lowering kernel.perf_event_max_sample_rate to 40500
and this is what I get when removing the express card again:
Jan 12 14:17:55 heisenberg kernel: xhci_hcd 0000:01:00.0: remove, state 4
Jan 12 14:17:55 heisenberg kernel: usb usb6: USB disconnect, device number 1
Jan 12 14:17:55 heisenberg kernel: xhci_hcd 0000:01:00.0: Host not halted after 16000 microseconds.
Jan 12 14:17:55 heisenberg kernel: xhci_hcd 0000:01:00.0: USB bus 6 deregistered
Jan 12 14:17:55 heisenberg kernel: xhci_hcd 0000:01:00.0: remove, state 4
Jan 12 14:17:55 heisenberg kernel: usb usb5: USB disconnect, device number 1
Jan 12 14:17:55 heisenberg kernel: xhci_hcd 0000:01:00.0: USB bus 5 deregistered
Just in case it helps:
# lspci
00:00.0 Host bridge: Intel Corporation 3rd Gen Core processor DRAM
Controller (rev 09)
00:02.0 VGA compatible controller: Intel Corporation 3rd Gen Core
processor Graphics Controller (rev 09)
00:14.0 USB controller: Intel Corporation 7 Series/C210 Series Chipset
Family USB xHCI Host Controller (rev 04)
00:16.0 Communication controller: Intel Corporation 7 Series/C216
Chipset Family MEI Controller #1 (rev 04)
00:16.3 Serial controller: Intel Corporation 7 Series/C210 Series
Chipset Family KT Controller (rev 04)
00:19.0 Ethernet controller: Intel Corporation 82579LM Gigabit Network
Connection (rev 04)
00:1a.0 USB controller: Intel Corporation 7 Series/C216 Chipset Family
USB Enhanced Host Controller #2 (rev 04)
00:1b.0 Audio device: Intel Corporation 7 Series/C216 Chipset Family
High Definition Audio Controller (rev 04)
00:1c.0 PCI bridge: Intel Corporation 7 Series/C216 Chipset Family PCI
Express Root Port 1 (rev c4)
00:1c.2 PCI bridge: Intel Corporation 7 Series/C210 Series Chipset
Family PCI Express Root Port 3 (rev c4)
00:1c.7 PCI bridge: Intel Corporation 7 Series/C210 Series Chipset
Family PCI Express Root Port 8 (rev c4)
00:1d.0 USB controller: Intel Corporation 7 Series/C216 Chipset Family
USB Enhanced Host Controller #1 (rev 04)
00:1f.0 ISA bridge: Intel Corporation QM77 Express Chipset LPC
Controller (rev 04)
00:1f.2 SATA controller: Intel Corporation 7 Series Chipset Family 6-
port SATA Controller [AHCI mode] (rev 04)
00:1f.3 SMBus: Intel Corporation 7 Series/C216 Chipset Family SMBus
Controller (rev 04)
01:00.0 USB controller: NEC Corporation uPD720200 USB 3.0 Host
Controller (rev 04)
0a:00.0 Network controller: Intel Corporation Centrino Advanced-N 6205
[Taylor Peak] (rev 34)
0b:00.0 Unassigned class [ff00]: Realtek Semiconductor Co., Ltd.
RTS5229 PCI Express Card Reader (rev 01)
# lsusb
Bus 002 Device 002: ID 8087:0024 Intel Corp. Integrated Rate Matching
Hub
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 006 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 010: ID 04f2:b2fc Chicony Electronics Co., Ltd
Bus 001 Device 004: ID 0489:e052 Foxconn / Hon Hai
Bus 001 Device 006: ID 0b97:7772 O2 Micro, Inc. OZ776 CCID Smartcard
Reader
Bus 001 Device 003: ID 0b97:7761 O2 Micro, Inc. Oz776 1.1 Hub
Bus 001 Device 002: ID 8087:0024 Intel Corp. Integrated Rate Matching
Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 003: ID 0409:005a NEC Corp. HighSpeed Hub
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Any ideas?
Don't hesitate to ask if you'd need more information.
Thanks,
Chris.
[0] http://www.startech.com/Cards-Adapters/USB-3.0/Cards/2-Port-Flush-Mount-USB-3-ExpressCard-Adapter~ECUSB3S254F
[1] http://sgcdn.startech.com/005329/media/sets/ECUSB3S254F_Manual/ECUSB3S254F.pdf
[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 5984 bytes --]
^ permalink raw reply [flat|nested] only message in thread
only message in thread, other threads:[~2017-01-12 20:55 UTC | newest]
Thread overview: (only message) (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-01-12 20:36 USB ExpressCard makes kworker process utilise 72-75% CPU infinitely Christoph Anton Mitterer
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.