Server crash when backup to PBS

[vch]

Hello,

After an update to the latest version, one of our PVE server crash every night during the backup to PBS.

We have the latest version from the entreprise repo (8.1.3).

The problem occurs every time we start the backup job. The problem was not present before the update.

The server become unresponsive at 00:30, just when the backup start. VMs are offline, SSH is offline, everything is down, etc ...
5-10min after, it's online again but with the VM 421 STOP. (cf logs)

We have other nodes with exactly the same version, the same hardware, etc ... and no problems.
It's seems the server crash during the backup of this specific VM.

Ceph is installed on all our nodes but this VM does not use CEPH and have dedicated local nvme drives (2 Kioxia drives KCD6XLUL960G) with a ZFS mirror.
It's an Ubuntu with a Postgresql DB. The QEMU agent is installed on the VM.

Hardware of the host :
Supermicro AS -1114S-WTRT/H12SSW-NT
48 x AMD EPYC 7443P 24-Core Processor (1 Socket)
128Gb RAM
Linux 6.5.11-7-pve (2023-12-05T09:44Z)

In normal times, the host has a load average of 10% CPU, plenty of free RAM and plenty of free disk space.

Thanks for helping.

 

[vch]

Logs of the backup task :

INFO: Starting Backup of VM 421 (qemu)

INFO: Backup started at 2024-01-06 00:30:00

INFO: status = running

INFO: VM Name: db-1

INFO: include disk 'scsi0' 'nvme:vm-421-disk-0' 264396M

INFO: backup mode: snapshot

INFO: ionice priority: 7

INFO: creating Proxmox Backup Server archive 'vm/421/2024-01-05T23:30:00Z'

INFO: issuing guest-agent 'fs-freeze' command

INFO: issuing guest-agent 'fs-thaw' command

INFO: started backup task 'da556b89-0037-432a-9892-2e95e885a6cf'

INFO: resuming VM again

INFO: scsi0: dirty-bitmap status: created new

INFO:   0% (348.0 MiB of 258.2 GiB) in 3s, read: 116.0 MiB/s, write: 52.0 MiB/s

INFO:   1% (2.6 GiB of 258.2 GiB) in 26s, read: 101.9 MiB/s, write: 51.1 MiB/s

INFO:   2% (5.8 GiB of 258.2 GiB) in 43s, read: 189.2 MiB/s, write: 23.5 MiB/s

INFO:   3% (7.9 GiB of 258.2 GiB) in 49s, read: 355.3 MiB/s, write: 48.7 MiB/s

INFO:   4% (10.3 GiB of 258.2 GiB) in 1m 2s, read: 196.3 MiB/s, write: 72.0 MiB/s

INFO:   5% (13.2 GiB of 258.2 GiB) in 1m 30s, read: 104.0 MiB/s, write: 46.3 MiB/s

INFO:   6% (15.6 GiB of 258.2 GiB) in 1m 46s, read: 153.5 MiB/s, write: 53.5 MiB/s

INFO:   7% (18.8 GiB of 258.2 GiB) in 1m 54s, read: 405.0 MiB/s, write: 64.5 MiB/s

INFO:   8% (20.7 GiB of 258.2 GiB) in 2m 3s, read: 222.7 MiB/s, write: 89.8 MiB/s

INFO:   9% (23.3 GiB of 258.2 GiB) in 2m 20s, read: 154.8 MiB/s, write: 76.0 MiB/s

INFO:  10% (26.0 GiB of 258.2 GiB) in 2m 28s, read: 343.0 MiB/s, write: 88.5 MiB/s

INFO:  11% (28.4 GiB of 258.2 GiB) in 2m 41s, read: 192.9 MiB/s, write: 116.0 MiB/s

INFO:  12% (31.3 GiB of 258.2 GiB) in 2m 53s, read: 245.0 MiB/s, write: 128.0 MiB/s

INFO:  13% (33.6 GiB of 258.2 GiB) in 3m 7s, read: 168.3 MiB/s, write: 75.4 MiB/s

INFO:  14% (36.4 GiB of 258.2 GiB) in 3m 32s, read: 115.2 MiB/s, write: 67.4 MiB/s

INFO:  15% (38.9 GiB of 258.2 GiB) in 3m 53s, read: 123.8 MiB/s, write: 63.8 MiB/s

INFO:  16% (41.9 GiB of 258.2 GiB) in 4m, read: 433.1 MiB/s, write: 136.0 MiB/s

INFO:  17% (44.0 GiB of 258.2 GiB) in 4m 10s, read: 212.4 MiB/s, write: 102.0 MiB/s

INFO:  18% (46.5 GiB of 258.2 GiB) in 4m 21s, read: 235.6 MiB/s, write: 63.3 MiB/s

INFO:  19% (49.2 GiB of 258.2 GiB) in 4m 37s, read: 173.8 MiB/s, write: 76.2 MiB/s

INFO:  20% (51.8 GiB of 258.2 GiB) in 4m 46s, read: 288.9 MiB/s, write: 125.3 MiB/s

INFO:  21% (54.4 GiB of 258.2 GiB) in 5m 28s, read: 64.6 MiB/s, write: 43.3 MiB/s

ERROR: VM 421 qmp command 'query-backup' failed - client closed connection

INFO: aborting backup job

ERROR: VM 421 not running

INFO: resuming VM again

ERROR: Backup of VM 421 failed - VM 421 not running

INFO: Failed at 2024-01-06 00:37:53

 

[vch]

Logs of the event (2 parts because of forum char limit):

n 06 00:30:00 pve-82457dcb pvescheduler[1479734]: INFO: starting new backup job: vzdump 201 301 660 998 401 421 666 630 640 --notes-template '{{guestname}}' --storage pbs-0e9f586c --mailto support@XXX.fr --mode snapshot --mailnotification always --quiet 1
Jan 06 00:30:00 pve-82457dcb pvescheduler[1479734]: INFO: Starting Backup of VM 421 (qemu)
Jan 06 00:30:00 pve-82457dcb pmxcfs[2505]: [status] notice: received log
Jan 06 00:30:01 pve-82457dcb pmxcfs[2505]: [status] notice: received log
Jan 06 00:36:30 pve-82457dcb pvescheduler[1484017]: replication: cfs-lock 'file-replication_cfg' error: got lock request timeout
Jan 06 00:36:47 pve-82457dcb zed[1484098]: eid=371 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=131072 offset=816242888704 priority=0 err=0 flags=0x40080480 delay=59278ms
Jan 06 00:36:47 pve-82457dcb zed[1484080]: eid=367 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=122880 offset=816245837824 priority=0 err=0 flags=0x40080480 delay=35181ms
Jan 06 00:36:47 pve-82457dcb zed[1484074]: eid=365 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=4096 offset=816259452928 priority=2 err=0 flags=0x180180 delay=36370ms bookmark=174:1:0:3172545
Jan 06 00:36:47 pve-82457dcb zed[1484059]: eid=360 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=131072 offset=816243449856 priority=0 err=0 flags=0x40080480 delay=33548ms
Jan 06 00:36:47 pve-82457dcb zed[1484071]: eid=364 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=122880 offset=816247214080 priority=0 err=0 flags=0x40080480 delay=32093ms
Jan 06 00:36:47 pve-82457dcb zed[1484088]: eid=369 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=86016 offset=816245112832 priority=0 err=0 flags=0x40080480 delay=47398ms
Jan 06 00:36:47 pve-82457dcb zed[1484083]: eid=368 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=122880 offset=816246882304 priority=0 err=0 flags=0x40080480 delay=32098ms
Jan 06 00:36:47 pve-82457dcb zed[1484062]: eid=361 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=131072 offset=816259047424 priority=2 err=0 flags=0x40080480 delay=33286ms
Jan 06 00:36:47 pve-82457dcb pve-firewall[2742]: firewall update time (67.876 seconds)
Jan 06 00:36:47 pve-82457dcb zed[1484033]: eid=358 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=122880 offset=816246513664 priority=0 err=0 flags=0x40080480 delay=33001ms
Jan 06 00:36:47 pve-82457dcb zed[1484103]: eid=372 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=122880 offset=816249647104 priority=0 err=0 flags=0x40080480 delay=60101ms
Jan 06 00:36:47 pve-82457dcb zed[1484065]: eid=362 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=122880 offset=816244105216 priority=0 err=0 flags=0x40080480 delay=33286ms
Jan 06 00:36:47 pve-82457dcb zed[1484095]: eid=370 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=49152 offset=816236675072 priority=0 err=0 flags=0x40080480 delay=60147ms
Jan 06 00:36:47 pve-82457dcb ceph-mon[2600]: 2024-01-06T00:36:47.405+0100 7fdac50446c0 -1 mon.pve-82457dcb@1(peon).paxos(paxos updating c 16471123..16471648) lease_expire from mon.0 v2:10.10.5.11:3300/0 is 72.535934448s seconds in the past; mons are probably laggy (or possibly clocks are too skewed)
Jan 06 00:36:47 pve-82457dcb zed[1484156]: eid=375 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=122880 offset=816244228096 priority=0 err=0 flags=0x40080480 delay=61875ms
Jan 06 00:36:47 pve-82457dcb zed[1484153]: eid=374 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=24576 offset=816244350976 priority=0 err=0 flags=0x40080480 delay=60152ms
Jan 06 00:36:47 pve-82457dcb ceph-mon[2600]: 2024-01-06T00:36:47.769+0100 7fdac78496c0 -1 mon.pve-82457dcb@1(electing) e3 get_health_metrics reporting 3 slow ops, oldest is mdsbeacon(1494871/pve-82457dcb up:standby seq=21519 v49)
Jan 06 00:36:47 pve-82457dcb ceph-osd[340460]: 2024-01-06T00:36:47.841+0100 7f73b796c6c0 -1 osd.0 1551 set_numa_affinity unable to identify public interface '' numa node: (2) No such file or directory
Jan 06 00:36:47 pve-82457dcb zed[1484197]: eid=377 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=122880 offset=816248160256 priority=0 err=0 flags=0x40080480 delay=48235ms
Jan 06 00:36:47 pve-82457dcb zed[1484218]: eid=381 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=28672 offset=816234598400 priority=0 err=0 flags=0x40080480 delay=77534ms
Jan 06 00:36:47 pve-82457dcb zed[1484243]: eid=383 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=131072 offset=816259538944 priority=2 err=0 flags=0x40080480 delay=53534ms
Jan 06 00:36:47 pve-82457dcb zed[1484207]: eid=380 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=86016 offset=816247128064 priority=0 err=0 flags=0x40080480 delay=77534ms
Jan 06 00:36:47 pve-82457dcb zed[1484237]: eid=382 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=122880 offset=816247336960 priority=0 err=0 flags=0x40080480 delay=76676ms
Jan 06 00:36:47 pve-82457dcb zed[1484270]: eid=384 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=122880 offset=816250015744 priority=0 err=0 flags=0x40080480 delay=45554ms
Jan 06 00:36:47 pve-82457dcb zed[1484194]: eid=378 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=8192 offset=816234577920 priority=0 err=0 flags=0x180080 delay=30561ms bookmark=174:1:0:3170073
Jan 06 00:36:47 pve-82457dcb zed[1484282]: eid=387 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=131072 offset=816260673536 priority=2 err=0 flags=0x40080480 delay=45450ms
Jan 06 00:36:47 pve-82457dcb zed[1484293]: eid=390 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=122880 offset=816244875264 priority=0 err=0 flags=0x40080480 delay=34455ms
Jan 06 00:37:17 pve-82457dcb pve-ha-lrm[3126]: loop take too long (32 seconds)
Jan 06 00:37:17 pve-82457dcb pve-ha-crm[2873]: loop take too long (32 seconds)
Jan 06 00:37:25 pve-82457dcb pvedaemon[1385005]: VM 631 qmp command failed - VM 631 qmp command 'query-proxmox-support' failed - got timeout
Jan 06 00:37:36 pve-82457dcb ceph-mon[2600]: 2024-01-06T00:37:36.168+0100 7fdac78496c0 -1 mon.pve-82457dcb@1(peon) e3 get_health_metrics reporting 37 slow ops, oldest is mgrbeacon mgr.pve-82457dcb(25654e9e-ecaa-4bc1-9ca1-0d3f883dc3f4,1494847, , 0)
Jan 06 00:37:37 pve-82457dcb zed[1484431]: eid=391 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=126976 offset=816264867840 priority=0 err=0 flags=0x40080480 delay=47929ms
Jan 06 00:37:37 pve-82457dcb zed[1484438]: eid=392 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=4096 offset=816271290368 priority=0 err=0 flags=0x180080 delay=49402ms bookmark=174:1:0:3174465
Jan 06 00:37:37 pve-82457dcb zed[1484439]: eid=393 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=4096 offset=816271376384 priority=0 err=0 flags=0x180080 delay=49401ms bookmark=174:1:0:3174486
Jan 06 00:37:37 pve-82457dcb zed[1484479]: eid=395 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=131072 offset=816268435456 priority=0 err=0 flags=0x40080480 delay=40036ms
Jan 06 00:37:37 pve-82457dcb zed[1484466]: eid=394 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=126976 offset=816265940992 priority=0 err=0 flags=0x40080480 delay=49459ms
Jan 06 00:37:37 pve-82457dcb zed[1484457]: eid=400 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=122880 offset=816266317824 priority=0 err=0 flags=0x40080480 delay=49462ms
Jan 06 00:37:37 pve-82457dcb zed[1484470]: eid=401 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=131072 offset=816274604032 priority=0 err=0 flags=0x40080480 delay=40025ms
Jan 06 00:37:37 pve-82457dcb zed[1484469]: eid=402 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A00DT5M8-part1 size=131072 offset=816268828672 priority=0 err=0 flags=0x40080480 delay=40029ms
Jan 06 00:37:37 pve-82457dcb zed[1484471]: eid=398 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=122880 offset=816270962688 priority=0 err=0 flags=0x40080480 delay=40021ms
Jan 06 00:37:37 pve-82457dcb zed[1484493]: eid=404 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=4096 offset=816269467648 priority=0 err=0 flags=0x180080 delay=49524ms bookmark=174:1:0:3174274

 

[vch]

Jan 06 00:37:45 pve-82457dcb kernel: corosync invoked oom-killer: gfp_mask=0x4c2cc0(GFP_KERNEL_ACCOUNT|__GFP_NOWARN|__GFP_COMP|__GFP_NOMEMALLOC), order=2, oom_score_adj=0
Jan 06 00:37:45 pve-82457dcb kernel: CPU: 7 PID: 2667 Comm: corosync Tainted: P           O       6.5.11-7-pve #1
Jan 06 00:37:45 pve-82457dcb kernel: Hardware name: Supermicro AS -1114S-WTRT/H12SSW-NT, BIOS 2.5 09/26/2022
Jan 06 00:37:45 pve-82457dcb kernel: Call Trace:
Jan 06 00:37:45 pve-82457dcb kernel:  <TASK>
Jan 06 00:37:45 pve-82457dcb kernel:  dump_stack_lvl+0x48/0x70
Jan 06 00:37:45 pve-82457dcb kernel:  dump_stack+0x10/0x20
Jan 06 00:37:45 pve-82457dcb kernel:  dump_header+0x4f/0x260
Jan 06 00:37:45 pve-82457dcb kernel:  oom_kill_process+0x10d/0x1c0
Jan 06 00:37:45 pve-82457dcb kernel:  out_of_memory+0x270/0x560
Jan 06 00:37:45 pve-82457dcb kernel:  __alloc_pages+0x114f/0x12e0
Jan 06 00:37:45 pve-82457dcb kernel:  ? __alloc_skb+0x8a/0x1b0
Jan 06 00:37:45 pve-82457dcb kernel:  __kmalloc_large_node+0x7e/0x160
Jan 06 00:37:45 pve-82457dcb kernel:  ? memcg_slab_post_alloc_hook+0x1bf/0x280
Jan 06 00:37:45 pve-82457dcb kernel:  __kmalloc_node_track_caller.cold+0x5/0xa3
Jan 06 00:37:45 pve-82457dcb kernel:  kmalloc_reserve+0x67/0x100
Jan 06 00:37:45 pve-82457dcb kernel:  __alloc_skb+0x8a/0x1b0
Jan 06 00:37:45 pve-82457dcb kernel:  alloc_skb_with_frags+0x4d/0x240
Jan 06 00:37:45 pve-82457dcb kernel:  ? srso_alias_return_thunk+0x5/0x7f
Jan 06 00:37:45 pve-82457dcb kernel:  sock_alloc_send_pskb+0x20e/0x260
Jan 06 00:37:45 pve-82457dcb kernel:  ? udp_recvmsg+0x90/0x580
Jan 06 00:37:45 pve-82457dcb kernel:  ? srso_alias_return_thunk+0x5/0x7f
Jan 06 00:37:45 pve-82457dcb kernel:  ? wait_for_unix_gc+0x46/0x110
Jan 06 00:37:45 pve-82457dcb kernel:  ? skb_ts_finish+0x20/0x50
Jan 06 00:37:45 pve-82457dcb kernel:  unix_dgram_sendmsg+0x171/0xb80
Jan 06 00:37:45 pve-82457dcb kernel:  ? srso_alias_return_thunk+0x5/0x7f
Jan 06 00:37:45 pve-82457dcb kernel:  ? inet_recvmsg+0x121/0x140
Jan 06 00:37:45 pve-82457dcb kernel:  unix_seqpacket_sendmsg+0x34/0x80
Jan 06 00:37:45 pve-82457dcb kernel:  sock_write_iter+0x191/0x1a0
Jan 06 00:37:45 pve-82457dcb kernel:  do_iter_readv_writev+0xf2/0x160
Jan 06 00:37:45 pve-82457dcb kernel:  do_iter_write+0xa5/0x220
Jan 06 00:37:45 pve-82457dcb kernel:  vfs_writev+0xf8/0x1c0
Jan 06 00:37:45 pve-82457dcb kernel:  do_writev+0x108/0x170
Jan 06 00:37:45 pve-82457dcb kernel:  __x64_sys_writev+0x1c/0x30
Jan 06 00:37:45 pve-82457dcb kernel:  do_syscall_64+0x5b/0x90
Jan 06 00:37:45 pve-82457dcb kernel:  ? srso_alias_return_thunk+0x5/0x7f
Jan 06 00:37:45 pve-82457dcb kernel:  ? syscall_exit_to_user_mode+0x37/0x60
Jan 06 00:37:45 pve-82457dcb kernel:  ? srso_alias_return_thunk+0x5/0x7f
Jan 06 00:37:45 pve-82457dcb kernel:  ? do_syscall_64+0x67/0x90
Jan 06 00:37:45 pve-82457dcb kernel:  ? srso_alias_return_thunk+0x5/0x7f
Jan 06 00:37:45 pve-82457dcb kernel:  ? do_syscall_64+0x67/0x90
Jan 06 00:37:45 pve-82457dcb kernel:  ? do_syscall_64+0x67/0x90
Jan 06 00:37:45 pve-82457dcb kernel:  ? srso_alias_return_thunk+0x5/0x7f
Jan 06 00:37:45 pve-82457dcb kernel:  ? syscall_exit_to_user_mode+0x37/0x60
Jan 06 00:37:45 pve-82457dcb kernel:  ? srso_alias_return_thunk+0x5/0x7f
Jan 06 00:37:45 pve-82457dcb kernel:  ? do_syscall_64+0x67/0x90
Jan 06 00:37:45 pve-82457dcb kernel:  ? syscall_exit_to_user_mode+0x37/0x60
Jan 06 00:37:45 pve-82457dcb kernel:  ? srso_alias_return_thunk+0x5/0x7f
Jan 06 00:37:45 pve-82457dcb kernel:  ? do_syscall_64+0x67/0x90
Jan 06 00:37:45 pve-82457dcb kernel:  ? do_syscall_64+0x67/0x90
Jan 06 00:37:45 pve-82457dcb kernel:  ? do_syscall_64+0x67/0x90
Jan 06 00:37:45 pve-82457dcb kernel:  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
Jan 06 00:37:45 pve-82457dcb kernel: RIP: 0033:0x7fb567a2ac8d
Jan 06 00:37:45 pve-82457dcb kernel: Code: 28 89 54 24 1c 48 89 74 24 10 89 7c 24 08 e8 3a 7a f8 ff 8b 54 24 1c 48 8b 74 24 10 41 89 c0 8b 7c 24 08 b8 14 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 33 44 89 c7 48 89 44 24 08 e8 8e 7a f8 ff 48
Jan 06 00:37:45 pve-82457dcb kernel: RSP: 002b:00007fb5649dfa60 EFLAGS: 00000293 ORIG_RAX: 0000000000000014
Jan 06 00:37:45 pve-82457dcb kernel: RAX: ffffffffffffffda RBX: 00007fb55df5c010 RCX: 00007fb567a2ac8d
Jan 06 00:37:45 pve-82457dcb kernel: RDX: 0000000000000001 RSI: 00007fb5649dfb50 RDI: 0000000000000016
Jan 06 00:37:45 pve-82457dcb kernel: RBP: 00007fb564a19e40 R08: 0000000000000000 R09: 0000000000000004
Jan 06 00:37:45 pve-82457dcb kernel: R10: 0000000000000575 R11: 0000000000000293 R12: 00007fb55db4c010
Jan 06 00:37:45 pve-82457dcb kernel: R13: 00005649963805a0 R14: 00007fb5649dfb50 R15: 00007fb5649e1eb0
Jan 06 00:37:45 pve-82457dcb kernel:  </TASK>
Jan 06 00:37:45 pve-82457dcb kernel: Mem-Info:
Jan 06 00:37:45 pve-82457dcb kernel: active_anon:6291798 inactive_anon:11653602 isolated_anon:0
 active_file:0 inactive_file:1403 isolated_file:0
 unevictable:37459 dirty:140 writeback:245
 slab_reclaimable:16003 slab_unreclaimable:1602873
 mapped:22564 shmem:22347 pagetables:46287
 sec_pagetables:35004 bounce:0
 kernel_misc_reclaimable:0
 free:2513010 free_pcp:258 free_cma:0
Jan 06 00:37:45 pve-82457dcb kernel: Node 0 active_anon:28318556kB inactive_anon:43463044kB active_file:0kB inactive_file:5412kB unevictable:149836kB isolated(anon):0kB isolated(file):0kB mapped:90244kB dirty:560kB writeback:980kB shmem:89388kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 6989824kB writeback_tmp:0kB kernel_stack:22208kB pagetables:185148kB sec_pagetables:140016kB all_unreclaimable? no
Jan 06 00:37:45 pve-82457dcb kernel: Node 0 DMA free:11264kB boost:0kB min:4kB low:16kB high:28kB reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15360kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Jan 06 00:37:45 pve-82457dcb kernel: lowmem_reserve[]: 0 2553 128575 128575 128575
Jan 06 00:37:45 pve-82457dcb kernel: Node 0 DMA32 free:504764kB boost:0kB min:1340kB low:3952kB high:6564kB reserved_highatomic:0KB active_anon:1701172kB inactive_anon:99400kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:2742108kB managed:2673640kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Jan 06 00:37:45 pve-82457dcb kernel: lowmem_reserve[]: 0 0 126021 126021 126021
Jan 06 00:37:45 pve-82457dcb kernel: Node 0 Normal free:9534968kB boost:486480kB min:552712kB low:681756kB high:810800kB reserved_highatomic:2048KB active_anon:31623428kB inactive_anon:38357724kB active_file:0kB inactive_file:5684kB unevictable:149836kB writepending:1540kB present:131318784kB managed:129054272kB mlocked:149836kB bounce:0kB free_pcp:952kB local_pcp:0kB free_cma:0kB
Jan 06 00:37:45 pve-82457dcb kernel: lowmem_reserve[]: 0 0 0 0 0
Jan 06 00:37:45 pve-82457dcb kernel: Node 0 DMA: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 1*1024kB (U) 1*2048kB (M) 2*4096kB (M) = 11264kB
Jan 06 00:37:45 pve-82457dcb kernel: Node 0 DMA32: 2715*4kB (UME) 2608*8kB (UME) 61*16kB (E) 84*32kB (UE) 652*64kB (UE) 1451*128kB (UE) 595*256kB (UE) 125*512kB (UE) 25*1024kB (U) 0*2048kB 0*4096kB = 504764kB
Jan 06 00:37:45 pve-82457dcb kernel: Node 0 Normal: 1774213*4kB (UM) 305080*8kB (UE) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 9537492kB
Jan 06 00:37:45 pve-82457dcb kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Jan 06 00:37:45 pve-82457dcb kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Jan 06 00:37:45 pve-82457dcb kernel: 26511 total pagecache pages
Jan 06 00:37:45 pve-82457dcb kernel: 0 pages in swap cache
Jan 06 00:37:45 pve-82457dcb kernel: Free swap  = 0kB
Jan 06 00:37:45 pve-82457dcb kernel: Total swap = 0kB
Jan 06 00:37:45 pve-82457dcb kernel: 33519222 pages RAM
Jan 06 00:37:45 pve-82457dcb kernel: 0 pages HighMem/MovableOnly
Jan 06 00:37:45 pve-82457dcb kernel: 583404 pages reserved
Jan 06 00:37:45 pve-82457dcb kernel: 0 pages hwpoisoned

 

[vch]

Jan 06 00:37:45 pve-82457dcb kernel: Tasks state (memory values in pages):
Jan 06 00:37:45 pve-82457dcb kernel: [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
Jan 06 00:37:45 pve-82457dcb kernel: [   1318]     0  1318     6814      768    77824        0         -1000 systemd-udevd
Jan 06 00:37:45 pve-82457dcb kernel: [   2141]   103  2141     1969      576    49152        0             0 rpcbind
Jan 06 00:37:45 pve-82457dcb kernel: [   2151] 64045  2151     5064     2880    69632        0             0 ceph-crash
Jan 06 00:37:45 pve-82457dcb kernel: [   2158]   101  2158     2329      768    53248        0          -900 dbus-daemon
Jan 06 00:37:45 pve-82457dcb kernel: [   2161]     0  2161    38187      288    61440        0         -1000 lxcfs
Jan 06 00:37:45 pve-82457dcb kernel: [   2163]     0  2163    69539      480    81920        0             0 pve-lxc-syscall
Jan 06 00:37:45 pve-82457dcb kernel: [   2166]     0  2166     1766      672    49152        0             0 ksmtuned
Jan 06 00:37:45 pve-82457dcb kernel: [   2168]     0  2168     2999      960    57344        0             0 smartd
Jan 06 00:37:45 pve-82457dcb kernel: [   2169]     0  2169     1327      288    49152        0             0 qmeventd
Jan 06 00:37:45 pve-82457dcb kernel: [   2178]     0  2178      583      192    36864        0         -1000 watchdog-mux
Jan 06 00:37:45 pve-82457dcb kernel: [   2184]     0  2184    60197     1344    90112        0             0 zed
Jan 06 00:37:45 pve-82457dcb kernel: [   2397]     0  2397     1256      288    53248        0             0 lxc-monitord
Jan 06 00:37:45 pve-82457dcb kernel: [   2417]     0  2417     3853     1440    61440        0         -1000 sshd
Jan 06 00:37:45 pve-82457dcb kernel: [   2427]     0  2427     1468      384    45056        0             0 agetty
Jan 06 00:37:45 pve-82457dcb kernel: [   2440]   100  2440     4715      586    57344        0             0 chronyd
Jan 06 00:37:45 pve-82457dcb kernel: [   2447]   100  2447     2633      288    57344        0             0 chronyd
Jan 06 00:37:45 pve-82457dcb kernel: [   2485]     0  2485   145008     1762   147456        0             0 rrdcached
Jan 06 00:37:45 pve-82457dcb kernel: [   2505]     0  2505   197879    19593   483328        0             0 pmxcfs
Jan 06 00:37:45 pve-82457dcb kernel: [   2591]     0  2591    10664      869    73728        0             0 master
Jan 06 00:37:45 pve-82457dcb kernel: [   2593]   104  2593    10810     1248    69632        0             0 qmgr
Jan 06 00:37:45 pve-82457dcb kernel: [   2600] 64045  2600   168544   102850  1081344        0             0 ceph-mon
Jan 06 00:37:45 pve-82457dcb kernel: [   2606]     0  2606   140712    42133   405504        0             0 corosync
Jan 06 00:37:45 pve-82457dcb kernel: [   2607]     0  2607     1652      288    49152        0             0 cron
Jan 06 00:37:45 pve-82457dcb kernel: [   2742]     0  2742    39341    25363   307200        0             0 pve-firewall
Jan 06 00:37:45 pve-82457dcb kernel: [   2746]     0  2746      615      192    45056        0             0 bpfilter_umh
Jan 06 00:37:45 pve-82457dcb kernel: [   2748]     0  2748    39326    25146   331776        0             0 pvestatd
Jan 06 00:37:45 pve-82457dcb kernel: [   2857]     0  2857    58317    35241   417792        0             0 pvedaemon
Jan 06 00:37:45 pve-82457dcb kernel: [   2873]     0  2873    54825    28585   376832        0             0 pve-ha-crm
Jan 06 00:37:45 pve-82457dcb kernel: [   3118]    33  3118    58650    35040   450560        0             0 pveproxy
Jan 06 00:37:45 pve-82457dcb kernel: [   3124]    33  3124    20199    13824   204800        0             0 spiceproxy
Jan 06 00:37:45 pve-82457dcb kernel: [   3126]     0  3126    54701    28066   372736        0             0 pve-ha-lrm
Jan 06 00:37:45 pve-82457dcb kernel: [   3390]     0  3390  2509401  2087264 18620416        0             0 kvm
Jan 06 00:37:45 pve-82457dcb kernel: [   3917]     0  3917  2420105  2116102 18509824        0             0 kvm
Jan 06 00:37:45 pve-82457dcb kernel: [   4180]     0  4180    53629    29490   360448        0             0 pvescheduler
Jan 06 00:37:45 pve-82457dcb kernel: [   5319]     0  5319  2442444  1310937 11812864        0             0 kvm
Jan 06 00:37:45 pve-82457dcb kernel: [  24398]     0 24398  2512348  1272266 11534336        0             0 kvm
Jan 06 00:37:45 pve-82457dcb kernel: [3075555]     0 3075555  4698362  4202402 35262464        0             0 kvm
Jan 06 00:37:45 pve-82457dcb kernel: [3405993] 64045 3405993   134340    77280   864256        0             0 ceph-mgr
Jan 06 00:37:45 pve-82457dcb kernel: [ 339170]     0 339170     8272     2592    90112        0          -250 systemd-journal
Jan 06 00:37:45 pve-82457dcb kernel: [ 339332]     0 339332     4243      768    77824        0             0 systemd-logind
Jan 06 00:37:45 pve-82457dcb kernel: [ 340166] 64045 340166    45630     7104   204800        0             0 ceph-mds
Jan 06 00:37:45 pve-82457dcb kernel: [ 340460] 64045 340460  1176299   891278  8351744        0             0 ceph-osd
Jan 06 00:37:45 pve-82457dcb kernel: [ 342406]     0 342406  9396812  8424410 69681152        0             0 kvm
Jan 06 00:37:45 pve-82457dcb kernel: [ 354786]     0 354786   725979   474143  5169152        0             0 kvm
Jan 06 00:37:45 pve-82457dcb kernel: [1385005]     0 1385005    60455    35242   430080        0             0 pvedaemon worke
Jan 06 00:37:45 pve-82457dcb kernel: [1411209]     0 1411209    60455    35146   430080        0             0 pvedaemon worke
Jan 06 00:37:45 pve-82457dcb kernel: [1428172]     0 1428172    60450    35146   430080        0             0 pvedaemon worke
Jan 06 00:37:45 pve-82457dcb kernel: [1456454]    33 1456454    20259    13711   176128        0             0 spiceproxy work
Jan 06 00:37:45 pve-82457dcb kernel: [1456457]     0 1456457    19796     1632    53248        0             0 pvefw-logger
Jan 06 00:37:45 pve-82457dcb kernel: [1456462]    33 1456462    60664    35955   430080        0             0 pveproxy worker
Jan 06 00:37:45 pve-82457dcb kernel: [1456463]    33 1456463    60665    35955   430080        0             0 pveproxy worker
Jan 06 00:37:45 pve-82457dcb kernel: [1456464]    33 1456464    60664    35571   430080        0             0 pveproxy worker
Jan 06 00:37:45 pve-82457dcb kernel: [1479734]     0 1479734    57956    30289   401408        0             0 task UPID:pve-8
Jan 06 00:37:45 pve-82457dcb kernel: [1483989]   104 1483989    10764      576    77824        0             0 pickup
Jan 06 00:37:45 pve-82457dcb kernel: [1484148]     0 1484148     1366      288    53248        0             0 sleep
Jan 06 00:37:45 pve-82457dcb kernel: [1484324]     0 1484324   801672     2400   372736        0             0 proxmox-backup-
Jan 06 00:37:45 pve-82457dcb kernel: [1484498]     0 1484498       98        0    36864        0             0 ebtables-restor
Jan 06 00:37:45 pve-82457dcb kernel: oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=corosync.service,mems_allowed=0,global_oom,task_memcg=/qemu.slice/421.scope,task=kvm,pid=342406,uid=0
Jan 06 00:37:45 pve-82457dcb kernel: Out of memory: Killed process 342406 (kvm) total-vm:37587248kB, anon-rss:33683500kB, file-rss:9532kB, shmem-rss:0kB, UID:0 pgtables:68044kB oom_score_adj:0
Jan 06 00:37:46 pve-82457dcb systemd[1]: 421.scope: A process of this unit has been killed by the OOM killer.
Jan 06 00:37:46 pve-82457dcb systemd[1]: 421.scope: Failed with result 'oom-kill'.
Jan 06 00:37:47 pve-82457dcb systemd[1]: 421.scope: Consumed 5h 47min 12.998s CPU time.
Jan 06 00:37:48 pve-82457dcb zed[1484529]: eid=408 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=131072 offset=816275165184 priority=0 err=0 flags=0x40080480 delay=34857ms
Jan 06 00:37:48 pve-82457dcb zed[1484531]: eid=407 class=delay pool='nvme' vdev=nvme-KCD6XLUL960G_Z2S0A004T5M8-part1 size=131072 offset=816274866176 priority=0 err=0 flags=0x40080480 delay=40355ms
Jan 06 00:37:48 pve-82457dcb pve-firewall[2742]: firewall update time (60.195 seconds)
Jan 06 00:37:48 pve-82457dcb ceph-mon[2600]: 2024-01-06T00:37:48.384+0100 7fdac78496c0 -1 mon.pve-82457dcb@1(peon) e3 get_health_metrics reporting 37 slow ops, oldest is mgrbeacon mgr.pve-82457dcb(25654e9e-ecaa-4bc1-9ca1-0d3f883dc3f4,1494847, , 0)
Jan 06 00:37:48 pve-82457dcb ceph-osd[340460]: 2024-01-06T00:37:48.392+0100 7f73b2c276c0 -1 osd.0 1552 set_numa_affinity unable to identify public interface '' numa node: (2) No such file or directory
Jan 06 00:37:48 pve-82457dcb pvestatd[2748]: status update time (139.580 seconds)
Jan 06 00:37:48 pve-82457dcb kernel:  zd208: p1 p14 p15
Jan 06 00:37:50 pve-82457dcb kernel: oom_reaper: reaped process 342406 (kvm), now anon-rss:0kB, file-rss:5836kB, shmem-rss:0kB
Jan 06 00:37:53 pve-82457dcb pvescheduler[1479734]: VM 421 qmp command failed - VM 421 qmp command 'query-backup' failed - client closed connection
Jan 06 00:37:53 pve-82457dcb pvescheduler[1479734]: VM 421 qmp command failed - VM 421 not running
Jan 06 00:37:53 pve-82457dcb pvescheduler[1479734]: VM 421 qmp command failed - VM 421 not running
Jan 06 00:37:53 pve-82457dcb kernel: vmbr0: port 4(tap421i0) entered disabled state
Jan 06 00:37:53 pve-82457dcb pvescheduler[1479734]: ERROR: Backup of VM 421 failed - VM 421 not running
Jan 06 00:37:53 pve-82457dcb pvescheduler[1479734]: INFO: Starting Backup of VM 630 (qemu)
Jan 06 00:37:53 pve-82457dcb kernel: tap421i0 (unregistering): left allmulticast mode
Jan 06 00:37:53 pve-82457dcb kernel: vmbr0: port 4(tap421i0) entered disabled state
Jan 06 00:37:54 pve-82457dcb qmeventd[1484791]: Starting cleanup for 421
Jan 06 00:37:54 pve-82457dcb qmeventd[1484791]: Finished cleanup for 421
Jan 06 00:38:58 pve-82457dcb pvescheduler[1479734]: INFO: Finished Backup of VM 630 (00:01:05)
Jan 06 00:38:58 pve-82457dcb pvescheduler[1479734]: INFO: Starting Backup of VM 640 (qemu)
Jan 06 00:39:01 pve-82457dcb pvescheduler[1479734]: VM 640 qmp command failed - VM 640 qmp command 'guest-ping' failed - got timeout
Jan 06 00:39:24 pve-82457dcb pvescheduler[1479734]: INFO: Finished Backup of VM 640 (00:00:26)
Jan 06 00:39:24 pve-82457dcb pvescheduler[1479734]: INFO: Backup job finished with errors
Jan 06 00:39:24 pve-82457dcb pvescheduler[1479734]: job errors

 

[feisal]

Hi,

Did you ever solve the problem?

 

[flotho]

Hi @vch @feisal
Do you have any more information ?

Regards

 

[feisal]

I stopped having the problem after I migrated the VMs to a new server.

 

[flotho]

could you add SOLVED prefix to your issue