[PATCH] memblock: Neaten logging

[PATCH] memblock: Neaten logging

[Joe Perches]

Use more typical kernel logging styles.

o Add and use #define pr_fmt KBUILD_MODNAME ": " fmt
o Neaten memblock_dbg to use %s: %pS: to output __func__ and caller
o Convert existing uses of pr_<level> and memblock_dbg appropriately

Logging output is now always prefixed with 'memblock: '
Debugging output is now prefixed with 'memblock: ', function and caller

Signed-off-by: Joe Perches <joe@perches.com>
---
 mm/memblock.c | 59 ++++++++++++++++++++++++++---------------------------------
 1 file changed, 26 insertions(+), 33 deletions(-)

diff --git a/mm/memblock.c b/mm/memblock.c
index 184dcd2e5d99..405335c966a8 100644
--- a/mm/memblock.c
+++ b/mm/memblock.c
@@ -6,6 +6,8 @@
  * Copyright (C) 2001 Peter Bergner.
  */
 
+#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt
+
 #include <linux/kernel.h>
 #include <linux/slab.h>
 #include <linux/init.h>
@@ -146,10 +148,12 @@ static __refdata struct memblock_type *memblock_memory = &memblock.memory;
 	     i++, rgn = &memblock_type->regions[i])
 
 #define memblock_dbg(fmt, ...)						\
-	do {								\
-		if (memblock_debug)					\
-			pr_info(fmt, ##__VA_ARGS__);			\
-	} while (0)
+do {									\
+	if (memblock_debug)						\
+		pr_info("%s: %pS: " fmt,				\
+			__func__, __builtin_return_address(0),		\
+			##__VA_ARGS__);					\
+} while (0)
 
 static int memblock_debug __initdata_memblock;
 static bool system_has_some_mirror __initdata_memblock = false;
@@ -447,14 +451,14 @@ static int __init_memblock memblock_double_array(struct memblock_type *type,
 		new_array = addr ? __va(addr) : NULL;
 	}
 	if (!addr) {
-		pr_err("memblock: Failed to double %s array from %ld to %ld entries !\n",
+		pr_err("Failed to double %s array from %ld to %ld entries !\n",
 		       type->name, type->max, type->max * 2);
 		return -1;
 	}
 
 	new_end = addr + new_size - 1;
-	memblock_dbg("memblock: %s is doubled to %ld at [%pa-%pa]",
-			type->name, type->max * 2, &addr, &new_end);
+	memblock_dbg("%s is doubled to %ld at [%pa-%pa]\n",
+		     type->name, type->max * 2, &addr, &new_end);
 
 	/*
 	 * Found space, we now need to move the array over before we add the
@@ -667,8 +671,7 @@ int __init_memblock memblock_add_node(phys_addr_t base, phys_addr_t size,
 {
 	phys_addr_t end = base + size - 1;
 
-	memblock_dbg("%s: [%pa-%pa] nid=%d %pS\n", __func__,
-		     &base, &end, nid, (void *)_RET_IP_);
+	memblock_dbg("[%pa-%pa] nid=%d\n", &base, &end, nid);
 
 	return memblock_add_range(&memblock.memory, base, size, nid, 0);
 }
@@ -688,8 +691,7 @@ int __init_memblock memblock_add(phys_addr_t base, phys_addr_t size)
 {
 	phys_addr_t end = base + size - 1;
 
-	memblock_dbg("%s: [%pa-%pa] %pS\n", __func__,
-		     &base, &end, (void *)_RET_IP_);
+	memblock_dbg("[%pa-%pa]\n", &base, &end);
 
 	return memblock_add_range(&memblock.memory, base, size, MAX_NUMNODES, 0);
 }
@@ -789,8 +791,7 @@ int __init_memblock memblock_remove(phys_addr_t base, phys_addr_t size)
 {
 	phys_addr_t end = base + size - 1;
 
-	memblock_dbg("%s: [%pa-%pa] %pS\n", __func__,
-		     &base, &end, (void *)_RET_IP_);
+	memblock_dbg("[%pa-%pa]\n", &base, &end);
 
 	return memblock_remove_range(&memblock.memory, base, size);
 }
@@ -821,8 +822,7 @@ int __init_memblock memblock_free(phys_addr_t base, phys_addr_t size)
 {
 	phys_addr_t end = base + size - 1;
 
-	memblock_dbg("%s: [%pa-%pa] %pS\n", __func__,
-		     &base, &end, (void *)_RET_IP_);
+	memblock_dbg("[%pa-%pa]\n", &base, &end);
 
 	kmemleak_free_part_phys(base, size);
 	return memblock_remove_range(&memblock.reserved, base, size);
@@ -832,8 +832,7 @@ int __init_memblock memblock_reserve(phys_addr_t base, phys_addr_t size)
 {
 	phys_addr_t end = base + size - 1;
 
-	memblock_dbg("%s: [%pa-%pa] %pS\n", __func__,
-		     &base, &end, (void *)_RET_IP_);
+	memblock_dbg("[%pa-%pa]\n", &base, &end);
 
 	return memblock_add_range(&memblock.reserved, base, size, MAX_NUMNODES, 0);
 }
@@ -843,8 +842,7 @@ int __init_memblock memblock_physmem_add(phys_addr_t base, phys_addr_t size)
 {
 	phys_addr_t end = base + size - 1;
 
-	memblock_dbg("%s: [%pa-%pa] %pS\n", __func__,
-		     &base, &end, (void *)_RET_IP_);
+	memblock_dbg("[%pa-%pa]\n", &base, &end);
 
 	return memblock_add_range(&physmem, base, size, MAX_NUMNODES, 0);
 }
@@ -1409,9 +1407,8 @@ phys_addr_t __init memblock_phys_alloc_range(phys_addr_t size,
 					     phys_addr_t start,
 					     phys_addr_t end)
 {
-	memblock_dbg("%s: %llu bytes align=0x%llx from=%pa max_addr=%pa %pS\n",
-		     __func__, (u64)size, (u64)align, &start, &end,
-		     (void *)_RET_IP_);
+	memblock_dbg("%llu bytes align=0x%llx from=%pa max_addr=%pa\n",
+		     (u64)size, (u64)align, &start, &end);
 	return memblock_alloc_range_nid(size, align, start, end, NUMA_NO_NODE,
 					false);
 }
@@ -1510,9 +1507,8 @@ void * __init memblock_alloc_exact_nid_raw(
 			phys_addr_t min_addr, phys_addr_t max_addr,
 			int nid)
 {
-	memblock_dbg("%s: %llu bytes align=0x%llx nid=%d from=%pa max_addr=%pa %pS\n",
-		     __func__, (u64)size, (u64)align, nid, &min_addr,
-		     &max_addr, (void *)_RET_IP_);
+	memblock_dbg("%llu bytes align=0x%llx nid=%d from=%pa max_addr=%pa\n",
+		     (u64)size, (u64)align, nid, &min_addr, &max_addr);
 
 	return memblock_alloc_internal(size, align, min_addr, max_addr, nid,
 				       true);
@@ -1542,9 +1538,8 @@ void * __init memblock_alloc_try_nid_raw(
 			phys_addr_t min_addr, phys_addr_t max_addr,
 			int nid)
 {
-	memblock_dbg("%s: %llu bytes align=0x%llx nid=%d from=%pa max_addr=%pa %pS\n",
-		     __func__, (u64)size, (u64)align, nid, &min_addr,
-		     &max_addr, (void *)_RET_IP_);
+	memblock_dbg("%llu bytes align=0x%llx nid=%d from=%pa max_addr=%pa\n",
+		     (u64)size, (u64)align, nid, &min_addr, &max_addr);
 
 	return memblock_alloc_internal(size, align, min_addr, max_addr, nid,
 				       false);
@@ -1574,9 +1569,8 @@ void * __init memblock_alloc_try_nid(
 {
 	void *ptr;
 
-	memblock_dbg("%s: %llu bytes align=0x%llx nid=%d from=%pa max_addr=%pa %pS\n",
-		     __func__, (u64)size, (u64)align, nid, &min_addr,
-		     &max_addr, (void *)_RET_IP_);
+	memblock_dbg("%llu bytes align=0x%llx nid=%d from=%pa max_addr=%pa\n",
+		     (u64)size, (u64)align, nid, &min_addr, &max_addr);
 	ptr = memblock_alloc_internal(size, align,
 					   min_addr, max_addr, nid, false);
 	if (ptr)
@@ -1599,8 +1593,7 @@ void __init __memblock_free_late(phys_addr_t base, phys_addr_t size)
 	phys_addr_t cursor, end;
 
 	end = base + size - 1;
-	memblock_dbg("%s: [%pa-%pa] %pS\n",
-		     __func__, &base, &end, (void *)_RET_IP_);
+	memblock_dbg("[%pa-%pa]\n", &base, &end);
 	kmemleak_free_part_phys(base, size);
 	cursor = PFN_UP(base);
 	end = PFN_DOWN(base + size);

Re: [PATCH] memblock: Neaten logging

[Mike Rapoport]

Hi Joe,

On Wed, Sep 29, 2021 at 09:43:14PM -0700, Joe Perches wrote:
> Use more typical kernel logging styles.
> 
> o Add and use #define pr_fmt KBUILD_MODNAME ": " fmt

I don't see it as an improvement. On the contrary, the output becomes
somewhat tautological:

memblock: memblock_reserve: smp_scan_config+0xa5/0xe9: [0x00000000000f5a60-0x00000000000f5a6f]
memblock: memblock_reserve: smp_scan_config+0xbc/0xe9: [0x00000000000f5a70-0x00000000000f5b83]
memblock: memblock_reserve: setup_arch+0x5d8/0xbcd: [0x0000000002e00000-0x0000000002e10fff]
memblock: memblock_add: e820__memblock_setup+0x5e/0x76: [0x0000000000001000-0x000000000009fbff]
memblock: memblock_add: e820__memblock_setup+0x5e/0x76: [0x0000000000100000-0x00000000bffdcfff]
memblock: memblock_add: e820__memblock_setup+0x5e/0x76: [0x0000000100000000-0x000000013fffffff]

And the output of memblock_dump_all() is perfectly fine without the prefix.

> o Neaten memblock_dbg to use %s: %pS: to output __func__ and caller
> o Convert existing uses of pr_<level> and memblock_dbg appropriately
> 
> Logging output is now always prefixed with 'memblock: '
> Debugging output is now prefixed with 'memblock: ', function and caller
> 
> Signed-off-by: Joe Perches <joe@perches.com>
> ---
>  mm/memblock.c | 59 ++++++++++++++++++++++++++---------------------------------
>  1 file changed, 26 insertions(+), 33 deletions(-)

What is the base commit for this patch?
It seems it missed a pr_warn in memblock_cap_memory_range()...
 
> diff --git a/mm/memblock.c b/mm/memblock.c
> index 184dcd2e5d99..405335c966a8 100644
> --- a/mm/memblock.c
> +++ b/mm/memblock.c

-- 
Sincerely yours,
Mike.

Re: [PATCH] memblock: Neaten logging

[Joe Perches]

On Thu, 2021-09-30 at 14:12 -0700, Mike Rapoport wrote:
> Hi Joe,
> 
> On Wed, Sep 29, 2021 at 09:43:14PM -0700, Joe Perches wrote:
> > Use more typical kernel logging styles.
> > 
> > o Add and use #define pr_fmt KBUILD_MODNAME ": " fmt
> 
> I don't see it as an improvement. On the contrary, the output becomes
> somewhat tautological:

And rather easier to grep as the prefix is constant.

> What is the base commit for this patch?
> It seems it missed a pr_warn in memblock_cap_memory_range()...

linus' master.

Re: [PATCH] memblock: Neaten logging

[Mike Rapoport]

On Thu, Sep 30, 2021 at 06:27:15PM -0700, Joe Perches wrote:
> On Thu, 2021-09-30 at 14:12 -0700, Mike Rapoport wrote:
> > Hi Joe,
> > 
> > On Wed, Sep 29, 2021 at 09:43:14PM -0700, Joe Perches wrote:
> > > Use more typical kernel logging styles.
> > > 
> > > o Add and use #define pr_fmt KBUILD_MODNAME ": " fmt
> > 
> > I don't see it as an improvement. On the contrary, the output becomes
> > somewhat tautological:
> 
> And rather easier to grep as the prefix is constant.

memblock_ is perfectly greppable
 
-- 
Sincerely yours,
Mike.

Re: [PATCH] memblock: Neaten logging

[Joe Perches]

On Fri, 2021-10-01 at 09:37 -0700, Mike Rapoport wrote:
> On Thu, Sep 30, 2021 at 06:27:15PM -0700, Joe Perches wrote:
> > On Thu, 2021-09-30 at 14:12 -0700, Mike Rapoport wrote:
> > > Hi Joe,
> > > 
> > > On Wed, Sep 29, 2021 at 09:43:14PM -0700, Joe Perches wrote:
> > > > Use more typical kernel logging styles.
> > > > 
> > > > o Add and use #define pr_fmt KBUILD_MODNAME ": " fmt
> > > 
> > > I don't see it as an improvement. On the contrary, the output becomes
> > > somewhat tautological:
> > 
> > And rather easier to grep as the prefix is constant.
> 
> memblock_ is perfectly greppable

Of course, but only when it's there, 2 instances out of 9.

$ git grep '\bpr_' mm/memblock.c
mm/memblock.c:                  pr_info(fmt, ##__VA_ARGS__);                    \
mm/memblock.c:          pr_warn("Could not allocate %pap bytes of mirrored memory\n",
mm/memblock.c:          pr_err("memblock: Failed to double %s array from %ld to %ld entries !\n",
mm/memblock.c:          pr_warn("Could not allocate %pap bytes of mirrored memory\n",
mm/memblock.c:          pr_warn("%s: No memory registered yet\n", __func__);
mm/memblock.c:  pr_info(" %s.cnt  = 0x%lx\n", type->name, type->cnt);
mm/memblock.c:          pr_info(" %s[%#x]\t[%pa-%pa], %pa bytes%s flags: %#x\n",
mm/memblock.c:  pr_info("MEMBLOCK configuration:\n");
mm/memblock.c:  pr_info(" memory size = %pa reserved size = %pa\n",

cheers, Joe

Re: [PATCH] memblock: Neaten logging

[Mike Rapoport]

On Fri, Oct 01, 2021 at 01:34:10PM -0700, Joe Perches wrote:
> On Fri, 2021-10-01 at 09:37 -0700, Mike Rapoport wrote:
> > On Thu, Sep 30, 2021 at 06:27:15PM -0700, Joe Perches wrote:
> > > On Thu, 2021-09-30 at 14:12 -0700, Mike Rapoport wrote:
> > > > Hi Joe,
> > > > 
> > > > On Wed, Sep 29, 2021 at 09:43:14PM -0700, Joe Perches wrote:
> > > > > Use more typical kernel logging styles.
> > > > > 
> > > > > o Add and use #define pr_fmt KBUILD_MODNAME ": " fmt
> > > > 
> > > > I don't see it as an improvement. On the contrary, the output becomes
> > > > somewhat tautological:
> > > 
> > > And rather easier to grep as the prefix is constant.
> > 
> > memblock_ is perfectly greppable
> 
> Of course, but only when it's there, 2 instances out of 9.

I didn't object to the patch as a whole. I just don't like the pr_fmt
definition.
 
> $ git grep '\bpr_' mm/memblock.c
> mm/memblock.c:          pr_warn("Could not allocate %pap bytes of mirrored memory\n",
> mm/memblock.c:          pr_err("memblock: Failed to double %s array from %ld to %ld entries !\n",
> mm/memblock.c:          pr_warn("Could not allocate %pap bytes of mirrored memory\n",

These can have %s for __func__ as a prefix,

> mm/memblock.c:          pr_warn("%s: No memory registered yet\n", __func__);

this one already has it,

> mm/memblock.c:  pr_info(" %s.cnt  = 0x%lx\n", type->name, type->cnt);
> mm/memblock.c:          pr_info(" %s[%#x]\t[%pa-%pa], %pa bytes%s flags: %#x\n",
> mm/memblock.c:  pr_info("MEMBLOCK configuration:\n");
> mm/memblock.c:  pr_info(" memory size = %pa reserved size = %pa\n",

and these are just fine now even without the prefix.

-- 
Sincerely yours,
Mike.

Re: [PATCH] memblock: Neaten logging

[Joe Perches]

On Fri, 2021-10-01 at 16:12 -0700, Mike Rapoport wrote:
> On Fri, Oct 01, 2021 at 01:34:10PM -0700, Joe Perches wrote:
> > On Fri, 2021-10-01 at 09:37 -0700, Mike Rapoport wrote:
> > > On Thu, Sep 30, 2021 at 06:27:15PM -0700, Joe Perches wrote:
> > > > On Thu, 2021-09-30 at 14:12 -0700, Mike Rapoport wrote:
> > > > > Hi Joe,
> > > > > 
> > > > > On Wed, Sep 29, 2021 at 09:43:14PM -0700, Joe Perches wrote:
> > > > > > Use more typical kernel logging styles.
> > > > > > 
> > > > > > o Add and use #define pr_fmt KBUILD_MODNAME ": " fmt
> > > > > 
> > > > > I don't see it as an improvement. On the contrary, the output becomes
> > > > > somewhat tautological:
> > > > 
> > > > And rather easier to grep as the prefix is constant.
> > > 
> > > memblock_ is perfectly greppable
> > 
> > Of course, but only when it's there, 2 instances out of 9.
> 
> I didn't object to the patch as a whole. I just don't like the pr_fmt
> definition.

You should do what you like.  I did what I like.

cheers, Joe

Re: [PATCH] memblock: Neaten logging

[Mike Rapoport]

On Fri, Oct 01, 2021 at 04:20:14PM -0700, Joe Perches wrote:
> On Fri, 2021-10-01 at 16:12 -0700, Mike Rapoport wrote:
> > On Fri, Oct 01, 2021 at 01:34:10PM -0700, Joe Perches wrote:
> > > On Fri, 2021-10-01 at 09:37 -0700, Mike Rapoport wrote:
> > > > On Thu, Sep 30, 2021 at 06:27:15PM -0700, Joe Perches wrote:
> > > > > On Thu, 2021-09-30 at 14:12 -0700, Mike Rapoport wrote:
> > > > > > Hi Joe,
> > > > > > 
> > > > > > On Wed, Sep 29, 2021 at 09:43:14PM -0700, Joe Perches wrote:
> > > > > > > Use more typical kernel logging styles.
> > > > > > > 
> > > > > > > o Add and use #define pr_fmt KBUILD_MODNAME ": " fmt
> > > > > > 
> > > > > > I don't see it as an improvement. On the contrary, the output becomes
> > > > > > somewhat tautological:
> > > > > 
> > > > > And rather easier to grep as the prefix is constant.
> > > > 
> > > > memblock_ is perfectly greppable
> > > 
> > > Of course, but only when it's there, 2 instances out of 9.
> > 
> > I didn't object to the patch as a whole. I just don't like the pr_fmt
> > definition.
> 
> You should do what you like.  I did what I like.
 
I'm perfectly fine with the current state.

-- 
Sincerely yours,
Mike.