systemd-udevd takes high CPU on CoreOS stable v835.9.0 #1036

ntquyen · 2015-12-15T07:18:38Z

After upgraded to v835.9.0 stable there are a lot of systemd-udevd taking very high CPU that make the OS slow performing

System log error related to systemd-udevd:

$ dmesg
...
systemd-udevd[57033]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
...

I'm using CoreOS stable v835.9.0 with kubelet running v1.0.1

The text was updated successfully, but these errors were encountered:

mischief · 2015-12-15T23:34:55Z

can you provide a full log of systemd-udevd?

journalctl -b -u systemd-udevd.service

ntquyen · 2015-12-16T02:32:27Z

Here you go:

$ sudo journalctl -b -u systemd-udevd.service

-- Logs begin at Sun 2015-12-13 05:13:50 UTC, end at Wed 2015-12-16 02:30:35 UTC. --
Dec 15 02:44:40 localhost systemd[1]: Starting udev Kernel Device Manager...
Dec 15 02:44:40 localhost systemd-udevd[228]: RUN{builtin}: 'uaccess' unknown /usr/lib64/udev/rules.d/73-seat-late.rules:15
Dec 15 02:44:40 localhost systemd[1]: Started udev Kernel Device Manager.
Dec 15 02:44:41 localhost systemd-udevd[228]: RUN{builtin}: 'uaccess' unknown /usr/lib64/udev/rules.d/73-seat-late.rules:15
Dec 15 02:46:37 localhost systemd-udevd[275]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:46:40 localhost systemd-udevd[285]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:46:40 localhost systemd-udevd[285]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:46:40 localhost systemd-udevd[285]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:46:42 localhost systemd-udevd[295]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:46:42 localhost systemd-udevd[295]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:46:47 localhost systemd-udevd[1405]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:46:47 localhost systemd-udevd[1405]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:46:48 localhost systemd[1]: Stopping udev Kernel Device Manager...
Dec 15 02:46:48 localhost systemd[1]: Stopped udev Kernel Device Manager.
Dec 15 02:47:01 dev-coreos-k8s_01 systemd-udevd[1713]: RUN{builtin}: 'uaccess' unknown /usr/lib64/udev/rules.d/73-seat-late.rules:15
Dec 15 02:47:02 dev-coreos-k8s_01 systemd-udevd[1713]: RUN{builtin}: 'uaccess' unknown /usr/lib64/udev/rules.d/73-seat-late.rules:15
Dec 15 02:47:11 dev-coreos-k8s_01 systemd-udevd[1743]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:47:11 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:47:16 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:47:16 dev-coreos-k8s_01 systemd-udevd[1743]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:47:16 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:47:16 dev-coreos-k8s_01 systemd-udevd[1743]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:47:16 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:47:17 dev-coreos-k8s_01 systemd-udevd[1743]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:47:17 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:47:18 dev-coreos-k8s_01 systemd-udevd[1743]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:47:18 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:47:23 dev-coreos-k8s_01 systemd-udevd[1743]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:47:23 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:47:32 dev-coreos-k8s_01 systemd-udevd[1743]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:47:32 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:47:32 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:47:34 dev-coreos-k8s_01 systemd-udevd[1743]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:47:34 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:47:36 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:47:41 dev-coreos-k8s_01 systemd-udevd[1743]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:47:41 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
Dec 15 02:47:43 dev-coreos-k8s_01 systemd-udevd[1743]: setting mode of /dev/vmbus/hv_vss to 020600 failed: No such file or directory
Dec 15 02:47:43 dev-coreos-k8s_01 systemd-udevd[1743]: setting owner of /dev/vmbus/hv_vss to uid=0, gid=0 failed: No such file or directory
...

mischief · 2015-12-16T02:36:56Z

@ntquyen what platform are you on? if possible, can you reproduce this in CoreOS alpha (891.0.0)?

ntquyen · 2015-12-16T02:44:12Z

I'm using CoreOS inside our in-house data center. I had this issue before with alpha versions prior to 891.0.0 (3 months ago). This issue is gone when I switched to v773.1.0 stable. But then stable version upgraded to v835.9.0 and I got this issue again

vcaputo · 2015-12-16T22:54:46Z

@ntquyen When you're watching top on one of these malfunctioning systems, do you observe a constant churn of systemd-udevd processes? It should be visible by watching the PID values of the systemd-udevd processes. If they're continuously increasing then the answer is yes.

I'd just like to know if there's a finite set of long-running systemd-udevd processes burning cpu, or if there's a continuous stream of short-lived systemd-udevd processes being created by the main systemd-udevd process.

systemd-udevd has a multiprocess execution model, but the new processes are forked in response to events, so this may be just a consequence of systemd-udevd getting flooded with events. The command udevadm monitor may also help shed some light on this.

Additionally, running systemd-udevd with --debug may help shed some light on what's going on, if udevadm monitor isn't helpful.

ntquyen · 2015-12-18T10:04:59Z

Thanks @vcaputo for you debug instructions! I will check at let you know.

ntquyen · 2015-12-21T07:23:42Z

The PIDs of systemd-udevd processes are constant, they are not increasing.

core@dev-coreos-k8s_02 ~ $ ps aux | grep systemd-udevd
root      1686 72.9  1.0  73712 39740 ?        Rs   Dec17 4399:57 /usr/lib/systemd/systemd-udevd
root      1897 10.6  0.3  59648 12864 ?        R    Dec17 643:16 /usr/lib/systemd/systemd-udevd
root      1898  0.0  0.0  59648  2188 ?        S    Dec17   0:00 /usr/lib/systemd/systemd-udevd
root      1899  0.0  0.0  59648  2556 ?        S    Dec17   0:00 /usr/lib/systemd/systemd-udevd
root      1900  0.3  0.5  59648 23492 ?        S    Dec17  24:03 /usr/lib/systemd/systemd-udevd
root      1901  0.0  0.5  59648 23364 ?        S    Dec17   0:15 /usr/lib/systemd/systemd-udevd
root      1902  0.0  0.0  59648  3120 ?        S    Dec17   0:01 /usr/lib/systemd/systemd-udevd
root      1906  7.1  0.5  59648 23492 ?        S    Dec17 428:20 /usr/lib/systemd/systemd-udevd
root      1907  0.0  0.5  59648 23492 ?        S    Dec17   5:09 /usr/lib/systemd/systemd-udevd
root      1908  0.0  0.3  59648 13276 ?        S    Dec17   0:00 /usr/lib/systemd/systemd-udevd
root      1909  0.0  0.0  59648  2164 ?        S    Dec17   0:00 /usr/lib/systemd/systemd-udevd
root      1910  0.0  0.5  59780 23368 ?        S    Dec17   1:07 /usr/lib/systemd/systemd-udevd
root      1911  0.0  0.5  59780 23376 ?        S    Dec17   0:00 /usr/lib/systemd/systemd-udevd
root      2954  1.4  0.0  66344  2632 ?        S    Dec17  83:03 /usr/lib/systemd/systemd-udevd
root     17692  4.0  0.5  69412 22884 ?        S    Dec17 241:51 /usr/lib/systemd/systemd-udevd
root     60802  0.0  0.0  63160  2164 ?        S    Dec17   0:00 /usr/lib/systemd/systemd-udevd
root     60804  0.0  0.0  60784  2568 ?        S    Dec17   0:02 /usr/lib/systemd/systemd-udevd

The command udevadm monitor print repeatedly a series of log:

core@dev-coreos-k8s_02 ~ $ systemctl status systemd-udevd
...
KERNEL[362225.203383] remove   /devices/virtual/misc/vmbus!hv_vss (misc)
UDEV  [362225.203424] add      /devices/virtual/misc/vmbus!hv_vss (misc)
KERNEL[362225.203511] remove   /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/vmbus_102964226 (vmbus)
KERNEL[362225.203929] add      /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/vmbus_102964227 (vmbus)
UDEV  [362225.204314] remove   /devices/virtual/misc/vmbus!hv_vss (misc)
UDEV  [362225.206125] add      /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/vmbus_102850814 (vmbus)
KERNEL[362225.206678] add      /devices/virtual/misc/vmbus!hv_vss (misc)
UDEV  [362225.207461] add      /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/vmbus_102850815 (vmbus)
KERNEL[362225.207603] remove   /devices/virtual/misc/vmbus!hv_vss (misc)
KERNEL[362225.207648] remove   /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/vmbus_102964227 (vmbus)
KERNEL[362225.208236] add      /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/vmbus_102964228 (vmbus)
KERNEL[362225.208397] add      /devices/virtual/misc/vmbus!hv_vss (misc)
UDEV  [362225.209317] remove   /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/vmbus_102850814 (vmbus)
UDEV  [362225.209941] remove   /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/vmbus_102850815 (vmbus)
KERNEL[362225.210097] remove   /devices/virtual/misc/vmbus!hv_vss (misc)
KERNEL[362225.210164] remove   /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/vmbus_102964228 (vmbus)
UDEV  [362225.210431] add      /devices/virtual/misc/vmbus!hv_vss (misc)
UDEV  [362225.210987] remove   /devices/virtual/misc/vmbus!hv_vss (misc)
...

I tried udevadm monitor in v773.1.0 which doesn't have this issue:

core@dev-coreos-k8s_03 ~ $ udevadm monitor
monitor will print the received events for:
UDEV - the event which udev sends out after rule processing
KERNEL - the kernel uevent

ntquyen · 2015-12-21T08:21:09Z

Running strace on one of the systemd-udevd processes, looks like it is looping:

core@dev-coreos-k8s_02 ~ $ sudo strace -fvvp 1686
Process 1686 attached
sendmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=-1279045853, groups=00000000}, msg_iov(2)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\321\0\0\0\0308\374\315\0\0\0\0"..., 40}, {"ACTION=add\0DEVPATH=/devices/LNXS"..., 209}], msg_controllen=0, msg_flags=0}, 0) = 249
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 17, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685795, 980578429}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 579203027}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 579251726}) = 0
recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"", 0}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=1906, uid=0, gid=0}}, msg_flags=0}, MSG_DONTWAIT) = 0
recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"", 0}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=1897, uid=0, gid=0}}, msg_flags=0}, MSG_DONTWAIT) = 0
recvmsg(7, 0x7fff0d47a290, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable)
sendmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=1686, groups=00000000}, msg_iov(2)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\243\0\0\0K\32Nu\0\0\0\0"..., 40}, {"ACTION=remove\0DEVPATH=/devices/v"..., 163}], msg_controllen=0, msg_flags=0}, 0) = 203
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 15, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685795, 985843143}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 584346542}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 584425141}) = 0
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 15, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685795, 986063240}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 584556239}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 584601638}) = 0
recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000001}, msg_iov(1)=[{"add@/devices/virtual/misc/vmbus!"..., 8192}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=0, uid=0, gid=0}}, msg_flags=0}, 0) = 164
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af0727a3e0, 0x5, 0x7f534078e858) = 0x10
clock_gettime(CLOCK_MONOTONIC, {366112, 584828734}) = 0
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af0692bbe0, 0x5, 0x7f534078e820) = 0x10
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af06461290, 0x5, 0x7f534078e7e8) = 0x10
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 15, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685795, 993953210}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 592917602}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 593379294}) = 0
recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"", 0}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=1897, uid=0, gid=0}}, msg_flags=0}, MSG_DONTWAIT) = 0
recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"", 0}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=2954, uid=0, gid=0}}, msg_flags=0}, MSG_DONTWAIT) = 0
recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"", 0}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=17692, uid=0, gid=0}}, msg_flags=0}, MSG_DONTWAIT) = 0
recvmsg(7, 0x7fff0d47a290, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable)
sendmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=1686, groups=00000000}, msg_iov(2)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\240\0\0\0K\32Nu\0\0\0\0"..., 40}, {"ACTION=add\0DEVPATH=/devices/virt"..., 160}], msg_controllen=0, msg_flags=0}, 0) = 200
sendmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=-1333008039, groups=00000000}, msg_iov(2)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\324\0\0\0\0308\374\315\0\0\0\0"..., 40}, {"ACTION=remove\0DEVPATH=/devices/L"..., 212}], msg_controllen=0, msg_flags=0}, 0) = 252
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 13, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685795, 998048843}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 596568042}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 596622541}) = 0
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 13, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685795, 998583535}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 597109833}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 597168032}) = 0
recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000001}, msg_iov(1)=[{"remove@/devices/virtual/misc/vmb"..., 8192}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=0, uid=0, gid=0}}, msg_flags=0}, 0) = 170
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af06a85c60, 0x5, 0x55af05eaebe0) = 0x10
clock_gettime(CLOCK_MONOTONIC, {366112, 597701824}) = 0
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af063b3e50, 0x5, 0x55af05eaeba8) = 0x10
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af05ed5390, 0x5, 0x55af05eaeb70) = 0x10
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 13, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685796, 1850481}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 600380780}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 600419879}) = 0
recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"", 0}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=1897, uid=0, gid=0}}, msg_flags=0}, MSG_DONTWAIT) = 0
recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"", 0}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=17692, uid=0, gid=0}}, msg_flags=0}, MSG_DONTWAIT) = 0
recvmsg(7, 0x7fff0d47a290, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable)
sendmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=1686, groups=00000000}, msg_iov(2)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\243\0\0\0K\32Nu\0\0\0\0"..., 40}, {"ACTION=remove\0DEVPATH=/devices/v"..., 163}], msg_controllen=0, msg_flags=0}, 0) = 203
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 11, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685796, 4212042}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 602761941}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 602814140}) = 0
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 11, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685796, 4459938}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 602971337}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 603040736}) = 0
recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000001}, msg_iov(1)=[{"remove@/devices/LNXSYSTM:00/LNXS"..., 8192}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=0, uid=0, gid=0}}, msg_flags=0}, 0) = 268
syscall_318(0x55af059d1930, 0x10, 0x1, 0, 0x5, 0x7f5342a87438) = 0x10
clock_gettime(CLOCK_MONOTONIC, {366112, 603511129}) = 0
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af073e3600, 0x5, 0x7f5342a87400) = 0x10
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af0780e0d0, 0x5, 0x7f5342a873c8) = 0x10
sendmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=-1333008039, groups=00000000}, msg_iov(2)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\324\0\0\0\0308\374\315\0\0\0\0"..., 40}, {"ACTION=remove\0DEVPATH=/devices/L"..., 212}], msg_controllen=0, msg_flags=0}, 0) = 252
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 13, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685796, 9337858}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 607847358}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 607915056}) = 0
recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"", 0}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=1897, uid=0, gid=0}}, msg_flags=0}, MSG_DONTWAIT) = 0
recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"", 0}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=17692, uid=0, gid=0}}, msg_flags=0}, MSG_DONTWAIT) = 0
recvmsg(7, 0x7fff0d47a290, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable)
sendmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=1686, groups=00000000}, msg_iov(2)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\240\0\0\0K\32Nu\0\0\0\0"..., 40}, {"ACTION=add\0DEVPATH=/devices/virt"..., 160}], msg_controllen=0, msg_flags=0}, 0) = 200
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}}, 11, 0) = 1
clock_gettime(CLOCK_REALTIME, {1450685796, 11322826}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 609829425}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 609879724}) = 0
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}}, 11, 0) = 1
clock_gettime(CLOCK_REALTIME, {1450685796, 11536822}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 610074521}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 610125920}) = 0
recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000001}, msg_iov(1)=[{"add@/devices/LNXSYSTM:00/LNXSYBU"..., 8192}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=0, uid=0, gid=0}}, msg_flags=0}, 0) = 262
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af05f9b5c0, 0x5, 0x7f5342a873c8) = 0x10
clock_gettime(CLOCK_MONOTONIC, {366112, 610453015}) = 0
syscall_318(0x55af059d1930, 0x10, 0x1, 0, 0x5, 0x7f5342a87400) = 0x10
syscall_318(0x55af059d1930, 0x10, 0x1, 0, 0x5, 0x7f5342a87438) = 0x10
sendmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=-1333008039, groups=00000000}, msg_iov(2)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\321\0\0\0\0308\374\315\0\0\0\0"..., 40}, {"ACTION=add\0DEVPATH=/devices/LNXS"..., 209}], msg_controllen=0, msg_flags=0}, 0) = 249
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}}, 13, 0) = 1
clock_gettime(CLOCK_REALTIME, {1450685796, 15509457}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 614039756}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 614091255}) = 0
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}}, 13, 0) = 1
clock_gettime(CLOCK_REALTIME, {1450685796, 15771553}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 614282152}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 614335451}) = 0
recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000001}, msg_iov(1)=[{"add@/devices/virtual/misc/vmbus!"..., 8192}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=0, uid=0, gid=0}}, msg_flags=0}, 0) = 164
syscall_318(0x55af059d1930, 0x10, 0x1, 0, 0x5, 0x55af05eba640) = 0x10
clock_gettime(CLOCK_MONOTONIC, {366112, 614576947}) = 0
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af05f2a3e0, 0x5, 0x55af05eba608) = 0x10
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af05fd0dc0, 0x5, 0x55af05eba5d0) = 0x10
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 13, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685796, 17155230}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 615732528}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 615800627}) = 0
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 13, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685796, 17477925}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 615991724}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 616140722}) = 0
recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000001}, msg_iov(1)=[{"remove@/devices/virtual/misc/vmb"..., 8192}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=0, uid=0, gid=0}}, msg_flags=0}, 0) = 170
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af066d3350, 0x5, 0x7f53429cdee8) = 0x10
clock_gettime(CLOCK_MONOTONIC, {366112, 616437917}) = 0
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af05eceed0, 0x5, 0x7f53429cdf20) = 0x10
syscall_318(0x55af059d1930, 0x10, 0x1, 0x55af069ad9e0, 0x5, 0x7f53429cdf58) = 0x10
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 13, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685796, 20259080}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 618767579}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 619048474}) = 0
recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"", 0}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=17692, uid=0, gid=0}}, msg_flags=0}, MSG_DONTWAIT) = 0
recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"", 0}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=1897, uid=0, gid=0}}, msg_flags=0}, MSG_DONTWAIT) = 0
recvmsg(7, 0x7fff0d47a290, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable)
sendmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=1686, groups=00000000}, msg_iov(2)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\243\0\0\0K\32Nu\0\0\0\0"..., 40}, {"ACTION=remove\0DEVPATH=/devices/v"..., 163}], msg_controllen=0, msg_flags=0}, 0) = 203
epoll_wait(10, {{EPOLLIN, {u32=97704288, u64=94210205342048}}, {EPOLLIN, {u32=97704528, u64=94210205342288}}}, 11, 0) = 2
clock_gettime(CLOCK_REALTIME, {1450685796, 22410644}) = 0
clock_gettime(CLOCK_MONOTONIC, {366112, 621149140}) = 0
clock_gettime(CLOCK_BOOTTIME, {366112, 621210139}) = 0
...
...
^CProcess 1686 detached

vcaputo · 2015-12-21T22:09:29Z

@ntquyen This doesn't appear to be a systemd-udevd bug, it looks like this virtual device is legitimately (from the systemd-udevd perspective) constantly being plugged/unplugged from the kernel, and systemd-udevd is simply responding to that.

Good news is you're not alone:
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1496927
http://www.linuxquestions.org/questions/fedora-35/high-cpu-load-from-systemd-udevd-under-hyper-v-after-kernel-update-4175561745/

Bad news is it doesn't appear to have been solved yet.

ntquyen · 2015-12-21T23:54:09Z

Thanks @vcaputo for the shared links! I'm running CoreOS in Hyper-V as well.. May be I'll rollback to v773.1.0 and wait for the bug fixed.

crawford · 2016-01-13T16:23:13Z

@ntquyen can you try the latest Alpha? We just bumped to the 4.4 kernel.

ntquyen · 2016-01-16T02:27:19Z

Thanks @crawford, I will try and let you know!

ntquyen · 2016-01-19T08:56:50Z

@crawford the latest alpha still has this issue.

crawford · 2016-01-19T15:17:16Z

OK. Thanks for testing. The Hyper-V guys are looking into this, so we'll see what they have to say.

ntquyen · 2016-03-22T06:32:27Z

This kernel bug has been fixed. Can't wait to see it in next alpha 😄
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1496927

mischief · 2016-03-22T07:20:53Z

torvalds/linux@ed9ba60 is currently only in linux v4.5. it is possible to backport it, though.

ntquyen · 2016-03-29T04:09:41Z

A much more simple solution: disabling Volume Snapshot for the VM in Hyper-V.

crawford · 2016-04-07T17:21:51Z

Should be fixed by coreos/coreos-overlay#1867.

mischief added reviewed/needs more information component/systemd labels Dec 15, 2015

ntquyen mentioned this issue Dec 16, 2015

systemd-udevd takes high CPU on CoreOS stable v835.9.0 paulshir/coreos-hyperv#11

Closed

crawford added team/os priority/P1 priority/P0 and removed priority/P1 labels Dec 17, 2015

mischief added this to the CoreOS 835.10.0 milestone Dec 17, 2015

crawford mentioned this issue Jan 7, 2016

Sometimes CoreOS 773.1.0 becomes unresponsive - cannot SSH #1063

Closed

crawford modified the milestones: CoreOS 835.10.0, CoreOS 877.2.0 Jan 12, 2016

crawford modified the milestones: CoreOS 877.2.0, CoreOS 877.3.0 Jan 13, 2016

crawford removed this from the CoreOS 877.3.0 milestone Jan 21, 2016

crawford closed this Apr 7, 2016

mhaberler mentioned this issue Apr 21, 2016

Terasic de0 nano SD image build incomplete machinekit/machinekit#915

Closed

coreos / bugs Archived

systemd-udevd takes high CPU on CoreOS stable v835.9.0 #1036

systemd-udevd takes high CPU on CoreOS stable v835.9.0 #1036

ntquyen commented Dec 15, 2015

mischief commented Dec 15, 2015

ntquyen commented Dec 16, 2015

mischief commented Dec 16, 2015

ntquyen commented Dec 16, 2015

vcaputo commented Dec 16, 2015

ntquyen commented Dec 18, 2015

ntquyen commented Dec 21, 2015

ntquyen commented Dec 21, 2015

vcaputo commented Dec 21, 2015

ntquyen commented Dec 21, 2015

crawford commented Jan 13, 2016

ntquyen commented Jan 16, 2016

ntquyen commented Jan 19, 2016

crawford commented Jan 19, 2016

ntquyen commented Mar 22, 2016

mischief commented Mar 22, 2016

ntquyen commented Mar 29, 2016

crawford commented Apr 7, 2016

coreos / bugs Archived

systemd-udevd takes high CPU on CoreOS stable v835.9.0 #1036

systemd-udevd takes high CPU on CoreOS stable v835.9.0 #1036

Comments

ntquyen commented Dec 15, 2015

mischief commented Dec 15, 2015

ntquyen commented Dec 16, 2015

mischief commented Dec 16, 2015

ntquyen commented Dec 16, 2015

vcaputo commented Dec 16, 2015

ntquyen commented Dec 18, 2015

ntquyen commented Dec 21, 2015

ntquyen commented Dec 21, 2015

vcaputo commented Dec 21, 2015

ntquyen commented Dec 21, 2015

crawford commented Jan 13, 2016

ntquyen commented Jan 16, 2016

ntquyen commented Jan 19, 2016

crawford commented Jan 19, 2016

ntquyen commented Mar 22, 2016

mischief commented Mar 22, 2016

ntquyen commented Mar 29, 2016

crawford commented Apr 7, 2016