Bug 108341
| Summary: | USB ExpressCard makes kworker process utilise 72% CPU infinitely | ||
|---|---|---|---|
| Product: | Drivers | Reporter: | Christoph Anton Mitterer (calestyo) |
| Component: | Other | Assignee: | drivers_other |
| Status: | RESOLVED OBSOLETE | ||
| Severity: | normal | ||
| Priority: | P1 | ||
| Hardware: | All | ||
| OS: | Linux | ||
| URL: | https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=805903 | ||
| Kernel Version: | 4.2.6 | Subsystem: | |
| Regression: | No | Bisected commit-id: | |
|
Description
Christoph Anton Mitterer
2015-11-23 19:28:47 UTC
Hey. The whole thing still happens on: $ uname -a Linux heisenberg 4.8.0-2-amd64 #1 SMP Debian 4.8.15-2 (2017-01-04) x86_64 GNU/Linux Ben Hutchings from Debian advised me to try running perf top on the mad kworker process. 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 Don't hesitate to ask if you'd need more information. Cheer, Chris. From my side, the bug can be closed as I no longer use the specific piece of hardware (I do still have it, if someone wants me to test something). |