[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