[PATCH v2] KVM: X86: Fix softlockup when get the current kvmclock timestamp

[PATCH v2] KVM: X86: Fix softlockup when get the current kvmclock timestamp

[Wanpeng Li]

From: Wanpeng Li <wanpeng.li@hotmail.com>

 watchdog: BUG: soft lockup - CPU#6 stuck for 22s! [qemu-system-x86:10185]
 CPU: 6 PID: 10185 Comm: qemu-system-x86 Tainted: G           OE   4.14.0-rc4+ #4
 RIP: 0010:kvm_get_time_scale+0x4e/0xa0 [kvm]
 Call Trace:
  ? get_kvmclock_ns+0xa3/0x140 [kvm]
  get_time_ref_counter+0x5a/0x80 [kvm]
  kvm_hv_process_stimers+0x120/0x5f0 [kvm]
  ? kvm_hv_process_stimers+0x120/0x5f0 [kvm]
  ? preempt_schedule+0x27/0x30
  ? ___preempt_schedule+0x16/0x18
  kvm_arch_vcpu_ioctl_run+0x4b4/0x1690 [kvm]
  ? kvm_arch_vcpu_load+0x47/0x230 [kvm]
  kvm_vcpu_ioctl+0x33a/0x620 [kvm]
  ? kvm_vcpu_ioctl+0x33a/0x620 [kvm]
  ? kvm_vm_ioctl_check_extension_generic+0x3b/0x40 [kvm]
  ? kvm_dev_ioctl+0x279/0x6c0 [kvm]
  do_vfs_ioctl+0xa1/0x5d0
  ? __fget+0x73/0xa0
  SyS_ioctl+0x79/0x90
  entry_SYSCALL_64_fastpath+0x1e/0xa9

This can be reproduced when running kvm-unit-tests/hyperv_stimer.flat and 
cpu-hotplug stress simultaneously. __this_cpu_read(cpu_tsc_khz) returns 0 
(set in kvmclock_cpu_down_prep()) when the pCPU is unhotplug which results 
in kvm_get_time_scale() gets into an infinite loop.

This patch fixes it by skipping to fill the hv_clock when the pCPU is offline.

Cc: Paolo Bonzini <pbonzini@redhat.com>
Cc: Radim Krčmář <rkrcmar@redhat.com>
Signed-off-by: Wanpeng Li <wanpeng.li@hotmail.com>
---
v1 -> v2:
 * avoid infinite loop

 arch/x86/kvm/x86.c | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
index 03869eb..d2507c6 100644
--- a/arch/x86/kvm/x86.c
+++ b/arch/x86/kvm/x86.c
@@ -1259,6 +1259,9 @@ static void kvm_get_time_scale(uint64_t scaled_hz, uint64_t base_hz,
 	uint64_t tps64;
 	uint32_t tps32;
 
+	if (unlikely(base_hz == 0))
+		return;
+
 	tps64 = base_hz;
 	scaled64 = scaled_hz;
 	while (tps64 > scaled64*2 || tps64 & 0xffffffff00000000ULL) {
-- 
2.7.4

Re: [PATCH v2] KVM: X86: Fix softlockup when get the current kvmclock timestamp

[Radim Krčmář]

2017-11-06 04:17-0800, Wanpeng Li:
> From: Wanpeng Li <wanpeng.li@hotmail.com>
> 
>  watchdog: BUG: soft lockup - CPU#6 stuck for 22s! [qemu-system-x86:10185]
>  CPU: 6 PID: 10185 Comm: qemu-system-x86 Tainted: G           OE   4.14.0-rc4+ #4
>  RIP: 0010:kvm_get_time_scale+0x4e/0xa0 [kvm]
>  Call Trace:
>   ? get_kvmclock_ns+0xa3/0x140 [kvm]
>   get_time_ref_counter+0x5a/0x80 [kvm]
>   kvm_hv_process_stimers+0x120/0x5f0 [kvm]
>   ? kvm_hv_process_stimers+0x120/0x5f0 [kvm]
>   ? preempt_schedule+0x27/0x30
>   ? ___preempt_schedule+0x16/0x18
>   kvm_arch_vcpu_ioctl_run+0x4b4/0x1690 [kvm]
>   ? kvm_arch_vcpu_load+0x47/0x230 [kvm]
>   kvm_vcpu_ioctl+0x33a/0x620 [kvm]
>   ? kvm_vcpu_ioctl+0x33a/0x620 [kvm]
>   ? kvm_vm_ioctl_check_extension_generic+0x3b/0x40 [kvm]
>   ? kvm_dev_ioctl+0x279/0x6c0 [kvm]
>   do_vfs_ioctl+0xa1/0x5d0
>   ? __fget+0x73/0xa0
>   SyS_ioctl+0x79/0x90
>   entry_SYSCALL_64_fastpath+0x1e/0xa9
> 
> This can be reproduced when running kvm-unit-tests/hyperv_stimer.flat and 
> cpu-hotplug stress simultaneously. __this_cpu_read(cpu_tsc_khz) returns 0 
> (set in kvmclock_cpu_down_prep()) when the pCPU is unhotplug which results 
> in kvm_get_time_scale() gets into an infinite loop.
> 
> This patch fixes it by skipping to fill the hv_clock when the pCPU is offline.
> 
> Cc: Paolo Bonzini <pbonzini@redhat.com>
> Cc: Radim Krčmář <rkrcmar@redhat.com>
> Signed-off-by: Wanpeng Li <wanpeng.li@hotmail.com>
> ---
> v1 -> v2:
>  * avoid infinite loop
> 
>  arch/x86/kvm/x86.c | 3 +++
>  1 file changed, 3 insertions(+)
> 
> diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
> index 03869eb..d2507c6 100644
> --- a/arch/x86/kvm/x86.c
> +++ b/arch/x86/kvm/x86.c
> @@ -1259,6 +1259,9 @@ static void kvm_get_time_scale(uint64_t scaled_hz, uint64_t base_hz,
>  	uint64_t tps64;
>  	uint32_t tps32;
>  
> +	if (unlikely(base_hz == 0))
> +		return;

This is a sensible thing to do and will prevent the loop, but KVM will
still have a minor bug:  get_kvmclock_ns() passes uninitialized stack
values with the expectation that kvm_get_time_scale() will set them, but
returning here would result in __pvclock_read_cycles() with random data
and inject timer interrupts early (if not worse).

I think it would be best if kvm_get_time_scale() wasn't executing when
cpu_tsc_khz is 0, by clearing cpu_tsc_khz later and setting earlier;
do you see any problems with moving the CPUHP_AP_X86_KVM_CLK_ONLINE
before CPUHP_AP_ONLINE?

Thanks.

Re: [PATCH v2] KVM: X86: Fix softlockup when get the current kvmclock timestamp

[Wanpeng Li]

2017-11-09 0:26 GMT+08:00 Radim Krčmář <rkrcmar@redhat.com>:
> 2017-11-06 04:17-0800, Wanpeng Li:
>> From: Wanpeng Li <wanpeng.li@hotmail.com>
>>
>>  watchdog: BUG: soft lockup - CPU#6 stuck for 22s! [qemu-system-x86:10185]
>>  CPU: 6 PID: 10185 Comm: qemu-system-x86 Tainted: G           OE   4.14.0-rc4+ #4
>>  RIP: 0010:kvm_get_time_scale+0x4e/0xa0 [kvm]
>>  Call Trace:
>>   ? get_kvmclock_ns+0xa3/0x140 [kvm]
>>   get_time_ref_counter+0x5a/0x80 [kvm]
>>   kvm_hv_process_stimers+0x120/0x5f0 [kvm]
>>   ? kvm_hv_process_stimers+0x120/0x5f0 [kvm]
>>   ? preempt_schedule+0x27/0x30
>>   ? ___preempt_schedule+0x16/0x18
>>   kvm_arch_vcpu_ioctl_run+0x4b4/0x1690 [kvm]
>>   ? kvm_arch_vcpu_load+0x47/0x230 [kvm]
>>   kvm_vcpu_ioctl+0x33a/0x620 [kvm]
>>   ? kvm_vcpu_ioctl+0x33a/0x620 [kvm]
>>   ? kvm_vm_ioctl_check_extension_generic+0x3b/0x40 [kvm]
>>   ? kvm_dev_ioctl+0x279/0x6c0 [kvm]
>>   do_vfs_ioctl+0xa1/0x5d0
>>   ? __fget+0x73/0xa0
>>   SyS_ioctl+0x79/0x90
>>   entry_SYSCALL_64_fastpath+0x1e/0xa9
>>
>> This can be reproduced when running kvm-unit-tests/hyperv_stimer.flat and
>> cpu-hotplug stress simultaneously. __this_cpu_read(cpu_tsc_khz) returns 0
>> (set in kvmclock_cpu_down_prep()) when the pCPU is unhotplug which results
>> in kvm_get_time_scale() gets into an infinite loop.
>>
>> This patch fixes it by skipping to fill the hv_clock when the pCPU is offline.
>>
>> Cc: Paolo Bonzini <pbonzini@redhat.com>
>> Cc: Radim Krčmář <rkrcmar@redhat.com>
>> Signed-off-by: Wanpeng Li <wanpeng.li@hotmail.com>
>> ---
>> v1 -> v2:
>>  * avoid infinite loop
>>
>>  arch/x86/kvm/x86.c | 3 +++
>>  1 file changed, 3 insertions(+)
>>
>> diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
>> index 03869eb..d2507c6 100644
>> --- a/arch/x86/kvm/x86.c
>> +++ b/arch/x86/kvm/x86.c
>> @@ -1259,6 +1259,9 @@ static void kvm_get_time_scale(uint64_t scaled_hz, uint64_t base_hz,
>>       uint64_t tps64;
>>       uint32_t tps32;
>>
>> +     if (unlikely(base_hz == 0))
>> +             return;
>
> This is a sensible thing to do and will prevent the loop, but KVM will
> still have a minor bug:  get_kvmclock_ns() passes uninitialized stack
> values with the expectation that kvm_get_time_scale() will set them, but
> returning here would result in __pvclock_read_cycles() with random data
> and inject timer interrupts early (if not worse).
>
> I think it would be best if kvm_get_time_scale() wasn't executing when
> cpu_tsc_khz is 0, by clearing cpu_tsc_khz later and setting earlier;
> do you see any problems with moving the CPUHP_AP_X86_KVM_CLK_ONLINE
> before CPUHP_AP_ONLINE?

I think this will break Thomas's hotplug state machine, and I'm not
the hotplug expert. How about something like below to avoid the random
data:

diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
index 34c85aa..954f510 100644
--- a/arch/x86/kvm/x86.c
+++ b/arch/x86/kvm/x86.c
@@ -1795,10 +1795,13 @@ u64 get_kvmclock_ns(struct kvm *kvm)
        /* both __this_cpu_read() and rdtsc() should be on the same cpu */
        get_cpu();

-       kvm_get_time_scale(NSEC_PER_SEC, __this_cpu_read(cpu_tsc_khz) * 1000LL,
-                          &hv_clock.tsc_shift,
-                          &hv_clock.tsc_to_system_mul);
-       ret = __pvclock_read_cycles(&hv_clock, rdtsc());
+       if (__this_cpu_read(cpu_tsc_khz)) {
+               kvm_get_time_scale(NSEC_PER_SEC,
__this_cpu_read(cpu_tsc_khz) * 1000LL,
+                                  &hv_clock.tsc_shift,
+                                  &hv_clock.tsc_to_system_mul);
+               ret = __pvclock_read_cycles(&hv_clock, rdtsc());
+       } else
+               ret = ktime_get_boot_ns() + ka->kvmclock_offset;

        put_cpu();

Re: [PATCH v2] KVM: X86: Fix softlockup when get the current kvmclock timestamp

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 4178 bytes --]

Hi,

Thank you for the patch! Perhaps something to improve:

[auto build test WARNING on kvm/linux-next]
[also build test WARNING on v4.14 next-20171124]
[if your patch is applied to the wrong git tree, please drop us a note to help improve the system]

url:    https://github.com/0day-ci/linux/commits/Wanpeng-Li/KVM-X86-Fix-softlockup-when-get-the-current-kvmclock-timestamp/20171109-030841
base:   https://git.kernel.org/pub/scm/virt/kvm/kvm.git linux-next
config: i386-allyesconfig (attached as .config)
compiler: gcc-7 (Debian 7.2.0-12) 7.2.1 20171025
reproduce:
        # save the attached .config to linux build tree
        make ARCH=i386 

Note: it may well be a FALSE warning. FWIW you are at least aware of it now.
http://gcc.gnu.org/wiki/Better_Uninitialized_Warnings

All warnings (new ones prefixed by >>):

   In file included from arch/x86/kvm/x86.h:7:0,
                    from arch/x86/kvm/x86.c:28:
   arch/x86/kvm/x86.c: In function 'get_kvmclock_ns':
>> arch/x86/include/asm/pvclock.h:93:15: warning: '*((void *)&hv_clock+28)' may be used uninitialized in this function [-Wmaybe-uninitialized]
     u64 offset = pvclock_scale_delta(delta, src->tsc_to_system_mul,
                  ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
              src->tsc_shift);
              ~~~~~~~~~~~~~~~
   arch/x86/kvm/x86.c:1785:32: note: '*((void *)&hv_clock+28)' was declared here
     struct pvclock_vcpu_time_info hv_clock;
                                   ^~~~~~~~
   In file included from arch/x86/kvm/x86.h:7:0,
                    from arch/x86/kvm/x86.c:28:
   arch/x86/include/asm/pvclock.h:65:2: warning: '*((void *)&hv_clock+24)' may be used uninitialized in this function [-Wmaybe-uninitialized]
     __asm__ (
     ^~~~~~~
   arch/x86/kvm/x86.c:1785:32: note: '*((void *)&hv_clock+24)' was declared here
     struct pvclock_vcpu_time_info hv_clock;
                                   ^~~~~~~~
--
   In file included from arch/x86//kvm/x86.h:7:0,
                    from arch/x86//kvm/x86.c:28:
   arch/x86//kvm/x86.c: In function 'get_kvmclock_ns':
>> arch/x86/include/asm/pvclock.h:93:15: warning: '*((void *)&hv_clock+28)' may be used uninitialized in this function [-Wmaybe-uninitialized]
     u64 offset = pvclock_scale_delta(delta, src->tsc_to_system_mul,
                  ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
              src->tsc_shift);
              ~~~~~~~~~~~~~~~
   arch/x86//kvm/x86.c:1785:32: note: '*((void *)&hv_clock+28)' was declared here
     struct pvclock_vcpu_time_info hv_clock;
                                   ^~~~~~~~
   In file included from arch/x86//kvm/x86.h:7:0,
                    from arch/x86//kvm/x86.c:28:
   arch/x86/include/asm/pvclock.h:65:2: warning: '*((void *)&hv_clock+24)' may be used uninitialized in this function [-Wmaybe-uninitialized]
     __asm__ (
     ^~~~~~~
   arch/x86//kvm/x86.c:1785:32: note: '*((void *)&hv_clock+24)' was declared here
     struct pvclock_vcpu_time_info hv_clock;
                                   ^~~~~~~~

vim +93 arch/x86/include/asm/pvclock.h

347bb4448 Zachary Amsden  2010-08-19  88  
dce2db0a3 Marcelo Tosatti 2012-11-27  89  static __always_inline
a5a1d1c29 Thomas Gleixner 2016-12-21  90  u64 __pvclock_read_cycles(const struct pvclock_vcpu_time_info *src, u64 tsc)
dce2db0a3 Marcelo Tosatti 2012-11-27  91  {
108b249c4 Paolo Bonzini   2016-09-01  92  	u64 delta = tsc - src->tsc_timestamp;
a5a1d1c29 Thomas Gleixner 2016-12-21 @93  	u64 offset = pvclock_scale_delta(delta, src->tsc_to_system_mul,
f7550d076 Minfei Huang    2016-05-27  94  					     src->tsc_shift);
3aed64f6d Paolo Bonzini   2016-06-09  95  	return src->system_time + offset;
dce2db0a3 Marcelo Tosatti 2012-11-27  96  }
dce2db0a3 Marcelo Tosatti 2012-11-27  97  

:::::: The code at line 93 was first introduced by commit
:::::: a5a1d1c2914b5316924c7893eb683a5420ebd3be clocksource: Use a plain u64 instead of cycle_t

:::::: TO: Thomas Gleixner <tglx@linutronix.de>
:::::: CC: Thomas Gleixner <tglx@linutronix.de>

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 61127 bytes --]

Re: [PATCH v2] KVM: X86: Fix softlockup when get the current kvmclock timestamp

[Wanpeng Li]

2017-11-25 11:14 GMT+08:00 kbuild test robot <lkp@intel.com>:
> Hi,
>
> Thank you for the patch! Perhaps something to improve:
>
> [auto build test WARNING on kvm/linux-next]
> [also build test WARNING on v4.14 next-20171124]
> [if your patch is applied to the wrong git tree, please drop us a note to help improve the system]

Don't worry, the version which has already been merged doesn't have this issue.

Regards,
Wanpeng Li

>
> url:    https://github.com/0day-ci/linux/commits/Wanpeng-Li/KVM-X86-Fix-softlockup-when-get-the-current-kvmclock-timestamp/20171109-030841
> base:   https://git.kernel.org/pub/scm/virt/kvm/kvm.git linux-next
> config: i386-allyesconfig (attached as .config)
> compiler: gcc-7 (Debian 7.2.0-12) 7.2.1 20171025
> reproduce:
>         # save the attached .config to linux build tree
>         make ARCH=i386
>
> Note: it may well be a FALSE warning. FWIW you are at least aware of it now.
> http://gcc.gnu.org/wiki/Better_Uninitialized_Warnings
>
> All warnings (new ones prefixed by >>):
>
>    In file included from arch/x86/kvm/x86.h:7:0,
>                     from arch/x86/kvm/x86.c:28:
>    arch/x86/kvm/x86.c: In function 'get_kvmclock_ns':
>>> arch/x86/include/asm/pvclock.h:93:15: warning: '*((void *)&hv_clock+28)' may be used uninitialized in this function [-Wmaybe-uninitialized]
>      u64 offset = pvclock_scale_delta(delta, src->tsc_to_system_mul,
>                   ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>               src->tsc_shift);
>               ~~~~~~~~~~~~~~~
>    arch/x86/kvm/x86.c:1785:32: note: '*((void *)&hv_clock+28)' was declared here
>      struct pvclock_vcpu_time_info hv_clock;
>                                    ^~~~~~~~
>    In file included from arch/x86/kvm/x86.h:7:0,
>                     from arch/x86/kvm/x86.c:28:
>    arch/x86/include/asm/pvclock.h:65:2: warning: '*((void *)&hv_clock+24)' may be used uninitialized in this function [-Wmaybe-uninitialized]
>      __asm__ (
>      ^~~~~~~
>    arch/x86/kvm/x86.c:1785:32: note: '*((void *)&hv_clock+24)' was declared here
>      struct pvclock_vcpu_time_info hv_clock;
>                                    ^~~~~~~~
> --
>    In file included from arch/x86//kvm/x86.h:7:0,
>                     from arch/x86//kvm/x86.c:28:
>    arch/x86//kvm/x86.c: In function 'get_kvmclock_ns':
>>> arch/x86/include/asm/pvclock.h:93:15: warning: '*((void *)&hv_clock+28)' may be used uninitialized in this function [-Wmaybe-uninitialized]
>      u64 offset = pvclock_scale_delta(delta, src->tsc_to_system_mul,
>                   ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>               src->tsc_shift);
>               ~~~~~~~~~~~~~~~
>    arch/x86//kvm/x86.c:1785:32: note: '*((void *)&hv_clock+28)' was declared here
>      struct pvclock_vcpu_time_info hv_clock;
>                                    ^~~~~~~~
>    In file included from arch/x86//kvm/x86.h:7:0,
>                     from arch/x86//kvm/x86.c:28:
>    arch/x86/include/asm/pvclock.h:65:2: warning: '*((void *)&hv_clock+24)' may be used uninitialized in this function [-Wmaybe-uninitialized]
>      __asm__ (
>      ^~~~~~~
>    arch/x86//kvm/x86.c:1785:32: note: '*((void *)&hv_clock+24)' was declared here
>      struct pvclock_vcpu_time_info hv_clock;
>                                    ^~~~~~~~
>
> vim +93 arch/x86/include/asm/pvclock.h
>
> 347bb4448 Zachary Amsden  2010-08-19  88
> dce2db0a3 Marcelo Tosatti 2012-11-27  89  static __always_inline
> a5a1d1c29 Thomas Gleixner 2016-12-21  90  u64 __pvclock_read_cycles(const struct pvclock_vcpu_time_info *src, u64 tsc)
> dce2db0a3 Marcelo Tosatti 2012-11-27  91  {
> 108b249c4 Paolo Bonzini   2016-09-01  92        u64 delta = tsc - src->tsc_timestamp;
> a5a1d1c29 Thomas Gleixner 2016-12-21 @93        u64 offset = pvclock_scale_delta(delta, src->tsc_to_system_mul,
> f7550d076 Minfei Huang    2016-05-27  94                                             src->tsc_shift);
> 3aed64f6d Paolo Bonzini   2016-06-09  95        return src->system_time + offset;
> dce2db0a3 Marcelo Tosatti 2012-11-27  96  }
> dce2db0a3 Marcelo Tosatti 2012-11-27  97
>
> :::::: The code at line 93 was first introduced by commit
> :::::: a5a1d1c2914b5316924c7893eb683a5420ebd3be clocksource: Use a plain u64 instead of cycle_t
>
> :::::: TO: Thomas Gleixner <tglx@linutronix.de>
> :::::: CC: Thomas Gleixner <tglx@linutronix.de>
>
> ---
> 0-DAY kernel test infrastructure                Open Source Technology Center
> https://lists.01.org/pipermail/kbuild-all                   Intel Corporation