All of lore.kernel.org
 help / color / mirror / Atom feed
* KVM: x86: switch unhandled MSR printk's to tracepoints
@ 2013-02-11 23:50 Marcelo Tosatti
  2013-02-12 12:33 ` Gleb Natapov
  0 siblings, 1 reply; 3+ messages in thread
From: Marcelo Tosatti @ 2013-02-11 23:50 UTC (permalink / raw)
  To: kvm; +Cc: Gleb Natapov


Such messages in the system log very often cause confusion because users
understand the "kvm: unhandled MSR" messages as errors.

Switch to trace points, making the information available on demand.

diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
index fe5e00e..c461368 100644
--- a/arch/x86/kvm/trace.h
+++ b/arch/x86/kvm/trace.h
@@ -318,6 +318,40 @@ TRACE_EVENT(kvm_msr,
 #define trace_kvm_msr_write_ex(ecx, data)  trace_kvm_msr(1, ecx, data, true)
 
 /*
+ * Tracepoint for unhandled guest MSR access.
+ */
+TRACE_EVENT(kvm_msr_unhandled,
+	TP_PROTO(bool write, u32 ecx, u64 data, bool unhandled),
+	TP_ARGS(write, ecx, data, unhandled),
+
+	TP_STRUCT__entry(
+		__field(	u32,		ecx		)
+		__field(	u64,		data		)
+		__field(	bool,		write		)
+		__field(	bool,		unhandled	)
+	),
+
+	TP_fast_assign(
+		__entry->ecx		= ecx;
+		__entry->data		= data;
+		__entry->write		= write;
+		__entry->unhandled	= unhandled;
+	),
+
+	TP_printk("unhandled MSR %s %x = 0x%llx (%s)",
+		  __entry->write ? "write" : "read",
+		  __entry->ecx, __entry->data,
+		  __entry->unhandled ? "injected #GP" : "ignored")
+);
+
+#define trace_kvm_msr_unhandled_read(ecx) trace_kvm_msr(0, ecx, 0, false)
+#define trace_kvm_msr_unhandled_read_ex(ecx) trace_kvm_msr(0, ecx, 0, true)
+#define trace_kvm_msr_unhandled_write(ecx, data)	\
+					  trace_kvm_msr(1, ecx, data, false)
+#define trace_kvm_msr_unhandled_write_ex(ecx, data)	\
+					  trace_kvm_msr(1, ecx, data, true)
+
+/*
  * Tracepoint for guest CR access.
  */
 TRACE_EVENT(kvm_cr,
diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
index c243b81..f5abcce 100644
--- a/arch/x86/kvm/x86.c
+++ b/arch/x86/kvm/x86.c
@@ -1772,8 +1772,7 @@ static int set_msr_hyperv_pw(struct kvm_vcpu *vcpu, u32 msr, u64 data)
 		break;
 	}
 	default:
-		vcpu_unimpl(vcpu, "HYPER-V unimplemented wrmsr: 0x%x "
-			    "data 0x%llx\n", msr, data);
+		trace_kvm_msr_unhandled_write_ex(msr, data);
 		return 1;
 	}
 	return 0;
@@ -1805,8 +1804,7 @@ static int set_msr_hyperv(struct kvm_vcpu *vcpu, u32 msr, u64 data)
 	case HV_X64_MSR_TPR:
 		return kvm_hv_vapic_msr_write(vcpu, APIC_TASKPRI, data);
 	default:
-		vcpu_unimpl(vcpu, "HYPER-V unimplemented wrmsr: 0x%x "
-			    "data 0x%llx\n", msr, data);
+		trace_kvm_msr_unhandled_write_ex(msr, data);
 		return 1;
 	}
 
@@ -1888,15 +1886,13 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
 		data &= ~(u64)0x100;	/* ignore ignne emulation enable */
 		data &= ~(u64)0x8;	/* ignore TLB cache disable */
 		if (data != 0) {
-			vcpu_unimpl(vcpu, "unimplemented HWCR wrmsr: 0x%llx\n",
-				    data);
+			trace_kvm_msr_unhandled_write_ex(msr, data);
 			return 1;
 		}
 		break;
 	case MSR_FAM10H_MMIO_CONF_BASE:
 		if (data != 0) {
-			vcpu_unimpl(vcpu, "unimplemented MMIO_CONF_BASE wrmsr: "
-				    "0x%llx\n", data);
+			trace_kvm_msr_unhandled_write_ex(msr, data);
 			return 1;
 		}
 		break;
@@ -1911,8 +1907,8 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
 			   thus reserved and should throw a #GP */
 			return 1;
 		}
-		vcpu_unimpl(vcpu, "%s: MSR_IA32_DEBUGCTLMSR 0x%llx, nop\n",
-			    __func__, data);
+
+		trace_kvm_msr_unhandled_write(msr, data);
 		break;
 	case MSR_IA32_UCODE_REV:
 	case MSR_IA32_UCODE_WRITE:
@@ -2020,8 +2016,7 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
 	case MSR_K7_EVNTSEL2:
 	case MSR_K7_EVNTSEL3:
 		if (data != 0)
-			vcpu_unimpl(vcpu, "unimplemented perfctr wrmsr: "
-				    "0x%x data 0x%llx\n", msr, data);
+			trace_kvm_msr_unhandled_write(msr, data);
 		break;
 	/* at least RHEL 4 unconditionally writes to the perfctr registers,
 	 * so we ignore writes to make it happy.
@@ -2030,8 +2025,7 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
 	case MSR_K7_PERFCTR1:
 	case MSR_K7_PERFCTR2:
 	case MSR_K7_PERFCTR3:
-		vcpu_unimpl(vcpu, "unimplemented perfctr wrmsr: "
-			    "0x%x data 0x%llx\n", msr, data);
+		trace_kvm_msr_unhandled_write(msr, data);
 		break;
 	case MSR_P6_PERFCTR0:
 	case MSR_P6_PERFCTR1:
@@ -2042,8 +2036,7 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
 			return kvm_pmu_set_msr(vcpu, msr, data);
 
 		if (pr || data != 0)
-			vcpu_unimpl(vcpu, "disabled perfctr wrmsr: "
-				    "0x%x data 0x%llx\n", msr, data);
+			trace_kvm_msr_unhandled_write(msr, data);
 		break;
 	case MSR_K7_CLK_CTL:
 		/*
@@ -2069,7 +2062,7 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
 		/* Drop writes to this legacy MSR -- see rdmsr
 		 * counterpart for further detail.
 		 */
-		vcpu_unimpl(vcpu, "ignored wrmsr: 0x%x data %llx\n", msr, data);
+		trace_kvm_msr_unhandled_write(msr, data);
 		break;
 	case MSR_AMD64_OSVW_ID_LENGTH:
 		if (!guest_cpuid_has_osvw(vcpu))
@@ -2087,12 +2080,10 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
 		if (kvm_pmu_msr(vcpu, msr))
 			return kvm_pmu_set_msr(vcpu, msr, data);
 		if (!ignore_msrs) {
-			vcpu_unimpl(vcpu, "unhandled wrmsr: 0x%x data %llx\n",
-				    msr, data);
+			trace_kvm_msr_unhandled_write_ex(msr, data);
 			return 1;
 		} else {
-			vcpu_unimpl(vcpu, "ignored wrmsr: 0x%x data %llx\n",
-				    msr, data);
+			trace_kvm_msr_unhandled_write(msr, data);
 			break;
 		}
 	}
@@ -2195,7 +2186,7 @@ static int get_msr_hyperv_pw(struct kvm_vcpu *vcpu, u32 msr, u64 *pdata)
 		data = kvm->arch.hv_hypercall;
 		break;
 	default:
-		vcpu_unimpl(vcpu, "Hyper-V unhandled rdmsr: 0x%x\n", msr);
+		trace_kvm_msr_unhandled_write_ex(msr, data);
 		return 1;
 	}
 
@@ -2226,7 +2217,7 @@ static int get_msr_hyperv(struct kvm_vcpu *vcpu, u32 msr, u64 *pdata)
 		data = vcpu->arch.hv_vapic;
 		break;
 	default:
-		vcpu_unimpl(vcpu, "Hyper-V unhandled rdmsr: 0x%x\n", msr);
+		trace_kvm_msr_unhandled_read_ex(msr);
 		return 1;
 	}
 	*pdata = data;
@@ -2385,10 +2376,10 @@ int kvm_get_msr_common(struct kvm_vcpu *vcpu, u32 msr, u64 *pdata)
 		if (kvm_pmu_msr(vcpu, msr))
 			return kvm_pmu_get_msr(vcpu, msr, pdata);
 		if (!ignore_msrs) {
-			vcpu_unimpl(vcpu, "unhandled rdmsr: 0x%x\n", msr);
+			trace_kvm_msr_unhandled_read_ex(msr);
 			return 1;
 		} else {
-			vcpu_unimpl(vcpu, "ignored rdmsr: 0x%x\n", msr);
+			trace_kvm_msr_unhandled_read(msr);
 			data = 0;
 		}
 		break;


^ permalink raw reply related	[flat|nested] 3+ messages in thread
* Re: KVM: x86: switch unhandled MSR printk's to tracepoints
  2013-02-11 23:50 KVM: x86: switch unhandled MSR printk's to tracepoints Marcelo Tosatti
@ 2013-02-12 12:33 ` Gleb Natapov
  2013-02-12 12:54   ` Marcelo Tosatti
  0 siblings, 1 reply; 3+ messages in thread
From: Gleb Natapov @ 2013-02-12 12:33 UTC (permalink / raw)
  To: Marcelo Tosatti; +Cc: kvm

On Mon, Feb 11, 2013 at 09:50:09PM -0200, Marcelo Tosatti wrote:
> 
> Such messages in the system log very often cause confusion because users
> understand the "kvm: unhandled MSR" messages as errors.
> 
They are errors. Linux compiled with PV support ignores them, but other
guest OSes or Linux without PV will crash. Some indication that guest
crash due to use of unsupported MSR is a helpful hint where to look.

> Switch to trace points, making the information available on demand.
What new information those trace points provide that we cannot get today
from trace_kvm_msr()?

> 
> diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
> index fe5e00e..c461368 100644
> --- a/arch/x86/kvm/trace.h
> +++ b/arch/x86/kvm/trace.h
> @@ -318,6 +318,40 @@ TRACE_EVENT(kvm_msr,
>  #define trace_kvm_msr_write_ex(ecx, data)  trace_kvm_msr(1, ecx, data, true)
>  
>  /*
> + * Tracepoint for unhandled guest MSR access.
> + */
> +TRACE_EVENT(kvm_msr_unhandled,
> +	TP_PROTO(bool write, u32 ecx, u64 data, bool unhandled),
> +	TP_ARGS(write, ecx, data, unhandled),
> +
> +	TP_STRUCT__entry(
> +		__field(	u32,		ecx		)
> +		__field(	u64,		data		)
> +		__field(	bool,		write		)
> +		__field(	bool,		unhandled	)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->ecx		= ecx;
> +		__entry->data		= data;
> +		__entry->write		= write;
> +		__entry->unhandled	= unhandled;
> +	),
> +
> +	TP_printk("unhandled MSR %s %x = 0x%llx (%s)",
> +		  __entry->write ? "write" : "read",
> +		  __entry->ecx, __entry->data,
> +		  __entry->unhandled ? "injected #GP" : "ignored")
> +);
> +
> +#define trace_kvm_msr_unhandled_read(ecx) trace_kvm_msr(0, ecx, 0, false)
> +#define trace_kvm_msr_unhandled_read_ex(ecx) trace_kvm_msr(0, ecx, 0, true)
> +#define trace_kvm_msr_unhandled_write(ecx, data)	\
> +					  trace_kvm_msr(1, ecx, data, false)
> +#define trace_kvm_msr_unhandled_write_ex(ecx, data)	\
> +					  trace_kvm_msr(1, ecx, data, true)
> +
> +/*
>   * Tracepoint for guest CR access.
>   */
>  TRACE_EVENT(kvm_cr,
> diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
> index c243b81..f5abcce 100644
> --- a/arch/x86/kvm/x86.c
> +++ b/arch/x86/kvm/x86.c
> @@ -1772,8 +1772,7 @@ static int set_msr_hyperv_pw(struct kvm_vcpu *vcpu, u32 msr, u64 data)
>  		break;
>  	}
>  	default:
> -		vcpu_unimpl(vcpu, "HYPER-V unimplemented wrmsr: 0x%x "
> -			    "data 0x%llx\n", msr, data);
> +		trace_kvm_msr_unhandled_write_ex(msr, data);
>  		return 1;
>  	}
>  	return 0;
> @@ -1805,8 +1804,7 @@ static int set_msr_hyperv(struct kvm_vcpu *vcpu, u32 msr, u64 data)
>  	case HV_X64_MSR_TPR:
>  		return kvm_hv_vapic_msr_write(vcpu, APIC_TASKPRI, data);
>  	default:
> -		vcpu_unimpl(vcpu, "HYPER-V unimplemented wrmsr: 0x%x "
> -			    "data 0x%llx\n", msr, data);
> +		trace_kvm_msr_unhandled_write_ex(msr, data);
>  		return 1;
>  	}
>  
> @@ -1888,15 +1886,13 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
>  		data &= ~(u64)0x100;	/* ignore ignne emulation enable */
>  		data &= ~(u64)0x8;	/* ignore TLB cache disable */
>  		if (data != 0) {
> -			vcpu_unimpl(vcpu, "unimplemented HWCR wrmsr: 0x%llx\n",
> -				    data);
> +			trace_kvm_msr_unhandled_write_ex(msr, data);
>  			return 1;
>  		}
>  		break;
>  	case MSR_FAM10H_MMIO_CONF_BASE:
>  		if (data != 0) {
> -			vcpu_unimpl(vcpu, "unimplemented MMIO_CONF_BASE wrmsr: "
> -				    "0x%llx\n", data);
> +			trace_kvm_msr_unhandled_write_ex(msr, data);
>  			return 1;
>  		}
>  		break;
> @@ -1911,8 +1907,8 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
>  			   thus reserved and should throw a #GP */
>  			return 1;
>  		}
> -		vcpu_unimpl(vcpu, "%s: MSR_IA32_DEBUGCTLMSR 0x%llx, nop\n",
> -			    __func__, data);
> +
> +		trace_kvm_msr_unhandled_write(msr, data);
>  		break;
>  	case MSR_IA32_UCODE_REV:
>  	case MSR_IA32_UCODE_WRITE:
> @@ -2020,8 +2016,7 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
>  	case MSR_K7_EVNTSEL2:
>  	case MSR_K7_EVNTSEL3:
>  		if (data != 0)
> -			vcpu_unimpl(vcpu, "unimplemented perfctr wrmsr: "
> -				    "0x%x data 0x%llx\n", msr, data);
> +			trace_kvm_msr_unhandled_write(msr, data);
>  		break;
>  	/* at least RHEL 4 unconditionally writes to the perfctr registers,
>  	 * so we ignore writes to make it happy.
> @@ -2030,8 +2025,7 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
>  	case MSR_K7_PERFCTR1:
>  	case MSR_K7_PERFCTR2:
>  	case MSR_K7_PERFCTR3:
> -		vcpu_unimpl(vcpu, "unimplemented perfctr wrmsr: "
> -			    "0x%x data 0x%llx\n", msr, data);
> +		trace_kvm_msr_unhandled_write(msr, data);
>  		break;
>  	case MSR_P6_PERFCTR0:
>  	case MSR_P6_PERFCTR1:
> @@ -2042,8 +2036,7 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
>  			return kvm_pmu_set_msr(vcpu, msr, data);
>  
>  		if (pr || data != 0)
> -			vcpu_unimpl(vcpu, "disabled perfctr wrmsr: "
> -				    "0x%x data 0x%llx\n", msr, data);
> +			trace_kvm_msr_unhandled_write(msr, data);
>  		break;
>  	case MSR_K7_CLK_CTL:
>  		/*
> @@ -2069,7 +2062,7 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
>  		/* Drop writes to this legacy MSR -- see rdmsr
>  		 * counterpart for further detail.
>  		 */
> -		vcpu_unimpl(vcpu, "ignored wrmsr: 0x%x data %llx\n", msr, data);
> +		trace_kvm_msr_unhandled_write(msr, data);
>  		break;
>  	case MSR_AMD64_OSVW_ID_LENGTH:
>  		if (!guest_cpuid_has_osvw(vcpu))
> @@ -2087,12 +2080,10 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
>  		if (kvm_pmu_msr(vcpu, msr))
>  			return kvm_pmu_set_msr(vcpu, msr, data);
>  		if (!ignore_msrs) {
> -			vcpu_unimpl(vcpu, "unhandled wrmsr: 0x%x data %llx\n",
> -				    msr, data);
> +			trace_kvm_msr_unhandled_write_ex(msr, data);
>  			return 1;
>  		} else {
> -			vcpu_unimpl(vcpu, "ignored wrmsr: 0x%x data %llx\n",
> -				    msr, data);
> +			trace_kvm_msr_unhandled_write(msr, data);
>  			break;
>  		}
>  	}
> @@ -2195,7 +2186,7 @@ static int get_msr_hyperv_pw(struct kvm_vcpu *vcpu, u32 msr, u64 *pdata)
>  		data = kvm->arch.hv_hypercall;
>  		break;
>  	default:
> -		vcpu_unimpl(vcpu, "Hyper-V unhandled rdmsr: 0x%x\n", msr);
> +		trace_kvm_msr_unhandled_write_ex(msr, data);
>  		return 1;
>  	}
>  
> @@ -2226,7 +2217,7 @@ static int get_msr_hyperv(struct kvm_vcpu *vcpu, u32 msr, u64 *pdata)
>  		data = vcpu->arch.hv_vapic;
>  		break;
>  	default:
> -		vcpu_unimpl(vcpu, "Hyper-V unhandled rdmsr: 0x%x\n", msr);
> +		trace_kvm_msr_unhandled_read_ex(msr);
>  		return 1;
>  	}
>  	*pdata = data;
> @@ -2385,10 +2376,10 @@ int kvm_get_msr_common(struct kvm_vcpu *vcpu, u32 msr, u64 *pdata)
>  		if (kvm_pmu_msr(vcpu, msr))
>  			return kvm_pmu_get_msr(vcpu, msr, pdata);
>  		if (!ignore_msrs) {
> -			vcpu_unimpl(vcpu, "unhandled rdmsr: 0x%x\n", msr);
> +			trace_kvm_msr_unhandled_read_ex(msr);
>  			return 1;
>  		} else {
> -			vcpu_unimpl(vcpu, "ignored rdmsr: 0x%x\n", msr);
> +			trace_kvm_msr_unhandled_read(msr);
>  			data = 0;
>  		}
>  		break;

--
			Gleb.

^ permalink raw reply	[flat|nested] 3+ messages in thread
* Re: KVM: x86: switch unhandled MSR printk's to tracepoints
  2013-02-12 12:33 ` Gleb Natapov
@ 2013-02-12 12:54   ` Marcelo Tosatti
  0 siblings, 0 replies; 3+ messages in thread
From: Marcelo Tosatti @ 2013-02-12 12:54 UTC (permalink / raw)
  To: Gleb Natapov; +Cc: kvm

On Tue, Feb 12, 2013 at 02:33:17PM +0200, Gleb Natapov wrote:
> On Mon, Feb 11, 2013 at 09:50:09PM -0200, Marcelo Tosatti wrote:
> > 
> > Such messages in the system log very often cause confusion because users
> > understand the "kvm: unhandled MSR" messages as errors.
> > 
> They are errors. Linux compiled with PV support ignores them, but other
> guest OSes or Linux without PV will crash. Some indication that guest
> crash due to use of unsupported MSR is a helpful hint where to look.

OK, closing 
https://bugzilla.redhat.com/show_bug.cgi?id=883216
as wontfix because printk_ratelimit renders the messages unreliable.

> > Switch to trace points, making the information available on demand.
> What new information those trace points provide that we cannot get today
> from trace_kvm_msr()?

None. 


^ permalink raw reply	[flat|nested] 3+ messages in thread
end of thread, other threads:[~2013-02-12 12:54 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2013-02-11 23:50 KVM: x86: switch unhandled MSR printk's to tracepoints Marcelo Tosatti
2013-02-12 12:33 ` Gleb Natapov
2013-02-12 12:54   ` Marcelo Tosatti

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.