# pveversion
pve-manager/4.4-13/7ea56165 (running kernel: 4.4.59-1-pve)
I have a vm set up with LXC on a Proxmox node (s2) dedicated for backups with 350GB op storage assigned. To be able to backup the other VM's and LXC's, I export the storage via NFS and then mount that storage to backup to. This works fine as long as the storage limit (# of copies set in the NFS backup mount) is not reached. (Aside: I copy the backups to a different offsite store after they're done, this is just a convenient way to manage the process)
This was how it was running when the # of copies was not reached.
However, when the limit is reached, this happens. Some backups still work, others not:
When I remove the 2nd and 3rd copy of the backup, then all is fine again:
Why is this and is there anything else I can do to trace or fix this?
pve-manager/4.4-13/7ea56165 (running kernel: 4.4.59-1-pve)
I have a vm set up with LXC on a Proxmox node (s2) dedicated for backups with 350GB op storage assigned. To be able to backup the other VM's and LXC's, I export the storage via NFS and then mount that storage to backup to. This works fine as long as the storage limit (# of copies set in the NFS backup mount) is not reached. (Aside: I copy the backups to a different offsite store after they're done, this is just a convenient way to manage the process)
This was how it was running when the # of copies was not reached.
Code:
VMID STATUS TIME SIZE FILENAME
101 ok 00:05:23 2.38GB /mnt/pve/backupnfs/dump/vzdump-qemu-101-2017_06_19-01_00_02.vma.lzo
104 ok 00:06:24 3.45GB /mnt/pve/backupnfs/dump/vzdump-qemu-104-2017_06_19-01_05_25.vma.lzo
105 ok 00:06:40 2.88GB /mnt/pve/backupnfs/dump/vzdump-qemu-105-2017_06_19-01_11_49.vma.lzo
108 ok 00:06:59 3.62GB /mnt/pve/backupnfs/dump/vzdump-qemu-108-2017_06_19-01_18_29.vma.lzo
109 ok 00:10:24 4.25GB /mnt/pve/backupnfs/dump/vzdump-qemu-109-2017_06_19-01_25_28.vma.lzo
110 ok 00:05:23 2.53GB /mnt/pve/backupnfs/dump/vzdump-qemu-110-2017_06_19-01_35_52.vma.lzo
112 ok 00:07:33 4.49GB /mnt/pve/backupnfs/dump/vzdump-qemu-112-2017_06_19-01_41_15.vma.lzo
114 ok 00:01:21 2.44GB /mnt/pve/backupnfs/dump/vzdump-qemu-114-2017_06_19-01_48_48.vma.lzo
115 ok 00:13:24 2.51GB /mnt/pve/backupnfs/dump/vzdump-qemu-115-2017_06_19-01_50_09.vma.lzo
116 ok 00:29:23 22.98GB /mnt/pve/backupnfs/dump/vzdump-qemu-116-2017_06_19-02_03_33.vma.lzo
117 ok 00:44:43 30.47GB /mnt/pve/backupnfs/dump/vzdump-qemu-117-2017_06_19-02_32_56.vma.lzo
118 ok 00:22:02 3.58GB /mnt/pve/backupnfs/dump/vzdump-qemu-118-2017_06_19-03_17_39.vma.lzo
124 ok 00:34:46 23.80GB /mnt/pve/backupnfs/dump/vzdump-qemu-124-2017_06_19-03_39_41.vma.lzo
Detailed backup logs:
vzdump 101 104 105 108 109 110 112 114 115 116 117 118 124 --node s1 --mailnotification always --mailto roland@greentree.systems --mode snapshot --storage backupnfs --compress lzo --quiet 1
101: Jun 19 01:00:02 INFO: Starting Backup of VM 101 (qemu)
101: Jun 19 01:00:02 INFO: status = stopped
101: Jun 19 01:00:02 INFO: update VM 101: -lock backup
101: Jun 19 01:00:02 INFO: backup mode: stop
101: Jun 19 01:00:02 INFO: ionice priority: 7
101: Jun 19 01:00:02 INFO: VM Name: client.numbe
101: Jun 19 01:00:02 INFO: include disk 'virtio0' 'cephrbd:vm-101-disk-1' 10G
101: Jun 19 01:00:03 INFO: creating archive '/mnt/pve/backupnfs/dump/vzdump-qemu-101-2017_06_19-01_00_02.vma.lzo'
101: Jun 19 01:00:03 INFO: starting kvm to execute backup task
101: Jun 19 01:00:06 INFO: started backup task '928a2aa0-ee9d-475d-b32a-1c47676769c3'
101: Jun 19 01:00:09 INFO: status: 0% (100270080/10737418240), sparse 0% (995328), duration 3, 33/33 MB/s
101: Jun 19 01:00:12 INFO: status: 1% (209059840/10737418240), sparse 0% (2781184), duration 6, 36/35 MB/s
101: Jun 19 01:00:15 INFO: status: 2% (305201152/10737418240), sparse 0% (3231744), duration 9, 32/31 MB/s
101: Jun 19 01:00:18 INFO: status: 3% (414318592/10737418240), sparse 0% (4878336), duration 12, 36/35 MB/s
101: Jun 19 01:00:21 INFO: status: 4% (514523136/10737418240), sparse 0% (5136384), duration 15, 33/33 MB/s
101: Jun 19 01:00:24 INFO: status: 5% (623378432/10737418240), sparse 0% (6279168), duration 18, 36/35 MB/s
101: Jun 19 01:00:27 INFO: status: 6% (715784192/10737418240), sparse 0% (7901184), duration 21, 30/30 MB/s
101: Jun 19 01:00:30 INFO: status: 7% (824115200/10737418240), sparse 0% (8327168), duration 24, 36/35 MB/s
101: Jun 19 01:00:33 INFO: status: 8% (916258816/10737418240), sparse 0% (13787136), duration 27, 30/28 MB/s
101: Jun 19 01:00:36 INFO: status: 9% (1030094848/10737418240), sparse 0% (18817024), duration 30, 37/36 MB/s
101: Jun 19 01:00:39 INFO: status: 10% (1121320960/10737418240), sparse 0% (35078144), duration 33, 30/24 MB/s
101: Jun 19 01:00:46 INFO: status: 11% (1206910976/10737418240), sparse 0% (41611264), duration 40, 12/11 MB/s
101: Jun 19 01:00:50 INFO: status: 12% (1297547264/10737418240), sparse 0% (47472640), duration 44, 22/21 MB/s
<snip>
101: Jun 19 01:04:54 INFO: status: 78% (8454537216/10737418240), sparse 20% (2192605184), duration 288, 81/0 MB/s
101: Jun 19 01:04:57 INFO: status: 81% (8700297216/10737418240), sparse 22% (2438365184), duration 291, 81/0 MB/s
101: Jun 19 01:05:00 INFO: status: 83% (8939438080/10737418240), sparse 24% (2677506048), duration 294, 79/0 MB/s
101: Jun 19 01:05:03 INFO: status: 85% (9185787904/10737418240), sparse 27% (2923855872), duration 297, 82/0 MB/s
101: Jun 19 01:05:06 INFO: status: 87% (9416212480/10737418240), sparse 29% (3154280448), duration 300, 76/0 MB/s
101: Jun 19 01:05:09 INFO: status: 89% (9638576128/10737418240), sparse 31% (3376644096), duration 303, 74/0 MB/s
101: Jun 19 01:05:12 INFO: status: 92% (9882501120/10737418240), sparse 33% (3620569088), duration 306, 81/0 MB/s
101: Jun 19 01:05:15 INFO: status: 94% (10142089216/10737418240), sparse 36% (3880157184), duration 309, 86/0 MB/s
101: Jun 19 01:05:18 INFO: status: 96% (10390863872/10737418240), sparse 38% (4128931840), duration 312, 82/0 MB/s
101: Jun 19 01:05:21 INFO: status: 98% (10620960768/10737418240), sparse 40% (4359028736), duration 315, 76/0 MB/s
101: Jun 19 01:05:23 INFO: status: 100% (10737418240/10737418240), sparse 41% (4475486208), duration 317, 58/0 MB/s
101: Jun 19 01:05:23 INFO: transferred 10737 MB in 317 seconds (33 MB/s)
101: Jun 19 01:05:23 INFO: stopping kvm after backup task
101: Jun 19 01:05:24 INFO: archive file size: 2.38GB
101: Jun 19 01:05:25 INFO: Finished Backup of VM 101 (00:05:23)
<snip>However, when the limit is reached, this happens. Some backups still work, others not:
Code:
VMID STATUS TIME SIZE FILENAME
101 ok 00:01:27 319MB /mnt/pve/backupnfs/dump/vzdump-lxc-101-2017_08_14-01_00_01.tar.lzo
103 ok 00:01:48 457MB /mnt/pve/backupnfs/dump/vzdump-lxc-103-2017_08_14-01_01_28.tar.lzo
105 err 00:03:31 0.00MB -
106 err 00:03:39 0.00MB -
107 err 00:04:25 0.00MB -
108 err 00:03:55 0.00MB -
109 err 00:03:18 0.00MB -
110 err 00:03:46 0.00MB -
112 err 00:03:52 0.00MB -
114 err 00:01:22 0.00MB -
115 err 00:03:59 0.00MB -
116 err 00:03:23 0.00MB -
117 err 00:04:41 0.00MB -
118 err 00:04:37 0.00MB -
121 err 00:03:55 0.00MB -
124 err 00:03:16 0.00MB -
Detailed backup logs:
vzdump 101 105 108 109 110 112 114 115 116 117 118 124 106 103 107 121 --node s1 --storage backupnfs --mailnotification always --mode snapshot --quiet 1 --compress lzo --mailto roland@greentree.systems
101: Aug 14 01:00:01 INFO: Starting Backup of VM 101 (lxc)
101: Aug 14 01:00:01 INFO: status = running
101: Aug 14 01:00:01 INFO: CT Name: wiki
101: Aug 14 01:00:02 INFO: backup mode: snapshot
101: Aug 14 01:00:02 INFO: ionice priority: 7
101: Aug 14 01:00:02 INFO: create storage snapshot 'vzdump'
101: Aug 14 01:00:04 INFO: creating archive '/mnt/pve/backupnfs/dump/vzdump-lxc-101-2017_08_14-01_00_01.tar.lzo'
101: Aug 14 01:01:27 INFO: Total bytes written: 626544640 (598MiB, 7.2MiB/s)
101: Aug 14 01:01:27 INFO: archive file size: 319MB
101: Aug 14 01:01:28 INFO: delete old backup '/mnt/pve/backupnfs/dump/vzdump-lxc-101-2017_07_24-01_00_02.tar.lzo'
101: Aug 14 01:01:28 INFO: remove vzdump snapshot
101: Aug 14 01:01:28 INFO: Finished Backup of VM 101 (00:01:27)
103: Aug 14 01:01:28 INFO: Starting Backup of VM 103 (lxc)
103: Aug 14 01:01:28 INFO: status = running
103: Aug 14 01:01:28 INFO: CT Name: kanboard
103: Aug 14 01:01:28 INFO: backup mode: snapshot
103: Aug 14 01:01:28 INFO: ionice priority: 7
103: Aug 14 01:01:28 INFO: create storage snapshot 'vzdump'
103: Aug 14 01:01:31 INFO: creating archive '/mnt/pve/backupnfs/dump/vzdump-lxc-103-2017_08_14-01_01_28.tar.lzo'
103: Aug 14 01:03:15 INFO: Total bytes written: 1203763200 (1.2GiB, 12MiB/s)
103: Aug 14 01:03:15 INFO: archive file size: 457MB
103: Aug 14 01:03:15 INFO: delete old backup '/mnt/pve/backupnfs/dump/vzdump-lxc-103-2017_07_24-01_01_21.tar.lzo'
103: Aug 14 01:03:15 INFO: remove vzdump snapshot
103: Aug 14 01:03:16 INFO: Finished Backup of VM 103 (00:01:48)
105: Aug 14 01:03:16 INFO: Starting Backup of VM 105 (qemu)
105: Aug 14 01:03:16 INFO: status = stopped
105: Aug 14 01:03:17 INFO: update VM 105: -lock backup
105: Aug 14 01:03:17 INFO: backup mode: stop
105: Aug 14 01:03:17 INFO: ionice priority: 7
105: Aug 14 01:03:17 INFO: VM Name: demo.numbe
105: Aug 14 01:03:17 INFO: include disk 'virtio0' 'cephrbd:vm-105-disk-1' 15G
105: Aug 14 01:03:17 INFO: creating archive '/mnt/pve/backupnfs/dump/vzdump-qemu-105-2017_08_14-01_03_16.vma.lzo'
105: Aug 14 01:03:17 INFO: starting kvm to execute backup task
105: Aug 14 01:03:20 INFO: started backup task '04834648-c6e1-4fc8-a8a9-82bc7d7a9058'
105: Aug 14 01:03:23 INFO: status: 0% (79691776/16106127360), sparse 0% (1495040), duration 3, 26/26 MB/s
105: Aug 14 01:03:26 INFO: status: 1% (170590208/16106127360), sparse 0% (3067904), duration 6, 30/29 MB/s
105: Aug 14 01:03:34 INFO: status: 2% (343867392/16106127360), sparse 0% (3203072), duration 14, 21/21 MB/s
105: Aug 14 01:03:42 INFO: status: 3% (491388928/16106127360), sparse 0% (5447680), duration 22, 18/18 MB/s
105: Aug 14 01:03:49 INFO: status: 4% (654311424/16106127360), sparse 0% (5505024), duration 29, 23/23 MB/s
105: Aug 14 01:03:58 INFO: status: 5% (823721984/16106127360), sparse 0% (9723904), duration 38, 18/18 MB/s
105: Aug 14 01:04:04 INFO: status: 6% (983629824/16106127360), sparse 0% (11710464), duration 44, 26/26 MB/s
105: Aug 14 01:04:12 INFO: status: 7% (1136525312/16106127360), sparse 0% (15556608), duration 52, 19/18 MB/s
105: Aug 14 01:04:22 INFO: status: 8% (1301544960/16106127360), sparse 0% (22003712), duration 62, 16/15 MB/s
105: Aug 14 01:04:29 INFO: status: 9% (1476067328/16106127360), sparse 0% (22691840), duration 69, 24/24 MB/s
105: Aug 14 01:04:34 INFO: status: 10% (1617690624/16106127360), sparse 0% (24203264), duration 74, 28/28 MB/s
105: Aug 14 01:04:40 INFO: status: 11% (1775108096/16106127360), sparse 0% (27942912), duration 80, 26/25 MB/s
105: Aug 14 01:04:51 INFO: status: 12% (1946157056/16106127360), sparse 0% (30552064), duration 91, 15/15 MB/s
105: Aug 14 01:05:02 INFO: status: 13% (2101084160/16106127360), sparse 0% (39124992), duration 102, 14/13 MB/s
105: Aug 14 01:05:08 INFO: status: 14% (2269118464/16106127360), sparse 0% (41893888), duration 108, 28/27 MB/s
105: Aug 14 01:05:14 INFO: status: 15% (2428108800/16106127360), sparse 0% (41893888), duration 114, 26/26 MB/s
105: Aug 14 01:05:24 INFO: status: 16% (2580414464/16106127360), sparse 0% (42520576), duration 124, 15/15 MB/s
105: Aug 14 01:05:32 INFO: status: 17% (2755002368/16106127360), sparse 0% (43843584), duration 132, 21/21 MB/s
105: Aug 14 01:05:39 INFO: status: 18% (2927624192/16106127360), sparse 0% (45453312), duration 139, 24/24 MB/s
105: Aug 14 01:05:44 INFO: status: 19% (3066036224/16106127360), sparse 0% (46612480), duration 144, 27/27 MB/s
105: Aug 14 01:05:50 INFO: status: 20% (3230072832/16106127360), sparse 0% (54177792), duration 150, 27/26 MB/s
105: Aug 14 01:06:05 INFO: status: 21% (3406102528/16106127360), sparse 0% (58343424), duration 165, 11/11 MB/s
105: Aug 14 01:06:10 INFO: status: 22% (3544973312/16106127360), sparse 0% (59932672), duration 170, 27/27 MB/s
105: Aug 14 01:06:17 INFO: status: 23% (3714842624/16106127360), sparse 0% (62693376), duration 177, 24/23 MB/s
105: Aug 14 01:06:25 INFO: status: 24% (3871342592/16106127360), sparse 0% (62816256), duration 185, 19/19 MB/s
105: Aug 14 01:06:36 INFO: status: 25% (4030726144/16106127360), sparse 0% (63045632), duration 196, 14/14 MB/s
105: Aug 14 01:06:42 INFO: status: 26% (4197515264/16106127360), sparse 0% (64917504), duration 202, 27/27 MB/s
105: Aug 14 01:06:44 INFO: status: 26% (4204003328/16106127360), sparse 0% (64917504), duration 204, 3/3 MB/s
105: Aug 14 01:06:44 ERROR: vma_queue_write: write error - Broken pipe
105: Aug 14 01:06:44 INFO: aborting backup job
105: Aug 14 01:06:44 INFO: stopping kvm after backup task
105: Aug 14 01:06:47 ERROR: Backup of VM 105 failed - vma_queue_write: write error - Broken pipe
<snip>When I remove the 2nd and 3rd copy of the backup, then all is fine again:
Code:
VMID STATUS TIME SIZE FILENAME
101 ok 00:01:18 346MB /mnt/pve/backupnfs/dump/vzdump-lxc-101-2017_08_14-08_45_02.tar.lzo
103 ok 00:01:46 457MB /mnt/pve/backupnfs/dump/vzdump-lxc-103-2017_08_14-08_46_20.tar.lzo
105 ok 00:07:07 2.94GB /mnt/pve/backupnfs/dump/vzdump-qemu-105-2017_08_14-08_48_06.vma.lzo
106 ok 00:06:58 3.45GB /mnt/pve/backupnfs/dump/vzdump-qemu-106-2017_08_14-08_55_13.vma.lzo
107 ok 00:05:40 2.38GB /mnt/pve/backupnfs/dump/vzdump-qemu-107-2017_08_14-09_02_11.vma.lzo
108 ok 00:07:58 3.53GB /mnt/pve/backupnfs/dump/vzdump-qemu-108-2017_08_14-09_07_51.vma.lzo
112 ok 00:08:06 4.49GB /mnt/pve/backupnfs/dump/vzdump-qemu-112-2017_08_14-09_15_49.vma.lzo
114 ok 00:01:28 2.44GB /mnt/pve/backupnfs/dump/vzdump-qemu-114-2017_08_14-09_23_55.vma.lzo
115 ok 00:16:16 3.79GB /mnt/pve/backupnfs/dump/vzdump-qemu-115-2017_08_14-09_25_23.vma.lzo
116 ok 00:31:15 22.30GB /mnt/pve/backupnfs/dump/vzdump-qemu-116-2017_08_14-09_41_39.vma.lzo
117 ok 00:31:57 22.52GB /mnt/pve/backupnfs/dump/vzdump-qemu-117-2017_08_14-10_12_54.vma.lzo
121 ok 00:28:48 4.68GB /mnt/pve/backupnfs/dump/vzdump-qemu-121-2017_08_14-10_44_52.vma.lzo
124 ok 00:38:03 24.10GB /mnt/pve/backupnfs/dump/vzdump-qemu-124-2017_08_14-11_13_40.vma.lzo
125 ok 00:01:07 349MB /mnt/pve/backupnfs/dump/vzdump-lxc-125-2017_08_14-11_51_43.tar.lzo
Detailed backup logs:
vzdump 101 105 108 112 114 115 116 117 124 106 103 107 121 125 --mode snapshot --mailto roland@greentree.systems --node s1 --mailnotification always --storage backupnfs --compress lzo --quiet 1
101: Aug 14 08:45:02 INFO: Starting Backup of VM 101 (lxc)
101: Aug 14 08:45:02 INFO: status = running
101: Aug 14 08:45:02 INFO: CT Name: wiki
101: Aug 14 08:45:02 INFO: backup mode: snapshot
101: Aug 14 08:45:02 INFO: ionice priority: 7
101: Aug 14 08:45:02 INFO: create storage snapshot 'vzdump'
101: Aug 14 08:45:04 INFO: creating archive '/mnt/pve/backupnfs/dump/vzdump-lxc-101-2017_08_14-08_45_02.tar.lzo'
101: Aug 14 08:46:19 INFO: Total bytes written: 675901440 (645MiB, 8.6MiB/s)
101: Aug 14 08:46:19 INFO: archive file size: 346MB
101: Aug 14 08:46:19 INFO: delete old backup '/mnt/pve/backupnfs/dump/vzdump-lxc-101-2017_08_07-01_00_03.tar.lzo'
101: Aug 14 08:46:19 INFO: remove vzdump snapshot
101: Aug 14 08:46:20 INFO: Finished Backup of VM 101 (00:01:18)
103: Aug 14 08:46:20 INFO: Starting Backup of VM 103 (lxc)
103: Aug 14 08:46:20 INFO: status = running
103: Aug 14 08:46:20 INFO: CT Name: kanboard
103: Aug 14 08:46:20 INFO: backup mode: snapshot
103: Aug 14 08:46:20 INFO: ionice priority: 7
103: Aug 14 08:46:20 INFO: create storage snapshot 'vzdump'
103: Aug 14 08:46:22 INFO: creating archive '/mnt/pve/backupnfs/dump/vzdump-lxc-103-2017_08_14-08_46_20.tar.lzo'
103: Aug 14 08:48:05 INFO: Total bytes written: 1203804160 (1.2GiB, 12MiB/s)
103: Aug 14 08:48:05 INFO: archive file size: 457MB
103: Aug 14 08:48:05 INFO: delete old backup '/mnt/pve/backupnfs/dump/vzdump-lxc-103-2017_08_07-01_01_28.tar.lzo'
103: Aug 14 08:48:05 INFO: remove vzdump snapshot
103: Aug 14 08:48:06 INFO: Finished Backup of VM 103 (00:01:46)
105: Aug 14 08:48:06 INFO: Starting Backup of VM 105 (qemu)
105: Aug 14 08:48:06 INFO: status = stopped
105: Aug 14 08:48:07 INFO: update VM 105: -lock backup
105: Aug 14 08:48:07 INFO: backup mode: stop
105: Aug 14 08:48:07 INFO: ionice priority: 7
105: Aug 14 08:48:07 INFO: VM Name: demo.numbe
105: Aug 14 08:48:07 INFO: include disk 'virtio0' 'cephrbd:vm-105-disk-1' 15G
105: Aug 14 08:48:07 INFO: creating archive '/mnt/pve/backupnfs/dump/vzdump-qemu-105-2017_08_14-08_48_06.vma.lzo'
105: Aug 14 08:48:07 INFO: starting kvm to execute backup task
105: Aug 14 08:48:08 INFO: started backup task '1ac4c5a6-aa99-4a44-8ff0-239befcdbaa0'
105: Aug 14 08:48:11 INFO: status: 0% (89391104/16106127360), sparse 0% (1495040), duration 3, 29/29 MB/s
105: Aug 14 08:48:14 INFO: status: 1% (180027392/16106127360), sparse 0% (3067904), duration 6, 30/29 MB/s
105: Aug 14 08:48:20 INFO: status: 2% (331874304/16106127360), sparse 0% (3182592), duration 12, 25/25 MB/s
105: Aug 14 08:48:26 INFO: status: 3% (503316480/16106127360), sparse 0% (5447680), duration 18, 28/28 MB/s
105: Aug 14 08:48:32 INFO: status: 4% (665190400/16106127360), sparse 0% (5505024), duration 24, 26/26 MB/s
105: Aug 14 08:48:38 INFO: status: 5% (810680320/16106127360), sparse 0% (9392128), duration 30, 24/23 MB/s
105: Aug 14 08:48:50 INFO: status: 6% (976814080/16106127360), sparse 0% (11620352), duration 42, 13/13 MB/s
105: Aug 14 08:49:00 INFO: status: 7% (1149501440/16106127360), sparse 0% (15556608), duration 52, 17/16 MB/s
105: Aug 14 08:49:06 INFO: status: 8% (1309802496/16106127360), sparse 0% (22020096), duration 58, 26/25 MB/s
105: Aug 14 08:49:12 INFO: status: 9% (1473511424/16106127360), sparse 0% (22691840), duration 64, 27/27 MB/s
105: Aug 14 08:49:25 INFO: status: 10% (1623588864/16106127360), sparse 0% (24227840), duration 77, 11/11 MB/s
105: Aug 14 08:49:32 INFO: status: 11% (1777205248/16106127360), sparse 0% (27942912), duration 84, 21/21 MB/s
105: Aug 14 08:49:38 INFO: status: 12% (1954545664/16106127360), sparse 0% (30552064), duration 90, 29/29 MB/s
105: Aug 14 08:49:44 INFO: status: 13% (2116681728/16106127360), sparse 0% (39481344), duration 96, 27/25 MB/s
105: Aug 14 08:49:57 INFO: status: 14% (2268594176/16106127360), sparse 0% (41893888), duration 109, 11/11 MB/s
105: Aug 14 08:50:05 INFO: status: 15% (2426208256/16106127360), sparse 0% (41893888), duration 117, 19/19 MB/s
105: Aug 14 08:50:11 INFO: status: 16% (2592079872/16106127360), sparse 0% (42520576), duration 123, 27/27 MB/s
105: Aug 14 08:50:17 INFO: status: 17% (2745892864/16106127360), sparse 0% (43843584), duration 129, 25/25 MB/s
105: Aug 14 08:50:25 INFO: status: 18% (2910978048/16106127360), sparse 0% (45404160), duration 137, 20/20 MB/s
105: Aug 14 08:50:33 INFO: status: 19% (3074031616/16106127360), sparse 0% (46612480), duration 145, 20/20 MB/s
105: Aug 14 08:50:39 INFO: status: 20% (3246391296/16106127360), sparse 0% (54403072), duration 151, 28/27 MB/s
105: Aug 14 08:50:44 INFO: status: 21% (3391029248/16106127360), sparse 0% (58343424), duration 156, 28/28 MB/s
105: Aug 14 08:50:53 INFO: status: 22% (3544317952/16106127360), sparse 0% (59932672), duration 165, 17/16 MB/s
105: Aug 14 08:51:05 INFO: status: 23% (3724541952/16106127360), sparse 0% (62697472), duration 177, 15/14 MB/s
105: Aug 14 08:51:10 INFO: status: 24% (3867148288/16106127360), sparse 0% (62816256), duration 182, 28/28 MB/s
105: Aug 14 08:51:18 INFO: status: 25% (4031578112/16106127360), sparse 0% (63045632), duration 190, 20/20 MB/s
105: Aug 14 08:51:27 INFO: status: 26% (4197974016/16106127360), sparse 0% (64917504), duration 199, 18/18 MB/s
105: Aug 14 08:51:33 INFO: status: 27% (4381605888/16106127360), sparse 0% (95145984), duration 205, 30/25 MB/s
105: Aug 14 08:51:38 INFO: status: 28% (4534042624/16106127360), sparse 0% (104267776), duration 210, 30/28 MB/s
105: Aug 14 08:51:44 INFO: status: 29% (4676648960/16106127360), sparse 0% (104472576), duration 216, 23/23 MB/s
105: Aug 14 08:52:01 INFO: status: 30% (4848156672/16106127360), sparse 0% (105156608), duration 233, 10/10 MB/s
105: Aug 14 08:52:07 INFO: status: 31% (5003804672/16106127360), sparse 0% (107626496), duration 239, 25/25 MB/s
105: Aug 14 08:52:13 INFO: status: 32% (5165547520/16106127360), sparse 0% (110850048), duration 245, 26/26 MB/s
105: Aug 14 08:52:19 INFO: status: 33% (5326372864/16106127360), sparse 0% (114987008), duration 251, 26/26 MB/s
105: Aug 14 08:52:32 INFO: status: 34% (5495521280/16106127360), sparse 0% (117010432), duration 264, 13/12 MB/s
105: Aug 14 08:52:38 INFO: status: 35% (5658116096/16106127360), sparse 0% (117657600), duration 270, 27/26 MB/s
105: Aug 14 08:52:44 INFO: status: 36% (5813305344/16106127360), sparse 0% (119390208), duration 276, 25/25 MB/s
105: Aug 14 08:52:53 INFO: status: 37% (5971509248/16106127360), sparse 0% (121376768), duration 285, 17/17 MB/s
105: Aug 14 08:53:01 INFO: status: 38% (6144851968/16106127360), sparse 0% (122105856), duration 293, 21/21 MB/s
105: Aug 14 08:53:07 INFO: status: 39% (6310133760/16106127360), sparse 0% (122343424), duration 299, 27/27 MB/s
105: Aug 14 08:53:13 INFO: status: 40% (6446645248/16106127360), sparse 0% (126390272), duration 305, 22/22 MB/s
105: Aug 14 08:53:17 INFO: status: 41% (6658654208/16106127360), sparse 2% (333762560), duration 309, 53/1 MB/s
105: Aug 14 08:53:20 INFO: status: 42% (6810763264/16106127360), sparse 3% (485871616), duration 312, 50/0 MB/s
105: Aug 14 08:53:23 INFO: status: 43% (6933184512/16106127360), sparse 3% (608292864), duration 315, 40/0 MB/s
105: Aug 14 08:53:26 INFO: status: 44% (7163281408/16106127360), sparse 5% (838389760), duration 318, 76/0 MB/s
105: Aug 14 08:53:29 INFO: status: 45% (7403208704/16106127360), sparse 6% (1078317056), duration 321, 79/0 MB/s
105: Aug 14 08:53:32 INFO: status: 47% (7646216192/16106127360), sparse 8% (1321324544), duration 324, 81/0 MB/s
105: Aug 14 08:53:35 INFO: status: 48% (7874740224/16106127360), sparse 9% (1549848576), duration 327, 76/0 MB/s
105: Aug 14 08:53:38 INFO: status: 50% (8120172544/16106127360), sparse 11% (1795280896), duration 330, 81/0 MB/s
105: Aug 14 08:53:41 INFO: status: 51% (8359968768/16106127360), sparse 12% (2035077120), duration 333, 79/0 MB/s
105: Aug 14 08:53:44 INFO: status: 53% (8584822784/16106127360), sparse 14% (2259931136), duration 336, 74/0 MB/s
105: Aug 14 08:53:47 INFO: status: 54% (8840871936/16106127360), sparse 15% (2515980288), duration 339, 85/0 MB/s
105: Aug 14 08:53:50 INFO: status: 56% (9096200192/16106127360), sparse 17% (2771308544), duration 342, 85/0 MB/s
105: Aug 14 08:53:53 INFO: status: 57% (9333506048/16106127360), sparse 18% (3008614400), duration 345, 79/0 MB/s
105: Aug 14 08:53:56 INFO: status: 59% (9550430208/16106127360), sparse 20% (3225538560), duration 348, 72/0 MB/s
105: Aug 14 08:53:59 INFO: status: 60% (9773449216/16106127360), sparse 21% (3448557568), duration 351, 74/0 MB/s
105: Aug 14 08:54:02 INFO: status: 62% (10022813696/16106127360), sparse 22% (3697922048), duration 354, 83/0 MB/s
105: Aug 14 08:54:05 INFO: status: 63% (10275258368/16106127360), sparse 24% (3950366720), duration 357, 84/0 MB/s
105: Aug 14 08:54:08 INFO: status: 65% (10533732352/16106127360), sparse 26% (4208840704), duration 360, 86/0 MB/s
105: Aug 14 08:54:11 INFO: status: 67% (10796204032/16106127360), sparse 27% (4471312384), duration 363, 87/0 MB/s
105: Aug 14 08:54:14 INFO: status: 68% (11057889280/16106127360), sparse 29% (4732997632), duration 366, 87/0 MB/s
105: Aug 14 08:54:17 INFO: status: 70% (11312037888/16106127360), sparse 30% (4987146240), duration 369, 84/0 MB/s
105: Aug 14 08:54:20 INFO: status: 71% (11581718528/16106127360), sparse 32% (5256826880), duration 372, 89/0 MB/s
105: Aug 14 08:54:23 INFO: status: 73% (11856052224/16106127360), sparse 34% (5531160576), duration 375, 91/0 MB/s
105: Aug 14 08:54:26 INFO: status: 75% (12118130688/16106127360), sparse 35% (5793239040), duration 378, 87/0 MB/s
105: Aug 14 08:54:29 INFO: status: 76% (12387549184/16106127360), sparse 37% (6062657536), duration 381, 89/0 MB/s
105: Aug 14 08:54:32 INFO: status: 78% (12652249088/16106127360), sparse 39% (6327357440), duration 384, 88/0 MB/s
105: Aug 14 08:54:35 INFO: status: 80% (12926844928/16106127360), sparse 40% (6601953280), duration 387, 91/0 MB/s
105: Aug 14 08:54:38 INFO: status: 81% (13189709824/16106127360), sparse 42% (6864818176), duration 390, 87/0 MB/s
105: Aug 14 08:54:41 INFO: status: 83% (13446938624/16106127360), sparse 44% (7122046976), duration 393, 85/0 MB/s
105: Aug 14 08:54:44 INFO: status: 85% (13711376384/16106127360), sparse 45% (7386484736), duration 396, 88/0 MB/s
105: Aug 14 08:54:47 INFO: status: 86% (13976797184/16106127360), sparse 47% (7651905536), duration 399, 88/0 MB/s
105: Aug 14 08:54:50 INFO: status: 88% (14269874176/16106127360), sparse 49% (7944982528), duration 402, 97/0 MB/s
105: Aug 14 08:54:53 INFO: status: 90% (14545846272/16106127360), sparse 51% (8220954624), duration 405, 91/0 MB/s
105: Aug 14 08:54:56 INFO: status: 92% (14837940224/16106127360), sparse 52% (8513048576), duration 408, 97/0 MB/s
105: Aug 14 08:54:59 INFO: status: 93% (15099494400/16106127360), sparse 54% (8774602752), duration 411, 87/0 MB/s
105: Aug 14 08:55:02 INFO: status: 95% (15375138816/16106127360), sparse 56% (9050247168), duration 414, 91/0 MB/s
105: Aug 14 08:55:05 INFO: status: 97% (15625224192/16106127360), sparse 57% (9300332544), duration 417, 83/0 MB/s
105: Aug 14 08:55:08 INFO: status: 98% (15893200896/16106127360), sparse 59% (9568309248), duration 420, 89/0 MB/s
105: Aug 14 08:55:11 INFO: status: 100% (16106127360/16106127360), sparse 60% (9781235712), duration 423, 70/0 MB/s
105: Aug 14 08:55:11 INFO: transferred 16106 MB in 423 seconds (38 MB/s)
105: Aug 14 08:55:11 INFO: stopping kvm after backup task
105: Aug 14 08:55:12 INFO: archive file size: 2.94GB
105: Aug 14 08:55:12 INFO: delete old backup '/mnt/pve/backupnfs/dump/vzdump-qemu-105-2017_07_24-01_03_00.vma.lzo'
105: Aug 14 08:55:13 INFO: Finished Backup of VM 105 (00:07:07)Why is this and is there anything else I can do to trace or fix this?