[PATCH 0/2] Trace emulated instrucions

[PATCH 0/2] Trace emulated instrucions

[Avi Kivity]

Add a trace of instruction emulation into ftrace.  This can help analyze
performance issues, or, in the case of failed emulation, identify the
missing instructions.

Avi Kivity (2):
  KVM: x86 emulator: Don't overwrite decode cache
  KVM: Trace emulated instructions

 arch/x86/kvm/emulate.c |   19 +++++-----
 arch/x86/kvm/trace.h   |   86 ++++++++++++++++++++++++++++++++++++++++++++++++
 arch/x86/kvm/x86.c     |    4 ++
 3 files changed, 100 insertions(+), 9 deletions(-)

[PATCH 1/2] KVM: x86 emulator: Don't overwrite decode cache

[Avi Kivity]

Currently if we an instruction spans a page boundary, when we fetch the
second half we overwrite the first half.  This prevents us from tracing
the full instruction opcodes.

Fix by appending the second half to the first.

Signed-off-by: Avi Kivity <avi@redhat.com>
---
 arch/x86/kvm/emulate.c |   19 ++++++++++---------
 1 files changed, 10 insertions(+), 9 deletions(-)

diff --git a/arch/x86/kvm/emulate.c b/arch/x86/kvm/emulate.c
index 64c9854..083b269 100644
--- a/arch/x86/kvm/emulate.c
+++ b/arch/x86/kvm/emulate.c
@@ -646,21 +646,22 @@ static unsigned long ss_base(struct x86_emulate_ctxt *ctxt)
 
 static int do_fetch_insn_byte(struct x86_emulate_ctxt *ctxt,
 			      struct x86_emulate_ops *ops,
-			      unsigned long linear, u8 *dest)
+			      unsigned long eip, u8 *dest)
 {
 	struct fetch_cache *fc = &ctxt->decode.fetch;
 	int rc;
-	int size;
+	int size, cur_size;
 
-	if (linear < fc->start || linear >= fc->end) {
-		size = min(15UL, PAGE_SIZE - offset_in_page(linear));
-		rc = ops->fetch(linear, fc->data, size, ctxt->vcpu, NULL);
+	if (eip == fc->end) {
+		cur_size = fc->end - fc->start;
+		size = min(15UL - cur_size, PAGE_SIZE - offset_in_page(eip));
+		rc = ops->fetch(ctxt->cs_base + eip, fc->data + cur_size,
+				size, ctxt->vcpu, NULL);
 		if (rc != X86EMUL_CONTINUE)
 			return rc;
-		fc->start = linear;
-		fc->end = linear + size;
+		fc->end += size;
 	}
-	*dest = fc->data[linear - fc->start];
+	*dest = fc->data[eip - fc->start];
 	return X86EMUL_CONTINUE;
 }
 
@@ -673,7 +674,6 @@ static int do_insn_fetch(struct x86_emulate_ctxt *ctxt,
 	/* x86 instructions are limited to 15 bytes. */
 	if (eip + size - ctxt->eip > 15)
 		return X86EMUL_UNHANDLEABLE;
-	eip += ctxt->cs_base;
 	while (size--) {
 		rc = do_fetch_insn_byte(ctxt, ops, eip++, dest++);
 		if (rc != X86EMUL_CONTINUE)
@@ -935,6 +935,7 @@ x86_decode_insn(struct x86_emulate_ctxt *ctxt, struct x86_emulate_ops *ops)
 	/* Shadow copy of register state. Committed on successful emulation. */
 	memset(c, 0, sizeof(struct decode_cache));
 	c->eip = ctxt->eip;
+	c->fetch.start = c->fetch.end = c->eip;
 	ctxt->cs_base = seg_base(ctxt, VCPU_SREG_CS);
 	memcpy(c->regs, ctxt->vcpu->arch.regs, sizeof c->regs);
 
-- 
1.7.0.2

[PATCH 2/2] KVM: Trace emulated instructions

[Avi Kivity]

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);
 		if (!vcpu->arch.pio.in)
 			vcpu->arch.pio.count = 0;
 		return EMULATE_DO_MMIO;
@@ -3784,9 +3786,11 @@ restart:
 		if (kvm_mmu_unprotect_page_virt(vcpu, cr2))
 			goto done;
 		if (!vcpu->mmio_needed) {
+			trace_kvm_emulate_insn_failed(vcpu);
 			kvm_report_emulation_failure(vcpu, "mmio");
 			return EMULATE_FAIL;
 		}
+		trace_kvm_emulate_insn_start(vcpu);
 		return EMULATE_DO_MMIO;
 	}
 
-- 
1.7.0.2

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

[Marcelo Tosatti]

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.

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

[Avi Kivity]

On 04/05/2010 09:44 PM, Marcelo Tosatti wrote:
> On Thu, Mar 25, 2010 at 05:02:56PM +0200, Avi Kivity wrote:
>    
>> Log emulated instructions in ftrace, especially if they failed.
>>      
> Why not log all emulated instructions? Seems useful to me.
>
>    

That was the intent, but it didn't pan out.  I tried to avoid 
double-logging where an mmio read is dispatched to userspace, and the 
instruction is re-executed.

Perhaps we should split it into a decode trace and execution result 
trace?  Less easy to use but avoids confusion due to duplication.

-- 
Do not meddle in the internals of kernels, for they are subtle and quick to panic.

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

[Marcelo Tosatti]

On Tue, Apr 06, 2010 at 12:38:00AM +0300, Avi Kivity wrote:
> On 04/05/2010 09:44 PM, Marcelo Tosatti wrote:
> >On Thu, Mar 25, 2010 at 05:02:56PM +0200, Avi Kivity wrote:
> >>Log emulated instructions in ftrace, especially if they failed.
> >Why not log all emulated instructions? Seems useful to me.
> >
> 
> That was the intent, but it didn't pan out.  I tried to avoid
> double-logging where an mmio read is dispatched to userspace, and
> the instruction is re-executed.
> 
> Perhaps we should split it into a decode trace and execution result
> trace?  Less easy to use but avoids confusion due to duplication.

I don't think duplication introduces confusion, as long as one can see
rip on the trace entry (the duplication can actually be useful).

[PATCH 2/2] KVM: Trace emulated instructions

[Avi Kivity]

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..b3adb5e 100644
--- a/arch/x86/kvm/x86.c
+++ b/arch/x86/kvm/x86.c
@@ -3716,6 +3716,7 @@ int emulate_instruction(struct kvm_vcpu *vcpu,
 			? X86EMUL_MODE_PROT32 : X86EMUL_MODE_PROT16;
 
 		r = x86_decode_insn(&vcpu->arch.emulate_ctxt, &emulate_ops);
+		trace_kvm_emulate_insn_start(vcpu);
 
 		/* Only allow emulation of specific instructions on #UD
 		 * (namely VMMCALL, sysenter, sysexit, syscall)*/
@@ -3748,6 +3749,7 @@ int emulate_instruction(struct kvm_vcpu *vcpu,
 		++vcpu->stat.insn_emulation;
 		if (r)  {
 			++vcpu->stat.insn_emulation_fail;
+			trace_kvm_emulate_insn_failed(vcpu);
 			if (kvm_mmu_unprotect_page_virt(vcpu, cr2))
 				return EMULATE_DONE;
 			return EMULATE_FAIL;
@@ -3784,6 +3786,8 @@ restart:
 		if (kvm_mmu_unprotect_page_virt(vcpu, cr2))
 			goto done;
 		if (!vcpu->mmio_needed) {
+			++vcpu->stat.insn_emulation_fail;
+			trace_kvm_emulate_insn_failed(vcpu);
 			kvm_report_emulation_failure(vcpu, "mmio");
 			return EMULATE_FAIL;
 		}
-- 
1.7.0.4