Lxc list very slow on LXD 4.0

trumee · April 4, 2020, 1:16pm

Hello,

lxc list takes a long time after upgrading to LXD 4.0. I timed it,

# time lxc list
real    0m30.393s
user    0m0.149s
sys     0m0.102s

Here is the log

# journalctl -u snap.lxd.daemon -n 300
-- Logs begin at Sun 2020-02-16 14:03:32 IST, end at Sat 2020-04-04 19:08:59 IST. --
Mar 30 10:43:26 nas lxd.daemon[9680]: t=2020-03-30T10:43:26+0530 lvl=warn msg="Detected poll(POLLNVAL) event."
Mar 30 18:34:36 nas lxd.daemon[9680]: t=2020-03-30T18:34:36+0530 lvl=warn msg="Detected poll(POLLNVAL) event."
Mar 30 18:54:39 nas lxd.daemon[9680]: t=2020-03-30T18:54:39+0530 lvl=warn msg="Detected poll(POLLNVAL) event."
Mar 30 18:56:38 nas lxd.daemon[9680]: t=2020-03-30T18:56:38+0530 lvl=warn msg="Detected poll(POLLNVAL) event."
Mar 30 23:47:28 nas lxd.daemon[9680]: t=2020-03-30T23:47:28+0530 lvl=warn msg="Detected poll(POLLNVAL) event: exiting."
Mar 30 23:47:28 nas lxd.daemon[9680]: t=2020-03-30T23:47:28+0530 lvl=warn msg="Detected poll(POLLNVAL) event."
Mar 31 00:55:06 nas lxd.daemon[9680]: t=2020-03-31T00:55:06+0530 lvl=warn msg="Detected poll(POLLNVAL) event: exiting."
Mar 31 00:55:06 nas lxd.daemon[9680]: t=2020-03-31T00:55:06+0530 lvl=warn msg="Detected poll(POLLNVAL) event."
Mar 31 07:55:55 nas systemd[1]: Stopping Service for snap application lxd.daemon...
Mar 31 07:55:55 nas lxd.daemon[2285827]: => Stop reason is: snap refresh
Mar 31 07:55:55 nas lxd.daemon[2285827]: => Stopping LXD
Mar 31 07:55:56 nas lxd.daemon[9089]: => LXD exited cleanly
Mar 31 07:55:56 nas systemd[1]: snap.lxd.daemon.service: Succeeded.
Mar 31 07:55:56 nas systemd[1]: Stopped Service for snap application lxd.daemon.
Mar 31 07:56:04 nas systemd[1]: Started Service for snap application lxd.daemon.
Mar 31 07:56:04 nas lxd.daemon[2290059]: => Preparing the system (14133)
Mar 31 07:56:04 nas lxd.daemon[2290059]: ==> Loading snap configuration
Mar 31 07:56:04 nas lxd.daemon[2290059]: ==> Setting up mntns symlink (mnt:[4026534980])
Mar 31 07:56:04 nas lxd.daemon[2290059]: ==> Setting up mount propagation on /var/snap/lxd/common/lxd/devices
Mar 31 07:56:04 nas lxd.daemon[2290059]: ==> Setting up persistent shmounts path
Mar 31 07:56:04 nas lxd.daemon[2290059]: ==> Setting up kmod wrapper
Mar 31 07:56:04 nas lxd.daemon[2290059]: ==> Preparing /boot
Mar 31 07:56:04 nas lxd.daemon[2290059]: ==> Preparing a clean copy of /run
Mar 31 07:56:04 nas lxd.daemon[2290059]: ==> Preparing a clean copy of /etc
Mar 31 07:56:05 nas lxd.daemon[2290059]: ==> Setting up ceph configuration
Mar 31 07:56:05 nas lxd.daemon[2290059]: ==> Setting up LVM configuration
Mar 31 07:56:05 nas lxd.daemon[2290059]: ==> Rotating logs
Mar 31 07:56:05 nas lxd.daemon[2290059]: ==> Setting up ZFS (0.8)
Mar 31 07:56:05 nas lxd.daemon[2290059]: ==> Escaping the systemd cgroups
Mar 31 07:56:05 nas lxd.daemon[2290059]: ====> Detected cgroup V1
Mar 31 07:56:05 nas lxd.daemon[2290059]: ==> Escaping the systemd process resource limits
Mar 31 07:56:05 nas lxd.daemon[2290059]: ==> Disabling shiftfs on this kernel (auto)
Mar 31 07:56:05 nas lxd.daemon[2290059]: => Re-using existing LXCFS
Mar 31 07:56:05 nas lxd.daemon[9673]: Closed liblxcfs.so
Mar 31 07:56:05 nas lxd.daemon[9673]: Running destructor lxcfs_exit
Mar 31 07:56:05 nas lxd.daemon[9673]: Running constructor lxcfs_init to reload liblxcfs
Mar 31 07:56:05 nas lxd.daemon[2290059]: => Starting LXD
Mar 31 07:56:05 nas lxd.daemon[2290898]: t=2020-03-31T07:56:05+0530 lvl=warn msg="AppArmor support has been disabled because of lack of kernel support"
Mar 31 07:56:05 nas lxd.daemon[2290898]: t=2020-03-31T07:56:05+0530 lvl=warn msg=" - Couldn't find the CGroup blkio.weight, I/O weight limits will be ignored"
Mar 31 07:56:06 nas lxd.daemon[9673]: mount namespace: 5
Mar 31 07:56:06 nas lxd.daemon[9673]: hierarchies:
Mar 31 07:56:06 nas lxd.daemon[9673]:   0: fd:   6:
Mar 31 07:56:06 nas lxd.daemon[9673]:   1: fd:   7: name=systemd
Mar 31 07:56:06 nas lxd.daemon[9673]:   2: fd:   8: memory
Mar 31 07:56:06 nas lxd.daemon[9673]:   3: fd:   9: rdma
Mar 31 07:56:06 nas lxd.daemon[9673]:   4: fd:  10: net_cls,net_prio
Mar 31 07:56:06 nas lxd.daemon[9673]:   5: fd:  11: cpu,cpuacct
Mar 31 07:56:06 nas lxd.daemon[9673]:   6: fd:  12: devices
Mar 31 07:56:06 nas lxd.daemon[9673]:   7: fd:  13: perf_event
Mar 31 07:56:06 nas lxd.daemon[9673]:   8: fd:  14: freezer
Mar 31 07:56:06 nas lxd.daemon[9673]:   9: fd:  15: pids
...skipping...
Apr 04 08:20:21 nas lxd.daemon[17101]: ==> Setting up kmod wrapper
Apr 04 08:20:21 nas lxd.daemon[17101]: ==> Preparing /boot
Apr 04 08:20:21 nas lxd.daemon[17101]: ==> Preparing a clean copy of /run
Apr 04 08:20:21 nas lxd.daemon[17101]: ==> Preparing a clean copy of /etc
Apr 04 08:20:22 nas lxd.daemon[17101]: ==> Setting up ceph configuration
Apr 04 08:20:22 nas lxd.daemon[17101]: ==> Setting up LVM configuration
Apr 04 08:20:22 nas lxd.daemon[17101]: ==> Rotating logs
Apr 04 08:20:22 nas lxd.daemon[17101]: ==> Setting up ZFS (0.8)
Apr 04 08:20:22 nas lxd.daemon[17101]: ==> Escaping the systemd cgroups
Apr 04 08:20:22 nas lxd.daemon[17101]: ====> Detected cgroup V1
Apr 04 08:20:22 nas lxd.daemon[17101]: ==> Escaping the systemd process resource limits
Apr 04 08:20:22 nas lxd.daemon[17101]: ==> Disabling shiftfs on this kernel (auto)
Apr 04 08:20:22 nas lxd.daemon[17101]: => Starting LXCFS
Apr 04 08:20:22 nas lxd.daemon[17703]: Running constructor lxcfs_init to reload liblxcfs
Apr 04 08:20:22 nas lxd.daemon[17703]: mount namespace: 4
Apr 04 08:20:22 nas lxd.daemon[17703]: hierarchies:
Apr 04 08:20:22 nas lxd.daemon[17703]:   0: fd:   5:
Apr 04 08:20:22 nas lxd.daemon[17703]:   1: fd:   6: name=systemd
Apr 04 08:20:22 nas lxd.daemon[17703]:   2: fd:   7: cpu,cpuacct
Apr 04 08:20:22 nas lxd.daemon[17703]:   3: fd:   8: hugetlb
Apr 04 08:20:22 nas lxd.daemon[17703]:   4: fd:   9: cpuset
Apr 04 08:20:22 nas lxd.daemon[17703]:   5: fd:  10: perf_event
Apr 04 08:20:22 nas lxd.daemon[17703]:   6: fd:  11: pids
Apr 04 08:20:22 nas lxd.daemon[17703]:   7: fd:  12: blkio
Apr 04 08:20:22 nas lxd.daemon[17703]:   8: fd:  13: net_cls,net_prio
Apr 04 08:20:22 nas lxd.daemon[17703]:   9: fd:  14: devices
Apr 04 08:20:22 nas lxd.daemon[17703]:  10: fd:  15: freezer
Apr 04 08:20:22 nas lxd.daemon[17703]:  11: fd:  16: memory
Apr 04 08:20:22 nas lxd.daemon[17703]:  12: fd:  17: rdma
Apr 04 08:20:22 nas lxd.daemon[17703]: Kernel supports pidfds
Apr 04 08:20:22 nas lxd.daemon[17703]: api_extensions:
Apr 04 08:20:22 nas lxd.daemon[17703]: - cgroups
Apr 04 08:20:22 nas lxd.daemon[17703]: - sys_cpu_online
Apr 04 08:20:22 nas lxd.daemon[17703]: - proc_cpuinfo
Apr 04 08:20:22 nas lxd.daemon[17703]: - proc_diskstats
Apr 04 08:20:22 nas lxd.daemon[17703]: - proc_loadavg
Apr 04 08:20:22 nas lxd.daemon[17703]: - proc_meminfo
Apr 04 08:20:22 nas lxd.daemon[17703]: - proc_stat
Apr 04 08:20:22 nas lxd.daemon[17703]: - proc_swaps
Apr 04 08:20:22 nas lxd.daemon[17703]: - proc_uptime
Apr 04 08:20:22 nas lxd.daemon[17703]: - shared_pidns
Apr 04 08:20:22 nas lxd.daemon[17703]: - cpuview_daemon
Apr 04 08:20:22 nas lxd.daemon[17703]: - loadavg_daemon
Apr 04 08:20:22 nas lxd.daemon[17703]: - pidfds
Apr 04 08:20:22 nas lxd.daemon[17101]: => Starting LXD
Apr 04 08:20:22 nas lxd.daemon[17721]: t=2020-04-04T08:20:22+0530 lvl=warn msg="AppArmor support has been disabled because of lack of kernel support"
Apr 04 08:20:22 nas lxd.daemon[17721]: t=2020-04-04T08:20:22+0530 lvl=warn msg=" - Couldn't find the CGroup blkio.weight, I/O weight limits will be ignored"
Apr 04 08:22:11 nas lxd.daemon[17101]: => LXD is ready
Apr 04 10:41:57 nas lxd.daemon[17721]: t=2020-04-04T10:41:57+0530 lvl=warn msg="Detected poll(POLLNVAL) event."
Apr 04 11:09:00 nas lxd.daemon[17721]: 2020/04/04 11:09:00 http: superfluous response.WriteHeader call from github.com/lxc/lxd/lxd/response.(*errorResponse).Render (response.go:224)
Apr 04 15:20:17 nas lxd.daemon[17721]: 2020/04/04 15:20:17 http: superfluous response.WriteHeader call from github.com/lxc/lxd/lxd/response.(*errorResponse).Render (response.go:224)
Apr 04 18:40:13 nas lxd.daemon[17721]: 2020/04/04 18:40:13 http: superfluous response.WriteHeader call from github.com/lxc/lxd/lxd/response.(*errorResponse).Render (response.go:224)

Any idea why this is so?

tomp · April 4, 2020, 6:09pm

You’re most likely being affected by this issue https://github.com/lxc/lxd/issues/7124

Its fixed already and will likely be cherry picked into the snap by @stgraber soon.

stgraber · April 4, 2020, 6:18pm

It’s currently sitting in candidate, we don’t do snap releases over weekends so it’ll hit stable on Monday.

trumee · April 4, 2020, 6:58pm

Thanks, that looks like it. Doing a ‘lxc list --fast’ is pretty quick.

stgraber · April 4, 2020, 7:01pm

You could do snap refresh lxd --candidate to see if the fix we’re rolling out on Monday will improve normal lxc list for you.

You can just snap refresh lxd --stable afterwards as there is no database changes between those two versions.

trumee · April 4, 2020, 8:24pm

Thanks, the fix is working fine.

$ time lxc list
real    0m0.378s
user    0m0.070s
sys     0m0.075s

stgraber · April 4, 2020, 9:15pm

Excellent, thanks for testing.