Clone from VM Template takes a long time.

[mazerR]

When I do a full clone of a VM Template it takes anywhere from 25-60 minutes to complete. When I check iotop it looks like the actual copy is finished within a minute of two and the disk usage falls back to idle but the VM takes another 20+ minutes to complete the clone. I don't see anything that stands out to me in journalctl. Is there something I'm missing? Is there something wrong or a setting I can change to reduce the clone time?

VM Template Settings
Memory: 2GB
Processor: 4c1s
Hard Disk: size 32G, ssd=1, discard=1, iothread=1
QEMU Guest Agent: Enabled

journalctl during the clone

May 08 13:00:42 runner-dev pvedaemon[580784]: <root@pam> starting task UPID:runner-dev:000902FE:0192FEC4:645946DA:qmclone:100:root@pam:
May 08 13:00:44 runner-dev pvedaemon[583090]: <root@pam> starting task UPID:runner-dev:0009032F:0192FF8E:645946DC:vncshell::root@pam:
May 08 13:00:44 runner-dev pvedaemon[590639]: starting termproxy UPID:runner-dev:0009032F:0192FF8E:645946DC:vncshell::root@pam:
May 08 13:00:45 runner-dev pvedaemon[580784]: <root@pam> successful auth for user 'root@pam'
May 08 13:00:45 runner-dev login[590644]: pam_unix(login:session): session opened for user root(uid=0) by root(uid=0)
May 08 13:00:45 runner-dev systemd[1]: Created slice User Slice of UID 0.
May 08 13:00:45 runner-dev systemd[1]: Starting User Runtime Directory /run/user/0...
May 08 13:00:45 runner-dev systemd-logind[1171]: New session 91 of user root.
May 08 13:00:45 runner-dev systemd[1]: Finished User Runtime Directory /run/user/0.
May 08 13:00:45 runner-dev systemd[1]: Starting User Manager for UID 0...
May 08 13:00:45 runner-dev systemd[590650]: pam_unix(systemd-user:session): session opened for user root(uid=0) by (uid=0)
May 08 13:00:45 runner-dev systemd[590650]: Queued start job for default target Main User Target.
May 08 13:00:45 runner-dev systemd[590650]: Created slice User Application Slice.
May 08 13:00:45 runner-dev systemd[590650]: Reached target Paths.
May 08 13:00:45 runner-dev systemd[590650]: Reached target Timers.
May 08 13:00:45 runner-dev systemd[590650]: Listening on GnuPG network certificate management daemon.
May 08 13:00:45 runner-dev systemd[590650]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
May 08 13:00:45 runner-dev systemd[590650]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
May 08 13:00:45 runner-dev systemd[590650]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
May 08 13:00:45 runner-dev systemd[590650]: Listening on GnuPG cryptographic agent and passphrase cache.
May 08 13:00:45 runner-dev systemd[590650]: Reached target Sockets.
May 08 13:00:45 runner-dev systemd[590650]: Reached target Basic System.
May 08 13:00:45 runner-dev systemd[590650]: Reached target Main User Target.
May 08 13:00:45 runner-dev systemd[590650]: Startup finished in 75ms.
May 08 13:00:45 runner-dev systemd[1]: Started User Manager for UID 0.
May 08 13:00:45 runner-dev systemd[1]: Started Session 91 of user root.
May 08 13:00:45 runner-dev login[590664]: ROOT LOGIN  on '/dev/pts/0'
May 08 13:01:01 runner-dev cron[1492]: (*system*vzdump) RELOAD (/etc/cron.d/vzdump)
May 08 13:08:31 runner-dev pvedaemon[583090]: <root@pam> successful auth for user 'root@pam'
May 08 13:08:31 runner-dev pveproxy[1536]: worker 586382 finished
May 08 13:08:31 runner-dev pveproxy[1536]: starting 1 worker(s)
May 08 13:08:31 runner-dev pveproxy[1536]: worker 591829 started
May 08 13:08:35 runner-dev pveproxy[591828]: got inotify poll request in wrong process - disabling inotify
May 08 13:12:15 runner-dev pveproxy[587811]: worker exit
May 08 13:12:15 runner-dev pveproxy[1536]: worker 587811 finished
May 08 13:12:15 runner-dev pveproxy[1536]: starting 1 worker(s)
May 08 13:12:15 runner-dev pveproxy[1536]: worker 592334 started
May 08 13:17:01 runner-dev CRON[592964]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
May 08 13:17:01 runner-dev CRON[592965]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
May 08 13:17:01 runner-dev CRON[592964]: pam_unix(cron:session): session closed for user root
May 08 13:22:01 runner-dev pveproxy[591829]: worker exit
May 08 13:22:01 runner-dev pveproxy[1536]: worker 591829 finished
May 08 13:22:01 runner-dev pveproxy[1536]: starting 1 worker(s)
May 08 13:22:01 runner-dev pveproxy[1536]: worker 593633 started
May 08 13:23:31 runner-dev pvedaemon[580766]: <root@pam> successful auth for user 'root@pam'
May 08 13:28:14 runner-dev pvedaemon[580784]: <root@pam> end task UPID:runner-dev:000902FE:0192FEC4:645946DA:qmclone:100:root@pam: OK

 

[fiona]

Hi,
please post the output of pveversion -v, the template configuration with qm config <ID> and the full task log for a clone operation. What kind of storages are the source and target storages of the operation?

 

[mazerR]

Hi,
please post the output of pveversion -v, the template configuration with qm config <ID> and the full task log for a clone operation. What kind of storages are the source and target storages of the operation?

Thanks for the Response! The disk is a PNY CS900 960GB SSD, which is the boot disk and the source/destination of the VMs.

proxmox-ve: 7.4-1 (running kernel: 5.15.107-1-pve)
pve-manager: 7.4-3 (running version: 7.4-3/9002ab8a)
pve-kernel-5.15: 7.4-2
pve-kernel-5.15.107-1-pve: 5.15.107-1
pve-kernel-5.15.102-1-pve: 5.15.102-1
ceph-fuse: 15.2.17-pve1
corosync: 3.1.7-pve1
criu: 3.15-1+pve-1
glusterfs-client: 9.2-1
ifupdown2: 3.1.0-1+pmx3
ksm-control-daemon: 1.4-1
libjs-extjs: 7.0.0-1
libknet1: 1.24-pve2
libproxmox-acme-perl: 1.4.4
libproxmox-backup-qemu0: 1.3.1-1
libproxmox-rs-perl: 0.2.1
libpve-access-control: 7.4-2
libpve-apiclient-perl: 3.2-1
libpve-common-perl: 7.3-4
libpve-guest-common-perl: 4.2-4
libpve-http-server-perl: 4.2-3
libpve-rs-perl: 0.7.5
libpve-storage-perl: 7.4-2
libspice-server1: 0.14.3-2.1
lvm2: 2.03.11-2.1
lxc-pve: 5.0.2-2
lxcfs: 5.0.3-pve1
novnc-pve: 1.4.0-1
proxmox-backup-client: 2.4.1-1
proxmox-backup-file-restore: 2.4.1-1
proxmox-kernel-helper: 7.4-1
proxmox-mail-forward: 0.1.1-1
proxmox-mini-journalreader: 1.3-1
proxmox-widget-toolkit: 3.6.5
pve-cluster: 7.3-3
pve-container: 4.4-3
pve-docs: 7.4-2
pve-edk2-firmware: 3.20230228-2
pve-firewall: 4.3-1
pve-firmware: 3.6-5
pve-ha-manager: 3.6.1
pve-i18n: 2.12-1
pve-qemu-kvm: 7.2.0-8
pve-xtermjs: 4.16.0-1
qemu-server: 7.4-3
smartmontools: 7.2-pve3
spiceterm: 3.2-2
swtpm: 0.8.0~bpo11+3
vncterm: 1.7-1
zfsutils-linux: 2.1.11-pve1

agent: 1
boot: order=scsi0;ide2;net0
cores: 4
ide2: local:iso/Rocky-8.7-x86_64-boot.iso,media=cdrom,size=870M
memory: 2048
meta: creation-qemu=7.2.0,ctime=1683230386
name: Rocky87Template
net0: virtio=4A:05:0B:D8:2F:3F,bridge=vmbr0,firewall=1,tag=6
numa: 0
ostype: l26
scsi0: local-lvm:base-100-disk-0,discard=on,iothread=1,size=32G,ssd=1
scsihw: virtio-scsi-single
smbios1: uuid=c9e48b3c-5591-44d4-80f0-5907a21bc521
sockets: 1
template: 1
vmgenid: e0cf73f1-65d8-41fc-85e9-75f9bcb9d9ea

create full clone of drive scsi0 (local-lvm:base-100-disk-0)
  Logical volume "vm-101-disk-0" created.
transferred 0.0 B of 32.0 GiB (0.00%)
transferred 327.7 MiB of 32.0 GiB (1.00%)
transferred 655.4 MiB of 32.0 GiB (2.00%)
transferred 983.0 MiB of 32.0 GiB (3.00%)
transferred 1.3 GiB of 32.0 GiB (4.00%)
transferred 1.6 GiB of 32.0 GiB (5.00%)
transferred 1.9 GiB of 32.0 GiB (6.01%)
transferred 2.2 GiB of 32.0 GiB (7.01%)
transferred 2.6 GiB of 32.0 GiB (8.01%)
transferred 2.9 GiB of 32.0 GiB (9.01%)
transferred 3.2 GiB of 32.0 GiB (10.01%)
transferred 3.5 GiB of 32.0 GiB (11.01%)
transferred 3.8 GiB of 32.0 GiB (12.01%)
transferred 4.2 GiB of 32.0 GiB (13.01%)
transferred 4.5 GiB of 32.0 GiB (14.01%)
transferred 4.8 GiB of 32.0 GiB (15.01%)
transferred 5.1 GiB of 32.0 GiB (16.02%)
transferred 5.4 GiB of 32.0 GiB (17.02%)
transferred 5.8 GiB of 32.0 GiB (18.02%)
transferred 6.1 GiB of 32.0 GiB (19.02%)
transferred 6.4 GiB of 32.0 GiB (20.02%)
transferred 6.7 GiB of 32.0 GiB (21.02%)
transferred 7.0 GiB of 32.0 GiB (22.02%)
transferred 7.4 GiB of 32.0 GiB (23.02%)
transferred 7.7 GiB of 32.0 GiB (24.02%)
transferred 8.0 GiB of 32.0 GiB (25.02%)
transferred 8.3 GiB of 32.0 GiB (26.03%)
transferred 8.6 GiB of 32.0 GiB (27.03%)
transferred 9.0 GiB of 32.0 GiB (28.03%)
transferred 9.3 GiB of 32.0 GiB (29.03%)
transferred 9.6 GiB of 32.0 GiB (30.03%)
transferred 9.9 GiB of 32.0 GiB (31.03%)
transferred 10.2 GiB of 32.0 GiB (32.03%)
transferred 10.6 GiB of 32.0 GiB (33.03%)
transferred 10.9 GiB of 32.0 GiB (34.03%)
transferred 11.2 GiB of 32.0 GiB (35.03%)
transferred 11.5 GiB of 32.0 GiB (36.04%)
transferred 11.9 GiB of 32.0 GiB (37.04%)
transferred 12.2 GiB of 32.0 GiB (38.04%)
transferred 12.5 GiB of 32.0 GiB (39.04%)
transferred 12.8 GiB of 32.0 GiB (40.04%)
transferred 13.1 GiB of 32.0 GiB (41.04%)
transferred 13.5 GiB of 32.0 GiB (42.04%)
transferred 13.8 GiB of 32.0 GiB (43.04%)
transferred 14.1 GiB of 32.0 GiB (44.04%)
transferred 14.4 GiB of 32.0 GiB (45.04%)
transferred 14.7 GiB of 32.0 GiB (46.04%)
transferred 15.1 GiB of 32.0 GiB (47.05%)
transferred 15.4 GiB of 32.0 GiB (48.05%)
transferred 15.7 GiB of 32.0 GiB (49.05%)
transferred 16.0 GiB of 32.0 GiB (50.05%)
transferred 16.3 GiB of 32.0 GiB (51.05%)
transferred 16.7 GiB of 32.0 GiB (52.05%)
transferred 17.0 GiB of 32.0 GiB (53.05%)
transferred 17.3 GiB of 32.0 GiB (54.05%)
transferred 17.6 GiB of 32.0 GiB (55.05%)
transferred 17.9 GiB of 32.0 GiB (56.05%)
transferred 18.3 GiB of 32.0 GiB (57.06%)
transferred 18.6 GiB of 32.0 GiB (58.06%)
transferred 18.9 GiB of 32.0 GiB (59.06%)
transferred 19.2 GiB of 32.0 GiB (60.06%)
transferred 19.5 GiB of 32.0 GiB (61.06%)
transferred 19.9 GiB of 32.0 GiB (62.06%)
transferred 20.2 GiB of 32.0 GiB (63.06%)
transferred 20.5 GiB of 32.0 GiB (64.06%)
transferred 20.8 GiB of 32.0 GiB (65.06%)
transferred 21.1 GiB of 32.0 GiB (66.06%)
transferred 21.5 GiB of 32.0 GiB (67.07%)
transferred 21.8 GiB of 32.0 GiB (68.07%)
transferred 22.1 GiB of 32.0 GiB (69.07%)
transferred 22.4 GiB of 32.0 GiB (70.07%)
transferred 22.7 GiB of 32.0 GiB (71.07%)
transferred 23.1 GiB of 32.0 GiB (72.07%)
transferred 23.4 GiB of 32.0 GiB (73.07%)
transferred 23.7 GiB of 32.0 GiB (74.07%)
transferred 24.0 GiB of 32.0 GiB (75.07%)
transferred 24.3 GiB of 32.0 GiB (76.07%)
transferred 24.7 GiB of 32.0 GiB (77.08%)
transferred 25.0 GiB of 32.0 GiB (78.08%)
transferred 25.3 GiB of 32.0 GiB (79.08%)
transferred 25.6 GiB of 32.0 GiB (80.08%)
transferred 25.9 GiB of 32.0 GiB (81.08%)
transferred 26.3 GiB of 32.0 GiB (82.08%)
transferred 26.6 GiB of 32.0 GiB (83.08%)
transferred 26.9 GiB of 32.0 GiB (84.08%)
transferred 27.2 GiB of 32.0 GiB (85.08%)
transferred 27.5 GiB of 32.0 GiB (86.08%)
transferred 27.9 GiB of 32.0 GiB (87.08%)
transferred 28.2 GiB of 32.0 GiB (88.09%)
transferred 28.5 GiB of 32.0 GiB (89.09%)
transferred 28.8 GiB of 32.0 GiB (90.09%)
transferred 29.1 GiB of 32.0 GiB (91.09%)
transferred 29.5 GiB of 32.0 GiB (92.09%)
transferred 29.8 GiB of 32.0 GiB (93.09%)
transferred 30.1 GiB of 32.0 GiB (94.09%)
transferred 30.4 GiB of 32.0 GiB (95.09%)
transferred 30.7 GiB of 32.0 GiB (96.09%)
transferred 31.1 GiB of 32.0 GiB (97.09%)
transferred 31.4 GiB of 32.0 GiB (98.10%)
transferred 31.7 GiB of 32.0 GiB (99.10%)
transferred 32.0 GiB of 32.0 GiB (100.00%)
transferred 32.0 GiB of 32.0 GiB (100.00%)
TASK OK

 

[fiona]

Can you try turning the discard setting off and see if it makes a difference? IIRC, there were reports about issues with LVM-thin and discard for migration, but maybe clone is affected too.

 

[mazerR]

Can you try turning the discard setting off and see if it makes a difference? IIRC, there were reports about issues with LVM-thin and discard for migration, but maybe clone is affected too.

I tried disabling discard that didn't improve the clone time at all. I also tried changing some other disk settings but they also didn't seem to make a difference. I also tried creating a new template with all the default settings besides the os and iso settings and cloning from that template is slow as well.

 

[fiona]

I'm not a hardware person, but maybe the SSD (it is a consumer SSD rather than enterprise SSD, right?) is just doing some caching and essentially "lying" to you about how fast it actually is with the writes. Then when the operation needs to finish it has to wait on the SSD.

 

[mazerR]

I reinstalled proxmox and recreated the VM and I noticed I am getting this error in dmesg.

[ 1935.281640] INFO: task qemu-img:6361 blocked for more than 362 seconds.
[ 1935.281661]       Tainted: P           O      5.15.102-1-pve #1
[ 1935.281678] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1935.281699] task:qemu-img        state:D stack:    0 pid: 6361 ppid:  6339 flags:0x00000000

 

[jimdammit]

Hey MazerR, I've been running into this same issue. Different hardware. On version 7.4 and 8.0. for quite some time now. Just completely reinstalled OS and changed hard drives as well.

What type of disk format is your template on? LVM, LVM-thin, ZFS?

What i tried was to create a folder on one of my drives using directory instead of LVM, LVM-thin. Then clone to the folder. Mine finished in 2min instead of 60 min like yours did. Then when i tried to clone that to LVM, or LVM-Thin storage from the directory, that's when the copy would start, and you get the message about being blocked.

Jul 11 23:42:04 pve kernel: INFO: task qemu-img:39541 blocked for more than 362 seconds.
Jul 11 23:42:04 pve kernel:       Tainted: P           O       6.2.16-3-pve #1
Jul 11 23:42:04 pve kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 11 23:42:04 pve kernel: task:qemu-img        state:D stack:0     pid:39541 ppid:37573  flags:0x00000002

So the function in qemu-img for converting to LVM/LVM-thin seems to be where the issue is.

 

[fiona]

Hi,

Hey MazerR, I've been running into this same issue. Different hardware. On version 7.4 and 8.0. for quite some time now. Just completely reinstalled OS and changed hard drives as well.

What type of disk format is your template on? LVM, LVM-thin, ZFS?

What i tried was to create a folder on one of my drives using directory instead of LVM, LVM-thin. Then clone to the folder. Mine finished in 2min instead of 60 min like yours did. Then when i tried to clone that to LVM, or LVM-Thin storage from the directory, that's when the copy would start, and you get the message about being blocked.

Jul 11 23:42:04 pve kernel: INFO: task qemu-img:39541 blocked for more than 362 seconds.
Jul 11 23:42:04 pve kernel:       Tainted: P           O       6.2.16-3-pve #1
Jul 11 23:42:04 pve kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 11 23:42:04 pve kernel: task:qemu-img        state:D stack:0     pid:39541 ppid:37573  flags:0x00000002

So the function in qemu-img for converting to LVM/LVM-thin seems to be where the issue is.

what kind of physical disks do you have? How does the load during the operation look like? How large is the virtual disk you are converting?

 

[jimdammit]

CPU(s) 32 x Intel(R) Xeon(R) CPU E5-2450 0 @ 2.10GHz (2 Sockets)
64Gig Ram
Kernel Version: Linux 6.2.16-3-pve #1 SMP PREEMPT_DYNAMIC PVE 6.2.16-3 (2023-06-17T05:58Z)
PVE Manager Version: pve-manager/8.0.3/bbf3993334bfa916
Disk: dell sas 3tb 7.2k
HEC310 raid 0. 4 disk each in their own group
CPU utilization low, memory utilization low.
Template is 10GB saved in LVM-Light raw format

I've tried setting up LVM-thin on another disk and same issues when cloning to that LVM-thin drive.