Hi,
I have a USB attached to one of the nodes , for a dedicated backup of a few VMs (on the same host, so no network here, just plain USB connection)
it was taking over 2 and half hours to backup 46 GB, so I changed the backup to the local hard drives and still takes a long time
Actually, there is no difference to when it was going to the USB. If anything a little longer.
The other backups I run to either local or USB run fine. (in relation space / time)
I have also noticed that the VMs that take a long time to backup (like 6000) are also running quite slow.
Questions are:
1: What impacts the speed of the backup if the hard drive (usb or local) are not otherwise utilized, like in my case, running at midnight and ALL other backup jobs are stopped for testing.
2: Does the performance of the VM itself has anything to do with the speed of the backup? if so, how can I troubleshoot why the VMs is slow, nothing has changed, no software, nothing new.. I just happened.
I putting here the detailed log of the last 'slow' backup for information in case someone understand anything here.
This is the backup last night that took 2:33 for 46.62 gb.
=================================================================================
Detailed backup logs:
vzdump 6000 --quiet 1 --mailto mvazquez@xxxxxxx.com --compress lzo --storage local --mode snapshot --mailnotification always
6000: 2019-02-28 00:00:03 INFO: Starting Backup of VM 6000 (qemu)
6000: 2019-02-28 00:00:03 INFO: status = running
6000: 2019-02-28 00:00:04 INFO: file /etc/pve/replication.cfg line 4 (section '1001-1') - unable to parse value of 'source': unexpected property 'source'
6000: 2019-02-28 00:00:04 INFO: file /etc/pve/replication.cfg line 11 (section '9035-0') - unable to parse value of 'source': unexpected property 'source'
6000: 2019-02-28 00:00:04 INFO: file /etc/pve/replication.cfg line 15 (section '98000-0') - unable to parse value of 'source': unexpected property 'source'
6000: 2019-02-28 00:00:04 INFO: file /etc/pve/replication.cfg line 19 (section '99401-0') - unable to parse value of 'source': unexpected property 'source'
6000: 2019-02-28 00:00:04 INFO: file /etc/pve/replication.cfg line 23 (section '999402-0') - unable to parse value of 'source': unexpected property 'source'
6000: 2019-02-28 00:00:04 INFO: update VM 6000: -lock backup
6000: 2019-02-28 00:00:04 INFO: VM Name: w2012DocuPhase
6000: 2019-02-28 00:00:04 INFO: include disk 'sata0' 'local-zfs:vm-6000-disk-1' 80G
6000: 2019-02-28 00:00:04 INFO: include disk 'sata1' 'local-zfs:vm-6000-disk-2' 500G
6000: 2019-02-28 00:00:04 INFO: backup mode: snapshot
6000: 2019-02-28 00:00:04 INFO: ionice priority: 7
6000: 2019-02-28 00:00:04 INFO: creating archive '/var/lib/vz/dump/vzdump-qemu-6000-2019_02_28-00_00_03.vma.lzo'
6000: 2019-02-28 01:00:04 ERROR: VM 6000 qmp command 'guest-fsfreeze-freeze' failed - got timeout
6000: 2019-02-28 01:00:14 ERROR: VM 6000 qmp command 'guest-fsfreeze-thaw' failed - got timeout
6000: 2019-02-28 01:00:14 INFO: started backup task 'fdf6aa69-ddd5-4a01-9fee-a533ff8c6fc9'
6000: 2019-02-28 01:00:18 INFO: status: 0% (171048960/622770257920), sparse 0% (49229824), duration 4, read/write 42/30 MB/s
6000: 2019-02-28 01:10:39 INFO: status: 1% (6241386496/622770257920), sparse 0% (185667584), duration 625, read/write 9/9 MB/s
6000: 2019-02-28 01:21:43 INFO: status: 2% (12475170816/622770257920), sparse 0% (468197376), duration 1289, read/write 9/8 MB/s
6000: 2019-02-28 01:32:20 INFO: status: 3% (18693750784/622770257920), sparse 0% (565837824), duration 1926, read/write 9/9 MB/s
6000: 2019-02-28 01:39:44 INFO: status: 4% (24919932928/622770257920), sparse 0% (726462464), duration 2370, read/write 14/13 MB/s
6000: 2019-02-28 01:48:11 INFO: status: 5% (31157518336/622770257920), sparse 0% (771772416), duration 2877, read/write 12/12 MB/s
6000: 2019-02-28 01:55:51 INFO: status: 6% (37395103744/622770257920), sparse 0% (794177536), duration 3337, read/write 13/13 MB/s
6000: 2019-02-28 02:02:08 INFO: status: 7% (43606081536/622770257920), sparse 0% (2925768704), duration 3714, read/write 16/10 MB/s
6000: 2019-02-28 02:07:05 INFO: status: 8% (49828462592/622770257920), sparse 0% (6079778816), duration 4011, read/write 20/10 MB/s
6000: 2019-02-28 02:12:39 INFO: status: 9% (56073650176/622770257920), sparse 1% (9208709120), duration 4345, read/write 18/9 MB/s
6000: 2019-02-28 02:17:33 INFO: status: 10% (62303633408/622770257920), sparse 1% (12329951232), duration 4639, read/write 21/10 MB/s
6000: 2019-02-28 02:19:51 INFO: status: 11% (68518412288/622770257920), sparse 2% (15431639040), duration 4777, read/write 45/22 MB/s
6000: 2019-02-28 02:22:25 INFO: status: 12% (74782605312/622770257920), sparse 2% (18547863552), duration 4931, read/write 40/20 MB/s
6000: 2019-02-28 02:26:13 INFO: status: 13% (80966975488/622770257920), sparse 3% (21642326016), duration 5159, read/write 27/13 MB/s
6000: 2019-02-28 02:31:16 INFO: status: 14% (87238770688/622770257920), sparse 3% (24802742272), duration 5462, read/write 20/10 MB/s
6000: 2019-02-28 02:33:50 INFO: status: 15% (93565091840/622770257920), sparse 4% (28831207424), duration 5616, read/write 41/14 MB/s
6000: 2019-02-28 02:33:58 INFO: status: 16% (99906486272/622770257920), sparse 5% (35172601856), duration 5624, read/write 792/0 MB/s
6000: 2019-02-28 02:34:06 INFO: status: 17% (106389045248/622770257920), sparse 6% (41655160832), duration 5632, read/write 810/0 MB/s
6000: 2019-02-28 02:34:13 INFO: status: 18% (112608018432/622770257920), sparse 7% (47874125824), duration 5639, read/write 888/0 MB/s
6000: 2019-02-28 02:34:22 INFO: status: 19% (118684254208/622770257920), sparse 8% (53950361600), duration 5648, read/write 675/0 MB/s
6000: 2019-02-28 02:34:32 INFO: status: 20% (124720513024/622770257920), sparse 9% (59986620416), duration 5658, read/write 603/0 MB/s
6000: 2019-02-28 02:34:42 INFO: status: 21% (131303866368/622770257920), sparse 10% (66569973760), duration 5668, read/write 658/0 MB/s
6000: 2019-02-28 02:34:51 INFO: status: 22% (137300410368/622770257920), sparse 11% (72566517760), duration 5677, read/write 666/0 MB/s
6000: 2019-02-28 02:35:01 INFO: status: 23% (143837364224/622770257920), sparse 12% (79103471616), duration 5687, read/write 653/0 MB/s
6000: 2019-02-28 02:35:11 INFO: status: 24% (149618032640/622770257920), sparse 13% (84884140032), duration 5697, read/write 578/0 MB/s
6000: 2019-02-28 02:35:20 INFO: status: 25% (156077916160/622770257920), sparse 14% (91344023552), duration 5706, read/write 717/0 MB/s
6000: 2019-02-28 02:35:30 INFO: status: 26% (162311962624/622770257920), sparse 15% (97578070016), duration 5716, read/write 623/0 MB/s
6000: 2019-02-28 02:35:41 INFO: status: 27% (168624783360/622770257920), sparse 16% (103890890752), duration 5727, read/write 573/0 MB/s
6000: 2019-02-28 02:35:50 INFO: status: 28% (174584692736/622770257920), sparse 17% (109850796032), duration 5736, read/write 662/0 MB/s
6000: 2019-02-28 02:36:00 INFO: status: 29% (180736229376/622770257920), sparse 18% (116002332672), duration 5746, read/write 615/0 MB/s
6000: 2019-02-28 02:36:11 INFO: status: 30% (187030634496/622770257920), sparse 19% (122296737792), duration 5757, read/write 572/0 MB/s
6000: 2019-02-28 02:36:21 INFO: status: 31% (193775665152/622770257920), sparse 20% (129041768448), duration 5767, read/write 674/0 MB/s
6000: 2019-02-28 02:36:32 INFO: status: 32% (199822409728/622770257920), sparse 21% (135088513024), duration 5778, read/write 549/0 MB/s
6000: 2019-02-28 02:36:41 INFO: status: 33% (205642006528/622770257920), sparse 22% (140908109824), duration 5787, read/write 646/0 MB/s
6000: 2019-02-28 02:36:52 INFO: status: 34% (211755466752/622770257920), sparse 23% (147021570048), duration 5798, read/write 555/0 MB/s
6000: 2019-02-28 02:37:02 INFO: status: 35% (218664927232/622770257920), sparse 24% (153931030528), duration 5808, read/write 690/0 MB/s
6000: 2019-02-28 02:37:11 INFO: status: 36% (224393166848/622770257920), sparse 25% (159659270144), duration 5817, read/write 636/0 MB/s
6000: 2019-02-28 02:37:21 INFO: status: 37% (230927499264/622770257920), sparse 26% (166193602560), duration 5827, read/write 653/0 MB/s
6000: 2019-02-28 02:37:29 INFO: status: 38% (236880461824/622770257920), sparse 27% (172146565120), duration 5835, read/write 744/0 MB/s
6000: 2019-02-28 02:37:40 INFO: status: 39% (243509755904/622770257920), sparse 28% (178775859200), duration 5846, read/write 602/0 MB/s
6000: 2019-02-28 02:37:50 INFO: status: 40% (249842499584/622770257920), sparse 29% (185108602880), duration 5856, read/write 633/0 MB/s
6000: 2019-02-28 02:37:57 INFO: status: 41% (255642107904/622770257920), sparse 30% (190908211200), duration 5863, read/write 828/0 MB/s
6000: 2019-02-28 02:38:08 INFO: status: 42% (262000869376/622770257920), sparse 31% (197266972672), duration 5874, read/write 578/0 MB/s
6000: 2019-02-28 02:38:17 INFO: status: 43% (268547194880/622770257920), sparse 32% (203813298176), duration 5883, read/write 727/0 MB/s
6000: 2019-02-28 02:38:24 INFO: status: 44% (274864799744/622770257920), sparse 33% (210130903040), duration 5890, read/write 902/0 MB/s
6000: 2019-02-28 02:38:32 INFO: status: 45% (280971116544/622770257920), sparse 34% (216237219840), duration 5898, read/write 763/0 MB/s
6000: 2019-02-28 02:38:40 INFO: status: 46% (286995382272/622770257920), sparse 35% (222261485568), duration 5906, read/write 753/0 MB/s
6000: 2019-02-28 02:38:48 INFO: status: 47% (293382127616/622770257920), sparse 36% (228648230912), duration 5914, read/write 798/0 MB/s
6000: 2019-02-28 02:38:55 INFO: status: 48% (299619713024/622770257920), sparse 37% (234885816320), duration 5921, read/write 891/0 MB/s
6000: 2019-02-28 02:39:03 INFO: status: 49% (305865359360/622770257920), sparse 38% (241131462656), duration 5929, read/write 780/0 MB/s
6000: 2019-02-28 02:39:12 INFO: status: 50% (311604674560/622770257920), sparse 39% (246870777856), duration 5938, read/write 637/0 MB/s
6000: 2019-02-28 02:39:24 INFO: status: 51% (318221320192/622770257920), sparse 40% (253487423488), duration 5950, read/write 551/0 MB/s
6000: 2019-02-28 02:39:33 INFO: status: 52% (324376068096/622770257920), sparse 41% (259642171392), duration 5959, read/write 683/0 MB/s
6000: 2019-02-28 02:39:40 INFO: status: 53% (330400792576/622770257920), sparse 42% (265666895872), duration 5966, read/write 860/0 MB/s
6000: 2019-02-28 02:39:49 INFO: status: 54% (336519888896/622770257920), sparse 43% (271785992192), duration 5975, read/write 679/0 MB/s
6000: 2019-02-28 02:39:57 INFO: status: 55% (342970662912/622770257920), sparse 44% (278236766208), duration 5983, read/write 806/0 MB/s
6000: 2019-02-28 02:40:03 INFO: status: 56% (348984049664/622770257920), sparse 45% (284250152960), duration 5989, read/write 1002/0 MB/s
6000: 2019-02-28 02:40:12 INFO: status: 57% (355800055808/622770257920), sparse 46% (291066159104), duration 5998, read/write 757/0 MB/s
6000: 2019-02-28 02:40:19 INFO: status: 58% (361216999424/622770257920), sparse 47% (296483102720), duration 6005, read/write 773/0 MB/s
6000: 2019-02-28 02:40:29 INFO: status: 59% (367500525568/622770257920), sparse 48% (302766628864), duration 6015, read/write 628/0 MB/s
6000: 2019-02-28 02:40:37 INFO: status: 60% (373835694080/622770257920), sparse 49% (309101797376), duration 6023, read/write 791/0 MB/s
6000: 2019-02-28 02:40:47 INFO: status: 61% (380248391680/622770257920), sparse 50% (315514494976), duration 6033, read/write 641/0 MB/s
6000: 2019-02-28 02:40:56 INFO: status: 62% (386613772288/622770257920), sparse 51% (321879875584), duration 6042, read/write 707/0 MB/s
6000: 2019-02-28 02:41:04 INFO: status: 63% (393072738304/622770257920), sparse 52% (328338841600), duration 6050, read/write 807/0 MB/s
6000: 2019-02-28 02:41:11 INFO: status: 64% (398657257472/622770257920), sparse 53% (333923360768), duration 6057, read/write 797/0 MB/s
6000: 2019-02-28 02:41:20 INFO: status: 65% (405237727232/622770257920), sparse 54% (340503830528), duration 6066, read/write 731/0 MB/s
6000: 2019-02-28 02:41:29 INFO: status: 66% (411244756992/622770257920), sparse 55% (346510860288), duration 6075, read/write 667/0 MB/s
6000: 2019-02-28 02:41:38 INFO: status: 67% (417780596736/622770257920), sparse 56% (353046700032), duration 6084, read/write 726/0 MB/s
6000: 2019-02-28 02:41:45 INFO: status: 68% (424056979456/622770257920), sparse 57% (359323082752), duration 6091, read/write 896/0 MB/s
6000: 2019-02-28 02:41:53 INFO: status: 69% (430218412032/622770257920), sparse 58% (365484515328), duration 6099, read/write 770/0 MB/s
6000: 2019-02-28 02:42:02 INFO: status: 70% (436334034944/622770257920), sparse 59% (371600138240), duration 6108, read/write 679/0 MB/s
6000: 2019-02-28 02:42:10 INFO: status: 71% (442243416064/622770257920), sparse 60% (377509519360), duration 6116, read/write 738/0 MB/s
6000: 2019-02-28 02:42:20 INFO: status: 72% (449058308096/622770257920), sparse 61% (384324411392), duration 6126, read/write 681/0 MB/s
6000: 2019-02-28 02:42:30 INFO: status: 73% (455324139520/622770257920), sparse 62% (390590242816), duration 6136, read/write 626/0 MB/s
6000: 2019-02-28 02:42:37 INFO: status: 74% (461016268800/622770257920), sparse 63% (396282372096), duration 6143, read/write 813/0 MB/s
6000: 2019-02-28 02:42:46 INFO: status: 75% (467120029696/622770257920), sparse 64% (402386132992), duration 6152, read/write 678/0 MB/s
6000: 2019-02-28 02:42:54 INFO: status: 76% (473469616128/622770257920), sparse 65% (408735719424), duration 6160, read/write 793/0 MB/s
6000: 2019-02-28 02:43:01 INFO: status: 77% (479824707584/622770257920), sparse 66% (415090810880), duration 6167, read/write 907/0 MB/s
6000: 2019-02-28 02:43:10 INFO: status: 78% (486193758208/622770257920), sparse 67% (421459861504), duration 6176, read/write 707/0 MB/s
6000: 2019-02-28 02:43:19 INFO: status: 79% (492270649344/622770257920), sparse 68% (427536752640), duration 6185, read/write 675/0 MB/s
6000: 2019-02-28 02:43:27 INFO: status: 80% (498542575616/622770257920), sparse 69% (433808678912), duration 6193, read/write 783/0 MB/s
6000: 2019-02-28 02:43:36 INFO: status: 81% (504597512192/622770257920), sparse 70% (439863615488), duration 6202, read/write 672/0 MB/s
6000: 2019-02-28 02:43:45 INFO: status: 82% (511249350656/622770257920), sparse 71% (446515453952), duration 6211, read/write 739/0 MB/s
6000: 2019-02-28 02:43:54 INFO: status: 83% (517192351744/622770257920), sparse 72% (452458455040), duration 6220, read/write 660/0 MB/s
6000: 2019-02-28 02:44:04 INFO: status: 84% (523888885760/622770257920), sparse 73% (459154989056), duration 6230, read/write 669/0 MB/s
6000: 2019-02-28 02:44:10 INFO: status: 85% (529680760832/622770257920), sparse 74% (464946864128), duration 6236, read/write 965/0 MB/s
6000: 2019-02-28 02:44:18 INFO: status: 86% (536231149568/622770257920), sparse 75% (471497252864), duration 6244, read/write 818/0 MB/s
6000: 2019-02-28 02:44:27 INFO: status: 87% (542064574464/622770257920), sparse 76% (477330677760), duration 6253, read/write 648/0 MB/s
6000: 2019-02-28 02:44:37 INFO: status: 88% (548319789056/622770257920), sparse 77% (483585892352), duration 6263, read/write 625/0 MB/s
6000: 2019-02-28 02:44:45 INFO: status: 89% (554933223424/622770257920), sparse 78% (490199326720), duration 6271, read/write 826/0 MB/s
6000: 2019-02-28 02:44:53 INFO: status: 90% (560650911744/622770257920), sparse 79% (495917015040), duration 6279, read/write 714/0 MB/s
6000: 2019-02-28 02:45:02 INFO: status: 91% (567427858432/622770257920), sparse 80% (502693961728), duration 6288, read/write 752/0 MB/s
6000: 2019-02-28 02:45:09 INFO: status: 92% (573400678400/622770257920), sparse 81% (508666781696), duration 6295, read/write 853/0 MB/s
6000: 2019-02-28 02:45:17 INFO: status: 93% (579725557760/622770257920), sparse 82% (514991661056), duration 6303, read/write 790/0 MB/s
6000: 2019-02-28 02:45:25 INFO: status: 94% (585505439744/622770257920), sparse 83% (520771543040), duration 6311, read/write 722/0 MB/s
6000: 2019-02-28 02:45:35 INFO: status: 95% (591827894272/622770257920), sparse 84% (527093997568), duration 6321, read/write 632/0 MB/s
6000: 2019-02-28 02:45:43 INFO: status: 96% (598421471232/622770257920), sparse 85% (533687574528), duration 6329, read/write 824/0 MB/s
6000: 2019-02-28 02:45:52 INFO: status: 97% (604676620288/622770257920), sparse 86% (539942723584), duration 6338, read/write 695/0 MB/s
6000: 2019-02-28 02:46:00 INFO: status: 98% (610330673152/622770257920), sparse 87% (545596776448), duration 6346, read/write 706/0 MB/s
6000: 2019-02-28 02:46:07 INFO: status: 99% (616750907392/622770257920), sparse 88% (552017010688), duration 6353, read/write 917/0 MB/s
6000: 2019-02-28 02:46:17 INFO: status: 100% (622770257920/622770257920), sparse 89% (558036357120), duration 6363, read/write 601/0 MB/s
6000: 2019-02-28 02:46:17 INFO: transferred 622770 MB in 6363 seconds (97 MB/s)
6000: 2019-02-28 02:46:17 INFO: archive file size: 46.60GB
6000: 2019-02-28 02:46:19 INFO: Finished Backup of VM 6000 (02:46:16)
I have a USB attached to one of the nodes , for a dedicated backup of a few VMs (on the same host, so no network here, just plain USB connection)
it was taking over 2 and half hours to backup 46 GB, so I changed the backup to the local hard drives and still takes a long time
Actually, there is no difference to when it was going to the USB. If anything a little longer.
The other backups I run to either local or USB run fine. (in relation space / time)
I have also noticed that the VMs that take a long time to backup (like 6000) are also running quite slow.
Questions are:
1: What impacts the speed of the backup if the hard drive (usb or local) are not otherwise utilized, like in my case, running at midnight and ALL other backup jobs are stopped for testing.
2: Does the performance of the VM itself has anything to do with the speed of the backup? if so, how can I troubleshoot why the VMs is slow, nothing has changed, no software, nothing new.. I just happened.
I putting here the detailed log of the last 'slow' backup for information in case someone understand anything here.
This is the backup last night that took 2:33 for 46.62 gb.
=================================================================================
Detailed backup logs:
vzdump 6000 --quiet 1 --mailto mvazquez@xxxxxxx.com --compress lzo --storage local --mode snapshot --mailnotification always
6000: 2019-02-28 00:00:03 INFO: Starting Backup of VM 6000 (qemu)
6000: 2019-02-28 00:00:03 INFO: status = running
6000: 2019-02-28 00:00:04 INFO: file /etc/pve/replication.cfg line 4 (section '1001-1') - unable to parse value of 'source': unexpected property 'source'
6000: 2019-02-28 00:00:04 INFO: file /etc/pve/replication.cfg line 11 (section '9035-0') - unable to parse value of 'source': unexpected property 'source'
6000: 2019-02-28 00:00:04 INFO: file /etc/pve/replication.cfg line 15 (section '98000-0') - unable to parse value of 'source': unexpected property 'source'
6000: 2019-02-28 00:00:04 INFO: file /etc/pve/replication.cfg line 19 (section '99401-0') - unable to parse value of 'source': unexpected property 'source'
6000: 2019-02-28 00:00:04 INFO: file /etc/pve/replication.cfg line 23 (section '999402-0') - unable to parse value of 'source': unexpected property 'source'
6000: 2019-02-28 00:00:04 INFO: update VM 6000: -lock backup
6000: 2019-02-28 00:00:04 INFO: VM Name: w2012DocuPhase
6000: 2019-02-28 00:00:04 INFO: include disk 'sata0' 'local-zfs:vm-6000-disk-1' 80G
6000: 2019-02-28 00:00:04 INFO: include disk 'sata1' 'local-zfs:vm-6000-disk-2' 500G
6000: 2019-02-28 00:00:04 INFO: backup mode: snapshot
6000: 2019-02-28 00:00:04 INFO: ionice priority: 7
6000: 2019-02-28 00:00:04 INFO: creating archive '/var/lib/vz/dump/vzdump-qemu-6000-2019_02_28-00_00_03.vma.lzo'
6000: 2019-02-28 01:00:04 ERROR: VM 6000 qmp command 'guest-fsfreeze-freeze' failed - got timeout
6000: 2019-02-28 01:00:14 ERROR: VM 6000 qmp command 'guest-fsfreeze-thaw' failed - got timeout
6000: 2019-02-28 01:00:14 INFO: started backup task 'fdf6aa69-ddd5-4a01-9fee-a533ff8c6fc9'
6000: 2019-02-28 01:00:18 INFO: status: 0% (171048960/622770257920), sparse 0% (49229824), duration 4, read/write 42/30 MB/s
6000: 2019-02-28 01:10:39 INFO: status: 1% (6241386496/622770257920), sparse 0% (185667584), duration 625, read/write 9/9 MB/s
6000: 2019-02-28 01:21:43 INFO: status: 2% (12475170816/622770257920), sparse 0% (468197376), duration 1289, read/write 9/8 MB/s
6000: 2019-02-28 01:32:20 INFO: status: 3% (18693750784/622770257920), sparse 0% (565837824), duration 1926, read/write 9/9 MB/s
6000: 2019-02-28 01:39:44 INFO: status: 4% (24919932928/622770257920), sparse 0% (726462464), duration 2370, read/write 14/13 MB/s
6000: 2019-02-28 01:48:11 INFO: status: 5% (31157518336/622770257920), sparse 0% (771772416), duration 2877, read/write 12/12 MB/s
6000: 2019-02-28 01:55:51 INFO: status: 6% (37395103744/622770257920), sparse 0% (794177536), duration 3337, read/write 13/13 MB/s
6000: 2019-02-28 02:02:08 INFO: status: 7% (43606081536/622770257920), sparse 0% (2925768704), duration 3714, read/write 16/10 MB/s
6000: 2019-02-28 02:07:05 INFO: status: 8% (49828462592/622770257920), sparse 0% (6079778816), duration 4011, read/write 20/10 MB/s
6000: 2019-02-28 02:12:39 INFO: status: 9% (56073650176/622770257920), sparse 1% (9208709120), duration 4345, read/write 18/9 MB/s
6000: 2019-02-28 02:17:33 INFO: status: 10% (62303633408/622770257920), sparse 1% (12329951232), duration 4639, read/write 21/10 MB/s
6000: 2019-02-28 02:19:51 INFO: status: 11% (68518412288/622770257920), sparse 2% (15431639040), duration 4777, read/write 45/22 MB/s
6000: 2019-02-28 02:22:25 INFO: status: 12% (74782605312/622770257920), sparse 2% (18547863552), duration 4931, read/write 40/20 MB/s
6000: 2019-02-28 02:26:13 INFO: status: 13% (80966975488/622770257920), sparse 3% (21642326016), duration 5159, read/write 27/13 MB/s
6000: 2019-02-28 02:31:16 INFO: status: 14% (87238770688/622770257920), sparse 3% (24802742272), duration 5462, read/write 20/10 MB/s
6000: 2019-02-28 02:33:50 INFO: status: 15% (93565091840/622770257920), sparse 4% (28831207424), duration 5616, read/write 41/14 MB/s
6000: 2019-02-28 02:33:58 INFO: status: 16% (99906486272/622770257920), sparse 5% (35172601856), duration 5624, read/write 792/0 MB/s
6000: 2019-02-28 02:34:06 INFO: status: 17% (106389045248/622770257920), sparse 6% (41655160832), duration 5632, read/write 810/0 MB/s
6000: 2019-02-28 02:34:13 INFO: status: 18% (112608018432/622770257920), sparse 7% (47874125824), duration 5639, read/write 888/0 MB/s
6000: 2019-02-28 02:34:22 INFO: status: 19% (118684254208/622770257920), sparse 8% (53950361600), duration 5648, read/write 675/0 MB/s
6000: 2019-02-28 02:34:32 INFO: status: 20% (124720513024/622770257920), sparse 9% (59986620416), duration 5658, read/write 603/0 MB/s
6000: 2019-02-28 02:34:42 INFO: status: 21% (131303866368/622770257920), sparse 10% (66569973760), duration 5668, read/write 658/0 MB/s
6000: 2019-02-28 02:34:51 INFO: status: 22% (137300410368/622770257920), sparse 11% (72566517760), duration 5677, read/write 666/0 MB/s
6000: 2019-02-28 02:35:01 INFO: status: 23% (143837364224/622770257920), sparse 12% (79103471616), duration 5687, read/write 653/0 MB/s
6000: 2019-02-28 02:35:11 INFO: status: 24% (149618032640/622770257920), sparse 13% (84884140032), duration 5697, read/write 578/0 MB/s
6000: 2019-02-28 02:35:20 INFO: status: 25% (156077916160/622770257920), sparse 14% (91344023552), duration 5706, read/write 717/0 MB/s
6000: 2019-02-28 02:35:30 INFO: status: 26% (162311962624/622770257920), sparse 15% (97578070016), duration 5716, read/write 623/0 MB/s
6000: 2019-02-28 02:35:41 INFO: status: 27% (168624783360/622770257920), sparse 16% (103890890752), duration 5727, read/write 573/0 MB/s
6000: 2019-02-28 02:35:50 INFO: status: 28% (174584692736/622770257920), sparse 17% (109850796032), duration 5736, read/write 662/0 MB/s
6000: 2019-02-28 02:36:00 INFO: status: 29% (180736229376/622770257920), sparse 18% (116002332672), duration 5746, read/write 615/0 MB/s
6000: 2019-02-28 02:36:11 INFO: status: 30% (187030634496/622770257920), sparse 19% (122296737792), duration 5757, read/write 572/0 MB/s
6000: 2019-02-28 02:36:21 INFO: status: 31% (193775665152/622770257920), sparse 20% (129041768448), duration 5767, read/write 674/0 MB/s
6000: 2019-02-28 02:36:32 INFO: status: 32% (199822409728/622770257920), sparse 21% (135088513024), duration 5778, read/write 549/0 MB/s
6000: 2019-02-28 02:36:41 INFO: status: 33% (205642006528/622770257920), sparse 22% (140908109824), duration 5787, read/write 646/0 MB/s
6000: 2019-02-28 02:36:52 INFO: status: 34% (211755466752/622770257920), sparse 23% (147021570048), duration 5798, read/write 555/0 MB/s
6000: 2019-02-28 02:37:02 INFO: status: 35% (218664927232/622770257920), sparse 24% (153931030528), duration 5808, read/write 690/0 MB/s
6000: 2019-02-28 02:37:11 INFO: status: 36% (224393166848/622770257920), sparse 25% (159659270144), duration 5817, read/write 636/0 MB/s
6000: 2019-02-28 02:37:21 INFO: status: 37% (230927499264/622770257920), sparse 26% (166193602560), duration 5827, read/write 653/0 MB/s
6000: 2019-02-28 02:37:29 INFO: status: 38% (236880461824/622770257920), sparse 27% (172146565120), duration 5835, read/write 744/0 MB/s
6000: 2019-02-28 02:37:40 INFO: status: 39% (243509755904/622770257920), sparse 28% (178775859200), duration 5846, read/write 602/0 MB/s
6000: 2019-02-28 02:37:50 INFO: status: 40% (249842499584/622770257920), sparse 29% (185108602880), duration 5856, read/write 633/0 MB/s
6000: 2019-02-28 02:37:57 INFO: status: 41% (255642107904/622770257920), sparse 30% (190908211200), duration 5863, read/write 828/0 MB/s
6000: 2019-02-28 02:38:08 INFO: status: 42% (262000869376/622770257920), sparse 31% (197266972672), duration 5874, read/write 578/0 MB/s
6000: 2019-02-28 02:38:17 INFO: status: 43% (268547194880/622770257920), sparse 32% (203813298176), duration 5883, read/write 727/0 MB/s
6000: 2019-02-28 02:38:24 INFO: status: 44% (274864799744/622770257920), sparse 33% (210130903040), duration 5890, read/write 902/0 MB/s
6000: 2019-02-28 02:38:32 INFO: status: 45% (280971116544/622770257920), sparse 34% (216237219840), duration 5898, read/write 763/0 MB/s
6000: 2019-02-28 02:38:40 INFO: status: 46% (286995382272/622770257920), sparse 35% (222261485568), duration 5906, read/write 753/0 MB/s
6000: 2019-02-28 02:38:48 INFO: status: 47% (293382127616/622770257920), sparse 36% (228648230912), duration 5914, read/write 798/0 MB/s
6000: 2019-02-28 02:38:55 INFO: status: 48% (299619713024/622770257920), sparse 37% (234885816320), duration 5921, read/write 891/0 MB/s
6000: 2019-02-28 02:39:03 INFO: status: 49% (305865359360/622770257920), sparse 38% (241131462656), duration 5929, read/write 780/0 MB/s
6000: 2019-02-28 02:39:12 INFO: status: 50% (311604674560/622770257920), sparse 39% (246870777856), duration 5938, read/write 637/0 MB/s
6000: 2019-02-28 02:39:24 INFO: status: 51% (318221320192/622770257920), sparse 40% (253487423488), duration 5950, read/write 551/0 MB/s
6000: 2019-02-28 02:39:33 INFO: status: 52% (324376068096/622770257920), sparse 41% (259642171392), duration 5959, read/write 683/0 MB/s
6000: 2019-02-28 02:39:40 INFO: status: 53% (330400792576/622770257920), sparse 42% (265666895872), duration 5966, read/write 860/0 MB/s
6000: 2019-02-28 02:39:49 INFO: status: 54% (336519888896/622770257920), sparse 43% (271785992192), duration 5975, read/write 679/0 MB/s
6000: 2019-02-28 02:39:57 INFO: status: 55% (342970662912/622770257920), sparse 44% (278236766208), duration 5983, read/write 806/0 MB/s
6000: 2019-02-28 02:40:03 INFO: status: 56% (348984049664/622770257920), sparse 45% (284250152960), duration 5989, read/write 1002/0 MB/s
6000: 2019-02-28 02:40:12 INFO: status: 57% (355800055808/622770257920), sparse 46% (291066159104), duration 5998, read/write 757/0 MB/s
6000: 2019-02-28 02:40:19 INFO: status: 58% (361216999424/622770257920), sparse 47% (296483102720), duration 6005, read/write 773/0 MB/s
6000: 2019-02-28 02:40:29 INFO: status: 59% (367500525568/622770257920), sparse 48% (302766628864), duration 6015, read/write 628/0 MB/s
6000: 2019-02-28 02:40:37 INFO: status: 60% (373835694080/622770257920), sparse 49% (309101797376), duration 6023, read/write 791/0 MB/s
6000: 2019-02-28 02:40:47 INFO: status: 61% (380248391680/622770257920), sparse 50% (315514494976), duration 6033, read/write 641/0 MB/s
6000: 2019-02-28 02:40:56 INFO: status: 62% (386613772288/622770257920), sparse 51% (321879875584), duration 6042, read/write 707/0 MB/s
6000: 2019-02-28 02:41:04 INFO: status: 63% (393072738304/622770257920), sparse 52% (328338841600), duration 6050, read/write 807/0 MB/s
6000: 2019-02-28 02:41:11 INFO: status: 64% (398657257472/622770257920), sparse 53% (333923360768), duration 6057, read/write 797/0 MB/s
6000: 2019-02-28 02:41:20 INFO: status: 65% (405237727232/622770257920), sparse 54% (340503830528), duration 6066, read/write 731/0 MB/s
6000: 2019-02-28 02:41:29 INFO: status: 66% (411244756992/622770257920), sparse 55% (346510860288), duration 6075, read/write 667/0 MB/s
6000: 2019-02-28 02:41:38 INFO: status: 67% (417780596736/622770257920), sparse 56% (353046700032), duration 6084, read/write 726/0 MB/s
6000: 2019-02-28 02:41:45 INFO: status: 68% (424056979456/622770257920), sparse 57% (359323082752), duration 6091, read/write 896/0 MB/s
6000: 2019-02-28 02:41:53 INFO: status: 69% (430218412032/622770257920), sparse 58% (365484515328), duration 6099, read/write 770/0 MB/s
6000: 2019-02-28 02:42:02 INFO: status: 70% (436334034944/622770257920), sparse 59% (371600138240), duration 6108, read/write 679/0 MB/s
6000: 2019-02-28 02:42:10 INFO: status: 71% (442243416064/622770257920), sparse 60% (377509519360), duration 6116, read/write 738/0 MB/s
6000: 2019-02-28 02:42:20 INFO: status: 72% (449058308096/622770257920), sparse 61% (384324411392), duration 6126, read/write 681/0 MB/s
6000: 2019-02-28 02:42:30 INFO: status: 73% (455324139520/622770257920), sparse 62% (390590242816), duration 6136, read/write 626/0 MB/s
6000: 2019-02-28 02:42:37 INFO: status: 74% (461016268800/622770257920), sparse 63% (396282372096), duration 6143, read/write 813/0 MB/s
6000: 2019-02-28 02:42:46 INFO: status: 75% (467120029696/622770257920), sparse 64% (402386132992), duration 6152, read/write 678/0 MB/s
6000: 2019-02-28 02:42:54 INFO: status: 76% (473469616128/622770257920), sparse 65% (408735719424), duration 6160, read/write 793/0 MB/s
6000: 2019-02-28 02:43:01 INFO: status: 77% (479824707584/622770257920), sparse 66% (415090810880), duration 6167, read/write 907/0 MB/s
6000: 2019-02-28 02:43:10 INFO: status: 78% (486193758208/622770257920), sparse 67% (421459861504), duration 6176, read/write 707/0 MB/s
6000: 2019-02-28 02:43:19 INFO: status: 79% (492270649344/622770257920), sparse 68% (427536752640), duration 6185, read/write 675/0 MB/s
6000: 2019-02-28 02:43:27 INFO: status: 80% (498542575616/622770257920), sparse 69% (433808678912), duration 6193, read/write 783/0 MB/s
6000: 2019-02-28 02:43:36 INFO: status: 81% (504597512192/622770257920), sparse 70% (439863615488), duration 6202, read/write 672/0 MB/s
6000: 2019-02-28 02:43:45 INFO: status: 82% (511249350656/622770257920), sparse 71% (446515453952), duration 6211, read/write 739/0 MB/s
6000: 2019-02-28 02:43:54 INFO: status: 83% (517192351744/622770257920), sparse 72% (452458455040), duration 6220, read/write 660/0 MB/s
6000: 2019-02-28 02:44:04 INFO: status: 84% (523888885760/622770257920), sparse 73% (459154989056), duration 6230, read/write 669/0 MB/s
6000: 2019-02-28 02:44:10 INFO: status: 85% (529680760832/622770257920), sparse 74% (464946864128), duration 6236, read/write 965/0 MB/s
6000: 2019-02-28 02:44:18 INFO: status: 86% (536231149568/622770257920), sparse 75% (471497252864), duration 6244, read/write 818/0 MB/s
6000: 2019-02-28 02:44:27 INFO: status: 87% (542064574464/622770257920), sparse 76% (477330677760), duration 6253, read/write 648/0 MB/s
6000: 2019-02-28 02:44:37 INFO: status: 88% (548319789056/622770257920), sparse 77% (483585892352), duration 6263, read/write 625/0 MB/s
6000: 2019-02-28 02:44:45 INFO: status: 89% (554933223424/622770257920), sparse 78% (490199326720), duration 6271, read/write 826/0 MB/s
6000: 2019-02-28 02:44:53 INFO: status: 90% (560650911744/622770257920), sparse 79% (495917015040), duration 6279, read/write 714/0 MB/s
6000: 2019-02-28 02:45:02 INFO: status: 91% (567427858432/622770257920), sparse 80% (502693961728), duration 6288, read/write 752/0 MB/s
6000: 2019-02-28 02:45:09 INFO: status: 92% (573400678400/622770257920), sparse 81% (508666781696), duration 6295, read/write 853/0 MB/s
6000: 2019-02-28 02:45:17 INFO: status: 93% (579725557760/622770257920), sparse 82% (514991661056), duration 6303, read/write 790/0 MB/s
6000: 2019-02-28 02:45:25 INFO: status: 94% (585505439744/622770257920), sparse 83% (520771543040), duration 6311, read/write 722/0 MB/s
6000: 2019-02-28 02:45:35 INFO: status: 95% (591827894272/622770257920), sparse 84% (527093997568), duration 6321, read/write 632/0 MB/s
6000: 2019-02-28 02:45:43 INFO: status: 96% (598421471232/622770257920), sparse 85% (533687574528), duration 6329, read/write 824/0 MB/s
6000: 2019-02-28 02:45:52 INFO: status: 97% (604676620288/622770257920), sparse 86% (539942723584), duration 6338, read/write 695/0 MB/s
6000: 2019-02-28 02:46:00 INFO: status: 98% (610330673152/622770257920), sparse 87% (545596776448), duration 6346, read/write 706/0 MB/s
6000: 2019-02-28 02:46:07 INFO: status: 99% (616750907392/622770257920), sparse 88% (552017010688), duration 6353, read/write 917/0 MB/s
6000: 2019-02-28 02:46:17 INFO: status: 100% (622770257920/622770257920), sparse 89% (558036357120), duration 6363, read/write 601/0 MB/s
6000: 2019-02-28 02:46:17 INFO: transferred 622770 MB in 6363 seconds (97 MB/s)
6000: 2019-02-28 02:46:17 INFO: archive file size: 46.60GB
6000: 2019-02-28 02:46:19 INFO: Finished Backup of VM 6000 (02:46:16)