dhcpcd causing high cpu usage

User01 · 2019-11-01 10:32:42

Hello community,

To manage the wifi on my lenovo x390 i'm using dhcpcd with wpa_supplicant hook. When my laptop wakes up from sleep / suspend the wifi connectes again, but dhcpcd is causing a high cpu usage (100%). The wifi interface is a intel dualband 9560 combi card for wireless and bluetooth. Bluetooth is not configured.

Can somebody help me solve this problem?

Regards,

Rico

WSDMatty · 2019-11-01 10:41:53

Check the system logs for what dhcpcd is doing right after waking from sleep.

systemctl status dhcpcd
journalctl -xe | grep dhcpcd

cdown · 2019-11-01 12:13:50

I am having this as well, and believe I've traced it down to an issue in the IPv4 link-layer code.

This only happens when in IPv4 mode -- it's at 100% CPU on both of my interfaces for IPv4 while IPv6 is chugging along fine. Looking at the backtrace, it seems it's because it's stuck looping in userspace (there are no syscalls happening) in ipv4ll_drop:

(gdb) bt
#0 0x0000562c69063488 in ipv4ll_drop ()
#1 0x0000562c69045995 in dhcpcd_drop ()
#2 0x0000562c69056d8a in link_netlink ()
#3 0x0000562c690570da in get_netlink.constprop ()
#4 0x0000562c690579a9 in if_handlelink ()
#5 0x0000562c69047afa in dhcpcd_handlelink ()
#6 0x0000562c690493ab in eloop_start ()
#7 0x0000562c69043d6d in main ()

There are no logs to syslog or stderr/stdout while this is happening. I would run a debug build, but am worried about losing the reproducer. Looking at the assembly, it's stuck in the following sequence:

0x562c6906347d <ipv4ll_drop+205> test %rbx,%rbx
0x562c69063480 <ipv4ll_drop+208> je 0x562c69063460 <ipv4ll_drop+176>
0x562c69063482 <ipv4ll_drop+210> mov %rbx,%rdi
0x562c69063485 <ipv4ll_drop+213> mov (%rbx),%rbx
0x562c69063488 <ipv4ll_drop+216> cmpw $0xfea9,0x10(%rdi)
0x562c6906348e <ipv4ll_drop+222> jne 0x562c6906347d <ipv4ll_drop+205>

Looking at what's at 0x562c69063460 (which we don't jump to at 0x562c69063480), which is basically just calling ipv4_deladdr, it looks like maybe we go from tailq loop back up to

if (state && state->addr != NULL) {

...but I have no idea about how that happens other than Compilers Are Magic(tm). Only the TAILQ_FOREACH_SAFE looks suspicious but that's not been touched between releases other than indentation from what I saw. Shrug.

Last edited by cdown (2019-11-01 12:14:30)

Acelogic · 2019-11-01 12:31:10

I've been having the same issue on my laptop. I downgraded to 8.0.6-1 to fix the issue for now.

Last edited by Acelogic (2019-11-01 12:31:50)

zoltix · 2019-11-01 14:47:22

same issue with thinkpad T460, it occurs when I turn on/off openvpn with netmanager under xfce
Regards

User01 · 2019-11-02 10:49:49

Hello,

I'm sorry for my late reply, I did a reboot of my laptop to fix the issue so I had to wait for it to happend again to collect some data.

Here are the results:

systemctl status dhcpcd
● dhcpcd.service - dhcpcd on all interfaces
   Loaded: loaded (/usr/lib/systemd/system/dhcpcd.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2019-11-01 23:06:57 CET; 12h ago
  Process: 435 ExecStart=/usr/bin/dhcpcd -q -b (code=exited, status=0/SUCCESS)
 Main PID: 437 (dhcpcd)
    Tasks: 2 (limit: 4915)
   Memory: 9.0M
   CGroup: /system.slice/dhcpcd.service
           ├─437 dhcpcd: [master] [ip4] [ip6]
           └─643 wpa_supplicant -B -c/etc/wpa_supplicant/wpa_supplicant.conf -iwlp0s20f3

Nov 01 23:07:02 X390 dhcpcd[437]: wlp0s20f3: adding address fe80::712e:f6aa:a04a:8375
Nov 01 23:07:02 X390 dhcpcd[437]: wlp0s20f3: rebinding lease of 192.168.178.10
Nov 01 23:07:02 X390 dhcpcd[437]: wlp0s20f3: soliciting an IPv6 router
Nov 01 23:07:03 X390 dhcpcd[437]: wlp0s20f3: probing address 192.168.178.10/24
Nov 01 23:07:08 X390 dhcpcd[437]: wlp0s20f3: leased 192.168.178.10 for 3600 seconds
Nov 01 23:07:08 X390 dhcpcd[437]: wlp0s20f3: adding route to 192.168.178.0/24
Nov 01 23:07:08 X390 dhcpcd[437]: wlp0s20f3: adding default route via 192.168.178.1
Nov 01 23:07:15 X390 dhcpcd[437]: wlp0s20f3: no IPv6 Routers available
Nov 02 11:07:54 X390 dhcpcd[437]: wlp0s20f3: carrier lost
Nov 02 11:07:54 X390 dhcpcd[437]: wlp0s20f3: deleting address fe80::712e:f6aa:a04a:8375

journalctl -xe | grep dhcpcd
Nov 01 23:06:57 X390 systemd[1]: Starting dhcpcd on all interfaces...
-- Subject: A start job for unit dhcpcd.service has begun execution
-- A start job for unit dhcpcd.service has begun execution.
Nov 01 23:06:57 X390 dhcpcd[435]: dev: loaded udev
Nov 01 23:06:57 X390 dhcpcd[435]: no valid interfaces found
Nov 01 23:06:57 X390 dhcpcd[435]: no valid interfaces found
Nov 01 23:06:57 X390 dhcpcd[435]: forked to background, child pid 437
Nov 01 23:06:57 X390 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 01 23:06:57 X390 systemd[1]: Started dhcpcd on all interfaces.
-- Subject: A start job for unit dhcpcd.service has finished successfully
-- A start job for unit dhcpcd.service has finished successfully.
Nov 01 23:06:58 X390 dhcpcd-run-hooks[522]: wlp0s20f3: starting wpa_supplicant
Nov 01 23:06:58 X390 dhcpcd[437]: wlp0s20f3: waiting for carrier
Nov 01 23:06:58 X390 dhcpcd[437]: wlp0s20f3: waiting for carrier
Nov 01 23:06:58 X390 dhcpcd[437]: enp0s31f6: waiting for carrier
Nov 01 23:06:58 X390 dhcpcd[437]: wlp0s20f3: carrier acquired
Nov 01 23:06:58 X390 dhcpcd[437]: DUID 00:04:78:d2:26:cc:29:b2:11:b2:a8:5c:a0:0a:68:35:a3:62
Nov 01 23:06:58 X390 dhcpcd[437]: wlp0s20f3: IAID 25:88:00:5e
Nov 01 23:06:58 X390 dhcpcd[437]: wlp0s20f3: adding address fe80::5eff:8dc2:647:44a1
Nov 01 23:06:58 X390 dhcpcd[437]: enp0s31f6: waiting for carrier
Nov 01 23:06:58 X390 dhcpcd[437]: wlp0s20f3: carrier lost
Nov 01 23:06:58 X390 dhcpcd[437]: wlp0s20f3: deleting address fe80::5eff:8dc2:647:44a1
Nov 01 23:07:02 X390 dhcpcd[437]: wlp0s20f3: carrier acquired
Nov 01 23:07:02 X390 dhcpcd[437]: wlp0s20f3: IAID 25:88:00:5e
Nov 01 23:07:02 X390 dhcpcd[437]: wlp0s20f3: adding address fe80::712e:f6aa:a04a:8375
Nov 01 23:07:02 X390 dhcpcd[437]: wlp0s20f3: rebinding lease of 192.168.178.10
Nov 01 23:07:02 X390 dhcpcd[437]: wlp0s20f3: soliciting an IPv6 router
Nov 01 23:07:03 X390 dhcpcd[437]: wlp0s20f3: probing address 192.168.178.10/24
Nov 01 23:07:08 X390 dhcpcd[437]: wlp0s20f3: leased 192.168.178.10 for 3600 seconds
Nov 01 23:07:08 X390 dhcpcd[437]: wlp0s20f3: adding route to 192.168.178.0/24
Nov 01 23:07:08 X390 dhcpcd[437]: wlp0s20f3: adding default route via 192.168.178.1
Nov 01 23:07:15 X390 dhcpcd[437]: wlp0s20f3: no IPv6 Routers available
Nov 02 11:07:54 X390 dhcpcd[437]: wlp0s20f3: carrier lost
Nov 02 11:07:54 X390 dhcpcd[437]: wlp0s20f3: deleting address fe80::712e:f6aa:a04a:8375
Nov 02 11:08:55 X390 sudo[29805]:     rico : TTY=pts/1 ; PWD=/home/rico ; USER=root ; COMMAND=/usr/bin/systemctl status dhcpcd

I hope this helps.

Regards,

Rico

Rimio · 2019-11-02 12:52:52

Same issue with an Asus UX550V. Cannot trace what triggers this behaviour.

WindedDragon · 2019-11-02 17:08:17

Same issue on a Lenovo Flex 15. It's been working fine for months but either yesterday or the day before when it connects to either WiFi or Ethernet it uses 100% CPU, not every time, but the majority.
Edit: To add more info.

Last edited by WindedDragon (2019-11-02 17:09:54)

thinman · 2019-11-02 18:06:40

I'm not currently running Arch, but Void Linux recently downgraded its dhcpcd package from 8.1.1 to 8.0.6 to solve this same issue, so it looks like it's coming from upstream. Hopefully it's okay to post this comment here.

simonzack · 2019-11-03 00:35:53

I'm having htis issue too on my desktop, it's been using 100% CPU for a while now. I'll try downgrading to 8.0.6, thanks.

Bkmz · 2019-11-03 15:00:29

I found this issue recently on my laptop. And I can guess that it can be reproduced with a small lease time from the DHCP server. Currently, I'm debugging my home network and have lease time less than 30minutes. And I can confirm that this behavior reproduces with 30 minutes or so.

cdown · 2019-11-05 17:06:10

The fix is here: https://roy.marples.name/cgit/dhcpcd.gi … 278e2237ca

I'll file a bug to locally patch on Arch if there's no new release soon.

brofjst · 2019-11-07 14:23:44

Same issue here

dhcpcd 8.1.1-1

Last edited by brofjst (2019-11-07 14:44:01)

jbrea · 2019-11-07 20:23:16

I was annoyed with this and impatient and therefore applied the patch locally.

asp checkout dhcpcd
cd dhcpcd/repos/core-x86_64

edit file PKGBUILD:
1. add the following line to sources (as new line 20)

        "ipv4.patch::https://roy.marples.name/cgit/dhcpcd.git/patch/?id=73ac184333f77b38a8b4c4202c2928278e2237ca"

2. Add section (e.g. after build() { ... })

prepare() {
  cd "${srcdir}/${pkgname}-${pkgver}"
  patch --forward --strip=1 --input="${srcdir}/ipv4.patch"
}

Then run

updpkgsums
makepkg
makepkg --install

hydrogen · 2019-11-08 03:39:23

Same issue, and it's okay when i restart dhcpcd.

JonnyRobbie · 2019-11-08 09:11:10

Same issue here. And this is not laptop, but desktop pc. After wake up, the dhcpcd gets 100%'d and sometimes after (usually when watching high traffic video), the whole inernet connection just goes down altogether.

[ALPM] upgraded dhcpcd (8.0.6-1 -> 8.1.1-1)

Upstream already notified https://roy.marples.name/archives/dhcpc … 02668.html and has a working patch, which is in Test repo. So it's probably just a matter of time: https://git.archlinux.org/svntogit/pack … caebd13e54 https://bugs.archlinux.org/task/64398 https://bugs.archlinux.org/task/64413

Last edited by JonnyRobbie (2019-11-08 09:20:06)

b4m · 2019-11-10 12:49:09

Thank you guys for taking action. Same issues here on a Thinkpad T460s. I'm ignoring the update to dhcpcd 8.1.1-1 for now, like so:

pacman -Syu --ignore dhcpcd

Last edited by b4m (2019-11-10 12:49:37)

john_schaf · 2019-11-12 22:47:24

Hello,

Thank you for this thread, and all the useful comments. I have the same problem here.
It now appears to be fixed in dhcpcd 8.1.1-2

hexhu · 2019-11-13 03:11:36

Resolved with dhcpcd 8.1.1-2, changes: https://git.archlinux.org/svntogit/pack … caebd13e54

Arch Linux

#1 2019-11-01 10:32:42

dhcpcd causing high cpu usage

#2 2019-11-01 10:41:53

Re: dhcpcd causing high cpu usage

#3 2019-11-01 12:13:50

Re: dhcpcd causing high cpu usage

#4 2019-11-01 12:31:10

Re: dhcpcd causing high cpu usage

#5 2019-11-01 14:47:22

Re: dhcpcd causing high cpu usage

#6 2019-11-02 10:49:49

Re: dhcpcd causing high cpu usage

#7 2019-11-02 12:52:52

Re: dhcpcd causing high cpu usage

#8 2019-11-02 17:08:17

Re: dhcpcd causing high cpu usage

#9 2019-11-02 18:06:40

Re: dhcpcd causing high cpu usage

#10 2019-11-03 00:35:53

Re: dhcpcd causing high cpu usage

#11 2019-11-03 15:00:29

Re: dhcpcd causing high cpu usage

#12 2019-11-05 17:06:10

Re: dhcpcd causing high cpu usage

#13 2019-11-07 14:23:44

Re: dhcpcd causing high cpu usage

#14 2019-11-07 20:23:16

Re: dhcpcd causing high cpu usage

#15 2019-11-08 03:39:23

Re: dhcpcd causing high cpu usage

#16 2019-11-08 09:11:10

Re: dhcpcd causing high cpu usage

#17 2019-11-10 12:49:09

Re: dhcpcd causing high cpu usage

#18 2019-11-12 22:47:24

Re: dhcpcd causing high cpu usage

#19 2019-11-13 03:11:36

Re: dhcpcd causing high cpu usage

Board footer