Re: kvm 4.10 merge grumbles wrt suspicious RCU usage , might_sleep() and sched: do not call blocking ops when !TASK_RUNNING

[Paolo Bonzini]

On 15/12/2016 04:36, Mike Galbraith wrote:
> Grumpy master.today, w. tune for maximum bloat PREEMPT config.

I'll queue a revert of 0b9f6c4615c993d2b552e0d2bd1ade49b56e5beb.

Paolo

> [  101.898909] ===============================
> [  101.898910] [ INFO: suspicious RCU usage. ]
> [  101.898912] 4.10.0-preempt #1 Tainted: G            E  
> [  101.898913] -------------------------------
> [  101.898914] ./include/linux/kvm_host.h:541 suspicious rcu_dereference_check() usage!
> [  101.898914] other info that might help us debug this:
> [  101.898916] rcu_scheduler_active = 1, debug_locks = 0
> [  101.898917] 2 locks held by qemu-system-x86/4265:
> [  101.898918]  #0:  (&vcpu->mutex){+.+.+.}, at: [<ffffffffa08d289c>] vcpu_load+0x1c/0x80 [kvm]
> [  101.898941]  #1:  (&rq->lock){-.-.-.}, at: [<ffffffff8172fcc0>] __schedule+0xb0/0xaa0
> [  101.898945] stack backtrace:
> [  101.898946] CPU: 2 PID: 4265 Comm: qemu-system-x86 Tainted: G            E   4.10.0-preempt #1
> [  101.898947] Hardware name: MEDION MS-7848/MS-7848, BIOS M7848W08.20C 09/23/2013
> [  101.898948] Call Trace:
> [  101.898952]  dump_stack+0x85/0xc9
> [  101.898954]  lockdep_rcu_suspicious+0xe7/0x120
> [  101.898960]  kvm_write_guest_offset_cached+0x145/0x180 [kvm]
> [  101.898969]  kvm_arch_vcpu_put+0x3e/0x70 [kvm]
> [  101.898974]  kvm_sched_out+0x2e/0x30 [kvm]
> [  101.898976]  __schedule+0x398/0xaa0
> [  101.898977]  preempt_schedule_common+0x34/0x47
> [  101.898978]  preempt_schedule+0x26/0x30
> [  101.898980]  ___preempt_schedule+0x16/0x18
> [  101.898988]  vcpu_enter_guest+0x1598/0x1690 [kvm]
> [  101.898995]  ? vcpu_enter_guest+0xaed/0x1690 [kvm]
> [  101.899003]  ? kvm_arch_vcpu_ioctl_run+0xb8/0x500 [kvm]
> [  101.899010]  ? kvm_arch_can_inject_async_page_present+0x43/0x50 [kvm]
> [  101.899017]  ? kvm_check_async_pf_completion+0x30/0x110 [kvm]
> [  101.899024]  kvm_arch_vcpu_ioctl_run+0xfe/0x500 [kvm]
> [  101.899030]  ? kvm_arch_vcpu_ioctl_run+0xb8/0x500 [kvm]
> [  101.899036]  kvm_vcpu_ioctl+0x370/0x760 [kvm]
> [  101.899038]  ? __fget+0xf8/0x210
> [  101.899039]  ? __lock_is_held+0x49/0x70
> [  101.899041]  do_vfs_ioctl+0x96/0x710
> [  101.899042]  ? __fget+0x115/0x210
> [  101.899044]  ? __fget+0x5/0x210
> [  101.899045]  SyS_ioctl+0x79/0x90
> [  101.899047]  entry_SYSCALL_64_fastpath+0x23/0xc6
> [  101.899048] RIP: 0033:0x7fd3680efbc7
> [  101.899049] RSP: 002b:00007fd352ca69b8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> [  101.899051] RAX: ffffffffffffffda RBX: 000055b9fd0c2450 RCX: 00007fd3680efbc7
> [  101.899051] RDX: 0000000000000000 RSI: 000000000000ae80 RDI: 0000000000000011
> [  101.899052] RBP: 00007fd36eb5f000 R08: 0000000000000000 R09: 000000000000ffff
> [  101.899053] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
> [  101.899054] R13: 0000000000000004 R14: 0000000000000001 R15: 000055b9fbbf42a0
> [  101.899056] BUG: sleeping function called from invalid context at ./arch/x86/include/asm/uaccess_64.h:181
> [  101.899057] in_atomic(): 1, irqs_disabled(): 1, pid: 4265, name: qemu-system-x86
> [  101.899057] INFO: lockdep is turned off.
> [  101.899058] irq event stamp: 7522870
> [  101.899065] hardirqs last  enabled at (7522869): [<ffffffffa08eccd7>] vcpu_enter_guest+0xa97/0x1690 [kvm]
> [  101.899067] hardirqs last disabled at (7522870): [<ffffffff8172fcac>] __schedule+0x9c/0xaa0
> [  101.899069] softirqs last  enabled at (7522868): [<ffffffff8173c17a>] __do_softirq+0x1ea/0x4c6
> [  101.899071] softirqs last disabled at (7522857): [<ffffffff81084245>] irq_exit+0xd5/0xe0
> [  101.899071] Preemption disabled at:
> [  101.899072] [<ffffffff81730963>] preempt_schedule_common+0x2a/0x47
> [  101.899074] CPU: 2 PID: 4265 Comm: qemu-system-x86 Tainted: G            E   4.10.0-preempt #1
> [  101.899075] Hardware name: MEDION MS-7848/MS-7848, BIOS M7848W08.20C 09/23/2013
> [  101.899075] Call Trace:
> [  101.899077]  dump_stack+0x85/0xc9
> [  101.899078]  ___might_sleep+0x17b/0x270
> [  101.899080]  __might_sleep+0x4a/0x90
> [  101.899082]  __might_fault+0x39/0xa0
> [  101.899088]  kvm_write_guest_offset_cached+0xa6/0x180 [kvm]
> [  101.899095]  kvm_arch_vcpu_put+0x3e/0x70 [kvm]
> [  101.899101]  kvm_sched_out+0x2e/0x30 [kvm]
> [  101.899102]  __schedule+0x398/0xaa0
> [  101.899103]  preempt_schedule_common+0x34/0x47
> [  101.899104]  preempt_schedule+0x26/0x30
> [  101.899106]  ___preempt_schedule+0x16/0x18
> [  101.899112]  vcpu_enter_guest+0x1598/0x1690 [kvm]
> [  101.899119]  ? vcpu_enter_guest+0xaed/0x1690 [kvm]
> [  101.899125]  ? kvm_arch_vcpu_ioctl_run+0xb8/0x500 [kvm]
> [  101.899132]  ? kvm_arch_can_inject_async_page_present+0x43/0x50 [kvm]
> [  101.899139]  ? kvm_check_async_pf_completion+0x30/0x110 [kvm]
> [  101.899145]  kvm_arch_vcpu_ioctl_run+0xfe/0x500 [kvm]
> [  101.899151]  ? kvm_arch_vcpu_ioctl_run+0xb8/0x500 [kvm]
> [  101.899157]  kvm_vcpu_ioctl+0x370/0x760 [kvm]
> [  101.899159]  ? __fget+0xf8/0x210
> [  101.899160]  ? __lock_is_held+0x49/0x70
> [  101.899161]  do_vfs_ioctl+0x96/0x710
> [  101.899163]  ? __fget+0x115/0x210
> [  101.899164]  ? __fget+0x5/0x210
> [  101.899165]  SyS_ioctl+0x79/0x90
> [  101.899167]  entry_SYSCALL_64_fastpath+0x23/0xc6
> [  101.899168] RIP: 0033:0x7fd3680efbc7
> [  101.899169] RSP: 002b:00007fd352ca69b8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> [  101.899170] RAX: ffffffffffffffda RBX: 000055b9fd0c2450 RCX: 00007fd3680efbc7
> [  101.899171] RDX: 0000000000000000 RSI: 000000000000ae80 RDI: 0000000000000011
> [  101.899172] RBP: 00007fd36eb5f000 R08: 0000000000000000 R09: 000000000000ffff
> [  101.899172] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
> [  101.899173] R13: 0000000000000004 R14: 0000000000000001 R15: 000055b9fbbf42a0
> [  101.959132] ------------[ cut here ]------------
> [  101.959140] WARNING: CPU: 2 PID: 4265 at kernel/sched/core.c:7840 __might_sleep+0x80/0x90
> [  101.959144] do not call blocking ops when !TASK_RUNNING; state=1 set at [<ffffffff810d0ed0>] prepare_to_swait+0x40/0xd0
> [  101.959146] Modules linked in: tun(E) ebtable_filter(E) ebtables(E) fuse(E) nf_log_ipv6(E) xt_pkttype(E) xt_physdev(E) br_netfilter(E) nf_log_ipv4(E) nf_log_common(E) xt_LOG(E) xt_limit(E) bridge(E) stp(E) llc(E) iscsi_ibft(E) iscsi_boot_sysfs(E) ip6t_REJECT(E) xt_tcpudp(E) nf_conntrack_ipv6(E) nf_defrag_ipv6(E) ip6table_raw(E) ipt_REJECT(E) iptable_raw(E) xt_CT(E) iptable_filter(E) ip6table_mangle(E) nf_conntrack_netbios_ns(E) nf_conntrack_broadcast(E) nf_conntrack_ipv4(E) nf_defrag_ipv4(E) ip_tables(E) xt_conntrack(E) nf_conntrack(E) ip6table_filter(E) ip6_tables(E) x_tables(E) intel_rapl(E) nls_iso8859_1(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) nls_cp437(E) coretemp(E) kvm_intel(E) nfsd(E) kvm(E) auth_rpcgss(E) nfs_acl(E) irqbypass(E) snd_hda_codec_realtek(E) lockd(E) grace(E) 
>  crct10dif_pclmul(E)
> [  101.959186]  crc32_pclmul(E) crc32c_intel(E) ghash_clmulni_intel(E) pl2303(E) usbserial(E) snd_hda_codec_hdmi(E) snd_hda_codec_generic(E) sunrpc(E) pcbc(E) snd_hda_intel(E) snd_hda_codec(E) snd_hda_core(E) snd_hwdep(E) aesni_intel(E) aes_x86_64(E) snd_pcm(E) i2c_i801(E) crypto_simd(E) snd_timer(E) snd(E) usblp(E) glue_helper(E) joydev(E) iTCO_wdt(E) iTCO_vendor_support(E) mei_me(E) lpc_ich(E) mei(E) mfd_core(E) shpchp(E) i2c_smbus(E) cryptd(E) intel_smartconnect(E) serio_raw(E) soundcore(E) battery(E) thermal(E) pcspkr(E) tpm_infineon(E) fan(E) efivarfs(E) hid_logitech_hidpp(E) hid_logitech_dj(E) hid_generic(E) usbhid(E) ehci_pci(E) nouveau(E) ehci_hcd(E) mxm_wmi(E) wmi(E) i2c_algo_bit(E) drm_kms_helper(E) syscopyarea(E) sysfillrect(E) ahci(E) xhci_pci(E) sysimgblt(E) r8169(E) fb_sys_fo
>  ps(E) mii(E)
> [  101.959230]  libahci(E) xhci_hcd(E) ttm(E) libata(E) usbcore(E) drm(E) fjes(E) video(E) button(E) af_packet(E) sd_mod(E) vfat(E) fat(E) ext4(E) crc16(E) jbd2(E) mbcache(E) dm_mod(E) loop(E) sg(E) scsi_mod(E) autofs4(E)
> [  101.959248] CPU: 2 PID: 4265 Comm: qemu-system-x86 Tainted: G        W   E   4.10.0-preempt #1
> [  101.959249] Hardware name: MEDION MS-7848/MS-7848, BIOS M7848W08.20C 09/23/2013
> [  101.959251] Call Trace:
> [  101.959255]  dump_stack+0x85/0xc9
> [  101.959258]  __warn+0xd1/0xf0
> [  101.959261]  warn_slowpath_fmt+0x4f/0x60
> [  101.959263]  ? prepare_to_swait+0x40/0xd0
> [  101.959265]  ? prepare_to_swait+0x40/0xd0
> [  101.959267]  __might_sleep+0x80/0x90
> [  101.959269]  __might_fault+0x39/0xa0
> [  101.959292]  kvm_write_guest_offset_cached+0xa6/0x180 [kvm]
> [  101.959304]  kvm_arch_vcpu_put+0x3e/0x70 [kvm]
> [  101.959312]  kvm_sched_out+0x2e/0x30 [kvm]
> [  101.959315]  __schedule+0x398/0xaa0
> [  101.959327]  ? kvm_apic_has_interrupt+0x23/0xc0 [kvm]
> [  101.959329]  schedule+0x40/0x90
> [  101.959338]  kvm_vcpu_block+0x7b/0x520 [kvm]
> [  101.959349]  kvm_arch_vcpu_ioctl_run+0x1d0/0x500 [kvm]
> [  101.959359]  ? kvm_arch_vcpu_ioctl_run+0xb8/0x500 [kvm]
> [  101.959368]  kvm_vcpu_ioctl+0x370/0x760 [kvm]
> [  101.959370]  ? __fget+0x5/0x210
> [  101.959373]  do_vfs_ioctl+0x96/0x710
> [  101.959375]  ? __fget+0x115/0x210
> [  101.959376]  ? __fget+0x5/0x210
> [  101.959379]  SyS_ioctl+0x79/0x90
> [  101.959381]  entry_SYSCALL_64_fastpath+0x23/0xc6
> [  101.959383] RIP: 0033:0x7fd3680efbc7
> [  101.959384] RSP: 002b:00007fd352ca69b8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> [  101.959386] RAX: ffffffffffffffda RBX: 000055b9fd0c2450 RCX: 00007fd3680efbc7
> [  101.959388] RDX: 0000000000000000 RSI: 000000000000ae80 RDI: 0000000000000011
> [  101.959389] RBP: 00007fd36eb5f000 R08: 0000000000000000 R09: 00000000000000ff
> [  101.959390] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
> [  101.959392] R13: 0000000000000001 R14: 0000000000000001 R15: 000055b9fbbf42a0
> [  101.959394] ---[ end trace 2152da2d0234c6fc ]---
> ...
>