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:
The "space reduction" is great enough = 37%.
However, when I recover other archives, I get no problem (when space reduction is quite small).
Even with large sparse bytes:
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:
Any ideas/suggestions?
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:
At the 50% recovering process I get the 50% and greater IO delay on node. All guest VMs is stuck, web-interface is unresponsible.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
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?