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 <[email protected]>
---
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
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
Commit-ID: e23a8b6a8f319c0f08b6ccef2dccbb37e7603dc2
Gitweb: http://git.kernel.org/tip/e23a8b6a8f319c0f08b6ccef2dccbb37e7603dc2
Author: Roland Dreier <[email protected]>
AuthorDate: Wed, 23 Sep 2009 15:35:35 -0700
Committer: Ingo Molnar <[email protected]>
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 <[email protected]>
Cc: Suresh Siddha <[email protected]>
Cc: Venkatesh Pallipadi <[email protected]>
LKML-Reference: <[email protected]>
Signed-off-by: Ingo Molnar <[email protected]>
---
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
* Roland Dreier <[email protected]> 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
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 <[email protected]>
---
> 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;
}
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 <[email protected]>
> 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.
> > - 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.
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
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.
Commit-ID: d3f6302e7e51b41af86c6496ffb2f95e8f2179df
Gitweb: http://git.kernel.org/tip/d3f6302e7e51b41af86c6496ffb2f95e8f2179df
Author: Roland Dreier <[email protected]>
AuthorDate: Thu, 24 Sep 2009 14:07:55 -0700
Committer: Ingo Molnar <[email protected]>
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 <[email protected]>
LKML-Reference: <[email protected]>
Signed-off-by: Ingo Molnar <[email protected]>
---
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;
}