All of lore.kernel.org
 help / color / mirror / Atom feed
* [Bug 209867] New: CPU soft lockup/stall with nested KVM and SMP
@ 2020-10-26 12:13 bugzilla-daemon
  2020-10-26 13:10 ` [Bug 209867] " bugzilla-daemon
                   ` (11 more replies)
  0 siblings, 12 replies; 13+ messages in thread
From: bugzilla-daemon @ 2020-10-26 12:13 UTC (permalink / raw)
  To: kvm

https://bugzilla.kernel.org/show_bug.cgi?id=209867

            Bug ID: 209867
           Summary: CPU soft lockup/stall with nested KVM and SMP
           Product: Virtualization
           Version: unspecified
    Kernel Version: 5.9.1-arch1-1
          Hardware: All
                OS: Linux
              Tree: Mainline
            Status: NEW
          Severity: high
          Priority: P1
         Component: kvm
          Assignee: virtualization_kvm@kernel-bugs.osdl.org
          Reporter: frantisek@sumsal.cz
        Regression: No

Hello,

During my systemd CI adventures I've encountered an issue with kernel 5.9.x
where the boot freezes at completely random moments because of a CPU soft
lockup. From my testing it seems to be reproducible with nested KVM & SMP > 1
(it does happen with SMP == 1 as well, but not always) - see[0].

Reproducer is quite straightforward - enable nested KVM on the host, create a
VM, and create a nested KVM VM in that VM. During my testing I used Vagrant[1]
(with libvirt backend) for the outer VM, and an image generated by mkosi[2] for
the inner VM. Both VMs run the same kernel version.

Hosts:
 * several AMD & Intel servers with RHEL 8.2 (4.18.0-193.19.1.el8_2)
 * AMD desktop with Fedora 32 (5.6.2-300.fc32.x86_64)

The behavior was consistent on all hosts.

Desktop results:
# qemu-system-x86_64 -net none -smp 2 -m 512 -nographic -machine accel=kvm
-enable-kvm -cpu host -kernel /boot/vmlinuz-linux -initrd
/boot/initramfs-linux.img -append 'debug rw console=ttyS0 root=/dev/sda1'
-drive format=raw,file=image.raw
...
[    4.602193] random: dbus-daemon: uninitialized urandom read (12 bytes read)
[    5.538763] random: crng init done
[   28.635398] watchdog: BUG: soft lockup - CPU#2 stuck for 22s! [systemd:1]
[   28.638215] Modules linked in: drm agpgart ip_tables x_tables ext4
crc32c_generic crc16 mbcache jbd2 sr_mod cdrom ata_generic pata_acpi
crc32_pclmul crc32c_intel serio_raw atkbd libps2 aesni_intel glue_helper
crypto_simd cryptd ata_piix floppy i8042 serio
[   28.642668] CPU: 2 PID: 1 Comm: systemd Not tainted 5.9.1-arch1-1 #1
[   28.648865] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
ArchLinux 1.14.0-1 04/01/2014
[   28.648865] RIP: 0010:smp_call_function_many_cond+0x2a3/0x2f0
[   28.655420] Code: c3 0d 3d 00 3b 05 61 0a 83 01 89 c7 0f 83 f4 fd ff ff 48
63 c7 49 8b 55 00 48 03 14 c5 00 19 81 8b 8b 42 08 a8 01 74 09 f3 90 <8b> 42 08
a8 01 75 f7 eb c9 48 c7 c2 60 45 d7 8b 48 89 ee 44 89 ff
[   28.655420] RSP: 0018:ffffacf800013b18 EFLAGS: 00000202
[   28.668750] RAX: 0000000000000011 RBX: 0000000000000000 RCX:
0000000000000000
[   28.668750] RDX: ffff91c39da333e0 RSI: 0000000000000000 RDI:
0000000000000000
[   28.668750] RBP: 0000000000000003 R08: 0000000000000000 R09:
0000000000000000
[   28.668750] R10: 0000000000000140 R11: 0000000000000002 R12:
0000000000000000
[   28.682088] R13: ffff91c39db2d340 R14: 0000000000000140 R15:
ffff91c39db2d348
[   28.682088] FS:  00007fd4cbc04340(0000) GS:ffff91c39db00000(0000)
knlGS:0000000000000000
[   28.682088] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   28.682088] CR2: 00007fd4cc9e8520 CR3: 000000001fa8e000 CR4:
0000000000350ee0
[   28.695419] Call Trace:
[   28.695419]  ? __flush_tlb_all+0x30/0x30
[   28.695419]  ? __flush_tlb_all+0x30/0x30
[   28.695419]  on_each_cpu+0x43/0xb0
[   28.695419]  __purge_vmap_area_lazy+0x5d/0x670
[   28.695419]  ? do_jit+0xbdf/0x1cd0
[   28.708758]  ? purge_fragmented_blocks+0xbd/0x1a0
[   28.708758]  _vm_unmap_aliases.part.0+0x110/0x140
[   28.708758]  change_page_attr_set_clr+0xb9/0x1c0
[   28.708758]  set_memory_ro+0x26/0x30
[   28.708758]  bpf_int_jit_compile+0x407/0x42b
[   28.708758]  bpf_prog_select_runtime+0x101/0x1a0
[   28.708758]  bpf_prog_load+0x49a/0x8e0
[   28.722089]  __do_sys_bpf+0x2dd/0x1ea0
[   28.722089]  do_syscall_64+0x33/0x40
[   28.722089]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   28.722089] RIP: 0033:0x7fd4cc91ed5d
[   28.722089] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89
f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01
f0 ff ff 73 01 c3 48 8b 0d e3 70 0c 00 f7 d8 64 89 01 48
[   28.735427] RSP: 002b:00007ffe18ec4218 EFLAGS: 00000246 ORIG_RAX:
0000000000000141
[   28.735427] RAX: ffffffffffffffda RBX: 000055cea99a9ab0 RCX:
00007fd4cc91ed5d
[   28.735427] RDX: 0000000000000070 RSI: 00007ffe18ec4220 RDI:
0000000000000005
[   28.748752] RBP: 0000000000000000 R08: 0070756f7267632f R09:
0000000800000008
[   28.748752] R10: 0000000000000000 R11: 0000000000000246 R12:
000055cea999fb20
[   28.748752] R13: 0000000000000001 R14: 0000000000000001 R15:
000055cea99836a0
[   56.635397] watchdog: BUG: soft lockup - CPU#2 stuck for 22s! [systemd:1]
[   56.638254] Modules linked in: drm agpgart ip_tables x_tables ext4
crc32c_generic crc16 mbcache jbd2 sr_mod cdrom ata_generic pata_acpi
crc32_pclmul crc32c_intel serio_raw atkbd libps2 aesni_intel glue_helper
crypto_simd cryptd ata_piix floppy i8042 serio
[   56.642094] CPU: 2 PID: 1 Comm: systemd Tainted: G             L   
5.9.1-arch1-1 #1
[   56.648798] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
ArchLinux 1.14.0-1 04/01/2014
[   56.648798] RIP: 0010:smp_call_function_many_cond+0x2a3/0x2f0
[   56.655444] Code: c3 0d 3d 00 3b 05 61 0a 83 01 89 c7 0f 83 f4 fd ff ff 48
63 c7 49 8b 55 00 48 03 14 c5 00 19 81 8b 8b 42 08 a8 01 74 09 f3 90 <8b> 42 08
a8 01 75 f7 eb c9 48 c7 c2 60 45 d7 8b 48 89 ee 44 89 ff
[   56.655444] RSP: 0018:ffffacf800013b18 EFLAGS: 00000202
[   56.655444] RAX: 0000000000000011 RBX: 0000000000000000 RCX:
0000000000000000
[   56.668871] RDX: ffff91c39da333e0 RSI: 0000000000000000 RDI:
0000000000000000
[   56.668871] RBP: 0000000000000003 R08: 0000000000000000 R09:
0000000000000000
[   56.668871] R10: 0000000000000140 R11: 0000000000000002 R12:
0000000000000000
[   56.668871] R13: ffff91c39db2d340 R14: 0000000000000140 R15:
ffff91c39db2d348
[   56.668871] FS:  00007fd4cbc04340(0000) GS:ffff91c39db00000(0000)
knlGS:0000000000000000
[   56.682244] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   56.682244] CR2: 00007fd4cc9e8520 CR3: 000000001fa8e000 CR4:
0000000000350ee0
[   56.682244] Call Trace:
[   56.682244]  ? __flush_tlb_all+0x30/0x30
[   56.682244]  ? __flush_tlb_all+0x30/0x30
[   56.682244]  on_each_cpu+0x43/0xb0
[   56.682244]  __purge_vmap_area_lazy+0x5d/0x670
[   56.695525]  ? do_jit+0xbdf/0x1cd0
[   56.695525]  ? purge_fragmented_blocks+0xbd/0x1a0
[   56.695525]  _vm_unmap_aliases.part.0+0x110/0x140
[   56.695525]  change_page_attr_set_clr+0xb9/0x1c0
[   56.695525]  set_memory_ro+0x26/0x30
[   56.695525]  bpf_int_jit_compile+0x407/0x42b
[   56.695525]  bpf_prog_select_runtime+0x101/0x1a0
[   56.708855]  bpf_prog_load+0x49a/0x8e0
[   56.708855]  __do_sys_bpf+0x2dd/0x1ea0
[   56.708855]  do_syscall_64+0x33/0x40
[   56.708855]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   56.708855] RIP: 0033:0x7fd4cc91ed5d
[   56.708855] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89
f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01
f0 ff ff 73 01 c3 48 8b 0d e3 70 0c 00 f7 d8 64 89 01 48
[   56.722223] RSP: 002b:00007ffe18ec4218 EFLAGS: 00000246 ORIG_RAX:
0000000000000141
[   56.722223] RAX: ffffffffffffffda RBX: 000055cea99a9ab0 RCX:
00007fd4cc91ed5d
[   56.722223] RDX: 0000000000000070 RSI: 00007ffe18ec4220 RDI:
0000000000000005
[   56.722223] RBP: 0000000000000000 R08: 0070756f7267632f R09:
0000000800000008
[   56.735526] R10: 0000000000000000 R11: 0000000000000246 R12:
000055cea999fb20
[   56.735526] R13: 0000000000000001 R14: 0000000000000001 R15:
000055cea99836a0
...
[   64.578716] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[   64.578716]  (detected by 2, t=18002 jiffies, g=-207, q=1973)
[   64.578716] rcu: All QSes seen, last rcu_preempt kthread activity 18002
(4294896513-4294878511), jiffies_till_next_fqs=2, root ->qsmask 0x0
[   64.578716] rcu: rcu_preempt kthread starved for 18002 jiffies! g-207 f0x2
RCU_GP_WAIT_FQS(5) ->state=0x200 ->cpu=0
[   64.588745] rcu:     Unless rcu_preempt kthread gets sufficient CPU time,
OOM is now expected behavior.
[   64.588745] rcu: RCU grace-period kthread stack dump:
[   64.588745] task:rcu_preempt     state:R stack:    0 pid:   11 ppid:     2
flags:0x00004000
[   64.602163] Call Trace:
[   64.602163]  __schedule+0x292/0x830
[   64.602163]  schedule+0x46/0xf0
[   64.602163]  schedule_timeout+0x99/0x170
[   64.602163]  ? __next_timer_interrupt+0x100/0x100
[   64.602163]  rcu_gp_kthread+0x5a4/0xbe0
[   64.602163]  ? __note_gp_changes+0x190/0x190
[   64.602163]  kthread+0x142/0x160
[   64.602163]  ? __kthread_bind_mask+0x60/0x60
[   64.615482]  ret_from_fork+0x22/0x30
...

Server results:
...
[   32.051205] watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [swapper/0:1]
[   32.051237] Modules linked in:
[   32.051237] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.9.1-arch1-1 #1
[   32.051237] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
ArchLinux 1.14.0-1 04/01/2014
[   32.051237] RIP: 0010:smp_call_function_many_cond+0x2a3/0x2f0
[   32.051237] Code: c3 0d 3d 00 3b 05 61 0a 83 01 89 c7 0f 83 f4 fd ff ff 48
63 c7 49 8b 55 00 48 03 14 c5 00 19 41 bb 8b 42 08 a8 01 74 09 f3 90 <8b> 42 08
a8 01 75 f7 eb c9 48 c7 c2 60 45 97 bb 48 89 ee 44 89 ff
[   32.051237] RSP: 0018:ffffa661c0013d98 EFLAGS: 00000202
[   32.051237] RAX: 0000000000000011 RBX: 0000000000000000 RCX:
0000000000000004
[   32.051237] RDX: ffff9e955db320a0 RSI: 0000000000000000 RDI:
0000000000000004
[   32.051237] RBP: 0000000000000007 R08: 0000000000000000 R09:
0000000000000004
[   32.051237] R10: 0000000000000005 R11: 0000000000000005 R12:
0000000000000000
[   32.051237] R13: ffff9e955da2d340 R14: 0000000000000140 R15:
ffff9e955da2d348
[   32.051237] FS:  0000000000000000(0000) GS:ffff9e955da00000(0000)
knlGS:0000000000000000
[   32.051237] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   32.051237] CR2: 0000000000000000 CR3: 000000001840e000 CR4:
00000000000406f0
[   32.051237] Call Trace:
[   32.051237]  ? _raw_spin_unlock+0x16/0x30
[   32.051237]  ? text_poke_loc_init+0x160/0x160
[   32.051237]  ? text_poke_loc_init+0x160/0x160
[   32.051237]  on_each_cpu+0x43/0xb0
[   32.051237]  text_poke_bp_batch+0x1d7/0x200
[   32.051237]  text_poke_finish+0x1b/0x26
[   32.051237]  arch_jump_label_transform_apply+0x16/0x30
[   32.051237]  static_key_slow_inc_cpuslocked+0x7a/0x90
[   32.051237]  static_key_slow_inc+0x16/0x20
[   32.051237]  ? kvm_init_platform+0x16/0x16
[   32.051237]  activate_jump_labels+0x2f/0x32
[   32.051237]  do_one_initcall+0x59/0x234
[   32.051237]  kernel_init_freeable+0x1b0/0x1f5
[   32.051237]  ? rest_init+0xbf/0xbf
[   32.051237]  kernel_init+0xa/0x111
[   32.051237]  ret_from_fork+0x22/0x30
...


Frankly, I'm at wits' end, as I've been noticing similar issues since kernel
5.8.x and still can pinpoint what's going on (again, see [0]), thus my aplogies
if I filed this under a wrong component.

Thank you.


[0]
https://github.com/systemd/systemd-centos-ci/pull/295#issuecomment-682519585
[1]
Vagrant.configure("2") do |config|
  config.vm.box = "generic/arch"
  config.vm.provider :libvirt do |libvirt|
    libvirt.cpus = 4
    libvirt.memory = "2048"
    libvirt.driver = "kvm"
    libvirt.nested = true
    libvirt.cpu_mode = "host-model"
    libvirt.random :model => "random"
  end
end

[2] # mkosi -b -d arch --qemu-headless -t gpt_ext4

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

^ permalink raw reply	[flat|nested] 13+ messages in thread
end of thread, other threads:[~2020-12-23 12:31 UTC | newest]

Thread overview: 13+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-10-26 12:13 [Bug 209867] New: CPU soft lockup/stall with nested KVM and SMP bugzilla-daemon
2020-10-26 13:10 ` [Bug 209867] " bugzilla-daemon
2020-10-26 13:10 ` bugzilla-daemon
2020-10-26 20:05 ` bugzilla-daemon
2020-11-02 16:16 ` bugzilla-daemon
2020-11-02 16:24 ` bugzilla-daemon
2020-11-09 10:59 ` bugzilla-daemon
2020-11-12 10:02 ` bugzilla-daemon
2020-11-21 16:19 ` bugzilla-daemon
2020-11-27 10:21 ` bugzilla-daemon
2020-12-01  8:39 ` bugzilla-daemon
2020-12-04 11:57 ` bugzilla-daemon
2020-12-23 12:31 ` bugzilla-daemon

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.