[PATCH v3] watchdog: Quiet down the boot messages

[PATCH v3] watchdog: Quiet down the boot messages

[Don Zickus]

A bunch of bugzillas have complained how noisy the nmi_watchdog is during
boot-up especially with its expected failure cases (like virt and bios
resource contention).

This is my attempt to quiet them down and keep it less confusing for the end
user.  What I did is print the message for cpu0 and save it for future
comparisons.  If future cpus have an identical message as cpu0, then don't
print the redundant info.  However, if a future cpu has a different message,
happily print that loudly.

Before the change, you would see something like:

    ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
    CPU0: Intel(R) Core(TM)2 Quad CPU    Q9550  @ 2.83GHz stepping 0a
    Performance Events: PEBS fmt0+, Core2 events, Intel PMU driver.
    ... version:                2
    ... bit width:              40
    ... generic registers:      2
    ... value mask:             000000ffffffffff
    ... max period:             000000007fffffff
    ... fixed-purpose events:   3
    ... event mask:             0000000700000003
    NMI watchdog enabled, takes one hw-pmu counter.
    Booting Node   0, Processors  #1
    NMI watchdog enabled, takes one hw-pmu counter.
     #2
    NMI watchdog enabled, takes one hw-pmu counter.
     #3 Ok.
    NMI watchdog enabled, takes one hw-pmu counter.
    Brought up 4 CPUs
    Total of 4 processors activated (22607.24 BogoMIPS).

After the change, it is simplified to:

    ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
    CPU0: Intel(R) Core(TM)2 Quad CPU    Q9550  @ 2.83GHz stepping 0a
    Performance Events: PEBS fmt0+, Core2 events, Intel PMU driver.
    ... version:                2
    ... bit width:              40
    ... generic registers:      2
    ... value mask:             000000ffffffffff
    ... max period:             000000007fffffff
    ... fixed-purpose events:   3
    ... event mask:             0000000700000003
    NMI watchdog enabled, takes one hw-pmu counter.
    Booting Node   0, Processors  #1 #2 #3 Ok.
    Brought up 4 CPUs

V2: little changes based on Joe Perches' feedback
V3: printk cleanup based on Ingo's feedback; checkpatch fix

Reported-and-tested-by: Nathan Zimmer <nzimmer@sgi.com>
Signed-off-by: Don Zickus <dzickus@redhat.com>
---
 kernel/watchdog.c |   21 ++++++++++++++++++++-
 1 files changed, 20 insertions(+), 1 deletions(-)

diff --git a/kernel/watchdog.c b/kernel/watchdog.c
index e5e1d85..74b1e27 100644
--- a/kernel/watchdog.c
+++ b/kernel/watchdog.c
@@ -377,6 +377,13 @@ static int watchdog_nmi_enable(int cpu)
 	struct perf_event_attr *wd_attr;
 	struct perf_event *event = per_cpu(watchdog_ev, cpu);
 
+	/*
+	 * People like the simple clean cpu node info on boot.
+	 * Reduce the watchdog noise by only printing messages
+	 * that are different from what cpu0 displayed.
+	 */
+	static unsigned long cpu0_err;
+
 	/* is it already setup and enabled? */
 	if (event && event->state > PERF_EVENT_STATE_OFF)
 		goto out;
@@ -390,11 +397,23 @@ static int watchdog_nmi_enable(int cpu)
 
 	/* Try to register using hardware perf events */
 	event = perf_event_create_kernel_counter(wd_attr, cpu, NULL, watchdog_overflow_callback, NULL);
+
+	/* save cpu0 error for future comparision */
+	if (cpu == 0 && IS_ERR(event))
+		cpu0_err = PTR_ERR(event);
+
 	if (!IS_ERR(event)) {
-		pr_info("enabled, takes one hw-pmu counter.\n");
+		/* only print for cpu0 or different than cpu0 */
+		if (cpu == 0 || cpu0_err) {
+			pr_info("enabled on all CPUs, permanently consumes ");
+			pr_cont("one hw-PMU counter.\n");
+		}
 		goto out_save;
 	}
 
+	/* skip displaying the same error again */
+	if (cpu > 0 && (PTR_ERR(event) == cpu0_err))
+		return PTR_ERR(event);
 
 	/* vary the KERN level based on the returned errno */
 	if (PTR_ERR(event) == -EOPNOTSUPP)
-- 
1.7.7.6

Re: [PATCH v3] watchdog: Quiet down the boot messages

[Joe Perches]

On Mon, 2012-06-11 at 16:04 -0400, Don Zickus wrote:
> A bunch of bugzillas have complained how noisy the nmi_watchdog is during
> boot-up especially with its expected failure cases (like virt and bios
> resource contention).
[]
> diff --git a/kernel/watchdog.c b/kernel/watchdog.c
[]
> @@ -390,11 +397,23 @@ static int watchdog_nmi_enable(int cpu)
[]
>  	if (!IS_ERR(event)) {
> -		pr_info("enabled, takes one hw-pmu counter.\n");
> +		/* only print for cpu0 or different than cpu0 */
> +		if (cpu == 0 || cpu0_err) {
> +			pr_info("enabled on all CPUs, permanently consumes ");
> +			pr_cont("one hw-PMU counter.\n");

Don't worry about formats exceeding 80 column please.
Don't break up pr_info into multiple bits either.

			pr_info("enabled on all cpus, permanently consumes one hw-PMU counter\n");

Re: [PATCH v3] watchdog: Quiet down the boot messages

[Don Zickus]

On Mon, Jun 11, 2012 at 01:56:50PM -0700, Joe Perches wrote:
> On Mon, 2012-06-11 at 16:04 -0400, Don Zickus wrote:
> > A bunch of bugzillas have complained how noisy the nmi_watchdog is during
> > boot-up especially with its expected failure cases (like virt and bios
> > resource contention).
> []
> > diff --git a/kernel/watchdog.c b/kernel/watchdog.c
> []
> > @@ -390,11 +397,23 @@ static int watchdog_nmi_enable(int cpu)
> []
> >  	if (!IS_ERR(event)) {
> > -		pr_info("enabled, takes one hw-pmu counter.\n");
> > +		/* only print for cpu0 or different than cpu0 */
> > +		if (cpu == 0 || cpu0_err) {
> > +			pr_info("enabled on all CPUs, permanently consumes ");
> > +			pr_cont("one hw-PMU counter.\n");
> 
> Don't worry about formats exceeding 80 column please.
> Don't break up pr_info into multiple bits either.
> 
> 			pr_info("enabled on all cpus, permanently consumes one hw-PMU counter\n");

Ok.  Thanks.

Cheers,
Don

Re: [PATCH v3] watchdog: Quiet down the boot messages

[Dave Jones]

On Mon, Jun 11, 2012 at 04:04:10PM -0400, Don Zickus wrote:
 > A bunch of bugzillas have complained how noisy the nmi_watchdog is during
 > boot-up especially with its expected failure cases (like virt and bios
 > resource contention).
 > 
 > This is my attempt to quiet them down and keep it less confusing for the end
 > user.  What I did is print the message for cpu0 and save it for future
 > comparisons.  If future cpus have an identical message as cpu0, then don't
 > print the redundant info.  However, if a future cpu has a different message,
 > happily print that loudly.

Would anyone object to compressing these lines too ?
 
 >     ... version:                2
 >     ... bit width:              40
 >     ... generic registers:      2
 >     ... value mask:             000000ffffffffff
 >     ... max period:             000000007fffffff
 >     ... fixed-purpose events:   3
 >     ... event mask:             0000000700000003

That's a lot of wasted space, that could just as easily take up two lines
without losing readability.

untested, but something like the below patch..

	Dave


diff --git a/arch/x86/kernel/cpu/perf_event.c b/arch/x86/kernel/cpu/perf_event.c
index c4706cf..68e83ad 100644
--- a/arch/x86/kernel/cpu/perf_event.c
+++ b/arch/x86/kernel/cpu/perf_event.c
@@ -1389,13 +1389,13 @@ static int __init init_hw_perf_events(void)
 	x86_pmu.attr_rdpmc = 1; /* enable userspace RDPMC usage by default */
 	x86_pmu_format_group.attrs = x86_pmu.format_attrs;
 
-	pr_info("... version:                %d\n",     x86_pmu.version);
-	pr_info("... bit width:              %d\n",     x86_pmu.cntval_bits);
-	pr_info("... generic registers:      %d\n",     x86_pmu.num_counters);
-	pr_info("... value mask:             %016Lx\n", x86_pmu.cntval_mask);
-	pr_info("... max period:             %016Lx\n", x86_pmu.max_period);
-	pr_info("... fixed-purpose events:   %d\n",     x86_pmu.num_counters_fixed);
-	pr_info("... event mask:             %016Lx\n", x86_pmu.intel_ctrl);
+	pr_info("... version: %d ", x86_pmu.version);
+	pr_info("bit width: %d ", x86_pmu.cntval_bits);
+	pr_info("generic registers: %d\n", x86_pmu.num_counters);
+	pr_info("... value mask: %016Lx ", x86_pmu.cntval_mask);
+	pr_info("max period: %016Lx ", x86_pmu.max_period);
+	pr_info("fixed-purpose events: %d ", x86_pmu.num_counters_fixed);
+	pr_info("event mask: %016Lx\n", x86_pmu.intel_ctrl);
 
 	perf_pmu_register(&pmu, "cpu", PERF_TYPE_RAW);
 	perf_cpu_notifier(x86_pmu_notifier);

Re: [PATCH v3] watchdog: Quiet down the boot messages

[Joe Perches]

On Mon, 2012-06-11 at 17:12 -0400, Dave Jones wrote:
[]
> Would anyone object to compressing these lines too ?
>  
>  >     ... version:                2
>  >     ... bit width:              40
>  >     ... generic registers:      2
>  >     ... value mask:             000000ffffffffff
>  >     ... max period:             000000007fffffff
>  >     ... fixed-purpose events:   3
>  >     ... event mask:             0000000700000003
[]
> diff --git a/arch/x86/kernel/cpu/perf_event.c b/arch/x86/kernel/cpu/perf_event.c
[]
> @@ -1389,13 +1389,13 @@ static int __init init_hw_perf_events(void)
>  	x86_pmu.attr_rdpmc = 1; /* enable userspace RDPMC usage by default */
>  	x86_pmu_format_group.attrs = x86_pmu.format_attrs;
>  
> -	pr_info("... version:                %d\n",     x86_pmu.version);
> -	pr_info("... bit width:              %d\n",     x86_pmu.cntval_bits);
> -	pr_info("... generic registers:      %d\n",     x86_pmu.num_counters);
> -	pr_info("... value mask:             %016Lx\n", x86_pmu.cntval_mask);
> -	pr_info("... max period:             %016Lx\n", x86_pmu.max_period);
> -	pr_info("... fixed-purpose events:   %d\n",     x86_pmu.num_counters_fixed);
> -	pr_info("... event mask:             %016Lx\n", x86_pmu.intel_ctrl);
> +	pr_info("... version: %d ", x86_pmu.version);
> +	pr_info("bit width: %d ", x86_pmu.cntval_bits);
> +	pr_info("generic registers: %d\n", x86_pmu.num_counters);
> +	pr_info("... value mask: %016Lx ", x86_pmu.cntval_mask);
> +	pr_info("max period: %016Lx ", x86_pmu.max_period);
> +	pr_info("fixed-purpose events: %d ", x86_pmu.num_counters_fixed);
> +	pr_info("event mask: %016Lx\n", x86_pmu.intel_ctrl);

That wouldn't work.

Every pr_<level> other than pr_cont will always be start a new line.

You want pr_cont for each of these other than the ... ones.

It'd be better too just to use 2 pr_info lines like:

	pr_info("... version: %d bit width: %d generic registers: %d\n",
		x86_pmu.version, x86_pmu.cntval_bits, x86_pmu.num_counters);
	pr_info("... value mask: %016Lx max period: %016Lx fixed-purpose events: %d event mask: %016Lx\n",
		x86_pmu.cntval_mask, x86_pmu.max_period,
		x86_pmu.num_counters_fixed, x86_pmu.intel_ctrl);

Re: [PATCH v3] watchdog: Quiet down the boot messages

[Ingo Molnar]

* Dave Jones <davej@redhat.com> wrote:

> On Mon, Jun 11, 2012 at 04:04:10PM -0400, Don Zickus wrote:
>  > A bunch of bugzillas have complained how noisy the nmi_watchdog is during
>  > boot-up especially with its expected failure cases (like virt and bios
>  > resource contention).
>  > 
>  > This is my attempt to quiet them down and keep it less confusing for the end
>  > user.  What I did is print the message for cpu0 and save it for future
>  > comparisons.  If future cpus have an identical message as cpu0, then don't
>  > print the redundant info.  However, if a future cpu has a different message,
>  > happily print that loudly.
> 
> Would anyone object to compressing these lines too ?
>  
>  >     ... version:                2
>  >     ... bit width:              40
>  >     ... generic registers:      2
>  >     ... value mask:             000000ffffffffff
>  >     ... max period:             000000007fffffff
>  >     ... fixed-purpose events:   3
>  >     ... event mask:             0000000700000003
> 
> That's a lot of wasted space, that could just as easily take 
> up two lines without losing readability.

Yeah, we can do that, this was early debug code.

I'd suggest compressing it further, to a single line, to 
something like:

 ... ver: 2, regs: 2/3, bits: 40, masks: 0xffffffffff/0x700000003/0x7fffffff

Thanks,

	Ingo