5.13.19-2-pve kernel bug, maybe, pve-manager/7.1-8/5b267f33

K

kristian.kirilov

Well-Known Member
Nov 17, 2016
64
2
48
39
Not sure how to start this topic, but I noticed strange behavior on one of my systems, here is the kernel output:

Code: 
[  242.670592] INFO: task pvescheduler:2292 blocked for more than 120 seconds.
[  242.670600]       Tainted: P           O      5.13.19-2-pve #1
[  242.670602] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  242.670604] task:pvescheduler    state:D stack:    0 pid: 2292 ppid:  2290 flags:0x00000004
[  242.670608] Call Trace:
[  242.670612]  __schedule+0x2fa/0x910
[  242.670618]  schedule+0x4f/0xc0
[  242.670622]  rwsem_down_write_slowpath+0x212/0x590
[  242.670626]  down_write+0x43/0x50
[  242.670629]  filename_create+0x7e/0x160
[  242.670634]  do_mkdirat+0x58/0x150
[  242.670637]  __x64_sys_mkdir+0x1b/0x20
[  242.670640]  do_syscall_64+0x61/0xb0
[  242.670644]  ? syscall_exit_to_user_mode+0x27/0x50
[  242.670646]  ? do_syscall_64+0x6e/0xb0
[  242.670649]  ? __x64_sys_alarm+0x4a/0x90
[  242.670654]  ? exit_to_user_mode_prepare+0x37/0x1b0
[  242.670658]  ? syscall_exit_to_user_mode+0x27/0x50
[  242.670661]  ? do_syscall_64+0x6e/0xb0
[  242.670663]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[  242.670667] RIP: 0033:0x7fecb3ac6b07
[  242.670669] RSP: 002b:00007ffee4775b38 EFLAGS: 00000246 ORIG_RAX: 0000000000000053
[  242.670673] RAX: ffffffffffffffda RBX: 00005609a93de2a0 RCX: 00007fecb3ac6b07
[  242.670675] RDX: 0000000000000027 RSI: 00000000000001ff RDI: 00005609aec86500
[  242.670677] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000001f28
[  242.670679] R10: 00007ffee4775b00 R11: 0000000000000246 R12: 00005609aec86500
[  242.670681] R13: 00005609a93e3ca8 R14: 00005609aad08688 R15: 00000000000001ff
[  242.670686] INFO: task pvesr:2734 blocked for more than 120 seconds.
[  242.670689]       Tainted: P           O      5.13.19-2-pve #1
[  242.670690] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  242.670692] task:pvesr           state:D stack:    0 pid: 2734 ppid:  2732 flags:0x00000000
[  242.670695] Call Trace:
[  242.670697]  __schedule+0x2fa/0x910
[  242.670700]  schedule+0x4f/0xc0
[  242.670703]  rwsem_down_write_slowpath+0x212/0x590
[  242.670706]  down_write+0x43/0x50
[  242.670709]  filename_create+0x7e/0x160
[  242.670712]  do_mkdirat+0x58/0x150
[  242.670716]  __x64_sys_mkdir+0x1b/0x20
[  242.670719]  do_syscall_64+0x61/0xb0
[  242.670721]  ? syscall_exit_to_user_mode+0x27/0x50
[  242.670724]  ? __x64_sys_read+0x1a/0x20
[  242.670727]  ? do_syscall_64+0x6e/0xb0
[  242.670730]  ? irqentry_exit_to_user_mode+0x9/0x20
[  242.670732]  ? irqentry_exit+0x19/0x30
[  242.670734]  ? exc_page_fault+0x8f/0x170
[  242.670736]  ? asm_exc_page_fault+0x8/0x30
[  242.670739]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[  242.670741] RIP: 0033:0x7fcdda383b07
[  242.670743] RSP: 002b:00007ffed62878f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000053
[  242.670746] RAX: ffffffffffffffda RBX: 00005647dee7a2a0 RCX: 00007fcdda383b07
[  242.670747] RDX: 00005647de8a9ae5 RSI: 00000000000001ff RDI: 00005647e2faa490
[  242.670749] RBP: 0000000000000000 R08: 00005647e2faa4f8 R09: 0000000000000000
[  242.670751] R10: 000000000000000f R11: 0000000000000246 R12: 00005647e2faa490
[  242.670753] R13: 00005647e02431f8 R14: 00005647e321e798 R15: 00000000000001ff
root@proxmox-node-1.home.lan:~#

I also see that, the corosync daemon constantly trying to sent cluster beacons to the other one.

Code: 
Dec 17 16:28:44 proxmox-node-1.home.lan corosync[2077]:   [KNET  ] link: host: 2 link: 0 is down
Dec 17 16:28:44 proxmox-node-1.home.lan corosync[2077]:   [KNET  ] host: host: 2 (passive) best link: 0 (pri: 1)
Dec 17 16:28:44 proxmox-node-1.home.lan corosync[2077]:   [KNET  ] host: host: 2 has no active links
Dec 17 16:28:45 proxmox-node-1.home.lan corosync[2077]:   [KNET  ] rx: host: 2 link: 0 is up
Dec 17 16:28:45 proxmox-node-1.home.lan corosync[2077]:   [KNET  ] host: host: 2 (passive) best link: 0 (pri: 1)
 
kristian.kirilov said:
Not sure how to start this topic, but I noticed strange behavior on one of my systems, here is the kernel output:

Code: 
[  242.670592] INFO: task pvescheduler:2292 blocked for more than 120 seconds.
[  242.670600]       Tainted: P           O      5.13.19-2-pve #1
[  242.670602] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  242.670604] task:pvescheduler    state:D stack:    0 pid: 2292 ppid:  2290 flags:0x00000004
[  242.670608] Call Trace:
[  242.670612]  __schedule+0x2fa/0x910
[  242.670618]  schedule+0x4f/0xc0
[  242.670622]  rwsem_down_write_slowpath+0x212/0x590
[  242.670626]  down_write+0x43/0x50
[  242.670629]  filename_create+0x7e/0x160
[  242.670634]  do_mkdirat+0x58/0x150
[  242.670637]  __x64_sys_mkdir+0x1b/0x20
[  242.670640]  do_syscall_64+0x61/0xb0
[  242.670644]  ? syscall_exit_to_user_mode+0x27/0x50
[  242.670646]  ? do_syscall_64+0x6e/0xb0
[  242.670649]  ? __x64_sys_alarm+0x4a/0x90
[  242.670654]  ? exit_to_user_mode_prepare+0x37/0x1b0
[  242.670658]  ? syscall_exit_to_user_mode+0x27/0x50
[  242.670661]  ? do_syscall_64+0x6e/0xb0
[  242.670663]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[  242.670667] RIP: 0033:0x7fecb3ac6b07
[  242.670669] RSP: 002b:00007ffee4775b38 EFLAGS: 00000246 ORIG_RAX: 0000000000000053
[  242.670673] RAX: ffffffffffffffda RBX: 00005609a93de2a0 RCX: 00007fecb3ac6b07
[  242.670675] RDX: 0000000000000027 RSI: 00000000000001ff RDI: 00005609aec86500
[  242.670677] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000001f28
[  242.670679] R10: 00007ffee4775b00 R11: 0000000000000246 R12: 00005609aec86500
[  242.670681] R13: 00005609a93e3ca8 R14: 00005609aad08688 R15: 00000000000001ff
[  242.670686] INFO: task pvesr:2734 blocked for more than 120 seconds.
[  242.670689]       Tainted: P           O      5.13.19-2-pve #1
[  242.670690] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  242.670692] task:pvesr           state:D stack:    0 pid: 2734 ppid:  2732 flags:0x00000000
[  242.670695] Call Trace:
[  242.670697]  __schedule+0x2fa/0x910
[  242.670700]  schedule+0x4f/0xc0
[  242.670703]  rwsem_down_write_slowpath+0x212/0x590
[  242.670706]  down_write+0x43/0x50
[  242.670709]  filename_create+0x7e/0x160
[  242.670712]  do_mkdirat+0x58/0x150
[  242.670716]  __x64_sys_mkdir+0x1b/0x20
[  242.670719]  do_syscall_64+0x61/0xb0
[  242.670721]  ? syscall_exit_to_user_mode+0x27/0x50
[  242.670724]  ? __x64_sys_read+0x1a/0x20
[  242.670727]  ? do_syscall_64+0x6e/0xb0
[  242.670730]  ? irqentry_exit_to_user_mode+0x9/0x20
[  242.670732]  ? irqentry_exit+0x19/0x30
[  242.670734]  ? exc_page_fault+0x8f/0x170
[  242.670736]  ? asm_exc_page_fault+0x8/0x30
[  242.670739]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[  242.670741] RIP: 0033:0x7fcdda383b07
[  242.670743] RSP: 002b:00007ffed62878f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000053
[  242.670746] RAX: ffffffffffffffda RBX: 00005647dee7a2a0 RCX: 00007fcdda383b07
[  242.670747] RDX: 00005647de8a9ae5 RSI: 00000000000001ff RDI: 00005647e2faa490
[  242.670749] RBP: 0000000000000000 R08: 00005647e2faa4f8 R09: 0000000000000000
[  242.670751] R10: 000000000000000f R11: 0000000000000246 R12: 00005647e2faa490
[  242.670753] R13: 00005647e02431f8 R14: 00005647e321e798 R15: 00000000000001ff
root@proxmox-node-1.home.lan:~#

I also see that, the corosync daemon constantly trying to sent cluster beacons to the other one.

Code: 
Dec 17 16:28:44 proxmox-node-1.home.lan corosync[2077]:   [KNET  ] link: host: 2 link: 0 is down
Dec 17 16:28:44 proxmox-node-1.home.lan corosync[2077]:   [KNET  ] host: host: 2 (passive) best link: 0 (pri: 1)
Dec 17 16:28:44 proxmox-node-1.home.lan corosync[2077]:   [KNET  ] host: host: 2 has no active links
Dec 17 16:28:45 proxmox-node-1.home.lan corosync[2077]:   [KNET  ] rx: host: 2 link: 0 is up
Dec 17 16:28:45 proxmox-node-1.home.lan corosync[2077]:   [KNET  ] host: host: 2 (passive) best link: 0 (pri: 1)
Click to expand...

On this node I have two network cards, and also noticed that the on-board network card is linked on 10MB speed, instead of 1G
 
So yeah, please ignore this tread till I manage to fix the network connection to 1GB, then we can check if the problem persist.
 
I'm having same issue.
Some time after rebooting the whole cluster (it's a real pain) everything works properly.
After a while web gui stops working, i'm uncertain of what triggers the state.
Luckily all vms continue working, but i can not login to web gui with correct password to any node and can't really operate the cluster.

qm list hangs
corosync-cfgtool -s shows all nodes on both links online
pvecm status shows all nodes online and cluster is quorate
pvesm status shows all storages as active
links are 1G

Here is what i'm having in dmesg
[ 5439.318622] INFO: task pvescheduler:225097 blocked for more than 120 seconds. [ 5439.318645] Tainted: P O 5.13.19-2-pve #1 [ 5439.318660] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 5439.318676] task:pvescheduler state:D stack: 0 pid:225097 ppid: 1537 flags:0x00000004 [ 5439.318679] Call Trace: [ 5439.318683] __schedule+0x2fa/0x910 [ 5439.318689] schedule+0x4f/0xc0 [ 5439.318691] rwsem_down_write_slowpath+0x212/0x590 [ 5439.318694] down_write+0x43/0x50 [ 5439.318696] filename_create+0x7e/0x160 [ 5439.318700] do_mkdirat+0x58/0x150 [ 5439.318703] __x64_sys_mkdir+0x1b/0x20 [ 5439.318705] do_syscall_64+0x61/0xb0 [ 5439.318708] ? __x64_sys_rt_sigaction+0x7f/0x100 [ 5439.318711] ? exit_to_user_mode_prepare+0x37/0x1b0 [ 5439.318715] ? syscall_exit_to_user_mode+0x27/0x50 [ 5439.318716] ? do_syscall_64+0x6e/0xb0 [ 5439.318718] entry_SYSCALL_64_after_hwframe+0x44/0xae [ 5439.318720] RIP: 0033:0x7f0b87605b07 [ 5439.318722] RSP: 002b:00007ffcf37252d8 EFLAGS: 00000246 ORIG_RAX: 0000000000000053 [ 5439.318724] RAX: ffffffffffffffda RBX: 000055980a8932a0 RCX: 00007f0b87605b07 [ 5439.318725] RDX: 0000000000000020 RSI: 00000000000001ff RDI: 000055981013e210 [ 5439.318726] RBP: 0000000000000000 R08: 0000000000000001 R09: 0000559808fa05e0 [ 5439.318727] R10: 0000000000000000 R11: 0000000000000246 R12: 000055981013e210 [ 5439.318728] R13: 000055980a898ca8 R14: 000055980c1bd9b8 R15: 00000000000001ff [ 7733.072450] perf: interrupt took too long (2508 > 2500), lowering kernel.perf_event_max_sample_rate to 79500
Versions are
root@micronode5:/etc/pve# pveversion pve-manager/7.1-8/5b267f33 (running kernel: 5.13.19-2-pve) root@micronode5:/etc/pve# uname -a Linux micronode5 5.13.19-2-pve #1 SMP PVE 5.13.19-4 (Mon, 29 Nov 2021 12:10:09 +0100) x86_64 GNU/Linux
 
After some research i've managed to set it working again but not shure if effect is going to be persistant.
And yes i know it's rude, but hard times calls for drastic measures.
I have ansible inventory file describing my cluster so i've done ad-hoc:
ansible mycluster -m shell -a "killall -9 corosync&&systemctl stop pve-cluster&&systemctl stop pvedaemon&&systemctl stop pveproxy&&systemctl stop pvestatd&& apt -y autoremove && apt install --reinstall pve-manager" -u stepan --become
folowerd by
ansible mycluster -m shell -a "killall -9 corosync&&systemctl restart pve-cluster&&systemctl restart pvedaemon&&systemctl restart pveproxy&&systemctl restart pvestatd" -u stepan --become

apt -y autoremove is there because there was some packages to autoremove and i was narrowing in df (but not exausted disk space - so it is not the cause)
 
You must log in or register to reply here.
Top Bottom