Hi,
Recently, we found that when we bring a hot-plugged vCPU online on a
VM of Ubuntu server 17.10 64bit, which is running on the KVM platform,
the VM will be stuck.
The VM's logs were as follows:
[ 97.704114] CPU2 has been hot-added
[ 97.704274] CPU3 has been hot-added
[ 117.464305] smpboot: Booting Node 0 Processor 2 APIC 0x2
[ 117.464502] kvm-clock: cpu 2, msr 4:3ff55081, secondary cpu clock
[ 117.484689] TSC ADJUST compensate: CPU2 observed 249396676850 warp.
Adjust: 249396676850
[ 217.494341] TSC ADJUST compensate: CPU2 observed 172 warp. Adjust:
249396677022
[ 217.494341] INFO: rcu_sched self-detected stall on CPU
[ 217.514378] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 217.514378] 0-...: (1 ticks this GP)
idle=93e/140000000000001/0 softirq=11320/11320 fqs=0
[ 217.514378] (detected by 1, t=25008 jiffies, g=3837, c=3836,
q=4)
[ 217.514378] Sending NMI from CPU 1 to CPUs 0:
[ 217.514378] NMI backtrace for cpu 0
[ 217.514378] CPU: 0 PID: 1762 Comm: bash Not tainted 4.13.0-16-generic
#19-Ubuntu
[ 217.514378] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS rel-1.9.1-0-gb3ef39f-20170718_152359-build9a64a246a225 04/01/2014
[ 217.514378] task: ffff90782caadd00 task.stack: ffffaeab03134000
[ 217.514378] RIP: 0010:io_serial_out+0x1a/0x20
[ 217.514378] RSP: 0018:ffff90783fc03c20 EFLAGS: 00000002
[ 217.514378] RAX: 000000000000005b RBX: ffffffffaa0e4840 RCX:
0000000000000000
[ 217.514378] RDX: 00000000000003f8 RSI: 0000000000000000 RDI:
ffffffffaa0e4840
[ 217.514378] RBP: ffff90783fc03c20 R08: 0000000000000000 R09:
0000000000000223
[ 217.514378] R10: 000000000000003a R11: ffffffffa9f3e1ad R12:
000000000000005b
[ 217.514378] R13: ffffffffa9f3e1da R14: ffffffffa9f3e1a1 R15:
ffffffffaa0e4840
[ 217.514378] FS: 00007f50a0724b80(0000) GS:ffff90783fc00000(0000)
knlGS:0000000000000000
[ 217.514378] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 217.514378] CR2: 00007ffc402cd7d8 CR3: 0000000426079000 CR4:
00000000001406f0
[ 217.514378] Call Trace:
[ 217.514378] <IRQ>
[ 217.514378] serial8250_console_putchar+0x27/0x30
[ 217.514378] ? wait_for_xmitr+0xa0/0xa0
[ 217.514378] uart_console_write+0x48/0x60
[ 217.514378] serial8250_console_write+0xfb/0x280
[ 217.514378] ? msg_print_text+0x80/0x100
[ 217.514378] univ8250_console_write+0x28/0x30
[ 217.514378] console_unlock+0x36c/0x4d0
[ 217.514378] vprintk_emit+0x333/0x3a0
[ 217.514378] vprintk_default+0x29/0x50
[ 217.514378] vprintk_func+0x27/0x60
[ 217.514378] printk+0x52/0x6e
[ 217.514378] rcu_check_callbacks+0x499/0x870
[ 217.514378] ? account_system_index_time+0x63/0x70
[ 217.514378] ? tick_sched_do_timer+0x50/0x50
[ 217.514378] update_process_times+0x2f/0x60
[ 217.514378] tick_sched_handle+0x26/0x70
[ 217.514378] ? tick_sched_do_timer+0x3f/0x50
[ 217.514378] tick_sched_timer+0x39/0x80
[ 217.514378] __hrtimer_run_queues+0xdd/0x220
[ 217.514378] hrtimer_interrupt+0xa0/0x1d0
[ 217.514378] local_apic_timer_interrupt+0x38/0x60
[ 217.514378] smp_apic_timer_interrupt+0x38/0x50
[ 217.514378] apic_timer_interrupt+0x89/0x90
[ 217.514378] RIP: 0010:native_cpu_up+0x3d5/0x920
[ 217.514378] RSP: 0018:ffffaeab03137c50 EFLAGS: 00000246 ORIG_RAX:
ffffffffffffff10
[ 217.514378] RAX: 0000000000000000 RBX: 0000000000000002 RCX:
0000000000000001
[ 217.514378] RDX: 0000000000000000 RSI: ffff90783fc9cd40 RDI:
0000000000000246
[ 217.514378] RBP: ffffaeab03137c90 R08: 0000000000000001 R09:
0000000000000000
[ 217.514378] R10: ffff90782f021a68 R11: 00000000000003ec R12:
0000000000000000
[ 217.514378] R13: 0000000000000002 R14: 0000000000000246 R15:
0000000000000000
[ 217.514378] </IRQ>
[ 217.514378] ? takedown_cpu+0xf0/0xf0
[ 217.514378] bringup_cpu+0x2a/0xe0
[ 217.514378] cpuhp_invoke_callback+0x84/0x3b0
[ 217.514378] ? zswap_cpu_comp_dead+0x60/0x60
[ 217.514378] cpuhp_up_callbacks+0x36/0xc0
[ 217.514378] _cpu_up+0x87/0xd0
[ 217.514378] do_cpu_up+0x8b/0xb0
[ 217.514378] cpu_up+0x13/0x20
[ 217.514378] cpu_subsys_online+0x3d/0x90
[ 217.514378] device_online+0x4a/0x90
[ 217.514378] online_store+0x89/0xa0
[ 217.514378] dev_attr_store+0x18/0x30
[ 217.514378] sysfs_kf_write+0x37/0x40
[ 217.514378] kernfs_fop_write+0x11c/0x1a0
[ 217.514378] __vfs_write+0x18/0x40
[ 217.514378] vfs_write+0xb1/0x1a0
[ 217.514378] SyS_write+0x55/0xc0
[ 217.514378] entry_SYSCALL_64_fastpath+0x1e/0xa9
[ 217.514378] RIP: 0033:0x7f509fe00054
[ 217.514378] RSP: 002b:00007ffc402cd4b8 EFLAGS: 00000246 ORIG_RAX:
0000000000000001
[ 217.514378] RAX: ffffffffffffffda RBX: 0000000000000000 RCX:
00007f509fe00054
[ 217.514378] RDX: 0000000000000002 RSI: 00000000011f7008 RDI:
0000000000000001
[ 217.514378] RBP: 0000000000000001 R08: 000000000136b028 R09:
0000000000000001
[ 217.514378] R10: 0000000000000073 R11: 0000000000000246 R12:
0000000000000000
[ 217.514378] R13: 00007ffc402cda30 R14: 0000000000000000 R15:
0000000000000000
[ 217.514378] Code: 55 48 89 e5 d3 e6 01 f2 ec 0f b6 c0 5d c3 0f 1f 00
0f 1f 44 00 00 0f b6 8f a1 00 00 00 89 d0 8b 57 08 55 48 89 e5 d3 e6 01
f2 ee <5d> c3 0f 1f 40 00 0f 1f 44 00 00 0f b6 87 a2 00 00 00 55 48 c7
[ 217.514378] rcu_sched kthread starved for 25008 jiffies! g3837 c3836
f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
[ 217.514378] rcu_sched S 0 8 2 0x00000000
[ 217.514378] Call Trace:
[ 217.514378] __schedule+0x28b/0x890
[ 217.514378] schedule+0x36/0x80
[ 217.514378] schedule_timeout+0x182/0x350
[ 217.514378] ? call_timer_fn+0x130/0x130
[ 217.514378] rcu_gp_kthread+0x561/0x980
[ 217.514378] ? rcu_gp_kthread+0x561/0x980
[ 217.514378] kthread+0x125/0x140
[ 217.514378] ? rcu_note_context_switch+0x150/0x150
[ 217.514378] ? kthread_create_on_node+0x70/0x70
[ 217.514378] ret_from_fork+0x25/0x30
[ 217.516040] 0-...: (1 ticks this GP)
idle=93e/140000000000001/0 softirq=11320/11320 fqs=1
[ 217.516040] (t=25008 jiffies g=3837 c=3836 q=272)
[ 217.516040] NMI backtrace for cpu 0
[ 217.516040] CPU: 0 PID: 1762 Comm: bash Not tainted 4.13.0-16-generic
#19-Ubuntu
[ 217.516040] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS rel-1.9.1-0-gb3ef39f-20170718_152359-build9a64a246a225 04/01/2014
[ 217.516040] Call Trace:
[ 217.516040] <IRQ>
[ 217.516040] dump_stack+0x63/0x8b
[ 217.516040] nmi_cpu_backtrace+0xca/0xd0
[ 217.516040] ? irq_force_complete_move+0x130/0x130
[ 217.516040] nmi_trigger_cpumask_backtrace+0xe6/0x120
[ 217.516040] arch_trigger_cpumask_backtrace+0x19/0x20
[ 217.516040] rcu_dump_cpu_stacks+0xa8/0xe4
[ 217.516040] rcu_check_callbacks+0x655/0x870
[ 217.516040] ? account_system_index_time+0x63/0x70
[ 217.516040] ? tick_sched_do_timer+0x50/0x50
[ 217.516040] update_process_times+0x2f/0x60
[ 217.516040] tick_sched_handle+0x26/0x70
[ 217.516040] ? tick_sched_do_timer+0x3f/0x50
[ 217.516040] tick_sched_timer+0x39/0x80
[ 217.516040] __hrtimer_run_queues+0xdd/0x220
[ 217.516040] hrtimer_interrupt+0xa0/0x1d0
[ 217.516040] local_apic_timer_interrupt+0x38/0x60
[ 217.516040] smp_apic_timer_interrupt+0x38/0x50
[ 217.516040] apic_timer_interrupt+0x89/0x90
[ 217.516040] RIP: 0010:native_cpu_up+0x3d5/0x920
[ 217.516040] RSP: 0018:ffffaeab03137c50 EFLAGS: 00000246 ORIG_RAX:
ffffffffffffff10
[ 217.516040] RAX: 0000000000000000 RBX: 0000000000000002 RCX:
0000000000000001
[ 217.516040] RDX: 0000000000000000 RSI: ffff90783fc9cd40 RDI:
0000000000000246
[ 217.516040] RBP: ffffaeab03137c90 R08: 0000000000000001 R09:
0000000000000000
[ 217.516040] R10: ffff90782f021a68 R11: 00000000000003ec R12:
0000000000000000
[ 217.516040] R13: 0000000000000002 R14: 0000000000000246 R15:
0000000000000000
[ 217.516040] </IRQ>
[ 217.516040] ? takedown_cpu+0xf0/0xf0
[ 217.516040] bringup_cpu+0x2a/0xe0
[ 217.516040] cpuhp_invoke_callback+0x84/0x3b0
[ 217.516040] ? zswap_cpu_comp_dead+0x60/0x60
[ 217.516040] cpuhp_up_callbacks+0x36/0xc0
[ 217.516040] _cpu_up+0x87/0xd0
[ 217.516040] do_cpu_up+0x8b/0xb0
[ 217.516040] cpu_up+0x13/0x20
[ 217.516040] cpu_subsys_online+0x3d/0x90
[ 217.516040] device_online+0x4a/0x90
[ 217.516040] online_store+0x89/0xa0
[ 217.516040] dev_attr_store+0x18/0x30
[ 217.516040] sysfs_kf_write+0x37/0x40
[ 217.516040] kernfs_fop_write+0x11c/0x1a0
[ 217.516040] __vfs_write+0x18/0x40
[ 217.516040] vfs_write+0xb1/0x1a0
[ 217.516040] SyS_write+0x55/0xc0
[ 217.516040] entry_SYSCALL_64_fastpath+0x1e/0xa9
[ 217.516040] RIP: 0033:0x7f509fe00054
[ 217.516040] RSP: 002b:00007ffc402cd4b8 EFLAGS: 00000246 ORIG_RAX:
0000000000000001
[ 217.516040] RAX: ffffffffffffffda RBX: 0000000000000000 RCX:
00007f509fe00054
[ 217.516040] RDX: 0000000000000002 RSI: 00000000011f7008 RDI:
0000000000000001
[ 217.516040] RBP: 0000000000000001 R08: 000000000136b028 R09:
0000000000000001
[ 217.516040] R10: 0000000000000073 R11: 0000000000000246 R12:
0000000000000000
[ 217.516040] R13: 00007ffc402cda30 R14: 0000000000000000 R15:
0000000000000000
[ 217.516040] clocksource: timekeeping watchdog on CPU0: Marking
clocksource 'tsc' as unstable because the skew is too large:
[ 217.516040] clocksource: 'kvm-clock' wd_now:
332a591e57 wd_last: 1bcddaeb9e mask: ffffffffffffffff
[ 217.516040] clocksource: 'tsc' cs_now:
4597aa80ab cs_last: 45637665bb mask: ffffffffffffffff
[ 217.516040] tsc: Marking TSC unstable due to clocksource watchdog
[ 217.523052] KVM setup async PF for cpu 2
[ 217.523056] kvm-stealtime: cpu 2, msr 43fc8d8c0
[ 217.523061] Will online and init hotplugged CPU: 2
We think that the following patch introduced this problem:
https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git/commit/?id=855615eee9b1989cac8ec5eaae4562db081a239b
And we noticed the following error message in the VM:
[Firmware Bug]: TSC_DEADLINE disabled due to Errata; please update
microcode to version: 0x3a (or later)
So, we also tried testing on a host with higher firmware versions.
The VM was still stuck.
How can this problem be solved?
Best Regards
