[6.3] vzdump-Backup bricht ab, VM bleibt hängen

[_Lars_]

Seit dem PVE-Upgrade von 6.1 auf 6.3 Anfang Januar ist jetzt zweimal das vzdump-Backup abgebrochen und die betreffende VM lief danach nicht mehr:

08./09.01.2020:
VMID NAME STATUS TIME SIZE FILENAME
100 <VM_NAME> err 01:50:22 0.00MB -

Detailed backup logs:
vzdump 100 --dumpdir /backup/dest --mailto [...] --compress lzo --quiet 1 --remove 0 --mode stop --mailnotification always

100: 2021-01-08 23:55:34 INFO: Starting Backup of VM 100 (qemu)
100: 2021-01-08 23:55:34 INFO: status = running
100: 2021-01-08 23:55:34 INFO: backup mode: stop
100: 2021-01-08 23:55:34 INFO: ionice priority: 7
100: 2021-01-08 23:55:34 INFO: VM Name: <VM_NAME>
100: 2021-01-08 23:55:34 INFO: include disk 'scsi0' 'pool_sas:vm-100-disk-0' 102G
100: 2021-01-08 23:55:34 INFO: include disk 'scsi1' 'pool_sas:vm-100-disk-1' 1500G
100: 2021-01-08 23:55:35 INFO: stopping vm
100: 2021-01-08 23:56:10 INFO: creating vzdump archive '/path/to/backup/vzdump-qemu-100-2021_01_08-23_55_34.vma.lzo'
100: 2021-01-08 23:56:10 INFO: starting kvm to execute backup task
100: 2021-01-08 23:56:11 INFO: started backup task '2b8433aa-80d2-48b3-a6ec-ec7dc0f9b70b'
100: 2021-01-08 23:56:11 INFO: resuming VM again after 36 seconds
100: 2021-01-08 23:56:14 INFO: 0% (899.0 MiB of 1.6 TiB) in 3s, read: 299.7 MiB/s, write: 266.0 MiB/s
[...]
100: 2021-01-09 01:24:07 INFO: 38% (608.8 GiB of 1.6 TiB) in 1h 27m 56s, read: 79.8 MiB/s, write: 79.8 MiB/s
100: 2021-01-09 01:35:52 ERROR: VM 100 qmp command 'query-backup' failed - got timeout
100: 2021-01-09 01:35:52 INFO: aborting backup job
100: 2021-01-09 01:45:52 ERROR: VM 100 qmp command 'backup-cancel' failed - unable to connect to VM 100 qmp socket - timeout after 5992 retries
100: 2021-01-09 01:45:56 ERROR: Backup of VM 100 failed - VM 100 qmp command 'query-backup' failed - got timeout

13./14.01.2020:
VMID NAME STATUS TIME SIZE FILENAME
100 <VM_NAME> err 01:01:10 0.00MB -

Detailed backup logs:
vzdump 100 --dumpdir /backup/dest --mailto [...] --compress lzo --quiet 1 --remove 0 --mode stop --mailnotification always

100: 2021-01-13 23:56:11 INFO: Starting Backup of VM 100 (qemu)
100: 2021-01-13 23:56:11 INFO: status = running
100: 2021-01-13 23:56:11 INFO: backup mode: stop
100: 2021-01-13 23:56:11 INFO: ionice priority: 7
100: 2021-01-13 23:56:11 INFO: VM Name: <VM_NAME>
100: 2021-01-13 23:56:11 INFO: include disk 'scsi0' 'pool_sas:vm-100-disk-0' 102G
100: 2021-01-13 23:56:11 INFO: include disk 'scsi1' 'pool_sas:vm-100-disk-1' 1500G
100: 2021-01-13 23:56:12 INFO: stopping vm
100: 2021-01-13 23:56:51 INFO: creating vzdump archive '/path/to/backup/vzdump-qemu-100-2021_01_13-23_56_11.vma.lzo'
100: 2021-01-13 23:56:51 INFO: starting kvm to execute backup task
100: 2021-01-13 23:56:52 INFO: started backup task '44b33452-d813-410b-9205-aaacb4ff7c16'
100: 2021-01-13 23:56:52 INFO: resuming VM again after 40 seconds
100: 2021-01-13 23:56:55 INFO: 0% (845.6 MiB of 1.6 TiB) in 3s, read: 281.9 MiB/s, write: 248.5 MiB/s
[...]
100: 2021-01-14 00:35:08 INFO: 23% (368.5 GiB of 1.6 TiB) in 38m 16s, read: 79.0 MiB/s, write: 79.0 MiB/s
100: 2021-01-14 00:47:17 ERROR: VM 100 qmp command 'query-backup' failed - got timeout
100: 2021-01-14 00:47:17 INFO: aborting backup job
100: 2021-01-14 00:57:17 ERROR: VM 100 qmp command 'backup-cancel' failed - unable to connect to VM 100 qmp socket - timeout after 5992 retries
100: 2021-01-14 00:57:21 ERROR: Backup of VM 100 failed - VM 100 qmp command 'query-backup' failed - got timeout

Einen Auszug aus /var/log/syslog vom Fall am 14.01. hab ich angehängt. Das System ist nicht irgendwie ausgelastet, in /var/log/kern.log ist nichts relevantes zu sehen.

Es werden zwei VM gesichert. Die erste (ID 102) mit einer LVM-Disk (320GB) lief beides mal durch, bei der zweiten (ID 100) mit zwei LVM disks (100GB und 1500GB) brach das Backup ab. Bei ersten Mal mußte ich die hänge VM explizit mit SIGKILL beenden, beim zweiten Mal lief sie nicht mehr. Vor dem Upgrade gab es dieses Problem nicht.
Platz auf dem Backup-Ziel ist genug vorhanden. Wo könnte ich noch suchen?

 

[oguz]

hi,

kannst du bitte diese posten:
- pveversion -v
- qm config VMID (fuer beide VM)

 

[pixelpeter]

Hallo,

Dasselbe auch bei mir. Es gab ein Timeout beim fsfreeze. Dann läuft die VM nicht mehr.
Es geht ein paar Tage, dann betrifft es eine VM, Am nächsten Tag eine andere.
Softwarestand: aktuelles Enterprise Repository.
Das Timeout Problem kam bei mir auch erst durch ein Update von 6.1 auf 6.3.
Die letzten Jahre hatten wir das nie.
Ich sehe aber das Problem darin das die VM tot ist. Ein Backup sollte schon mal abbrechen können ohne das da etwas passiert.


Peter

 

[_Lars_]

Das System ist eine Community Edition und dient als Testsystem für die Produktivumgebung.
In den VMs sind QM-Agent und die VirtIO-Treiber in Version 0.1.185 installiert

node01~:# pveversion -v

proxmox-ve: 6.3-1 (running kernel: 5.4.78-2-pve)
pve-manager: 6.3-3 (running version: 6.3-3/eee5f901)
pve-kernel-5.4: 6.3-3
pve-kernel-helper: 6.3-3
pve-kernel-5.3: 6.1-6
pve-kernel-5.0: 6.0-11
pve-kernel-5.4.78-2-pve: 5.4.78-2
pve-kernel-5.3.18-3-pve: 5.3.18-3
pve-kernel-5.3.13-3-pve: 5.3.13-3
pve-kernel-5.3.13-2-pve: 5.3.13-2
pve-kernel-5.3.13-1-pve: 5.3.13-1
pve-kernel-5.0.21-5-pve: 5.0.21-10
ceph-fuse: 12.2.11+dfsg1-2.1+b1
corosync: 3.0.4-pve1
criu: 3.11-3
glusterfs-client: 5.5-3
ifupdown: 0.8.35+pve1
libjs-extjs: 6.0.1-10
libknet1: 1.16-pve1
libproxmox-acme-perl: 1.0.7
libproxmox-backup-qemu0: 1.0.2-1
libpve-access-control: 6.1-3
libpve-apiclient-perl: 3.1-3
libpve-common-perl: 6.3-2
libpve-guest-common-perl: 3.1-3
libpve-http-server-perl: 3.1-1
libpve-storage-perl: 6.3-3
libqb0: 1.0.5-1
libspice-server1: 0.14.2-4~pve6+1
lvm2: 2.03.02-pve4
lxc-pve: 4.0.3-1
lxcfs: 4.0.3-pve3
novnc-pve: 1.1.0-1
proxmox-backup-client: 1.0.6-1
proxmox-mini-journalreader: 1.1-1
proxmox-widget-toolkit: 2.4-3
pve-cluster: 6.2-1
pve-container: 3.3-2
pve-docs: 6.3-1
pve-edk2-firmware: 2.20200531-1
pve-firewall: 4.1-3
pve-firmware: 3.1-3
pve-ha-manager: 3.1-1
pve-i18n: 2.2-2
pve-qemu-kvm: 5.1.0-7
pve-xtermjs: 4.7.0-3
qemu-server: 6.3-2
smartmontools: 7.1-pve2
spiceterm: 3.1-1
vncterm: 1.6-2
zfsutils-linux: 0.8.5-pve1

Das ist die betroffende VM, läuft beim Backup als zweites:

node01~:# qm config 100
balloon: 0
boot: c
bootdisk: scsi0
cores: 4
cpu: EPYC
ide2: none,media=cdrom
memory: 24576
name: <name>
net0: virtio=00:11:22:33:44:55,bridge=vmbr0
numa: 0
ostype: win8
scsi0: pool_sas:vm-100-disk-0,size=102G
scsi1: pool_sas:vm-100-disk-1,size=1500G
scsihw: virtio-scsi-pci
smbios1: uuid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx
sockets: 1
usb0: host=3-2.2,usb3=1
vmgenid: xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx

Diese VM war bisher nicht betroffen, läuft im backup zuerst:

node01~:# qm config 102
agent: 1
balloon: 0
boot: c
bootdisk: scsi0
cores: 6
cpu: EPYC
ide2: none,media=cdrom
memory: 32768
name: <name>
net0: virtio=AA:BB:CC:DD:EE:FF,bridge=vmbr0
numa: 0
ostype: win10
scsi0: pool_sas:vm-102-disk-0,size=320G
scsihw: virtio-scsi-pci
smbios1: uuid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx
sockets: 1
vmgenid: xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx

 

[_Lars_]

Heute Nacht trat das Problem wieder auf, jetzt zum zweiten Mal in Folge.

Wie bekomme ich ein paar mehr Debugausgaben, was beim Stoppen/Starten der VM passiert?

 

[_Lars_]

Bis heute läuft das Backup ohne Fehler, allerdings brach letzte Nacht die Lese- und Schreiberate so weit ein, daß das Backup, welches üblicherweise gegen 03:00 Uhr fertig ist, bis eben 14:42 Uhr dauerte:

[...]
100: 2021-01-20 00:12:52 INFO: 13% (208.4 GiB of 1.6 TiB) in 15m 10s, read: 257.3 MiB/s, write: 251.6 MiB/s
100: 2021-01-20 00:13:54 INFO: 14% (224.4 GiB of 1.6 TiB) in 16m 12s, read: 264.4 MiB/s, write: 256.4 MiB/s
100: 2021-01-20 00:15:00 INFO: 15% (240.4 GiB of 1.6 TiB) in 17m 18s, read: 248.9 MiB/s, write: 239.4 MiB/s
100: 2021-01-20 00:16:07 INFO: 16% (256.5 GiB of 1.6 TiB) in 18m 25s, read: 245.5 MiB/s, write: 217.8 MiB/s
100: 2021-01-20 00:26:32 INFO: 17% (272.3 GiB of 1.6 TiB) in 28m 50s, read: 26.0 MiB/s, write: 25.6 MiB/s
100: 2021-01-20 00:43:10 INFO: 18% (288.4 GiB of 1.6 TiB) in 45m 28s, read: 16.4 MiB/s, write: 16.4 MiB/s
100: 2021-01-20 00:56:13 INFO: 19% (304.5 GiB of 1.6 TiB) in 58m 31s, read: 21.1 MiB/s, write: 21.1 MiB/s
100: 2021-01-20 01:03:25 INFO: 20% (320.4 GiB of 1.6 TiB) in 1h 5m 43s, read: 37.8 MiB/s, write: 36.2 MiB/s
100: 2021-01-20 01:18:10 INFO: 21% (336.4 GiB of 1.6 TiB) in 1h 20m 28s, read: 18.5 MiB/s, write: 18.5 MiB/s
100: 2021-01-20 01:33:17 INFO: 22% (352.4 GiB of 1.6 TiB) in 1h 35m 35s, read: 18.1 MiB/s, write: 18.1 MiB/s
100: 2021-01-20 01:48:53 INFO: 23% (368.5 GiB of 1.6 TiB) in 1h 51m 11s, read: 17.5 MiB/s, write: 17.5 MiB/s
100: 2021-01-20 02:04:31 INFO: 24% (384.5 GiB of 1.6 TiB) in 2h 6m 49s, read: 17.5 MiB/s, write: 17.5 MiB/s
[...]

Teilweise ging die Werte am Vormittag bis in den Kilobytebereich runter. Die RAID-Devices (LVM-Pool als auch Backup) sind im Status "optimal",
keine Meldung im "kern.log", ich weiß nicht, wo ich suchen soll.

@pixelpeter: Tritt das Problem bei Dir auch noch auf?

 

[_Lars_]

Schade, daß dieser Thread zum Monolog geworden ist. Letzte Nacht wieder dieser Slowdown, das Backup läuft immernoch. Zumindest bricht es nicht mehr ab, das ist ein Fortschritt. Aber so können die Mitarbeiter an diesem Standort nicht mehr das richtige Backup-Tape einlegen, weil das Backup nicht vor Dienstschluß fertig ist.

Ich habe alle logs durchforstet, nirgends ein Hinweis, der irgendwie weiterhilft. Beim noch laufenden Backup brach wieder bei 16% die Transferrate auf ähnliche Werte wie die Nacht zuvor ein.

Die Änderung von Absturz zu Slowdown trat nach dem "apt upgrade" am 16.01. auf, bei dem folgendes aktualisiert wurde:

libpve-storage-perl:amd64 (6.3-3, 6.3-4)
pve-qemu-kvm:amd64 (5.1.0-7, 5.1.0-8)
libpve-guest-common-perl:amd64 (3.1-3, 3.1-4)
qemu-server:amd64 (6.3-2, 6.3-3)
lxcfs:amd64 (4.0.3-pve3, 4.0.6-pve1)

 

[oguz]

hallo,

Schade, daß dieser Thread zum Monolog geworden ist.

sorry!

Die Änderung von Absturz zu Slowndown trat nach dem "apt upgrade" am 16.01. auf, bei dem folgendes aktualisiert wurde:

hast du nach dem upgrade deine VM/CT nochmal aus und eingeschaltet?

was fuer ein storage benutzt diese VM? kannst du bitte /etc/pve/storage.cfg posten?

 

[_Lars_]

hast du nach dem upgrade deine VM/CT nochmal aus und eingeschaltet?

Ja, weil VirtIO-Treiber und QM-Agent auf 0.1.185 aktualisiert.

was fuer ein storage benutzt diese VM? kannst du bitte /etc/pve/storage.cfg posten?

dir: local
    path /var/lib/vz
    content vztmpl,iso,images,snippets,rootdir
    maxfiles 0

lvm: pool_sas
    vgname pool_sas
    content rootdir,images
    nodes node01
    shared 0

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

root@node01:~# pvs
    Logging initialised at Thu Jan 21 15:43:59 2021
    Set umask from 0022 to 0077
  PV         VG        Fmt  Attr PSize  PFree
  /dev/sdd   pool_sata lvm2 a--  <1.82t  1.50g
  /dev/sde   pool_sas  lvm2 a--   3.49t <1.21t

Die Partitionen /dev/sdd und /dev/sde sind lokale Hardware-RAIDs.
"pool_sas", auf dem die beiden VM liegen ist ein RAID1 aus zwei SAMSUNG PM1643 mit je 3,84TB (SAS 12Gbps)
"pool_sata" ist ebenfalls ein RAID1 aus zwei 2TB SSDs, welches nur für's Schreiben des Backups genutzt wird

EDIT: Jetzt läuft auch das Backup der ersten VM mit angezogener Handbremse. Während das bisher für 320Gb keine 30 Minuten brauchte, sind jetzt (0:40) gerade einmal 33% bei Leseraten von um 20MB/s geschafft. :-(

 

[crmspezi]

Hallo Lars,
ich habe die gleichen Probleme wie Du, auf mehreren Hosts, nur bei Windows VM's, Guest Tools alt bis neu. Die gleichen Probleme bestanden von schon vor Monaten einmal, auch mit der "Aufmerksamkeit" hier.
Vor 3 Tagen habe ich aus dem community repository auf dem PBS und den PVE's alles auf den aktuellen Update Stand gebracht. Das Freeze ist auch weg, aber die Performance ist sehr schlecht geworden (zwischen 10-30MB/s). Der Storage schafft ca. 250MB/s (10G Anbindung) und hat trotz Raidz2 über 12 SATA HDD's vernünftige IO Leistung dafür. Zum Test habe ich da mal eine IO lastige Windows Server Testinstallation auf dem PBS Storage gemacht (zfs over iSCSI). Das lief gut, wenn auch nicht perfekt. Es kann also nicht an der Hardware liegen.

Deshalb sichere ich auch parallel aus den VM's heraus mit Veeam (free) auf den gleichen Storage (anderes VDEV), hier allerdings mit über 150MByte/s ohne Probleme. Der PBS ist eine sehr gute Lösung, nur machen mir hier die immer wiederkehrenden Probleme viele Bauchschmerzen, so dass ich die vzdump Backup's derzeit mal wieder nur auf den PBS am WE nutzen tue.

Viele Grüße
crmspezi

 

[_Lars_]

Den PBs habe ich noch nicht ausprobiert, aber wenn der die gleichen Probleme hat...
Ich wollte ungern die große VM mit 1.6TB auf die 6.1 zurückverschieben, das kostet unnötig viel Zeit.

 

[oguz]

was ist beim /backup/dest mit deinem dumpdir ? gibt es da genug platz?
kannst du vielleicht mit einem anderen dumpdir probieren?

 

[crmspezi]

meine /etc/vzdump.conf
# vzdump default settings
# zstd: 4
#tmpdir: DIR
#dumpdir: DIR
#storage: STORAGE_ID
#mode: snapshot|suspend|stop
#bwlimit: KBPS
#ionice: PRI
#lockwait: MINUTES
#stopwait: MINUTES
#size: MB
#stdexcludes: BOOLEAN
#mailto: ADDRESSLIST
#maxfiles: N
#script: FILENAME
#exclude-path: PATHLIST
#pigz: N

Ich habe in Erinnerung, damit sollte das Ziel als /backup/dest mit benutzt werden (laut Doku pve 5.x von damals). Ein /backup/dest gibt es nicht bei mir. Ebenso wenig Swap.

 

[_Lars_]

was ist beim /backup/dest mit deinem dumpdir ? gibt es da genug platz?
kannst du vielleicht mit einem anderen dumpdir probieren?

Auf /backup/dest ist bei mir genug Platz. Ich würde auch eher einen harten Abbruch in der Art "out of space", als einen Einbrauch der Leseraten mit dennoch erfolgreicehm Abschluss des Backups.

Ein anderes Ziel, das der Schreibrate des lokalen Backup-Storage gleich käme, kann ich nicht einrichten, weil ich auf 1GB/s-LAN beschränkt bin.

Das Backup läuft hier wie folgt:
1) beide VMs werden auf das lokale Backup-Storage (Hardware-RAID1 aus zwei 2TB-SSDs) gesichert
2) die lokale Sicherung wird danach auf ein externes Wechsel-Medium kopiert (und das klappt nicht mehr, weil das Backup jetzt statt 3,5h tlw. 16-17h benötigt!)