Huge IO delay when recovering VM

Dec 14, 2017
7
0
21
52
Hello,

Today I try to recover VM from achive and get a huge IO delay on PVE node.
Before that, everything was fine.
I noticed the following: when "space reduction due to 4K zero blocks" at end of the recovery report is great enough, I get huge IO delay.

For example, when I recover this arhive:
restore vma archive: lzop -d -c /mnt/pve/nas-backup/dump/vzdump-qemu-109-2017_12_14-13_44_36.vma.lzo|vma extract -v -r /var/tmp/vzdumptmp22120.fifo - /var/tmp/vzdumptmp22120
CFG: size: 369 name: qemu-server.conf
DEV: dev_id=1 size: 136365211648 devname: drive-scsi0
CTIME: Thu Dec 14 13:44:45 2017
Using default stripesize 64.00 KiB.
Logical volume "vm-109-disk-1" created.
new volume ID is 'main-data:vm-109-disk-1'
map 'drive-scsi0' to '/dev/sg/vm-109-disk-1' (write zeros = 0)
progress 1% (read 1363673088 bytes, duration 5 sec)
progress 2% (read 2727346176 bytes, duration 12 sec)
progress 3% (read 4091019264 bytes, duration 19 sec)
progress 4% (read 5454626816 bytes, duration 26 sec)
progress 5% (read 6818299904 bytes, duration 32 sec)
progress 6% (read 8181972992 bytes, duration 41 sec)
progress 7% (read 9545580544 bytes, duration 48 sec)
progress 8% (read 10909253632 bytes, duration 54 sec)
progress 9% (read 12272926720 bytes, duration 62 sec)
progress 10% (read 13636534272 bytes, duration 69 sec)
progress 11% (read 15000207360 bytes, duration 76 sec)
progress 12% (read 16363880448 bytes, duration 83 sec)
progress 13% (read 17727488000 bytes, duration 89 sec)
progress 14% (read 19091161088 bytes, duration 96 sec)
progress 15% (read 20454834176 bytes, duration 101 sec)
progress 16% (read 21818441728 bytes, duration 106 sec)
progress 17% (read 23182114816 bytes, duration 114 sec)
progress 18% (read 24545787904 bytes, duration 121 sec)
progress 19% (read 25909395456 bytes, duration 129 sec)
progress 20% (read 27273068544 bytes, duration 137 sec)
progress 21% (read 28636741632 bytes, duration 143 sec)
progress 22% (read 30000349184 bytes, duration 148 sec)
progress 23% (read 31364022272 bytes, duration 152 sec)
progress 24% (read 32727695360 bytes, duration 157 sec)
progress 25% (read 34091302912 bytes, duration 162 sec)
progress 26% (read 35454976000 bytes, duration 167 sec)
progress 27% (read 36818649088 bytes, duration 174 sec)
progress 28% (read 38182322176 bytes, duration 178 sec)
progress 29% (read 39545929728 bytes, duration 187 sec)
progress 30% (read 40909602816 bytes, duration 190 sec)
progress 31% (read 42273275904 bytes, duration 193 sec)
progress 32% (read 43636883456 bytes, duration 196 sec)
progress 33% (read 45000556544 bytes, duration 199 sec)
progress 34% (read 46364229632 bytes, duration 202 sec)
progress 35% (read 47727837184 bytes, duration 205 sec)
progress 36% (read 49091510272 bytes, duration 209 sec)
progress 37% (read 50455183360 bytes, duration 212 sec)
progress 38% (read 51818790912 bytes, duration 215 sec)
progress 39% (read 53182464000 bytes, duration 218 sec)
progress 40% (read 54546137088 bytes, duration 221 sec)
progress 41% (read 55909744640 bytes, duration 224 sec)
progress 42% (read 57273417728 bytes, duration 227 sec)
progress 43% (read 58637090816 bytes, duration 230 sec)
progress 44% (read 60000698368 bytes, duration 233 sec)
progress 45% (read 61364371456 bytes, duration 238 sec)
progress 46% (read 62728044544 bytes, duration 241 sec)
progress 47% (read 64091652096 bytes, duration 245 sec)
progress 48% (read 65455325184 bytes, duration 328 sec)
progress 49% (read 66818998272 bytes, duration 371 sec)
<problem started here>
progress 50% (read 68182605824 bytes, duration 422 sec)
progress 51% (read 69546278912 bytes, duration 554 sec)
progress 52% (read 70909952000 bytes, duration 686 sec)
progress 53% (read 72273625088 bytes, duration 808 sec)
progress 54% (read 73637232640 bytes, duration 898 sec)
progress 55% (read 75000905728 bytes, duration 997 sec)
progress 56% (read 76364578816 bytes, duration 1036 sec)
progress 57% (read 77728186368 bytes, duration 1042 sec)
progress 58% (read 79091859456 bytes, duration 1050 sec)
progress 59% (read 80455532544 bytes, duration 1056 sec)
progress 60% (read 81819140096 bytes, duration 1062 sec)
progress 61% (read 83182813184 bytes, duration 1068 sec)
progress 62% (read 84546486272 bytes, duration 1070 sec)
progress 63% (read 85910093824 bytes, duration 1070 sec)
progress 64% (read 87273766912 bytes, duration 1070 sec)
progress 65% (read 88637440000 bytes, duration 1070 sec)
progress 66% (read 90001047552 bytes, duration 1070 sec)
progress 67% (read 91364720640 bytes, duration 1071 sec)
progress 68% (read 92728393728 bytes, duration 1071 sec)
progress 69% (read 94092001280 bytes, duration 1071 sec)
progress 70% (read 95455674368 bytes, duration 1071 sec)
progress 71% (read 96819347456 bytes, duration 1071 sec)
progress 72% (read 98182955008 bytes, d =uration 1071 sec)
progress 73% (read 99546628096 bytes, duration 1071 sec)
progress 74% (read 100910301184 bytes, duration 1071 sec)
progress 75% (read 102273908736 bytes, duration 1071 sec)
progress 76% (read 103637581824 bytes, duration 1071 sec)
progress 77% (read 105001254912 bytes, duration 1072 sec)
progress 78% (read 106364928000 bytes, duration 1072 sec)
progress 79% (read 107728535552 bytes, duration 1072 sec)
progress 80% (read 109092208640 bytes, duration 1072 sec)
progress 81% (read 110455881728 bytes, duration 1072 sec)
progress 82% (read 111819489280 bytes, duration 1072 sec)
progress 83% (read 113183162368 bytes, duration 1072 sec)
progress 84% (read 114546835456 bytes, duration 1072 sec)
progress 85% (read 115910443008 bytes, duration 1072 sec)
progress 86% (read 117274116096 bytes, duration 1072 sec)
progress 87% (read 118637789184 bytes, duration 1072 sec)
progress 88% (read 120001396736 bytes, duration 1072 sec)
progress 89% (read 121365069824 bytes, duration 1073 sec)
progress 90% (read 122728742912 bytes, duration 1073 sec)
progress 91% (read 124092350464 bytes, duration 1073 sec)
progress 92% (read 125456023552 bytes, duration 1073 sec)
progress 93% (read 126819696640 bytes, duration 1073 sec)
progress 94% (read 128183304192 bytes, duration 1073 sec)
progress 95% (read 129546977280 bytes, duration 1073 sec)
progress 96% (read 130910650368 bytes, duration 1073 sec)
progress 97% (read 132274257920 bytes, duration 1073 sec)
progress 98% (read 133637931008 bytes, duration 1073 sec)
progress 99% (read 135001604096 bytes, duration 1073 sec)
progress 100% (read 136365211648 bytes, duration 1073 sec)
total bytes read 136365211648, sparse bytes 75825487872 (55.6%)
space reduction due to 4K zero blocks 37.1%
TASK OK
At the 50% recovering process I get the 50% and greater IO delay on node. All guest VMs is stuck, web-interface is unresponsible.
The "space reduction" is great enough = 37%.

However, when I recover other archives, I get no problem (when space reduction is quite small).
restore vma archive: lzop -d -c /mnt/pve/nas-backup/dump/vzdump-qemu-102-2017_12_08-06_15_02.vma.lzo|vma extract -v -r /var/tmp/vzdumptmp27425.fifo - /var/tmp/vzdumptmp27425
CFG: size: 403 name: qemu-server.conf
DEV: dev_id=1 size: 171798691840 devname: drive-scsi0
CTIME: Fri Dec 8 06:15:08 2017
Using default stripesize 64.00 KiB.
Logical volume "vm-111-disk-1" created.
new volume ID is 'main-data:vm-111-disk-1'
map 'drive-scsi0' to '/dev/sg/vm-111-disk-1' (write zeros = 0)
progress 1% (read 1718026240 bytes, duration 9 sec)
progress 2% (read 3435986944 bytes, duration 18 sec)
progress 3% (read 5154013184 bytes, duration 26 sec)
progress 4% (read 6871973888 bytes, duration 34 sec)
progress 5% (read 8589934592 bytes, duration 43 sec)
progress 6% (read 10307960832 bytes, duration 53 sec)
progress 7% (read 12025921536 bytes, duration 65 sec)
progress 8% (read 13743947776 bytes, duration 78 sec)
progress 9% (read 15461908480 bytes, duration 86 sec)
progress 10% (read 17179869184 bytes, duration 94 sec)
progress 11% (read 18897895424 bytes, duration 105 sec)
progress 12% (read 20615856128 bytes, duration 115 sec)
progress 13% (read 22333882368 bytes, duration 124 sec)
progress 14% (read 24051843072 bytes, duration 135 sec)
progress 15% (read 25769803776 bytes, duration 144 sec)
progress 16% (read 27487830016 bytes, duration 155 sec)
progress 17% (read 29205790720 bytes, duration 162 sec)
progress 18% (read 30923816960 bytes, duration 171 sec)
progress 19% (read 32641777664 bytes, duration 181 sec)
progress 20% (read 34359738368 bytes, duration 191 sec)
progress 21% (read 36077764608 bytes, duration 200 sec)
progress 22% (read 37795725312 bytes, duration 209 sec)
progress 23% (read 39513751552 bytes, duration 219 sec)
progress 24% (read 41231712256 bytes, duration 231 sec)
progress 25% (read 42949672960 bytes, duration 243 sec)
progress 26% (read 44667699200 bytes, duration 254 sec)
progress 27% (read 46385659904 bytes, duration 264 sec)
progress 28% (read 48103686144 bytes, duration 272 sec)
progress 29% (read 49821646848 bytes, duration 284 sec)
progress 30% (read 51539607552 bytes, duration 298 sec)
progress 31% (read 53257633792 bytes, duration 305 sec)
progress 32% (read 54975594496 bytes, duration 314 sec)
progress 33% (read 56693620736 bytes, duration 325 sec)
progress 34% (read 58411581440 bytes, duration 333 sec)
progress 35% (read 60129542144 bytes, duration 346 sec)
progress 36% (read 61847568384 bytes, duration 359 sec)
progress 37% (read 63565529088 bytes, duration 366 sec)
progress 38% (read 65283555328 bytes, duration 379 sec)
progress 39% (read 67001516032 bytes, duration 387 sec)
progress 40% (read 68719476736 bytes, duration 395 sec)
progress 41% (read 70437502976 bytes, duration 402 sec)
progress 42% (read 72155463680 bytes, duration 413 sec)
progress 43% (read 73873489920 bytes, duration 421 sec)
progress 44% (read 75591450624 bytes, duration 435 sec)
progress 45% (read 77309411328 bytes, duration 446 sec)
progress 46% (read 79027437568 bytes, duration 458 sec)
progress 47% (read 80745398272 bytes, duration 465 sec)
progress 48% (read 82463424512 bytes, duration 473 sec)
progress 49% (read 84181385216 bytes, duration 479 sec)
progress 50% (read 85899345920 bytes, duration 488 sec)
progress 51% (read 87617372160 bytes, duration 495 sec)
progress 52% (read 89335332864 bytes, duration 503 sec)
progress 53% (read 91053359104 bytes, duration 509 sec)
progress 54% (read 92771319808 bytes, duration 516 sec)
progress 55% (read 94489280512 bytes, duration 526 sec)
progress 56% (read 96207306752 bytes, duration 534 sec)
progress 57% (read 97925267456 bytes, duration 545 sec)
progress 58% (read 99643293696 bytes, duration 555 sec)
progress 59% (read 101361254400 bytes, duration 562 sec)
progress 60% (read 103079215104 bytes, duration 574 sec)
progress 61% (read 104797241344 bytes, duration 584 sec)
progress 62% (read 106515202048 bytes, duration 592 sec)
progress 63% (read 108233228288 bytes, duration 601 sec)
progress 64% (read 109951188992 bytes, duration 614 sec)
progress 65% (read 111669149696 bytes, duration 625 sec)
progress 66% (read 113387175936 bytes, duration 631 sec)
progress 67% (read 115105136640 bytes, duration 637 sec)
progress 68% (read 116823162880 bytes, duration 647 sec)
progress 69% (read 118541123584 bytes, duration 659 sec)
progress 70% (read 120259084288 bytes, duration 665 sec)
progress 71% (read 121977110528 bytes, duration 671 sec)
progress 72% (read 123695071232 bytes, duration 680 sec)
progress 73% (read 125413097472 bytes, duration 689 sec)
progress 74% (read 127131058176 bytes, duration 699 sec)
progress 75% (read 128849018880 bytes, duration 708 sec)
progress 76% (read 130567045120 bytes, duration 717 sec)
progress 77% (read 132285005824 bytes, duration 725 sec)
progress 78% (read 134003032064 bytes, duration 733 sec)
progress 79% (read 135720992768 bytes, duration 742 sec)
progress 80% (read 137438953472 bytes, duration 752 sec)
progress 81% (read 139156979712 bytes, duration 763 sec)
progress 82% (read 140874940416 bytes, duration 773 sec)
progress 83% (read 142592966656 bytes, duration 780 sec)
progress 84% (read 144310927360 bytes, duration 789 sec)
progress 85% (read 146028888064 bytes, duration 795 sec)
progress 86% (read 147746914304 bytes, duration 803 sec)
progress 87% (read 149464875008 bytes, duration 808 sec)
progress 88% (read 151182901248 bytes, duration 818 sec)
progress 89% (read 152900861952 bytes, duration 826 sec)
progress 90% (read 154618822656 bytes, duration 838 sec)
progress 91% (read 156336848896 bytes, duration 852 sec)
progress 92% (read 158054809600 bytes, duration 867 sec)
progress 93% (read 159772835840 bytes, duration 876 sec)
progress 94% (read 161490796544 bytes, duration 884 sec)
progress 95% (read 163208757248 bytes, duration 893 sec)
progress 96% (read 164926783488 bytes, duration 902 sec)
progress 97% (read 166644744192 bytes, duration 911 sec)
progress 98% (read 168362770432 bytes, duration 924 sec)
progress 99% (read 170080731136 bytes, duration 932 sec)
progress 100% (read 171798691840 bytes, duration 938 sec)
total bytes read 171798691840, sparse bytes 1617276928 (0.941%)
space reduction due to 4K zero blocks 0.203%
TASK OK

Even with large sparse bytes:
restore vma archive: lzop -d -c /mnt/pve/nas-backup/dump/vzdump-qemu-108-2017_12_11-18_24_38.vma.lzo|vma extract -v -r /var/tmp/vzdumptmp45816.fifo - /var/tmp/vzdumptmp45816
CFG: size: 363 name: qemu-server.conf
DEV: dev_id=1 size: 136365211648 devname: drive-scsi0
CTIME: Mon Dec 11 18:24:39 2017
Using default stripesize 64.00 KiB.
Logical volume "vm-111-disk-1" created.
new volume ID is 'main-data:vm-111-disk-1'
map 'drive-scsi0' to '/dev/sg/vm-111-disk-1' (write zeros = 0)
progress 1% (read 1363673088 bytes, duration 5 sec)
progress 2% (read 2727346176 bytes, duration 9 sec)
progress 3% (read 4091019264 bytes, duration 9 sec)
progress 4% (read 5454626816 bytes, duration 9 sec)
progress 5% (read 6818299904 bytes, duration 10 sec)
progress 6% (read 8181972992 bytes, duration 10 sec)
progress 7% (read 9545580544 bytes, duration 10 sec)
progress 8% (read 10909253632 bytes, duration 10 sec)
progress 9% (read 12272926720 bytes, duration 10 sec)
progress 10% (read 13636534272 bytes, duration 10 sec)
progress 11% (read 15000207360 bytes, duration 10 sec)
progress 12% (read 16363880448 bytes, duration 11 sec)
progress 13% (read 17727488000 bytes, duration 11 sec)
progress 14% (read 19091161088 bytes, duration 11 sec)
progress 15% (read 20454834176 bytes, duration 11 sec)
progress 16% (read 21818441728 bytes, duration 11 sec)
progress 17% (read 23182114816 bytes, duration 11 sec)
progress 18% (read 24545787904 bytes, duration 11 sec)
progress 19% (read 25909395456 bytes, duration 11 sec)
progress 20% (read 27273068544 bytes, duration 11 sec)
progress 21% (read 28636741632 bytes, duration 12 sec)
progress 22% (read 30000349184 bytes, duration 12 sec)
progress 23% (read 31364022272 bytes, duration 12 sec)
progress 24% (read 32727695360 bytes, duration 12 sec)
progress 25% (read 34091302912 bytes, duration 12 sec)
progress 26% (read 35454976000 bytes, duration 12 sec)
progress 27% (read 36818649088 bytes, duration 12 sec)
progress 28% (read 38182322176 bytes, duration 12 sec)
progress 29% (read 39545929728 bytes, duration 12 sec)
progress 30% (read 40909602816 bytes, duration 12 sec)
progress 31% (read 42273275904 bytes, duration 13 sec)
progress 32% (read 43636883456 bytes, duration 13 sec)
progress 33% (read 45000556544 bytes, duration 13 sec)
progress 34% (read 46364229632 bytes, duration 13 sec)
progress 35% (read 47727837184 bytes, duration 13 sec)
progress 36% (read 49091510272 bytes, duration 13 sec)
progress 37% (read 50455183360 bytes, duration 13 sec)
progress 38% (read 51818790912 bytes, duration 13 sec)
progress 39% (read 53182464000 bytes, duration 13 sec)
progress 40% (read 54546137088 bytes, duration 14 sec)
progress 41% (read 55909744640 bytes, duration 14 sec)
progress 42% (read 57273417728 bytes, duration 14 sec)
progress 43% (read 58637090816 bytes, duration 14 sec)
progress 44% (read 60000698368 bytes, duration 14 sec)
progress 45% (read 61364371456 bytes, duration 14 sec)
progress 46% (read 62728044544 bytes, duration 14 sec)
progress 47% (read 64091652096 bytes, duration 14 sec)
progress 48% (read 65455325184 bytes, duration 15 sec)
progress 49% (read 66818998272 bytes, duration 15 sec)
progress 50% (read 68182605824 bytes, duration 20 sec)
progress 51% (read 69546278912 bytes, duration 25 sec)
progress 52% (read 70909952000 bytes, duration 28 sec)
progress 53% (read 72273625088 bytes, duration 28 sec)
progress 54% (read 73637232640 bytes, duration 28 sec)
progress 55% (read 75000905728 bytes, duration 28 sec)
progress 56% (read 76364578816 bytes, duration 28 sec)
progress 57% (read 77728186368 bytes, duration 28 sec)
progress 58% (read 79091859456 bytes, duration 28 sec)
progress 59% (read 80455532544 bytes, duration 29 sec)
progress 60% (read 81819140096 bytes, duration 29 sec)
progress 61% (read 83182813184 bytes, duration 29 sec)
progress 62% (read 84546486272 bytes, duration 29 sec)
progress 63% (read 85910093824 bytes, duration 29 sec)
progress 64% (read 87273766912 bytes, duration 29 sec)
progress 65% (read 88637440000 bytes, duration 29 sec)
progress 66% (read 90001047552 bytes, duration 29 sec)
progress 67% (read 91364720640 bytes, duration 30 sec)
progress 68% (read 92728393728 bytes, duration 30 sec)
progress 69% (read 94092001280 bytes, duration 30 sec)
progress 70% (read 95455674368 bytes, duration 30 sec)
progress 71% (read 96819347456 bytes, duration 31 sec)
progress 72% (read 98182955008 bytes, duration 31 sec)
progress 73% (read 99546628096 bytes, duration 31 sec)
progress 74% (read 100910301184 bytes, duration 31 sec)
progress 75% (read 102273908736 bytes, duration 31 sec)
progress 76% (read 103637581824 bytes, duration 33 sec)
progress 77% (read 105001254912 bytes, duration 36 sec)
progress 78% (read 106364928000 bytes, duration 37 sec)
progress 79% (read 107728535552 bytes, duration 37 sec)
progress 80% (read 109092208640 bytes, duration 37 sec)
progress 81% (read 110455881728 bytes, duration 37 sec)
progress 82% (read 111819489280 bytes, duration 37 sec)
progress 83% (read 113183162368 bytes, duration 37 sec)
progress 84% (read 114546835456 bytes, duration 37 sec)
progress 85% (read 115910443008 bytes, duration 37 sec)
progress 86% (read 117274116096 bytes, duration 38 sec)
progress 87% (read 118637789184 bytes, duration 38 sec)
progress 88% (read 120001396736 bytes, duration 38 sec)
progress 89% (read 121365069824 bytes, duration 38 sec)
progress 90% (read 122728742912 bytes, duration 38 sec)
progress 91% (read 124092350464 bytes, duration 39 sec)
progress 92% (read 125456023552 bytes, duration 39 sec)
progress 93% (read 126819696640 bytes, duration 39 sec)
progress 94% (read 128183304192 bytes, duration 39 sec)
progress 95% (read 129546977280 bytes, duration 39 sec)
progress 96% (read 130910650368 bytes, duration 39 sec)
progress 97% (read 132274257920 bytes, duration 39 sec)
progress 98% (read 133637931008 bytes, duration 39 sec)
progress 99% (read 135001604096 bytes, duration 39 sec)
progress 100% (read 136365211648 bytes, duration 39 sec)
total bytes read 136365211648, sparse bytes 129111408640 (94.7%)
space reduction due to 4K zero blocks 0.595%
TASK OK

As you can see, the IO delay was great only if the "space reduction" is great enough. Well, at least - I think so )

I run PVE 5.1-36 on HP Proliant DL380p Gen8. Storage is LVM-thin on hardware RAID5 with BBWC.
PVEPERF is:
Code:
CPU BOGOMIPS:      95751.60
REGEX/SECOND:      1385077
HD SIZE:           126.18 GB (/dev/mapper/pve-root)
BUFFERED READS:    232.80 MB/sec
AVERAGE SEEK TIME: 5.03 ms
FSYNCS/SECOND:     5366.26

Any ideas/suggestions?
 
Can I turn off the "space reduction@ feature during VM backup?
No.

As you can see, the IO delay was great only if the "space reduction" is great enough. Well, at least - I think so )
This is very likely due to some cache running full and LVM syncs to the RAID. A alternative is to restore to a non-LVM storage and use the disk move option.
 
we are evaluating migrate to another platform for this...
Same problem, SAS disks (but RAID 10) and same server.
After 50% of recovery task the IO delay goes up! and other times for other backups goes well (less big but not significantly).

When recover VM at another storage like same "BackUp" storage the problem dissapear.. but then if I want to move disk to the vms-storage (local default Thin-LVM) the IO Delay grows and VMs hang
 
Last edited:
You can also try to set a bandwidth limit (man datacenter.cfg), but in the end it comes down to how fast the lvm-thin pool can write.
 
I have said it many times, but there should be a way to limit IO on both backups and restores. I know there are some command line options, but there should be something in the GUI for this. I've seen quite a few threads like this so there is no doubt it causes people issues.
 
We already implemented a GUI for a restore speed limit.

limit-restore-speed.png
 
Nice! good update!

now, for example, for 23GB vzdump backup.. what limit to apply? how to determine de optimal value ?
thanks again!

That is really enviroment specific. I know in my enviroment 400-500MB/s is pushing it and causes latency to skyrocket. Personally I would run at 100-200Mb/s. You could kick off a restore with no limit, see what it runs at, then cut it in half.
 
That is really enviroment specific. I know in my enviroment 400-500MB/s is pushing it and causes latency to skyrocket. Personally I would run at 100-200Mb/s. You could kick off a restore with no limit, see what it runs at, then cut it in half.
need to test and tune :D

are there some command / param to test it with out apply server update?
 

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!