Re: [arch/x86][tsc_sync] The VM is stuck when we set a hot-plugged vCPU online.

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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



[Index of Archives]     [KVM ARM]     [KVM ia64]     [KVM ppc]     [Virtualization Tools]     [Spice Development]     [Libvirt]     [Libvirt Users]     [Linux USB Devel]     [Linux Audio Users]     [Yosemite Questions]     [Linux Kernel]     [Linux SCSI]     [XFree86]

  Powered by Linux