[PATCH 0/4] cosmetic fixes to module pr_debugs

[PATCH 0/4] cosmetic fixes to module pr_debugs

[Jim Cromie]

Hi Luis,

These 4 patches alter pr_debug() messages for more info, and less
log-spam.

* add "for $modname:" to banners
  helpful for finding one of many

[   40.885922] main:layout_sections: Core section allocation order for test_dynamic_debug:
    	       ~20 lines of output
[   40.885967] main:move_module: Final section addresses for test_dynamic_debug:
    	       ~2 lines - .init.text/data

* add symbol name to "Absolute symbol: <value>"
  val ~== 0 - less interesting than name

[   40.886006] main:simplify_symbols: Absolute symbol: 0x00000000 test_dynamic_debug.c
[   40.886008] main:simplify_symbols: Absolute symbol: 0x00000000 test_dynamic_debug.mod.c

* add size to section report. gives more info.

[   40.885968] main:move_module: 	0xffffffffc0249000 0x0000035d .text
[   40.885971] main:move_module: 	0xffffffffc0252000 0x0000003c .init.text

* drop already_uses: pr_debug("$ uses $b!") messages

  echo module main +pmf >/proc/dynamic_debug/control
  modprobe i915

before:
  dmesg | grep already_uses | cut -c15- | wc
    673    2722   28641
  dmesg | grep already_uses | cut -c15- | sort -u | wc
     26     134    1237

after:
  dmesg | grep already_uses | cut -c15- | wc
     15      90     756
  dmesg | grep already_uses | cut -c15- | sort -u | wc
     15      90     756


Jim Cromie (4):
  module: in layout_sections, move_module: add the modname
  module: add symbol-name to pr_debug Absolute symbol
  module: add section-size to move_module pr_debug
  module: already_uses() - reduce pr_debug output volume

 kernel/module/main.c | 18 ++++++++----------
 1 file changed, 8 insertions(+), 10 deletions(-)

-- 
2.39.2

[PATCH 1/4] module: in layout_sections, move_module: add the modname

[Jim Cromie]

layout_sections() and move_module() each issue ~50 messages for each
module loaded.  Add mod-name into their 2 header lines, to help the
reader find his module.

no functional changes.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 kernel/module/main.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/kernel/module/main.c b/kernel/module/main.c
index b4759f1695b7..39f267c40286 100644
--- a/kernel/module/main.c
+++ b/kernel/module/main.c
@@ -1523,10 +1523,10 @@ static void layout_sections(struct module *mod, struct load_info *info)
 	for (i = 0; i < info->hdr->e_shnum; i++)
 		info->sechdrs[i].sh_entsize = ~0UL;
 
-	pr_debug("Core section allocation order:\n");
+	pr_debug("Core section allocation order for %s:\n", mod->name);
 	__layout_sections(mod, info, false);
 
-	pr_debug("Init section allocation order:\n");
+	pr_debug("Init section allocation order for %s:\n", mod->name);
 	__layout_sections(mod, info, true);
 }
 
@@ -2162,7 +2162,7 @@ static int move_module(struct module *mod, struct load_info *info)
 	}
 
 	/* Transfer each section which specifies SHF_ALLOC */
-	pr_debug("final section addresses:\n");
+	pr_debug("Final section addresses for %s:\n", mod->name);
 	for (i = 0; i < info->hdr->e_shnum; i++) {
 		void *dest;
 		Elf_Shdr *shdr = &info->sechdrs[i];
-- 
2.39.2

[PATCH 2/4] module: add symbol-name to pr_debug Absolute symbol

[Jim Cromie]

The pr_debug("Absolute symbol" ..) reports value, (which is usually
0), but not the name, which is more informative.  So add it.

no functional changes

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 kernel/module/main.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/kernel/module/main.c b/kernel/module/main.c
index 39f267c40286..e248a3697ffb 100644
--- a/kernel/module/main.c
+++ b/kernel/module/main.c
@@ -1350,8 +1350,8 @@ static int simplify_symbols(struct module *mod, const struct load_info *info)
 
 		case SHN_ABS:
 			/* Don't need to do anything */
-			pr_debug("Absolute symbol: 0x%08lx\n",
-			       (long)sym[i].st_value);
+			pr_debug("Absolute symbol: 0x%08lx %s\n",
+				 (long)sym[i].st_value, name);
 			break;
 
 		case SHN_LIVEPATCH:
-- 
2.39.2

[PATCH 3/4] module: add section-size to move_module pr_debug

[Jim Cromie]

move_module() pr_debug's "Final section addresses for $modname".
Add section addresses to the message, for anyone looking at these.

no functional changes.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 kernel/module/main.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/kernel/module/main.c b/kernel/module/main.c
index e248a3697ffb..a2a8ed8564ae 100644
--- a/kernel/module/main.c
+++ b/kernel/module/main.c
@@ -2177,8 +2177,8 @@ static int move_module(struct module *mod, struct load_info *info)
 			memcpy(dest, (void *)shdr->sh_addr, shdr->sh_size);
 		/* Update sh_addr to point to copy in image. */
 		shdr->sh_addr = (unsigned long)dest;
-		pr_debug("\t0x%lx %s\n",
-			 (long)shdr->sh_addr, info->secstrings + shdr->sh_name);
+		pr_debug("\t0x%lx 0x%.8lx %s\n", (long)shdr->sh_addr,
+			 (long)shdr->sh_size, info->secstrings + shdr->sh_name);
 	}
 
 	return 0;
-- 
2.39.2

[PATCH 4/4] module: already_uses() - reduce pr_debug output volume

[Jim Cromie]

already_uses() is unnecessarily chatty.

`modprobe i915` yields 491 messages like:

  [   64.108744] i915 uses drm!

This is a normal situation, and isn't worth all the log entries.

NOTE: I've preserved the "does not use %s" messages, which happens
less often, but does happen.  Its not clear to me what it tells a
reader, or what info might improve the pr_debug's utility.

[ 6847.584999] main:already_uses:569: amdgpu does not use ttm!
[ 6847.585001] main:add_module_usage:584: Allocating new usage for amdgpu.
[ 6847.585014] main:already_uses:569: amdgpu does not use drm!
[ 6847.585016] main:add_module_usage:584: Allocating new usage for amdgpu.
[ 6847.585024] main:already_uses:569: amdgpu does not use drm_display_helper!
[ 6847.585025] main:add_module_usage:584: Allocating new usage for amdgpu.
[ 6847.585084] main:already_uses:569: amdgpu does not use drm_kms_helper!
[ 6847.585086] main:add_module_usage:584: Allocating new usage for amdgpu.
[ 6847.585175] main:already_uses:569: amdgpu does not use drm_buddy!
[ 6847.585176] main:add_module_usage:584: Allocating new usage for amdgpu.
[ 6847.585202] main:already_uses:569: amdgpu does not use i2c_algo_bit!
[ 6847.585204] main:add_module_usage:584: Allocating new usage for amdgpu.
[ 6847.585249] main:already_uses:569: amdgpu does not use gpu_sched!
[ 6847.585250] main:add_module_usage:584: Allocating new usage for amdgpu.
[ 6847.585314] main:already_uses:569: amdgpu does not use video!
[ 6847.585315] main:add_module_usage:584: Allocating new usage for amdgpu.
[ 6847.585409] main:already_uses:569: amdgpu does not use iommu_v2!
[ 6847.585410] main:add_module_usage:584: Allocating new usage for amdgpu.
[ 6847.585816] main:already_uses:569: amdgpu does not use drm_ttm_helper!
[ 6847.585818] main:add_module_usage:584: Allocating new usage for amdgpu.
[ 6848.762268] dyndbg: add-module: amdgpu.2533 sites

no functional changes.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 kernel/module/main.c | 4 +---
 1 file changed, 1 insertion(+), 3 deletions(-)

diff --git a/kernel/module/main.c b/kernel/module/main.c
index a2a8ed8564ae..0a5583686994 100644
--- a/kernel/module/main.c
+++ b/kernel/module/main.c
@@ -563,10 +563,8 @@ static int already_uses(struct module *a, struct module *b)
 	struct module_use *use;
 
 	list_for_each_entry(use, &b->source_list, source_list) {
-		if (use->source == a) {
-			pr_debug("%s uses %s!\n", a->name, b->name);
+		if (use->source == a)
 			return 1;
-		}
 	}
 	pr_debug("%s does not use %s!\n", a->name, b->name);
 	return 0;
-- 
2.39.2

Re: [PATCH 0/4] cosmetic fixes to module pr_debugs

[Luis Chamberlain]

From: Luis Chamberlain <mcgrof@kernel.org>

On Tue, 21 Mar 2023 19:36:19 -0600, Jim Cromie wrote:
> These 4 patches alter pr_debug() messages for more info, and less
> log-spam.
> 
> * add "for $modname:" to banners
>   helpful for finding one of many
> 
> [   40.885922] main:layout_sections: Core section allocation order for test_dynamic_debug:
>     	       ~20 lines of output
> [   40.885967] main:move_module: Final section addresses for test_dynamic_debug:
>     	       ~2 lines - .init.text/data
> 
> [...]

Applied, thanks!

[1/4] module: in layout_sections, move_module: add the modname
      commit: 4ab9c7dca82f215fa596fb61192384e4c922bf9c
[2/4] module: add symbol-name to pr_debug Absolute symbol
      commit: 9f5d69a7852db158bc9f5c5afa105ce12058afc3
[3/4] module: add section-size to move_module pr_debug
      commit: 8cf2cfac04e4b24dfc4371306e202b09ab574a80
[4/4] module: already_uses() - reduce pr_debug output volume
      commit: 6e82310365bade624ff38dd11a8467739adab6cc

  Luis

[PATCH 2/4] module: add symbol-name to pr_debug Absolute symbol

[Jim Cromie]

Symbol name is likely to be at least as useful as the value (which is
written, and is usually 0), if one is looking at these messages.

no functional changes

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 kernel/module.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/kernel/module.c b/kernel/module.c
index af2641b28d73..ab16b8da2555 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -2300,8 +2300,8 @@ static int simplify_symbols(struct module *mod, const struct load_info *info)
 
 		case SHN_ABS:
 			/* Don't need to do anything */
-			pr_debug("Absolute symbol: 0x%08lx\n",
-			       (long)sym[i].st_value);
+			pr_debug("Absolute symbol: 0x%08lx %s\n",
+				 (long)sym[i].st_value, name);
 			break;
 
 		case SHN_LIVEPATCH:
-- 
2.30.2