Early kernel messages are overflowing the static log buffer

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

Absolutely!

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

Yeah.

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

Hello,

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

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.

---
Applied to percpu#for-linus. Will push out in several days. Thanks.

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

index efe8168..02ba912 100644
@@ -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

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.

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

...

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.

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.

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

Thanks,

Ingo