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

[Paolo Bonzini <pbonzini@redhat.com>]

On 20/05/19 10:18, Wanpeng Li wrote:
> From: Wanpeng Li <wanpengli@tencent.com>
> 
> 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@redhat.com>
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.

[1] Commit 8b89fe1f6c43 ("kvm: x86: move tracepoints outside extended quiescent state")
[2] https://patchwork.kernel.org/patch/7821111/

Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>

---
 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,