Re: [PATCH 2/2] KVM: selftests: Add KVM/PV clock selftest to prove timer drift correction

[David Woodhouse]

On Mon, 2024-04-22 at 15:02 -0700, Chen, Zide wrote:
> 
> 
> On 4/20/2024 9:03 AM, David Woodhouse wrote:
> > On Fri, 2024-04-19 at 16:54 -0700, Chen, Zide wrote:
> > > 
> > > However, the selftest hangs:
> > > 
> > > [Apr19 16:15] kselftest: Running tests in kvm
> > > [Apr19 16:16] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> > > [  +0.000628] rcu:      78-...0: (1 GPs behind) idle=3c8c/1/0x4000000000000000 softirq=5908/5913 fqs=14025
> > > [  +0.000468] rcu:      (detected by 104, t=60003 jiffies, g=60073, q=3100 ncpus=128)
> > > [  +0.000389] Sending NMI from CPU 104 to CPUs 78:
> > > [  +0.000360] NMI backtrace for cpu 78
> > > [  +0.000004] CPU: 78 PID: 33515 Comm: pvclock_test Tainted: G O       6.9.0-rc1zide-l0+ #194
> > > [  +0.000003] Hardware name: Inspur NF5280M7/NF5280M7, BIOS 05.08.01 08/18/2023
> > > [  +0.000002] RIP: 0010:pvclock_update_vm_gtod_copy+0xb5/0x200 [kvm]
> > 
> > Ah, kvm_get_time_scale() doesn't much like being asked to scale to zero.
> > 
> > diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
> > index a07b60351894..45fb99986cf9 100644
> > --- a/arch/x86/kvm/x86.c
> > +++ b/arch/x86/kvm/x86.c
> > @@ -3046,7 +3046,8 @@ static void pvclock_update_vm_gtod_copy(struct kvm *kvm)
> >                  * Copy from the field protected solely by ka->tsc_write_lock,
> >                  * to the field protected by the ka->pvclock_sc seqlock.
> >                  */
> > -               ka->master_tsc_scaling_ratio = ka->last_tsc_scaling_ratio;
> > +               ka->master_tsc_scaling_ratio = ka->last_tsc_scaling_ratio ? :
> > +                       kvm_caps.default_tsc_scaling_ratio;
> >  
> >                 /*
> >                  * Calculate the scaling factors precisely the same way
> >                  * that kvm_guest_time_update() does.
> >                 last_tsc_hz = kvm_scale_tsc(tsc_khz * 1000,
> >                                           ka->last_tsc_scaling_ratio);
> 
> Should be ka->master_tsc_scaling_ratio?

Oops, yes. I'll actually do some proper testing on a host with TSC
scaling this week. Thanks.

> If I restored the KVM_REQ_GLOBAL_CLOCK_UPDATE request from
> kvm_arch_vcpu_load(), the selftest works for me, and I ran the test for
> 1000+ iterations, w/ or w/o TSC scaling, the TEST_ASSERT(delta_corrected
>  <= ±1) never got hit. This is awesome!
>
> However, without KVM_REQ_GLOBAL_CLOCK_UPDATE, it still fails on creating
> a VM. Maybe the init sequence sill needs some rework.

That one confuses me. The crash is actually in debugfs, as it's
registering the per-vm or per-vcpu stats. I can't imagine *how* that's
occurring. Or see why the availability of TSC scaling would cause it to
show up for you and not me. Can I have your .config please?

First thought would be that there's some change in the KVM structures
and you have some stale object files using the old struct, but then I
realise I forgot to actually *remove* the now-unused
kvmclock_update_work from x86's struct kvm_arch anyway.

I'll try to reproduce, as I think I want to *know* what's going on
here, even if I am going to drop that patch as mentioned in 
https://lore.kernel.org/kvm/a6723ac9e0169839cb33e8022a47c2de213866ac.camel@xxxxxxxxxxxxx

Are you able to load that vmlinux in gdb and
(gdb) list *start_creating+0x80
(gdb) list *kvm_create_vm_debugfs+0x28b

Thanks again.

>  BUG: unable to handle page fault for address: 005b29e3f221ccf0
>  #PF: supervisor read access in kernel mode
>  #PF: error_code(0x0000) - not-present page
>  PGD 0
>  Oops: 0000 [#1] PREEMPT SMP NOPTI
>  CPU: 86 PID: 4118 Comm: pvclock_test Tainted
>  Hardware name: Inspur NF5280M7/NF5280M7, BIOS 05.08.01 08/18/2023
>  RIP: 0010:start_creating+0x80/0x190
>  Code: ce ad 48 c7 c6 70 a1 ce ad 48 c7 c7 80 1c 9b ab e8 b5 10 d5 ff 4c
> 63 e0 45 85 e4 0f 85 cd 00 00 00 48 85 db 0f 84 b5 00 00 00 <48> 8b 43
> 30 48 8d b8 b8 >
>  RSP: 0018:ff786eaacf3cfdd0 EFLAGS: 00010206
>  RAX: 0000000000000000 RBX: 005b29e3f221ccc0 RCX: 0000000000000000
>  RDX: 0000000000000001 RSI: ffffffffadcea170 RDI: 0000000000000000
>  RBP: ffffffffc06ac8cf R08: ffffffffa6ea0fe0 R09: ffffffffc06a5940
>  R10: ff786eaacf3cfe30 R11: 00000013a7b5feaa R12: 0000000000000000
>  R13: 0000000000000124 R14: ff786eaacfa11000 R15: 00000000000081a4
>  FS:  00007f0837c89740(0000) GS:ff4f44b6bfd80000(0000)
> knlGS:0000000000000000
>  CS:  0010 DS: 0000 ES: 0000 CR0
>  CR2: 005b29e3f221ccf0 CR3: 000000014bdf8002 CR4: 0000000000f73ef0
>  DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>  DR3: 0000000000000000 DR6: 00000000fffe07f0 DR7: 0000000000000400
>  PKRU: 55555554
>  Call Trace:
>   <TASK>
>   ? __die+0x24/0x70
>   ? page_fault_oops+0x81/0x150
>   ? do_user_addr_fault+0x64/0x6c0
>   ? exc_page_fault+0x8a/0x1a0
>   ? asm_exc_page_fault+0x26/0x30
>   ? start_creating+0x80/0x190
>   __debugfs_create_file+0x43/0x1f0
>   kvm_create_vm_debugfs+0x28b/0x2d0 [kvm]
>   kvm_create_vm+0x457/0x650 [kvm]
>   kvm_dev_ioctl+0x88/0x180 [kvm]
>   __x64_sys_ioctl+0x8e/0xd0
>   do_syscall_64+0x5b/0x120
>   entry_SYSCALL_64_after_hwframe+0x71/0x79
>  RIP: 0033:0x7f0837b1a94f
>  Code: 00 48 89 44 24 18 31 c0 48 8d 44 24 60 c7 04 24 10 00 00 00 48 89
> 44 24 08 48 8d 44 24 20 48 89 44 24 10 b8 10 00 00 00 0f 05 <41> 89 c0
> 3d 00 f0 ff ff >
>  RSP: 002b:00007ffe01be3fc0 EFLAGS: 00000246 ORIG_RAX
>  RAX: ffffffffffffffda RBX: 0000000000434480 RCX: 00007f0837b1a94f
>  RDX: 0000000000000000 RSI: 000000000000ae01 RDI: 0000000000000005
>  RBP: 0000000000000009 R08: 000000000041b1a0 R09: 000000000041bfcf
>  R10: 00007f0837bd8882 R11: 0000000000000246 R12: 0000000000434480
>  R13: 000000000041e0f0 R14: 0000000000001000 R15: 0000000000000207
>   </TASK>
>  Modules linked in: kvm_intel(O) kvm(O) [last unloaded: kvm(O)]
>  CR2: 005b29e3f221ccf0

Attachment: smime.p7s
Description: S/MIME cryptographic signature