From aba2f06c070f604e388cf77b1dcc7f4cf4577eb0 Mon Sep 17 00:00:00 2001 From: Paolo Bonzini Date: Thu, 12 Nov 2015 16:42:18 +0100 Subject: KVM: x86: correctly print #AC in traces Poor #AC was so unimportant until a few days ago that we were not even tracing its name correctly. But now it's all over the place. Cc: stable@vger.kernel.org Signed-off-by: Paolo Bonzini --- arch/x86/kvm/trace.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'arch/x86/kvm/trace.h') diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h index 120302511802..ab9ae67a80e4 100644 --- a/arch/x86/kvm/trace.h +++ b/arch/x86/kvm/trace.h @@ -268,7 +268,7 @@ TRACE_EVENT(kvm_inj_virq, #define kvm_trace_sym_exc \ EXS(DE), EXS(DB), EXS(BP), EXS(OF), EXS(BR), EXS(UD), EXS(NM), \ EXS(DF), EXS(TS), EXS(NP), EXS(SS), EXS(GP), EXS(PF), \ - EXS(MF), EXS(MC) + EXS(MF), EXS(AC), EXS(MC) /* * Tracepoint for kvm interrupt injection: -- cgit v1.2.3 From 18659a9cb1885d00dd428f8857f7f628e54a45ee Mon Sep 17 00:00:00 2001 From: Andrey Smetanin Date: Wed, 23 Dec 2015 16:53:59 +0300 Subject: kvm/x86: Hyper-V SynIC tracepoints Trace the following Hyper SynIC events: * set msr * set sint irq * ack sint * sint irq eoi Signed-off-by: Andrey Smetanin CC: Gleb Natapov CC: Paolo Bonzini CC: Roman Kagan CC: Denis V. Lunev CC: qemu-devel@nongnu.org Signed-off-by: Paolo Bonzini --- arch/x86/kvm/hyperv.c | 10 +++--- arch/x86/kvm/trace.h | 93 +++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 98 insertions(+), 5 deletions(-) (limited to 'arch/x86/kvm/trace.h') diff --git a/arch/x86/kvm/hyperv.c b/arch/x86/kvm/hyperv.c index 101c2e4a0255..2d83d4598507 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 ab9ae67a80e4..4be350003bce 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 -- cgit v1.2.3 From ac3e5fcae8ca658e7dcc3fdcd50af7e4779f58c1 Mon Sep 17 00:00:00 2001 From: Andrey Smetanin Date: Wed, 23 Dec 2015 16:54:00 +0300 Subject: kvm/x86: Hyper-V SynIC timers tracepoints 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 CC: Gleb Natapov CC: Paolo Bonzini CC: Roman Kagan CC: Denis V. Lunev CC: qemu-devel@nongnu.org Signed-off-by: Paolo Bonzini --- arch/x86/kvm/hyperv.c | 27 +++++++- arch/x86/kvm/trace.h | 170 ++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 196 insertions(+), 1 deletion(-) (limited to 'arch/x86/kvm/trace.h') diff --git a/arch/x86/kvm/hyperv.c b/arch/x86/kvm/hyperv.c index 2d83d4598507..c58ba67175ac 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; @@ -448,6 +453,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)), @@ -466,6 +476,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); @@ -475,6 +489,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; @@ -486,6 +503,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) @@ -564,8 +584,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 4be350003bce..ad9f6a23f139 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 -- cgit v1.2.3