[SOLVED] Backup REALLY slow after upgrade to Proxmox VE 4.0

[jester]

After upgrading my server to Proxmox VE 4 my backup to USB-disk has become REALLY slow. Excerpts from the backup report mails:

Before upgrade (PVE 3.4-6):

103

webmail

OK

00:13:07

/media/usb0//dump/vzdump-qemu-103-2015_11_15-01_01_16.vma.lzo

[TD="align: right"]5.04GB[/TD]

After upgrade (PVE 4.0-57):

103

webmail

OK

04:59:50

/media/usb0//dump/vzdump-qemu-103-2015_11_17-04_50_15.vma.lzo

[TD="align: right"]5.08GB[/TD]

Anyone with an idea what might be going on?


Regards.

 

[Erk]

You need to supply more information than you have.

Did you check your backup settings to see that there was no bandwidth limit?

https://pve.proxmox.com/wiki/VZDump

 

[jester]

Hi Erk,
Thanx for your reply.

Server was upgraded to PVE4, no other changes were made. Next backup after upgrade had these problems, same usb3 backup disk.
Just to be sure i checked /etc/vzdump.conf and the bwlimit parameter is commented out.

 

[Erk]

Hi Erk,
Thanx for your reply.

Server was upgraded to PVE4, no other changes were made. Next backup after upgrade had these problems, same usb3 backup disk.
Just to be sure i checked /etc/vzdump.conf and the bwlimit parameter is commented out.

What does the backup log say about the speed obtained?

 

[jester]

Hi Erk,
Don't know where to find the backup log, this is from the mails before and after the upgrade. Speed dropped from 20MiB/s to 823KiB/s.

Before:

101: Nov 15 01:00:01 INFO: Starting Backup of VM 101 (openvz)
101: Nov 15 01:00:01 INFO: CTID 101 exist mounted running
101: Nov 15 01:00:01 INFO: status = running
101: Nov 15 01:00:01 INFO: backup mode: snapshot
101: Nov 15 01:00:01 INFO: ionice priority: 7
101: Nov 15 01:00:01 INFO: creating lvm snapshot of /dev/mapper/pve-data ('/dev/pve/vzsnap-pmx01-0')
101: Nov 15 01:00:02 INFO:   Logical volume "vzsnap-pmx01-0" created
101: Nov 15 01:00:02 INFO: creating archive '/media/usb0//dump/vzdump-openvz-101-2015_11_15-01_00_01.tar.lzo'
101: Nov 15 01:01:14 INFO: Total bytes written: 1465856000 (1.4GiB, 20MiB/s)
101: Nov 15 01:01:14 INFO: archive file size: 837MB
101: Nov 15 01:01:14 INFO: delete old backup '/media/usb0//dump/vzdump-openvz-101-2015_11_11-01_00_01.tar.lzo'
101: Nov 15 01:01:16 INFO: Finished Backup of VM 101 (00:01:15)

And after:

101: Nov 17 01:00:01 INFO: Starting Backup of VM 101 (lxc)
101: Nov 17 01:00:01 INFO: status = running
101: Nov 17 01:00:01 INFO: mode failure - some volumes does not support snapshots
101: Nov 17 01:00:01 INFO: trying 'suspend' mode instead
101: Nov 17 01:00:01 INFO: backup mode: suspend
101: Nov 17 01:00:01 INFO: ionice priority: 7
101: Nov 17 01:00:01 INFO: starting first sync /proc/9273/root// to /media/usb0//dump/vzdump-lxc-101-2015_11_17-01_00_01.tmp
101: Nov 17 03:16:09 INFO: Number of files: 82,581 (reg: 43,389, dir: 7,235, link: 31,925, dev: 2, special: 30)
101: Nov 17 03:16:09 INFO: Number of created files: 82,580 (reg: 43,389, dir: 7,234, link: 31,925, dev: 2, special: 30)
101: Nov 17 03:16:09 INFO: Number of deleted files: 0
101: Nov 17 03:16:09 INFO: Number of regular files transferred: 43,375
101: Nov 17 03:16:09 INFO: Total file size: 1,417,111,897 bytes
101: Nov 17 03:16:09 INFO: Total transferred file size: 1,413,411,781 bytes
101: Nov 17 03:16:09 INFO: Literal data: 1,413,411,781 bytes
101: Nov 17 03:16:09 INFO: Matched data: 0 bytes
101: Nov 17 03:16:09 INFO: File list size: 2,686,309
101: Nov 17 03:16:09 INFO: File list generation time: 0.001 seconds
101: Nov 17 03:16:09 INFO: File list transfer time: 0.000 seconds
101: Nov 17 03:16:09 INFO: Total bytes sent: 1,419,242,391
101: Nov 17 03:16:09 INFO: Total bytes received: 959,013
101: Nov 17 03:16:09 INFO: sent 1,419,242,391 bytes  received 959,013 bytes  173,863.18 bytes/sec
101: Nov 17 03:16:09 INFO: total size is 1,417,111,897  speedup is 1.00
101: Nov 17 03:16:09 INFO: first sync finished (8168 seconds)
101: Nov 17 03:16:09 INFO: suspend vm
101: Nov 17 03:16:09 INFO: starting final sync /proc/9273/root// to /media/usb0//dump/vzdump-lxc-101-2015_11_17-01_00_01.tmp
101: Nov 17 03:16:11 INFO: Number of files: 82,581 (reg: 43,389, dir: 7,235, link: 31,925, dev: 2, special: 30)
101: Nov 17 03:16:11 INFO: Number of created files: 0
101: Nov 17 03:16:11 INFO: Number of deleted files: 0
101: Nov 17 03:16:11 INFO: Number of regular files transferred: 4
101: Nov 17 03:16:11 INFO: Total file size: 1,417,111,897 bytes
101: Nov 17 03:16:11 INFO: Total transferred file size: 279,571 bytes
101: Nov 17 03:16:11 INFO: Literal data: 12,707 bytes
101: Nov 17 03:16:11 INFO: Matched data: 266,864 bytes
101: Nov 17 03:16:11 INFO: File list size: 0
101: Nov 17 03:16:11 INFO: File list generation time: 0.001 seconds
101: Nov 17 03:16:11 INFO: File list transfer time: 0.000 seconds
101: Nov 17 03:16:11 INFO: Total bytes sent: 3,576,503
101: Nov 17 03:16:11 INFO: Total bytes received: 10,582
101: Nov 17 03:16:11 INFO: sent 3,576,503 bytes  received 10,582 bytes  2,391,390.00 bytes/sec
101: Nov 17 03:16:11 INFO: total size is 1,417,111,897  speedup is 395.06
101: Nov 17 03:16:11 INFO: final sync finished (2 seconds)
101: Nov 17 03:16:11 INFO: resume vm
101: Nov 17 03:16:11 INFO: vm is online again after 2 seconds
101: Nov 17 03:16:11 INFO: creating archive '/media/usb0//dump/vzdump-lxc-101-2015_11_17-01_00_01.tar.lzo'
101: Nov 17 03:46:52 INFO: Total bytes written: 1550694400 (1.5GiB, 823KiB/s)
101: Nov 17 03:46:53 INFO: archive file size: 846MB
101: Nov 17 04:50:15 INFO: Finished Backup of VM 101 (03:50:14)

Anything else i can lookup or test?

 

[Erk]

There is an error in your log which says:

101: Nov 17 01:00:01 INFO: mode failure - some volumes does not support snapshots
101: Nov 17 01:00:01 INFO: trying 'suspend' mode instead
101: Nov 17 01:00:01 INFO: backup mode: suspend


Where your previous log showed the snapshot was possible.
Also your previous backup was an opernvz container and now it says lxc so a lot has been changed.

 

[jester]

Problem is the same for KVM vm's being backed-up (and not showing the 'mode failure' error), so that does not seem to be related:

Before:

103: Nov 15 01:01:16 INFO: Starting Backup of VM 103 (qemu)
103: Nov 15 01:01:16 INFO: status = running
103: Nov 15 01:01:16 INFO: update VM 103: -lock backup
103: Nov 15 01:01:17 INFO: backup mode: snapshot
103: Nov 15 01:01:17 INFO: ionice priority: 7
103: Nov 15 01:01:17 INFO: snapshots found (not included into backup)
103: Nov 15 01:01:17 INFO: creating archive '/media/usb0//dump/vzdump-qemu-103-2015_11_15-01_01_16.vma.lzo'
103: Nov 15 01:01:17 INFO: started backup task 'abfcd4a9-1e56-4ec5-88b6-03b3e117377c'
103: Nov 15 01:01:20 INFO: status: 0% (83623936/34359738368), sparse 0% (12124160), duration 3, 27/23 MB/s
103: Nov 15 01:01:24 INFO: status: 1% (407764992/34359738368), sparse 0% (248803328), duration 7, 81/21 MB/s
103: Nov 15 01:01:36 INFO: status: 2% (702480384/34359738368), sparse 0% (265707520), duration 19, 24/23 MB/s
103: Nov 15 01:01:45 INFO: status: 3% (1052901376/34359738368), sparse 0% (274083840), duration 28, 38/38 MB/s
...
103: Nov 15 01:13:59 INFO: status: 96% (33020051456/34359738368), sparse 54% (18865475584), duration 762, 35/34 MB/s
103: Nov 15 01:14:08 INFO: status: 97% (33343143936/34359738368), sparse 54% (18868215808), duration 771, 35/35 MB/s
103: Nov 15 01:14:21 INFO: status: 100% (34359738368/34359738368), sparse 57% (19801989120), duration 784, 78/6 MB/s
103: Nov 15 01:14:21 INFO: transferred 34359 MB in 784 seconds (43 MB/s)
103: Nov 15 01:14:21 INFO: archive file size: 5.04GB
103: Nov 15 01:14:21 INFO: delete old backup '/media/usb0//dump/vzdump-qemu-103-2015_11_11-01_01_15.vma.lzo'
103: Nov 15 01:14:23 INFO: Finished Backup of VM 103 (00:13:07)

After:

103: Nov 17 04:50:15 INFO: Starting Backup of VM 103 (qemu)
103: Nov 17 04:50:15 INFO: status = running
103: Nov 17 04:50:16 INFO: update VM 103: -lock backup
103: Nov 17 04:50:16 INFO: backup mode: snapshot
103: Nov 17 04:50:16 INFO: ionice priority: 7
103: Nov 17 04:50:16 INFO: snapshots found (not included into backup)
103: Nov 17 04:50:16 INFO: creating archive '/media/usb0//dump/vzdump-qemu-103-2015_11_17-04_50_15.vma.lzo'
103: Nov 17 04:50:16 INFO: started backup task 'cd357fc0-d227-483c-8835-394658b2b6c3'
103: Nov 17 04:50:19 INFO: status: 0% (15204352/34359738368), sparse 0% (9371648), duration 3, 5/1 MB/s
103: Nov 17 04:53:03 INFO: status: 1% (345899008/34359738368), sparse 0% (188329984), duration 167, 2/0 MB/s
103: Nov 17 04:58:27 INFO: status: 2% (687996928/34359738368), sparse 0% (265773056), duration 491, 1/0 MB/s
103: Nov 17 05:05:04 INFO: status: 3% (1033895936/34359738368), sparse 0% (278429696), duration 888, 0/0 MB/s
...
103: Nov 17 09:40:49 INFO: status: 96% (32985841664/34359738368), sparse 54% (18851258368), duration 17433, 0/0 MB/s
103: Nov 17 09:47:55 INFO: status: 97% (33331740672/34359738368), sparse 54% (18855350272), duration 17859, 0/0 MB/s
103: Nov 17 09:50:03 INFO: status: 100% (34359738368/34359738368), sparse 57% (19789123584), duration 17987, 8/0 MB/s
103: Nov 17 09:50:03 INFO: transferred 34359 MB in 17987 seconds (1 MB/s)
103: Nov 17 09:50:03 INFO: archive file size: 5.08GB
103: Nov 17 09:50:03 INFO: delete old backup '/media/usb0//dump/vzdump-qemu-103-2015_11_05-01_01_19.vma.lzo'
103: Nov 17 09:50:05 INFO: Finished Backup of VM 103 (04:59:50)

 

[jester]

The speed of the USB3 disk does not seem to be the problem:

root@pmx01:/media/usb0# dd if=/dev/zero of=tmp_file bs=1M count=1024 conv=fdatasync ; rm -f tmp_file
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB) copied, 93.5955 s, 11.5 MB/s

 

[jester]

Would it be possible to install an 2.6 kernel to see if this makes the difference?

 

[jester]

Just for anyone encountering something similar: During testing i noticed that when i manually mounted the usb drive the backup speed was normal again (actually even faster than before)
...so i'm presuming the usbmount-package i was using was the culprit!

Removed usbmount and i'm now using some udev rules to persistently mount my usb-drives on the same location for backup and everything is working again.