Early kernel messages are overflowing the static log buffer

Early kernel messages are overflowing the static log buffer

[Mike Travis]

Hi Ingo,

We have a problem on customer sites in that the early log buffer
messages overflow the static 128M log buffer before the log_buffer_len
parameter can be processed.  This causes a major problem when we
are trying to debug a kernel panic from the customer's panic dump.

I've tried processing the log_buffer_len as soon as possible,
(right after the setup of Bootmem on Node 0), but I still lose 
quite a bit.  I think I've calculated that there are about
192M of messages output on a 2048 processor 128 node 4TB system
before the log buffer can be dynamically reallocated.  And this
increases the complexity a bit because this is in arch dependent
code, so a generic reallocation routine is still needed.

And distros are against any attempt to increase the size of the
static log buffer so that's not really an option.

So it seems we need to reduce the number of messages.  

The voluminous message sources before buffer reallocation are:

[    0.000000]  BIOS-e820: 0000000000000000 - 000000000008f000 (usable)                                              
...
[    0.000000] EFI: mem00: type=3, attr=0xf, range=[0x0000000000000000-0x0000000000001000) (0MB)                     [    
...
[    0.000000] modified physical RAM map:
[    0.000000]  modified: 0000000000000000 - 0000000000001000 (usable)                         
...
[    0.000000] SRAT: PXM 0 -> APIC 0 -> Node 0
...
[    0.000000] Bootmem setup node 0 0000000000000000-0000000800000000
[    0.000000]   NODE_DATA [000000000000e100 - 00000000000420ff]
[    0.000000]   bootmap [0000000000100000 -  00000000001fffff] pages 100
...
[    0.000000] early_node_map[137] active PFN ranges
[    0.000000]     0: 0x00000000 -> 0x00000001
...
[    0.000000] On node 1 totalpages: 8388608
[    0.000000]   Normal zone: 114688 pages used for memmap
[    0.000000]   Normal zone: 8273920 pages, LIFO batch:31
...
[    0.000000] ACPI: X2APIC (apic_id[0x00] uid[0x00] enabled)
...
[    0.000000] PM: Registered nosave memory: 0000000000001000 - 0000000000006000
...
[    0.000000] pcpu-alloc: [000] 0000 0001 0002 0003 0004 0005 0006 0007 1024 1025 1026 1027 1028 1029 1030 1031

What I'm asking is which of these would be most acceptable to
either remove or replace with some sort of message reduction?
Note that a lot of the messages are completely redundant.  Like
the Bootmem setup generally has exactly the same information
(spread over 15 lines), for each of the 128 Nodes.

One patch that I still have was David's "reduce srat verbosity in
the kernel log" that was rejected by you as too complex.  This
would have resulted in about a 16:1 reduction in SRAT: messages,
without loss of an information.  Before I start another doomed patch,
I'd like to find out the guidelines.  Remember, no one really looks
at these messages unless the system panics, usually during startup.
So the information here may be key to diagnosing the problem.

Thanks,
Mike

Re: Early kernel messages are overflowing the static log buffer

[Ingo Molnar]

* Mike Travis <travis@sgi.com> wrote:

> So it seems we need to reduce the number of messages.

Absolutely!

> The voluminous message sources before buffer reallocation are:
> 
> [    0.000000]  BIOS-e820: 0000000000000000 - 000000000008f000
> (usable)                                              ...
> [    0.000000] EFI: mem00: type=3, attr=0xf,
> range=[0x0000000000000000-0x0000000000001000) (0MB)
> [    ...
> [    0.000000] modified physical RAM map:
> [    0.000000]  modified: 0000000000000000 - 0000000000001000
> (usable)                         ...
> [    0.000000] SRAT: PXM 0 -> APIC 0 -> Node 0
> ...
> [    0.000000] Bootmem setup node 0 0000000000000000-0000000800000000
> [    0.000000]   NODE_DATA [000000000000e100 - 00000000000420ff]
> [    0.000000]   bootmap [0000000000100000 -  00000000001fffff] pages 100
> ...
> [    0.000000] early_node_map[137] active PFN ranges
> [    0.000000]     0: 0x00000000 -> 0x00000001
> ...
> [    0.000000] On node 1 totalpages: 8388608
> [    0.000000]   Normal zone: 114688 pages used for memmap
> [    0.000000]   Normal zone: 8273920 pages, LIFO batch:31
> ...
> [    0.000000] ACPI: X2APIC (apic_id[0x00] uid[0x00] enabled)
> ...
> [    0.000000] PM: Registered nosave memory: 0000000000001000 - 0000000000006000
> ...
> [    0.000000] pcpu-alloc: [000] 0000 0001 0002 0003 0004 0005 0006 0007 1024 1025 1026 1027 1028 1029 1030 1031
> 
> What I'm asking is which of these would be most acceptable to
> either remove or replace with some sort of message reduction?

The pcpu alloc messages look entirely superfluous and zappable - make them 
KERN_DEBUG perhaps (and Cc: Tejun)?

> Note that a lot of the messages are completely redundant.  Like
> the Bootmem setup generally has exactly the same information
> (spread over 15 lines), for each of the 128 Nodes.

Yeah.

> One patch that I still have was David's "reduce srat verbosity in
> the kernel log" that was rejected by you as too complex.  This
> would have resulted in about a 16:1 reduction in SRAT: messages,
> without loss of an information.  Before I start another doomed patch,
> I'd like to find out the guidelines.  Remember, no one really looks
> at these messages unless the system panics, usually during startup.
> So the information here may be key to diagnosing the problem.

Mind resending that patch again? Maybe we can find a simpler solution. I almost 
never NAK patches permanently - there can always be reasons i missed, or better 
implementations.

We dont want to lose physical memory layout information - it's useful in many other 
types of post mortem analysis and we dont want to force people to reboot into some 
debug kernel just to be able to report essential bits.

Thanks,

	Ingo

Re: Early kernel messages are overflowing the static log buffer

[Tejun Heo]

Hello,

On Wed, Dec 22, 2010 at 02:09:46PM +0100, Ingo Molnar wrote:
> > [    0.000000] pcpu-alloc: [000] 0000 0001 0002 0003 0004 0005 0006 0007 1024 1025 1026 1027 1028 1029 1030 1031
> > 
> > What I'm asking is which of these would be most acceptable to
> > either remove or replace with some sort of message reduction?
> 
> The pcpu alloc messages look entirely superfluous and zappable - make them 
> KERN_DEBUG perhaps (and Cc: Tejun)?

Yeap, with percpu allocator now mostly stable, I don't think the
message needs to be KERN_INFO anymore.  I'll change it to KERN_DEBUG.

Thanks.

-- 
tejun

[PATCH] percpu: print out alloc information with KERN_DEBUG instead of KERN_INFO

[Tejun Heo]

Now that percpu allocator is mostly stable, there is no reason to
print alloc information with KERN_INFO and clutter the boot messages.
Switch it to KERN_DEBUG.

Signed-off-by: Tejun Heo <tj@kernel.org>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Mike Travis <travis@sgi.com>
---
Applied to percpu#for-linus.  Will push out in several days.  Thanks.

 mm/percpu.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/mm/percpu.c b/mm/percpu.c
index efe8168..02ba912 100644
--- a/mm/percpu.c
+++ b/mm/percpu.c
@@ -1268,7 +1268,7 @@ int __init pcpu_setup_first_chunk(const struct pcpu_alloc_info *ai,
 
 	/* we're done parsing the input, undefine BUG macro and dump config */
 #undef PCPU_SETUP_BUG_ON
-	pcpu_dump_alloc_info(KERN_INFO, ai);
+	pcpu_dump_alloc_info(KERN_DEBUG, ai);
 
 	pcpu_nr_groups = ai->nr_groups;
 	pcpu_group_offsets = group_offsets;
-- 
1.7.1

Re: Early kernel messages are overflowing the static log buffer

[Mike Travis]

Thanks.

I have a patchset almost ready for submission.  We have a giant
system (6 racks with some huge amount of nodes) for a few more
days, and the buffer still overflowed with my changes.  So I'm
making one more tweak to cut down the amount of characters 
generated without losing information.

Tejun Heo wrote:
> Hello,
> 
> On Wed, Dec 22, 2010 at 02:09:46PM +0100, Ingo Molnar wrote:
>>> [    0.000000] pcpu-alloc: [000] 0000 0001 0002 0003 0004 0005 0006 0007 1024 1025 1026 1027 1028 1029 1030 1031
>>>
>>> What I'm asking is which of these would be most acceptable to
>>> either remove or replace with some sort of message reduction?
>> The pcpu alloc messages look entirely superfluous and zappable - make them 
>> KERN_DEBUG perhaps (and Cc: Tejun)?
> 
> Yeap, with percpu allocator now mostly stable, I don't think the
> message needs to be KERN_INFO anymore.  I'll change it to KERN_DEBUG.
> 
> Thanks.
> 

This doesn't really help the log buffer overflow problem as KERN_DEBUG
messages still end up in the buffer.  The pr_debug() macro does compile
out the messages if the system does not have KERNEL debug set, though
distros also have this set as a default.

Thanks,
Mike

Re: Early kernel messages are overflowing the static log buffer

[Mike Travis]

...
>> Yeap, with percpu allocator now mostly stable, I don't think the
>> message needs to be KERN_INFO anymore.  I'll change it to KERN_DEBUG.
>>
>> Thanks.
>>
> 
> This doesn't really help the log buffer overflow problem as KERN_DEBUG
> messages still end up in the buffer.  The pr_debug() macro does compile
> out the messages if the system does not have KERNEL debug set, though
> distros also have this set as a default.

Btw, I meant to add that the my patchset allocates the log buffer right
after boot mem is setup.  So this output does not affect the overflow
problem, though it is nice to clean up the console output whenever we can.

Re: Early kernel messages are overflowing the static log buffer

[Ingo Molnar]

* Mike Travis <travis@sgi.com> wrote:

> Thanks.
> 
> I have a patchset almost ready for submission.  We have a giant
> system (6 racks with some huge amount of nodes) for a few more
> days, and the buffer still overflowed with my changes.  So I'm
> making one more tweak to cut down the amount of characters generated
> without losing information.

Also feel free to make judgement calls to cut information - people _think_ they need 
all that boot time noise but it's rarely useful. Memory layout is - but a lot of 
other details are not. So dont try to preserve things at any cost.

> This doesn't really help the log buffer overflow problem as KERN_DEBUG
> messages still end up in the buffer.  The pr_debug() macro does compile
> out the messages if the system does not have KERNEL debug set, though
> distros also have this set as a default.

Make the whole printout dependent on a percpu-debug boot parameter? (and default the 
switch to off?)

Thanks,

	Ingo