Strange difference between backup times of VMs

dan

New Member
Jan 16, 2009
21
0
1
Hi,

I have discovered some strange behaviour of the backup process. The backup of VM 100 is very fast (23MiB/s) but VM 101 takes like forever (530KiB/s). Why is there such a great difference in the backup speed?

Code:
100: Oct 20 03:00:01 INFO: Starting Backup of VM 100 (openvz)
100: Oct 20 03:00:01 INFO: CTID 100 exist mounted running
100: Oct 20 03:00:01 INFO: status = running
100: Oct 20 03:00:01 INFO: backup mode: snapshot
100: Oct 20 03:00:01 INFO: ionice priority: 7
100: Oct 20 03:00:01 INFO: creating lvm snapshot of /dev/mapper/vg0-vms ('/dev/vg0/vzsnap-host-0')
100: Oct 20 03:00:03 INFO:   Logical volume "vzsnap-host-0" created
100: Oct 20 03:00:04 INFO: creating archive '/backup/dump/vzdump-openvz-100-2012_10_20-03_00_01.tar.lzo'
100: Oct 20 03:09:13 INFO: Total bytes written: 12840028160 (12GiB, 23MiB/s)
100: Oct 20 03:09:13 INFO: archive file size: 1.85GB
100: Oct 20 03:09:13 INFO: delete old backup '/backup/dump/vzdump-openvz-100-2012_10_17-03_00_01.tar.lzo'
100: Oct 20 03:09:16 INFO: Finished Backup of VM 100 (00:09:15)


101: Oct 20 03:09:16 INFO: Starting Backup of VM 101 (openvz)
101: Oct 20 03:09:16 INFO: CTID 101 exist mounted running
101: Oct 20 03:09:16 INFO: status = running
101: Oct 20 03:09:16 INFO: backup mode: snapshot
101: Oct 20 03:09:16 INFO: ionice priority: 7
101: Oct 20 03:09:16 INFO: creating lvm snapshot of /dev/mapper/vg0-vms ('/dev/vg0/vzsnap-host-0')
101: Oct 20 03:09:17 INFO:   Logical volume "vzsnap-host-0" created
101: Oct 20 03:09:18 INFO: creating archive '/backup/dump/vzdump-openvz-101-2012_10_20-03_09_16.tar.lzo'
101: Oct 20 08:26:13 INFO: Total bytes written: 10152939520 (9.5GiB, 530KiB/s)
101: Oct 20 08:26:13 INFO: archive file size: 3.35GB
101: Oct 20 08:26:13 INFO: delete old backup '/backup/dump/vzdump-openvz-101-2012_10_17-03_09_20.tar.lzo'
101: Oct 20 08:26:18 INFO: Finished Backup of VM 101 (05:17:02)
 
Last edited:

dan

New Member
Jan 16, 2009
21
0
1
Is it always that slow? Or did that just happened once?

Hello Dietmar,

thanks for your reply. Actually it is getting worse over time. This is a log from the end of september:

Code:
100: Sep 29 03:00:01 INFO: Starting Backup of VM 100 (openvz)100: Sep 29 03:00:01 INFO: CTID 100 exist mounted running
100: Sep 29 03:00:01 INFO: status = running
100: Sep 29 03:00:01 INFO: backup mode: snapshot
100: Sep 29 03:00:01 INFO: ionice priority: 7
100: Sep 29 03:00:01 INFO: creating lvm snapshot of /dev/mapper/vg0-vms ('/dev/vg0/vzsnap-host-0')
100: Sep 29 03:00:02 INFO:   Logical volume "vzsnap-host-0" created
100: Sep 29 03:00:04 INFO: creating archive '/backup/dump/vzdump-openvz-100-2012_09_29-03_00_01.tar.lzo'
100: Sep 29 03:07:49 INFO: Total bytes written: 12335749120 (12GiB, 26MiB/s)
100: Sep 29 03:07:49 INFO: archive file size: 1.60GB
100: Sep 29 03:07:49 INFO: delete old backup '/backup/dump/vzdump-openvz-100-2012_09_26-03_00_01.tar.lzo'
100: Sep 29 03:07:51 INFO: Finished Backup of VM 100 (00:07:50)


101: Sep 29 03:07:51 INFO: Starting Backup of VM 101 (openvz)
101: Sep 29 03:07:51 INFO: CTID 101 exist mounted running
101: Sep 29 03:07:51 INFO: status = running
101: Sep 29 03:07:51 INFO: backup mode: snapshot
101: Sep 29 03:07:51 INFO: ionice priority: 7
101: Sep 29 03:07:51 INFO: creating lvm snapshot of /dev/mapper/vg0-vms ('/dev/vg0/vzsnap-host-0')
101: Sep 29 03:07:52 INFO:   Logical volume "vzsnap-host-0" created
101: Sep 29 03:07:53 INFO: creating archive '/backup/dump/vzdump-openvz-101-2012_09_29-03_07_51.tar.lzo'
101: Sep 29 05:19:00 INFO: Total bytes written: 8029317120 (7.5GiB, 1010KiB/s)
101: Sep 29 05:19:00 INFO: archive file size: 2.36GB
101: Sep 29 05:19:00 INFO: delete old backup '/backup/dump/vzdump-openvz-101-2012_09_26-03_07_59.tar.lzo'
101: Sep 29 05:19:03 INFO: Finished Backup of VM 101 (02:11:12)

Edit:
In the syslog I found a lot of those records:
Code:
Oct 20 08:26:19 host kernel: EXT4-fs (dm-4): ext4_orphan_cleanup: deleting unreferenced inode 27661914
Oct 20 08:26:19 host kernel: VZDQ: Tried to clean orphans on qmblk with 1 state
Oct 20 08:26:19 host kernel: BUG: Quota files for 101 are broken: no quota engine running
Oct 20 08:26:19 host kernel: EXT4-fs (dm-4): ext4_orphan_cleanup: deleting unreferenced inode 27661911
Oct 20 08:26:19 host kernel: VZDQ: Tried to clean orphans on qmblk with 1 state
Oct 20 08:26:19 host kernel: BUG: Quota files for 101 are broken: no quota engine running
Oct 20 08:26:19 host kernel: EXT4-fs (dm-4): ext4_orphan_cleanup: deleting unreferenced inode 27661915
Oct 20 08:26:19 host kernel: VZDQ: Tried to clean orphans on qmblk with 1 state
Oct 20 08:26:19 host kernel: BUG: Quota files for 101 are broken: no quota engine running
Oct 20 08:26:19 host kernel: EXT4-fs (dm-4): ext4_orphan_cleanup: deleting unreferenced inode 27793036
 
Last edited:

dietmar

Proxmox Staff Member
Staff member
Apr 28, 2005
17,114
513
133
Austria
www.proxmox.com
Those logs are from mounting the snapshot - quite normal.

The CT growed from 2.36GB to 3.35GB, that explains why it get slower over time.

Maybe the CT contains many small files?
 

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get your own in 60 seconds.

Buy now!