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@xxxxxxxxxx>
> ---
>  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);
>