[PATCH 2/2] x86: Reduce verbosity of "PAT enabled" kernel message

[PATCH 2/2] x86: Reduce verbosity of "PAT enabled" kernel message

[Roland Dreier]

On modern systems, the kernel prints the message

    x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106

once for every CPU.  This gets kind of ridiculous on huge systems; for
example, on a 64-thread system I was lucky enough to get:

    dmesg| grep 'PAT enabled' | wc
         64     704    5174

There is already a BUG() if non-boot CPUs have PAT capabilities that
don't match the boot CPU, so just print the message on the boot CPU.
(I kept the print after the wrmsrl() that enables PAT, so that the log
output continues to mean that the system survived enabling PAT on the
boot CPU)

Signed-off-by: Roland Dreier <rolandd@cisco.com>
---
 arch/x86/mm/pat.c |    7 +++++--
 1 files changed, 5 insertions(+), 2 deletions(-)

diff --git a/arch/x86/mm/pat.c b/arch/x86/mm/pat.c
index 7257cf3..e78cd0e 100644
--- a/arch/x86/mm/pat.c
+++ b/arch/x86/mm/pat.c
@@ -81,6 +81,7 @@ enum {
 void pat_init(void)
 {
 	u64 pat;
+	bool boot_cpu = !boot_pat_state;
 
 	if (!pat_enabled)
 		return;
@@ -122,8 +123,10 @@ void pat_init(void)
 		rdmsrl(MSR_IA32_CR_PAT, boot_pat_state);
 
 	wrmsrl(MSR_IA32_CR_PAT, pat);
-	printk(KERN_INFO "x86 PAT enabled: cpu %d, old 0x%Lx, new 0x%Lx\n",
-	       smp_processor_id(), boot_pat_state, pat);
+
+	if (boot_cpu)
+		printk(KERN_INFO "x86 PAT enabled: cpu %d, old 0x%Lx, new 0x%Lx\n",
+		       smp_processor_id(), boot_pat_state, pat);
 }
 
 #undef PAT

Re: [PATCH 2/2] x86: Reduce verbosity of "PAT enabled" kernel message

[Roland Dreier]

By the way, there is further work to be done in this direction... these
were the easy ones (that save me 127 lines of dmesg :).

The philosophy should probably be things that we would want to see to
debug crashes at boot should go into the kernel log -- that makes it
easy for users to grab the output and send it on for debugging.  If we
can move other stuff somewhere that users can grab easily after boot,
then that's probably worth it.

I think the next things to look at are:

* secondary CPU booting:

     Calibrating delay using timer specific routine.. xxxx BogoMIPS (lpj=xxxx)
     CPU: Physical Processor ID: 2
     CPU: Processor Core ID: 0
     CPU: L1 I cache: xxxx, L1 D cache: xxxx
     CPU: L2 cache: xxxx
     CPU: L3 cache: xxxx
     CPU 1/0x40 -> Node 0
     mce: CPU supports xxxx MCE banks
     CPU1: Thermal monitoring enabled (TM1)
     CPU 1 MCA banks ....

  where all 64 CPUs are exactly the same -- I guess checking for
  non-homogenous systems might be kind of complicated but we really
  shouldn't print all this for every CPU when they all match the boot
  CPU precisely.

* scheduler domain stuff:

     CPU0 attaching sched-domain:
      domain 0: span 0,32 level SIBLING
       groups: 0 (cpu_power = xxxx) 32 (cpu_power = xxxx)
       domain 1: span 0,4,8,12,16,20,24,28,32,36,40,44,48,52,56,60 level MC
        groups: 0,32 (cpu_power = xxxx) 4,36 (cpu_power = xxxx) 8,40 (cpu_power = xxxx) 12,44 (cpu_power = xxxx) 16,48 (cpu_power = xxxx) 20,52 (cpu_power = xxxx) 24,56 (cpu_power = xxxx) 28,60 (cpu_power = xxxx)
        domain 2: span 0-63 level CPU
         groups: 0,4,8,12,16,20,24,28,32,36,40,44,48,52,56,60 (cpu_power = xxxx) 1,5,9,13,17,21,25,29,33,37,41,45,49,53,57,61 (cpu_power = xxxx) 2,6,10,14,18,22,26,30,34,38,42,46,50,54,58,62 (cpu_power = xxxx) 3,7,11,15,19,23,27,31,35,39,43,47,51,55,59,63 (cpu_power = xxxx)

  not sure what the best way to present this is but 64 copies of this
  output do consume a lot of log buffer space!

* misc stuff, where we get 64 copies of a single message, eg

     Switched to high resolution mode on CPU 0

     ACPI: Processor [CPU0] (supports 8 throttling states)
     processor LNXCPU:01: registered as cooling_device1

[tip:x86/urgent] x86: Reduce verbosity of "PAT enabled" kernel message

[tip-bot for Roland Dreier]

Commit-ID:  e23a8b6a8f319c0f08b6ccef2dccbb37e7603dc2
Gitweb:     http://git.kernel.org/tip/e23a8b6a8f319c0f08b6ccef2dccbb37e7603dc2
Author:     Roland Dreier <rdreier@cisco.com>
AuthorDate: Wed, 23 Sep 2009 15:35:35 -0700
Committer:  Ingo Molnar <mingo@elte.hu>
CommitDate: Thu, 24 Sep 2009 11:35:19 +0200

x86: Reduce verbosity of "PAT enabled" kernel message

On modern systems, the kernel prints the message

    x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106

once for every CPU.

This gets kind of ridiculous on huge systems; for example, on a
64-thread system I was lucky enough to get:

    dmesg| grep 'PAT enabled' | wc
         64     704    5174

There is already a BUG() if non-boot CPUs have PAT capabilities
that don't match the boot CPU, so just print the message on the
boot CPU. (I kept the print after the wrmsrl() that enables PAT,
so that the log output continues to mean that the system survived
enabling PAT on the boot CPU)

Signed-off-by: Roland Dreier <rolandd@cisco.com>
Cc: Suresh Siddha <suresh.b.siddha@intel.com>
Cc: Venkatesh Pallipadi <venkatesh.pallipadi@intel.com>
LKML-Reference: <adavdj92sso.fsf@cisco.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>


---
 arch/x86/mm/pat.c |    7 +++++--
 1 files changed, 5 insertions(+), 2 deletions(-)

diff --git a/arch/x86/mm/pat.c b/arch/x86/mm/pat.c
index 7257cf3..e78cd0e 100644
--- a/arch/x86/mm/pat.c
+++ b/arch/x86/mm/pat.c
@@ -81,6 +81,7 @@ enum {
 void pat_init(void)
 {
 	u64 pat;
+	bool boot_cpu = !boot_pat_state;
 
 	if (!pat_enabled)
 		return;
@@ -122,8 +123,10 @@ void pat_init(void)
 		rdmsrl(MSR_IA32_CR_PAT, boot_pat_state);
 
 	wrmsrl(MSR_IA32_CR_PAT, pat);
-	printk(KERN_INFO "x86 PAT enabled: cpu %d, old 0x%Lx, new 0x%Lx\n",
-	       smp_processor_id(), boot_pat_state, pat);
+
+	if (boot_cpu)
+		printk(KERN_INFO "x86 PAT enabled: cpu %d, old 0x%Lx, new 0x%Lx\n",
+		       smp_processor_id(), boot_pat_state, pat);
 }
 
 #undef PAT

Re: [PATCH 2/2] x86: Reduce verbosity of "PAT enabled" kernel message

[Ingo Molnar]

* Roland Dreier <rdreier@cisco.com> wrote:

> By the way, there is further work to be done in this direction... 
> these were the easy ones (that save me 127 lines of dmesg :).

thanks Roland - i've applied them to tip:x86/urgent, for v2.6.32 merge.

Feel free to send more such patches, they are nice improvements.

> The philosophy should probably be things that we would want to see to 
> debug crashes at boot should go into the kernel log -- that makes it 
> easy for users to grab the output and send it on for debugging.  If we 
> can move other stuff somewhere that users can grab easily after boot, 
> then that's probably worth it.
> 
> I think the next things to look at are:
> 
> * secondary CPU booting:
> 
>      Calibrating delay using timer specific routine.. xxxx BogoMIPS (lpj=xxxx)
>      CPU: Physical Processor ID: 2
>      CPU: Processor Core ID: 0
>      CPU: L1 I cache: xxxx, L1 D cache: xxxx
>      CPU: L2 cache: xxxx
>      CPU: L3 cache: xxxx
>      CPU 1/0x40 -> Node 0
>      mce: CPU supports xxxx MCE banks
>      CPU1: Thermal monitoring enabled (TM1)
>      CPU 1 MCA banks ....
> 
>   where all 64 CPUs are exactly the same -- I guess checking for
>   non-homogenous systems might be kind of complicated but we really
>   shouldn't print all this for every CPU when they all match the boot
>   CPU precisely.

Agreed.

> 
> * scheduler domain stuff:
> 
>      CPU0 attaching sched-domain:
>       domain 0: span 0,32 level SIBLING
>        groups: 0 (cpu_power = xxxx) 32 (cpu_power = xxxx)
>        domain 1: span 0,4,8,12,16,20,24,28,32,36,40,44,48,52,56,60 level MC
>         groups: 0,32 (cpu_power = xxxx) 4,36 (cpu_power = xxxx) 8,40 (cpu_power = xxxx) 12,44 (cpu_power = xxxx) 16,48 (cpu_power = xxxx) 20,52 (cpu_power = xxxx) 24,56 (cpu_power = xxxx) 28,60 (cpu_power = xxxx)
>         domain 2: span 0-63 level CPU
>          groups: 0,4,8,12,16,20,24,28,32,36,40,44,48,52,56,60 (cpu_power = xxxx) 1,5,9,13,17,21,25,29,33,37,41,45,49,53,57,61 (cpu_power = xxxx) 2,6,10,14,18,22,26,30,34,38,42,46,50,54,58,62 (cpu_power = xxxx) 3,7,11,15,19,23,27,31,35,39,43,47,51,55,59,63 (cpu_power = xxxx)
> 
>   not sure what the best way to present this is but 64 copies of this
>   output do consume a lot of log buffer space!

Just turn it off after the first instance and give it a sched=debug boot 
parameter perhaps - that's enough.

> * misc stuff, where we get 64 copies of a single message, eg
> 
>      Switched to high resolution mode on CPU 0
> 
>      ACPI: Processor [CPU0] (supports 8 throttling states)
>      processor LNXCPU:01: registered as cooling_device1

Yeah. The switched-to message could be eliminated altogether.

Thanks,

	Ingo

[PATCH] hrtimer: Remove overly verbose "switch to high res mode" message

[Roland Dreier]

On big systems, printing <number of CPUs> copies of

    Switched to high resolution mode on CPU nnn

clutters up the kernel log for minimal gain.  Just get rid of them.

Signed-off-by: Roland Dreier <rolandd@cisco.com>
---
 > Yeah. The switched-to message could be eliminated altogether.

easy enough...

 kernel/hrtimer.c |    2 --
 1 files changed, 0 insertions(+), 2 deletions(-)

diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
index e5d98ce..4267279 100644
--- a/kernel/hrtimer.c
+++ b/kernel/hrtimer.c
@@ -720,8 +720,6 @@ static int hrtimer_switch_to_hres(void)
 	/* "Retrigger" the interrupt to get things going */
 	retrigger_next_event(NULL);
 	local_irq_restore(flags);
-	printk(KERN_DEBUG "Switched to high resolution mode on CPU %d\n",
-	       smp_processor_id());
 	return 1;
 }
 

Re: [PATCH] hrtimer: Remove overly verbose "switch to high res mode" message

[Joe Perches]

On Thu, 2009-09-24 at 14:07 -0700, Roland Dreier wrote:
> On big systems, printing <number of CPUs> copies of
>     Switched to high resolution mode on CPU nnn
> clutters up the kernel log for minimal gain.  Just get rid of them.
> Signed-off-by: Roland Dreier <rolandd@cisco.com>
> diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
> index e5d98ce..4267279 100644
> --- a/kernel/hrtimer.c
> +++ b/kernel/hrtimer.c
> @@ -720,8 +720,6 @@ static int hrtimer_switch_to_hres(void)
>  	/* "Retrigger" the interrupt to get things going */
>  	retrigger_next_event(NULL);
>  	local_irq_restore(flags);
> -	printk(KERN_DEBUG "Switched to high resolution mode on CPU %d\n",
> -	       smp_processor_id());

Perhaps pr_debug instead?
It gets compiled to nothing unless DEBUG is defined.

Re: [PATCH] hrtimer: Remove overly verbose "switch to high res mode" message

[Roland Dreier]

 > > -	printk(KERN_DEBUG "Switched to high resolution mode on CPU %d\n",
 > > -	       smp_processor_id());
 > 
 > Perhaps pr_debug instead?
 > It gets compiled to nothing unless DEBUG is defined.

Dunno... is that kernel log message ever useful now?

 - R.

Re: [PATCH] hrtimer: Remove overly verbose "switch to high res mode" message

[Joe Perches]

On Thu, 2009-09-24 at 14:15 -0700, Roland Dreier wrote:
> > > -	printk(KERN_DEBUG "Switched to high resolution mode on CPU %d\n",
>  > > -	       smp_processor_id());
>  > Perhaps pr_debug instead?
> Dunno... is that kernel log message ever useful now?

Dunno either.
I think lots of kernel log messages are not particularly useful.
Others frequently think different...

cheers, Joe

Re: [PATCH] hrtimer: Remove overly verbose "switch to high res mode" message

[Valdis.Kletnieks]

[-- Attachment #1: Type: text/plain, Size: 998 bytes --]

On Thu, 24 Sep 2009 14:15:14 PDT, Roland Dreier said:
> 
>  > > -	printk(KERN_DEBUG "Switched to high resolution mode on CPU %d\n",
>  > > -	       smp_processor_id());
>  > 
>  > Perhaps pr_debug instead?
>  > It gets compiled to nothing unless DEBUG is defined.
> 
> Dunno... is that kernel log message ever useful now?

There's 3 cases to consider:

1) Kernel built with CONFIG_HIGH_RES_TIMERS=n.  We get no message then.

2) We have high-res timers and it succeeded. We probably don't care if that's
the usual case, so lose the message in that case, just like we probably
don't need a message that we managed to fork off init.

3) We attempted to switch to high-res mode, and it *failed*. We already throw
the appropriate KERN_WARNING for that a few lines up.

And since we issue a message in the one case we *care* about, we can
determine that the *lack* of that KERN_WARNING means the switch went OK.

Thus, we don't need the message, as it doesn't *tell* us anything we didn't
already know.

[-- Attachment #2: Type: application/pgp-signature, Size: 227 bytes --]

[tip:timers/urgent] hrtimer: Remove overly verbose "switch to high res mode" message

[tip-bot for Roland Dreier]

Commit-ID:  d3f6302e7e51b41af86c6496ffb2f95e8f2179df
Gitweb:     http://git.kernel.org/tip/d3f6302e7e51b41af86c6496ffb2f95e8f2179df
Author:     Roland Dreier <rdreier@cisco.com>
AuthorDate: Thu, 24 Sep 2009 14:07:55 -0700
Committer:  Ingo Molnar <mingo@elte.hu>
CommitDate: Sat, 26 Sep 2009 16:58:09 +0200

hrtimer: Remove overly verbose "switch to high res mode" message

On big systems, printing <number of CPUs> copies of

    Switched to high resolution mode on CPU nnn

clutters up the kernel log for minimal gain.  Just get rid of them.

Signed-off-by: Roland Dreier <rolandd@cisco.com>
LKML-Reference: <ada1vlw126s.fsf_-_@cisco.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>


---
 kernel/hrtimer.c |    2 --
 1 files changed, 0 insertions(+), 2 deletions(-)

diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
index e5d98ce..4267279 100644
--- a/kernel/hrtimer.c
+++ b/kernel/hrtimer.c
@@ -720,8 +720,6 @@ static int hrtimer_switch_to_hres(void)
 	/* "Retrigger" the interrupt to get things going */
 	retrigger_next_event(NULL);
 	local_irq_restore(flags);
-	printk(KERN_DEBUG "Switched to high resolution mode on CPU %d\n",
-	       smp_processor_id());
 	return 1;
 }