Received-SPF: pass (google.com: domain of linux-kernel+bounces-14960-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.48.161 as permitted sender) client-ip=147.75.48.161;
Date: Tue, 2 Jan 2024 15:00:45 -0800
In-Reply-To: <CAE8KmOyffXD4k69vRAFwesaqrBGzFY3i+kefbkHcQf4=jNYzOA@mail.gmail.com>
Precedence: bulk
Mime-Version: 1.0
References: <CAE8KmOw1DzOr-GvQ9E+Y5RCX1GQ1h1Bumk5pB++9=SjMUPHxBg@mail.gmail.com>
 <ZT_HeK7GXdY-6L3t@google.com> <CAE8KmOxKkojqrqWE1RMa4YY3=of1AEFcDth_6b2ZCHJHzb8nng@mail.gmail.com>
 <CAE8KmOxd-Xib+qfiiBepP-ydjSAn32gjOTdLLUqm-i5vgzTv8w@mail.gmail.com> <CAE8KmOyffXD4k69vRAFwesaqrBGzFY3i+kefbkHcQf4=jNYzOA@mail.gmail.com>
Message-ID: <ZZSVnT0Ovk5QrasA@google.com>
Subject: Re: Fwd: About patch bdedff263132 - KVM: x86: Route pending NMIs
From: Sean Christopherson <seanjc@google.com>
To: Prasad Pandit <ppandit@redhat.com>
Cc: kvm@vger.kernel.org, linux-kernel@vger.kernel.org
Content-Type: text/plain; charset="us-ascii"

On Fri, Dec 29, 2023, Prasad Pandit wrote:
> Hello Sean,
> 
> On Tue, 31 Oct 2023 at 17:45, Prasad Pandit <ppandit@redhat.com> wrote:
> > On Mon, 30 Oct 2023 at 20:41, Sean Christopherson <seanjc@google.com> wrote:
> >>> -               kvm_make_request(KVM_REQ_NMI, vcpu);
> >>> +               if (events->nmi.pending)
> >>> +                       kvm_make_request(KVM_REQ_NMI, vcpu);
> > >
> > > This looks sane, but it should be unnecessary as KVM_REQ_NMI nmi_queued=0 should
> > > be a (costly) nop.  Hrm, unless the vCPU is in HLT, in which case KVM will treat
> > > a spurious KVM_REQ_NMI as a wake event.  When I made this change, my assumption
> > > was that userspace would set KVM_VCPUEVENT_VALID_NMI_PENDING iff there was
> > > relevant information to process.  But if I'm reading the code correctly, QEMU
> > > invokes KVM_SET_VCPU_EVENTS with KVM_VCPUEVENT_VALID_NMI_PENDING at the end of
> > > machine creation.
> > >

...

> * Above are 3 different ways in which KVM_SET_VCPU_EVENTS ioctl(2) gets called.
>         QEMU/target/i386/kvm/kvm.c: kvm_put_vcpu_events()
>          if (level >= KVM_PUT_RESET_STATE) {
>              events.flags |= KVM_VCPUEVENT_VALID_NMI_PENDING;
>   But KVM_VCPUEVENT_VALID_NMI_PENDING is set only when level >=
> 2(KVM_PUT_RESET_STATE). ie. in the first (level=1) case _NMI_PENDING
> is not set.
> 
> * In the real-time host set-up I have, KVM_VCPUEVENT_VALID_NMI_PENDING
> is called twice for each VCPU and after that kernel goes into what
> looks like a lock contention loop. Each time
> KVM_VCPUEVENT_VALID_NMI_PENDING is called with 'cpu->env->nmi_injected
> = 0' and  'cpu->env->nmi_pending = 0'.  ie. for each VCPU two NMI
> events are injected via - kvm_make_request(KVM_REQ_NMI, vcpu), when
> vcpu has no NMIs pending.
> 
> # perf lock report -t
>                 Name   acquired  contended     avg wait   total wait   max wait     min wait
> 
>            CPU 3/KVM     154017     154017     62.19 us      9.58 s   101.01 us      1.49 us
>            CPU 9/KVM     152796     152796     62.67 us      9.58 s    95.92 us      1.49 us
>            CPU 7/KVM     151554     151554     63.16 us      9.57 s   102.70 us      1.48 us
>            CPU 1/KVM     151273     151273     65.30 us      9.88 s    98.88 us      1.52 us
>            CPU 6/KVM     151107     151107     63.34 us      9.57 s   107.64 us      1.50 us
>            CPU 8/KVM     151038     151038     63.37 us      9.57 s   102.93 us      1.51 us
>            CPU 2/KVM     150701     150701     63.52 us      9.57 s    99.24 us      1.50 us
>            CPU 5/KVM     150695     150695     63.56 us      9.58 s   142.15 us      1.50 us
>            CPU 4/KVM     150527     150527     63.60 us      9.57 s   102.04 us      1.44 us
>      qemu-system-x86        665        665     65.92 us     43.84 ms  100.67 us      1.55 us
>            CPU 0/KVM          2          2    210.46 us    420.92 us  411.89 us      9.03 us
>      qemu-system-x86          1          1    404.91 us    404.91 us  404.91 us    404.91 us
>         TC tc-pc.ram          1          1    414.22 us    414.22 us  414.22 us    414.22 us
>   === output for debug===
> bad: 10, total: 13
> bad rate: 76.92 %
> histogram of events caused bad sequence
>     acquire: 0
>    acquired: 10
>   contended: 0
>     release: 0
> 
> 
> * VCPU#0 thread seems to wait indefinitely to get qemu_mutex_iothread_lock() to
> make any progress.

Heh, I don't know that I would describe "412 microseconds" as "indefinitely", but
it's certainly a long time, especially during boot.

> The proposed patch above to check 'events->nmi_pending' for non-zero value helps
> to fix this issue.
> 
> ...wdyt?

Piecing things together, the issue is I was wrong about the -EAGAIN exit being
benign.

 : Hmm, but even that should be benign unless userspace is stuffing other guest
 : state.  E.g. KVM will spuriously exit to userspace with -EAGAIN while the vCPU
 : is in KVM_MP_STATE_UNINITIALIZED, and I don't see a way for the vCPU to be put
 : into a blocking state after transitioning out of UNINITIATED via INIT+SIPI without
 : processing KVM_REQ_NMI.

QEMU responds to the spurious exit by bailing from the vCPU's inner runloop, and
when that happens, the associated task (briefly) acquires a global mutex, the
so called BQL (Big QEMU Lock).  I assumed that QEMU would eat the -EAGAIN and do
nothing interesting, but QEMU interprets the -EAGAIN as "there might be a global
state change the vCPU needs to handle".

As you discovered, having 9 vCPUs constantly acquiring and releasing a single
mutex makes for slow going when vCPU0 needs to acquire said mutex, e.g. to do
emulated MMIO.

Ah, and the other wrinkle is that KVM won't actually yield during KVM_RUN for
UNINITIALIZED vCPUs, i.e. all those vCPU tasks will stay at 100% utilization even
though there's nothing for them to do.  That may or may not matter in your case,
but it would be awful behavior in a setup with oversubscribed vCPUs.

I'm not 100% confident there isn't something else going on, e.g. a 400+ microsecond
wait time is a little odd, but this is inarguably a KVM regression and I doubt
it's worth anyone's time to dig deeper.

Can you give me a Signed-off-by for this?  I'll write a changelog and post a
proper patch.

# cat ~test/rpmbuild/SOURCES/linux-kernel-test.patch
+++ linux-5.14.0-372.el9/arch/x86/kvm/x86.c     2023-10-30
09:05:05.172815973 -0400
@@ -5277,7 +5277,8 @@ static int kvm_vcpu_ioctl_x86_set_vcpu_e
        if (events->flags & KVM_VCPUEVENT_VALID_NMI_PENDING) {
                vcpu->arch.nmi_pending = 0;
                atomic_set(&vcpu->arch.nmi_queued, events->nmi.pending);
-               kvm_make_request(KVM_REQ_NMI, vcpu);
+               if (events->nmi.pending)
+                       kvm_make_request(KVM_REQ_NMI, vcpu);
        }
        static_call(kvm_x86_set_nmi_mask)(vcpu, events->nmi.masked);

> PS: The kvm_make_request() routine has following comment, I wonder if
> this is what is happening with empty NMI events.
>          Request that don't require vCPU action should never be logged in
>          vcpu->requests.  The vCPU won't clear the request, so it will stay
>          logged indefinitely and prevent the vCPU from entering the guest.

Yeah, that's kinda sorta what's happening, although that comment is about requests
that are never cleared in *any* path, e.g. violation of that rule causes a vCPU
to be 100% stuck.