* NFS client deadlock while doing nested virtualization tests on my systems
@ 2021-10-05 14:08 Maxim Levitsky
0 siblings, 0 replies; only message in thread
From: Maxim Levitsky @ 2021-10-05 14:08 UTC (permalink / raw)
To: J. Bruce Fields; +Cc: Paolo Bonzini, linux-nfs, qemu-devel, kvm@vger.kernel.org
[-- Attachment #1: Type: text/plain, Size: 10076 bytes --]
Lately I was trying to narrow down what now looks like an NFSv4 client bug.
I believe that I have enough information to pass it down to people who are more knowledgeable in this area.
My setup:
- My main work computer (Zen2 AMD machine), has an NFS exports share with all the files that all my other lab computers and VMs use.
- Nested virtualization is used to reproduce the issue, but I believe that it only contributes to
unusual timings that make this deadlock more reproducible.
- First level of virtualization (L1) (that is regular VM running on KVM on bare metal) was my test fedora 32 VM with 5.14
kernel, built from exactly the same source as the host kernel (but with different .config).
L1 VM uses a regular qcow2 file located on the main computer's filesystem and it running on it.
L1 VM uses kernel's NFSv4 client to access L0’s shared directory where all the VM's qcow2 files reside
(including itself, but it pretends it doesn't know this to avoid escaping to the real world ;-) )
To see if there is some kind of deadlock if L2 still somehow acceses the L1 qcow2 file, I moved the L1's qcow2
files out of the shared folder, so now L1 only mounts a single folder over NFS which has the test VM and nothing else
That didn't help either.
- Second level of virtualization (L2) (a nested VM running in L1 VM) was a Windows 10 VM (build 1909, as I didn't bother updating this test VM)
which uses a pair of qcow2 files (base and snapshot on top of it), both located on that NFS shared folder.
L2 VM used to run another level of virtualization with Hyper-v, but I was able to reproduce the issue with HyperV disabled.
- For all testing, a custom compiled kernel 5.14.0 was used (both on host (L0) and the L1 guest)
(with patches from kvm tree and some of my patches which I believe don’t contribute to the issue).
I also tested older kernels in the L1 guest, and I also tested 5.15-rc3 on both L0 and L1 and had the same result.
- Qemu 5.2.0 was used for all userspace parts of KVM in both L0 and L1
(I usually use latest master branch of the qemu git, but I suspected qemu, so I used relatively old version which I used for a
long time before)
- Issue was reproduced with vhost disabled in both L0 and L1. virtio-net was used for networking on top of tap interface.
Issue was reproduced without ‘-overcommit cpu_pm=on’ (I tend to use this qemu option too often)
- aio=native was used for the IO, and cache=none for the L2 VM:
-device virtio-scsi,id=scsi-ctrl,bus=rport.0
-drive if=none,id=os_image,file=./disk_s1.qcow2,aio=native,discard=unmap,cache=none
-device scsi-hd,drive=os_image,bus=scsi-ctrl.0,bootindex=1
however I also tested L2 with discard=ignore,aio=threads, and the guest eventually crashed as well in the same way.
- I also tested this with e1000e in the L1, and the test failed indicating that this isn't related to virtio
- It seems that the test survives if the windows VM is started on a different system (also Zen2 machine), and
its qcow2 file still streamed via NFS. Network speed though will be vastly different since I use 1GB network.
- I tested NFSv3 as well. The NFS client also hangs, but when it recovers the VM doesn't crash.
On the other hand, when I force stop L1, the NFS server deadlocks when attempting to restart it, and once
even oopsed the host.
I attached the backtraces for this.
What is happening:
The nested VM (L2) boots, and after a while hangs on IO. L1’s NFS client deadlocks, and causes the L1 itself to mostly hang “nfs style”.
After a few minutes it recovers by reconnecting, gives back IO errors to the nested guest which bluescreens and crashes.
Qemu is usually blocked on NFS io, but not always, in one case it was just hang, probably blocking on GUI or something which
was blocked on NFS.
The dmesg in L1 usually shows that we have qemu blocked on NFS twice
One is the qemu main thread doing ‘io_submit’ on the file which was opened with O_DIRECT
[ 1844.377677] task:qemu-system-x86 state:D stack: 0 pid: 4517 ppid: 4511 flags:0x00000000
[ 1844.379164] Call Trace:
[ 1844.379613] __schedule+0x2dd/0x1440
[ 1844.380245] schedule+0x4e/0xb0
[ 1844.380834] rwsem_down_read_slowpath+0x2e4/0x330
[ 1844.381662] down_read+0x43/0x90
[ 1844.382277] nfs_start_io_direct+0x1e/0x70 [nfs]
[ 1844.383181] nfs_file_direct_write+0x1f7/0x340 [nfs]
[ 1844.384113] nfs_file_write+0x26f/0x320 [nfs]
[ 1844.384907] aio_write+0xfc/0x1f0
[ 1844.385511] ? __pollwait+0xd0/0xd0
[ 1844.386187] ? __fget_files+0x5f/0x90
[ 1844.386859] ? __fget_light+0x32/0x80
[ 1844.387520] io_submit_one+0x1f6/0x790
[ 1844.388255] __x64_sys_io_submit+0x84/0x180
[ 1844.389049] ? fput+0x13/0x20
[ 1844.389603] ? ksys_read+0xce/0xe0
[ 1844.390225] do_syscall_64+0x36/0xb0
[ 1844.390870] entry_SYSCALL_64_after_hwframe+0x44/0xae
Another is one of the qemu thread pool workers which is still used for fallocate syscall which is running this syscall.
[ 1844.403632] task:worker state:D stack: 0 pid: 4555 ppid: 4511 flags:0x00000000
[ 1844.405108] Call Trace:
[ 1844.405587] __schedule+0x2dd/0x1440
[ 1844.406215] ? hrtimer_cancel+0x15/0x30
[ 1844.406904] ? futex_wait+0x223/0x250
[ 1844.407601] schedule+0x4e/0xb0
[ 1844.408194] inode_dio_wait+0xd1/0x100
[ 1844.408871] ? var_wake_function+0x30/0x30
[ 1844.409617] nfs_sync_inode+0x13/0x30 [nfs]
[ 1844.410426] nfs42_proc_fallocate.isra.0+0x91/0x100 [nfsv4]
[ 1844.411504] nfs42_proc_allocate+0x8c/0xe0 [nfsv4]
[ 1844.412426] nfs42_fallocate+0x59/0x80 [nfsv4]
[ 1844.413222] vfs_fallocate+0x152/0x2f0
[ 1844.413926] __x64_sys_fallocate+0x44/0x70
[ 1844.414635] do_syscall_64+0x36/0xb0
While this is happening NFS client in L1 is hanging it, blocking all IO on the NFS mount.
The NFS server continues to work normally as I am able to do IO from my other test systems to the server,
e.g start another VM on a test system which also uses NFS to stream the VM’s qcow2 file.
The bug is not 100% reproducible and relatively random but happens often in my current setting of VMs that always start from the same snapshot.
However usually leaving the VM for hour or two, makes this bug reproduce.
I know that a few months ago it didn't happen, or at least I didn't notice it despite a lot of testing with the same VMs.
I still don't know what might have changed. It is possible that I didn't use NFS back then.
Wireshark captures I did seems to show that all requests submitted to the NFS server are replied by it, so it looks like it is not the reason for the hang,
but it is possible that some of the requests didn't reach the server in the first place.
I attached such trace (I have full trace if needed). The last packet before the hang is frame 81322.
I attach more detailed dmesg captures in case it helps.
I also captured kernel backtrace of all qemu threads via /proc/pid/task/tid/stack:
202206 : qemu-system-x86
[<0>] nfs_start_io_direct+0x1e/0x70 [nfs]
[<0>] nfs_file_direct_write+0x1f7/0x340 [nfs]
[<0>] nfs_file_write+0x26f/0x320 [nfs]
[<0>] aio_write+0xfc/0x1f0
[<0>] io_submit_one+0x1f6/0x790
[<0>] __x64_sys_io_submit+0x84/0x180
[<0>] do_syscall_64+0x36/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xae
=================
202219 : qemu-system-x86
[<0>] futex_wait_queue_me+0xa4/0x100
[<0>] futex_wait+0x105/0x250
[<0>] do_futex+0xea/0xa30
[<0>] __x64_sys_futex+0x74/0x1b0
[<0>] do_syscall_64+0x36/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xae
=================
202220 : gmain
[<0>] do_sys_poll+0x3f9/0x610
[<0>] __x64_sys_poll+0x3b/0x140
[<0>] do_syscall_64+0x36/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xae
=================
202221 : threaded-ml
[<0>] do_sys_poll+0x3f9/0x610
[<0>] __x64_sys_poll+0x3b/0x140
[<0>] do_syscall_64+0x36/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xae
=================
202224 : IO mon_iothread
[<0>] do_sys_poll+0x3f9/0x610
[<0>] __x64_sys_poll+0x3b/0x140
[<0>] do_syscall_64+0x36/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xae
=================
202225 : CPU 0/KVM
[<0>] kvm_vcpu_block+0x5c/0x3a0 [kvm]
[<0>] kvm_arch_vcpu_ioctl_run+0x651/0x1710 [kvm]
[<0>] kvm_vcpu_ioctl+0x284/0x6c0 [kvm]
[<0>] __x64_sys_ioctl+0x8e/0xc0
[<0>] do_syscall_64+0x36/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xae
=================
202226 : CPU 1/KVM
[<0>] kvm_vcpu_block+0x5c/0x3a0 [kvm]
[<0>] kvm_arch_vcpu_ioctl_run+0x651/0x1710 [kvm]
[<0>] kvm_vcpu_ioctl+0x284/0x6c0 [kvm]
[<0>] __x64_sys_ioctl+0x8e/0xc0
[<0>] do_syscall_64+0x36/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xae
=================
202227 : CPU 2/KVM
[<0>] futex_wait_queue_me+0xa4/0x100
[<0>] futex_wait+0x105/0x250
[<0>] do_futex+0xea/0xa30
[<0>] __x64_sys_futex+0x74/0x1b0
[<0>] do_syscall_64+0x36/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xae
=================
202228 : CPU 3/KVM
[<0>] kvm_vcpu_block+0x5c/0x3a0 [kvm]
[<0>] kvm_arch_vcpu_ioctl_run+0x651/0x1710 [kvm]
[<0>] kvm_vcpu_ioctl+0x284/0x6c0 [kvm]
[<0>] __x64_sys_ioctl+0x8e/0xc0
[<0>] do_syscall_64+0x36/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xae
=================
204640 : worker
[<0>] inode_dio_wait+0xd1/0x100
[<0>] nfs_sync_inode+0x13/0x30 [nfs]
[<0>] nfs42_proc_fallocate.isra.0+0x91/0x100 [nfsv4]
[<0>] nfs42_proc_allocate+0x8c/0xe0 [nfsv4]
[<0>] nfs42_fallocate+0x59/0x80 [nfsv4]
[<0>] vfs_fallocate+0x152/0x2f0
[<0>] __x64_sys_fallocate+0x44/0x70
[<0>] do_syscall_64+0x36/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xae
=================
As you see, all nested vCPUs are blocked in L1 kernel, so when the hang happens, a hung vCPU should
not be a problem.
It is possible though that L0 is not letting L1's vCPUs run for some reason and that is what causing NFS client to stall.
Once I was able to capture the above backtrace where qemu would not be stuck on NFS but still
hung, and NFS client still hanging L1. In this case it is likely that qemu got stuck on something
else (gui?).
Any help on debugging this is welcome. I can provide more info if needed as well.
Best regards,
Maxim Levitsky
[-- Attachment #2: backtrace.txt --]
[-- Type: text/plain, Size: 17564 bytes --]
[ 521.681136] SVM: kvm [2547]: vcpu0, guest rIP: 0xfffff8e76decec1a unimplemented wrmsr: 0xc0010115 data 0x0
[ 523.811541] SVM: kvm [2547]: vcpu1, guest rIP: 0xfffff8e76decec1a unimplemented wrmsr: 0xc0010115 data 0x0
[ 523.818659] SVM: kvm [2547]: vcpu2, guest rIP: 0xfffff8e76decec1a unimplemented wrmsr: 0xc0010115 data 0x0
[ 523.823000] SVM: kvm [2547]: vcpu3, guest rIP: 0xfffff8e76decec1a unimplemented wrmsr: 0xc0010115 data 0x0
[ 595.505792] snd_hda_intel 0000:00:1f.4: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
[ 738.405045] INFO: task qemu-system-x86:2547 blocked for more than 122 seconds.
[ 738.406111] Tainted: G O 5.14.0.stable #87
[ 738.407003] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 738.408120] task:qemu-system-x86 state:D stack: 0 pid: 2547 ppid: 2539 flags:0x00000000
[ 738.409298] Call Trace:
[ 738.409658] __schedule+0x2df/0x1440
[ 738.410186] schedule+0x4e/0xb0
[ 738.410626] rwsem_down_read_slowpath+0x2e4/0x330
[ 738.411317] down_read+0x43/0x90
[ 738.411782] nfs_start_io_direct+0x1e/0x70 [nfs]
[ 738.412448] nfs_file_direct_write+0x1f7/0x340 [nfs]
[ 738.413183] nfs_file_write+0x269/0x310 [nfs]
[ 738.413833] aio_write+0xfc/0x1f0
[ 738.414307] ? __pollwait+0xd0/0xd0
[ 738.414813] ? __fget_files+0x5f/0x90
[ 738.415334] ? __fget_light+0x32/0x80
[ 738.415861] io_submit_one+0x1f6/0x790
[ 738.416399] __x64_sys_io_submit+0x84/0x180
[ 738.417031] ? fput+0x13/0x20
[ 738.417445] ? ksys_read+0xce/0xe0
[ 738.417941] do_syscall_64+0x36/0xb0
[ 738.418452] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 738.419215] RIP: 0033:0x7fb605c9e37d
[ 738.419714] RSP: 002b:00007ffd10142c18 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[ 738.420769] RAX: ffffffffffffffda RBX: 00007fb601ebc808 RCX: 00007fb605c9e37d
[ 738.421777] RDX: 00007ffd10142c90 RSI: 0000000000000001 RDI: 00007fb600d07000
[ 738.422769] RBP: 00007fb600d07000 R08: 00007ffd10144a30 R09: 000000000319cfe0
[ 738.423828] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
[ 738.424823] R13: 000000000000000b R14: 00007ffd10142c90 R15: 0000000000000000
[ 738.425844] INFO: task worker:2592 blocked for more than 122 seconds.
[ 738.426746] Tainted: G O 5.14.0.stable #87
[ 738.427626] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 738.428691] task:worker state:D stack: 0 pid: 2592 ppid: 2539 flags:0x00000000
[ 738.429821] Call Trace:
[ 738.430185] __schedule+0x2df/0x1440
[ 738.430670] ? futex_wait+0x105/0x250
[ 738.431202] schedule+0x4e/0xb0
[ 738.431629] inode_dio_wait+0xd1/0x100
[ 738.432156] ? var_wake_function+0x30/0x30
[ 738.432710] nfs_sync_inode+0x13/0x30 [nfs]
[ 738.433333] nfs42_proc_fallocate.isra.0+0x91/0x100 [nfsv4]
[ 738.434119] nfs42_proc_deallocate+0x94/0x110 [nfsv4]
[ 738.434834] nfs42_fallocate+0x69/0x80 [nfsv4]
[ 738.435512] vfs_fallocate+0x152/0x2e0
[ 738.436030] __x64_sys_fallocate+0x44/0x70
[ 738.436610] do_syscall_64+0x36/0xb0
[ 738.437102] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 738.437798] RIP: 0033:0x7fb605c9941f
[ 738.438314] RSP: 002b:00007fb43b2cd7e0 EFLAGS: 00000293 ORIG_RAX: 000000000000011d
[ 738.439348] RAX: ffffffffffffffda RBX: 0000000003d59970 RCX: 00007fb605c9941f
[ 738.440332] RDX: 000000001bd50000 RSI: 0000000000000003 RDI: 0000000000000018
[ 738.441319] RBP: 00007fb43b2cd830 R08: 0000000000000000 R09: 00000000ffffffff
[ 738.442271] R10: 0000000000050000 R11: 0000000000000293 R12: 00007ffd10144c2e
[ 738.443231] R13: 00007ffd10144c2f R14: 00007ffd10144cf0 R15: 00007fb43b2cf700
[ 753.700979] nfs: server starship not responding, still trying
[ 753.700992] nfs: server starship not responding, still trying
[ 753.701000] nfs: server starship not responding, still trying
[ 753.884982] nfs: server starship not responding, still trying
[ 753.894976] nfs: server starship not responding, still trying
[ 753.894985] nfs: server starship not responding, still trying
[ 754.852990] nfs: server starship not responding, still trying
[ 754.853000] nfs: server starship not responding, still trying
[ 754.853013] nfs: server starship not responding, still trying
[ 754.853017] nfs: server starship not responding, still trying
[ 759.140996] rpc_check_timeout: 5 callbacks suppressed
[ 759.140999] nfs: server starship not responding, still trying
[ 799.844991] nfs: server starship not responding, still trying
[ 861.284994] INFO: task qemu-system-x86:2547 blocked for more than 245 seconds.
[ 861.286105] Tainted: G O 5.14.0.stable #87
[ 861.286942] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 861.288039] task:qemu-system-x86 state:D stack: 0 pid: 2547 ppid: 2539 flags:0x00000000
[ 861.289209] Call Trace:
[ 861.289580] __schedule+0x2df/0x1440
[ 861.290125] schedule+0x4e/0xb0
[ 861.290565] rwsem_down_read_slowpath+0x2e4/0x330
[ 861.291251] down_read+0x43/0x90
[ 861.291771] nfs_start_io_direct+0x1e/0x70 [nfs]
[ 861.292451] nfs_file_direct_write+0x1f7/0x340 [nfs]
[ 861.293176] nfs_file_write+0x269/0x310 [nfs]
[ 861.293818] aio_write+0xfc/0x1f0
[ 861.294290] ? __pollwait+0xd0/0xd0
[ 861.294790] ? __fget_files+0x5f/0x90
[ 861.295306] ? __fget_light+0x32/0x80
[ 861.295844] io_submit_one+0x1f6/0x790
[ 861.296387] __x64_sys_io_submit+0x84/0x180
[ 861.296991] ? fput+0x13/0x20
[ 861.297405] ? ksys_read+0xce/0xe0
[ 861.297910] do_syscall_64+0x36/0xb0
[ 861.298413] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 861.299134] RIP: 0033:0x7fb605c9e37d
[ 861.299668] RSP: 002b:00007ffd10142c18 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[ 861.300740] RAX: ffffffffffffffda RBX: 00007fb601ebc808 RCX: 00007fb605c9e37d
[ 861.301767] RDX: 00007ffd10142c90 RSI: 0000000000000001 RDI: 00007fb600d07000
[ 861.302754] RBP: 00007fb600d07000 R08: 00007ffd10144a30 R09: 000000000319cfe0
[ 861.303759] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
[ 861.304759] R13: 000000000000000b R14: 00007ffd10142c90 R15: 0000000000000000
[ 861.305779] INFO: task worker:2592 blocked for more than 245 seconds.
[ 861.306684] Tainted: G O 5.14.0.stable #87
[ 861.307512] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 861.308660] task:worker state:D stack: 0 pid: 2592 ppid: 2539 flags:0x00000000
[ 861.309806] Call Trace:
[ 861.310172] __schedule+0x2df/0x1440
[ 861.310657] ? futex_wait+0x105/0x250
[ 861.311176] schedule+0x4e/0xb0
[ 861.311600] inode_dio_wait+0xd1/0x100
[ 861.312152] ? var_wake_function+0x30/0x30
[ 861.312704] nfs_sync_inode+0x13/0x30 [nfs]
[ 861.313302] nfs42_proc_fallocate.isra.0+0x91/0x100 [nfsv4]
[ 861.314099] nfs42_proc_deallocate+0x94/0x110 [nfsv4]
[ 861.314807] nfs42_fallocate+0x69/0x80 [nfsv4]
[ 861.315445] vfs_fallocate+0x152/0x2e0
[ 861.316008] __x64_sys_fallocate+0x44/0x70
[ 861.316582] do_syscall_64+0x36/0xb0
[ 861.317074] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 861.317774] RIP: 0033:0x7fb605c9941f
[ 861.318293] RSP: 002b:00007fb43b2cd7e0 EFLAGS: 00000293 ORIG_RAX: 000000000000011d
[ 861.319312] RAX: ffffffffffffffda RBX: 0000000003d59970 RCX: 00007fb605c9941f
[ 861.320319] RDX: 000000001bd50000 RSI: 0000000000000003 RDI: 0000000000000018
[ 861.321279] RBP: 00007fb43b2cd830 R08: 0000000000000000 R09: 00000000ffffffff
[ 861.322248] R10: 0000000000050000 R11: 0000000000000293 R12: 00007ffd10144c2e
[ 861.323210] R13: 00007ffd10144c2f R14: 00007ffd10144cf0 R15: 00007fb43b2cf700
[ 869.988970] nfs: server starship not responding, still trying
[ 984.164970] INFO: task qemu-system-x86:2547 blocked for more than 368 seconds.
[ 984.166056] Tainted: G O 5.14.0.stable #87
[ 984.166879] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 984.168027] task:qemu-system-x86 state:D stack: 0 pid: 2547 ppid: 2539 flags:0x00000000
[ 984.169204] Call Trace:
[ 984.169564] __schedule+0x2df/0x1440
[ 984.170099] schedule+0x4e/0xb0
[ 984.170549] rwsem_down_read_slowpath+0x2e4/0x330
[ 984.171226] down_read+0x43/0x90
[ 984.171679] nfs_start_io_direct+0x1e/0x70 [nfs]
[ 984.172389] nfs_file_direct_write+0x1f7/0x340 [nfs]
[ 984.173123] nfs_file_write+0x269/0x310 [nfs]
[ 984.173756] aio_write+0xfc/0x1f0
[ 984.174269] ? __pollwait+0xd0/0xd0
[ 984.174777] ? __fget_files+0x5f/0x90
[ 984.175307] ? __fget_light+0x32/0x80
[ 984.175816] io_submit_one+0x1f6/0x790
[ 984.176397] __x64_sys_io_submit+0x84/0x180
[ 984.177000] ? fput+0x13/0x20
[ 984.177425] ? ksys_read+0xce/0xe0
[ 984.177908] do_syscall_64+0x36/0xb0
[ 984.178427] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 984.179129] RIP: 0033:0x7fb605c9e37d
[ 984.179635] RSP: 002b:00007ffd10142c18 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[ 984.180702] RAX: ffffffffffffffda RBX: 00007fb601ebc808 RCX: 00007fb605c9e37d
[ 984.181704] RDX: 00007ffd10142c90 RSI: 0000000000000001 RDI: 00007fb600d07000
[ 984.182734] RBP: 00007fb600d07000 R08: 00007ffd10144a30 R09: 000000000319cfe0
[ 984.183727] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
[ 984.184753] R13: 000000000000000b R14: 00007ffd10142c90 R15: 0000000000000000
[ 984.185786] INFO: task worker:2592 blocked for more than 368 seconds.
[ 984.186705] Tainted: G O 5.14.0.stable #87
[ 984.187537] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 984.188643] task:worker state:D stack: 0 pid: 2592 ppid: 2539 flags:0x00000000
[ 984.189812] Call Trace:
[ 984.190169] __schedule+0x2df/0x1440
[ 984.190710] ? futex_wait+0x105/0x250
[ 984.191230] schedule+0x4e/0xb0
[ 984.191682] inode_dio_wait+0xd1/0x100
[ 984.192223] ? var_wake_function+0x30/0x30
[ 984.192840] nfs_sync_inode+0x13/0x30 [nfs]
[ 984.193460] nfs42_proc_fallocate.isra.0+0x91/0x100 [nfsv4]
[ 984.194280] nfs42_proc_deallocate+0x94/0x110 [nfsv4]
[ 984.195037] nfs42_fallocate+0x69/0x80 [nfsv4]
[ 984.195687] vfs_fallocate+0x152/0x2e0
[ 984.196216] __x64_sys_fallocate+0x44/0x70
[ 984.196815] do_syscall_64+0x36/0xb0
[ 984.197334] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 984.198052] RIP: 0033:0x7fb605c9941f
[ 984.198558] RSP: 002b:00007fb43b2cd7e0 EFLAGS: 00000293 ORIG_RAX: 000000000000011d
[ 984.199588] RAX: ffffffffffffffda RBX: 0000000003d59970 RCX: 00007fb605c9941f
[ 984.200585] RDX: 000000001bd50000 RSI: 0000000000000003 RDI: 0000000000000018
[ 984.201559] RBP: 00007fb43b2cd830 R08: 0000000000000000 R09: 00000000ffffffff
[ 984.202547] R10: 0000000000050000 R11: 0000000000000293 R12: 00007ffd10144c2e
[ 984.203507] R13: 00007ffd10144c2f R14: 00007ffd10144cf0 R15: 00007fb43b2cf700
[ 1107.044901] INFO: task qemu-system-x86:2547 blocked for more than 491 seconds.
[ 1107.045965] Tainted: G O 5.14.0.stable #87
[ 1107.046827] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1107.047923] task:qemu-system-x86 state:D stack: 0 pid: 2547 ppid: 2539 flags:0x00000000
[ 1107.049136] Call Trace:
[ 1107.049484] __schedule+0x2df/0x1440
[ 1107.050008] schedule+0x4e/0xb0
[ 1107.050458] rwsem_down_read_slowpath+0x2e4/0x330
[ 1107.051129] down_read+0x43/0x90
[ 1107.051582] nfs_start_io_direct+0x1e/0x70 [nfs]
[ 1107.052285] nfs_file_direct_write+0x1f7/0x340 [nfs]
[ 1107.053011] nfs_file_write+0x269/0x310 [nfs]
[ 1107.053647] aio_write+0xfc/0x1f0
[ 1107.054133] ? __pollwait+0xd0/0xd0
[ 1107.054628] ? __fget_files+0x5f/0x90
[ 1107.055195] ? __fget_light+0x32/0x80
[ 1107.055706] io_submit_one+0x1f6/0x790
[ 1107.056287] __x64_sys_io_submit+0x84/0x180
[ 1107.056891] ? fput+0x13/0x20
[ 1107.057306] ? ksys_read+0xce/0xe0
[ 1107.057778] do_syscall_64+0x36/0xb0
[ 1107.058319] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 1107.059042] RIP: 0033:0x7fb605c9e37d
[ 1107.059540] RSP: 002b:00007ffd10142c18 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[ 1107.060601] RAX: ffffffffffffffda RBX: 00007fb601ebc808 RCX: 00007fb605c9e37d
[ 1107.061594] RDX: 00007ffd10142c90 RSI: 0000000000000001 RDI: 00007fb600d07000
[ 1107.062602] RBP: 00007fb600d07000 R08: 00007ffd10144a30 R09: 000000000319cfe0
[ 1107.063597] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
[ 1107.064663] R13: 000000000000000b R14: 00007ffd10142c90 R15: 0000000000000000
[ 1107.065663] INFO: task worker:2592 blocked for more than 491 seconds.
[ 1107.066615] Tainted: G O 5.14.0.stable #87
[ 1107.067446] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1107.068545] task:worker state:D stack: 0 pid: 2592 ppid: 2539 flags:0x00000000
[ 1107.069708] Call Trace:
[ 1107.070065] __schedule+0x2df/0x1440
[ 1107.070585] ? futex_wait+0x105/0x250
[ 1107.071107] schedule+0x4e/0xb0
[ 1107.071559] inode_dio_wait+0xd1/0x100
[ 1107.072089] ? var_wake_function+0x30/0x30
[ 1107.072682] nfs_sync_inode+0x13/0x30 [nfs]
[ 1107.073299] nfs42_proc_fallocate.isra.0+0x91/0x100 [nfsv4]
[ 1107.074124] nfs42_proc_deallocate+0x94/0x110 [nfsv4]
[ 1107.074894] nfs42_fallocate+0x69/0x80 [nfsv4]
[ 1107.075547] vfs_fallocate+0x152/0x2e0
[ 1107.076081] __x64_sys_fallocate+0x44/0x70
[ 1107.076700] do_syscall_64+0x36/0xb0
[ 1107.077209] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 1107.077934] RIP: 0033:0x7fb605c9941f
[ 1107.078446] RSP: 002b:00007fb43b2cd7e0 EFLAGS: 00000293 ORIG_RAX: 000000000000011d
[ 1107.079543] RAX: ffffffffffffffda RBX: 0000000003d59970 RCX: 00007fb605c9941f
[ 1107.080594] RDX: 000000001bd50000 RSI: 0000000000000003 RDI: 0000000000000018
[ 1107.081588] RBP: 00007fb43b2cd830 R08: 0000000000000000 R09: 00000000ffffffff
[ 1107.082596] R10: 0000000000050000 R11: 0000000000000293 R12: 00007ffd10144c2e
[ 1107.083590] R13: 00007ffd10144c2f R14: 00007ffd10144cf0 R15: 00007fb43b2cf700
[ 1229.924880] INFO: task qemu-system-x86:2547 blocked for more than 614 seconds.
[ 1229.925960] Tainted: G O 5.14.0.stable #87
[ 1229.926777] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1229.927859] task:qemu-system-x86 state:D stack: 0 pid: 2547 ppid: 2539 flags:0x00000000
[ 1229.929038] Call Trace:
[ 1229.929396] __schedule+0x2df/0x1440
[ 1229.929908] schedule+0x4e/0xb0
[ 1229.930363] rwsem_down_read_slowpath+0x2e4/0x330
[ 1229.931072] down_read+0x43/0x90
[ 1229.931525] nfs_start_io_direct+0x1e/0x70 [nfs]
[ 1229.932231] nfs_file_direct_write+0x1f7/0x340 [nfs]
[ 1229.932950] nfs_file_write+0x269/0x310 [nfs]
[ 1229.933564] aio_write+0xfc/0x1f0
[ 1229.934024] ? __pollwait+0xd0/0xd0
[ 1229.934531] ? __fget_files+0x5f/0x90
[ 1229.935039] ? __fget_light+0x32/0x80
[ 1229.935538] io_submit_one+0x1f6/0x790
[ 1229.936070] __x64_sys_io_submit+0x84/0x180
[ 1229.936650] ? fput+0x13/0x20
[ 1229.937080] ? ksys_read+0xce/0xe0
[ 1229.937538] do_syscall_64+0x36/0xb0
[ 1229.938072] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 1229.938781] RIP: 0033:0x7fb605c9e37d
[ 1229.939269] RSP: 002b:00007ffd10142c18 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[ 1229.940304] RAX: ffffffffffffffda RBX: 00007fb601ebc808 RCX: 00007fb605c9e37d
[ 1229.941283] RDX: 00007ffd10142c90 RSI: 0000000000000001 RDI: 00007fb600d07000
[ 1229.942264] RBP: 00007fb600d07000 R08: 00007ffd10144a30 R09: 000000000319cfe0
[ 1229.943229] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
[ 1229.944191] R13: 000000000000000b R14: 00007ffd10142c90 R15: 0000000000000000
[ 1229.945199] INFO: task worker:2592 blocked for more than 614 seconds.
[ 1229.946085] Tainted: G O 5.14.0.stable #87
[ 1229.946912] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1229.947960] task:worker state:D stack: 0 pid: 2592 ppid: 2539 flags:0x00000000
[ 1229.949114] Call Trace:
[ 1229.949450] __schedule+0x2df/0x1440
[ 1229.949955] ? futex_wait+0x105/0x250
[ 1229.950465] schedule+0x4e/0xb0
[ 1229.950916] inode_dio_wait+0xd1/0x100
[ 1229.951418] ? var_wake_function+0x30/0x30
[ 1229.951994] nfs_sync_inode+0x13/0x30 [nfs]
[ 1229.952580] nfs42_proc_fallocate.isra.0+0x91/0x100 [nfsv4]
[ 1229.953417] nfs42_proc_deallocate+0x94/0x110 [nfsv4]
[ 1229.954165] nfs42_fallocate+0x69/0x80 [nfsv4]
[ 1229.954845] vfs_fallocate+0x152/0x2e0
[ 1229.955361] __x64_sys_fallocate+0x44/0x70
[ 1229.955931] do_syscall_64+0x36/0xb0
[ 1229.956461] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 1229.957173] RIP: 0033:0x7fb605c9941f
[ 1229.957654] RSP: 002b:00007fb43b2cd7e0 EFLAGS: 00000293 ORIG_RAX: 000000000000011d
[ 1229.958682] RAX: ffffffffffffffda RBX: 0000000003d59970 RCX: 00007fb605c9941f
[ 1229.959647] RDX: 000000001bd50000 RSI: 0000000000000003 RDI: 0000000000000018
[ 1229.960630] RBP: 00007fb43b2cd830 R08: 0000000000000000 R09: 00000000ffffffff
[ 1229.961604] R10: 0000000000050000 R11: 0000000000000293 R12: 00007ffd10144c2e
[ 1229.962578] R13: 00007ffd10144c2f R14: 00007ffd10144cf0 R15: 00007fb43b2cf700
[ 1341.029300] nfs: server starship OK
[ 1341.029301] nfs: server starship OK
[ 1341.029340] nfs: server starship OK
[ 1341.029439] nfs: server starship OK
[ 1341.029480] nfs: server starship OK
[ 1341.029485] nfs: server starship OK
[ 1341.029504] nfs: server starship OK
[ 1341.029513] nfs: server starship OK
[ 1341.029517] nfs: server starship OK
[ 1341.029518] nfs: server starship OK
[ 1341.055837] NFS: __nfs4_reclaim_open_state: Lock reclaim failed!
[ 1341.057301] NFS: __nfs4_reclaim_open_state: Lock reclaim failed!
[-- Attachment #3: backtrace2.txt --]
[-- Type: text/plain, Size: 7659 bytes --]
[mlevitsk@fedora32 ~]$[ 1824.918021] nfs: server starship not responding, still trying
[ 1824.918035] nfs: server starship not responding, still trying
[ 1824.918043] nfs: server starship not responding, still trying
[ 1825.214024] nfs: server starship not responding, still trying
[ 1825.494008] nfs: server starship not responding, still trying
[ 1825.494018] nfs: server starship not responding, still trying
[ 1825.523020] nfs: server starship not responding, still trying
[ 1825.710019] nfs: server starship not responding, still trying
[ 1826.262017] nfs: server starship not responding, still trying
[ 1826.262025] nfs: server starship not responding, still trying
[ 1844.374047] INFO: task qemu-system-x86:4517 blocked for more than 122 seconds.
[ 1844.375385] Not tainted 5.15.0-rc3.unstable #88
[ 1844.376270] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1844.377677] task:qemu-system-x86 state:D stack: 0 pid: 4517 ppid: 4511 flags:0x00000000
[ 1844.379164] Call Trace:
[ 1844.379613] __schedule+0x2dd/0x1440
[ 1844.380245] schedule+0x4e/0xb0
[ 1844.380834] rwsem_down_read_slowpath+0x2e4/0x330
[ 1844.381662] down_read+0x43/0x90
[ 1844.382277] nfs_start_io_direct+0x1e/0x70 [nfs]
[ 1844.383181] nfs_file_direct_write+0x1f7/0x340 [nfs]
[ 1844.384113] nfs_file_write+0x26f/0x320 [nfs]
[ 1844.384907] aio_write+0xfc/0x1f0
[ 1844.385511] ? __pollwait+0xd0/0xd0
[ 1844.386187] ? __fget_files+0x5f/0x90
[ 1844.386859] ? __fget_light+0x32/0x80
[ 1844.387520] io_submit_one+0x1f6/0x790
[ 1844.388255] __x64_sys_io_submit+0x84/0x180
[ 1844.389049] ? fput+0x13/0x20
[ 1844.389603] ? ksys_read+0xce/0xe0
[ 1844.390225] do_syscall_64+0x36/0xb0
[ 1844.390870] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 1844.391792] RIP: 0033:0x7f836ff9c37d
[ 1844.392469] RSP: 002b:00007ffe5808be18 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[ 1844.393798] RAX: ffffffffffffffda RBX: 00007f836c183828 RCX: 00007f836ff9c37d
[ 1844.395066] RDX: 00007ffe5808be90 RSI: 0000000000000001 RDI: 00007f836afce000
[ 1844.396334] RBP: 00007f836afce000 R08: 00007ffe5808dc30 R09: 0000000002969f00
[ 1844.397596] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
[ 1844.398849] R13: 000000000000000b R14: 00007ffe5808be90 R15: 0000000000000000
[ 1844.400169] INFO: task worker:4555 blocked for more than 122 seconds.
[ 1844.401306] Not tainted 5.15.0-rc3.unstable #88
[ 1844.402233] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1844.403632] task:worker state:D stack: 0 pid: 4555 ppid: 4511 flags:0x00000000
[ 1844.405108] Call Trace:
[ 1844.405587] __schedule+0x2dd/0x1440
[ 1844.406215] ? hrtimer_cancel+0x15/0x30
[ 1844.406904] ? futex_wait+0x223/0x250
[ 1844.407601] schedule+0x4e/0xb0
[ 1844.408194] inode_dio_wait+0xd1/0x100
[ 1844.408871] ? var_wake_function+0x30/0x30
[ 1844.409617] nfs_sync_inode+0x13/0x30 [nfs]
[ 1844.410426] nfs42_proc_fallocate.isra.0+0x91/0x100 [nfsv4]
[ 1844.411504] nfs42_proc_allocate+0x8c/0xe0 [nfsv4]
[ 1844.412426] nfs42_fallocate+0x59/0x80 [nfsv4]
[ 1844.413222] vfs_fallocate+0x152/0x2f0
[ 1844.413926] __x64_sys_fallocate+0x44/0x70
[ 1844.414635] do_syscall_64+0x36/0xb0
[ 1844.415288] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 1844.416209] RIP: 0033:0x7f836ff9741f
[ 1844.416838] RSP: 002b:00007f81a5cb77a0 EFLAGS: 00000293 ORIG_RAX: 000000000000011d
[ 1844.418118] RAX: ffffffffffffffda RBX: 0000000002137360 RCX: 00007f836ff9741f
[ 1844.419352] RDX: 00000000143f0000 RSI: 0000000000000000 RDI: 0000000000000018
[ 1844.420629] RBP: 00007f81a5cb77f0 R08: 0000000000000000 R09: 00000000ffffffff
[ 1844.421860] R10: 0000000000050000 R11: 0000000000000293 R12: 00007ffe5808de2e
[ 1844.423082] R13: 00007ffe5808de2f R14: 00007ffe5808def0 R15: 00007f81a5cb9700
[ 1911.958025] rpc_check_timeout: 7 callbacks suppressed
[ 1911.958029] nfs: server starship not responding, still trying
[ 1967.254016] INFO: task qemu-system-x86:4517 blocked for more than 245 seconds.
[ 1967.255338] Not tainted 5.15.0-rc3.unstable #88
[ 1967.256218] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1967.257662] task:qemu-system-x86 state:D stack: 0 pid: 4517 ppid: 4511 flags:0x00000000
[ 1967.259150] Call Trace:
[ 1967.259595] __schedule+0x2dd/0x1440
[ 1967.260242] schedule+0x4e/0xb0
[ 1967.260839] rwsem_down_read_slowpath+0x2e4/0x330
[ 1967.261674] down_read+0x43/0x90
[ 1967.262294] nfs_start_io_direct+0x1e/0x70 [nfs]
[ 1967.263205] nfs_file_direct_write+0x1f7/0x340 [nfs]
[ 1967.264139] nfs_file_write+0x26f/0x320 [nfs]
[ 1967.264996] aio_write+0xfc/0x1f0
[ 1967.265599] ? __pollwait+0xd0/0xd0
[ 1967.266229] ? __fget_files+0x5f/0x90
[ 1967.266904] ? __fget_light+0x32/0x80
[ 1967.267600] io_submit_one+0x1f6/0x790
[ 1967.268312] __x64_sys_io_submit+0x84/0x180
[ 1967.269090] ? fput+0x13/0x20
[ 1967.269620] ? ksys_read+0xce/0xe0
[ 1967.270239] do_syscall_64+0x36/0xb0
[ 1967.270882] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 1967.271796] RIP: 0033:0x7f836ff9c37d
[ 1967.272475] RSP: 002b:00007ffe5808be18 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
[ 1967.273836] RAX: ffffffffffffffda RBX: 00007f836c183828 RCX: 00007f836ff9c37d
[ 1967.275113] RDX: 00007ffe5808be90 RSI: 0000000000000001 RDI: 00007f836afce000
[ 1967.276383] RBP: 00007f836afce000 R08: 00007ffe5808dc30 R09: 0000000002969f00
[ 1967.277678] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
[ 1967.278922] R13: 000000000000000b R14: 00007ffe5808be90 R15: 0000000000000000
[ 1967.280207] INFO: task worker:4555 blocked for more than 245 seconds.
[ 1967.281380] Not tainted 5.15.0-rc3.unstable #88
[ 1967.282283] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1967.283675] task:worker state:D stack: 0 pid: 4555 ppid: 4511 flags:0x00000000
[ 1967.285123] Call Trace:
[ 1967.285626] __schedule+0x2dd/0x1440
[ 1967.286252] ? hrtimer_cancel+0x15/0x30
[ 1967.286972] ? futex_wait+0x223/0x250
[ 1967.287652] schedule+0x4e/0xb0
[ 1967.288205] inode_dio_wait+0xd1/0x100
[ 1967.288887] ? var_wake_function+0x30/0x30
[ 1967.289675] nfs_sync_inode+0x13/0x30 [nfs]
[ 1967.290457] nfs42_proc_fallocate.isra.0+0x91/0x100 [nfsv4]
[ 1967.291480] nfs42_proc_allocate+0x8c/0xe0 [nfsv4]
[ 1967.292369] nfs42_fallocate+0x59/0x80 [nfsv4]
[ 1967.293230] vfs_fallocate+0x152/0x2f0
[ 1967.293937] __x64_sys_fallocate+0x44/0x70
[ 1967.294666] do_syscall_64+0x36/0xb0
[ 1967.295328] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 1967.296247] RIP: 0033:0x7f836ff9741f
[ 1967.296907] RSP: 002b:00007f81a5cb77a0 EFLAGS: 00000293 ORIG_RAX: 000000000000011d
[ 1967.298252] RAX: ffffffffffffffda RBX: 0000000002137360 RCX: 00007f836ff9741f
[ 1967.299509] RDX: 00000000143f0000 RSI: 0000000000000000 RDI: 0000000000000018
[ 1967.300786] RBP: 00007f81a5cb77f0 R08: 0000000000000000 R09: 00000000ffffffff
[ 1967.302058] R10: 0000000000050000 R11: 0000000000000293 R12: 00007ffe5808de2e
[ 1967.303306] R13: 00007ffe5808de2f R14: 00007ffe5808def0 R15: 00007f81a5cb9700
[ 2059.330865] nfs: server starship OK
[ 2059.330881] nfs: server starship OK
[ 2059.330894] nfs: server starship OK
[ 2059.330909] nfs: server starship OK
[ 2059.330914] nfs: server starship OK
[ 2059.330918] nfs: server starship OK
[ 2059.330920] nfs: server starship OK
[ 2059.330923] nfs: server starship OK
[ 2059.330926] nfs: server starship OK
[ 2059.330951] nfs: server starship OK
[ 2059.357705] NFS: __nfs4_reclaim_open_state: Lock reclaim failed!
[ 2059.358996] NFS: __nfs4_reclaim_open_state: Lock reclaim failed!
[ 2059.361227] NFS: __nfs4_reclaim_open_state: Lock reclaim failed!
[-- Attachment #4: Type: text/plain, Size: 4663 bytes --]
[ 1079.894584] rpc-srv/tcp: nfsd: got error -11 when sending 8320 bytes - shutting down socket
[15538.451334] rpc-srv/tcp: nfsd: got error -11 when sending 65664 bytes - shutting down socket
[mlevitsk@starship ~]$cd VM/
Session terminated, killing shell... ...killed.
[28111.171764] lockd: couldn't shutdown host module for net f0000098!
[28111.173658] kernel tried to execute NX-protected page - exploit attempt? (uid: 0)
[28111.174165] BUG: unable to handle page fault for address: ffff8881042f80b0
[28111.174634] #PF: supervisor instruction fetch in kernel mode
[28111.174996] #PF: error_code(0x0011) - permissions violation
[28111.175378] PGD 3201067 P4D 3201067 PUD 209f1fc067 PMD 11673d063 PTE 80000001042f8163
[28111.175897] Oops: 0011 [#1] SMP
[28111.176137] CPU: 39 PID: 1989 Comm: lockd Tainted: G O 5.15.0-rc3.unstable #4 c74cb40e1c7cfbb76f5f8fab27d10002f7624b68
[28111.176923] Hardware name: Gigabyte Technology Co., Ltd. TRX40 DESIGNARE/TRX40 DESIGNARE, BIOS F4c 03/05/2020
[28111.177589] RIP: 0010:0xffff8881042f80b0
[28111.177871] Code: ff ff 00 11 42 12 81 88 ff ff 90 00 b6 10 81 88 ff ff d0 50 31 05 81 88 ff ff a0 80 2f 04 81 88 ff ff a0 80 2f 04 81 88 ff ff <b0> 80 2f 04 81 88 ff ff b0 80 2f 04 81 88 ff ff 50 66 9f 74 81 88
[28111.179041] RSP: 0018:ffffc90004a07d18 EFLAGS: 00010282
[28111.179387] RAX: ffff8881042f80b0 RBX: ffff88818e91a2e8 RCX: 0000000000000000
[28111.179862] RDX: ffffc90004a07d30 RSI: 0000000000000006 RDI: ffff88818e91a2e8
[28111.180313] RBP: ffffc90004a07d20 R08: ffffc90004a07d30 R09: ffff88818a1a6050
[28111.180786] R10: 0000000000000000 R11: ffffffff829f9580 R12: ffff888613a1d900
[28111.181225] R13: ffffffff8159e040 R14: ffff888115482510 R15: ffff888613a1d900
[28111.181655] FS: 0000000000000000(0000) GS:ffff88a01e9c0000(0000) knlGS:0000000000000000
[28111.182206] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[28111.182604] CR2: ffff8881042f80b0 CR3: 000000010ecb6000 CR4: 0000000000350ee0
[28111.183085] Call Trace:
[28111.183272] ? vfs_lock_file+0x1e/0x40
[28111.183548] nlm_unlock_files+0x6d/0xc0
[28111.183817] ? mutex_lock+0x13/0x40
[28111.184062] ? nlmsvc_traverse_blocks+0x101/0x140
[28111.184386] nlm_traverse_files+0x151/0x280
[28111.184670] nlmsvc_invalidate_all+0x19/0x40
[28111.184967] lockd+0xef/0x1c0
[28111.185179] ? set_grace_period+0xc0/0xc0
[28111.185458] kthread+0x127/0x180
[28111.185687] ? set_kthread_struct+0x80/0x80
[28111.185984] ret_from_fork+0x1f/0x30
[28111.186240] Modules linked in: xt_state xt_conntrack ip6table_filter ip6_tables tun pmbus pmbus_core ee1004 jc42 wmi_bmof iwlmvm uvcvideo snd_hda_codec_hdmi videobuf2_vmalloc mac80211 videobuf2_memops snd_hda_intel libarc4 snd_usb_audio videobuf2_v4l2 snd_intel_dspcfg kvm_amd btusb snd_hda_codec snd_usbmidi_lib videobuf2_common btrtl snd_hwdep iwlwifi kvm btbcm btintel snd_rawmidi snd_hda_core videodev xpad irqbypass pcspkr i2c_nvidia_gpu snd_pcm bluetooth joydev input_leds ff_memless mc cfg80211 i2c_piix4 zenpower thunderbolt bfq tpm_crb rtc_cmos wmi tpm_tis tpm_tis_core binfmt_misc fuse dm_crypt wacom hid_logitech_hidpp hid_logitech_dj ext4 mbcache jbd2 sd_mod uas usb_storage hid_generic usbhid amdgpu drm_ttm_helper ttm gpu_sched drm_kms_helper cfbfillrect syscopyarea cfbimgblt sysfillrect sysimgblt fb_sys_fops cfbcopyarea cec rc_core ahci igb drm libahci xhci_pci drm_panel_orientation_quirks libata i2c_algo_bit ccp xhci_hcd nvme nvme_core t10_pi dm_mirror dm_region_hash dm_log
[28111.186281] vendor_reset(O) nbd usbmon it87 hwmon_vid i2c_dev i2c_core autofs4
[28111.192288] CR2: ffff8881042f80b0
[28111.192514] ---[ end trace fee75091aa3bdf61 ]---
[28111.203651] RIP: 0010:0xffff8881042f80b0
[28111.203950] Code: ff ff 00 11 42 12 81 88 ff ff 90 00 b6 10 81 88 ff ff d0 50 31 05 81 88 ff ff a0 80 2f 04 81 88 ff ff a0 80 2f 04 81 88 ff ff <b0> 80 2f 04 81 88 ff ff b0 80 2f 04 81 88 ff ff 50 66 9f 74 81 88
[28111.205128] RSP: 0018:ffffc90004a07d18 EFLAGS: 00010282
[28111.205474] RAX: ffff8881042f80b0 RBX: ffff88818e91a2e8 RCX: 0000000000000000
[28111.205933] RDX: ffffc90004a07d30 RSI: 0000000000000006 RDI: ffff88818e91a2e8
[28111.206409] RBP: ffffc90004a07d20 R08: ffffc90004a07d30 R09: ffff88818a1a6050
[28111.206895] R10: 0000000000000000 R11: ffffffff829f9580 R12: ffff888613a1d900
[28111.207353] R13: ffffffff8159e040 R14: ffff888115482510 R15: ffff888613a1d900
[28111.207825] FS: 0000000000000000(0000) GS:ffff88a01e9c0000(0000) knlGS:0000000000000000
[28111.208340] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[28111.208720] CR2: ffff8881042f80b0 CR3: 000000010ecb6000 CR4: 0000000000350ee0
[28111.263621] nfsd: last server has exited, flushing export cache
[-- Attachment #5: Type: text/plain, Size: 8592 bytes --]
[28494.605874] nfsd: last server has exited, flushing export cache
[28494.752038] NFSD: Using nfsdcld client tracking operations.
[28494.752462] NFSD: starting 90-second grace period (net f0000098)
[28550.237900] NFSD: all clients done reclaiming, ending NFSv4 grace period (net f0000098)
[29062.881971] rpc-srv/tcp: nfsd: got error -11 when sending 65664 bytes - shutting down socket
[30293.066082] lockd: couldn't shutdown host module for net f0000098!
[30327.451815] BUG: workqueue lockup - pool cpus=4 node=0 flags=0x0 nice=0 stuck for 34s!
[30327.452367] Showing busy workqueues and worker pools:
[30327.452735] workqueue events: flags=0x0
[30327.453013] pwq 8: cpus=4 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[30327.453473] pending: kfree_rcu_monitor
[30327.453841] workqueue mm_percpu_wq: flags=0x8
[30327.454188] pwq 8: cpus=4 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[30327.454638] pending: vmstat_update
[30327.454939] workqueue kblockd: flags=0x18
[30327.455200] pwq 9: cpus=4 node=0 flags=0x0 nice=-20 active=1/256 refcnt=2
[30327.455636] pending: blk_mq_run_work_fn
[30353.070356] rcu: INFO: rcu_sched self-detected stall on CPU
[30353.070754] rcu: 4-....: (59999 ticks this GP) idle=dd7/1/0x4000000000000000 softirq=1487839/1487839 fqs=14979 last_accelerate: adac/9814 dyntick_enabled: 1
[30353.071634] (t=60001 jiffies g=7822577 q=36089)
[30353.071940] NMI backtrace for cpu 4
[30353.072175] CPU: 4 PID: 48380 Comm: lockd Tainted: G O 5.15.0-rc3.unstable #4 c74cb40e1c7cfbb76f5f8fab27d10002f7624b68
[30353.072905] Hardware name: Gigabyte Technology Co., Ltd. TRX40 DESIGNARE/TRX40 DESIGNARE, BIOS F4c 03/05/2020
[30353.073513] Call Trace:
[30353.073681] <IRQ>
[30353.073834] dump_stack_lvl+0x45/0x63
[30353.074081] dump_stack+0x10/0x12
[30353.074326] nmi_cpu_backtrace.cold+0x32/0x81
[30353.074623] ? lapic_can_unplug_cpu+0x80/0x80
[30353.074929] nmi_trigger_cpumask_backtrace+0x85/0xc0
[30353.075247] arch_trigger_cpumask_backtrace+0x19/0x40
[30353.075567] rcu_dump_cpu_stacks+0xcb/0xfd
[30353.075854] rcu_sched_clock_irq.cold+0xe8/0x220
[30353.076155] ? account_system_index_time+0x99/0xc0
[30353.076483] update_process_times+0x94/0x100
[30353.076769] tick_sched_handle+0x29/0x80
[30353.077028] tick_sched_timer+0x6b/0x80
[30353.077304] ? tick_sched_handle+0x80/0x80
[30353.077572] __hrtimer_run_queues+0x129/0x280
[30353.077850] hrtimer_interrupt+0x101/0x240
[30353.078138] __sysvec_apic_timer_interrupt+0x56/0x100
[30353.078482] sysvec_apic_timer_interrupt+0x77/0xc0
[30353.078792] </IRQ>
[30353.078943] asm_sysvec_apic_timer_interrupt+0x12/0x20
[30353.079264] RIP: 0010:_raw_spin_lock+0x7/0x40
[30353.079554] Code: 82 5b ff 5d c3 66 66 2e 0f 1f 84 00 00 00 00 00 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 31 c0 <ba> 01 00 00 00 f0 0f b1 17 75 01 c3 55 89 c6 48 89 e5 e8 22 7f 5b
[30353.080681] RSP: 0018:ffffc90006557e28 EFLAGS: 00000246
[30353.081033] RAX: 0000000000000000 RBX: ffff88816e5cd130 RCX: 0000000000000000
[30353.081484] RDX: ffff8889208d7400 RSI: 0000000000000000 RDI: ffff88816e5cd118
[30353.081950] RBP: ffffc90006557e80 R08: ffff88a018b278c0 R09: 7fffffffffffffff
[30353.082421] R10: 0000000008118c00 R11: 000000000010e778 R12: 0000000000000000
[30353.082850] R13: ffffffff8159e040 R14: ffff88816e5cd118 R15: ffff888bd3635b00
[30353.083300] ? nlmsvc_same_host+0x40/0x40
[30353.083560] ? nlm_traverse_files+0xf8/0x280
[30353.083862] nlmsvc_invalidate_all+0x19/0x40
[30353.084131] lockd+0xef/0x1c0
[30353.084333] ? set_grace_period+0xc0/0xc0
[30353.084615] kthread+0x127/0x180
[30353.084837] ? set_kthread_struct+0x80/0x80
[30353.085102] ret_from_fork+0x1f/0x30
[30387.864386] BUG: workqueue lockup - pool cpus=4 node=0 flags=0x0 nice=0 stuck for 94s!
[30387.864984] Showing busy workqueues and worker pools:
[30387.865373] workqueue events: flags=0x0
[30387.865654] pwq 8: cpus=4 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[30387.866106] pending: kfree_rcu_monitor
[30387.866430] workqueue events_power_efficient: flags=0x80
[30387.866783] pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[30387.867214] pending: neigh_periodic_work
[30387.867529] workqueue mm_percpu_wq: flags=0x8
[30387.867808] pwq 8: cpus=4 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[30387.868221] pending: vmstat_update
[30418.070674] BUG: workqueue lockup - pool cpus=4 node=0 flags=0x0 nice=0 stuck for 124s!
[30418.071292] Showing busy workqueues and worker pools:
[30418.071645] workqueue events: flags=0x0
[30418.071951] pwq 8: cpus=4 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[30418.072461] pending: kfree_rcu_monitor
[30418.072819] workqueue mm_percpu_wq: flags=0x8
[30418.073114] pwq 8: cpus=4 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[30418.073528] pending: vmstat_update
[30448.276963] BUG: workqueue lockup - pool cpus=4 node=0 flags=0x0 nice=0 stuck for 155s!
[30448.277474] Showing busy workqueues and worker pools:
[30448.277808] workqueue events: flags=0x0
[30448.278081] pwq 8: cpus=4 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[30448.278506] pending: kfree_rcu_monitor
[30448.278867] workqueue mm_percpu_wq: flags=0x8
[30448.279206] pwq 8: cpus=4 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[30448.279642] pending: vmstat_update
[30469.779855] INFO: task nfsd:48383 blocked for more than 122 seconds.
[30469.780340] Tainted: G O 5.15.0-rc3.unstable #4
[30469.780793] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[30469.781332] task:nfsd state:D stack: 0 pid:48383 ppid: 2 flags:0x00004000
[30469.781883] Call Trace:
[30469.782059] __schedule+0x2cb/0x1380
[30469.782294] ? sugov_exit+0xc0/0xc0
[30469.782534] ? enqueue_entity+0x15b/0x700
[30469.782785] schedule+0x4e/0xc0
[30469.782997] schedule_timeout+0xfb/0x140
[30469.783272] ? ttwu_do_activate+0x83/0x140
[30469.783539] wait_for_completion+0x88/0x100
[30469.783845] kthread_stop+0x71/0x180
[30469.784114] lockd_down+0x5e/0xc0
[30469.784335] nfsd_shutdown_net+0x65/0x80
[30469.784594] nfsd_last_thread+0x10b/0x140
[30469.784876] ? svc_close_net+0x54/0x180
[30469.785132] svc_shutdown_net+0x30/0x40
[30469.785382] nfsd_destroy+0x44/0x80
[30469.785623] nfsd+0x12c/0x180
[30469.785818] ? nfsd_shutdown_threads+0xc0/0xc0
[30469.786101] kthread+0x127/0x180
[30469.786325] ? set_kthread_struct+0x80/0x80
[30469.786590] ret_from_fork+0x1f/0x30
[30469.786847] INFO: task exportfs:50946 blocked for more than 122 seconds.
[30469.787255] Tainted: G O 5.15.0-rc3.unstable #4
[30469.787636] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[30469.788211] task:exportfs state:D stack: 0 pid:50946 ppid: 1 flags:0x00000004
[30469.788729] Call Trace:
[30469.788913] __schedule+0x2cb/0x1380
[30469.789138] ? terminate_walk+0xdd/0x100
[30469.789406] schedule+0x4e/0xc0
[30469.789617] schedule_preempt_disabled+0xe/0x40
[30469.789960] __mutex_lock.constprop.0+0x2c2/0x480
[30469.790275] __mutex_lock_slowpath+0x13/0x40
[30469.790554] mutex_lock+0x34/0x40
[30469.790792] expkey_flush+0x15/0x40
[30469.791025] write_flush.constprop.0+0xf8/0x140
[30469.791302] write_flush_procfs+0x32/0x40
[30469.791573] proc_reg_write+0x54/0xc0
[30469.791827] ? __cond_resched+0x1a/0x80
[30469.792086] vfs_write+0xc4/0x280
[30469.792326] ksys_write+0x67/0x100
[30469.792565] __x64_sys_write+0x1a/0x40
[30469.792795] do_syscall_64+0x35/0x80
[30469.793037] entry_SYSCALL_64_after_hwframe+0x44/0xae
[30469.793352] RIP: 0033:0x7fa3ee3498d7
[30469.793589] RSP: 002b:00007ffc82865108 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[30469.794093] RAX: ffffffffffffffda RBX: 00005613767b1a50 RCX: 00007fa3ee3498d7
[30469.794555] RDX: 000000000000000b RSI: 00007ffc828651b0 RDI: 0000000000000004
[30469.794999] RBP: 00005613767accb3 R08: 00000000ffffffff R09: 000000000000001b
[30469.795466] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffc828651d0
[30469.795955] R13: 00007ffc828651b0 R14: 0000000000000004 R15: 00005613767acc94
[30478.483258] BUG: workqueue lockup - pool cpus=4 node=0 flags=0x0 nice=0 stuck for 185s!
[30478.483842] Showing busy workqueues and worker pools:
[30478.484175] workqueue events: flags=0x0
[30478.484494] pwq 8: cpus=4 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[30478.484915] pending: kfree_rcu_monitor
[30478.485254] workqueue mm_percpu_wq: flags=0x8
[30478.485532] pwq 8: cpus=4 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[30478.485984] pending: vmstat_update
[-- Attachment #6: Type: application/x-xz-compressed-tar, Size: 92024 bytes --]
^ permalink raw reply [flat|nested] only message in thread
only message in thread, other threads:[~2021-10-05 14:11 UTC | newest]
Thread overview: (only message) (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2021-10-05 14:08 NFS client deadlock while doing nested virtualization tests on my systems Maxim Levitsky
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).