lvm2: vgcfgbackup in postinst takes several minutes

[Steve Beattie]

The postinst for lvm2 includes a call to vgcfgbackup; in the version included in eoan 2.03.02-2ubuntu4 (and 2.03.02-2ubuntu3 before it), this command takes several minutes to run when invoked in an schroot as happens when a building a package with sbuild that ends up pulling lvm2 as part of its build dependency chain. An example package with lvm2 in its build depends is rsnapshot, but this behavior was seen with a build of glibc. Some notes:

  - this behavior is NOT seen with the version of lvm2 in disco.
  - this happens in bionic with a 4.15 kernel and disco with a 5.0 kernel (different hosts, so different sets of block devices)
  - this happens regardless of whether the host is currently using logical volumes or not

Here's the time difference between running the disco version and the eoan version:

(disco-amd64)root@HOSTNAME:~# time vgcfgbackup
  WARNING: Failed to connect to lvmetad. Falling back to device scanning.

real 0m0.204s
user 0m0.014s
sys 0m0.010s

(eoan-amd64)root@HOSTNAME:~# time vgcfgbackup
  WARNING: Device /dev/sda not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda2 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda3 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdb not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdb1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdb2 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdb3 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdc not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdc1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdd not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdd1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sde not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sde1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sde2 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda2 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda3 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdb1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdb2 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdb3 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdc1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdd1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sde1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sde2 not initialized in udev database even after waiting 10000000 microseconds.

real 4m11.405s
user 0m0.470s
sys 0m0.576s

/proc/mounts in the schroot:

(eoan-amd64)root@HOSTNAME:~# cat /proc/mounts
eoan-amd64 / overlay rw,relatime,lowerdir=/var/lib/schroot/union/underlay/eoan-amd64-29c7f791-9409-4505-9192-7c4685b8be34,upperdir=/srv/devel/schroot-overlays/eoan-amd64-29c7f791-9409-4505-9192-7c4685b8be34/upper,workdir=/srv/devel/schroot-overlays/eoan-amd64-29c7f791-9409-4505-9192-7c4685b8be34/work 0 0
proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
sysfs /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0
udev /dev devtmpfs rw,nosuid,relatime,size=10197712k,nr_inodes=2549428,mode=755 0 0
devpts /dev/pts devpts rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000 0 0
/dev/sda2 /home ext4 rw,relatime,errors=remount-ro,data=ordered 0 0
/dev/sda2 /tmp ext4 rw,relatime,errors=remount-ro,data=ordered 0 0
tmpfs /run/shm tmpfs rw,relatime 0 0
/dev/sda2 /scratch ext4 rw,relatime,errors=remount-ro,data=ordered 0 0
/dev/sdc1 /srv/work ext4 rw,relatime,errors=remount-ro,data=ordered 0 0

strace of vgcfgbackup is attached

[Brian Murray (brian-murray)]

I tested this on an virtual machine running Eoan and did not notice vgcfgbackup taking as much time as it doesn in an schroot.

bdmurray@clean-eoan-amd64:~$ sudo time vgcfgbackup
0.00user 0.00system 0:00.02elapsed 37%CPU (0avgtext+0avgdata 10848maxresident)k
3584inputs+0outputs (0major+1411minor)pagefaults 0swaps

[Łukasz Zemczak (sil2100)]

I did a quick test with a test package to check if launchpad builders would be affected by this delay on Eoan and did not notice any additional delays. Overall build time of the test package was always below 3 minutes, the lvm2 build-dependency seemed to happen in normal time and a call to `time vgcfgbackup` during package build resulted in the following times:

0.00user 0.00system 0:00.04elapsed 27%CPU (0avgtext+0avgdata 9336maxresident)k
0inputs+0outputs (0major+964minor)pagefaults 0swaps