FYI, we noticed the following commit: https://github.com/0day-ci/linux Trond-Myklebust/NFS-Don-t-flush-caches-for-a-getattr-that-races-with-writeback/20160615-032846 commit 5aaca3e48a8af4a0dc5f194db9d29bb970dd445e ("NFS: Cache access checks more aggressively") on test machine: vm-lkp-wsx03-2G: 2 threads qemu-system-x86_64 -enable-kvm -cpu host with 2G memory caused below changes: +------------------------------------------------------------------------------------+------------+------------+ | | b15f825456 | 5aaca3e48a | +------------------------------------------------------------------------------------+------------+------------+ | boot_successes | 22 | 0 | | boot_failures | 0 | 22 | | INFO:suspicious_RCU_usage | 0 | 22 | | BUG:sleeping_function_called_from_invalid_context_at_mm/slab.h | 0 | 22 | | INFO:lockdep_is_turned_off | 0 | 22 | | BUG:scheduling_while_atomic | 0 | 22 | | BUG:sleeping_function_called_from_invalid_context_at_kernel/locking/percpu-rwsem.c | 0 | 11 | | WARNING:at_kernel/softirq.c:#__local_bh_disable_ip | 0 | 10 | | WARNING:at_kernel/time/timer.c:#del_timer_sync | 0 | 10 | | backtrace:do_sys_open | 0 | 21 | | backtrace:SyS_open | 0 | 21 | | backtrace:SYSC_newstat | 0 | 10 | | backtrace:SyS_newstat | 0 | 10 | | BUG:sleeping_function_called_from_invalid_context_at_net/core/sock.c | 0 | 1 | | Kernel_panic-not_syncing:Aiee,killing_interrupt_handler | 0 | 6 | | backtrace:SYSC_newlstat | 0 | 6 | | backtrace:SyS_newlstat | 0 | 6 | +------------------------------------------------------------------------------------+------------+------------+ [ 41.505679] mount.nfs (820) used greatest stack depth: 11400 bytes left [ 41.810842] [ 41.811358] =============================== [ 41.812192] [ INFO: suspicious RCU usage. ] [ 41.813003] 4.7.0-rc3-00002-g5aaca3e #1 Not tainted [ 41.813899] ------------------------------- [ 41.814707] include/linux/rcupdate.h:554 Illegal context switch in RCU read-side critical section! [ 41.816588] [ 41.816588] other info that might help us debug this: [ 41.816588] [ 41.818246] [ 41.818246] rcu_scheduler_active = 1, debug_locks = 0 [ 41.819557] 2 locks held by wrapper/875: [ 41.820326] #0: (rcu_read_lock){......}, at: [] rcu_read_lock+0x0/0x68 [ 41.822256] #1: (rcu_read_lock){......}, at: [] rcu_read_lock+0x0/0x68 [ 41.824204] [ 41.824204] stack backtrace: [ 41.825180] CPU: 1 PID: 875 Comm: wrapper Not tainted 4.7.0-rc3-00002-g5aaca3e #1 [ 41.826594] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1 04/01/2014 [ 41.828168] 0000000000000000 ffff88007d283a98 ffffffff817767c7 ffff88007d3c9100 [ 41.829890] 0000000000000001 ffff88007d283ac8 ffffffff8112049f ffffffff839fa873 [ 41.831597] 0000000000000184 0000000000000000 0000000002400040 ffff88007d283ad8 [ 41.833309] Call Trace: [ 41.833870] [] dump_stack+0x82/0xb8 [ 41.834791] [] lockdep_rcu_suspicious+0xf7/0x100 [ 41.835865] [] rcu_preempt_sleep_check+0x45/0x47 [ 41.836938] [] ___might_sleep+0x1c/0x1c4 [ 41.837921] [] __might_sleep+0x75/0x7c [ 41.838883] [] slab_pre_alloc_hook+0x32/0x3f [ 41.839926] [] kmem_cache_alloc_trace+0x3d/0x133 [ 41.841008] [] ? nfs_alloc_fattr+0x20/0x37 [ 41.842010] [] nfs_alloc_fattr+0x20/0x37 [ 41.843004] [] __nfs_revalidate_inode+0xeb/0x2eb [ 41.844088] [] nfs_do_access+0x3ec/0x46f [ 41.845083] [] ? generic_lookup_cred+0x1a/0x1c [ 41.846141] [] ? rpcauth_lookupcred+0x61/0x6a [ 41.847182] [] nfs_permission+0xbe/0x188 [ 41.848176] [] __inode_permission+0x3e/0xa0 [ 41.849222] [] inode_permission+0x3f/0x41 [ 41.850227] [] link_path_walk+0x47/0x478 [ 41.851217] [] ? path_init+0x11d/0x2a4 [ 41.852182] [] path_openat+0x2ba/0x750 [ 41.853157] [] ? kvm_clock_read+0x25/0x2e [ 41.854163] [] do_filp_open+0x4d/0xa3 [ 41.855119] [] ? sched_clock_cpu+0x15/0xae [ 41.856140] [] ? _raw_spin_unlock+0x27/0x31 [ 41.857176] [] ? __alloc_fd+0x1b2/0x1c4 [ 41.858161] [] do_sys_open+0x72/0x102 [ 41.859119] [] ? do_sys_open+0x72/0x102 [ 41.860099] [] SyS_open+0x1e/0x20 [ 41.861000] [] entry_SYSCALL_64_fastpath+0x1f/0xbd [ 41.862103] [] ? trace_hardirqs_off_caller+0x3f/0xab [ 41.863269] BUG: sleeping function called from invalid context at mm/slab.h:388 [ 41.864906] in_atomic(): 1, irqs_disabled(): 0, pid: 875, name: wrapper [ 41.866026] INFO: lockdep is turned off. [ 41.866788] CPU: 1 PID: 875 Comm: wrapper Not tainted 4.7.0-rc3-00002-g5aaca3e #1 [ 41.868181] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1 04/01/2014 [ 41.869768] 0000000000000000 ffff88007d283ad8 ffffffff817767c7 ffff88007d3c9100 [ 41.871478] 000000000000036b ffff88007d283b00 ffffffff81105eda ffffffff839fa873 [ 41.873186] 0000000000000184 0000000000000000 ffff88007d283b28 ffffffff81105f56 [ 41.874902] Call Trace: [ 41.875470] [] dump_stack+0x82/0xb8 [ 41.876405] [] ___might_sleep+0x1bd/0x1c4 [ 41.877407] [] __might_sleep+0x75/0x7c [ 41.878373] [] slab_pre_alloc_hook+0x32/0x3f [ 41.879416] [] kmem_cache_alloc_trace+0x3d/0x133 [ 41.880490] [] ? nfs_alloc_fattr+0x20/0x37 [ 41.881499] [] nfs_alloc_fattr+0x20/0x37 [ 41.882483] [] __nfs_revalidate_inode+0xeb/0x2eb [ 41.883560] [] nfs_do_access+0x3ec/0x46f [ 41.884543] [] ? generic_lookup_cred+0x1a/0x1c [ 41.885597] [] ? rpcauth_lookupcred+0x61/0x6a [ 41.886641] [] nfs_permission+0xbe/0x188 [ 41.887628] [] __inode_permission+0x3e/0xa0 [ 41.888649] [] inode_permission+0x3f/0x41 [ 41.889653] [] link_path_walk+0x47/0x478 [ 41.890638] [] ? path_init+0x11d/0x2a4 [ 41.891595] [] path_openat+0x2ba/0x750 [ 41.892565] [] ? kvm_clock_read+0x25/0x2e [ 41.893564] [] do_filp_open+0x4d/0xa3 [ 41.894513] [] ? sched_clock_cpu+0x15/0xae [ 41.895520] [] ? _raw_spin_unlock+0x27/0x31 [ 41.896535] [] ? __alloc_fd+0x1b2/0x1c4 [ 41.897508] [] do_sys_open+0x72/0x102 [ 41.898453] [] ? do_sys_open+0x72/0x102 [ 41.899437] [] SyS_open+0x1e/0x20 [ 41.900346] [] entry_SYSCALL_64_fastpath+0x1f/0xbd [ 41.901445] [] ? trace_hardirqs_off_caller+0x3f/0xab [ 41.902740] BUG: scheduling while atomic: wrapper/875/0x00000003 [ 41.903862] INFO: lockdep is turned off. [ 41.904629] Modules linked in: [ 41.905359] CPU: 1 PID: 875 Comm: wrapper Not tainted 4.7.0-rc3-00002-g5aaca3e #1 [ 41.906742] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1 04/01/2014 [ 41.910291] 0000000000000000 ffff88007d2837d8 ffffffff817767c7 ffff88007d3c9100 [ 41.912029] 0000000000000000 ffff88007d2837f0 ffffffff81105441 ffff88009f5d8fc0 [ 41.913778] ffff88007d283850 ffffffff82ecb27d ffff88007d283820 00ffffff81121949 [ 41.915520] Call Trace: [ 41.916094] [] dump_stack+0x82/0xb8 [ 41.917032] [] __schedule_bug+0x61/0x70 [ 41.918009] [] __schedule+0x6b/0x76f [ 41.918958] [] ? trace_event_raw_event_xs_tcp_data_ready+0xd4/0xd4 [ 41.920430] [] schedule+0x88/0x9d [ 41.921336] [] rpc_wait_bit_killable+0x24/0xab [ 41.922395] [] __wait_on_bit+0x4c/0x7e [ 41.923370] [] out_of_line_wait_on_bit+0x72/0x7d [ 41.924457] [] ? trace_event_raw_event_xs_tcp_data_ready+0xd4/0xd4 [ 41.925908] [] ? autoremove_wake_function+0x3a/0x3a [ 41.927032] [] ? call_transmit_status+0xa4/0xa4 [ 41.928103] [] __rpc_execute+0x19b/0x41b [ 41.929094] [] ? wake_up_bit+0x25/0x2a [ 41.930075] [] rpc_execute+0xfe/0x166 [ 41.931034] [] rpc_run_task+0x121/0x12d [ 41.932008] [] nfs4_call_sync_sequence+0x55/0x73 [ 41.933095] [] nfs4_call_sync+0x31/0x33 [ 41.934076] [] _nfs4_proc_getattr+0xb6/0xc8 [ 41.935104] [] ? dump_stack+0xb3/0xb8 [ 41.936061] [] nfs4_proc_getattr+0x49/0x172 [ 41.937084] [] ? nfs4_proc_getattr+0x49/0x172 [ 41.938128] [] ? nfs_alloc_fattr+0x20/0x37 [ 41.939135] [] __nfs_revalidate_inode+0x127/0x2eb [ 41.940244] [] nfs_do_access+0x3ec/0x46f [ 41.941232] [] ? generic_lookup_cred+0x1a/0x1c [ 41.942289] [] ? rpcauth_lookupcred+0x61/0x6a [ 41.943335] [] nfs_permission+0xbe/0x188 [ 41.944325] [] __inode_permission+0x3e/0xa0 [ 41.945351] [] inode_permission+0x3f/0x41 [ 41.946348] [] link_path_walk+0x47/0x478 [ 41.947333] [] ? path_init+0x11d/0x2a4 [ 41.948297] [] path_openat+0x2ba/0x750 [ 41.949280] [] ? kvm_clock_read+0x25/0x2e [ 41.950274] [] do_filp_open+0x4d/0xa3 [ 41.951195] [] ? sched_clock_cpu+0x15/0xae [ 41.952229] [] ? _raw_spin_unlock+0x27/0x31 [ 41.953253] [] ? __alloc_fd+0x1b2/0x1c4 [ 41.954184] [] do_sys_open+0x72/0x102 [ 41.955120] [] ? do_sys_open+0x72/0x102 [ 41.956103] [] SyS_open+0x1e/0x20 [ 41.957004] [] entry_SYSCALL_64_fastpath+0x1f/0xbd [ 41.958075] [] ? trace_hardirqs_off_caller+0x3f/0xab [ 41.959358] BUG: scheduling while atomic: wrapper/875/0x7fffffff [ 41.960456] INFO: lockdep is turned off. [ 41.961248] Modules linked in: [ 41.961950] CPU: 1 PID: 875 Comm: wrapper Tainted: G W 4.7.0-rc3-00002-g5aaca3e #1 [ 41.963473] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1 04/01/2014 [ 41.965132] 0000000000000000 ffff88007d2838a8 ffffffff817767c7 ffff88007d3c9100 [ 41.966819] 0000000000000000 ffff88007d2838c0 ffffffff81105441 ffff88009f5d8fc0 [ 41.968549] ffff88007d283920 ffffffff82ecb27d ffff88007d2838f0 00ffffff81121949 [ 41.970276] Call Trace: [ 41.970824] [] dump_stack+0x82/0xb8 [ 41.971744] [] __schedule_bug+0x61/0x70 [ 41.985444] [] __schedule+0x6b/0x76f [ 41.986341] [] ? trace_event_raw_event_xs_tcp_data_ready+0xd4/0xd4 [ 41.987717] [] schedule+0x88/0x9d [ 41.988600] [] rpc_wait_bit_killable+0x24/0xab [ 41.989626] [] __wait_on_bit+0x4c/0x7e [ 41.990864] [] out_of_line_wait_on_bit+0x72/0x7d [ 41.992519] [] ? trace_event_raw_event_xs_tcp_data_ready+0xd4/0xd4 [ 41.994727] [] ? autoremove_wake_function+0x3a/0x3a [ 41.996442] [] __rpc_wait_for_completion_task+0x2d/0x2f [ 41.998271] [] rpc_wait_for_completion_task+0xb/0xd [ 41.999795] [] nfs4_run_open_task+0x108/0x135 [ 42.000860] [] nfs4_do_open+0x1f5/0x6e7 [ 42.001974] [] nfs4_atomic_open+0xe/0x1c [ 42.002940] [] nfs_atomic_open+0x1ce/0x33c [ 42.003945] [] lookup_open+0x2b5/0x4fb [ 42.004904] [] ? update_fast_ctr+0x1e/0x3e [ 42.005952] [] ? update_fast_ctr+0x1e/0x3e [ 42.006936] [] path_openat+0x3bc/0x750 [ 42.007987] [] ? kvm_clock_read+0x25/0x2e [ 42.008979] [] do_filp_open+0x4d/0xa3 [ 42.009894] [] ? sched_clock_cpu+0x15/0xae [ 42.010871] [] ? _raw_spin_unlock+0x27/0x31 [ 42.011840] [] ? __alloc_fd+0x1b2/0x1c4 [ 42.012799] [] do_sys_open+0x72/0x102 [ 42.013709] [] ? do_sys_open+0x72/0x102 [ 42.014644] [] SyS_open+0x1e/0x20 [ 42.015936] [] entry_SYSCALL_64_fastpath+0x1f/0xbd [ 42.017596] [] ? trace_hardirqs_off_caller+0x3f/0xab [ 42.028359] BUG: scheduling while atomic: wrapper/879/0x00000003 [ 42.029615] INFO: lockdep is turned off. [ 42.030374] Modules linked in: [ 42.031067] CPU: 0 PID: 879 Comm: wrapper Tainted: G W 4.7.0-rc3-00002-g5aaca3e #1 [ 42.032615] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1 04/01/2014 [ 42.034176] 0000000000000000 ffff88007cb8b7d8 ffffffff817767c7 ffff88007ba24dc0 [ 42.035844] 0000000000000000 ffff88007cb8b7f0 ffffffff81105441 ffff88009f3d8fc0 [ 42.037569] ffff88007cb8b850 ffffffff82ecb27d ffff88007cb8b820 00ffffff81121949 [ 42.039241] Call Trace: [ 42.039794] [] dump_stack+0x82/0xb8 [ 42.040724] [] __schedule_bug+0x61/0x70 [ 42.041691] [] __schedule+0x6b/0x76f [ 42.042640] [] ? trace_event_raw_event_xs_tcp_data_ready+0xd4/0xd4 [ 42.044086] [] schedule+0x88/0x9d [ 42.045000] [] rpc_wait_bit_killable+0x24/0xab [ 42.046054] [] __wait_on_bit+0x4c/0x7e [ 42.047017] [] out_of_line_wait_on_bit+0x72/0x7d [ 42.048113] [] ? trace_event_raw_event_xs_tcp_data_ready+0xd4/0xd4 [ 42.049574] [] ? autoremove_wake_function+0x3a/0x3a [ 42.050681] [] ? call_transmit_status+0xa4/0xa4 [ 42.051754] [] __rpc_execute+0x19b/0x41b [ 42.052766] [] ? wake_up_bit+0x25/0x2a [ 42.053726] [] rpc_execute+0xfe/0x166 FYI, raw QEMU command line is: qemu-system-x86_64 -enable-kvm -cpu host -kernel /pkg/linux/x86_64-allyesdebian/gcc-6/5aaca3e48a8af4a0dc5f194db9d29bb970dd445e/vmlinuz-4.7.0-rc3-00002-g5aaca3e -append 'root=/dev/ram0 user=lkp job=/lkp/scheduled/vm-lkp-wsx03-2G-9/bisect_boot-1-debian-x86_64-2015-02-07.cgz-x86_64-allyesdebian-5aaca3e48a8af4a0dc5f194db9d29bb970dd445e-20160615-56778-vqa2gx-0.yaml~ ARCH=x86_64 kconfig=x86_64-allyesdebian branch=linux-devel/devel-catchup-201606150345 commit=5aaca3e48a8af4a0dc5f194db9d29bb970dd445e BOOT_IMAGE=/pkg/linux/x86_64-allyesdebian/gcc-6/5aaca3e48a8af4a0dc5f194db9d29bb970dd445e/vmlinuz-4.7.0-rc3-00002-g5aaca3e max_uptime=600 RESULT_ROOT=/result/boot/1/vm-lkp-wsx03-2G/debian-x86_64-2015-02-07.cgz/x86_64-allyesdebian/gcc-6/5aaca3e48a8af4a0dc5f194db9d29bb970dd445e/0 LKP_SERVER=inn earlyprintk=ttyS0,115200 systemd.log_level=err debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100 panic=-1 softlockup_panic=1 nmi_watchdog=panic oops=panic load_ramdisk=2 prompt_ramdisk=0 console=ttyS0,115200 console=tty0 vga=normal rw ip=::::vm-lkp-wsx03-2G-9::dhcp' -initrd /fs/sdc1/initrd-vm-lkp-wsx03-2G-9 -m 2560 -smp 2 -device e1000,netdev=net0 -netdev user,id=net0,hostfwd=tcp::23628-:22 -boot order=nc -no-reboot -watchdog i6300esb -rtc base=localtime -drive file=/fs/sdc1/disk0-vm-lkp-wsx03-2G-9,media=disk,if=virtio -drive file=/fs/sdc1/disk1-vm-lkp-wsx03-2G-9,media=disk,if=virtio -pidfile /dev/shm/kboot/pid-vm-lkp-wsx03-2G-9 -serial file:/dev/shm/kboot/serial-vm-lkp-wsx03-2G-9 -daemonize -display none -monitor null Thanks, Kernel Test Robot