[PATCH 0/6] init: Shrink early messages to prevent overflowing the kernel log buffer

[PATCH 0/6] init: Shrink early messages to prevent overflowing the kernel log buffer

[Mike Travis]

v2: updated to apply to x86-tip

On larger systems, information in the kernel log is lost because
there is so much early text printed, that it overflows the static
log buffer before the log_buf_len kernel parameter can be processed,
and a bigger log buffer allocated.

Distros are relunctant to increase memory usage by increasing the
size of the static log buffer, so minimize the problem by allocating
the new log buffer as early as possible, and reducing the amount
of characters those early messages generate.

Some stats from testing these changes on our current lab UV systems.
(Both of these systems lost all of the e820 and EFI memmap ranges
before the changes.)

System X:
	8,793,945,145,344 bytes of system memory
	256 nodes
	599 EFI Mem ranges
	4096 cpu_ids
	43% of static log buffer unused

System Y:
	11,779,115,188,224 bytes of system memory
	492 Nodes
	976 EFI Mem ranges
	1968 cpu_ids
	17% of static log buffer unused

The last stat is how close the static log buffer came
to overflowing.  While these resources are fairly close
to today's max limits, there is not a lot of head room
for growth.

An alternative for the future might be to create a larger
static log buffer in the __initdata section, and then
always allocate a dynamically sized log buffer to replace
it.  This would also allow shrinking the log buffer for
memory tight situations.  But it would add complexity to
the code.

-- 

[PATCH 1/6] ACPI: Minimize X2APIC initial messages

[Mike Travis]

[-- Attachment #1: minimize-x2apic-msgs --]
[-- Type: text/plain, Size: 1657 bytes --]

Minimize X2APIC messages by printing 8 per line and dropping
the "enabled" flag since that's assumed.  It will still print
"disabled" if necessary.

v2: updated to apply to x86-tip

Signed-off-by: Mike Travis <travis@sgi.com>
Reviewed-by: Jack Steiner <steiner@sgi.com>
Reviewed-by: Robin Holt <holt@sgi.com>
---
 arch/x86/kernel/acpi/boot.c |    3 +++
 drivers/acpi/tables.c       |   16 +++++++++++-----
 2 files changed, 14 insertions(+), 5 deletions(-)

--- linux.orig/arch/x86/kernel/acpi/boot.c
+++ linux/arch/x86/kernel/acpi/boot.c
@@ -903,6 +903,9 @@ static int __init acpi_parse_madt_lapic_
 	if (!count) {
 		x2count = acpi_table_parse_madt(ACPI_MADT_TYPE_LOCAL_X2APIC,
 					acpi_parse_x2apic, MAX_LOCAL_APIC);
+		/* insure trailing newline is output */
+		pr_cont("\n");
+
 		count = acpi_table_parse_madt(ACPI_MADT_TYPE_LOCAL_APIC,
 					acpi_parse_lapic, MAX_LOCAL_APIC);
 	}
--- linux.orig/drivers/acpi/tables.c
+++ linux/drivers/acpi/tables.c
@@ -66,11 +66,17 @@ void acpi_table_print_madt_entry(struct
 		{
 			struct acpi_madt_local_x2apic *p =
 			    (struct acpi_madt_local_x2apic *)header;
-			printk(KERN_INFO PREFIX
-			       "X2APIC (apic_id[0x%02x] uid[0x%02x] %s)\n",
-			       p->local_apic_id, p->uid,
-			       (p->lapic_flags & ACPI_MADT_ENABLED) ?
-			       "enabled" : "disabled");
+
+			if ((p->uid & 7) == 0)
+				pr_info(PREFIX "X2APIC apic_id=uid:");
+
+			pr_cont(" %02x=%02x%s%s",
+				p->local_apic_id, p->uid,
+				/* assume "enabled" unless "disabled" */
+				(p->lapic_flags & ACPI_MADT_ENABLED) ?
+					"" : " disabled",
+				/* nl every 8th item */
+				(p->uid & 7) == 7 ? "\n" : "");
 		}
 		break;
 

-- 

Re: [PATCH 1/6] ACPI: Minimize X2APIC initial messages

[David Rientjes]

On Fri, 18 Feb 2011, Mike Travis wrote:

> Minimize X2APIC messages by printing 8 per line and dropping
> the "enabled" flag since that's assumed.  It will still print
> "disabled" if necessary.
> 
> v2: updated to apply to x86-tip
> 

For each patch in this series, it would be tremendously helpful to show 
what format the current output is in and what the format is after the 
patch is applied.

> Signed-off-by: Mike Travis <travis@sgi.com>
> Reviewed-by: Jack Steiner <steiner@sgi.com>
> Reviewed-by: Robin Holt <holt@sgi.com>
> ---
>  arch/x86/kernel/acpi/boot.c |    3 +++
>  drivers/acpi/tables.c       |   16 +++++++++++-----
>  2 files changed, 14 insertions(+), 5 deletions(-)
> 
> --- linux.orig/arch/x86/kernel/acpi/boot.c
> +++ linux/arch/x86/kernel/acpi/boot.c
> @@ -903,6 +903,9 @@ static int __init acpi_parse_madt_lapic_
>  	if (!count) {
>  		x2count = acpi_table_parse_madt(ACPI_MADT_TYPE_LOCAL_X2APIC,
>  					acpi_parse_x2apic, MAX_LOCAL_APIC);
> +		/* insure trailing newline is output */

s/insure/ensure/

> +		pr_cont("\n");

I know that this is the only code that passes ACPI_MADT_TYPE_LOCAL_X2APIC.  
That said, this line really has no place in the caller.

> +
>  		count = acpi_table_parse_madt(ACPI_MADT_TYPE_LOCAL_APIC,
>  					acpi_parse_lapic, MAX_LOCAL_APIC);
>  	}
> --- linux.orig/drivers/acpi/tables.c
> +++ linux/drivers/acpi/tables.c
> @@ -66,11 +66,17 @@ void acpi_table_print_madt_entry(struct
>  		{
>  			struct acpi_madt_local_x2apic *p =
>  			    (struct acpi_madt_local_x2apic *)header;
> -			printk(KERN_INFO PREFIX
> -			       "X2APIC (apic_id[0x%02x] uid[0x%02x] %s)\n",
> -			       p->local_apic_id, p->uid,
> -			       (p->lapic_flags & ACPI_MADT_ENABLED) ?
> -			       "enabled" : "disabled");
> +
> +			if ((p->uid & 7) == 0)
> +				pr_info(PREFIX "X2APIC apic_id=uid:");
> +
> +			pr_cont(" %02x=%02x%s%s",
> +				p->local_apic_id, p->uid,
> +				/* assume "enabled" unless "disabled" */
> +				(p->lapic_flags & ACPI_MADT_ENABLED) ?
> +					"" : " disabled",

Because you're printing only " disabled" when ACPI_MADT_ENABLED is not 
set, this seems like the format of the line would be ambiguous with regard 
to which entry it applies to.  I could imagine a line such as

	X2APIC apic_id=uid: 01=01 disabled 02=02

and then we're left wondering which entry is actually disabled.  I'd 
prefer "01=01(disabled) 02=02" instead.

Also, why did you drop the "0x" prefixes from the current format?

> +				/* nl every 8th item */
> +				(p->uid & 7) == 7 ? "\n" : "");
>  		}
>  		break;
>  

Re: [PATCH 1/6] ACPI: Minimize X2APIC initial messages

[Mike Travis]

David Rientjes wrote:
> On Fri, 18 Feb 2011, Mike Travis wrote:
> 
>> Minimize X2APIC messages by printing 8 per line and dropping
>> the "enabled" flag since that's assumed.  It will still print
>> "disabled" if necessary.
>>
>> v2: updated to apply to x86-tip
>>
> 
> For each patch in this series, it would be tremendously helpful to show 
> what format the current output is in and what the format is after the 
> patch is applied.

Will do.  I actually did think about this, as seeing a huge amount
of console output is a relatively rare occurrence... ;-)

> 
>> Signed-off-by: Mike Travis <travis@sgi.com>
>> Reviewed-by: Jack Steiner <steiner@sgi.com>
>> Reviewed-by: Robin Holt <holt@sgi.com>
>> ---
>>  arch/x86/kernel/acpi/boot.c |    3 +++
>>  drivers/acpi/tables.c       |   16 +++++++++++-----
>>  2 files changed, 14 insertions(+), 5 deletions(-)
>>
>> --- linux.orig/arch/x86/kernel/acpi/boot.c
>> +++ linux/arch/x86/kernel/acpi/boot.c
>> @@ -903,6 +903,9 @@ static int __init acpi_parse_madt_lapic_
>>  	if (!count) {
>>  		x2count = acpi_table_parse_madt(ACPI_MADT_TYPE_LOCAL_X2APIC,
>>  					acpi_parse_x2apic, MAX_LOCAL_APIC);
>> +		/* insure trailing newline is output */
> 
> s/insure/ensure/

Oops. ;-)
> 
>> +		pr_cont("\n");
> 
> I know that this is the only code that passes ACPI_MADT_TYPE_LOCAL_X2APIC.  
> That said, this line really has no place in the caller.

x2apic is probably the only type of system that can grow so large as to
need worrying about overflowing the log buffer.  That said, there is
logic in printk() to add a missing '\n'.  Should I just rely on that
and leave this out?

> 
>> +
>>  		count = acpi_table_parse_madt(ACPI_MADT_TYPE_LOCAL_APIC,
>>  					acpi_parse_lapic, MAX_LOCAL_APIC);
>>  	}
>> --- linux.orig/drivers/acpi/tables.c
>> +++ linux/drivers/acpi/tables.c
>> @@ -66,11 +66,17 @@ void acpi_table_print_madt_entry(struct
>>  		{
>>  			struct acpi_madt_local_x2apic *p =
>>  			    (struct acpi_madt_local_x2apic *)header;
>> -			printk(KERN_INFO PREFIX
>> -			       "X2APIC (apic_id[0x%02x] uid[0x%02x] %s)\n",
>> -			       p->local_apic_id, p->uid,
>> -			       (p->lapic_flags & ACPI_MADT_ENABLED) ?
>> -			       "enabled" : "disabled");
>> +
>> +			if ((p->uid & 7) == 0)
>> +				pr_info(PREFIX "X2APIC apic_id=uid:");
>> +
>> +			pr_cont(" %02x=%02x%s%s",
>> +				p->local_apic_id, p->uid,
>> +				/* assume "enabled" unless "disabled" */
>> +				(p->lapic_flags & ACPI_MADT_ENABLED) ?
>> +					"" : " disabled",
> 
> Because you're printing only " disabled" when ACPI_MADT_ENABLED is not 
> set, this seems like the format of the line would be ambiguous with regard 
> to which entry it applies to.  I could imagine a line such as
> 
> 	X2APIC apic_id=uid: 01=01 disabled 02=02
> 
> and then we're left wondering which entry is actually disabled.  I'd 
> prefer "01=01(disabled) 02=02" instead.

Yes, thanks.  That does make more sense.
> 
> Also, why did you drop the "0x" prefixes from the current format?

With 4096 cores that removes 8k bytes from the log buffer.  Do we really
need the 0x everywhere?  At what point does the context imply hex?

> 
>> +				/* nl every 8th item */
>> +				(p->uid & 7) == 7 ? "\n" : "");
>>  		}
>>  		break;
>>  

Re: [PATCH 1/6] ACPI: Minimize X2APIC initial messages

[David Rientjes]

On Mon, 21 Feb 2011, Mike Travis wrote:

> > > Minimize X2APIC messages by printing 8 per line and dropping
> > > the "enabled" flag since that's assumed.  It will still print
> > > "disabled" if necessary.
> > > 
> > > v2: updated to apply to x86-tip
> > > 
> > 
> > For each patch in this series, it would be tremendously helpful to show what
> > format the current output is in and what the format is after the patch is
> > applied.
> 
> Will do.  I actually did think about this, as seeing a huge amount
> of console output is a relatively rare occurrence... ;-)
> 
> > 
> > > Signed-off-by: Mike Travis <travis@sgi.com>
> > > Reviewed-by: Jack Steiner <steiner@sgi.com>
> > > Reviewed-by: Robin Holt <holt@sgi.com>
> > > ---
> > >  arch/x86/kernel/acpi/boot.c |    3 +++
> > >  drivers/acpi/tables.c       |   16 +++++++++++-----
> > >  2 files changed, 14 insertions(+), 5 deletions(-)
> > > 
> > > --- linux.orig/arch/x86/kernel/acpi/boot.c
> > > +++ linux/arch/x86/kernel/acpi/boot.c
> > > @@ -903,6 +903,9 @@ static int __init acpi_parse_madt_lapic_
> > >  	if (!count) {
> > >  		x2count = acpi_table_parse_madt(ACPI_MADT_TYPE_LOCAL_X2APIC,
> > >  					acpi_parse_x2apic, MAX_LOCAL_APIC);
> > > +		/* insure trailing newline is output */
> > 
> > s/insure/ensure/
> 
> Oops. ;-)
> > 
> > > +		pr_cont("\n");
> > 
> > I know that this is the only code that passes ACPI_MADT_TYPE_LOCAL_X2APIC.
> > That said, this line really has no place in the caller.
> 
> x2apic is probably the only type of system that can grow so large as to
> need worrying about overflowing the log buffer.  That said, there is
> logic in printk() to add a missing '\n'.  Should I just rely on that
> and leave this out?
> 

It's really a shame that it can't be dealt with in the call to 
acpi_table_parse_madt() even if it's just for ACPI_MADT_TYPE_LOCAL_X2APIC.  
The above would be a last resort if there was absolutely no way that you 
can determine which is the last entry to be printed.  I just thought I'd 
comment on it in the hope that you'd find some clever way of avoiding the 
newline in the caller :)

> > 
> > > +
> > >  		count = acpi_table_parse_madt(ACPI_MADT_TYPE_LOCAL_APIC,
> > >  					acpi_parse_lapic, MAX_LOCAL_APIC);
> > >  	}
> > > --- linux.orig/drivers/acpi/tables.c
> > > +++ linux/drivers/acpi/tables.c
> > > @@ -66,11 +66,17 @@ void acpi_table_print_madt_entry(struct
> > >  		{
> > >  			struct acpi_madt_local_x2apic *p =
> > >  			    (struct acpi_madt_local_x2apic *)header;
> > > -			printk(KERN_INFO PREFIX
> > > -			       "X2APIC (apic_id[0x%02x] uid[0x%02x] %s)\n",
> > > -			       p->local_apic_id, p->uid,
> > > -			       (p->lapic_flags & ACPI_MADT_ENABLED) ?
> > > -			       "enabled" : "disabled");
> > > +
> > > +			if ((p->uid & 7) == 0)
> > > +				pr_info(PREFIX "X2APIC apic_id=uid:");
> > > +
> > > +			pr_cont(" %02x=%02x%s%s",
> > > +				p->local_apic_id, p->uid,
> > > +				/* assume "enabled" unless "disabled" */
> > > +				(p->lapic_flags & ACPI_MADT_ENABLED) ?
> > > +					"" : " disabled",
> > 
> > Because you're printing only " disabled" when ACPI_MADT_ENABLED is not set,
> > this seems like the format of the line would be ambiguous with regard to
> > which entry it applies to.  I could imagine a line such as
> > 
> > 	X2APIC apic_id=uid: 01=01 disabled 02=02
> > 
> > and then we're left wondering which entry is actually disabled.  I'd prefer
> > "01=01(disabled) 02=02" instead.
> 
> Yes, thanks.  That does make more sense.
> > 
> > Also, why did you drop the "0x" prefixes from the current format?
> 
> With 4096 cores that removes 8k bytes from the log buffer.  Do we really
> need the 0x everywhere?  At what point does the context imply hex?
> 

I personally always prefer the "0x" prefix when you're outputting hex 
because it may not be clear from the value itself.  The VM sometimes 
outputs pfns in base-10 and sometimes in base-16 and it's very confusing 
unless you look at the implementation, for example.  I don't think "0x" is 
egregious long and is worth adding to remove any ambiguity in the value.

[PATCH 2/6] x86: Minimize initial e820 messages

[Mike Travis]

[-- Attachment #1: minimize-e820-msgs --]
[-- Type: text/plain, Size: 7139 bytes --]

Minimize the early e820 messages by printing less characters
for the address range as well as abbreviating the type info
for each entry.

Also the "modified physical RAM map" was mostly a duplicate of
the original e820 memory map printout.  Minimize the output
by only printing those entries that were actually modified.

v1: Added pertinent __init & __initdata specifiers
    Changed some inlines to __init functions to avoid the
    the compiler un-inlining them into the wrong section.

v2: updated to apply to x86-tip

Signed-off-by: Mike Travis <travis@sgi.com>
Reviewed-by: Jack Steiner <steiner@sgi.com>
Reviewed-by: Robin Holt <holt@sgi.com>
---
 arch/x86/kernel/e820.c      |  138 +++++++++++++++++++++++++++-----------------
 arch/x86/platform/efi/efi.c |   10 +--
 2 files changed, 91 insertions(+), 57 deletions(-)

--- linux.orig/arch/x86/kernel/e820.c
+++ linux/arch/x86/kernel/e820.c
@@ -39,6 +39,13 @@
 struct e820map e820;
 struct e820map e820_saved;
 
+/*
+ * Keep track of previous e820 mappings so we can reduce the number
+ * of messages when printing the "modified" e820 map
+ */
+static struct e820map e820_prev __initdata;
+static int e820_prev_saved __initdata;
+
 /* For PCI or other memory-mapped resources */
 unsigned long pci_mem_start = 0xaeedbabe;
 #ifdef CONFIG_PCI
@@ -125,42 +132,85 @@ void __init e820_add_region(u64 start, u
 	__e820_add_region(&e820, start, size, type);
 }
 
-static void __init e820_print_type(u32 type)
+/* long description */
+static const char * __init e820_type_to_string(int e820_type)
+{
+	switch (e820_type) {
+	case E820_RESERVED_KERN:	return "Kernel RAM";
+	case E820_RAM:	return "System RAM";
+	case E820_ACPI:	return "ACPI Tables";
+	case E820_NVS:	return "ACPI Non-Volatile Storage";
+	case E820_UNUSABLE:	return "Unusable Memory";
+	default:	return "Reserved";
+	}
+}
+
+/* short description, saves log space when there are 100's of e820 entries */
+static char * __init e820_types(int e820_type)
 {
-	switch (type) {
-	case E820_RAM:
-	case E820_RESERVED_KERN:
-		printk(KERN_CONT "(usable)");
-		break;
-	case E820_RESERVED:
-		printk(KERN_CONT "(reserved)");
-		break;
-	case E820_ACPI:
-		printk(KERN_CONT "(ACPI data)");
-		break;
-	case E820_NVS:
-		printk(KERN_CONT "(ACPI NVS)");
-		break;
-	case E820_UNUSABLE:
-		printk(KERN_CONT "(unusable)");
-		break;
-	default:
-		printk(KERN_CONT "type %u", type);
-		break;
+	switch (e820_type) {
+	case E820_RESERVED_KERN:	return "KRAM";
+	case E820_RAM:	return "SRAM";
+	case E820_ACPI:	return "ACPI";
+	case E820_NVS:	return "NVS";
+	case E820_UNUSABLE:	return "UM";
+	default:	return "RESVD";
 	}
 }
 
+static void __init e820_print_header(void)
+{
+	pr_info("types: %s=(%s) %s=(%s) %s=(%s) %s=(%s) %s=(%s) %s=(%s)\n",
+		e820_types(E820_RESERVED_KERN),
+				e820_type_to_string(E820_RESERVED_KERN),
+		e820_types(E820_RAM), e820_type_to_string(E820_RAM),
+		e820_types(E820_RESERVED), e820_type_to_string(E820_RESERVED),
+		e820_types(E820_ACPI), e820_type_to_string(E820_ACPI),
+		e820_types(E820_NVS), e820_type_to_string(E820_NVS),
+		e820_types(E820_UNUSABLE), e820_type_to_string(E820_UNUSABLE));
+}
+
+/* compare new entry with old so we only print "modified" entries */
+static int __init not_modified(int i, int j)
+{
+	for (; j < e820_prev.nr_map &&
+		e820_prev.map[j].addr <= e820.map[i].addr; j++) {
+
+		if (e820.map[i].addr == e820_prev.map[j].addr &&
+		    e820.map[i].size == e820_prev.map[j].size &&
+		    e820.map[i].type == e820_prev.map[j].type)
+			return j;
+	}
+	return 0;
+}
+
 void __init e820_print_map(char *who)
 {
-	int i;
+	int i, j = 0;
+	int hdr = 0;
+	int mod = strcmp(who, "modified") == 0;
 
 	for (i = 0; i < e820.nr_map; i++) {
-		printk(KERN_INFO " %s: %016Lx - %016Lx ", who,
-		       (unsigned long long) e820.map[i].addr,
-		       (unsigned long long)
-		       (e820.map[i].addr + e820.map[i].size));
-		e820_print_type(e820.map[i].type);
-		printk(KERN_CONT "\n");
+		/* only print those entries that were really modified */
+		if (mod)
+			j = not_modified(i, j);
+
+		if (!j) {
+			if (!hdr++)
+				e820_print_header();
+
+			pr_info("%s: %Lx+%Lx (%s)\n", who,
+			       (unsigned long long) e820.map[i].addr,
+			       (unsigned long long) e820.map[i].size,
+			       e820_types(e820.map[i].type));
+		}
+	}
+	if (!hdr)
+		pr_info("<none>\n");
+
+	if (!e820_prev_saved) {
+		memcpy(&e820_prev, &e820, sizeof(struct e820map));
+		e820_prev_saved = 1;
 	}
 }
 
@@ -437,13 +487,11 @@ static u64 __init __e820_update_range(st
 		size = ULLONG_MAX - start;
 
 	end = start + size;
-	printk(KERN_DEBUG "e820 update range: %016Lx - %016Lx ",
+	pr_debug("e820 update range: %Lx+%Lx %s ==> %s\n",
 		       (unsigned long long) start,
-		       (unsigned long long) end);
-	e820_print_type(old_type);
-	printk(KERN_CONT " ==> ");
-	e820_print_type(new_type);
-	printk(KERN_CONT "\n");
+		       (unsigned long long) size,
+			e820_type_to_string(old_type),
+			e820_type_to_string(new_type));
 
 	for (i = 0; i < e820x->nr_map; i++) {
 		struct e820entry *ei = &e820x->map[i];
@@ -518,12 +566,10 @@ u64 __init e820_remove_range(u64 start,
 		size = ULLONG_MAX - start;
 
 	end = start + size;
-	printk(KERN_DEBUG "e820 remove range: %016Lx - %016Lx ",
+	printk(KERN_DEBUG "e820 remove range: %016Lx - %016Lx %s\n",
 		       (unsigned long long) start,
-		       (unsigned long long) end);
-	if (checktype)
-		e820_print_type(old_type);
-	printk(KERN_CONT "\n");
+		       (unsigned long long) end,
+			checktype ? e820_type_to_string(old_type) : "");
 
 	for (i = 0; i < e820.nr_map; i++) {
 		struct e820entry *ei = &e820.map[i];
@@ -576,7 +622,7 @@ void __init update_e820(void)
 	if (sanitize_e820_map(e820.map, ARRAY_SIZE(e820.map), &nr_map))
 		return;
 	e820.nr_map = nr_map;
-	printk(KERN_INFO "modified physical RAM map:\n");
+	printk(KERN_INFO "physical RAM map entries that were modified:\n");
 	e820_print_map("modified");
 }
 static void __init update_e820_saved(void)
@@ -926,18 +972,6 @@ void __init finish_e820_parsing(void)
 	}
 }
 
-static inline const char *e820_type_to_string(int e820_type)
-{
-	switch (e820_type) {
-	case E820_RESERVED_KERN:
-	case E820_RAM:	return "System RAM";
-	case E820_ACPI:	return "ACPI Tables";
-	case E820_NVS:	return "ACPI Non-volatile Storage";
-	case E820_UNUSABLE:	return "Unusable memory";
-	default:	return "reserved";
-	}
-}
-
 /*
  * Mark e820 reserved areas as busy for the resource manager.
  */
--- linux.orig/arch/x86/platform/efi/efi.c
+++ linux/arch/x86/platform/efi/efi.c
@@ -306,11 +306,11 @@ static void __init print_efi_memmap(void
 	     p < memmap.map_end;
 	     p += memmap.desc_size, i++) {
 		md = p;
-		printk(KERN_INFO PFX "mem%02u: type=%u, attr=0x%llx, "
-			"range=[0x%016llx-0x%016llx) (%lluMB)\n",
-			i, md->type, md->attribute, md->phys_addr,
-			md->phys_addr + (md->num_pages << EFI_PAGE_SHIFT),
-			(md->num_pages >> (20 - EFI_PAGE_SHIFT)));
+		pr_info(PFX
+			"mem%u: range %llx+%llx (%lluMB) type %u attr %llx\n",
+			i, md->phys_addr, md->num_pages << EFI_PAGE_SHIFT,
+			(md->num_pages >> (20 - EFI_PAGE_SHIFT)),
+			md->type, md->attribute);
 	}
 }
 #endif  /*  EFI_DEBUG  */

-- 

Re: [PATCH 2/6] x86: Minimize initial e820 messages

[David Rientjes]

On Fri, 18 Feb 2011, Mike Travis wrote:

> Minimize the early e820 messages by printing less characters
> for the address range as well as abbreviating the type info
> for each entry.
> 
> Also the "modified physical RAM map" was mostly a duplicate of
> the original e820 memory map printout.  Minimize the output
> by only printing those entries that were actually modified.
> 
> v1: Added pertinent __init & __initdata specifiers
>     Changed some inlines to __init functions to avoid the
>     the compiler un-inlining them into the wrong section.
> 
> v2: updated to apply to x86-tip
> 
> Signed-off-by: Mike Travis <travis@sgi.com>
> Reviewed-by: Jack Steiner <steiner@sgi.com>
> Reviewed-by: Robin Holt <holt@sgi.com>
> ---
>  arch/x86/kernel/e820.c      |  138 +++++++++++++++++++++++++++-----------------
>  arch/x86/platform/efi/efi.c |   10 +--
>  2 files changed, 91 insertions(+), 57 deletions(-)
> 
> --- linux.orig/arch/x86/kernel/e820.c
> +++ linux/arch/x86/kernel/e820.c
> @@ -39,6 +39,13 @@
>  struct e820map e820;
>  struct e820map e820_saved;
>  
> +/*
> + * Keep track of previous e820 mappings so we can reduce the number
> + * of messages when printing the "modified" e820 map
> + */
> +static struct e820map e820_prev __initdata;
> +static int e820_prev_saved __initdata;

bool?

> +
>  /* For PCI or other memory-mapped resources */
>  unsigned long pci_mem_start = 0xaeedbabe;
>  #ifdef CONFIG_PCI
> @@ -125,42 +132,85 @@ void __init e820_add_region(u64 start, u
>  	__e820_add_region(&e820, start, size, type);
>  }
>  
> -static void __init e820_print_type(u32 type)
> +/* long description */
> +static const char * __init e820_type_to_string(int e820_type)
> +{
> +	switch (e820_type) {
> +	case E820_RESERVED_KERN:	return "Kernel RAM";
> +	case E820_RAM:	return "System RAM";
> +	case E820_ACPI:	return "ACPI Tables";
> +	case E820_NVS:	return "ACPI Non-Volatile Storage";
> +	case E820_UNUSABLE:	return "Unusable Memory";
> +	default:	return "Reserved";
> +	}
> +}

All of the callers of this function would probably benefit from 
surrounding each return string with ( and ).

> +
> +/* short description, saves log space when there are 100's of e820 entries */
> +static char * __init e820_types(int e820_type)
>  {
> -	switch (type) {
> -	case E820_RAM:
> -	case E820_RESERVED_KERN:
> -		printk(KERN_CONT "(usable)");
> -		break;
> -	case E820_RESERVED:
> -		printk(KERN_CONT "(reserved)");
> -		break;
> -	case E820_ACPI:
> -		printk(KERN_CONT "(ACPI data)");
> -		break;
> -	case E820_NVS:
> -		printk(KERN_CONT "(ACPI NVS)");
> -		break;
> -	case E820_UNUSABLE:
> -		printk(KERN_CONT "(unusable)");
> -		break;
> -	default:
> -		printk(KERN_CONT "type %u", type);
> -		break;
> +	switch (e820_type) {
> +	case E820_RESERVED_KERN:	return "KRAM";
> +	case E820_RAM:	return "SRAM";

Using the abbreviation "SRAM" for "system RAM" is just going to lead to 
confusion.

> +	case E820_ACPI:	return "ACPI";
> +	case E820_NVS:	return "NVS";
> +	case E820_UNUSABLE:	return "UM";

I know these are intended to be very short, but nobody is going to 
conclude that "UM" means unusuable memory.

> +	default:	return "RESVD";
>  	}
>  }
>  
> +static void __init e820_print_header(void)
> +{
> +	pr_info("types: %s=(%s) %s=(%s) %s=(%s) %s=(%s) %s=(%s) %s=(%s)\n",
> +		e820_types(E820_RESERVED_KERN),
> +				e820_type_to_string(E820_RESERVED_KERN),
> +		e820_types(E820_RAM), e820_type_to_string(E820_RAM),
> +		e820_types(E820_RESERVED), e820_type_to_string(E820_RESERVED),
> +		e820_types(E820_ACPI), e820_type_to_string(E820_ACPI),
> +		e820_types(E820_NVS), e820_type_to_string(E820_NVS),
> +		e820_types(E820_UNUSABLE), e820_type_to_string(E820_UNUSABLE));
> +}
> +
> +/* compare new entry with old so we only print "modified" entries */
> +static int __init not_modified(int i, int j)

I know it's static, but this needs a better function name.  I hope it's 
never passed negative actuals by mistake.

> +{
> +	for (; j < e820_prev.nr_map &&
> +		e820_prev.map[j].addr <= e820.map[i].addr; j++) {
> +
> +		if (e820.map[i].addr == e820_prev.map[j].addr &&
> +		    e820.map[i].size == e820_prev.map[j].size &&
> +		    e820.map[i].type == e820_prev.map[j].type)
> +			return j;
> +	}
> +	return 0;
> +}
> +
>  void __init e820_print_map(char *who)
>  {
> -	int i;
> +	int i, j = 0;
> +	int hdr = 0;
> +	int mod = strcmp(who, "modified") == 0;

bool?

>  
>  	for (i = 0; i < e820.nr_map; i++) {
> -		printk(KERN_INFO " %s: %016Lx - %016Lx ", who,
> -		       (unsigned long long) e820.map[i].addr,
> -		       (unsigned long long)
> -		       (e820.map[i].addr + e820.map[i].size));
> -		e820_print_type(e820.map[i].type);
> -		printk(KERN_CONT "\n");
> +		/* only print those entries that were really modified */
> +		if (mod)
> +			j = not_modified(i, j);
> +
> +		if (!j) {
> +			if (!hdr++)
> +				e820_print_header();
> +
> +			pr_info("%s: %Lx+%Lx (%s)\n", who,

We don't want a space prefix anymore?

> +			       (unsigned long long) e820.map[i].addr,
> +			       (unsigned long long) e820.map[i].size,
> +			       e820_types(e820.map[i].type));
> +		}
> +	}
> +	if (!hdr)
> +		pr_info("<none>\n");
> +
> +	if (!e820_prev_saved) {
> +		memcpy(&e820_prev, &e820, sizeof(struct e820map));
> +		e820_prev_saved = 1;
>  	}
>  }
>  
> @@ -437,13 +487,11 @@ static u64 __init __e820_update_range(st
>  		size = ULLONG_MAX - start;
>  
>  	end = start + size;
> -	printk(KERN_DEBUG "e820 update range: %016Lx - %016Lx ",
> +	pr_debug("e820 update range: %Lx+%Lx %s ==> %s\n",
>  		       (unsigned long long) start,
> -		       (unsigned long long) end);
> -	e820_print_type(old_type);
> -	printk(KERN_CONT " ==> ");
> -	e820_print_type(new_type);
> -	printk(KERN_CONT "\n");
> +		       (unsigned long long) size,
> +			e820_type_to_string(old_type),
> +			e820_type_to_string(new_type));
>  
>  	for (i = 0; i < e820x->nr_map; i++) {
>  		struct e820entry *ei = &e820x->map[i];
> @@ -518,12 +566,10 @@ u64 __init e820_remove_range(u64 start,
>  		size = ULLONG_MAX - start;
>  
>  	end = start + size;
> -	printk(KERN_DEBUG "e820 remove range: %016Lx - %016Lx ",
> +	printk(KERN_DEBUG "e820 remove range: %016Lx - %016Lx %s\n",
>  		       (unsigned long long) start,
> -		       (unsigned long long) end);
> -	if (checktype)
> -		e820_print_type(old_type);
> -	printk(KERN_CONT "\n");
> +		       (unsigned long long) end,
> +			checktype ? e820_type_to_string(old_type) : "");
>  
>  	for (i = 0; i < e820.nr_map; i++) {
>  		struct e820entry *ei = &e820.map[i];
> @@ -576,7 +622,7 @@ void __init update_e820(void)
>  	if (sanitize_e820_map(e820.map, ARRAY_SIZE(e820.map), &nr_map))
>  		return;
>  	e820.nr_map = nr_map;
> -	printk(KERN_INFO "modified physical RAM map:\n");
> +	printk(KERN_INFO "physical RAM map entries that were modified:\n");
>  	e820_print_map("modified");
>  }
>  static void __init update_e820_saved(void)
> @@ -926,18 +972,6 @@ void __init finish_e820_parsing(void)
>  	}
>  }
>  
> -static inline const char *e820_type_to_string(int e820_type)
> -{
> -	switch (e820_type) {
> -	case E820_RESERVED_KERN:
> -	case E820_RAM:	return "System RAM";
> -	case E820_ACPI:	return "ACPI Tables";
> -	case E820_NVS:	return "ACPI Non-volatile Storage";
> -	case E820_UNUSABLE:	return "Unusable memory";
> -	default:	return "reserved";
> -	}
> -}
> -
>  /*
>   * Mark e820 reserved areas as busy for the resource manager.
>   */
> --- linux.orig/arch/x86/platform/efi/efi.c
> +++ linux/arch/x86/platform/efi/efi.c
> @@ -306,11 +306,11 @@ static void __init print_efi_memmap(void
>  	     p < memmap.map_end;
>  	     p += memmap.desc_size, i++) {
>  		md = p;
> -		printk(KERN_INFO PFX "mem%02u: type=%u, attr=0x%llx, "
> -			"range=[0x%016llx-0x%016llx) (%lluMB)\n",
> -			i, md->type, md->attribute, md->phys_addr,
> -			md->phys_addr + (md->num_pages << EFI_PAGE_SHIFT),
> -			(md->num_pages >> (20 - EFI_PAGE_SHIFT)));
> +		pr_info(PFX
> +			"mem%u: range %llx+%llx (%lluMB) type %u attr %llx\n",

The range you're printing is now ambiguous because you're now showing the 
length rather than the ending length (implying that what you're displaying 
is not a range at all, but it's specified as one).  I typically don't see 
"100+12" as describing [100,112), for example.

This is also the second time in the patchset where you're printing hex 
values without a "0x" prefix, that can be confusing and it's not like "0x" 
is egregiously long.  I can understand removing the zero padding, but not 
the prefix.

> +			i, md->phys_addr, md->num_pages << EFI_PAGE_SHIFT,
> +			(md->num_pages >> (20 - EFI_PAGE_SHIFT)),
> +			md->type, md->attribute);
>  	}
>  }
>  #endif  /*  EFI_DEBUG  */

Re: [PATCH 2/6] x86: Minimize initial e820 messages

[Mike Travis]

David Rientjes wrote:
> On Fri, 18 Feb 2011, Mike Travis wrote:
> 
>> Minimize the early e820 messages by printing less characters
>> for the address range as well as abbreviating the type info
>> for each entry.
>>
>> Also the "modified physical RAM map" was mostly a duplicate of
>> the original e820 memory map printout.  Minimize the output
>> by only printing those entries that were actually modified.
>>
>> v1: Added pertinent __init & __initdata specifiers
>>     Changed some inlines to __init functions to avoid the
>>     the compiler un-inlining them into the wrong section.
>>
>> v2: updated to apply to x86-tip
>>
>> Signed-off-by: Mike Travis <travis@sgi.com>
>> Reviewed-by: Jack Steiner <steiner@sgi.com>
>> Reviewed-by: Robin Holt <holt@sgi.com>
>> ---
>>  arch/x86/kernel/e820.c      |  138 +++++++++++++++++++++++++++-----------------
>>  arch/x86/platform/efi/efi.c |   10 +--
>>  2 files changed, 91 insertions(+), 57 deletions(-)
>>
>> --- linux.orig/arch/x86/kernel/e820.c
>> +++ linux/arch/x86/kernel/e820.c
>> @@ -39,6 +39,13 @@
>>  struct e820map e820;
>>  struct e820map e820_saved;
>>  
>> +/*
>> + * Keep track of previous e820 mappings so we can reduce the number
>> + * of messages when printing the "modified" e820 map
>> + */
>> +static struct e820map e820_prev __initdata;
>> +static int e820_prev_saved __initdata;
> 
> bool?
> 
>> +
>>  /* For PCI or other memory-mapped resources */
>>  unsigned long pci_mem_start = 0xaeedbabe;
>>  #ifdef CONFIG_PCI
>> @@ -125,42 +132,85 @@ void __init e820_add_region(u64 start, u
>>  	__e820_add_region(&e820, start, size, type);
>>  }
>>  
>> -static void __init e820_print_type(u32 type)
>> +/* long description */
>> +static const char * __init e820_type_to_string(int e820_type)
>> +{
>> +	switch (e820_type) {
>> +	case E820_RESERVED_KERN:	return "Kernel RAM";
>> +	case E820_RAM:	return "System RAM";
>> +	case E820_ACPI:	return "ACPI Tables";
>> +	case E820_NVS:	return "ACPI Non-Volatile Storage";
>> +	case E820_UNUSABLE:	return "Unusable Memory";
>> +	default:	return "Reserved";
>> +	}
>> +}
> 
> All of the callers of this function would probably benefit from 
> surrounding each return string with ( and ).

Good point, thanks.
> 
>> +
>> +/* short description, saves log space when there are 100's of e820 entries */
>> +static char * __init e820_types(int e820_type)
>>  {
>> -	switch (type) {
>> -	case E820_RAM:
>> -	case E820_RESERVED_KERN:
>> -		printk(KERN_CONT "(usable)");
>> -		break;
>> -	case E820_RESERVED:
>> -		printk(KERN_CONT "(reserved)");
>> -		break;
>> -	case E820_ACPI:
>> -		printk(KERN_CONT "(ACPI data)");
>> -		break;
>> -	case E820_NVS:
>> -		printk(KERN_CONT "(ACPI NVS)");
>> -		break;
>> -	case E820_UNUSABLE:
>> -		printk(KERN_CONT "(unusable)");
>> -		break;
>> -	default:
>> -		printk(KERN_CONT "type %u", type);
>> -		break;
>> +	switch (e820_type) {
>> +	case E820_RESERVED_KERN:	return "KRAM";
>> +	case E820_RAM:	return "SRAM";
> 
> Using the abbreviation "SRAM" for "system RAM" is just going to lead to 
> confusion.

Suggestions?

> 
>> +	case E820_ACPI:	return "ACPI";
>> +	case E820_NVS:	return "NVS";
>> +	case E820_UNUSABLE:	return "UM";
> 
> I know these are intended to be very short, but nobody is going to 
> conclude that "UM" means unusuable memory.

UM, what do you think it should be?  ;-)

> 
>> +	default:	return "RESVD";
>>  	}
>>  }
>>  
>> +static void __init e820_print_header(void)
>> +{
>> +	pr_info("types: %s=(%s) %s=(%s) %s=(%s) %s=(%s) %s=(%s) %s=(%s)\n",
>> +		e820_types(E820_RESERVED_KERN),
>> +				e820_type_to_string(E820_RESERVED_KERN),
>> +		e820_types(E820_RAM), e820_type_to_string(E820_RAM),
>> +		e820_types(E820_RESERVED), e820_type_to_string(E820_RESERVED),
>> +		e820_types(E820_ACPI), e820_type_to_string(E820_ACPI),
>> +		e820_types(E820_NVS), e820_type_to_string(E820_NVS),
>> +		e820_types(E820_UNUSABLE), e820_type_to_string(E820_UNUSABLE));
>> +}
>> +
>> +/* compare new entry with old so we only print "modified" entries */
>> +static int __init not_modified(int i, int j)
> 
> I know it's static, but this needs a better function name.  I hope it's 
> never passed negative actuals by mistake.

What (!not) doesn't make sense? ;-)

> 
>> +{
>> +	for (; j < e820_prev.nr_map &&
>> +		e820_prev.map[j].addr <= e820.map[i].addr; j++) {
>> +
>> +		if (e820.map[i].addr == e820_prev.map[j].addr &&
>> +		    e820.map[i].size == e820_prev.map[j].size &&
>> +		    e820.map[i].type == e820_prev.map[j].type)
>> +			return j;
>> +	}
>> +	return 0;
>> +}
>> +
>>  void __init e820_print_map(char *who)
>>  {
>> -	int i;
>> +	int i, j = 0;
>> +	int hdr = 0;
>> +	int mod = strcmp(who, "modified") == 0;
> 
> bool?
> 
>>  
>>  	for (i = 0; i < e820.nr_map; i++) {
>> -		printk(KERN_INFO " %s: %016Lx - %016Lx ", who,
>> -		       (unsigned long long) e820.map[i].addr,
>> -		       (unsigned long long)
>> -		       (e820.map[i].addr + e820.map[i].size));
>> -		e820_print_type(e820.map[i].type);
>> -		printk(KERN_CONT "\n");
>> +		/* only print those entries that were really modified */
>> +		if (mod)
>> +			j = not_modified(i, j);
>> +
>> +		if (!j) {
>> +			if (!hdr++)
>> +				e820_print_header();
>> +
>> +			pr_info("%s: %Lx+%Lx (%s)\n", who,
> 
> We don't want a space prefix anymore?

Why would we?
> 
>> +			       (unsigned long long) e820.map[i].addr,
>> +			       (unsigned long long) e820.map[i].size,
>> +			       e820_types(e820.map[i].type));
>> +		}
>> +	}
>> +	if (!hdr)
>> +		pr_info("<none>\n");
>> +
>> +	if (!e820_prev_saved) {
>> +		memcpy(&e820_prev, &e820, sizeof(struct e820map));
>> +		e820_prev_saved = 1;
>>  	}
>>  }
>>  
>> @@ -437,13 +487,11 @@ static u64 __init __e820_update_range(st
>>  		size = ULLONG_MAX - start;
>>  
>>  	end = start + size;
>> -	printk(KERN_DEBUG "e820 update range: %016Lx - %016Lx ",
>> +	pr_debug("e820 update range: %Lx+%Lx %s ==> %s\n",
>>  		       (unsigned long long) start,
>> -		       (unsigned long long) end);
>> -	e820_print_type(old_type);
>> -	printk(KERN_CONT " ==> ");
>> -	e820_print_type(new_type);
>> -	printk(KERN_CONT "\n");
>> +		       (unsigned long long) size,
>> +			e820_type_to_string(old_type),
>> +			e820_type_to_string(new_type));
>>  
>>  	for (i = 0; i < e820x->nr_map; i++) {
>>  		struct e820entry *ei = &e820x->map[i];
>> @@ -518,12 +566,10 @@ u64 __init e820_remove_range(u64 start,
>>  		size = ULLONG_MAX - start;
>>  
>>  	end = start + size;
>> -	printk(KERN_DEBUG "e820 remove range: %016Lx - %016Lx ",
>> +	printk(KERN_DEBUG "e820 remove range: %016Lx - %016Lx %s\n",
>>  		       (unsigned long long) start,
>> -		       (unsigned long long) end);
>> -	if (checktype)
>> -		e820_print_type(old_type);
>> -	printk(KERN_CONT "\n");
>> +		       (unsigned long long) end,
>> +			checktype ? e820_type_to_string(old_type) : "");
>>  
>>  	for (i = 0; i < e820.nr_map; i++) {
>>  		struct e820entry *ei = &e820.map[i];
>> @@ -576,7 +622,7 @@ void __init update_e820(void)
>>  	if (sanitize_e820_map(e820.map, ARRAY_SIZE(e820.map), &nr_map))
>>  		return;
>>  	e820.nr_map = nr_map;
>> -	printk(KERN_INFO "modified physical RAM map:\n");
>> +	printk(KERN_INFO "physical RAM map entries that were modified:\n");
>>  	e820_print_map("modified");
>>  }
>>  static void __init update_e820_saved(void)
>> @@ -926,18 +972,6 @@ void __init finish_e820_parsing(void)
>>  	}
>>  }
>>  
>> -static inline const char *e820_type_to_string(int e820_type)
>> -{
>> -	switch (e820_type) {
>> -	case E820_RESERVED_KERN:
>> -	case E820_RAM:	return "System RAM";
>> -	case E820_ACPI:	return "ACPI Tables";
>> -	case E820_NVS:	return "ACPI Non-volatile Storage";
>> -	case E820_UNUSABLE:	return "Unusable memory";
>> -	default:	return "reserved";
>> -	}
>> -}
>> -
>>  /*
>>   * Mark e820 reserved areas as busy for the resource manager.
>>   */
>> --- linux.orig/arch/x86/platform/efi/efi.c
>> +++ linux/arch/x86/platform/efi/efi.c
>> @@ -306,11 +306,11 @@ static void __init print_efi_memmap(void
>>  	     p < memmap.map_end;
>>  	     p += memmap.desc_size, i++) {
>>  		md = p;
>> -		printk(KERN_INFO PFX "mem%02u: type=%u, attr=0x%llx, "
>> -			"range=[0x%016llx-0x%016llx) (%lluMB)\n",
>> -			i, md->type, md->attribute, md->phys_addr,
>> -			md->phys_addr + (md->num_pages << EFI_PAGE_SHIFT),
>> -			(md->num_pages >> (20 - EFI_PAGE_SHIFT)));
>> +		pr_info(PFX
>> +			"mem%u: range %llx+%llx (%lluMB) type %u attr %llx\n",
> 
> The range you're printing is now ambiguous because you're now showing the 
> length rather than the ending length (implying that what you're displaying 
> is not a range at all, but it's specified as one).  I typically don't see 
> "100+12" as describing [100,112), for example.

Again, I'm open for suggestions.  I thought that changing base-end to base+range
would be coherent?  
> 
> This is also the second time in the patchset where you're printing hex 
> values without a "0x" prefix, that can be confusing and it's not like "0x" 
> is egregiously long.  I can understand removing the zero padding, but not 
> the prefix.

The problem comes when there are zillions of them.

> 
>> +			i, md->phys_addr, md->num_pages << EFI_PAGE_SHIFT,
>> +			(md->num_pages >> (20 - EFI_PAGE_SHIFT)),
>> +			md->type, md->attribute);
>>  	}
>>  }
>>  #endif  /*  EFI_DEBUG  */

Re: [PATCH 2/6] x86: Minimize initial e820 messages

[David Rientjes]

On Mon, 21 Feb 2011, Mike Travis wrote:

> > > --- linux.orig/arch/x86/kernel/e820.c
> > > +++ linux/arch/x86/kernel/e820.c
> > > @@ -39,6 +39,13 @@
> > >  struct e820map e820;
> > >  struct e820map e820_saved;
> > >  +/*
> > > + * Keep track of previous e820 mappings so we can reduce the number
> > > + * of messages when printing the "modified" e820 map
> > > + */
> > > +static struct e820map e820_prev __initdata;
> > > +static int e820_prev_saved __initdata;
> > 
> > bool?
> > 
> > > +
> > >  /* For PCI or other memory-mapped resources */
> > >  unsigned long pci_mem_start = 0xaeedbabe;
> > >  #ifdef CONFIG_PCI
> > > @@ -125,42 +132,85 @@ void __init e820_add_region(u64 start, u
> > >  	__e820_add_region(&e820, start, size, type);
> > >  }
> > >  -static void __init e820_print_type(u32 type)
> > > +/* long description */
> > > +static const char * __init e820_type_to_string(int e820_type)
> > > +{
> > > +	switch (e820_type) {
> > > +	case E820_RESERVED_KERN:	return "Kernel RAM";
> > > +	case E820_RAM:	return "System RAM";
> > > +	case E820_ACPI:	return "ACPI Tables";
> > > +	case E820_NVS:	return "ACPI Non-Volatile Storage";
> > > +	case E820_UNUSABLE:	return "Unusable Memory";
> > > +	default:	return "Reserved";
> > > +	}
> > > +}
> > 
> > All of the callers of this function would probably benefit from surrounding
> > each return string with ( and ).
> 
> Good point, thanks.
> > 
> > > +
> > > +/* short description, saves log space when there are 100's of e820
> > > entries */
> > > +static char * __init e820_types(int e820_type)
> > >  {
> > > -	switch (type) {
> > > -	case E820_RAM:
> > > -	case E820_RESERVED_KERN:
> > > -		printk(KERN_CONT "(usable)");
> > > -		break;
> > > -	case E820_RESERVED:
> > > -		printk(KERN_CONT "(reserved)");
> > > -		break;
> > > -	case E820_ACPI:
> > > -		printk(KERN_CONT "(ACPI data)");
> > > -		break;
> > > -	case E820_NVS:
> > > -		printk(KERN_CONT "(ACPI NVS)");
> > > -		break;
> > > -	case E820_UNUSABLE:
> > > -		printk(KERN_CONT "(unusable)");
> > > -		break;
> > > -	default:
> > > -		printk(KERN_CONT "type %u", type);
> > > -		break;
> > > +	switch (e820_type) {
> > > +	case E820_RESERVED_KERN:	return "KRAM";
> > > +	case E820_RAM:	return "SRAM";
> > 
> > Using the abbreviation "SRAM" for "system RAM" is just going to lead to
> > confusion.
> 
> Suggestions?
> 

Well, SRAM is just unacceptable for obvious reasons.  I hope something 
like "SysRAM" and "KernRAM" isn't too long.

> > 
> > > +	case E820_ACPI:	return "ACPI";
> > > +	case E820_NVS:	return "NVS";
> > > +	case E820_UNUSABLE:	return "UM";
> > 
> > I know these are intended to be very short, but nobody is going to conclude
> > that "UM" means unusuable memory.
> 
> UM, what do you think it should be?  ;-)
> 

lol, probably just "unusable."

> > 
> > > +	default:	return "RESVD";
> > >  	}
> > >  }
> > >  +static void __init e820_print_header(void)
> > > +{
> > > +	pr_info("types: %s=(%s) %s=(%s) %s=(%s) %s=(%s) %s=(%s) %s=(%s)\n",
> > > +		e820_types(E820_RESERVED_KERN),
> > > +				e820_type_to_string(E820_RESERVED_KERN),
> > > +		e820_types(E820_RAM), e820_type_to_string(E820_RAM),
> > > +		e820_types(E820_RESERVED), e820_type_to_string(E820_RESERVED),
> > > +		e820_types(E820_ACPI), e820_type_to_string(E820_ACPI),
> > > +		e820_types(E820_NVS), e820_type_to_string(E820_NVS),
> > > +		e820_types(E820_UNUSABLE),
> > > e820_type_to_string(E820_UNUSABLE));
> > > +}
> > > +
> > > +/* compare new entry with old so we only print "modified" entries */
> > > +static int __init not_modified(int i, int j)
> > 
> > I know it's static, but this needs a better function name.  I hope it's
> > never passed negative actuals by mistake.
> 
> What (!not) doesn't make sense? ;-)
> 

It's a poor function name because it's way too generic, it should include 
e820 in some way.  e820_entry_is_unmodified(), for example.

> > >  void __init e820_print_map(char *who)
> > >  {
> > > -	int i;
> > > +	int i, j = 0;
> > > +	int hdr = 0;
> > > +	int mod = strcmp(who, "modified") == 0;
> > 
> > bool?
> > 
> > >   	for (i = 0; i < e820.nr_map; i++) {
> > > -		printk(KERN_INFO " %s: %016Lx - %016Lx ", who,
> > > -		       (unsigned long long) e820.map[i].addr,
> > > -		       (unsigned long long)
> > > -		       (e820.map[i].addr + e820.map[i].size));
> > > -		e820_print_type(e820.map[i].type);
> > > -		printk(KERN_CONT "\n");
> > > +		/* only print those entries that were really modified */
> > > +		if (mod)
> > > +			j = not_modified(i, j);
> > > +
> > > +		if (!j) {
> > > +			if (!hdr++)
> > > +				e820_print_header();
> > > +
> > > +			pr_info("%s: %Lx+%Lx (%s)\n", who,
> > 
> > We don't want a space prefix anymore?
> 
> Why would we?

To differentiate it from the other messages since we're printing multiple 
lines that only make sense in relationship to one another (like how we 
print stacks on x86).

> > 
> > > +			       (unsigned long long) e820.map[i].addr,
> > > +			       (unsigned long long) e820.map[i].size,
> > > +			       e820_types(e820.map[i].type));
> > > +		}
> > > +	}
> > > +	if (!hdr)
> > > +		pr_info("<none>\n");
> > > +
> > > +	if (!e820_prev_saved) {
> > > +		memcpy(&e820_prev, &e820, sizeof(struct e820map));
> > > +		e820_prev_saved = 1;
> > >  	}
> > >  }
> > >  @@ -437,13 +487,11 @@ static u64 __init __e820_update_range(st
> > >  		size = ULLONG_MAX - start;
> > >   	end = start + size;
> > > -	printk(KERN_DEBUG "e820 update range: %016Lx - %016Lx ",
> > > +	pr_debug("e820 update range: %Lx+%Lx %s ==> %s\n",
> > >  		       (unsigned long long) start,
> > > -		       (unsigned long long) end);
> > > -	e820_print_type(old_type);
> > > -	printk(KERN_CONT " ==> ");
> > > -	e820_print_type(new_type);
> > > -	printk(KERN_CONT "\n");
> > > +		       (unsigned long long) size,
> > > +			e820_type_to_string(old_type),
> > > +			e820_type_to_string(new_type));
> > >   	for (i = 0; i < e820x->nr_map; i++) {
> > >  		struct e820entry *ei = &e820x->map[i];
> > > @@ -518,12 +566,10 @@ u64 __init e820_remove_range(u64 start,
> > >  		size = ULLONG_MAX - start;
> > >   	end = start + size;
> > > -	printk(KERN_DEBUG "e820 remove range: %016Lx - %016Lx ",
> > > +	printk(KERN_DEBUG "e820 remove range: %016Lx - %016Lx %s\n",
> > >  		       (unsigned long long) start,
> > > -		       (unsigned long long) end);
> > > -	if (checktype)
> > > -		e820_print_type(old_type);
> > > -	printk(KERN_CONT "\n");
> > > +		       (unsigned long long) end,
> > > +			checktype ? e820_type_to_string(old_type) : "");
> > >   	for (i = 0; i < e820.nr_map; i++) {
> > >  		struct e820entry *ei = &e820.map[i];
> > > @@ -576,7 +622,7 @@ void __init update_e820(void)
> > >  	if (sanitize_e820_map(e820.map, ARRAY_SIZE(e820.map), &nr_map))
> > >  		return;
> > >  	e820.nr_map = nr_map;
> > > -	printk(KERN_INFO "modified physical RAM map:\n");
> > > +	printk(KERN_INFO "physical RAM map entries that were modified:\n");
> > >  	e820_print_map("modified");
> > >  }
> > >  static void __init update_e820_saved(void)
> > > @@ -926,18 +972,6 @@ void __init finish_e820_parsing(void)
> > >  	}
> > >  }
> > >  -static inline const char *e820_type_to_string(int e820_type)
> > > -{
> > > -	switch (e820_type) {
> > > -	case E820_RESERVED_KERN:
> > > -	case E820_RAM:	return "System RAM";
> > > -	case E820_ACPI:	return "ACPI Tables";
> > > -	case E820_NVS:	return "ACPI Non-volatile Storage";
> > > -	case E820_UNUSABLE:	return "Unusable memory";
> > > -	default:	return "reserved";
> > > -	}
> > > -}
> > > -
> > >  /*
> > >   * Mark e820 reserved areas as busy for the resource manager.
> > >   */
> > > --- linux.orig/arch/x86/platform/efi/efi.c
> > > +++ linux/arch/x86/platform/efi/efi.c
> > > @@ -306,11 +306,11 @@ static void __init print_efi_memmap(void
> > >  	     p < memmap.map_end;
> > >  	     p += memmap.desc_size, i++) {
> > >  		md = p;
> > > -		printk(KERN_INFO PFX "mem%02u: type=%u, attr=0x%llx, "
> > > -			"range=[0x%016llx-0x%016llx) (%lluMB)\n",
> > > -			i, md->type, md->attribute, md->phys_addr,
> > > -			md->phys_addr + (md->num_pages << EFI_PAGE_SHIFT),
> > > -			(md->num_pages >> (20 - EFI_PAGE_SHIFT)));
> > > +		pr_info(PFX
> > > +			"mem%u: range %llx+%llx (%lluMB) type %u attr %llx\n",
> > 
> > The range you're printing is now ambiguous because you're now showing the
> > length rather than the ending length (implying that what you're displaying
> > is not a range at all, but it's specified as one).  I typically don't see
> > "100+12" as describing [100,112), for example.
> 
> Again, I'm open for suggestions.  I thought that changing base-end to
> base+range
> would be coherent?  

A range consists of a start and an end, so you changed base-end to 
base+length, not base+range.  If I see "100+12", I see that as 112 because 
it seems like it's either arithmetic or an offset from base 100.  The last 
thing that comes to mind is [100,112), though.  Changing this isn't really 
a part of the goals of your patchset either.

> > This is also the second time in the patchset where you're printing hex
> > values without a "0x" prefix, that can be confusing and it's not like "0x"
> > is egregiously long.  I can understand removing the zero padding, but not
> > the prefix.
> 
> The problem comes when there are zillions of them.

I'd be surprised if you can't spare two characters for a hex value in the 
kernel log.

Re: [PATCH 2/6] x86: Minimize initial e820 messages

[Bjorn Helgaas]

On Friday, February 18, 2011 07:47:07 pm Mike Travis wrote:
> Minimize the early e820 messages by printing less characters
> for the address range as well as abbreviating the type info
> for each entry.

> +			pr_info("%s: %Lx+%Lx (%s)\n", who,
> +			       (unsigned long long) e820.map[i].addr,
> +			       (unsigned long long) e820.map[i].size,
> +			       e820_types(e820.map[i].type));

If we're going to change the way we print E820 ranges, I think
we should make them consistent with the way we handle %pR, e.g.,
use something like this:

    "%s: [mem %#018Lx-%#018Lx]"

This is a little different because %pR wouldn't make the field
so wide, but when we discussed this earlier, keeping the table
alignment was thought to be important.  That discussion starts
here: https://lkml.org/lkml/2010/9/22/248

Same comment applies to the update, remove, PCI gap (which
your patch currently doesn't touch), and EFI output.

I know this kind of derails the whole "remove characters" point
of your patch (and I support that in principle), but I do think
consistency is important, too.  We have too many different ways
of printing the same information.

Bjorn

[PATCH 3/6] x86: Minimize SRAT messages

[Mike Travis]

[-- Attachment #1: minimize-srat-msgs.v2 --]
[-- Type: text/plain, Size: 2391 bytes --]

Condense the SRAT: messages to show all APIC id's for the
node on a single line.

v1: Added pertinent __init & __initdata specifiers.
v2: updated to apply to x86-tip

Signed-off-by: Mike Travis <travis@sgi.com>
Reviewed-by: Jack Steiner <steiner@sgi.com>
Reviewed-by: Robin Holt <holt@sgi.com>
---
 arch/x86/mm/srat_64.c |   22 ++++++++++++++++++----
 drivers/acpi/numa.c   |    3 +++
 2 files changed, 21 insertions(+), 4 deletions(-)

--- linux.orig/arch/x86/mm/srat_64.c
+++ linux/arch/x86/mm/srat_64.c
@@ -110,6 +110,12 @@ void __init acpi_numa_slit_init(struct a
 	memblock_x86_reserve_range(phys, phys + length, "ACPI SLIT");
 }
 
+/*
+ * Keep track of previous node and PXM values to reduce clutter
+ * in message and reduce the byte count in the kernel log.
+ */
+static int __initdata last_node = -1, last_pxm = -1;
+
 /* Callback for Proximity Domain -> x2APIC mapping */
 void __init
 acpi_numa_x2apic_affinity_init(struct acpi_srat_x2apic_cpu_affinity *pa)
@@ -141,8 +147,17 @@ acpi_numa_x2apic_affinity_init(struct ac
 	set_apicid_to_node(apic_id, node);
 	node_set(node, cpu_nodes_parsed);
 	acpi_numa = 1;
-	printk(KERN_INFO "SRAT: PXM %u -> APIC 0x%04x -> Node %u\n",
-	       pxm, apic_id, node);
+	if (node != last_node) {
+		pr_info("SRAT: Node %u: PXM:APIC %u:%u",
+		       node, pxm, apic_id);
+		last_node = node;
+		last_pxm = pxm;
+	} else if (pxm != last_pxm) {
+		pr_cont(" %u:%u", pxm, apic_id);
+		last_pxm = pxm;
+	} else {
+		pr_cont(" :%u", apic_id);
+	}
 }
 
 /* Callback for Proximity Domain -> LAPIC mapping */
@@ -301,8 +316,7 @@ acpi_numa_memory_affinity_init(struct ac
 			nd->end = end;
 	}
 
-	printk(KERN_INFO "SRAT: Node %u PXM %u %lx-%lx\n", node, pxm,
-	       start, end);
+	pr_info("SRAT: Node %u PXM %u %lx+%lx\n", node, pxm, start, end-start);
 
 	if (ma->flags & ACPI_SRAT_MEM_HOT_PLUGGABLE) {
 		update_nodes_add(node, start, end);
--- linux.orig/drivers/acpi/numa.c
+++ linux/drivers/acpi/numa.c
@@ -286,6 +286,9 @@ int __init acpi_numa_init(void)
 	if (!acpi_table_parse(ACPI_SIG_SRAT, acpi_parse_srat)) {
 		acpi_table_parse_srat(ACPI_SRAT_TYPE_X2APIC_CPU_AFFINITY,
 				     acpi_parse_x2apic_affinity, 0);
+		/* insure trailing newline is output */
+		pr_cont("\n");
+
 		acpi_table_parse_srat(ACPI_SRAT_TYPE_CPU_AFFINITY,
 				     acpi_parse_processor_affinity, 0);
 		ret = acpi_table_parse_srat(ACPI_SRAT_TYPE_MEMORY_AFFINITY,

-- 

Re: [PATCH 3/6] x86: Minimize SRAT messages

[David Rientjes]

On Fri, 18 Feb 2011, Mike Travis wrote:

> Condense the SRAT: messages to show all APIC id's for the
> node on a single line.
> 
> v1: Added pertinent __init & __initdata specifiers.
> v2: updated to apply to x86-tip
> 
> Signed-off-by: Mike Travis <travis@sgi.com>
> Reviewed-by: Jack Steiner <steiner@sgi.com>
> Reviewed-by: Robin Holt <holt@sgi.com>
> ---
>  arch/x86/mm/srat_64.c |   22 ++++++++++++++++++----
>  drivers/acpi/numa.c   |    3 +++
>  2 files changed, 21 insertions(+), 4 deletions(-)
> 
> --- linux.orig/arch/x86/mm/srat_64.c
> +++ linux/arch/x86/mm/srat_64.c
> @@ -110,6 +110,12 @@ void __init acpi_numa_slit_init(struct a
>  	memblock_x86_reserve_range(phys, phys + length, "ACPI SLIT");
>  }
>  
> +/*
> + * Keep track of previous node and PXM values to reduce clutter
> + * in message and reduce the byte count in the kernel log.
> + */
> +static int __initdata last_node = -1, last_pxm = -1;

NUMA_NO_NODE and PXM_INVAL, respectively?

> +
>  /* Callback for Proximity Domain -> x2APIC mapping */
>  void __init
>  acpi_numa_x2apic_affinity_init(struct acpi_srat_x2apic_cpu_affinity *pa)
> @@ -141,8 +147,17 @@ acpi_numa_x2apic_affinity_init(struct ac
>  	set_apicid_to_node(apic_id, node);
>  	node_set(node, cpu_nodes_parsed);
>  	acpi_numa = 1;
> -	printk(KERN_INFO "SRAT: PXM %u -> APIC 0x%04x -> Node %u\n",
> -	       pxm, apic_id, node);
> +	if (node != last_node) {
> +		pr_info("SRAT: Node %u: PXM:APIC %u:%u",
> +		       node, pxm, apic_id);
> +		last_node = node;
> +		last_pxm = pxm;
> +	} else if (pxm != last_pxm) {
> +		pr_cont(" %u:%u", pxm, apic_id);
> +		last_pxm = pxm;
> +	} else {
> +		pr_cont(" :%u", apic_id);
> +	}
>  }
>  
>  /* Callback for Proximity Domain -> LAPIC mapping */
> @@ -301,8 +316,7 @@ acpi_numa_memory_affinity_init(struct ac
>  			nd->end = end;
>  	}
>  
> -	printk(KERN_INFO "SRAT: Node %u PXM %u %lx-%lx\n", node, pxm,
> -	       start, end);
> +	pr_info("SRAT: Node %u PXM %u %lx+%lx\n", node, pxm, start, end-start);

I still don't see the benefit of printing the length rather than the end 
address.  We care about the range of memory that this node and pxm 
represent, not its size.

>  
>  	if (ma->flags & ACPI_SRAT_MEM_HOT_PLUGGABLE) {
>  		update_nodes_add(node, start, end);
> --- linux.orig/drivers/acpi/numa.c
> +++ linux/drivers/acpi/numa.c
> @@ -286,6 +286,9 @@ int __init acpi_numa_init(void)
>  	if (!acpi_table_parse(ACPI_SIG_SRAT, acpi_parse_srat)) {
>  		acpi_table_parse_srat(ACPI_SRAT_TYPE_X2APIC_CPU_AFFINITY,
>  				     acpi_parse_x2apic_affinity, 0);
> +		/* insure trailing newline is output */
> +		pr_cont("\n");

Same two comments as first patch.

> +
>  		acpi_table_parse_srat(ACPI_SRAT_TYPE_CPU_AFFINITY,
>  				     acpi_parse_processor_affinity, 0);
>  		ret = acpi_table_parse_srat(ACPI_SRAT_TYPE_MEMORY_AFFINITY,

Re: [PATCH 3/6] x86: Minimize SRAT messages

[Mike Travis]

[I was finally able to get some time on our large UV test system.]

Here are the stats testing on a system with 248 nodes, 606 EFI
mem ranges, 1984 cores

after get_log_buff_early:  (17% overflow)

        [    0.000000] early log_buf free: -45723/262183(-17%)
        [    0.000000] first line: : mem339: type=7, attr=0xf, range=[0x00000e6000000000-0x00000e6fff000000) (6552

Here I enabled some cores that were disabled so now the system
has 248 nodes, 606 EFI mem ranges, 2368 cores.

after minimize-time-zero-msgs:  (5% overflow)

[0] early log_buf free: -15184/262172(-5%)
[0] first line: [0x000000007226e000-0x0000000072271000) (0MB) <6>[0] EFI: mem67: type=3, attr=0

Condensing the SRAT: PXM APIC messages resulted in 26% space free
in the early log buffer...

Was 2368 lines (for 2368 cores):

 779 [0] SRAT: PXM 0 -> APIC 0x0000 -> Node 0
 780 [0] SRAT: PXM 0 -> APIC 0x0002 -> Node 0
 781 [0] SRAT: PXM 0 -> APIC 0x0004 -> Node 0
 ...
 3145 [0] SRAT: PXM 247 -> APIC 0x3df0 -> Node 247
 3146 [0] SRAT: PXM 247 -> APIC 0x3df2 -> Node 247

Now it's 248 lines (for 248 Nodes) (Nodes 0..191 have 10 core cpus.)

 777 [0] SRAT: Node 0: PXM:APIC 0:0 :2 :4 :16 :18 :32 :34 :36 :48 :50
 778 [0] SRAT: Node 1: PXM:APIC 1:64 :66 :68 :80 :82 :96 :98 :100 :112 :114
 779 [0] SRAT: Node 2: PXM:APIC 2:128 :130 :132 :144 :146 :160 :162 :164 :176 :178
 ...
 968 [0] SRAT: Node 190: PXM:APIC 190:12160 :12162 :12164 :12176 :12178 :12192 :12194 :12196 :12208 :12210
 969 [0] SRAT: Node 191: PXM:APIC 191:12224 :12226 :12228 :12240 :12242 :12256 :12258 :12260 :12272 :12274
 ...
 1023 [0] SRAT: Node 246: PXM:APIC 246:15744 :15746 :15748 :15760 :15778 :15780 :15792 :15794
 1024 [0] SRAT: Node 247: PXM:APIC 247:15808 :15810 :15812 :15826 :15840 :15844 :15856 :15858

[0] early log_buf free: 69649/192523(26%)
[0] first line: <6>[0] Initializing cgroup subsys cpuset <6>[0] Initializing cgroup subsys cpu                                       

My question is is the above decimal satisfactory, or should it be hex as
shown below?  (Which will add 8k bytes for the "0x" when there are 4096 cores
but the hex values will be smaller.)

 821 [0] SRAT: Node 0: PXM:APIC 0:0x0 :0x2 :0x4 :0x10 :0x12 :0x20 :0x22 :0x24 :0x30 :0x32
 822 [0] SRAT: Node 1: PXM:APIC 1:0x40 :0x42 :0x44 :0x50 :0x52 :0x60 :0x62 :0x64 :0x70 :0x72
 823 [0] SRAT: Node 2: PXM:APIC 2:0x80 :0x82 :0x84 :0x90 :0x92 :0xa0 :0xa2 :0xa4 :0xb0 :0xb2
...
1011 [0] SRAT: Node 190: PXM:APIC 190:0x2f80 :0x2f82 :0x2f84 :0x2f90 :0x2f92 :0x2fa0 :0x2fa2 :0x2fa4 :0x2fb0 :0x2fb2
1012 [0] SRAT: Node 191: PXM:APIC 191:0x2fc0 :0x2fc2 :0x2fc4 :0x2fd0 :0x2fd2 :0x2fe0 :0x2fe2 :0x2fe4 :0x2ff0 :0x2ff2
...
1067 [0] SRAT: Node 246: PXM:APIC 246:0x3d80 :0x3d82 :0x3d84 :0x3d90 :0x3da2 :0x3da4 :0x3db0 :0x3db2
1068 [0] SRAT: Node 247: PXM:APIC 247:0x3dc0 :0x3dc2 :0x3dc4 :0x3dd2 :0x3de0 :0x3de4 :0x3df0 :0x3df2

I will do some more study to see if affecting only these changes will
be enough to not overflow the early log buffer in a max config system.

(Btw, I have not figured out how to predict ahead of time that this
APIC id is the last one on the Node to insert the '\n'.)

Thanks,
Mike

Re: [PATCH 3/6] x86: Minimize SRAT messages

[David Rientjes]

On Wed, 23 Feb 2011, Mike Travis wrote:

> [I was finally able to get some time on our large UV test system.]
> 
> Here are the stats testing on a system with 248 nodes, 606 EFI
> mem ranges, 1984 cores
> 
> after get_log_buff_early:  (17% overflow)
> 
>        [    0.000000] early log_buf free: -45723/262183(-17%)
>        [    0.000000] first line: : mem339: type=7, attr=0xf,
> range=[0x00000e6000000000-0x00000e6fff000000) (6552
> 
> Here I enabled some cores that were disabled so now the system
> has 248 nodes, 606 EFI mem ranges, 2368 cores.
> 
> after minimize-time-zero-msgs:  (5% overflow)
> 
> [0] early log_buf free: -15184/262172(-5%)
> [0] first line: [0x000000007226e000-0x0000000072271000) (0MB) <6>[0] EFI:
> mem67: type=3, attr=0
> 
> Condensing the SRAT: PXM APIC messages resulted in 26% space free
> in the early log buffer...
> 
> Was 2368 lines (for 2368 cores):
> 
> 779 [0] SRAT: PXM 0 -> APIC 0x0000 -> Node 0
> 780 [0] SRAT: PXM 0 -> APIC 0x0002 -> Node 0
> 781 [0] SRAT: PXM 0 -> APIC 0x0004 -> Node 0
> ...
> 3145 [0] SRAT: PXM 247 -> APIC 0x3df0 -> Node 247
> 3146 [0] SRAT: PXM 247 -> APIC 0x3df2 -> Node 247
> 

Very cool, if you include these format changes from old to new in the 
individual patch descriptions it would be great.

> Now it's 248 lines (for 248 Nodes) (Nodes 0..191 have 10 core cpus.)
> 
> 777 [0] SRAT: Node 0: PXM:APIC 0:0 :2 :4 :16 :18 :32 :34 :36 :48 :50
> 778 [0] SRAT: Node 1: PXM:APIC 1:64 :66 :68 :80 :82 :96 :98 :100 :112 :114
> 779 [0] SRAT: Node 2: PXM:APIC 2:128 :130 :132 :144 :146 :160 :162 :164 :176
> :178
> ...
> 968 [0] SRAT: Node 190: PXM:APIC 190:12160 :12162 :12164 :12176 :12178 :12192
> :12194 :12196 :12208 :12210
> 969 [0] SRAT: Node 191: PXM:APIC 191:12224 :12226 :12228 :12240 :12242 :12256
> :12258 :12260 :12272 :12274
> ...
> 1023 [0] SRAT: Node 246: PXM:APIC 246:15744 :15746 :15748 :15760 :15778 :15780
> :15792 :15794
> 1024 [0] SRAT: Node 247: PXM:APIC 247:15808 :15810 :15812 :15826 :15840 :15844
> :15856 :15858
> 

Although they look a bit odd, I think these lines are easily parsable and 
understood even without looking at the implementation.

> [0] early log_buf free: 69649/192523(26%)
> [0] first line: <6>[0] Initializing cgroup subsys cpuset <6>[0] Initializing
> cgroup subsys cpu                                       
> My question is is the above decimal satisfactory, or should it be hex as
> shown below?  (Which will add 8k bytes for the "0x" when there are 4096 cores
> but the hex values will be smaller.)
> 
> 821 [0] SRAT: Node 0: PXM:APIC 0:0x0 :0x2 :0x4 :0x10 :0x12 :0x20 :0x22 :0x24
> :0x30 :0x32
> 822 [0] SRAT: Node 1: PXM:APIC 1:0x40 :0x42 :0x44 :0x50 :0x52 :0x60 :0x62
> :0x64 :0x70 :0x72
> 823 [0] SRAT: Node 2: PXM:APIC 2:0x80 :0x82 :0x84 :0x90 :0x92 :0xa0 :0xa2
> :0xa4 :0xb0 :0xb2
> ...
> 1011 [0] SRAT: Node 190: PXM:APIC 190:0x2f80 :0x2f82 :0x2f84 :0x2f90 :0x2f92
> :0x2fa0 :0x2fa2 :0x2fa4 :0x2fb0 :0x2fb2
> 1012 [0] SRAT: Node 191: PXM:APIC 191:0x2fc0 :0x2fc2 :0x2fc4 :0x2fd0 :0x2fd2
> :0x2fe0 :0x2fe2 :0x2fe4 :0x2ff0 :0x2ff2
> ...
> 1067 [0] SRAT: Node 246: PXM:APIC 246:0x3d80 :0x3d82 :0x3d84 :0x3d90 :0x3da2
> :0x3da4 :0x3db0 :0x3db2
> 1068 [0] SRAT: Node 247: PXM:APIC 247:0x3dc0 :0x3dc2 :0x3dc4 :0x3dd2 :0x3de0
> :0x3de4 :0x3df0 :0x3df2
> 
> I will do some more study to see if affecting only these changes will
> be enough to not overflow the early log buffer in a max config system.
> 

I still think we should try to emit the "0x" prefix for any values printed 
in hexadecimal which may or may not be obvious (such as nodes 0 and 1 
above), this is pretty standard.  The final decision would be up to Ingo, 
though.

[PATCH 4/6] printk: Break out printk_time

[Mike Travis]

[-- Attachment #1: break-out-printk_time --]
[-- Type: text/plain, Size: 1521 bytes --]

Clean up printk_time by making it a separate function.

Signed-off-by: Mike Travis <travis@sgi.com>
---
 kernel/printk.c |   38 +++++++++++++++++++++-----------------
 1 file changed, 21 insertions(+), 17 deletions(-)

--- linux.orig/kernel/printk.c
+++ linux/kernel/printk.c
@@ -726,6 +726,24 @@ static inline void printk_delay(void)
 	}
 }
 
+/* Follow the token with the time */
+static inline int printk_emit_time(void)
+{
+	char tbuf[50], *tp;
+	unsigned tlen;
+	unsigned long long t;
+	unsigned long microsec_rem;
+
+	t = cpu_clock(printk_cpu);
+	microsec_rem = do_div(t, 1000000000) / 1000;
+	tlen = sprintf(tbuf, "[%5lu.%06lu] ", (unsigned long)t, microsec_rem);
+
+	for (tp = tbuf; tp < tbuf + tlen; tp++)
+		emit_log_char(*tp);
+
+	return tlen;
+}
+
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
 	int printed_len = 0;
@@ -810,23 +828,9 @@ asmlinkage int vprintk(const char *fmt,
 			printed_len += 3;
 			new_text_line = 0;
 
-			if (printk_time) {
-				/* Follow the token with the time */
-				char tbuf[50], *tp;
-				unsigned tlen;
-				unsigned long long t;
-				unsigned long nanosec_rem;
-
-				t = cpu_clock(printk_cpu);
-				nanosec_rem = do_div(t, 1000000000);
-				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
-						(unsigned long) t,
-						nanosec_rem / 1000);
-
-				for (tp = tbuf; tp < tbuf + tlen; tp++)
-					emit_log_char(*tp);
-				printed_len += tlen;
-			}
+			/* add time if requested */
+			if (printk_time)
+				printed_len += printk_emit_time();
 
 			if (!*p)
 				break;

-- 

Re: [PATCH 4/6] printk: Break out printk_time

[David Rientjes]

On Fri, 18 Feb 2011, Mike Travis wrote:

> Clean up printk_time by making it a separate function.
> 
> Signed-off-by: Mike Travis <travis@sgi.com>

Acked-by: David Rientjes <rientjes@google.com>

[PATCH 5/6] printk: Minimize time zero output

[Mike Travis]

[-- Attachment #1: minimize-time-zero-msgs --]
[-- Type: text/plain, Size: 938 bytes --]

Reduce the length for time zero messages by only printing "[0] ".

v2: updated to apply to x86-tip

Signed-off-by: Mike Travis <travis@sgi.com>
Reviewed-by: Jack Steiner <steiner@sgi.com>
Reviewed-by: Robin Holt <holt@sgi.com>
---
 kernel/printk.c |   11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

--- linux.orig/kernel/printk.c
+++ linux/kernel/printk.c
@@ -735,9 +735,14 @@ static inline int printk_emit_time(void)
 	unsigned long microsec_rem;
 
 	t = cpu_clock(printk_cpu);
-	microsec_rem = do_div(t, 1000000000) / 1000;
-	tlen = sprintf(tbuf, "[%5lu.%06lu] ", (unsigned long)t, microsec_rem);
-
+	if (likely(t)) {
+		microsec_rem = do_div(t, 1000000000) / 1000;
+		tlen = sprintf(tbuf, "[%5lu.%06lu] ",
+					(unsigned long)t, microsec_rem);
+	} else {
+		/* reduce byte count in log when time is zero */
+		tlen = sprintf(tbuf, "[0] ");
+	}
 	for (tp = tbuf; tp < tbuf + tlen; tp++)
 		emit_log_char(*tp);
 

-- 

Re: [PATCH 5/6] printk: Minimize time zero output

[David Rientjes]

On Fri, 18 Feb 2011, Mike Travis wrote:

> Reduce the length for time zero messages by only printing "[0] ".
> 
> v2: updated to apply to x86-tip
> 
> Signed-off-by: Mike Travis <travis@sgi.com>
> Reviewed-by: Jack Steiner <steiner@sgi.com>
> Reviewed-by: Robin Holt <holt@sgi.com>
> ---
>  kernel/printk.c |   11 ++++++++---
>  1 file changed, 8 insertions(+), 3 deletions(-)
> 
> --- linux.orig/kernel/printk.c
> +++ linux/kernel/printk.c
> @@ -735,9 +735,14 @@ static inline int printk_emit_time(void)
>  	unsigned long microsec_rem;
>  
>  	t = cpu_clock(printk_cpu);
> -	microsec_rem = do_div(t, 1000000000) / 1000;
> -	tlen = sprintf(tbuf, "[%5lu.%06lu] ", (unsigned long)t, microsec_rem);
> -
> +	if (likely(t)) {
> +		microsec_rem = do_div(t, 1000000000) / 1000;
> +		tlen = sprintf(tbuf, "[%5lu.%06lu] ",
> +					(unsigned long)t, microsec_rem);

The definition of microsec_rem can become local to this clause.

> +	} else {
> +		/* reduce byte count in log when time is zero */
> +		tlen = sprintf(tbuf, "[0] ");

If we know the padding when cpu_clock() is non-zero, then why not make 
sure the kernel log is aligned properly by using the same padding here?

> +	}
>  	for (tp = tbuf; tp < tbuf + tlen; tp++)
>  		emit_log_char(*tp);
>  

Re: [PATCH 5/6] printk: Minimize time zero output

[Mike Travis]

David Rientjes wrote:
> On Fri, 18 Feb 2011, Mike Travis wrote:
> 
>> Reduce the length for time zero messages by only printing "[0] ".
>>
>> v2: updated to apply to x86-tip
>>
>> Signed-off-by: Mike Travis <travis@sgi.com>
>> Reviewed-by: Jack Steiner <steiner@sgi.com>
>> Reviewed-by: Robin Holt <holt@sgi.com>
>> ---
>>  kernel/printk.c |   11 ++++++++---
>>  1 file changed, 8 insertions(+), 3 deletions(-)
>>
>> --- linux.orig/kernel/printk.c
>> +++ linux/kernel/printk.c
>> @@ -735,9 +735,14 @@ static inline int printk_emit_time(void)
>>  	unsigned long microsec_rem;
>>  
>>  	t = cpu_clock(printk_cpu);
>> -	microsec_rem = do_div(t, 1000000000) / 1000;
>> -	tlen = sprintf(tbuf, "[%5lu.%06lu] ", (unsigned long)t, microsec_rem);
>> -
>> +	if (likely(t)) {
>> +		microsec_rem = do_div(t, 1000000000) / 1000;
>> +		tlen = sprintf(tbuf, "[%5lu.%06lu] ",
>> +					(unsigned long)t, microsec_rem);
> 
> The definition of microsec_rem can become local to this clause.

Ok.
> 
>> +	} else {
>> +		/* reduce byte count in log when time is zero */
>> +		tlen = sprintf(tbuf, "[0] ");
> 
> If we know the padding when cpu_clock() is non-zero, then why not make 
> sure the kernel log is aligned properly by using the same padding here?

I'm not sure I understand what you are asking.  The whole point of this
exercise is to remove bytes from the early log buffer so it does not
overflow.  What would you like me to change?

> 
>> +	}
>>  	for (tp = tbuf; tp < tbuf + tlen; tp++)
>>  		emit_log_char(*tp);
>>  

Re: [PATCH 5/6] printk: Minimize time zero output

[David Rientjes]

On Mon, 21 Feb 2011, Mike Travis wrote:

> > > Reduce the length for time zero messages by only printing "[0] ".
> > > 
> > > v2: updated to apply to x86-tip
> > > 
> > > Signed-off-by: Mike Travis <travis@sgi.com>
> > > Reviewed-by: Jack Steiner <steiner@sgi.com>
> > > Reviewed-by: Robin Holt <holt@sgi.com>
> > > ---
> > >  kernel/printk.c |   11 ++++++++---
> > >  1 file changed, 8 insertions(+), 3 deletions(-)
> > > 
> > > --- linux.orig/kernel/printk.c
> > > +++ linux/kernel/printk.c
> > > @@ -735,9 +735,14 @@ static inline int printk_emit_time(void)
> > >  	unsigned long microsec_rem;
> > >   	t = cpu_clock(printk_cpu);
> > > -	microsec_rem = do_div(t, 1000000000) / 1000;
> > > -	tlen = sprintf(tbuf, "[%5lu.%06lu] ", (unsigned long)t, microsec_rem);
> > > -
> > > +	if (likely(t)) {
> > > +		microsec_rem = do_div(t, 1000000000) / 1000;
> > > +		tlen = sprintf(tbuf, "[%5lu.%06lu] ",
> > > +					(unsigned long)t, microsec_rem);
> > 
> > The definition of microsec_rem can become local to this clause.
> 
> Ok.
> > 
> > > +	} else {
> > > +		/* reduce byte count in log when time is zero */
> > > +		tlen = sprintf(tbuf, "[0] ");
> > 
> > If we know the padding when cpu_clock() is non-zero, then why not make sure
> > the kernel log is aligned properly by using the same padding here?
> 
> I'm not sure I understand what you are asking.  The whole point of this
> exercise is to remove bytes from the early log buffer so it does not
> overflow.  What would you like me to change?
> 

Based on your changelog, it looks like you're trying to avoid the time 
spent calculating the time (the divides), not trying to optimize for 
space, so I recommended "[    0.000000]" so the log is aligned.  If the 
patchset is reducing the number of lines emitted to the log, then this 
shouldn't be as significant of an issue?

[PATCH 6/6] printk: Allocate kernel log buffer earlier

[Mike Travis]

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

On larger systems, because of the numerous ACPI, Bootmem and EFI
messages, the static log buffer overflows before the larger one
specified by the log_buf_len param is allocated.  Minimize the
overflow by allocating the new log buffer as soon as possible.

All arch's are covered by the "setup_log_buf" in start_kernel().
The x86 arch allocates it right after bootmem is created.

v1: Added pertinent __init & __initdata specifiers.
v2: updated to apply to x86-tip

Signed-off-by: Mike Travis <travis@sgi.com>
Reviewed-by: Jack Steiner <steiner@sgi.com>
Reviewed-by: Robin Holt <holt@sgi.com>
---
 arch/x86/kernel/setup.c |    5 ++
 include/linux/printk.h  |    4 +
 init/main.c             |    1 
 kernel/printk.c         |  108 ++++++++++++++++++++++++++++++++++--------------
 4 files changed, 87 insertions(+), 31 deletions(-)

--- linux.orig/arch/x86/kernel/setup.c
+++ linux/arch/x86/kernel/setup.c
@@ -1007,6 +1007,11 @@ void __init setup_arch(char **cmdline_p)
 	memblock_find_dma_reserve();
 	dma32_reserve_bootmem();
 
+	/*
+	 * Allocate bigger log buffer as early as possible
+	 */
+	setup_log_buf();
+
 #ifdef CONFIG_KVM_CLOCK
 	kvmclock_init();
 #endif
--- linux.orig/include/linux/printk.h
+++ linux/include/linux/printk.h
@@ -1,6 +1,8 @@
 #ifndef __KERNEL_PRINTK__
 #define __KERNEL_PRINTK__
 
+#include <linux/init.h>
+
 extern const char linux_banner[];
 extern const char linux_proc_banner[];
 
@@ -89,6 +91,8 @@ int no_printk(const char *fmt, ...)
 extern asmlinkage __attribute__ ((format (printf, 1, 2)))
 void early_printk(const char *fmt, ...);
 
+void __init setup_log_buf(void);
+
 extern int printk_needs_cpu(int cpu);
 extern void printk_tick(void);
 
--- linux.orig/init/main.c
+++ linux/init/main.c
@@ -592,6 +592,7 @@ asmlinkage void __init start_kernel(void
 	 * These use large bootmem allocations and must precede
 	 * kmem_cache_init()
 	 */
+	setup_log_buf();
 	pidhash_init();
 	vfs_caches_init_early();
 	sort_main_extable();
--- linux.orig/kernel/printk.c
+++ linux/kernel/printk.c
@@ -162,46 +162,92 @@ void log_buf_kexec_setup(void)
 }
 #endif
 
+/* requested log_buf_len from kernel cmdline */
+static unsigned long __initdata new_log_buf_len;
+
+/* save requested log_buf_len since it's too early to process it */
 static int __init log_buf_len_setup(char *str)
 {
 	unsigned size = memparse(str, &str);
-	unsigned long flags;
 
 	if (size)
 		size = roundup_pow_of_two(size);
-	if (size > log_buf_len) {
-		unsigned start, dest_idx, offset;
-		char *new_log_buf;
-
-		new_log_buf = alloc_bootmem(size);
-		if (!new_log_buf) {
-			printk(KERN_WARNING "log_buf_len: allocation failed\n");
-			goto out;
-		}
-
-		spin_lock_irqsave(&logbuf_lock, flags);
-		log_buf_len = size;
-		log_buf = new_log_buf;
-
-		offset = start = min(con_start, log_start);
-		dest_idx = 0;
-		while (start != log_end) {
-			log_buf[dest_idx] = __log_buf[start & (__LOG_BUF_LEN - 1)];
-			start++;
-			dest_idx++;
-		}
-		log_start -= offset;
-		con_start -= offset;
-		log_end -= offset;
-		spin_unlock_irqrestore(&logbuf_lock, flags);
+	if (size > log_buf_len)
+		new_log_buf_len = size;
 
-		printk(KERN_NOTICE "log_buf_len: %d\n", log_buf_len);
-	}
-out:
-	return 1;
+	return 0;
+}
+early_param("log_buf_len", log_buf_len_setup);
+
+/*
+ * Debug code to determine if early log buffer overflowed and by how much.
+ * Length of first line saved is arbitrary as all we need is some context
+ * from the that line.
+ */
+static char __initdata first_line[40];
+
+/* Grab part of the first line from early log buf */
+static void __init fl_buf_copy(unsigned dest_idx, char c)
+{
+	if (dest_idx < sizeof(first_line) - 1)
+		first_line[dest_idx] = c;
+}
+
+/*
+ * Print free bytes left in early log buffer (might be negative)
+ * and part of first line.
+ */
+static void __init fl_print_stats(unsigned dest_idx)
+{
+	char *first_nl;
+	int free = __LOG_BUF_LEN - dest_idx;
+
+	/*
+	 * If first line was shorter than length of first_line buffer,
+	 * remove the newline so we don't get a blank line in the output.
+	 */
+	first_nl = strchr(first_line, '\n');
+	if (first_nl)
+		*first_nl = '\0';
+
+	pr_info("early log_buf free: %d(%d%%) first line: %s\n",
+		free, (free * 100) / __LOG_BUF_LEN, first_line);
 }
 
-__setup("log_buf_len=", log_buf_len_setup);
+void __init setup_log_buf(void)
+{
+	unsigned long flags;
+	unsigned start, dest_idx, offset;
+	char *new_log_buf;
+
+	if (!new_log_buf_len)
+		return;
+
+	new_log_buf = alloc_bootmem(new_log_buf_len);
+
+	spin_lock_irqsave(&logbuf_lock, flags);
+	log_buf_len = new_log_buf_len;
+	log_buf = new_log_buf;
+	new_log_buf_len = 0;
+
+	offset = start = min(con_start, log_start);
+	dest_idx = 0;
+	while (start != log_end) {
+		unsigned log_idx_mask = start & (__LOG_BUF_LEN - 1);
+
+		log_buf[dest_idx] = __log_buf[log_idx_mask];
+		fl_buf_copy(dest_idx, __log_buf[log_idx_mask]);
+		start++;
+		dest_idx++;
+	}
+	log_start -= offset;
+	con_start -= offset;
+	log_end -= offset;
+	spin_unlock_irqrestore(&logbuf_lock, flags);
+
+	pr_info("log_buf_len: %d\n", log_buf_len);
+	fl_print_stats(dest_idx);
+}
 
 #ifdef CONFIG_BOOT_PRINTK_DELAY
 

--