Extremely slow restore of VMDK to ZFS

[gkovacs]

I have two, similar Windows VMs on Proxmox 3.4, one has a qcow2 disk, the other vmdk. When restoring these on Proxmox 4 to ZFS (from the same NFS mount), the qcow2 restore hits 200-300 MB/sec while the wmdk is limited to 3-6 MB/sec.

All in all, the 14 GB vmdk restore took 3151 seconds, while the 11 GB qcow2 restore took 31 seconds, so it was a hundred times slower. WTF?

Proxmox 4 node installed on ZFS 4x2GB HDD in RAID10, L2ARC/ZIL on SSD added later.

iotop during vmdk restore:

Total DISK READ :      11.31 M/s | Total DISK WRITE :       5.89 M/s
Actual DISK READ:       5.55 M/s | Actual DISK WRITE:       6.62 M/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND
30785 be/4 root      212.19 K/s    5.89 M/s  0.00 % 96.50 % vma extract -v -r /var/tmp/vzdumptmp30779.fifo - /var/tmp/vzdumptmp30779

vmdk restore

qmrestore vzdump-qemu-111-2015_11_04-13_20_21.vma.lzo 111
restore vma archive: lzop -d -c /mnt/pve/NFS/dump/vzdump-qemu-111-2015_11_04-13_20_21.vma.lzo|vma extract -v -r /var/tmp/vzdumptmp30779.fifo - /var/tmp/vzdumptmp30779
CFG: size: 379 name: qemu-server.conf
DEV: dev_id=1 size: 45097156608 devname: drive-virtio0
CTIME: Wed Nov  4 13:20:24 2015
Formatting '/var/lib/vz/images/111/vm-111-disk-1.vmdk', fmt=vmdk size=45097156608 compat6=off
new volume ID is 'local:111/vm-111-disk-1.vmdk'
map 'drive-virtio0' to '/var/lib/vz/images/111/vm-111-disk-1.vmdk' (write zeros = 0)
progress 1% (read 451018752 bytes, duration 82 sec)
progress 2% (read 901971968 bytes, duration 167 sec)
progress 3% (read 1352925184 bytes, duration 245 sec)
progress 4% (read 1803943936 bytes, duration 330 sec)
progress 5% (read 2254897152 bytes, duration 411 sec)
progress 6% (read 2705850368 bytes, duration 485 sec)
progress 7% (read 3156803584 bytes, duration 562 sec)
progress 8% (read 3607822336 bytes, duration 577 sec)
progress 9% (read 4058775552 bytes, duration 577 sec)
progress 10% (read 4509728768 bytes, duration 577 sec)
progress 11% (read 4960747520 bytes, duration 577 sec)
progress 12% (read 5411700736 bytes, duration 577 sec)
progress 13% (read 5862653952 bytes, duration 577 sec)
progress 14% (read 6313607168 bytes, duration 578 sec)
progress 15% (read 6764625920 bytes, duration 578 sec)
progress 16% (read 7215579136 bytes, duration 578 sec)
progress 17% (read 7666532352 bytes, duration 578 sec)
progress 18% (read 8117551104 bytes, duration 578 sec)
progress 19% (read 8568504320 bytes, duration 578 sec)
progress 20% (read 9019457536 bytes, duration 603 sec)
progress 21% (read 9470410752 bytes, duration 895 sec)
progress 22% (read 9921429504 bytes, duration 1198 sec)
progress 23% (read 10372382720 bytes, duration 1273 sec)
progress 24% (read 10823335936 bytes, duration 1348 sec)
progress 25% (read 11274289152 bytes, duration 1422 sec)
progress 26% (read 11725307904 bytes, duration 1493 sec)
progress 27% (read 12176261120 bytes, duration 1571 sec)
progress 28% (read 12627214336 bytes, duration 1649 sec)
progress 29% (read 13078233088 bytes, duration 1728 sec)
progress 30% (read 13529186304 bytes, duration 1802 sec)
progress 31% (read 13980139520 bytes, duration 1870 sec)
progress 32% (read 14431092736 bytes, duration 1941 sec)
progress 33% (read 14882111488 bytes, duration 2018 sec)
progress 34% (read 15333064704 bytes, duration 2092 sec)
progress 35% (read 15784017920 bytes, duration 2168 sec)
progress 36% (read 16235036672 bytes, duration 2239 sec)
progress 37% (read 16685989888 bytes, duration 2315 sec)
progress 38% (read 17136943104 bytes, duration 2394 sec)
progress 39% (read 17587896320 bytes, duration 2559 sec)
progress 40% (read 18038915072 bytes, duration 2717 sec)
progress 41% (read 18489868288 bytes, duration 2801 sec)
progress 42% (read 18940821504 bytes, duration 2866 sec)
progress 43% (read 19391840256 bytes, duration 2914 sec)
progress 44% (read 19842793472 bytes, duration 2954 sec)
progress 45% (read 20293746688 bytes, duration 3020 sec)
progress 46% (read 20744699904 bytes, duration 3074 sec)
progress 47% (read 21195718656 bytes, duration 3128 sec)
progress 48% (read 21646671872 bytes, duration 3128 sec)
progress 49% (read 22097625088 bytes, duration 3128 sec)
progress 50% (read 22548578304 bytes, duration 3151 sec)
progress 51% (read 22999597056 bytes, duration 3151 sec)
progress 52% (read 23450550272 bytes, duration 3151 sec)
progress 53% (read 23901503488 bytes, duration 3151 sec)
progress 54% (read 24352522240 bytes, duration 3151 sec)
progress 55% (read 24803475456 bytes, duration 3151 sec)
progress 56% (read 25254428672 bytes, duration 3151 sec)
progress 57% (read 25705381888 bytes, duration 3151 sec)
progress 58% (read 26156400640 bytes, duration 3151 sec)
progress 59% (read 26607353856 bytes, duration 3151 sec)
progress 60% (read 27058307072 bytes, duration 3151 sec)
progress 61% (read 27509325824 bytes, duration 3151 sec)
progress 62% (read 27960279040 bytes, duration 3151 sec)
progress 63% (read 28411232256 bytes, duration 3151 sec)
progress 64% (read 28862185472 bytes, duration 3151 sec)
progress 65% (read 29313204224 bytes, duration 3151 sec)
progress 66% (read 29764157440 bytes, duration 3151 sec)
progress 67% (read 30215110656 bytes, duration 3151 sec)
progress 68% (read 30666129408 bytes, duration 3151 sec)
progress 69% (read 31117082624 bytes, duration 3151 sec)
progress 70% (read 31568035840 bytes, duration 3151 sec)
progress 71% (read 32018989056 bytes, duration 3151 sec)
progress 72% (read 32470007808 bytes, duration 3151 sec)
progress 73% (read 32920961024 bytes, duration 3151 sec)
progress 74% (read 33371914240 bytes, duration 3151 sec)
progress 75% (read 33822867456 bytes, duration 3151 sec)
progress 76% (read 34273886208 bytes, duration 3151 sec)
progress 77% (read 34724839424 bytes, duration 3151 sec)
progress 78% (read 35175792640 bytes, duration 3151 sec)
progress 79% (read 35626811392 bytes, duration 3151 sec)
progress 80% (read 36077764608 bytes, duration 3151 sec)
progress 81% (read 36528717824 bytes, duration 3151 sec)
progress 82% (read 36979671040 bytes, duration 3151 sec)
progress 83% (read 37430689792 bytes, duration 3151 sec)
progress 84% (read 37881643008 bytes, duration 3151 sec)
progress 85% (read 38332596224 bytes, duration 3151 sec)
progress 86% (read 38783614976 bytes, duration 3151 sec)
progress 87% (read 39234568192 bytes, duration 3151 sec)
progress 88% (read 39685521408 bytes, duration 3151 sec)
progress 89% (read 40136474624 bytes, duration 3151 sec)
progress 90% (read 40587493376 bytes, duration 3151 sec)
progress 91% (read 41038446592 bytes, duration 3151 sec)
progress 92% (read 41489399808 bytes, duration 3151 sec)
progress 93% (read 41940418560 bytes, duration 3151 sec)
progress 94% (read 42391371776 bytes, duration 3151 sec)
progress 95% (read 42842324992 bytes, duration 3151 sec)
progress 96% (read 43293278208 bytes, duration 3151 sec)
progress 97% (read 43744296960 bytes, duration 3151 sec)
progress 98% (read 44195250176 bytes, duration 3151 sec)
progress 99% (read 44646203392 bytes, duration 3151 sec)
progress 100% (read 45097156608 bytes, duration 3151 sec)
total bytes read 45097156608, sparse bytes 30639149056 (67.9%)
space reduction due to 4K zero blocks 1.47%

qcow restore

qmrestore vzdump-qemu-112-2015_11_04-03_54_25.vma.lzo 112
restore vma archive: lzop -d -c /mnt/pve/NFS/dump/vzdump-qemu-112-2015_11_04-03_54_25.vma.lzo|vma extract -v -r /var/tmp/vzdumptmp20043.fifo - /var/tmp/vzdumptmp20043
CFG: size: 409 name: qemu-server.conf
DEV: dev_id=1 size: 45096468480 devname: drive-ide0
CTIME: Wed Nov  4 03:54:27 2015
Formatting '/var/lib/vz/images/112/vm-112-disk-1.qcow2', fmt=qcow2 size=45096468480 encryption=off cluster_size=65536 preallocation='metadata' lazy_refcounts=off refcount_bits=16
new volume ID is 'local:112/vm-112-disk-1.qcow2'
map 'drive-ide0' to '/var/lib/vz/images/112/vm-112-disk-1.qcow2' (write zeros = 0)
progress 1% (read 451018752 bytes, duration 2 sec)
progress 2% (read 901971968 bytes, duration 3 sec)
progress 3% (read 1352925184 bytes, duration 4 sec)
progress 4% (read 1803878400 bytes, duration 5 sec)
progress 5% (read 2254831616 bytes, duration 6 sec)
progress 6% (read 2705850368 bytes, duration 7 sec)
progress 7% (read 3156803584 bytes, duration 9 sec)
progress 8% (read 3607756800 bytes, duration 9 sec)
progress 9% (read 4058710016 bytes, duration 9 sec)
progress 10% (read 4509663232 bytes, duration 9 sec)
progress 11% (read 4960616448 bytes, duration 9 sec)
progress 12% (read 5411635200 bytes, duration 9 sec)
progress 13% (read 5862588416 bytes, duration 9 sec)
progress 14% (read 6313541632 bytes, duration 9 sec)
progress 15% (read 6764494848 bytes, duration 9 sec)
progress 16% (read 7215448064 bytes, duration 9 sec)
progress 17% (read 7666401280 bytes, duration 9 sec)
progress 18% (read 8117420032 bytes, duration 9 sec)
progress 19% (read 8568373248 bytes, duration 9 sec)
progress 20% (read 9019326464 bytes, duration 10 sec)
progress 21% (read 9470279680 bytes, duration 11 sec)
progress 22% (read 9921232896 bytes, duration 11 sec)
progress 23% (read 10372186112 bytes, duration 11 sec)
progress 24% (read 10823204864 bytes, duration 12 sec)
progress 25% (read 11274158080 bytes, duration 13 sec)
progress 26% (read 11725111296 bytes, duration 14 sec)
progress 27% (read 12176064512 bytes, duration 15 sec)
progress 28% (read 12627017728 bytes, duration 16 sec)
progress 29% (read 13077970944 bytes, duration 17 sec)
progress 30% (read 13528989696 bytes, duration 18 sec)
progress 31% (read 13979942912 bytes, duration 20 sec)
progress 32% (read 14430896128 bytes, duration 21 sec)
progress 33% (read 14881849344 bytes, duration 22 sec)
progress 34% (read 15332802560 bytes, duration 23 sec)
progress 35% (read 15783755776 bytes, duration 24 sec)
progress 36% (read 16234774528 bytes, duration 25 sec)
progress 37% (read 16685727744 bytes, duration 27 sec)
progress 38% (read 17136680960 bytes, duration 28 sec)
progress 39% (read 17587634176 bytes, duration 29 sec)
progress 40% (read 18038587392 bytes, duration 30 sec)
progress 41% (read 18489540608 bytes, duration 30 sec)
progress 42% (read 18940559360 bytes, duration 30 sec)
progress 43% (read 19391512576 bytes, duration 30 sec)
progress 44% (read 19842465792 bytes, duration 30 sec)
progress 45% (read 20293419008 bytes, duration 30 sec)
progress 46% (read 20744372224 bytes, duration 30 sec)
progress 47% (read 21195325440 bytes, duration 30 sec)
progress 48% (read 21646344192 bytes, duration 30 sec)
progress 49% (read 22097297408 bytes, duration 30 sec)
progress 50% (read 22548250624 bytes, duration 30 sec)
progress 51% (read 22999203840 bytes, duration 30 sec)
progress 52% (read 23450157056 bytes, duration 30 sec)
progress 53% (read 23901175808 bytes, duration 30 sec)
progress 54% (read 24352129024 bytes, duration 30 sec)
progress 55% (read 24803082240 bytes, duration 30 sec)
progress 56% (read 25254035456 bytes, duration 30 sec)
progress 57% (read 25704988672 bytes, duration 30 sec)
progress 58% (read 26155941888 bytes, duration 30 sec)
progress 59% (read 26606960640 bytes, duration 30 sec)
progress 60% (read 27057913856 bytes, duration 30 sec)
progress 61% (read 27508867072 bytes, duration 30 sec)
progress 62% (read 27959820288 bytes, duration 30 sec)
progress 63% (read 28410773504 bytes, duration 30 sec)
progress 64% (read 28861726720 bytes, duration 30 sec)
progress 65% (read 29312745472 bytes, duration 30 sec)
progress 66% (read 29763698688 bytes, duration 30 sec)
progress 67% (read 30214651904 bytes, duration 30 sec)
progress 68% (read 30665605120 bytes, duration 30 sec)
progress 69% (read 31116558336 bytes, duration 30 sec)
progress 70% (read 31567511552 bytes, duration 31 sec)
progress 71% (read 32018530304 bytes, duration 31 sec)
progress 72% (read 32469483520 bytes, duration 31 sec)
progress 73% (read 32920436736 bytes, duration 31 sec)
progress 74% (read 33371389952 bytes, duration 31 sec)
progress 75% (read 33822343168 bytes, duration 31 sec)
progress 76% (read 34273296384 bytes, duration 31 sec)
progress 77% (read 34724315136 bytes, duration 31 sec)
progress 78% (read 35175268352 bytes, duration 31 sec)
progress 79% (read 35626221568 bytes, duration 31 sec)
progress 80% (read 36077174784 bytes, duration 31 sec)
progress 81% (read 36528128000 bytes, duration 31 sec)
progress 82% (read 36979081216 bytes, duration 31 sec)
progress 83% (read 37430099968 bytes, duration 31 sec)
progress 84% (read 37881053184 bytes, duration 31 sec)
progress 85% (read 38332006400 bytes, duration 31 sec)
progress 86% (read 38782959616 bytes, duration 31 sec)
progress 87% (read 39233912832 bytes, duration 31 sec)
progress 88% (read 39684866048 bytes, duration 31 sec)
progress 89% (read 40135884800 bytes, duration 31 sec)
progress 90% (read 40586838016 bytes, duration 31 sec)
progress 91% (read 41037791232 bytes, duration 31 sec)
progress 92% (read 41488744448 bytes, duration 31 sec)
progress 93% (read 41939697664 bytes, duration 31 sec)
progress 94% (read 42390650880 bytes, duration 31 sec)
progress 95% (read 42841669632 bytes, duration 31 sec)
progress 96% (read 43292622848 bytes, duration 31 sec)
progress 97% (read 43743576064 bytes, duration 31 sec)
progress 98% (read 44194529280 bytes, duration 31 sec)
progress 99% (read 44645482496 bytes, duration 31 sec)
progress 100% (read 45096435712 bytes, duration 31 sec)
total bytes read 45096501248, sparse bytes 33854398464 (75.1%)
space reduction due to 4K zero blocks 0.31%

Not sure if related to this thread:
http://forum.proxmox.com/threads/12...ups-two-lzo-processes-thrashing-restore-drive