Re: [PATCH v4 4/5] KVM: LAPIC: Delay trace advance expire delta

[Wanpeng Li]

On Mon, 20 May 2019 at 19:14, Paolo Bonzini <pbonzini@xxxxxxxxxx> wrote:
>
> On 20/05/19 10:18, Wanpeng Li wrote:
> > From: Wanpeng Li <wanpengli@xxxxxxxxxxx>
> >
> > wait_lapic_expire() call was moved above guest_enter_irqoff() because of
> > its tracepoint, which violated the RCU extended quiescent state invoked
> > by guest_enter_irqoff()[1][2]. This patch simply moves the tracepoint
> > below guest_exit_irqoff() in vcpu_enter_guest(). Snapshot the delta before
> > VM-Enter, but trace it after VM-Exit. This can help us to move
> > wait_lapic_expire() just before vmentry in the later patch.
> >
> > [1] Commit 8b89fe1f6c43 ("kvm: x86: move tracepoints outside extended quiescent state")
> > [2] https://patchwork.kernel.org/patch/7821111/
>
> This is a bit confusing, since the delta is printed after the
> corresponding vmexit but the wait is done before the vmentry.  I think
> we can drop the tracepoint:
>
> ------------- 8< ----------------
> From ae148d98d49b96b5222e2c78ac1b1e13cc526d71 Mon Sep 17 00:00:00 2001
> From: Paolo Bonzini <pbonzini@xxxxxxxxxx>
> Date: Mon, 20 May 2019 13:10:01 +0200
> Subject: [PATCH] KVM: lapic: replace wait_lapic_expire tracepoint with
>  restart_apic_timer
>
> wait_lapic_expire() call was moved above guest_enter_irqoff() because of
> its tracepoint, which violated the RCU extended quiescent state invoked
> by guest_enter_irqoff()[1][2].
>
> We would like to move wait_lapic_expire() just before vmentry, which would
> place wait_lapic_expire() again inside the extended quiescent state.  Drop
> the tracepoint, but add instead another one that can be useful and where
> we can check the status of the adaptive tuning procedure.

https://lkml.org/lkml/2019/5/15/1435

Maybe Sean's comment is reasonable, per-vCPU debugfs entry for
adaptive tuning and wait_lapic_expire() tracepoint for hand tuning.

Regards,
Wanpeng Li

>
> [1] Commit 8b89fe1f6c43 ("kvm: x86: move tracepoints outside extended quiescent state")
> [2] https://patchwork.kernel.org/patch/7821111/
>
> Signed-off-by: Paolo Bonzini <pbonzini@xxxxxxxxxx>
>
> ---
>  arch/x86/kvm/lapic.c |  4 +++-
>  arch/x86/kvm/trace.h | 15 +++++++--------
>  2 files changed, 10 insertions(+), 9 deletions(-)
>
> diff --git a/arch/x86/kvm/lapic.c b/arch/x86/kvm/lapic.c
> index c12b090f4fad..8f05c1d0b486 100644
> --- a/arch/x86/kvm/lapic.c
> +++ b/arch/x86/kvm/lapic.c
> @@ -1545,7 +1545,6 @@ void wait_lapic_expire(struct kvm_vcpu *vcpu)
>         tsc_deadline = apic->lapic_timer.expired_tscdeadline;
>         apic->lapic_timer.expired_tscdeadline = 0;
>         guest_tsc = kvm_read_l1_tsc(vcpu, rdtsc());
> -       trace_kvm_wait_lapic_expire(vcpu->vcpu_id, guest_tsc - tsc_deadline);
>
>         if (guest_tsc < tsc_deadline)
>                 __wait_lapic_expire(vcpu, tsc_deadline - guest_tsc);
> @@ -1763,6 +1762,9 @@ static void start_sw_timer(struct kvm_lapic *apic)
>
>  static void restart_apic_timer(struct kvm_lapic *apic)
>  {
> +       trace_kvm_restart_apic_timer(apic->vcpu->vcpu_id,
> +                                    apic->lapic_timer.timer_advance_ns);
> +
>         preempt_disable();
>
>         if (!apic_lvtt_period(apic) && atomic_read(&apic->lapic_timer.pending))
> diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
> index 4d47a2631d1f..f6e000038f3f 100644
> --- a/arch/x86/kvm/trace.h
> +++ b/arch/x86/kvm/trace.h
> @@ -953,24 +953,23 @@
>                   __entry->flags)
>  );
>
> -TRACE_EVENT(kvm_wait_lapic_expire,
> -       TP_PROTO(unsigned int vcpu_id, s64 delta),
> -       TP_ARGS(vcpu_id, delta),
> +TRACE_EVENT(kvm_restart_apic_timer,
> +       TP_PROTO(unsigned int vcpu_id, u32 advance),
> +       TP_ARGS(vcpu_id, advance),
>
>         TP_STRUCT__entry(
>                 __field(        unsigned int,   vcpu_id         )
> -               __field(        s64,            delta           )
> +               __field(        u32,            advance         )
>         ),
>
>         TP_fast_assign(
>                 __entry->vcpu_id           = vcpu_id;
> -               __entry->delta             = delta;
> +               __entry->advance           = advance;
>         ),
>
> -       TP_printk("vcpu %u: delta %lld (%s)",
> +       TP_printk("vcpu %u: advance %u",
>                   __entry->vcpu_id,
> -                 __entry->delta,
> -                 __entry->delta < 0 ? "early" : "late")
> +                 __entry->advance)
>  );
>
>  TRACE_EVENT(kvm_enter_smm,