Strange difference between backup times of VMs

[dan]

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?

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)

 

[dietmar]

Is it always that slow? Or did that just happened once?

 

[dan]

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:

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:

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

 

[dietmar]

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?