Strange difference between backup times of VMs

D

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:
dietmar said:
Is it always that slow? Or did that just happened once?
Click to expand...

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:
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?
 
You must log in or register to reply here.
Top Bottom