[PATCH v1 0/2] KVM: Hyper-V SynIC tracepoints

[PATCH v1 0/2] KVM: Hyper-V SynIC tracepoints

[Andrey Smetanin]

The patches adds tracepoints inside Hyper-V SynIC
and SynIC timers code.

The series applies on top of
'kvm/x86: Update SynIC timers on guest entry only'
previously sent.

Signed-off-by: Andrey Smetanin <asmetanin@virtuozzo.com>
CC: Gleb Natapov <gleb@kernel.org>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Roman Kagan <rkagan@virtuozzo.com>
CC: Denis V. Lunev <den@openvz.org>
CC: qemu-devel@nongnu.org

Andrey Smetanin (2):
  kvm/x86: Hyper-V SynIC tracepoints
  kvm/x86: Hyper-V SynIC timers tracepoints

 arch/x86/kvm/hyperv.c |  37 +++++--
 arch/x86/kvm/trace.h  | 263 ++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 294 insertions(+), 6 deletions(-)

-- 
2.4.3

[Qemu-devel] [PATCH v1 0/2] KVM: Hyper-V SynIC tracepoints

[Andrey Smetanin]

The patches adds tracepoints inside Hyper-V SynIC
and SynIC timers code.

The series applies on top of
'kvm/x86: Update SynIC timers on guest entry only'
previously sent.

Signed-off-by: Andrey Smetanin <asmetanin@virtuozzo.com>
CC: Gleb Natapov <gleb@kernel.org>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Roman Kagan <rkagan@virtuozzo.com>
CC: Denis V. Lunev <den@openvz.org>
CC: qemu-devel@nongnu.org

Andrey Smetanin (2):
  kvm/x86: Hyper-V SynIC tracepoints
  kvm/x86: Hyper-V SynIC timers tracepoints

 arch/x86/kvm/hyperv.c |  37 +++++--
 arch/x86/kvm/trace.h  | 263 ++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 294 insertions(+), 6 deletions(-)

-- 
2.4.3

[PATCH v1 1/2] kvm/x86: Hyper-V SynIC tracepoints

[Andrey Smetanin]

Trace the following Hyper SynIC events:
* set msr
* set sint irq
* ack sint
* sint irq eoi

Signed-off-by: Andrey Smetanin <asmetanin@virtuozzo.com>
CC: Gleb Natapov <gleb@kernel.org>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Roman Kagan <rkagan@virtuozzo.com>
CC: Denis V. Lunev <den@openvz.org>
CC: qemu-devel@nongnu.org
---
 arch/x86/kvm/hyperv.c | 10 +++---
 arch/x86/kvm/trace.h  | 93 +++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 98 insertions(+), 5 deletions(-)

diff --git a/arch/x86/kvm/hyperv.c b/arch/x86/kvm/hyperv.c
index 7857329..e69a823 100644
--- a/arch/x86/kvm/hyperv.c
+++ b/arch/x86/kvm/hyperv.c
@@ -152,7 +152,7 @@ static void kvm_hv_notify_acked_sint(struct kvm_vcpu *vcpu, u32 sint)
 	struct kvm_vcpu_hv_stimer *stimer;
 	int gsi, idx, stimers_pending;
 
-	vcpu_debug(vcpu, "Hyper-V SynIC acked sint %d\n", sint);
+	trace_kvm_hv_notify_acked_sint(vcpu->vcpu_id, sint);
 
 	if (synic->msg_page & HV_SYNIC_SIMP_ENABLE)
 		synic_clear_sint_msg_pending(synic, sint);
@@ -202,8 +202,8 @@ static int synic_set_msr(struct kvm_vcpu_hv_synic *synic,
 	if (!synic->active)
 		return 1;
 
-	vcpu_debug(vcpu, "Hyper-V SynIC set msr 0x%x 0x%llx host %d\n",
-		   msr, data, host);
+	trace_kvm_hv_synic_set_msr(vcpu->vcpu_id, msr, data, host);
+
 	ret = 0;
 	switch (msr) {
 	case HV_X64_MSR_SCONTROL:
@@ -312,7 +312,7 @@ int synic_set_irq(struct kvm_vcpu_hv_synic *synic, u32 sint)
 	irq.level = 1;
 
 	ret = kvm_irq_delivery_to_apic(vcpu->kvm, NULL, &irq, NULL);
-	vcpu_debug(vcpu, "Hyper-V SynIC set irq ret %d\n", ret);
+	trace_kvm_hv_synic_set_irq(vcpu->vcpu_id, sint, irq.vector, ret);
 	return ret;
 }
 
@@ -332,7 +332,7 @@ void kvm_hv_synic_send_eoi(struct kvm_vcpu *vcpu, int vector)
 	struct kvm_vcpu_hv_synic *synic = vcpu_to_synic(vcpu);
 	int i;
 
-	vcpu_debug(vcpu, "Hyper-V SynIC send eoi vec %d\n", vector);
+	trace_kvm_hv_synic_send_eoi(vcpu->vcpu_id, vector);
 
 	for (i = 0; i < ARRAY_SIZE(synic->sint); i++)
 		if (synic_get_sint_vector(synic_read_sint(synic, i)) == vector)
diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
index 1203025..5be9c13 100644
--- a/arch/x86/kvm/trace.h
+++ b/arch/x86/kvm/trace.h
@@ -1025,6 +1025,99 @@ TRACE_EVENT(kvm_pi_irte_update,
 		  __entry->pi_desc_addr)
 );
 
+/*
+ * Tracepoint for kvm_hv_notify_acked_sint.
+ */
+TRACE_EVENT(kvm_hv_notify_acked_sint,
+	TP_PROTO(int vcpu_id, u32 sint),
+	TP_ARGS(vcpu_id, sint),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(u32, sint)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->sint = sint;
+	),
+
+	TP_printk("vcpu_id %d sint %u", __entry->vcpu_id, __entry->sint)
+);
+
+/*
+ * Tracepoint for synic_set_irq.
+ */
+TRACE_EVENT(kvm_hv_synic_set_irq,
+	TP_PROTO(int vcpu_id, u32 sint, int vector, int ret),
+	TP_ARGS(vcpu_id, sint, vector, ret),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(u32, sint)
+		__field(int, vector)
+		__field(int, ret)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->sint = sint;
+		__entry->vector = vector;
+		__entry->ret = ret;
+	),
+
+	TP_printk("vcpu_id %d sint %u vector %d ret %d",
+		  __entry->vcpu_id, __entry->sint, __entry->vector,
+		  __entry->ret)
+);
+
+/*
+ * Tracepoint for kvm_hv_synic_send_eoi.
+ */
+TRACE_EVENT(kvm_hv_synic_send_eoi,
+	TP_PROTO(int vcpu_id, int vector),
+	TP_ARGS(vcpu_id, vector),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(u32, sint)
+		__field(int, vector)
+		__field(int, ret)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->vector	= vector;
+	),
+
+	TP_printk("vcpu_id %d vector %d", __entry->vcpu_id, __entry->vector)
+);
+
+/*
+ * Tracepoint for synic_set_msr.
+ */
+TRACE_EVENT(kvm_hv_synic_set_msr,
+	TP_PROTO(int vcpu_id, u32 msr, u64 data, bool host),
+	TP_ARGS(vcpu_id, msr, data, host),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(u32, msr)
+		__field(u64, data)
+		__field(bool, host)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->msr = msr;
+		__entry->data = data;
+		__entry->host = host
+	),
+
+	TP_printk("vcpu_id %d msr 0x%x data 0x%llx host %d",
+		  __entry->vcpu_id, __entry->msr, __entry->data, __entry->host)
+);
+
 #endif /* _TRACE_KVM_H */
 
 #undef TRACE_INCLUDE_PATH
-- 
2.4.3

[Qemu-devel] [PATCH v1 1/2] kvm/x86: Hyper-V SynIC tracepoints

[Andrey Smetanin]

Trace the following Hyper SynIC events:
* set msr
* set sint irq
* ack sint
* sint irq eoi

Signed-off-by: Andrey Smetanin <asmetanin@virtuozzo.com>
CC: Gleb Natapov <gleb@kernel.org>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Roman Kagan <rkagan@virtuozzo.com>
CC: Denis V. Lunev <den@openvz.org>
CC: qemu-devel@nongnu.org
---
 arch/x86/kvm/hyperv.c | 10 +++---
 arch/x86/kvm/trace.h  | 93 +++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 98 insertions(+), 5 deletions(-)

diff --git a/arch/x86/kvm/hyperv.c b/arch/x86/kvm/hyperv.c
index 7857329..e69a823 100644
--- a/arch/x86/kvm/hyperv.c
+++ b/arch/x86/kvm/hyperv.c
@@ -152,7 +152,7 @@ static void kvm_hv_notify_acked_sint(struct kvm_vcpu *vcpu, u32 sint)
 	struct kvm_vcpu_hv_stimer *stimer;
 	int gsi, idx, stimers_pending;
 
-	vcpu_debug(vcpu, "Hyper-V SynIC acked sint %d\n", sint);
+	trace_kvm_hv_notify_acked_sint(vcpu->vcpu_id, sint);
 
 	if (synic->msg_page & HV_SYNIC_SIMP_ENABLE)
 		synic_clear_sint_msg_pending(synic, sint);
@@ -202,8 +202,8 @@ static int synic_set_msr(struct kvm_vcpu_hv_synic *synic,
 	if (!synic->active)
 		return 1;
 
-	vcpu_debug(vcpu, "Hyper-V SynIC set msr 0x%x 0x%llx host %d\n",
-		   msr, data, host);
+	trace_kvm_hv_synic_set_msr(vcpu->vcpu_id, msr, data, host);
+
 	ret = 0;
 	switch (msr) {
 	case HV_X64_MSR_SCONTROL:
@@ -312,7 +312,7 @@ int synic_set_irq(struct kvm_vcpu_hv_synic *synic, u32 sint)
 	irq.level = 1;
 
 	ret = kvm_irq_delivery_to_apic(vcpu->kvm, NULL, &irq, NULL);
-	vcpu_debug(vcpu, "Hyper-V SynIC set irq ret %d\n", ret);
+	trace_kvm_hv_synic_set_irq(vcpu->vcpu_id, sint, irq.vector, ret);
 	return ret;
 }
 
@@ -332,7 +332,7 @@ void kvm_hv_synic_send_eoi(struct kvm_vcpu *vcpu, int vector)
 	struct kvm_vcpu_hv_synic *synic = vcpu_to_synic(vcpu);
 	int i;
 
-	vcpu_debug(vcpu, "Hyper-V SynIC send eoi vec %d\n", vector);
+	trace_kvm_hv_synic_send_eoi(vcpu->vcpu_id, vector);
 
 	for (i = 0; i < ARRAY_SIZE(synic->sint); i++)
 		if (synic_get_sint_vector(synic_read_sint(synic, i)) == vector)
diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
index 1203025..5be9c13 100644
--- a/arch/x86/kvm/trace.h
+++ b/arch/x86/kvm/trace.h
@@ -1025,6 +1025,99 @@ TRACE_EVENT(kvm_pi_irte_update,
 		  __entry->pi_desc_addr)
 );
 
+/*
+ * Tracepoint for kvm_hv_notify_acked_sint.
+ */
+TRACE_EVENT(kvm_hv_notify_acked_sint,
+	TP_PROTO(int vcpu_id, u32 sint),
+	TP_ARGS(vcpu_id, sint),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(u32, sint)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->sint = sint;
+	),
+
+	TP_printk("vcpu_id %d sint %u", __entry->vcpu_id, __entry->sint)
+);
+
+/*
+ * Tracepoint for synic_set_irq.
+ */
+TRACE_EVENT(kvm_hv_synic_set_irq,
+	TP_PROTO(int vcpu_id, u32 sint, int vector, int ret),
+	TP_ARGS(vcpu_id, sint, vector, ret),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(u32, sint)
+		__field(int, vector)
+		__field(int, ret)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->sint = sint;
+		__entry->vector = vector;
+		__entry->ret = ret;
+	),
+
+	TP_printk("vcpu_id %d sint %u vector %d ret %d",
+		  __entry->vcpu_id, __entry->sint, __entry->vector,
+		  __entry->ret)
+);
+
+/*
+ * Tracepoint for kvm_hv_synic_send_eoi.
+ */
+TRACE_EVENT(kvm_hv_synic_send_eoi,
+	TP_PROTO(int vcpu_id, int vector),
+	TP_ARGS(vcpu_id, vector),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(u32, sint)
+		__field(int, vector)
+		__field(int, ret)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->vector	= vector;
+	),
+
+	TP_printk("vcpu_id %d vector %d", __entry->vcpu_id, __entry->vector)
+);
+
+/*
+ * Tracepoint for synic_set_msr.
+ */
+TRACE_EVENT(kvm_hv_synic_set_msr,
+	TP_PROTO(int vcpu_id, u32 msr, u64 data, bool host),
+	TP_ARGS(vcpu_id, msr, data, host),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(u32, msr)
+		__field(u64, data)
+		__field(bool, host)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->msr = msr;
+		__entry->data = data;
+		__entry->host = host
+	),
+
+	TP_printk("vcpu_id %d msr 0x%x data 0x%llx host %d",
+		  __entry->vcpu_id, __entry->msr, __entry->data, __entry->host)
+);
+
 #endif /* _TRACE_KVM_H */
 
 #undef TRACE_INCLUDE_PATH
-- 
2.4.3

Re: [PATCH v1 1/2] kvm/x86: Hyper-V SynIC tracepoints

[Roman Kagan]

On Wed, Dec 23, 2015 at 04:53:59PM +0300, Andrey Smetanin wrote:
> Trace the following Hyper SynIC events:
> * set msr
> * set sint irq
> * ack sint
> * sint irq eoi
> 
> Signed-off-by: Andrey Smetanin <asmetanin@virtuozzo.com>
> CC: Gleb Natapov <gleb@kernel.org>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> CC: Roman Kagan <rkagan@virtuozzo.com>
> CC: Denis V. Lunev <den@openvz.org>
> CC: qemu-devel@nongnu.org
> ---
>  arch/x86/kvm/hyperv.c | 10 +++---
>  arch/x86/kvm/trace.h  | 93 +++++++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 98 insertions(+), 5 deletions(-)

Reviewed-by: Roman Kagan <rkagan@virtuozzo.com>

Re: [Qemu-devel] [PATCH v1 1/2] kvm/x86: Hyper-V SynIC tracepoints

[Roman Kagan]

On Wed, Dec 23, 2015 at 04:53:59PM +0300, Andrey Smetanin wrote:
> Trace the following Hyper SynIC events:
> * set msr
> * set sint irq
> * ack sint
> * sint irq eoi
> 
> Signed-off-by: Andrey Smetanin <asmetanin@virtuozzo.com>
> CC: Gleb Natapov <gleb@kernel.org>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> CC: Roman Kagan <rkagan@virtuozzo.com>
> CC: Denis V. Lunev <den@openvz.org>
> CC: qemu-devel@nongnu.org
> ---
>  arch/x86/kvm/hyperv.c | 10 +++---
>  arch/x86/kvm/trace.h  | 93 +++++++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 98 insertions(+), 5 deletions(-)

Reviewed-by: Roman Kagan <rkagan@virtuozzo.com>

[PATCH v1 2/2] kvm/x86: Hyper-V SynIC timers tracepoints

[Andrey Smetanin]

Trace the following Hyper SynIC timers events:
* periodic timer start
* one-shot timer start
* timer callback
* timer expiration and message delivery result
* timer config setup
* timer count setup
* timer cleanup

Signed-off-by: Andrey Smetanin <asmetanin@virtuozzo.com>
CC: Gleb Natapov <gleb@kernel.org>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Roman Kagan <rkagan@virtuozzo.com>
CC: Denis V. Lunev <den@openvz.org>
CC: qemu-devel@nongnu.org
---
 arch/x86/kvm/hyperv.c |  27 +++++++-
 arch/x86/kvm/trace.h  | 170 ++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 196 insertions(+), 1 deletion(-)

diff --git a/arch/x86/kvm/hyperv.c b/arch/x86/kvm/hyperv.c
index e69a823..d50675a 100644
--- a/arch/x86/kvm/hyperv.c
+++ b/arch/x86/kvm/hyperv.c
@@ -405,6 +405,9 @@ static void stimer_cleanup(struct kvm_vcpu_hv_stimer *stimer)
 {
 	struct kvm_vcpu *vcpu = stimer_to_vcpu(stimer);
 
+	trace_kvm_hv_stimer_cleanup(stimer_to_vcpu(stimer)->vcpu_id,
+				    stimer->index);
+
 	hrtimer_cancel(&stimer->timer);
 	clear_bit(stimer->index,
 		  vcpu_to_hv_vcpu(vcpu)->stimer_pending_bitmap);
@@ -417,6 +420,8 @@ static enum hrtimer_restart stimer_timer_callback(struct hrtimer *timer)
 	struct kvm_vcpu_hv_stimer *stimer;
 
 	stimer = container_of(timer, struct kvm_vcpu_hv_stimer, timer);
+	trace_kvm_hv_stimer_callback(stimer_to_vcpu(stimer)->vcpu_id,
+				     stimer->index);
 	stimer_mark_pending(stimer, true);
 
 	return HRTIMER_NORESTART;
@@ -446,6 +451,11 @@ static int stimer_start(struct kvm_vcpu_hv_stimer *stimer)
 		} else
 			stimer->exp_time = time_now + stimer->count;
 
+		trace_kvm_hv_stimer_start_periodic(
+					stimer_to_vcpu(stimer)->vcpu_id,
+					stimer->index,
+					time_now, stimer->exp_time);
+
 		hrtimer_start(&stimer->timer,
 			      ktime_add_ns(ktime_now,
 					   100 * (stimer->exp_time - time_now)),
@@ -464,6 +474,10 @@ static int stimer_start(struct kvm_vcpu_hv_stimer *stimer)
 		return 0;
 	}
 
+	trace_kvm_hv_stimer_start_one_shot(stimer_to_vcpu(stimer)->vcpu_id,
+					   stimer->index,
+					   time_now, stimer->count);
+
 	hrtimer_start(&stimer->timer,
 		      ktime_add_ns(ktime_now, 100 * (stimer->count - time_now)),
 		      HRTIMER_MODE_ABS);
@@ -473,6 +487,9 @@ static int stimer_start(struct kvm_vcpu_hv_stimer *stimer)
 static int stimer_set_config(struct kvm_vcpu_hv_stimer *stimer, u64 config,
 			     bool host)
 {
+	trace_kvm_hv_stimer_set_config(stimer_to_vcpu(stimer)->vcpu_id,
+				       stimer->index, config, host);
+
 	stimer_cleanup(stimer);
 	if ((stimer->config & HV_STIMER_ENABLE) && HV_STIMER_SINT(config) == 0)
 		config &= ~HV_STIMER_ENABLE;
@@ -484,6 +501,9 @@ static int stimer_set_config(struct kvm_vcpu_hv_stimer *stimer, u64 config,
 static int stimer_set_count(struct kvm_vcpu_hv_stimer *stimer, u64 count,
 			    bool host)
 {
+	trace_kvm_hv_stimer_set_count(stimer_to_vcpu(stimer)->vcpu_id,
+				      stimer->index, count, host);
+
 	stimer_cleanup(stimer);
 	stimer->count = count;
 	if (stimer->count == 0)
@@ -562,8 +582,13 @@ static int stimer_send_msg(struct kvm_vcpu_hv_stimer *stimer)
 
 static void stimer_expiration(struct kvm_vcpu_hv_stimer *stimer)
 {
+	int r;
+
 	stimer->msg_pending = true;
-	if (!stimer_send_msg(stimer)) {
+	r = stimer_send_msg(stimer);
+	trace_kvm_hv_stimer_expiration(stimer_to_vcpu(stimer)->vcpu_id,
+				       stimer->index, r);
+	if (!r) {
 		stimer->msg_pending = false;
 		if (!(stimer->config & HV_STIMER_PERIODIC))
 			stimer->config |= ~HV_STIMER_ENABLE;
diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
index 5be9c13..41010d8 100644
--- a/arch/x86/kvm/trace.h
+++ b/arch/x86/kvm/trace.h
@@ -1118,6 +1118,176 @@ TRACE_EVENT(kvm_hv_synic_set_msr,
 		  __entry->vcpu_id, __entry->msr, __entry->data, __entry->host)
 );
 
+/*
+ * Tracepoint for stimer_set_config.
+ */
+TRACE_EVENT(kvm_hv_stimer_set_config,
+	TP_PROTO(int vcpu_id, int timer_index, u64 config, bool host),
+	TP_ARGS(vcpu_id, timer_index, config, host),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+		__field(u64, config)
+		__field(bool, host)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+		__entry->config = config;
+		__entry->host = host;
+	),
+
+	TP_printk("vcpu_id %d timer %d config 0x%llx host %d",
+		  __entry->vcpu_id, __entry->timer_index, __entry->config,
+		  __entry->host)
+);
+
+/*
+ * Tracepoint for stimer_set_count.
+ */
+TRACE_EVENT(kvm_hv_stimer_set_count,
+	TP_PROTO(int vcpu_id, int timer_index, u64 count, bool host),
+	TP_ARGS(vcpu_id, timer_index, count, host),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+		__field(u64, count)
+		__field(bool, host)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+		__entry->count = count;
+		__entry->host = host;
+	),
+
+	TP_printk("vcpu_id %d timer %d count %llu host %d",
+		  __entry->vcpu_id, __entry->timer_index, __entry->count,
+		  __entry->host)
+);
+
+/*
+ * Tracepoint for stimer_start(periodic timer case).
+ */
+TRACE_EVENT(kvm_hv_stimer_start_periodic,
+	TP_PROTO(int vcpu_id, int timer_index, u64 time_now, u64 exp_time),
+	TP_ARGS(vcpu_id, timer_index, time_now, exp_time),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+		__field(u64, time_now)
+		__field(u64, exp_time)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+		__entry->time_now = time_now;
+		__entry->exp_time = exp_time;
+	),
+
+	TP_printk("vcpu_id %d timer %d time_now %llu exp_time %llu",
+		  __entry->vcpu_id, __entry->timer_index, __entry->time_now,
+		  __entry->exp_time)
+);
+
+/*
+ * Tracepoint for stimer_start(one-shot timer case).
+ */
+TRACE_EVENT(kvm_hv_stimer_start_one_shot,
+	TP_PROTO(int vcpu_id, int timer_index, u64 time_now, u64 count),
+	TP_ARGS(vcpu_id, timer_index, time_now, count),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+		__field(u64, time_now)
+		__field(u64, count)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+		__entry->time_now = time_now;
+		__entry->count = count;
+	),
+
+	TP_printk("vcpu_id %d timer %d time_now %llu count %llu",
+		  __entry->vcpu_id, __entry->timer_index, __entry->time_now,
+		  __entry->count)
+);
+
+/*
+ * Tracepoint for stimer_timer_callback.
+ */
+TRACE_EVENT(kvm_hv_stimer_callback,
+	TP_PROTO(int vcpu_id, int timer_index),
+	TP_ARGS(vcpu_id, timer_index),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+	),
+
+	TP_printk("vcpu_id %d timer %d",
+		  __entry->vcpu_id, __entry->timer_index)
+);
+
+/*
+ * Tracepoint for stimer_expiration.
+ */
+TRACE_EVENT(kvm_hv_stimer_expiration,
+	TP_PROTO(int vcpu_id, int timer_index, int msg_send_result),
+	TP_ARGS(vcpu_id, timer_index, msg_send_result),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+		__field(int, msg_send_result)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+		__entry->msg_send_result = msg_send_result;
+	),
+
+	TP_printk("vcpu_id %d timer %d msg send result %d",
+		  __entry->vcpu_id, __entry->timer_index,
+		  __entry->msg_send_result)
+);
+
+/*
+ * Tracepoint for stimer_cleanup.
+ */
+TRACE_EVENT(kvm_hv_stimer_cleanup,
+	TP_PROTO(int vcpu_id, int timer_index),
+	TP_ARGS(vcpu_id, timer_index),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+	),
+
+	TP_printk("vcpu_id %d timer %d",
+		  __entry->vcpu_id, __entry->timer_index)
+);
+
 #endif /* _TRACE_KVM_H */
 
 #undef TRACE_INCLUDE_PATH
-- 
2.4.3

[Qemu-devel] [PATCH v1 2/2] kvm/x86: Hyper-V SynIC timers tracepoints

[Andrey Smetanin]

Trace the following Hyper SynIC timers events:
* periodic timer start
* one-shot timer start
* timer callback
* timer expiration and message delivery result
* timer config setup
* timer count setup
* timer cleanup

Signed-off-by: Andrey Smetanin <asmetanin@virtuozzo.com>
CC: Gleb Natapov <gleb@kernel.org>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Roman Kagan <rkagan@virtuozzo.com>
CC: Denis V. Lunev <den@openvz.org>
CC: qemu-devel@nongnu.org
---
 arch/x86/kvm/hyperv.c |  27 +++++++-
 arch/x86/kvm/trace.h  | 170 ++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 196 insertions(+), 1 deletion(-)

diff --git a/arch/x86/kvm/hyperv.c b/arch/x86/kvm/hyperv.c
index e69a823..d50675a 100644
--- a/arch/x86/kvm/hyperv.c
+++ b/arch/x86/kvm/hyperv.c
@@ -405,6 +405,9 @@ static void stimer_cleanup(struct kvm_vcpu_hv_stimer *stimer)
 {
 	struct kvm_vcpu *vcpu = stimer_to_vcpu(stimer);
 
+	trace_kvm_hv_stimer_cleanup(stimer_to_vcpu(stimer)->vcpu_id,
+				    stimer->index);
+
 	hrtimer_cancel(&stimer->timer);
 	clear_bit(stimer->index,
 		  vcpu_to_hv_vcpu(vcpu)->stimer_pending_bitmap);
@@ -417,6 +420,8 @@ static enum hrtimer_restart stimer_timer_callback(struct hrtimer *timer)
 	struct kvm_vcpu_hv_stimer *stimer;
 
 	stimer = container_of(timer, struct kvm_vcpu_hv_stimer, timer);
+	trace_kvm_hv_stimer_callback(stimer_to_vcpu(stimer)->vcpu_id,
+				     stimer->index);
 	stimer_mark_pending(stimer, true);
 
 	return HRTIMER_NORESTART;
@@ -446,6 +451,11 @@ static int stimer_start(struct kvm_vcpu_hv_stimer *stimer)
 		} else
 			stimer->exp_time = time_now + stimer->count;
 
+		trace_kvm_hv_stimer_start_periodic(
+					stimer_to_vcpu(stimer)->vcpu_id,
+					stimer->index,
+					time_now, stimer->exp_time);
+
 		hrtimer_start(&stimer->timer,
 			      ktime_add_ns(ktime_now,
 					   100 * (stimer->exp_time - time_now)),
@@ -464,6 +474,10 @@ static int stimer_start(struct kvm_vcpu_hv_stimer *stimer)
 		return 0;
 	}
 
+	trace_kvm_hv_stimer_start_one_shot(stimer_to_vcpu(stimer)->vcpu_id,
+					   stimer->index,
+					   time_now, stimer->count);
+
 	hrtimer_start(&stimer->timer,
 		      ktime_add_ns(ktime_now, 100 * (stimer->count - time_now)),
 		      HRTIMER_MODE_ABS);
@@ -473,6 +487,9 @@ static int stimer_start(struct kvm_vcpu_hv_stimer *stimer)
 static int stimer_set_config(struct kvm_vcpu_hv_stimer *stimer, u64 config,
 			     bool host)
 {
+	trace_kvm_hv_stimer_set_config(stimer_to_vcpu(stimer)->vcpu_id,
+				       stimer->index, config, host);
+
 	stimer_cleanup(stimer);
 	if ((stimer->config & HV_STIMER_ENABLE) && HV_STIMER_SINT(config) == 0)
 		config &= ~HV_STIMER_ENABLE;
@@ -484,6 +501,9 @@ static int stimer_set_config(struct kvm_vcpu_hv_stimer *stimer, u64 config,
 static int stimer_set_count(struct kvm_vcpu_hv_stimer *stimer, u64 count,
 			    bool host)
 {
+	trace_kvm_hv_stimer_set_count(stimer_to_vcpu(stimer)->vcpu_id,
+				      stimer->index, count, host);
+
 	stimer_cleanup(stimer);
 	stimer->count = count;
 	if (stimer->count == 0)
@@ -562,8 +582,13 @@ static int stimer_send_msg(struct kvm_vcpu_hv_stimer *stimer)
 
 static void stimer_expiration(struct kvm_vcpu_hv_stimer *stimer)
 {
+	int r;
+
 	stimer->msg_pending = true;
-	if (!stimer_send_msg(stimer)) {
+	r = stimer_send_msg(stimer);
+	trace_kvm_hv_stimer_expiration(stimer_to_vcpu(stimer)->vcpu_id,
+				       stimer->index, r);
+	if (!r) {
 		stimer->msg_pending = false;
 		if (!(stimer->config & HV_STIMER_PERIODIC))
 			stimer->config |= ~HV_STIMER_ENABLE;
diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
index 5be9c13..41010d8 100644
--- a/arch/x86/kvm/trace.h
+++ b/arch/x86/kvm/trace.h
@@ -1118,6 +1118,176 @@ TRACE_EVENT(kvm_hv_synic_set_msr,
 		  __entry->vcpu_id, __entry->msr, __entry->data, __entry->host)
 );
 
+/*
+ * Tracepoint for stimer_set_config.
+ */
+TRACE_EVENT(kvm_hv_stimer_set_config,
+	TP_PROTO(int vcpu_id, int timer_index, u64 config, bool host),
+	TP_ARGS(vcpu_id, timer_index, config, host),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+		__field(u64, config)
+		__field(bool, host)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+		__entry->config = config;
+		__entry->host = host;
+	),
+
+	TP_printk("vcpu_id %d timer %d config 0x%llx host %d",
+		  __entry->vcpu_id, __entry->timer_index, __entry->config,
+		  __entry->host)
+);
+
+/*
+ * Tracepoint for stimer_set_count.
+ */
+TRACE_EVENT(kvm_hv_stimer_set_count,
+	TP_PROTO(int vcpu_id, int timer_index, u64 count, bool host),
+	TP_ARGS(vcpu_id, timer_index, count, host),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+		__field(u64, count)
+		__field(bool, host)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+		__entry->count = count;
+		__entry->host = host;
+	),
+
+	TP_printk("vcpu_id %d timer %d count %llu host %d",
+		  __entry->vcpu_id, __entry->timer_index, __entry->count,
+		  __entry->host)
+);
+
+/*
+ * Tracepoint for stimer_start(periodic timer case).
+ */
+TRACE_EVENT(kvm_hv_stimer_start_periodic,
+	TP_PROTO(int vcpu_id, int timer_index, u64 time_now, u64 exp_time),
+	TP_ARGS(vcpu_id, timer_index, time_now, exp_time),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+		__field(u64, time_now)
+		__field(u64, exp_time)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+		__entry->time_now = time_now;
+		__entry->exp_time = exp_time;
+	),
+
+	TP_printk("vcpu_id %d timer %d time_now %llu exp_time %llu",
+		  __entry->vcpu_id, __entry->timer_index, __entry->time_now,
+		  __entry->exp_time)
+);
+
+/*
+ * Tracepoint for stimer_start(one-shot timer case).
+ */
+TRACE_EVENT(kvm_hv_stimer_start_one_shot,
+	TP_PROTO(int vcpu_id, int timer_index, u64 time_now, u64 count),
+	TP_ARGS(vcpu_id, timer_index, time_now, count),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+		__field(u64, time_now)
+		__field(u64, count)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+		__entry->time_now = time_now;
+		__entry->count = count;
+	),
+
+	TP_printk("vcpu_id %d timer %d time_now %llu count %llu",
+		  __entry->vcpu_id, __entry->timer_index, __entry->time_now,
+		  __entry->count)
+);
+
+/*
+ * Tracepoint for stimer_timer_callback.
+ */
+TRACE_EVENT(kvm_hv_stimer_callback,
+	TP_PROTO(int vcpu_id, int timer_index),
+	TP_ARGS(vcpu_id, timer_index),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+	),
+
+	TP_printk("vcpu_id %d timer %d",
+		  __entry->vcpu_id, __entry->timer_index)
+);
+
+/*
+ * Tracepoint for stimer_expiration.
+ */
+TRACE_EVENT(kvm_hv_stimer_expiration,
+	TP_PROTO(int vcpu_id, int timer_index, int msg_send_result),
+	TP_ARGS(vcpu_id, timer_index, msg_send_result),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+		__field(int, msg_send_result)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+		__entry->msg_send_result = msg_send_result;
+	),
+
+	TP_printk("vcpu_id %d timer %d msg send result %d",
+		  __entry->vcpu_id, __entry->timer_index,
+		  __entry->msg_send_result)
+);
+
+/*
+ * Tracepoint for stimer_cleanup.
+ */
+TRACE_EVENT(kvm_hv_stimer_cleanup,
+	TP_PROTO(int vcpu_id, int timer_index),
+	TP_ARGS(vcpu_id, timer_index),
+
+	TP_STRUCT__entry(
+		__field(int, vcpu_id)
+		__field(int, timer_index)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->timer_index = timer_index;
+	),
+
+	TP_printk("vcpu_id %d timer %d",
+		  __entry->vcpu_id, __entry->timer_index)
+);
+
 #endif /* _TRACE_KVM_H */
 
 #undef TRACE_INCLUDE_PATH
-- 
2.4.3

Re: [PATCH v1 2/2] kvm/x86: Hyper-V SynIC timers tracepoints

[Roman Kagan]

On Wed, Dec 23, 2015 at 04:54:00PM +0300, Andrey Smetanin wrote:
> Trace the following Hyper SynIC timers events:
> * periodic timer start
> * one-shot timer start
> * timer callback
> * timer expiration and message delivery result
> * timer config setup
> * timer count setup
> * timer cleanup
> 
> Signed-off-by: Andrey Smetanin <asmetanin@virtuozzo.com>
> CC: Gleb Natapov <gleb@kernel.org>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> CC: Roman Kagan <rkagan@virtuozzo.com>
> CC: Denis V. Lunev <den@openvz.org>
> CC: qemu-devel@nongnu.org
> ---
>  arch/x86/kvm/hyperv.c |  27 +++++++-
>  arch/x86/kvm/trace.h  | 170 ++++++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 196 insertions(+), 1 deletion(-)

Reviewed-by: Roman Kagan <rkagan@virtuozzo.com>

Re: [Qemu-devel] [PATCH v1 2/2] kvm/x86: Hyper-V SynIC timers tracepoints

[Roman Kagan]

On Wed, Dec 23, 2015 at 04:54:00PM +0300, Andrey Smetanin wrote:
> Trace the following Hyper SynIC timers events:
> * periodic timer start
> * one-shot timer start
> * timer callback
> * timer expiration and message delivery result
> * timer config setup
> * timer count setup
> * timer cleanup
> 
> Signed-off-by: Andrey Smetanin <asmetanin@virtuozzo.com>
> CC: Gleb Natapov <gleb@kernel.org>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> CC: Roman Kagan <rkagan@virtuozzo.com>
> CC: Denis V. Lunev <den@openvz.org>
> CC: qemu-devel@nongnu.org
> ---
>  arch/x86/kvm/hyperv.c |  27 +++++++-
>  arch/x86/kvm/trace.h  | 170 ++++++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 196 insertions(+), 1 deletion(-)

Reviewed-by: Roman Kagan <rkagan@virtuozzo.com>

Re: [PATCH v1 0/2] KVM: Hyper-V SynIC tracepoints

[Paolo Bonzini]

On 23/12/2015 14:53, Andrey Smetanin wrote:
> The patches adds tracepoints inside Hyper-V SynIC
> and SynIC timers code.
> 
> The series applies on top of
> 'kvm/x86: Update SynIC timers on guest entry only'
> previously sent.

Applied, thanks.

Paolo

> Signed-off-by: Andrey Smetanin <asmetanin@virtuozzo.com>
> CC: Gleb Natapov <gleb@kernel.org>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> CC: Roman Kagan <rkagan@virtuozzo.com>
> CC: Denis V. Lunev <den@openvz.org>
> CC: qemu-devel@nongnu.org
> 
> Andrey Smetanin (2):
>   kvm/x86: Hyper-V SynIC tracepoints
>   kvm/x86: Hyper-V SynIC timers tracepoints
> 
>  arch/x86/kvm/hyperv.c |  37 +++++--
>  arch/x86/kvm/trace.h  | 263 ++++++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 294 insertions(+), 6 deletions(-)
> 

Re: [Qemu-devel] [PATCH v1 0/2] KVM: Hyper-V SynIC tracepoints

[Paolo Bonzini]

On 23/12/2015 14:53, Andrey Smetanin wrote:
> The patches adds tracepoints inside Hyper-V SynIC
> and SynIC timers code.
> 
> The series applies on top of
> 'kvm/x86: Update SynIC timers on guest entry only'
> previously sent.

Applied, thanks.

Paolo

> Signed-off-by: Andrey Smetanin <asmetanin@virtuozzo.com>
> CC: Gleb Natapov <gleb@kernel.org>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> CC: Roman Kagan <rkagan@virtuozzo.com>
> CC: Denis V. Lunev <den@openvz.org>
> CC: qemu-devel@nongnu.org
> 
> Andrey Smetanin (2):
>   kvm/x86: Hyper-V SynIC tracepoints
>   kvm/x86: Hyper-V SynIC timers tracepoints
> 
>  arch/x86/kvm/hyperv.c |  37 +++++--
>  arch/x86/kvm/trace.h  | 263 ++++++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 294 insertions(+), 6 deletions(-)
>