[PATCH 0/4] kvm: x86: introduce CONFIG_KVM_DEBUG

[PATCH 0/4] kvm: x86: introduce CONFIG_KVM_DEBUG

[Yi Wang]

This series introduce CONFIG_KVM_DEBUG, using which we can make
the invoking *_debug in KVM simly and uniform.

FYI: the former discussion can been found in:
https://www.spinics.net/lists/kvm/msg187026.html

Yi Wang (4):
  kvm: x86: Add CONFIG_KVM_DEBUG
  kvm: x86: allow set apic and ioapic debug dynamically
  kvm: x86: replace MMU_DEBUG with CONFIG_KVM_DEBUG
  kvm: x86: convert TSC pr_debugs to be gated by CONFIG_KVM_DEBUG

 arch/x86/kvm/Kconfig  |  8 ++++++++
 arch/x86/kvm/ioapic.c |  2 +-
 arch/x86/kvm/lapic.c  |  5 ++++-
 arch/x86/kvm/mmu.c    |  5 ++---
 arch/x86/kvm/x86.c    | 18 ++++++++++++------
 5 files changed, 27 insertions(+), 11 deletions(-)

-- 
1.8.3.1

[PATCH 1/4] kvm: x86: Add CONFIG_KVM_DEBUG

[Yi Wang]

There are some *_debug functions in KVM, it may be
better to introduce CONFIG_DEBUG_KVM to replace the
*_debug macro, which can avoid bloating and slowing KVM,
as Sean suggested.

Signed-off-by: Yi Wang <wang.yi59@zte.com.cn>
---
 arch/x86/kvm/Kconfig | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/arch/x86/kvm/Kconfig b/arch/x86/kvm/Kconfig
index fc04241..7e76eb2 100644
--- a/arch/x86/kvm/Kconfig
+++ b/arch/x86/kvm/Kconfig
@@ -95,6 +95,14 @@ config KVM_MMU_AUDIT
 	 This option adds a R/W kVM module parameter 'mmu_audit', which allows
 	 auditing of KVM MMU events at runtime.
 
+config KVM_DEBUG
+	bool "Enable KVM debugging"
+	default n
+	depends on KVM
+	---help---
+	Say Y here if you want to enable verbose KVM debug output.
+
+
 # OK, it's a little counter-intuitive to do this, but it puts it neatly under
 # the virtualization menu.
 source "drivers/vhost/Kconfig"
-- 
1.8.3.1

[PATCH 2/4] kvm: x86: allow set apic and ioapic debug dynamically

[Yi Wang]

There are two *_debug() macros in kvm apic source file:
- ioapic_debug, which is disable using #if 0
- apic_debug, which is commented

Maybe it's better to control these two macros using CONFIG_KVM_DEBUG,
which can be set in make menuconfig.

Signed-off-by: Yi Wang <wang.yi59@zte.com.cn>
---
 arch/x86/kvm/ioapic.c | 2 +-
 arch/x86/kvm/lapic.c  | 5 ++++-
 2 files changed, 5 insertions(+), 2 deletions(-)

diff --git a/arch/x86/kvm/ioapic.c b/arch/x86/kvm/ioapic.c
index 1add1bc..8099253 100644
--- a/arch/x86/kvm/ioapic.c
+++ b/arch/x86/kvm/ioapic.c
@@ -45,7 +45,7 @@
 #include "lapic.h"
 #include "irq.h"
 
-#if 0
+#ifdef CONFIG_KVM_DEBUG
 #define ioapic_debug(fmt,arg...) printk(KERN_WARNING fmt,##arg)
 #else
 #define ioapic_debug(fmt, arg...)
diff --git a/arch/x86/kvm/lapic.c b/arch/x86/kvm/lapic.c
index 4924f83..dfff5c6 100644
--- a/arch/x86/kvm/lapic.c
+++ b/arch/x86/kvm/lapic.c
@@ -54,8 +54,11 @@
 #define PRIu64 "u"
 #define PRIo64 "o"
 
-/* #define apic_debug(fmt,arg...) printk(KERN_WARNING fmt,##arg) */
+#ifdef CONFIG_KVM_DEBUG
+#define apic_debug(fmt,arg...) printk(KERN_WARNING fmt,##arg)
+#else
 #define apic_debug(fmt, arg...) do {} while (0)
+#endif
 
 /* 14 is the version for Xeon and Pentium 8.4.8*/
 #define APIC_VERSION			(0x14UL | ((KVM_APIC_LVT_NUM - 1) << 16))
-- 
1.8.3.1

Re: [PATCH 2/4] kvm: x86: allow set apic and ioapic debug dynamically

[Paolo Bonzini]

On 01/07/19 08:21, Yi Wang wrote:
> There are two *_debug() macros in kvm apic source file:
> - ioapic_debug, which is disable using #if 0
> - apic_debug, which is commented
> 
> Maybe it's better to control these two macros using CONFIG_KVM_DEBUG,
> which can be set in make menuconfig.
> 
> Signed-off-by: Yi Wang <wang.yi59@zte.com.cn>
> ---
>  arch/x86/kvm/ioapic.c | 2 +-
>  arch/x86/kvm/lapic.c  | 5 ++++-
>  2 files changed, 5 insertions(+), 2 deletions(-)
> 
> diff --git a/arch/x86/kvm/ioapic.c b/arch/x86/kvm/ioapic.c
> index 1add1bc..8099253 100644
> --- a/arch/x86/kvm/ioapic.c
> +++ b/arch/x86/kvm/ioapic.c
> @@ -45,7 +45,7 @@
>  #include "lapic.h"
>  #include "irq.h"
>  
> -#if 0
> +#ifdef CONFIG_KVM_DEBUG
>  #define ioapic_debug(fmt,arg...) printk(KERN_WARNING fmt,##arg)
>  #else
>  #define ioapic_debug(fmt, arg...)
> diff --git a/arch/x86/kvm/lapic.c b/arch/x86/kvm/lapic.c
> index 4924f83..dfff5c6 100644
> --- a/arch/x86/kvm/lapic.c
> +++ b/arch/x86/kvm/lapic.c
> @@ -54,8 +54,11 @@
>  #define PRIu64 "u"
>  #define PRIo64 "o"
>  
> -/* #define apic_debug(fmt,arg...) printk(KERN_WARNING fmt,##arg) */
> +#ifdef CONFIG_KVM_DEBUG
> +#define apic_debug(fmt,arg...) printk(KERN_WARNING fmt,##arg)
> +#else
>  #define apic_debug(fmt, arg...) do {} while (0)
> +#endif
>  
>  /* 14 is the version for Xeon and Pentium 8.4.8*/
>  #define APIC_VERSION			(0x14UL | ((KVM_APIC_LVT_NUM - 1) << 16))
> 

I would just drop all of them.  I've never used them in years, the kvm
tracepoints are enough.

Paolo

Re: [PATCH 2/4] kvm: x86: allow set apic and ioapic debug dynamically

[Liran Alon]

> On 3 Jul 2019, at 19:23, Paolo Bonzini <pbonzini@redhat.com> wrote:
> 
> On 01/07/19 08:21, Yi Wang wrote:
>> There are two *_debug() macros in kvm apic source file:
>> - ioapic_debug, which is disable using #if 0
>> - apic_debug, which is commented
>> 
>> Maybe it's better to control these two macros using CONFIG_KVM_DEBUG,
>> which can be set in make menuconfig.
>> 
>> Signed-off-by: Yi Wang <wang.yi59@zte.com.cn>
>> ---
>> arch/x86/kvm/ioapic.c | 2 +-
>> arch/x86/kvm/lapic.c  | 5 ++++-
>> 2 files changed, 5 insertions(+), 2 deletions(-)
>> 
>> diff --git a/arch/x86/kvm/ioapic.c b/arch/x86/kvm/ioapic.c
>> index 1add1bc..8099253 100644
>> --- a/arch/x86/kvm/ioapic.c
>> +++ b/arch/x86/kvm/ioapic.c
>> @@ -45,7 +45,7 @@
>> #include "lapic.h"
>> #include "irq.h"
>> 
>> -#if 0
>> +#ifdef CONFIG_KVM_DEBUG
>> #define ioapic_debug(fmt,arg...) printk(KERN_WARNING fmt,##arg)
>> #else
>> #define ioapic_debug(fmt, arg...)
>> diff --git a/arch/x86/kvm/lapic.c b/arch/x86/kvm/lapic.c
>> index 4924f83..dfff5c6 100644
>> --- a/arch/x86/kvm/lapic.c
>> +++ b/arch/x86/kvm/lapic.c
>> @@ -54,8 +54,11 @@
>> #define PRIu64 "u"
>> #define PRIo64 "o"
>> 
>> -/* #define apic_debug(fmt,arg...) printk(KERN_WARNING fmt,##arg) */
>> +#ifdef CONFIG_KVM_DEBUG
>> +#define apic_debug(fmt,arg...) printk(KERN_WARNING fmt,##arg)
>> +#else
>> #define apic_debug(fmt, arg...) do {} while (0)
>> +#endif
>> 
>> /* 14 is the version for Xeon and Pentium 8.4.8*/
>> #define APIC_VERSION			(0x14UL | ((KVM_APIC_LVT_NUM - 1) << 16))
>> 
> 
> I would just drop all of them.  I've never used them in years, the kvm
> tracepoints are enough.
> 
> Paolo

As someone who have done many LAPIC/IOAPIC debugging, I tend to agree. :)

-Liran

[PATCH 3/4] kvm: x86: replace MMU_DEBUG with CONFIG_KVM_DEBUG

[Yi Wang]

As CONFIG_KVM_DEBUG has been introduced in the former
patch, it's better to replace MMU_DEBUG with CONFIG_KVM_DEBUG.

Signed-off-by: Yi Wang <wang.yi59@zte.com.cn>
---
 arch/x86/kvm/mmu.c | 5 ++---
 1 file changed, 2 insertions(+), 3 deletions(-)

diff --git a/arch/x86/kvm/mmu.c b/arch/x86/kvm/mmu.c
index 1e9ba81..d54214e 100644
--- a/arch/x86/kvm/mmu.c
+++ b/arch/x86/kvm/mmu.c
@@ -68,9 +68,8 @@ enum {
 	AUDIT_POST_SYNC
 };
 
-#undef MMU_DEBUG
 
-#ifdef MMU_DEBUG
+#ifdef CONFIG_KVM_DEBUG
 static bool dbg = 0;
 module_param(dbg, bool, 0644);
 
@@ -1994,7 +1993,7 @@ int kvm_test_age_hva(struct kvm *kvm, unsigned long hva)
 	return kvm_handle_hva(kvm, hva, 0, kvm_test_age_rmapp);
 }
 
-#ifdef MMU_DEBUG
+#ifdef CONFIG_KVM_DEBUG
 static int is_empty_shadow_page(u64 *spt)
 {
 	u64 *pos;
-- 
1.8.3.1

[PATCH 4/4] kvm: x86: convert TSC pr_debugs to be gated by CONFIG_KVM_DEBUG

[Yi Wang]

There are some pr_debug in TSC code, which may affect
performance, so it may make sense to wrap them using a new
macro tsc_debug which takes effect only when CONFIG_KVM_DEBUG
is defined.

Signed-off-by: Yi Wang <wang.yi59@zte.com.cn>
---
 arch/x86/kvm/x86.c | 18 ++++++++++++------
 1 file changed, 12 insertions(+), 6 deletions(-)

diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
index 83aefd7..1505e53 100644
--- a/arch/x86/kvm/x86.c
+++ b/arch/x86/kvm/x86.c
@@ -74,6 +74,12 @@
 #define CREATE_TRACE_POINTS
 #include "trace.h"
 
+#ifdef CONFIG_KVM_DEBUG
+#define tsc_debug(x...) pr_debug(x)
+#else
+#define tsc_debug(x...)
+#endif
+
 #define MAX_IO_MSRS 256
 #define KVM_MAX_MCE_BANKS 32
 u64 __read_mostly kvm_mce_cap_supported = MCG_CTL_P | MCG_SER_P;
@@ -1522,7 +1528,7 @@ static void kvm_get_time_scale(uint64_t scaled_hz, uint64_t base_hz,
 	*pshift = shift;
 	*pmultiplier = div_frac(scaled64, tps32);
 
-	pr_debug("%s: base_hz %llu => %llu, shift %d, mul %u\n",
+	tsc_debug("%s: base_hz %llu => %llu, shift %d, mul %u\n",
 		 __func__, base_hz, scaled_hz, shift, *pmultiplier);
 }
 
@@ -1603,7 +1609,7 @@ static int kvm_set_tsc_khz(struct kvm_vcpu *vcpu, u32 user_tsc_khz)
 	thresh_lo = adjust_tsc_khz(tsc_khz, -tsc_tolerance_ppm);
 	thresh_hi = adjust_tsc_khz(tsc_khz, tsc_tolerance_ppm);
 	if (user_tsc_khz < thresh_lo || user_tsc_khz > thresh_hi) {
-		pr_debug("kvm: requested TSC rate %u falls outside tolerance [%u,%u]\n", user_tsc_khz, thresh_lo, thresh_hi);
+		tsc_debug("kvm: requested TSC rate %u falls outside tolerance [%u,%u]\n", user_tsc_khz, thresh_lo, thresh_hi);
 		use_scaling = 1;
 	}
 	return set_tsc_khz(vcpu, user_tsc_khz, use_scaling);
@@ -1766,12 +1772,12 @@ void kvm_write_tsc(struct kvm_vcpu *vcpu, struct msr_data *msr)
 	    vcpu->arch.virtual_tsc_khz == kvm->arch.last_tsc_khz) {
 		if (!kvm_check_tsc_unstable()) {
 			offset = kvm->arch.cur_tsc_offset;
-			pr_debug("kvm: matched tsc offset for %llu\n", data);
+			tsc_debug("kvm: matched tsc offset for %llu\n", data);
 		} else {
 			u64 delta = nsec_to_cycles(vcpu, elapsed);
 			data += delta;
 			offset = kvm_compute_tsc_offset(vcpu, data);
-			pr_debug("kvm: adjusted tsc offset by %llu\n", delta);
+			tsc_debug("kvm: adjusted tsc offset by %llu\n", delta);
 		}
 		matched = true;
 		already_matched = (vcpu->arch.this_tsc_generation == kvm->arch.cur_tsc_generation);
@@ -1790,7 +1796,7 @@ void kvm_write_tsc(struct kvm_vcpu *vcpu, struct msr_data *msr)
 		kvm->arch.cur_tsc_write = data;
 		kvm->arch.cur_tsc_offset = offset;
 		matched = false;
-		pr_debug("kvm: new tsc generation %llu, clock %llu\n",
+		tsc_debug("kvm: new tsc generation %llu, clock %llu\n",
 			 kvm->arch.cur_tsc_generation, data);
 	}
 
@@ -6860,7 +6866,7 @@ static void kvm_timer_init(void)
 		cpufreq_register_notifier(&kvmclock_cpufreq_notifier_block,
 					  CPUFREQ_TRANSITION_NOTIFIER);
 	}
-	pr_debug("kvm: max_tsc_khz = %ld\n", max_tsc_khz);
+	tsc_debug("kvm: max_tsc_khz = %ld\n", max_tsc_khz);
 
 	cpuhp_setup_state(CPUHP_AP_X86_KVM_CLK_ONLINE, "x86/kvm/clk:online",
 			  kvmclock_cpu_online, kvmclock_cpu_down_prep);
-- 
1.8.3.1

Re: [PATCH 4/4] kvm: x86: convert TSC pr_debugs to be gated by CONFIG_KVM_DEBUG

[Paolo Bonzini]

On 01/07/19 08:21, Yi Wang wrote:
> There are some pr_debug in TSC code, which may affect
> performance, so it may make sense to wrap them using a new
> macro tsc_debug which takes effect only when CONFIG_KVM_DEBUG
> is defined.
> 
> Signed-off-by: Yi Wang <wang.yi59@zte.com.cn>
> ---
>  arch/x86/kvm/x86.c | 18 ++++++++++++------
>  1 file changed, 12 insertions(+), 6 deletions(-)
> 
> diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
> index 83aefd7..1505e53 100644
> --- a/arch/x86/kvm/x86.c
> +++ b/arch/x86/kvm/x86.c
> @@ -74,6 +74,12 @@
>  #define CREATE_TRACE_POINTS
>  #include "trace.h"
>  
> +#ifdef CONFIG_KVM_DEBUG
> +#define tsc_debug(x...) pr_debug(x)
> +#else
> +#define tsc_debug(x...)
> +#endif
> +
>  #define MAX_IO_MSRS 256
>  #define KVM_MAX_MCE_BANKS 32
>  u64 __read_mostly kvm_mce_cap_supported = MCG_CTL_P | MCG_SER_P;
> @@ -1522,7 +1528,7 @@ static void kvm_get_time_scale(uint64_t scaled_hz, uint64_t base_hz,
>  	*pshift = shift;
>  	*pmultiplier = div_frac(scaled64, tps32);
>  
> -	pr_debug("%s: base_hz %llu => %llu, shift %d, mul %u\n",
> +	tsc_debug("%s: base_hz %llu => %llu, shift %d, mul %u\n",
>  		 __func__, base_hz, scaled_hz, shift, *pmultiplier);
>  }

Just remove this.

> @@ -1603,7 +1609,7 @@ static int kvm_set_tsc_khz(struct kvm_vcpu *vcpu, u32 user_tsc_khz)
>  	thresh_lo = adjust_tsc_khz(tsc_khz, -tsc_tolerance_ppm);
>  	thresh_hi = adjust_tsc_khz(tsc_khz, tsc_tolerance_ppm);
>  	if (user_tsc_khz < thresh_lo || user_tsc_khz > thresh_hi) {
> -		pr_debug("kvm: requested TSC rate %u falls outside tolerance [%u,%u]\n", user_tsc_khz, thresh_lo, thresh_hi);
> +		tsc_debug("kvm: requested TSC rate %u falls outside tolerance [%u,%u]\n", user_tsc_khz, thresh_lo, thresh_hi);

This is okay as a pr_debug, it only happens once per VM and only if it
is configured wrong.

>  		use_scaling = 1;
>  	}
>  	return set_tsc_khz(vcpu, user_tsc_khz, use_scaling);
> @@ -1766,12 +1772,12 @@ void kvm_write_tsc(struct kvm_vcpu *vcpu, struct msr_data *msr)
>  	    vcpu->arch.virtual_tsc_khz == kvm->arch.last_tsc_khz) {
>  		if (!kvm_check_tsc_unstable()) {
>  			offset = kvm->arch.cur_tsc_offset;
> -			pr_debug("kvm: matched tsc offset for %llu\n", data);
> +			tsc_debug("kvm: matched tsc offset for %llu\n", data);
>  		} else {
>  			u64 delta = nsec_to_cycles(vcpu, elapsed);
>  			data += delta;
>  			offset = kvm_compute_tsc_offset(vcpu, data);
> -			pr_debug("kvm: adjusted tsc offset by %llu\n", delta);
> +			tsc_debug("kvm: adjusted tsc offset by %llu\n", delta);

Again just drop these, there are tracepoints for it.
>  		}
>  		matched = true;
>  		already_matched = (vcpu->arch.this_tsc_generation == kvm->arch.cur_tsc_generation);
> @@ -1790,7 +1796,7 @@ void kvm_write_tsc(struct kvm_vcpu *vcpu, struct msr_data *msr)
>  		kvm->arch.cur_tsc_write = data;
>  		kvm->arch.cur_tsc_offset = offset;
>  		matched = false;
> -		pr_debug("kvm: new tsc generation %llu, clock %llu\n",
> +		tsc_debug("kvm: new tsc generation %llu, clock %llu\n",
>  			 kvm->arch.cur_tsc_generation, data);

Drop.

>  	}
>  
> @@ -6860,7 +6866,7 @@ static void kvm_timer_init(void)
>  		cpufreq_register_notifier(&kvmclock_cpufreq_notifier_block,
>  					  CPUFREQ_TRANSITION_NOTIFIER);
>  	}
> -	pr_debug("kvm: max_tsc_khz = %ld\n", max_tsc_khz);
> +	tsc_debug("kvm: max_tsc_khz = %ld\n", max_tsc_khz);

Drop.

Thanks,

Paolo

>  	cpuhp_setup_state(CPUHP_AP_X86_KVM_CLK_ONLINE, "x86/kvm/clk:online",
>  			  kvmclock_cpu_online, kvmclock_cpu_down_prep);
> 

Re: [PATCH 0/4] kvm: x86: introduce CONFIG_KVM_DEBUG

[Paolo Bonzini]

On 01/07/19 08:21, Yi Wang wrote:
> This series introduce CONFIG_KVM_DEBUG, using which we can make
> the invoking *_debug in KVM simly and uniform.
> 
> FYI: the former discussion can been found in:
> https://www.spinics.net/lists/kvm/msg187026.html

Basically everything except MMU_DEBUG can just be deleted, they are
little more than debugging printk that were left in the code.

For MMU_DEBUG, the way to go is to add more tracepoints, but then
converting all pgprintk occurrences to tracepoints would be wrong.  You
can only find the "right" tracepoints when debugging MMU code.  I do
have a couple patches in this area, I will send them when possible.

Paolo

> Yi Wang (4):
>   kvm: x86: Add CONFIG_KVM_DEBUG
>   kvm: x86: allow set apic and ioapic debug dynamically
>   kvm: x86: replace MMU_DEBUG with CONFIG_KVM_DEBUG
>   kvm: x86: convert TSC pr_debugs to be gated by CONFIG_KVM_DEBUG
> 
>  arch/x86/kvm/Kconfig  |  8 ++++++++
>  arch/x86/kvm/ioapic.c |  2 +-
>  arch/x86/kvm/lapic.c  |  5 ++++-
>  arch/x86/kvm/mmu.c    |  5 ++---
>  arch/x86/kvm/x86.c    | 18 ++++++++++++------
>  5 files changed, 27 insertions(+), 11 deletions(-)
>