Backup performance issues

HBO · Oct 7, 2017

Hi,

i've got a performance issue with backups on a nfs storage:

Code:

INFO: Starting Backup of VM 102 (qemu)
INFO: status = running
INFO: update VM 102: -lock backup
INFO: VM Name: deltapeak-mailserver-K14163
INFO: include disk 'scsi0' 'zfs-sata:vm-102-disk-1' 100G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating archive '/mnt/pve/Backups/dump/vzdump-qemu-102-2017_10_07-00_01_01.vma.lzo'
INFO: started backup task '952cdf4f-3bab-4bc4-b956-cce32288ff41'
INFO: status: 0% (41811968/107374182400), sparse 0% (25141248), duration 5, read/write 8/3 MB/s
INFO: status: 1% (1106116608/107374182400), sparse 0% (920281088), duration 101, read/write 11/1 MB/s
INFO: status: 2% (2151415808/107374182400), sparse 1% (1895993344), duration 132, read/write 33/2 MB/s
INFO: status: 3% (3230924800/107374182400), sparse 2% (2838163456), duration 175, read/write 25/3 MB/s
INFO: status: 4% (4334747648/107374182400), sparse 3% (3817332736), duration 216, read/write 26/3 MB/s
INFO: status: 5% (5407834112/107374182400), sparse 4% (4767154176), duration 254, read/write 28/3 MB/s
INFO: status: 6% (6484656128/107374182400), sparse 5% (5802696704), duration 284, read/write 35/1 MB/s
INFO: status: 7% (7518552064/107374182400), sparse 6% (6673756160), duration 323, read/write 26/4 MB/s
INFO: status: 8% (8632270848/107374182400), sparse 7% (7741149184), duration 345, read/write 50/2 MB/s
INFO: status: 9% (9672851456/107374182400), sparse 8% (8688201728), duration 393, read/write 21/1 MB/s
INFO: status: 10% (10779885568/107374182400), sparse 9% (9764179968), duration 418, read/write 44/1 MB/s
INFO: status: 11% (11828985856/107374182400), sparse 9% (10719158272), duration 450, read/write 32/2 MB/s
INFO: status: 12% (12935102464/107374182400), sparse 10% (11774205952), duration 481, read/write 35/1 MB/s
INFO: status: 13% (13961396224/107374182400), sparse 11% (12710875136), duration 515, read/write 30/2 MB/s
INFO: status: 14% (15086518272/107374182400), sparse 12% (13754044416), duration 546, read/write 36/2 MB/s
INFO: status: 15% (16157310976/107374182400), sparse 13% (14676611072), duration 582, read/write 29/4 MB/s
INFO: status: 16% (17329160192/107374182400), sparse 14% (15764844544), duration 612, read/write 39/2 MB/s
INFO: status: 17% (18289917952/107374182400), sparse 15% (16603881472), duration 638, read/write 36/4 MB/s
INFO: status: 18% (19382861824/107374182400), sparse 16% (17625219072), duration 663, read/write 43/2 MB/s
INFO: status: 19% (20415643648/107374182400), sparse 17% (18606456832), duration 683, read/write 51/2 MB/s
INFO: status: 20% (21517959168/107374182400), sparse 18% (19626500096), duration 704, read/write 52/3 MB/s
INFO: status: 21% (22629646336/107374182400), sparse 19% (20459278336), duration 766, read/write 17/4 MB/s
INFO: status: 22% (23684579328/107374182400), sparse 19% (21437329408), duration 790, read/write 43/3 MB/s
INFO: status: 23% (24726077440/107374182400), sparse 20% (22172368896), duration 831, read/write 25/7 MB/s
INFO: status: 24% (25850740736/107374182400), sparse 21% (23165140992), duration 867, read/write 31/3 MB/s
INFO: status: 25% (26881294336/107374182400), sparse 22% (23998349312), duration 902, read/write 29/5 MB/s
INFO: status: 26% (28059631616/107374182400), sparse 23% (25098006528), duration 925, read/write 51/3 MB/s
INFO: status: 27% (29025107968/107374182400), sparse 24% (25957568512), duration 946, read/write 45/5 MB/s
INFO: status: 28% (30070407168/107374182400), sparse 25% (26919268352), duration 968, read/write 47/3 MB/s
INFO: status: 29% (31195267072/107374182400), sparse 25% (27751563264), duration 1043, read/write 14/3 MB/s
INFO: status: 30% (32275038208/107374182400), sparse 26% (28305420288), duration 1120, read/write 14/6 MB/s
INFO: status: 31% (33334231040/107374182400), sparse 27% (29176901632), duration 1150, read/write 35/6 MB/s
INFO: status: 32% (34403647488/107374182400), sparse 28% (30086373376), duration 1174, read/write 44/6 MB/s
INFO: status: 33% (35559178240/107374182400), sparse 28% (30947418112), duration 1201, read/write 42/10 MB/s
INFO: status: 34% (36574068736/107374182400), sparse 29% (31723745280), duration 1241, read/write 25/5 MB/s
INFO: status: 35% (37618450432/107374182400), sparse 30% (32456622080), duration 1265, read/write 43/12 MB/s
INFO: status: 36% (38688718848/107374182400), sparse 31% (33299972096), duration 1281, read/write 66/14 MB/s
INFO: status: 37% (39913652224/107374182400), sparse 31% (34344038400), duration 1306, read/write 48/7 MB/s
INFO: status: 38% (40914911232/107374182400), sparse 32% (35256266752), duration 1318, read/write 83/7 MB/s
INFO: status: 39% (42024828928/107374182400), sparse 33% (36143747072), duration 1348, read/write 36/7 MB/s
INFO: status: 40% (42997907456/107374182400), sparse 34% (36965502976), duration 1367, read/write 51/7 MB/s
INFO: status: 41% (44043730944/107374182400), sparse 35% (37775228928), duration 1393, read/write 40/9 MB/s
INFO: status: 42% (45240549376/107374182400), sparse 36% (38762549248), duration 1411, read/write 66/11 MB/s
INFO: status: 43% (46257405952/107374182400), sparse 36% (39658098688), duration 1423, read/write 84/10 MB/s
INFO: status: 44% (47289335808/107374182400), sparse 37% (40480174080), duration 1443, read/write 51/10 MB/s
INFO: status: 45% (48387850240/107374182400), sparse 38% (41073348608), duration 1573, read/write 8/3 MB/s
INFO: status: 46% (49562386432/107374182400), sparse 39% (41924173824), duration 1592, read/write 61/17 MB/s
INFO: status: 47% (50489851904/107374182400), sparse 39% (42629955584), duration 1603, read/write 84/20 MB/s
INFO: status: 48% (51683393536/107374182400), sparse 40% (43809955840), duration 1608, read/write 238/2 MB/s
INFO: status: 49% (52885454848/107374182400), sparse 41% (44864323584), duration 1644, read/write 33/4 MB/s
INFO: status: 50% (53857615872/107374182400), sparse 42% (45747601408), duration 1663, read/write 51/4 MB/s
INFO: status: 51% (54967533568/107374182400), sparse 43% (46772367360), duration 1680, read/write 65/5 MB/s
INFO: status: 52% (56117821440/107374182400), sparse 44% (47904145408), duration 1690, read/write 115/1 MB/s
INFO: status: 53% (57011863552/107374182400), sparse 45% (48785031168), duration 1699, read/write 99/1 MB/s
INFO: status: 54% (57985597440/107374182400), sparse 46% (49755324416), duration 1702, read/write 324/1 MB/s
INFO: status: 55% (59518681088/107374182400), sparse 47% (51284197376), duration 1706, read/write 383/1 MB/s
INFO: status: 56% (60281454592/107374182400), sparse 48% (52017426432), duration 1710, read/write 190/7 MB/s
INFO: status: 57% (61306175488/107374182400), sparse 49% (53021122560), duration 1714, read/write 256/5 MB/s
INFO: status: 58% (62379786240/107374182400), sparse 50% (54088757248), duration 1718, read/write 268/1 MB/s
INFO: status: 59% (63911493632/107374182400), sparse 51% (55616868352), duration 1723, read/write 306/0 MB/s
INFO: status: 60% (64565280768/107374182400), sparse 52% (56230080512), duration 1729, read/write 108/6 MB/s
INFO: status: 61% (66043052032/107374182400), sparse 53% (57690181632), duration 1733, read/write 369/4 MB/s
INFO: status: 62% (67007676416/107374182400), sparse 54% (58631069696), duration 1737, read/write 241/5 MB/s
INFO: status: 63% (67869474816/107374182400), sparse 55% (59491983360), duration 1740, read/write 287/0 MB/s
INFO: status: 64% (68727275520/107374182400), sparse 56% (60340592640), duration 1744, read/write 214/2 MB/s
INFO: status: 65% (70539608064/107374182400), sparse 57% (62152921088), duration 1748, read/write 453/0 MB/s
INFO: status: 66% (71337312256/107374182400), sparse 58% (62913515520), duration 1751, read/write 265/12 MB/s
INFO: status: 67% (72116731904/107374182400), sparse 59% (63690104832), duration 1755, read/write 194/0 MB/s
INFO: status: 68% (73693593600/107374182400), sparse 60% (65266589696), duration 1758, read/write 525/0 MB/s
INFO: status: 70% (75297718272/107374182400), sparse 62% (66869207040), duration 1761, read/write 534/0 MB/s
INFO: status: 71% (76780601344/107374182400), sparse 63% (68342947840), duration 1768, read/write 211/1 MB/s
INFO: status: 72% (78100758528/107374182400), sparse 64% (69662048256), duration 1771, read/write 440/0 MB/s
INFO: status: 73% (78962884608/107374182400), sparse 65% (70523260928), duration 1774, read/write 287/0 MB/s
INFO: status: 74% (80372826112/107374182400), sparse 66% (71917457408), duration 1778, read/write 352/3 MB/s
INFO: status: 76% (82496585728/107374182400), sparse 68% (74040750080), duration 1781, read/write 707/0 MB/s
INFO: status: 77% (83306741760/107374182400), sparse 69% (74849533952), duration 1784, read/write 270/0 MB/s
INFO: status: 79% (85437775872/107374182400), sparse 71% (76974886912), duration 1789, read/write 426/1 MB/s
INFO: status: 81% (87079321600/107374182400), sparse 73% (78614372352), duration 1792, read/write 547/0 MB/s
INFO: status: 82% (88519606272/107374182400), sparse 74% (80033759232), duration 1797, read/write 288/4 MB/s
INFO: status: 84% (90381615104/107374182400), sparse 76% (81895763968), duration 1800, read/write 620/0 MB/s
INFO: status: 86% (92349923328/107374182400), sparse 78% (83864068096), duration 1804, read/write 492/0 MB/s
INFO: status: 88% (94497210368/107374182400), sparse 80% (86011351040), duration 1810, read/write 357/0 MB/s
INFO: status: 90% (96644694016/107374182400), sparse 82% (88158826496), duration 1815, read/write 429/0 MB/s
INFO: status: 92% (98792439808/107374182400), sparse 84% (90306535424), duration 1820, read/write 429/0 MB/s
INFO: status: 94% (100939923456/107374182400), sparse 86% (92454014976), duration 1825, read/write 429/0 MB/s
INFO: status: 96% (103085178880/107374182400), sparse 88% (94595403776), duration 1830, read/write 429/0 MB/s
INFO: status: 97% (104157413376/107374182400), sparse 88% (95536955392), duration 1851, read/write 51/6 MB/s
INFO: status: 98% (105229320192/107374182400), sparse 89% (96495755264), duration 1873, read/write 48/5 MB/s
INFO: status: 99% (106305028096/107374182400), sparse 89% (96538312704), duration 2076, read/write 5/5 MB/s
INFO: status: 100% (107374182400/107374182400), sparse 90% (96652546048), duration 2107, read/write 34/30 MB/s
INFO: transferred 107374 MB in 2107 seconds (50 MB/s)
INFO: archive file size: 5.56GB
INFO: Finished Backup of VM 102 (00:35:09)

System Info:
-

proxmox-ve: 5.0-15 (running kernel: 4.10.15-1-pve)
pve-manager: 5.0-23 (running version: 5.0-23/af4267bf)
pve-kernel-4.10.15-1-pve: 4.10.15-15
libpve-http-server-perl: 2.0-5
lvm2: 2.02.168-pve2
corosync: 2.4.2-pve3
libqb0: 1.0.1-1
pve-cluster: 5.0-10
qemu-server: 5.0-12
pve-firmware: 2.0-2
libpve-common-perl: 5.0-16
libpve-guest-common-perl: 2.0-11
libpve-access-control: 5.0-5
libpve-storage-perl: 5.0-12
pve-libspice-server1: 0.12.8-3
vncterm: 1.5-2
pve-docs: 5.0-8
pve-qemu-kvm: 2.9.0-2
pve-container: 2.0-15
pve-firewall: 3.0-1
pve-ha-manager: 2.0-2
ksm-control-daemon: 1.2-2
glusterfs-client: 3.8.8-1
lxc-pve: 2.0.8-3
lxcfs: 2.0.7-pve2
criu: 2.11.1-1~bpo90
novnc-pve: 0.6-4
smartmontools: 6.5+svn4324-1
zfsutils-linux: 0.6.5.9-pve16~bpo90

- backup from zfs pool using broadcom 3008 hba
- zfs proxmox pool (rpool) mirrored connected on mainboard (supermicro 2028U-TRTP+) using intel dc s3510 series
- zfs zil/l2arc disk connected on mainboard using intel dc s3610
- nfs backup system connected with 10ge dac (netperf shows 10ge speed is full usable)
-

Code:

NAME   SIZE  ALLOC   FREE  EXPANDSZ   FRAG    CAP  DEDUP  HEALTH  ALTROOT
rpool   111G  17.3G  93.7G         -    38%    15%  1.00x  ONLINE  -
  mirror   111G  17.3G  93.7G         -    38%    15%
    sdg2      -      -      -         -      -      -
    sdh2      -      -      -         -      -      -
sata  5.44T  2.07T  3.37T         -    45%    37%  1.00x  ONLINE  -
  mirror  1.81T   705G  1.12T         -    45%    37%
    sda      -      -      -         -      -      -
    sdb      -      -      -         -      -      -
  mirror  1.81T   705G  1.12T         -    46%    37%
    sdc      -      -      -         -      -      -
    sdd      -      -      -         -      -      -
  mirror  1.81T   705G  1.12T         -    46%    37%
    sde      -      -      -         -      -      -
    sdf      -      -      -         -      -      -
log      -      -      -         -      -      -
  sdi1  79.5G  39.2M  79.5G         -     0%     0%
cache      -      -      -         -      -      -
  sdi2   367G   330G  36.8G         -     0%    89%

-

Code:

------------------------------------------------------------------------

ZFS Subsystem Report                            Sat Oct 07 10:13:12 2017
ARC Summary: (HEALTHY)
        Memory Throttle Count:                  0

ARC Misc:
        Deleted:                                10.59b
        Mutex Misses:                           2.07m
        Evict Skips:                            2.07m

ARC Size:                               73.98%  23.67   GiB
        Target Size: (Adaptive)         74.08%  23.70   GiB
        Min Size (Hard Limit):          37.50%  12.00   GiB
        Max Size (High Water):          2:1     32.00   GiB

ARC Size Breakdown:
        Recently Used Cache Size:       43.77%  10.38   GiB
        Frequently Used Cache Size:     56.23%  13.33   GiB

ARC Hash Breakdown:
        Elements Max:                           103.14m
        Elements Current:               86.53%  89.25m
        Collisions:                             11.31b
        Chain Max:                              12
        Chains:                                 25.92m

ARC Total accesses:                                     42.27b
        Cache Hit Ratio:                77.06%  32.58b
        Cache Miss Ratio:               22.94%  9.70b
        Actual Hit Ratio:               71.01%  30.02b

        Data Demand Efficiency:         91.96%  18.88b
        Data Prefetch Efficiency:       27.25%  10.93b

        CACHE HITS BY CACHE LIST:
          Anonymously Used:             6.46%   2.11b
          Most Recently Used:           51.87%  16.90b
          Most Frequently Used:         40.28%  13.12b
          Most Recently Used Ghost:     1.07%   349.18m
          Most Frequently Used Ghost:   0.32%   103.56m

        CACHE HITS BY DATA TYPE:
          Demand Data:                  53.30%  17.36b
          Prefetch Data:                9.14%   2.98b
          Demand Metadata:              37.33%  12.16b
          Prefetch Metadata:            0.22%   72.33m

        CACHE MISSES BY DATA TYPE:
          Demand Data:                  15.66%  1.52b
          Prefetch Data:                81.96%  7.95b
          Demand Metadata:              2.20%   213.50m
          Prefetch Metadata:            0.18%   17.84m

L2 ARC Summary: (HEALTHY)
        Low Memory Aborts:                      72.20k
        Free on Write:                          1.59m
        R/W Clashes:                            16
        Bad Checksums:                          0
        IO Errors:                              0

L2 ARC Size: (Adaptive)                         338.44  GiB
        Compressed:                     97.61%  330.35  GiB
        Header Size:                    2.35%   7.95    GiB

L2 ARC Evicts:
        Lock Retries:                           21.64k
        Upon Reading:                           661

L2 ARC Breakdown:                               9.70b
        Hit Ratio:                      5.11%   495.17m
        Miss Ratio:                     94.89%  9.20b
        Feeds:                                  8.85m

L2 ARC Writes:
        Writes Sent:                    100.00% 8.21m

DMU Prefetch Efficiency:                                        48.71b
        Hit Ratio:                      96.99%  47.25b
        Miss Ratio:                     3.01%   1.46b

Does these performance up and downs result on using the mainboard sata ports for pve zpool (rpool) and zil/l2arc?

HBO · Oct 9, 2017

After upgrading to latest version it's a bit faster, but i don't get a stable performance i think:

proxmox-ve: 5.0-23 (running kernel: 4.10.17-3-pve)
pve-manager: 5.0-32 (running version: 5.0-32/2560e073)
pve-kernel-4.10.15-1-pve: 4.10.15-15
pve-kernel-4.10.17-3-pve: 4.10.17-23
libpve-http-server-perl: 2.0-6
lvm2: 2.02.168-pve3
corosync: 2.4.2-pve3
libqb0: 1.0.1-1
pve-cluster: 5.0-14
qemu-server: 5.0-15
pve-firmware: 2.0-2
libpve-common-perl: 5.0-18
libpve-guest-common-perl: 2.0-12
libpve-access-control: 5.0-6
libpve-storage-perl: 5.0-15
pve-libspice-server1: 0.12.8-3
vncterm: 1.5-2
pve-docs: 5.0-9
pve-qemu-kvm: 2.9.1-1
pve-container: 2.0-16
pve-firewall: 3.0-3
pve-ha-manager: 2.0-2
ksm-control-daemon: 1.2-2
glusterfs-client: 3.8.8-1
lxc-pve: 2.1.0-2
lxcfs: 2.0.7-pve4
criu: 2.11.1-1~bpo90
novnc-pve: 0.6-4
smartmontools: 6.5+svn4324-1
zfsutils-linux: 0.6.5.11-pve17~bpo90

Code:

INFO: starting new backup job: vzdump 113 132 167 210 163 164 169 209 205 110 123 176 150 162 --quiet 1 --mailto ... --mailnotification failure --storage Backups --compress lzo --mode snapshot
INFO: Starting Backup of VM 110 (qemu)
INFO: status = running
INFO: update VM 110: -lock backup
INFO: VM Name: ....
INFO: include disk 'scsi0' 'zfs-sata:vm-110-disk-1' 100G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating archive '/mnt/pve/Backups/dump/vzdump-qemu-110-2017_10_09-00_01_02.vma.lzo'
INFO: started backup task '74a68a55-d6db-4175-88b0-9e7ac840337e'
INFO: status: 0% (171048960/107374182400), sparse 0% (25899008), duration 3, read/write 57/48 MB/s
INFO: status: 1% (1121320960/107374182400), sparse 0% (379740160), duration 18, read/write 63/39 MB/s
INFO: status: 2% (2178023424/107374182400), sparse 0% (422445056), duration 36, read/write 58/56 MB/s
INFO: status: 3% (3230924800/107374182400), sparse 0% (654200832), duration 58, read/write 47/37 MB/s
INFO: status: 4% (4325638144/107374182400), sparse 0% (739254272), duration 79, read/write 52/48 MB/s
...
INFO: status: 33% (35490758656/107374182400), sparse 6% (6897131520), duration 586, read/write 50/40 MB/s
INFO: status: 34% (36608278528/107374182400), sparse 6% (6940819456), duration 597, read/write 101/97 MB/s
INFO: status: 35% (37657378816/107374182400), sparse 6% (7128645632), duration 608, read/write 95/78 MB/s
INFO: status: 36% (38664667136/107374182400), sparse 6% (7136952320), duration 619, read/write 91/90 MB/s
...
INFO: status: 90% (96703479808/107374182400), sparse 25% (27776008192), duration 1459, read/write 75/61 MB/s
INFO: status: 91% (97782988800/107374182400), sparse 25% (27841503232), duration 1471, read/write 89/84 MB/s
INFO: status: 92% (98824486912/107374182400), sparse 25% (27842473984), duration 1481, read/write 104/104 MB/s
INFO: status: 93% (99953410048/107374182400), sparse 25% (27876630528), duration 1496, read/write 75/72 MB/s
INFO: status: 94% (100953096192/107374182400), sparse 25% (27880796160), duration 1507, read/write 90/90 MB/s
...
INFO: status: 99% (106419060736/107374182400), sparse 26% (27975352320), duration 1565, read/write 96/94 MB/s
INFO: status: 100% (107374182400/107374182400), sparse 26% (27977449472), duration 1575, read/write 95/95 MB/s
INFO: transferred 107374 MB in 1575 seconds (68 MB/s)
INFO: archive file size: 50.12GB
INFO: delete old backup '/mnt/pve/Backups/dump/vzdump-qemu-110-2017_10_02-00_19_15.vma.lzo'
INFO: Finished Backup of VM 110 (00:26:18)
INFO: Starting Backup of VM 132 (qemu)
INFO: status = running
INFO: update VM 132: -lock backup
INFO: VM Name: ....
INFO: include disk 'scsi0' 'zfs-sata:vm-132-disk-1' 32G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating archive '/mnt/pve/Backups/dump/vzdump-qemu-132-2017_10_09-00_38_01.vma.lzo'
INFO: started backup task '66dfccdc-7f8d-4d64-ab7a-c5ae92d7867a'
INFO: status: 0% (258473984/34359738368), sparse 0% (34287616), duration 3, read/write 86/74 MB/s
INFO: status: 1% (490340352/34359738368), sparse 0% (43040768), duration 7, read/write 57/55 MB/s
...
INFO: status: 13% (4492886016/34359738368), sparse 0% (234618880), duration 63, read/write 80/59 MB/s
INFO: status: 14% (4815978496/34359738368), sparse 0% (304025600), duration 66, read/write 107/84 MB/s
INFO: status: 15% (5218893824/34359738368), sparse 1% (353927168), duration 72, read/write 67/58 MB/s
INFO: status: 16% (5549588480/34359738368), sparse 1% (408440832), duration 76, read/write 82/69 MB/s
...
INFO: status: 34% (11764367360/34359738368), sparse 2% (728715264), duration 158, read/write 94/75 MB/s
INFO: status: 35% (12174884864/34359738368), sparse 2% (900329472), duration 161, read/write 136/79 MB/s
INFO: status: 36% (12539789312/34359738368), sparse 3% (1090441216), duration 164, read/write 121/58 MB/s
INFO: status: 37% (12900892672/34359738368), sparse 3% (1209479168), duration 167, read/write 120/80 MB/s
...
INFO: status: 42% (14459338752/34359738368), sparse 4% (1391063040), duration 187, read/write 102/79 MB/s
INFO: status: 43% (15052308480/34359738368), sparse 5% (1781366784), duration 190, read/write 197/67 MB/s
INFO: status: 44% (15196749824/34359738368), sparse 5% (1836597248), duration 193, read/write 48/29 MB/s
INFO: status: 45% (15462825984/34359738368), sparse 5% (1836863488), duration 207, read/write 19/18 MB/s
INFO: status: 46% (15820128256/34359738368), sparse 5% (1853759488), duration 231, read/write 14/14 MB/s
INFO: status: 47% (16150822912/34359738368), sparse 5% (1881522176), duration 246, read/write 22/20 MB/s
INFO: status: 48% (16527130624/34359738368), sparse 5% (1978650624), duration 267, read/write 17/13 MB/s
INFO: status: 49% (16842620928/34359738368), sparse 5% (2008268800), duration 283, read/write 19/17 MB/s
INFO: status: 50% (17188519936/34359738368), sparse 6% (2121838592), duration 307, read/write 14/9 MB/s
INFO: status: 51% (17568628736/34359738368), sparse 6% (2209681408), duration 317, read/write 38/29 MB/s
INFO: status: 52% (17887920128/34359738368), sparse 6% (2209742848), duration 322, read/write 63/63 MB/s
...
INFO: status: 66% (22684893184/34359738368), sparse 7% (2425602048), duration 471, read/write 92/91 MB/s
INFO: status: 67% (23061200896/34359738368), sparse 7% (2454958080), duration 476, read/write 75/69 MB/s
INFO: status: 68% (23445110784/34359738368), sparse 7% (2526457856), duration 480, read/write 95/78 MB/s
INFO: status: 69% (23791009792/34359738368), sparse 7% (2745618432), duration 483, read/write 115/42 MB/s
INFO: status: 70% (24302583808/34359738368), sparse 8% (2975932416), duration 491, read/write 63/35 MB/s
INFO: status: 75% (25853886464/34359738368), sparse 13% (4478889984), duration 494, read/write 517/16 MB/s
INFO: status: 76% (26159087616/34359738368), sparse 13% (4531421184), duration 505, read/write 27/22 MB/s
INFO: status: 77% (26485981184/34359738368), sparse 13% (4531564544), duration 523, read/write 18/18 MB/s
INFO: status: 78% (26809073664/34359738368), sparse 13% (4531580928), duration 550, read/write 11/11 MB/s
...
INFO: status: 92% (31689670656/34359738368), sparse 15% (5186002944), duration 615, read/write 76/74 MB/s
INFO: status: 93% (31970951168/34359738368), sparse 15% (5191073792), duration 630, read/write 18/18 MB/s
INFO: status: 94% (32324452352/34359738368), sparse 15% (5201956864), duration 645, read/write 23/22 MB/s
INFO: status: 95% (32655147008/34359738368), sparse 15% (5207085056), duration 657, read/write 27/27 MB/s
INFO: status: 96% (32985841664/34359738368), sparse 15% (5210062848), duration 674, read/write 19/19 MB/s
INFO: status: 97% (33354547200/34359738368), sparse 15% (5214232576), duration 686, read/write 30/30 MB/s
INFO: status: 98% (33700446208/34359738368), sparse 15% (5221597184), duration 696, read/write 34/33 MB/s
INFO: status: 100% (34359738368/34359738368), sparse 16% (5816553472), duration 699, read/write 219/21 MB/s
INFO: transferred 34359 MB in 699 seconds (49 MB/s)
INFO: archive file size: 12.15GB
INFO: delete old backup '/mnt/pve/Backups/dump/vzdump-qemu-132-2017_10_02-01_18_12.vma.lzo'
INFO: Finished Backup of VM 132 (00:11:40)
INFO: Starting Backup of VM 210 (qemu)
INFO: status = running
INFO: update VM 210: -lock backup
INFO: VM Name: ....
INFO: include disk 'virtio0' 'zfs-sata:vm-210-disk-1' 20G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating archive '/mnt/pve/Backups/dump/vzdump-qemu-210-2017_10_09-03_03_58.vma.lzo'
INFO: started backup task 'd16db746-efc3-4207-82d7-2ad429f14c88'
INFO: status: 0% (87425024/21474836480), sparse 0% (1007616), duration 4, read/write 21/21 MB/s
INFO: status: 1% (323092480/21474836480), sparse 0% (121090048), duration 8, read/write 58/28 MB/s
INFO: status: 2% (554958848/21474836480), sparse 1% (325574656), duration 13, read/write 46/5 MB/s
INFO: status: 4% (922681344/21474836480), sparse 2% (605360128), duration 16, read/write 122/29 MB/s
INFO: status: 7% (1638268928/21474836480), sparse 5% (1283149824), duration 20, read/write 178/9 MB/s
INFO: status: 8% (1725693952/21474836480), sparse 5% (1283407872), duration 23, read/write 29/29 MB/s
INFO: status: 9% (1934753792/21474836480), sparse 5% (1283592192), duration 40, read/write 12/12 MB/s
INFO: status: 10% (2185625600/21474836480), sparse 5% (1283682304), duration 57, read/write 14/14 MB/s
INFO: status: 11% (2368077824/21474836480), sparse 5% (1283842048), duration 65, read/write 22/22 MB/s
INFO: status: 12% (2603745280/21474836480), sparse 5% (1284730880), duration 75, read/write 23/23 MB/s
INFO: status: 13% (2812805120/21474836480), sparse 6% (1317273600), duration 83, read/write 26/22 MB/s
INFO: status: 21% (4615897088/21474836480), sparse 14% (3101638656), duration 86, read/write 601/6 MB/s
INFO: status: 30% (6572081152/21474836480), sparse 23% (5043621888), duration 89, read/write 652/4 MB/s
INFO: status: 31% (6678511616/21474836480), sparse 23% (5043916800), duration 93, read/write 26/26 MB/s
INFO: status: 32% (6891372544/21474836480), sparse 23% (5049389056), duration 104, read/write 19/18 MB/s
INFO: status: 34% (7330136064/21474836480), sparse 24% (5306372096), duration 116, read/write 36/15 MB/s
INFO: status: 44% (9599385600/21474836480), sparse 35% (7575621632), duration 119, read/write 756/0 MB/s
INFO: status: 53% (11532500992/21474836480), sparse 44% (9490145280), duration 122, read/write 644/6 MB/s
INFO: status: 54% (11616124928/21474836480), sparse 44% (9490309120), duration 128, read/write 13/13 MB/s
INFO: status: 97% (104205975552/107374182400), sparse 87% (93891178496), duration 751, read/write 47/20 MB/s
INFO: status: 99% (107044536320/107374182400), sparse 90% (96729739264), duration 754, read/write 946/0 MB/s
INFO: status: 100% (107374182400/107374182400), sparse 90% (97059385344), duration 755, read/write 329/0 MB/s
INFO: transferred 107374 MB in 755 seconds (142 MB/s)
INFO: archive file size: 6.29GB
INFO: delete old backup '/mnt/pve/Backups/dump/vzdump-qemu-209-2017_10_02-06_57_11.vma.lzo'
INFO: Finished Backup of VM 209 (00:12:37)

aderumier · Oct 9, 2017

What do you mean by stable performance ?

if the MB/s is different, it's because of sparse % (zeroes block), so it's normal that it's faster.

Last update increase block size for backup. (I think it was 4K before, and now 64k or 128k, not sure)

is it faster if you backup on a local storage ?

HBO · Oct 9, 2017

I think the read/write performance off this zfs pool is not very fast. Using 6 mirrored Seagate ST2000NX0263 with ZIL/L2ARC there should be more power? But ZIL/L2ARC disk is not connected to HBA, only SATA port on mainboard. Is this a bottleneck? Backup to local rpool zvol from proxmox is a bit slower, but these discs use only mainboard SATA ports too.
I've got 4 consumer Sandisks connected to mainboard too with softraid 10 and lvm-thin, their performance is a crap.

*edit*
Backup from zfs pool with HBA to Proxmox rpool mirrored with 2 Intel DC and only 60MB/s max?

Code:

INFO: starting new backup job: vzdump 110 --mode snapshot --compress lzo --storage local --remove 0 --node pve-node01
INFO: Starting Backup of VM 110 (qemu)
INFO: status = running
INFO: update VM 110: -lock backup
INFO: VM Name: icm-mail-K14001
INFO: include disk 'scsi0' 'zfs-sata:vm-110-disk-1' 100G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating archive '/var/lib/vz/dump/vzdump-qemu-110-2017_10_09-08_02_26.vma.lzo'
INFO: started backup task '45395110-c326-4925-91b8-a56eacd90697'
INFO: status: 0% (190054400/107374182400), sparse 0% (26333184), duration 5, read/write 38/32 MB/s
INFO: status: 1% (1128923136/107374182400), sparse 0% (379711488), duration 16, read/write 85/53 MB/s
INFO: status: 2% (2147614720/107374182400), sparse 0% (415051776), duration 33, read/write 59/57 MB/s
INFO: status: 3% (3329753088/107374182400), sparse 0% (723542016), duration 48, read/write 78/58 MB/s
INFO: status: 4% (4321837056/107374182400), sparse 0% (740659200), duration 64, read/write 62/60 MB/s
INFO: status: 5% (5427953664/107374182400), sparse 0% (774623232), duration 83, read/write 58/56 MB/s
INFO: status: 6% (6507462656/107374182400), sparse 0% (782954496), duration 101, read/write 59/59 MB/s
INFO: status: 7% (7548960768/107374182400), sparse 0% (819851264), duration 118, read/write 61/59 MB/s
INFO: status: 8% (8594259968/107374182400), sparse 0% (821854208), duration 134, read/write 65/65 MB/s
INFO: status: 9% (9726984192/107374182400), sparse 0% (860225536), duration 151, read/write 66/64 MB/s
INFO: status: 10% (10741874688/107374182400), sparse 0% (860225536), duration 163, read/write 84/84 MB/s
INFO: status: 11% (11840389120/107374182400), sparse 0% (881004544), duration 185, read/write 49/48 MB/s
INFO: status: 12% (12889489408/107374182400), sparse 0% (1015316480), duration 201, read/write 65/57 MB/s
INFO: status: 13% (13961396224/107374182400), sparse 0% (1063301120), duration 219, read/write 59/56 MB/s
INFO: status: 14% (15033303040/107374182400), sparse 0% (1064943616), duration 238, read/write 56/56 MB/s
INFO: status: 15% (16139419648/107374182400), sparse 1% (1309310976), duration 258, read/write 55/43 MB/s
INFO: status: 16% (17215127552/107374182400), sparse 1% (1960886272), duration 274, read/write 67/26 MB/s
INFO: status: 17% (18345623552/107374182400), sparse 2% (2294255616), duration 293, read/write 59/41 MB/s
INFO: status: 18% (19328532480/107374182400), sparse 2% (2680922112), duration 307, read/write 70/42 MB/s
INFO: status: 19% (20430848000/107374182400), sparse 2% (2769461248), duration 327, read/write 55/50 MB/s
INFO: status: 20% (21476147200/107374182400), sparse 2% (2770845696), duration 345, read/write 58/57 MB/s
INFO: status: 21% (22612672512/107374182400), sparse 2% (2869452800), duration 368, read/write 49/45 MB/s
INFO: status: 22% (23764402176/107374182400), sparse 3% (3404550144), duration 379, read/write 104/56 MB/s
INFO: status: 23% (24767889408/107374182400), sparse 3% (3793465344), duration 392, read/write 77/47 MB/s
INFO: status: 24% (25847398400/107374182400), sparse 3% (4217872384), duration 405, read/write 83/50 MB/s
INFO: status: 25% (26862288896/107374182400), sparse 4% (4339691520), duration 423, read/write 56/49 MB/s
INFO: status: 26% (28063432704/107374182400), sparse 4% (4621148160), duration 441, read/write 66/51 MB/s
INFO: status: 27% (29089726464/107374182400), sparse 4% (5050695680), duration 451, read/write 102/59 MB/s
INFO: status: 28% (30184439808/107374182400), sparse 5% (5492576256), duration 466, read/write 72/43 MB/s
INFO: status: 29% (31229739008/107374182400), sparse 5% (5919973376), duration 478, read/write 87/51 MB/s
INFO: status: 30% (32278839296/107374182400), sparse 6% (6507216896), duration 489, read/write 95/41 MB/s
INFO: status: 31% (33331740672/107374182400), sparse 6% (6801043456), duration 506, read/write 61/44 MB/s
INFO: status: 32% (34407448576/107374182400), sparse 6% (6819217408), duration 524, read/write 59/58 MB/s
INFO: status: 33% (35498360832/107374182400), sparse 6% (7015596032), duration 549, read/write 43/35 MB/s
INFO: status: 34% (36608278528/107374182400), sparse 6% (7050420224), duration 568, read/write 58/56 MB/s
INFO: status: 35% (37638373376/107374182400), sparse 6% (7244484608), duration 582, read/write 73/59 MB/s
INFO: status: 36% (38725484544/107374182400), sparse 6% (7260323840), duration 604, read/write 49/48 MB/s
INFO: status: 37% (39728971776/107374182400), sparse 6% (7461326848), duration 622, read/write 55/44 MB/s
INFO: status: 38% (40941518848/107374182400), sparse 7% (7950438400), duration 636, read/write 86/51 MB/s
INFO: status: 39% (42013425664/107374182400), sparse 7% (8282943488), duration 652, read/write 66/46 MB/s
INFO: status: 40% (42967498752/107374182400), sparse 8% (8680427520), duration 663, read/write 86/50 MB/s
INFO: status: 41% (44058411008/107374182400), sparse 8% (9024131072), duration 679, read/write 68/46 MB/s
INFO: status: 42% (45259554816/107374182400), sparse 8% (9567105024), duration 689, read/write 120/65 MB/s
INFO: status: 43% (46187020288/107374182400), sparse 9% (9900597248), duration 703, read/write 66/42 MB/s
INFO: status: 44% (47281733632/107374182400), sparse 9% (10204368896), duration 723, read/write 54/39 MB/s
INFO: status: 45% (48414457856/107374182400), sparse 9% (10655117312), duration 746, read/write 49/29 MB/s
INFO: status: 46% (49480794112/107374182400), sparse 10% (11205283840), duration 770, read/write 44/21 MB/s
INFO: status: 47% (50482249728/107374182400), sparse 10% (11573829632), duration 795, read/write 40/25 MB/s
INFO: status: 48% (51698597888/107374182400), sparse 11% (12373065728), duration 816, read/write 57/19 MB/s
INFO: status: 49% (52648869888/107374182400), sparse 12% (13043339264), duration 833, read/write 55/16 MB/s
INFO: status: 50% (53795225600/107374182400), sparse 12% (13938819072), duration 844, read/write 104/22 MB/s
INFO: status: 51% (54883909632/107374182400), sparse 13% (14519730176), duration 861, read/write 64/29 MB/s
INFO: status: 52% (55853187072/107374182400), sparse 14% (15155073024), duration 871, read/write 96/33 MB/s
INFO: status: 53% (56978309120/107374182400), sparse 14% (15869583360), duration 886, read/write 75/27 MB/s
INFO: status: 54% (58027409408/107374182400), sparse 15% (16549511168), duration 897, read/write 95/33 MB/s
INFO: status: 55% (59171536896/107374182400), sparse 15% (17000407040), duration 913, read/write 71/43 MB/s
INFO: status: 56% (60277653504/107374182400), sparse 16% (17440227328), duration 927, read/write 79/47 MB/s
INFO: status: 57% (61250732032/107374182400), sparse 16% (17824501760), duration 939, read/write 81/49 MB/s
INFO: status: 58% (62440472576/107374182400), sparse 17% (18501738496), duration 950, read/write 108/46 MB/s
INFO: status: 59% (63390744576/107374182400), sparse 17% (18882719744), duration 960, read/write 95/56 MB/s
INFO: status: 60% (64432242688/107374182400), sparse 18% (19408187392), duration 981, read/write 49/24 MB/s
INFO: status: 61% (65545961472/107374182400), sparse 18% (19782533120), duration 1000, read/write 58/38 MB/s
INFO: status: 62% (66579857408/107374182400), sparse 18% (20271800320), duration 1011, read/write 93/49 MB/s
INFO: status: 63% (67788603392/107374182400), sparse 19% (20587696128), duration 1028, read/write 71/52 MB/s
INFO: status: 64% (68845305856/107374182400), sparse 19% (20814209024), duration 1047, read/write 55/43 MB/s
INFO: status: 65% (69879201792/107374182400), sparse 19% (21014110208), duration 1064, read/write 60/49 MB/s
INFO: status: 66% (70973915136/107374182400), sparse 19% (21279154176), duration 1082, read/write 60/46 MB/s
INFO: status: 67% (72068628480/107374182400), sparse 20% (21521506304), duration 1100, read/write 60/47 MB/s
INFO: status: 68% (73026502656/107374182400), sparse 20% (21830090752), duration 1114, read/write 68/46 MB/s
INFO: status: 69% (74109812736/107374182400), sparse 20% (22226944000), duration 1127, read/write 83/52 MB/s
INFO: status: 70% (75200724992/107374182400), sparse 21% (22561140736), duration 1144, read/write 64/44 MB/s
INFO: status: 71% (76287836160/107374182400), sparse 21% (22883459072), duration 1161, read/write 63/44 MB/s
INFO: status: 72% (77336936448/107374182400), sparse 21% (23223836672), duration 1180, read/write 55/37 MB/s
INFO: status: 73% (78443053056/107374182400), sparse 21% (23580348416), duration 1197, read/write 65/44 MB/s
INFO: status: 74% (79568175104/107374182400), sparse 22% (23882457088), duration 1215, read/write 62/45 MB/s
INFO: status: 75% (80636280832/107374182400), sparse 22% (24190513152), duration 1231, read/write 66/47 MB/s
INFO: status: 76% (81639768064/107374182400), sparse 22% (24405737472), duration 1248, read/write 59/46 MB/s
INFO: status: 77% (82757287936/107374182400), sparse 23% (24700882944), duration 1266, read/write 62/45 MB/s
INFO: status: 78% (83756974080/107374182400), sparse 23% (24960458752), duration 1281, read/write 66/49 MB/s
INFO: status: 79% (84832681984/107374182400), sparse 23% (25070014464), duration 1313, read/write 33/30 MB/s
INFO: status: 80% (85999616000/107374182400), sparse 23% (25549254656), duration 1333, read/write 58/34 MB/s
INFO: status: 81% (87063920640/107374182400), sparse 24% (25948045312), duration 1350, read/write 62/39 MB/s
INFO: status: 82% (88154832896/107374182400), sparse 24% (26316664832), duration 1369, read/write 57/38 MB/s
INFO: status: 83% (89188728832/107374182400), sparse 24% (26464735232), duration 1394, read/write 41/35 MB/s
INFO: status: 84% (90374668288/107374182400), sparse 25% (26858291200), duration 1412, read/write 65/44 MB/s
INFO: status: 85% (91275526144/107374182400), sparse 25% (27093098496), duration 1427, read/write 60/44 MB/s
INFO: status: 86% (92362637312/107374182400), sparse 25% (27177754624), duration 1447, read/write 54/50 MB/s
INFO: status: 87% (93419339776/107374182400), sparse 25% (27451899904), duration 1462, read/write 70/52 MB/s
INFO: status: 88% (94590074880/107374182400), sparse 25% (27597012992), duration 1481, read/write 61/53 MB/s
INFO: status: 89% (95578357760/107374182400), sparse 25% (27847786496), duration 1497, read/write 61/46 MB/s
INFO: status: 90% (96779501568/107374182400), sparse 26% (28084064256), duration 1513, read/write 75/60 MB/s
INFO: status: 91% (97775386624/107374182400), sparse 26% (28122927104), duration 1530, read/write 58/56 MB/s
INFO: status: 92% (98797879296/107374182400), sparse 26% (28123795456), duration 1548, read/write 56/56 MB/s
INFO: status: 93% (99968614400/107374182400), sparse 26% (28158054400), duration 1571, read/write 50/49 MB/s
INFO: status: 94% (100960698368/107374182400), sparse 26% (28162220032), duration 1589, read/write 55/54 MB/s
INFO: status: 95% (102032605184/107374182400), sparse 26% (28195840000), duration 1607, read/write 59/57 MB/s
INFO: status: 96% (103104512000/107374182400), sparse 26% (28195840000), duration 1625, read/write 59/59 MB/s
INFO: status: 97% (104168816640/107374182400), sparse 26% (28229459968), duration 1644, read/write 56/54 MB/s
INFO: status: 98% (105328148480/107374182400), sparse 26% (28229459968), duration 1666, read/write 52/52 MB/s
INFO: status: 99% (106320232448/107374182400), sparse 26% (28256776192), duration 1682, read/write 62/60 MB/s
INFO: status: 100% (107374182400/107374182400), sparse 26% (28258873344), duration 1701, read/write 55/55 MB/s
INFO: transferred 107374 MB in 1701 seconds (63 MB/s)
INFO: archive file size: 49.98GB
INFO: Finished Backup of VM 110 (00:28:23)
INFO: Backup job finished successfully
TASK OK

guletz · Oct 9, 2017

Hi,

The time spent to finish a backup with vzdump, depends a lot if your guest have a lot of small files(a mail server as example) or not. And I think, if your VM use zfs, and the backup destination is also on zfs, it is a non-sense to compress your backup(by default zfs use adaptive compression).
In my opinion, is musch better to use zfs send/receive(it is very fast)!

HBO · Oct 9, 2017

That's true, but here an example: Simple VM with CentOS minimal installation and postfix relay for smth auth. Used 2GB from 20GB:

Code:

INFO: Starting Backup of VM 210 (qemu)
INFO: status = running
INFO: update VM 210: -lock backup
INFO: VM Name: mailp
INFO: include disk 'virtio0' 'zfs-sata:vm-210-disk-1' 20G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating archive '/mnt/pve/Backups/dump/vzdump-qemu-210-2017_10_09-03_03_58.vma.lzo'
INFO: started backup task 'd16db746-efc3-4207-82d7-2ad429f14c88'
INFO: status: 0% (87425024/21474836480), sparse 0% (1007616), duration 4, read/write 21/21 MB/s
INFO: status: 1% (323092480/21474836480), sparse 0% (121090048), duration 8, read/write 58/28 MB/s
INFO: status: 2% (554958848/21474836480), sparse 1% (325574656), duration 13, read/write 46/5 MB/s
INFO: status: 4% (922681344/21474836480), sparse 2% (605360128), duration 16, read/write 122/29 MB/s
INFO: status: 7% (1638268928/21474836480), sparse 5% (1283149824), duration 20, read/write 178/9 MB/s
INFO: status: 8% (1725693952/21474836480), sparse 5% (1283407872), duration 23, read/write 29/29 MB/s
INFO: status: 9% (1934753792/21474836480), sparse 5% (1283592192), duration 40, read/write 12/12 MB/s
INFO: status: 10% (2185625600/21474836480), sparse 5% (1283682304), duration 57, read/write 14/14 MB/s
INFO: status: 11% (2368077824/21474836480), sparse 5% (1283842048), duration 65, read/write 22/22 MB/s
INFO: status: 12% (2603745280/21474836480), sparse 5% (1284730880), duration 75, read/write 23/23 MB/s
INFO: status: 13% (2812805120/21474836480), sparse 6% (1317273600), duration 83, read/write 26/22 MB/s
INFO: status: 21% (4615897088/21474836480), sparse 14% (3101638656), duration 86, read/write 601/6 MB/s
INFO: status: 30% (6572081152/21474836480), sparse 23% (5043621888), duration 89, read/write 652/4 MB/s
INFO: status: 31% (6678511616/21474836480), sparse 23% (5043916800), duration 93, read/write 26/26 MB/s
INFO: status: 32% (6891372544/21474836480), sparse 23% (5049389056), duration 104, read/write 19/18 MB/s
INFO: status: 34% (7330136064/21474836480), sparse 24% (5306372096), duration 116, read/write 36/15 MB/s
INFO: status: 44% (9599385600/21474836480), sparse 35% (7575621632), duration 119, read/write 756/0 MB/s
INFO: status: 53% (11532500992/21474836480), sparse 44% (9490145280), duration 122, read/write 644/6 MB/s
INFO: status: 54% (11616124928/21474836480), sparse 44% (9490309120), duration 128, read/write 13/13 MB/s
INFO: status: 55% (11844190208/21474836480), sparse 44% (9491808256), duration 138, read/write 22/22 MB/s
INFO: status: 56% (12038045696/21474836480), sparse 44% (9492725760), duration 145, read/write 27/27 MB/s
INFO: status: 57% (12250906624/21474836480), sparse 44% (9492725760), duration 162, read/write 12/12 MB/s
INFO: status: 58% (12478971904/21474836480), sparse 44% (9557794816), duration 170, read/write 28/20 MB/s
INFO: status: 60% (12923699200/21474836480), sparse 46% (9955033088), duration 173, read/write 148/15 MB/s
INFO: status: 69% (14976614400/21474836480), sparse 55% (12007948288), duration 176, read/write 684/0 MB/s
INFO: status: 76% (16508125184/21474836480), sparse 62% (13502537728), duration 179, read/write 510/12 MB/s
INFO: status: 77% (16603152384/21474836480), sparse 62% (13502746624), duration 182, read/write 31/31 MB/s
INFO: status: 78% (16751394816/21474836480), sparse 62% (13506211840), duration 193, read/write 13/13 MB/s
INFO: status: 83% (17846566912/21474836480), sparse 67% (14442725376), duration 212, read/write 57/8 MB/s
INFO: status: 98% (21086928896/21474836480), sparse 82% (17683087360), duration 215, read/write 1080/0 MB/s
INFO: status: 100% (21474836480/21474836480), sparse 84% (18070994944), duration 216, read/write 387/0 MB/s
INFO: transferred 21474 MB in 216 seconds (99 MB/s)
INFO: archive file size: 1.28GB
INFO: delete old backup '/mnt/pve/Backups/dump/vzdump-qemu-210-2017_10_02-07_08_53.vma.lzo'
INFO: Finished Backup of VM 210 (00:03:37)
INFO: Backup job finished successfully
TASK OK

Possible to get more speed with another ionice value? What value have best performance?

aderumier · Oct 9, 2017

guletz said:
Hi,

The time spent to finish a backup with vzdump, depends a lot if your guest have a lot of small files(a mail server as example) or not.

For qemu, vzdump backup blocks, not files, so no impact here if you have millions a small files
for lxc, indeed, a lot of files can slowdown backup

aderumier · Oct 9, 2017

HBO said:
Possible to get more speed with another ionice value? What value have best performance?

I don't think that ionice is working with zfs. (as zfs has his own io scheduler).

AFAIK, ionice only work with cfq scheduler. (and proxmox use deadline by default)

guletz · Oct 9, 2017

aderumier said:
For qemu, vzdump backup blocks, not files, so no impact here if you have millions a small files
for lxc, indeed, a lot of files can slowdown backup

Good to know that vzdump work with blocks. Even with blocks, many small files can result a slowdown backup. I write a small file = 6 K at the fs level, who will need a 2 zvol blocks(with 4k default zvol block size). Multiply 2 blocks with 1.000.000 files. Yes, the performance is better comapared with files, but could be a lot of others factors !!!

HBO · Oct 9, 2017

Thats true, i did a few benchmarks on Linux and Windows VMs. All VMs have more than 400MB/s read/write performance with small and big files. So what causes these slow backups?

Found this in cron.d:

# Scrub the second Sunday of every month.
24 0 8-14 * * root [ $(date +\%w) -eq 0 ] && [ -x /usr/lib/zfs-linux/scrub ] && /usr/lib/zfs-linux/scrub

So:

Code:

  scan: scrub in progress since Sun Oct  8 00:24:05 2017

    1.77T scanned out of 2.07T at 19.4M/s, 4h25m to go
    0 repaired, 85.73% done

I'll wait for backups this night...

HBO · Oct 10, 2017

Scrub finished yesterday 4pm. Backup job this night took 4h 30min, same backup job with running scrup day before took only 3 hours.
This fluctuation can't be normal?!

guletz · Oct 10, 2017

Like I said, try to make the backup, without compression.

HBO · Oct 10, 2017

I don't know why this should work, tried it and performance is not better. As i asked in first post, is it possible that there is a bottleneck because off using mainboard connected devices pro proxmox rpool and ZIL/L2ARC disk?

guletz · Oct 10, 2017

HBO said:
As i asked in first post, is it possible that there is a bottleneck because off using mainboard connected devices pro proxmox rpool and ZIL/L2ARC disk?

I guess that you make backup's when your clients have a very low activitity, so ZIL and/or L2ARC is not used very much. But you can test if the presence of ZIL/L2ARC have any impact during backup period. You can remove any ZIL/L2ARC device before the backup, and after the backup is finish you can re-add again in the pool. Any ZIL/L2ARC device can be add and/or remove from pool at any time.

HBO · Oct 11, 2017

Looks like same speed without ZIL/L2ARC, backups took 4h 38min.
But why speed on vm's differ so hard during backup job from 30 to 600 MB/s? There is no difference (PVE Staff said stop mode works better) between snapshot and stop mode.

It's possible to get more information from PVE staff?

fabian · Oct 11, 2017

HBO said:
Looks like same speed without ZIL/L2ARC, backups took 4h 38min.
But why speed on vm's differ so hard during backup job from 30 to 600 MB/s? There is no difference (PVE Staff said stop mode works better) between snapshot and stop mode.

It's possible to get more information from PVE staff?

the speed varies because your VM disks contains holes, which don't actually need to be read from disk (but still count as read). you can see the jumps in the sparse column whenever the read speed is higher than normal, and that nothing/little gets written at those points. it looks like your regular read speed is probably somewhere in the 20-40MB/s range.

how is the performance of the zpool on the host? how is it inside a VM? you can benchmark using fio, and play around with different block sizes (both for the I/O, and for the zvol itself).

HBO · Oct 11, 2017

I had some problems with my zpool (8k blocksize instead off 4k). This is fixed, in german area i posted some fio tests: https://forum.proxmox.com/threads/zfs-performance-testen.36906/#post-181108

Performance is good, 1-2% iowait, inside VM i have up to 800MB/s write and 1,2GB/s read. That's the point why i'm asking because off this slow backup speed.

Writing 100GB file manually from pve system to nfs export works with full speed.

fabian · Oct 11, 2017

HBO said:
I had some problems with my zpool (8k blocksize instead off 4k). This is fixed, in german area i posted some fio tests: https://forum.proxmox.com/threads/zfs-performance-testen.36906/#post-181108

Performance is good, 1-2% iowait, inside VM i have up to 800MB/s write and 1,2GB/s read. That's the point why i'm asking because off this slow backup speed.

Writing 100GB file manually from pve system to nfs export works with full speed.

then the next step would be to watch with "zpool iostat -vy POOLNAME 10" and "iostat -ydmx /dev/DISK1 /dev/DISK2 /dev/DISK3 ... 10" during a fast fio run/other I/O and a slow backup. it is possible that the way vzdump accesses the disks via Qemu produces a bad access pattern in combination with your 4Kn disks.

HBO · Oct 11, 2017

So here it is.

Code:

root@pve-node01:~# fio --filename=/dev/zvol/sata/test --sync=1 --rw=randwrite --bs=4k --numjobs=1 --iodepth=1 --runtime=120 --time_based --group_reporting --name=journal-test
journal-test: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=psync, iodepth=1
fio-2.16
Starting 1 process
Jobs: 1 (f=1): [f(1)] [100.0% done] [0KB/0KB/0KB /s] [0/0/0 iops] [eta 00m:00s]
journal-test: (groupid=0, jobs=1): err= 0: pid=36868: Wed Oct 11 10:48:07 2017
  write: io=2184.7MB, bw=18642KB/s, iops=4660, runt=120001msec
    clat (usec): min=136, max=3235.1K, avg=212.72, stdev=4342.85
     lat (usec): min=136, max=3235.1K, avg=212.92, stdev=4342.85
    clat percentiles (usec):
     |  1.00th=[  149],  5.00th=[  161], 10.00th=[  167], 20.00th=[  179],
     | 30.00th=[  187], 40.00th=[  195], 50.00th=[  203], 60.00th=[  209],
     | 70.00th=[  215], 80.00th=[  227], 90.00th=[  241], 95.00th=[  258],
     | 99.00th=[  306], 99.50th=[  322], 99.90th=[  556], 99.95th=[ 1112],
     | 99.99th=[ 2928]
    lat (usec) : 250=93.67%, 500=6.21%, 750=0.04%, 1000=0.02%
    lat (msec) : 2=0.03%, 4=0.02%, 10=0.01%, 20=0.01%, 50=0.01%
    lat (msec) : 100=0.01%, 250=0.01%, >=2000=0.01%
  cpu          : usr=1.17%, sys=23.84%, ctx=1118839, majf=0, minf=542
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=559274/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
  WRITE: io=2184.7MB, aggrb=18642KB/s, minb=18642KB/s, maxb=18642KB/s, mint=120001msec, maxt=120001msec
root@pve-node01:~# fio --filename=/dev/zvol/sata/test --sync=1 --rw=randread --bs=4k --numjobs=1 --iodepth=1 --runtime=120 --time_based --group_reporting --name=journal-test
journal-test: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=psync, iodepth=1
fio-2.16
Starting 1 process
Jobs: 1 (f=1): [f(1)] [100.0% done] [0KB/0KB/0KB /s] [0/0/0 iops] [eta 00m:00s]
journal-test: (groupid=0, jobs=1): err= 0: pid=37584: Wed Oct 11 10:50:16 2017
  read : io=162826MB, bw=1356.9MB/s, iops=347358, runt=120001msec
    clat (usec): min=0, max=1904, avg= 2.45, stdev= 2.92
     lat (usec): min=0, max=1904, avg= 2.49, stdev= 2.93
    clat percentiles (usec):
     |  1.00th=[    1],  5.00th=[    1], 10.00th=[    1], 20.00th=[    1],
     | 30.00th=[    1], 40.00th=[    1], 50.00th=[    1], 60.00th=[    2],
     | 70.00th=[    2], 80.00th=[    2], 90.00th=[    9], 95.00th=[   10],
     | 99.00th=[   11], 99.50th=[   11], 99.90th=[   14], 99.95th=[   15],
     | 99.99th=[   19]
    lat (usec) : 2=54.88%, 4=31.68%, 10=5.90%, 20=7.53%, 50=0.01%
    lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%
    lat (msec) : 2=0.01%
  cpu          : usr=18.29%, sys=81.67%, ctx=105, majf=0, minf=182
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=41683335/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
   READ: io=162826MB, aggrb=1356.9MB/s, minb=1356.9MB/s, maxb=1356.9MB/s, mint=120001msec, maxt=120001msec

Files iostat-fio.log and zpool-iostat-fio.log depend on this FIO result.

Code:

INFO: starting new backup job: vzdump 147 --mode snapshot --compress lzo --storage Backups --remove 0 --node pve-node01
INFO: Starting Backup of VM 147 (qemu)
INFO: status = running
INFO: update VM 147: -lock backup
INFO: VM Name: win10-Intern-K14163
INFO: include disk 'scsi0' 'zfs-sata:vm-147-disk-1' 100G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating archive '/mnt/pve/Backups/dump/vzdump-qemu-147-2017_10_11-10_54_22.vma.lzo'
INFO: started backup task 'ad8b2d3c-4e1b-490f-8119-f10f9874d607'
INFO: status: 0% (642383872/107374182400), sparse 0% (572862464), duration 3, read/write 214/23 MB/s
INFO: status: 1% (1132724224/107374182400), sparse 0% (637833216), duration 13, read/write 49/42 MB/s
INFO: status: 2% (2159017984/107374182400), sparse 0% (639987712), duration 45, read/write 32/32 MB/s
INFO: status: 3% (3249930240/107374182400), sparse 0% (654483456), duration 88, read/write 25/25 MB/s
INFO: status: 4% (4310433792/107374182400), sparse 0% (702910464), duration 120, read/write 33/31 MB/s
INFO: status: 5% (5393743872/107374182400), sparse 0% (730501120), duration 166, read/write 23/22 MB/s
INFO: status: 6% (6503661568/107374182400), sparse 0% (767389696), duration 196, read/write 36/35 MB/s
INFO: status: 7% (7556562944/107374182400), sparse 0% (799043584), duration 247, read/write 20/20 MB/s
INFO: status: 8% (8620867584/107374182400), sparse 0% (813047808), duration 278, read/write 34/33 MB/s
INFO: status: 9% (9856221184/107374182400), sparse 1% (1195143168), duration 316, read/write 32/22 MB/s
INFO: status: 10% (10753277952/107374182400), sparse 1% (1219944448), duration 339, read/write 39/37 MB/s
INFO: status: 11% (11878793216/107374182400), sparse 1% (1628250112), duration 365, read/write 43/27 MB/s
INFO: status: 12% (13827833856/107374182400), sparse 3% (3577290752), duration 368, read/write 649/0 MB/s
INFO: status: 14% (15192948736/107374182400), sparse 4% (4937412608), duration 375, read/write 195/0 MB/s
INFO: status: 15% (16112812032/107374182400), sparse 4% (4970274816), duration 574, read/write 4/4 MB/s
INFO: status: 16% (17184718848/107374182400), sparse 4% (4970307584), duration 680, read/write 10/10 MB/s
INFO: status: 17% (18264227840/107374182400), sparse 4% (4970311680), duration 885, read/write 5/5 MB/s
INFO: status: 18% (19332333568/107374182400), sparse 4% (4970319872), duration 960, read/write 14/14 MB/s
INFO: status: 19% (20430848000/107374182400), sparse 4% (5007421440), duration 1023, read/write 17/16 MB/s
INFO: status: 20% (21479948288/107374182400), sparse 4% (5011763200), duration 1054, read/write 33/33 MB/s
INFO: status: 21% (22582263808/107374182400), sparse 4% (5014872064), duration 1085, read/write 35/35 MB/s
INFO: status: 22% (23699783680/107374182400), sparse 4% (5017366528), duration 1116, read/write 36/35 MB/s
INFO: status: 23% (24699469824/107374182400), sparse 4% (5018697728), duration 1145, read/write 34/34 MB/s
INFO: status: 24% (25801785344/107374182400), sparse 4% (5024526336), duration 1181, read/write 30/30 MB/s
INFO: status: 25% (26885095424/107374182400), sparse 4% (5026283520), duration 1212, read/write 34/34 MB/s
INFO: status: 26% (27930394624/107374182400), sparse 4% (5027561472), duration 1248, read/write 29/29 MB/s
INFO: status: 27% (29028909056/107374182400), sparse 4% (5064454144), duration 1280, read/write 34/33 MB/s
INFO: status: 28% (30070407168/107374182400), sparse 4% (5083488256), duration 1304, read/write 43/42 MB/s
INFO: status: 29% (31142313984/107374182400), sparse 4% (5236903936), duration 1339, read/write 30/26 MB/s
INFO: status: 30% (32297844736/107374182400), sparse 4% (5236985856), duration 1361, read/write 52/52 MB/s
INFO: status: 31% (33331740672/107374182400), sparse 4% (5236985856), duration 1390, read/write 35/35 MB/s
INFO: status: 32% (34494873600/107374182400), sparse 4% (5236985856), duration 1409, read/write 61/61 MB/s
INFO: status: 33% (35479355392/107374182400), sparse 4% (5237186560), duration 1435, read/write 37/37 MB/s
INFO: status: 34% (36528455680/107374182400), sparse 4% (5271203840), duration 1463, read/write 37/36 MB/s
INFO: status: 35% (37581357056/107374182400), sparse 4% (5319151616), duration 1506, read/write 24/23 MB/s
INFO: status: 36% (38695075840/107374182400), sparse 5% (5819650048), duration 1527, read/write 53/29 MB/s
INFO: status: 37% (39740375040/107374182400), sparse 6% (6695731200), duration 1538, read/write 95/15 MB/s
INFO: status: 38% (41345548288/107374182400), sparse 7% (8154382336), duration 1548, read/write 160/14 MB/s
INFO: status: 39% (41910796288/107374182400), sparse 8% (8698990592), duration 1552, read/write 141/5 MB/s
INFO: status: 40% (43199365120/107374182400), sparse 9% (9869230080), duration 1560, read/write 161/14 MB/s
INFO: status: 41% (44073615360/107374182400), sparse 9% (10256920576), duration 1581, read/write 41/23 MB/s
INFO: status: 42% (45103710208/107374182400), sparse 9% (10261655552), duration 1620, read/write 26/26 MB/s
INFO: status: 43% (46230994944/107374182400), sparse 9% (10733830144), duration 1637, read/write 66/38 MB/s
INFO: status: 44% (48187441152/107374182400), sparse 11% (12690276352), duration 1640, read/write 652/0 MB/s
INFO: status: 46% (50152144896/107374182400), sparse 13% (14654980096), duration 1643, read/write 654/0 MB/s
INFO: status: 48% (52103741440/107374182400), sparse 15% (16606576640), duration 1646, read/write 650/0 MB/s
INFO: status: 50% (54013132800/107374182400), sparse 17% (18515968000), duration 1649, read/write 636/0 MB/s
INFO: status: 52% (55920164864/107374182400), sparse 19% (20423000064), duration 1652, read/write 635/0 MB/s
INFO: status: 53% (57837813760/107374182400), sparse 20% (22340648960), duration 1655, read/write 639/0 MB/s
INFO: status: 55% (59749629952/107374182400), sparse 22% (24252465152), duration 1658, read/write 637/0 MB/s
INFO: status: 57% (61670359040/107374182400), sparse 24% (26173194240), duration 1661, read/write 640/0 MB/s
INFO: status: 59% (63601573888/107374182400), sparse 26% (28104409088), duration 1664, read/write 643/0 MB/s
INFO: status: 61% (65521254400/107374182400), sparse 27% (30024089600), duration 1667, read/write 639/0 MB/s
INFO: status: 62% (67409281024/107374182400), sparse 29% (31912116224), duration 1670, read/write 629/0 MB/s
INFO: status: 64% (69319262208/107374182400), sparse 31% (33822097408), duration 1673, read/write 636/0 MB/s
INFO: status: 66% (71231143936/107374182400), sparse 33% (35733979136), duration 1676, read/write 637/0 MB/s
INFO: status: 68% (73137848320/107374182400), sparse 35% (37640683520), duration 1680, read/write 476/0 MB/s
INFO: status: 69% (75038588928/107374182400), sparse 36% (39541424128), duration 1683, read/write 633/0 MB/s
INFO: status: 71% (76951715840/107374182400), sparse 38% (41454551040), duration 1686, read/write 637/0 MB/s
INFO: status: 73% (78874804224/107374182400), sparse 40% (43377639424), duration 1689, read/write 641/0 MB/s
INFO: status: 75% (80773578752/107374182400), sparse 42% (45276413952), duration 1692, read/write 632/0 MB/s
INFO: status: 76% (82677465088/107374182400), sparse 43% (47180300288), duration 1695, read/write 634/0 MB/s
INFO: status: 78% (84585283584/107374182400), sparse 45% (49088118784), duration 1698, read/write 635/0 MB/s
INFO: status: 80% (86513221632/107374182400), sparse 47% (51016056832), duration 1701, read/write 642/0 MB/s
INFO: status: 82% (88417894400/107374182400), sparse 49% (52920729600), duration 1704, read/write 634/0 MB/s
INFO: status: 84% (90316341248/107374182400), sparse 51% (54819176448), duration 1707, read/write 632/0 MB/s
INFO: status: 85% (92209283072/107374182400), sparse 52% (56712118272), duration 1710, read/write 630/0 MB/s
INFO: status: 87% (94120640512/107374182400), sparse 54% (58623475712), duration 1713, read/write 637/0 MB/s
INFO: status: 89% (96023740416/107374182400), sparse 56% (60526575616), duration 1716, read/write 634/0 MB/s
INFO: status: 91% (97930772480/107374182400), sparse 58% (62433607680), duration 1719, read/write 635/0 MB/s
INFO: status: 92% (99827253248/107374182400), sparse 59% (64330088448), duration 1722, read/write 632/0 MB/s
INFO: status: 94% (101744640000/107374182400), sparse 61% (66247475200), duration 1725, read/write 639/0 MB/s
INFO: status: 96% (103633518592/107374182400), sparse 63% (68136353792), duration 1728, read/write 629/0 MB/s
INFO: status: 98% (105610477568/107374182400), sparse 65% (70113312768), duration 1731, read/write 658/0 MB/s
INFO: status: 99% (106905600000/107374182400), sparse 66% (71355228160), duration 1735, read/write 323/13 MB/s
INFO: status: 100% (107374182400/107374182400), sparse 66% (71357321216), duration 1743, read/write 58/58 MB/s
INFO: transferred 107374 MB in 1743 seconds (61 MB/s)
INFO: archive file size: 23.39GB
INFO: Finished Backup of VM 147 (00:29:05)
INFO: Backup job finished successfully
TASK OK

Files iostat-vzdump.log and zpool-iostat-vzdump.log depend on this vzdump output.

Looks like vzdump/qemu isn't able to use the maximum performance? Bug with vzdump or qemu?

fabian · Oct 11, 2017

those logs are either incomplete, or you are mainly benchmarking your caches, at least for reading:
1356.9MB/s is nowhere close to what your logs show. if you repeat the experiment, it might make sense to also run "arcstat 10" and include the l2arc and zil devices in the iostat device list for a more complete picture.

that being said, I think you are probably mainly hitting "reading uncached data in small blocks using a single thread from spinning disks is not fast" when running vzdump..

Backup performance issues

Active Member

Active Member

Renowned Member

Active Member

Famous Member

Active Member

Renowned Member

Renowned Member

Famous Member

Active Member

Active Member

Famous Member

Active Member

Famous Member

Active Member

Proxmox Staff Member

Active Member

Proxmox Staff Member

Active Member

Attachments

Proxmox Staff Member