snapd generating wakeup events, keeps CPU from being idle

[Colin Ian King]

I was analysing the Eoan desktop image to see where wakeup events are being generated and spotted that snapd was causing quite a few wakeups over a 30 minute period. I used health-check [1] to monitor the snapd activity to see timer events activity:

sudo apt install health-check
sudo health-check -p snapd -f -r -d 1800

There seems to be a nanosleep() system call that is generating ~0.35 sleep/wakeups per second which is the main contributing factor to the overall 1.37 context switches per second. Snapd is not exactly idle on an "idle" system. There are also some epoll_pwait() system calls being called with a zero timeout, so these look like non-blocking epoll peeks which may be eating more CPU time by polling instead of blocking waits.

Can these sleep/wakeups and polling epolls be investigated to make snapd be more power friendly?

See attached log for more details.

References:
[1] https://kernel.ubuntu.com/~cking/health-check/

[Daniel J Blueman (watchmaker)]

I have been finding snapd wakes up at ~12Hz, putting it among the top 10 kernel tasks and processes consuming energy under PowerTOP on an idle GNOME desktop, only GNOME terminal open.

I have been seeing the same behaviour since snapd was mandated; given no housekeeping is expected, these wakeups can most likely be avoided. On Ubuntu 21.10 on a Dell XPS 15:

PowerTOP v2.11 Overview Idle stats Frequency stats Device stats Tunables WakeUp

The battery reports a discharge rate of 5.27 W
The power consumed was 111 J
The estimated remaining time is 15 hours, 0 minutes

Summary: 157.6 wakeups/second, 0.0 GPU ops/seconds, 0.0 VFS ops/sec and 2.2% CPU use

Power est. Usage Events/s Category Description
...
 49.6 mW 4.2 ms/s 4.7 Process [PID 1966] /usr/bin/gnome-shell
 49.6 mW 194.8 µs/s 13.3 Process [PID 13] [rcu_sched]
 42.4 mW 135.1 µs/s 11.5 kWork psi_avgs_work
 42.2 mW 105.6 µs/s 11.5 Process [PID 888] /usr/lib/snapd/snapd

[Daniel J Blueman (watchmaker)]

strace while no snaps are open shows frequent messages being read from fd 4:

$ sudo strace -ffp $(pidof snapd)
[pid 5860] futex(0x55d25953e338, FUTEX_WAIT_PRIVATE, 0, {tv_sec=34, tv_nsec=89621} <unfinished ...>
[pid 5899] <... select resumed>) = 1 (in [4])
[pid 5899] futex(0x55d25953e338, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 5899] recvfrom(4, <unfinished ...>
[pid 5860] <... futex resumed>) = 0
[pid 5899] <... recvfrom resumed>[{prefix="libudev", magic=htonl(0xfeedcafe), header_size=40, properties_off=40, properties_len=370, filter_subsystem_hash=htonl(0xc370b302), filter_devtype_hash=htonl(0), filter_tag_bloom_hi=htonl(0x2080400), filter_tag_bloom_lo=htonl(0x10c00001)}, "ACTION=change\0DEVPATH=/devices/p"...], 4096, MSG_PEEK, {sa_family=AF_NETLINK, nl_pid=429, nl_groups=0x000002}, [112 => 12]) = 410
[pid 5860] nanosleep({tv_sec=0, tv_nsec=20000}, <unfinished ...>
[pid 5899] recvfrom(4, [{prefix="libudev", magic=htonl(0xfeedcafe), header_size=40, properties_off=40, properties_len=370, filter_subsystem_hash=htonl(0xc370b302), filter_devtype_hash=htonl(0), filter_tag_bloom_hi=htonl(0x2080400), filter_tag_bloom_lo=htonl(0x10c00001)}, "ACTION=change\0DEVPATH=/devices/p"...], 4096, 0, {sa_family=AF_NETLINK, nl_pid=429, nl_groups=0x000002}, [112 => 12]) = 410
[pid 5860] <... nanosleep resumed>NULL) = 0
[pid 5899] fcntl(10, F_GETFL) = 0 (flags O_RDONLY)
[pid 5899] fcntl(10, F_SETFL, O_RDONLY) = 0
[pid 5899] select(11, [4 10], NULL, NULL, NULL <unfinished ...>
[pid 5860] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 5860] futex(0x55d25953e338, FUTEX_WAIT_PRIVATE, 0, {tv_sec=25, tv_nsec=990469943}

(and similar, repeating)

File descriptor 4 corresponds to a kernel netlink socket:

$ lsof -p $(pidof snapd)
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
...
snapd 5859 root 4u netlink 0t0 68137 KOBJECT_UEVENT

[Daniel J Blueman (watchmaker)]

For this Dell XPS 9510, there is an ambient light sensor, which continuously adjusts the screen brightness via DBus - these events are not being filtered by snapd; the filtering should be improved accordingly.

[Maciej Borzecki (maciek-borzecki)]

@watchmaker any chance you could run `udevadm monitor` and collect the log with events?

snapd monitors udev device changes with filter set SUBSYSTEM == "usb" || SUBSYSTEM == "tty" || SUBSYSTEM == "net".