Re: [PATCH 2/2] KVM: Trace emulated instructions

[Marcelo Tosatti <mtosatti@redhat.com>]

On Thu, Mar 25, 2010 at 05:02:56PM +0200, Avi Kivity wrote:
> Log emulated instructions in ftrace, especially if they failed.
> 
> Signed-off-by: Avi Kivity <avi@redhat.com>
> ---
>  arch/x86/kvm/trace.h |   86 ++++++++++++++++++++++++++++++++++++++++++++++++++
>  arch/x86/kvm/x86.c   |    4 ++
>  2 files changed, 90 insertions(+), 0 deletions(-)
> 
> diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
> index 32c912c..a6544b8 100644
> --- a/arch/x86/kvm/trace.h
> +++ b/arch/x86/kvm/trace.h
> @@ -603,6 +603,92 @@ TRACE_EVENT(kvm_skinit,
>  		  __entry->rip, __entry->slb)
>  );
>  
> +#define __print_insn(insn, ilen) ({		                 \
> +	int i;							 \
> +	const char *ret = p->buffer + p->len;			 \
> +								 \
> +	for (i = 0; i < ilen; ++i)				 \
> +		trace_seq_printf(p, " %02x", insn[i]);		 \
> +	trace_seq_printf(p, "%c", 0);				 \
> +	ret;							 \
> +	})
> +
> +#define KVM_EMUL_INSN_F_CR0_PE (1 << 0)
> +#define KVM_EMUL_INSN_F_EFL_VM (1 << 1)
> +#define KVM_EMUL_INSN_F_CS_D   (1 << 2)
> +#define KVM_EMUL_INSN_F_CS_L   (1 << 3)
> +
> +#define kvm_trace_symbol_emul_flags	                  \
> +	{ 0,   			    "real" },		  \
> +	{ KVM_EMUL_INSN_F_CR0_PE			  \
> +	  | KVM_EMUL_INSN_F_EFL_VM, "vm16" },		  \
> +	{ KVM_EMUL_INSN_F_CR0_PE,   "prot16" },		  \
> +	{ KVM_EMUL_INSN_F_CR0_PE			  \
> +	  | KVM_EMUL_INSN_F_CS_D,   "prot32" },		  \
> +	{ KVM_EMUL_INSN_F_CR0_PE			  \
> +	  | KVM_EMUL_INSN_F_CS_L,   "prot64" }
> +
> +#define kei_decode_mode(mode) ({			\
> +	u8 flags = 0xff;				\
> +	switch (mode) {					\
> +	case X86EMUL_MODE_REAL:				\
> +		flags = 0;				\
> +		break;					\
> +	case X86EMUL_MODE_VM86:				\
> +		flags = KVM_EMUL_INSN_F_EFL_VM;		\
> +		break;					\
> +	case X86EMUL_MODE_PROT16:			\
> +		flags = KVM_EMUL_INSN_F_CR0_PE;		\
> +		break;					\
> +	case X86EMUL_MODE_PROT32:			\
> +		flags = KVM_EMUL_INSN_F_CR0_PE		\
> +			| KVM_EMUL_INSN_F_CS_D;		\
> +		break;					\
> +	case X86EMUL_MODE_PROT64:			\
> +		flags = KVM_EMUL_INSN_F_CR0_PE		\
> +			| KVM_EMUL_INSN_F_CS_L;		\
> +		break;					\
> +	}						\
> +	flags;						\
> +	})
> +
> +TRACE_EVENT(kvm_emulate_insn,
> +	TP_PROTO(struct kvm_vcpu *vcpu, __u8 failed),
> +	TP_ARGS(vcpu, failed),
> +
> +	TP_STRUCT__entry(
> +		__field(    __u64, rip                       )
> +		__field(    __u32, csbase                    )
> +		__field(    __u8,  len                       )
> +		__array(    __u8,  insn,    15	             )
> +		__field(    __u8,  flags       	   	     )
> +		__field(    __u8,  failed                    )
> +		),
> +
> +	TP_fast_assign(
> +		__entry->rip = vcpu->arch.emulate_ctxt.decode.fetch.start;
> +		__entry->csbase = kvm_x86_ops->get_segment_base(vcpu, VCPU_SREG_CS);
> +		__entry->len = vcpu->arch.emulate_ctxt.decode.eip
> +			       - vcpu->arch.emulate_ctxt.decode.fetch.start;
> +		memcpy(__entry->insn,
> +		       vcpu->arch.emulate_ctxt.decode.fetch.data,
> +		       15);
> +		__entry->flags = kei_decode_mode(vcpu->arch.emulate_ctxt.mode);
> +		__entry->failed = failed;
> +		),
> +
> +	TP_printk("%x:%llx:%s (%s)%s",
> +		  __entry->csbase, __entry->rip,
> +		  __print_insn(__entry->insn, __entry->len),
> +		  __print_symbolic(__entry->flags,
> +				   kvm_trace_symbol_emul_flags),
> +		  __entry->failed ? " failed" : ""
> +		)
> +	);
> +
> +#define trace_kvm_emulate_insn_start(vcpu) trace_kvm_emulate_insn(vcpu, 0)
> +#define trace_kvm_emulate_insn_failed(vcpu) trace_kvm_emulate_insn(vcpu, 1)
> +
>  #endif /* _TRACE_KVM_H */
>  
>  #undef TRACE_INCLUDE_PATH
> diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
> index fd5c3d3..9413da5 100644
> --- a/arch/x86/kvm/x86.c
> +++ b/arch/x86/kvm/x86.c
> @@ -3750,6 +3750,7 @@ int emulate_instruction(struct kvm_vcpu *vcpu,
>  			++vcpu->stat.insn_emulation_fail;
>  			if (kvm_mmu_unprotect_page_virt(vcpu, cr2))
>  				return EMULATE_DONE;
> +			trace_kvm_emulate_insn_failed(vcpu);
>  			return EMULATE_FAIL;
>  		}
>  	}
> @@ -3767,6 +3768,7 @@ restart:
>  		kvm_x86_ops->set_interrupt_shadow(vcpu, shadow_mask);
>  
>  	if (vcpu->arch.pio.count) {
> +		trace_kvm_emulate_insn_start(vcpu);

Why not log all emulated instructions? Seems useful to me.