2018-03-29 15:43 GMT+08:00 Ken <jinjian@xxxxxxxxxx>: > 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? I can't reproduce this when hot-adding vCPUs and the guest/host kernels are both latest kvm/queue. Regards, Wanpeng Li
