Re: module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

Re: module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

[Dan Kegel]

In July of 2002, Andrea Arcangeli posted a patch
(see thread http://marc.theaimsgroup.com/?l=linux-kernel&m=102772338115172&w=2)
to dump module names and address ranges during oops logging,
and said that there should eventually be a "module tracking aware ksymoops":

> I implemented what I need to track down oopses with modules. ksymoops
> should learn about it too. This will also allow us to recognize
> immediatly the kernel image used.
> 
> here an example of oops in a module with the patch applied (only 1
> module is affected so only 1 module is listed). I checked that
> 0xca40306e-0xca403060 gives the exact offset to lookup in the objdump -d
> of the module object.
 >
> this patch will solve all the issues in being able to track down module
> oopses and kernel image without introducing any waste of ram (nitpick:
> except 40 bytes of ram). For user compiled kernels, if the user isn't
> capable of saving System.map and vmlinux kksymoops remains a viable
> alternative, but I don't feel it needed for pre-compiled kernel images
> provided a compile-time database exists ...

He has carried that patch forward, and it's e.g. in his current 2.4 tree:
http://www.kernel.org/pub/linux/kernel/people/andrea/kernels/v2.4/2.4.23pre6aa3/90_module-oops-tracking-3

Looking at ksymoops' source and Changelog, it isn't obvious whether
ksymoops-2.4.9 is "module tracking aware" yet.  Has anyone worked
on this?

Thanks,
Dan

Re: module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

[cort]

All I need is the nearest symbol name and that's it.  The patch was pretty
simple so it could be easily merged.  It added only a few 100's of bytes on
x86 and below 1k on PPC.  It would be handy to have this in a kernel rather
than require some user utility that requires I make it work in a
cross-build environment, copy the 'insmod -m' map output to my host
machine, run the user program on the system.map and the user utilities for
every boot, crash, debug cycle.

The patch is tiny and simple and I hoped to keep it that way.  If I want to
dig into the system and seriously debug rather than follow a known problem
I can use xmon on PPC, kgdb or more often than not a real JTAG debugger.

How about this - we print the module beginning _and_ the EIP symbol if we
can find one.  You get what you want and I get what I want (I won't even
add a line of output to get what I want).

To solve the ksyms mystery can you send me what versions of modutils, what
architecture, what distribution and anything else you think might be
useful?  I'd like to know what cases this fails in.

} You follow it. The reason I'm dropping functionality is that I want the
} functionality in userspace, not because your patch in-kernel was wasting
} any resources, but because from userspace the functionality will do the
} *right* thing always without me having to check if the symbol happened
} to be right because it was exported (and still no idea why you've more
} symbols than me in ksyms for modules). Also rarely I can get away with
} just the EIP.  So in short the symbol isn't going to help because I'd
} need to recheck with ksymoops anyways and I need the stack trace too
} potentially part of other modules, so I prefer to provide via the oops
} only the numeric information, but *all* of it :) to also reduce the oops
} size.  If your main object is to skip the ksymoops step, then I think
} even in such case you want to go to a full complete kksymoops instead of
} the halfway approch. I think ksymoops + module oops tracking patch is
} more than enough for the bugreports (modulo dprobes/lkcd etc...). For
} developement using a true debugger to get stack traces and inspect ram
} (i.e. uml or kgdb or kdb ) is probably superior to any other oops
} functionalty anyways (so if your object is to avoid the ksymoops step
} during developement I would suggest a real debugger that will save even
} more time).
} 
} I like the strict module oops tracking in particular for pre-compiled
} kernels where we don't even need to ask the user the system.map/vmlinux
} in order to debug it, and so where it would be a total loss of global
} ram resources to load in kernel ram of every machine all the symbols of
} the whole kernel and modules. Furthmore this adds a critical needed
} feature to have a chance to debug module oopses, so it's a must-have.
} 
} Nevertheless adding your ksym lookup for the EIP wouldn't hurt and it
} wouldn't waste lines (columns doesn't matter near the EIP), so we could
} merge the two things together, but as said above I don't feel the need
} of it as far as ksymoops learns about resolving the eip through the
} module information now included in the oops.
} 
} I updated the patch to reduce the number of lines of the oops, this is
} incremental with the previous patch.
} 
} --- 2.4.19rc3aa2/kernel/module.c.~1~	Sat Jul 27 00:48:38 2002
} +++ 2.4.19rc3aa2/kernel/module.c	Sat Jul 27 03:44:16 2002
} @@ -1271,26 +1271,29 @@ static void __module_oops_tracking_print
}  
}  	for (mod = module_list; mod != &kernel_module; mod = mod->next) {
}  		if (!nr--)
} -			printk("	[(%s:<%p>:<%p>)]\n",
} +			printk(" [(%s:<%p>:<%p>)]",
}  			       mod->name,
}  			       (char *) mod + mod->size_of_struct,
}  			       (char *) mod + mod->size);
}  	}
} -	
}  }
}  
}  void module_oops_tracking_print(void)
}  {
}  	int nr;
} +	int i = 0;
}  
} -	printk("Module Oops Tracking:\n");
} +	printk("Modules:");
}  	nr = find_first_bit(module_oops_tracking, MODULE_OOPS_TRACKING_NR_BITS);
}  	for (;;) {
}  		if (nr == MODULE_OOPS_TRACKING_NR_BITS)
} -			return;
} +			break;
} +		if (i && !(i++ % 2))
} +			printk("\n        ");
}  		__module_oops_tracking_print(nr);
}  		nr = find_next_bit(module_oops_tracking, MODULE_OOPS_TRACKING_NR_BITS, nr+1);
}  	}
} +	printk("\n");
}  }
}  
}  #else		/* CONFIG_MODULES */
} 
} 
} Andrea

Re: module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

[Andrea Arcangeli]

On Sat, Jul 27, 2002 at 11:33:11AM +1000, Keith Owens wrote:
> On Sat, 27 Jul 2002 03:19:06 +0200, 
> Andrea Arcangeli <andrea@suse.de> wrote:
> >here an updated patch that moves the bitflag from the dedicated array to
> >the mod->flags per your suggesiton.
> >Oops: 0002
> >2.4.19-rc3aa2 #3 SMP Sat Jul 27 05:06:19 CEST 2002
> 
> Kernel version without any identifying string cannot be picked up by
> ksymoops.  Can you append the kernel version to the die message?  That
> means changing all arch/*/traps.c but it saves a line on the console.
> 
> Oops: 0002 2.4.19-rc3aa2 #3 SMP Sat Jul 27 05:06:19 CEST 2002

ok, it saves one more line (will be in next -aa too, for rc3aa2 it's too
late 8).

diff -urNp z/arch/i386/kernel/traps.c 2.4.19rc3aa2/arch/i386/kernel/traps.c
--- z/arch/i386/kernel/traps.c	Sat Jul 27 03:42:39 2002
+++ 2.4.19rc3aa2/arch/i386/kernel/traps.c	Sat Jul 27 03:41:56 2002
@@ -113,6 +113,7 @@ static inline int kernel_text_address(un
 		 * module area. Of course it'd be better to test only
 		 * for the .text subset... */
 		if (mod_bound(addr, 0, mod)) {
+			module_oops_tracking_mark(mod);
 			retval = 1;
 			break;
 		}
@@ -208,6 +209,8 @@ void show_registers(struct pt_regs *regs
 		esp = regs->esp;
 		ss = regs->xss & 0xffff;
 	}
+	module_oops_tracking_init();
+	kernel_text_address(regs->eip);
 	printk("CPU:    %d\nEIP:    %04x:[<%08lx>]    %s\nEFLAGS: %08lx\n",
 		smp_processor_id(), 0xffff & regs->xcs, regs->eip, print_tainted(), regs->eflags);
 	printk("eax: %08lx   ebx: %08lx   ecx: %08lx   edx: %08lx\n",
@@ -226,8 +229,9 @@ void show_registers(struct pt_regs *regs
 
 		printk("\nStack: ");
 		show_stack((unsigned long*)esp);
+		module_oops_tracking_print();
 
-		printk("\nCode: ");
+		printk("Code: ");
 		if(regs->eip < PAGE_OFFSET)
 			goto bad;
 
@@ -288,7 +292,8 @@ void die(const char * str, struct pt_reg
 	spin_lock_irq(&die_lock);
 	bust_spinlocks(1);
 	handle_BUG(regs);
-	printk("%s: %04lx\n", str, err & 0xffff);
+	printk("%s: %04lx ", str, err & 0xffff);
+	printk(oops_id);
 	show_registers(regs);
 	bust_spinlocks(0);
 	spin_unlock_irq(&die_lock);
diff -urNp z/include/linux/kernel.h 2.4.19rc3aa2/include/linux/kernel.h
--- z/include/linux/kernel.h	Sat Jul 27 03:42:39 2002
+++ 2.4.19rc3aa2/include/linux/kernel.h	Sat Jul 27 04:57:04 2002
@@ -109,6 +109,8 @@ extern const char *print_tainted(void);
 
 extern void dump_stack(void);
 
+extern char *oops_id;
+
 #if DEBUG
 #define pr_debug(fmt,arg...) \
 	printk(KERN_DEBUG fmt,##arg)
diff -urNp z/include/linux/module.h 2.4.19rc3aa2/include/linux/module.h
--- z/include/linux/module.h	Sat Jul 27 03:42:39 2002
+++ 2.4.19rc3aa2/include/linux/module.h	Sat Jul 27 04:57:40 2002
@@ -110,6 +110,7 @@ struct module_info
 #define MOD_USED_ONCE		16
 #define MOD_JUST_FREED		32
 #define MOD_INITIALIZING	64
+#define MOD_OOPS_PRINT		128
 
 /* Values for query_module's which.  */
 
@@ -411,4 +412,14 @@ __attribute__((section("__ksymtab"))) =	
 #define SET_MODULE_OWNER(some_struct) do { } while (0)
 #endif
 
+#ifdef CONFIG_MODULES
+extern void module_oops_tracking_init(void);
+extern void module_oops_tracking_mark(struct module *);
+extern void module_oops_tracking_print(void);
+#else
+#define module_oops_tracking_init() do { } while (0)
+#define module_oops_tracking_mark(x) do { } while (0)
+#define module_oops_tracking_print() do { } while (0)
+#endif
+
 #endif /* _LINUX_MODULE_H */
diff -urNp z/init/version.c 2.4.19rc3aa2/init/version.c
--- z/init/version.c	Sat Jul 27 03:42:39 2002
+++ 2.4.19rc3aa2/init/version.c	Sat Jul 27 05:03:14 2002
@@ -24,3 +24,5 @@ struct new_utsname system_utsname = {
 const char *linux_banner = 
 	"Linux version " UTS_RELEASE " (" LINUX_COMPILE_BY "@"
 	LINUX_COMPILE_HOST ") (" LINUX_COMPILER ") " UTS_VERSION "\n";
+
+const char *oops_id = UTS_RELEASE " " UTS_VERSION "\n";
diff -urNp z/kernel/module.c 2.4.19rc3aa2/kernel/module.c
--- z/kernel/module.c	Sat Jul 27 03:42:39 2002
+++ 2.4.19rc3aa2/kernel/module.c	Sat Jul 27 02:38:24 2002
@@ -1242,6 +1242,50 @@ struct seq_operations ksyms_op = {
 	show:	s_show
 };
 
+/*
+ * The module tracking logic assumes the module list doesn't
+ * change under the oops. In case of a race we could get not
+ * the exact information about the affected modules, but it's
+ * almost impossible to trigger and it's a not interesting case.
+ * This code runs protected by the die_lock spinlock, the arch/
+ * caller takes care of it.
+ */
+void module_oops_tracking_init(void)
+{
+	struct module * mod;
+
+	for (mod = module_list; mod != &kernel_module; mod = mod->next)
+		mod->flags &= MOD_OOPS_PRINT;
+}
+
+void module_oops_tracking_mark(struct module * mod)
+{
+	mod->flags |= MOD_OOPS_PRINT;
+}
+
+void module_oops_tracking_print(void)
+{
+	struct module *mod;
+	int i = 0;
+
+	for (mod = module_list; mod != &kernel_module; mod = mod->next) {
+		if (!(mod->flags & MOD_OOPS_PRINT))
+			continue;
+		if (!i)
+			printk("Modules:");
+		if (i && !(i % 2))
+			printk("\n        ");
+		i++;
+
+		printk(" [(%s:<%p>:<%p>)]",
+		       mod->name,
+		       (char *) mod + mod->size_of_struct,
+		       (char *) mod + mod->size);
+	}
+	if (i)
+		printk("\n");
+}
+
 #else		/* CONFIG_MODULES */
 
 /* Dummy syscalls for people who don't want modules */

Andrea

Re: module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

[Keith Owens]

On Sat, 27 Jul 2002 03:19:06 +0200, 
Andrea Arcangeli <andrea@suse.de> wrote:
>here an updated patch that moves the bitflag from the dedicated array to
>the mod->flags per your suggesiton.
>Oops: 0002
>2.4.19-rc3aa2 #3 SMP Sat Jul 27 05:06:19 CEST 2002

Kernel version without any identifying string cannot be picked up by
ksymoops.  Can you append the kernel version to the die message?  That
means changing all arch/*/traps.c but it saves a line on the console.

Oops: 0002 2.4.19-rc3aa2 #3 SMP Sat Jul 27 05:06:19 CEST 2002

>+void module_oops_tracking_init(void)
>+{
>+	struct module * mod;
>+
>+	for (mod = module_list; mod != &kernel_module; mod = mod->next)
>+		mod->flags &= MOD_OOPS_PRINT;

		mod->flags &= ~MOD_OOPS_PRINT;

Re: module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

[Andrea Arcangeli]

On Sat, Jul 27, 2002 at 02:31:21AM +0200, Andrea Arcangeli wrote:
> On Sat, Jul 27, 2002 at 10:19:31AM +1000, Keith Owens wrote:
> > On Sat, 27 Jul 2002 00:37:50 +0200, 
> > Andrea Arcangeli <andrea@suse.de> wrote:
> > >I implemented what I need to track down oopses with modules. ksymoops
> > >should learn about it too. This will also allow us to recognize
> > >immediatly the kernel image used.
> > >+#define MODULE_OOPS_TRACKING_NR_LONGS 10
> > >+#define MODULE_OOPS_TRACKING_NR_BITS (BITS_PER_LONG * MODULE_OOPS_TRACKING_NR_LONGS)
> > >+static unsigned long module_oops_tracking[MODULE_OOPS_TRACKING_NR_LONGS];
> > >+void module_oops_tracking_mark(int nr)
> > >+{
> > >+	if (nr < MODULE_OOPS_TRACKING_NR_BITS)
> > >+		set_bit(nr, module_oops_tracking);
> > >+}
> > >+
> > >+static void __module_oops_tracking_print(int nr)
> > >+{
> > >+	struct module *mod;
> > >+
> > >+	for (mod = module_list; mod != &kernel_module; mod = mod->next) {
> > >+		if (!nr--)
> > >+			printk("	[(%s:<%p>:<%p>)]\n",
> > >+			       mod->name,
> > >+			       (char *) mod + mod->size_of_struct,
> > >+			       (char *) mod + mod->size);
> > >+	}
> > >+	
> > >+}
> > 
> > Instead of adding a separate bit map and scanning the module chain to
> > convert a bit number to a module entry, add a new entry to mod->flags.
> > 
> >   #define MOD_OOPS_PRINTED 128
> > 
> > That simplifies the code and reduces the number of times you have to
> > scan the module list.
> 
> ok, the prepare stage will be a bit more complicated but it seems
> a worthwhile change, thanks.

here an updated patch that moves the bitflag from the dedicated array to
the mod->flags per your suggesiton.

The output now looks like this (I also compressed the oops_id info so
that it doesn't overflow 80 cols, given I saved 1 suprios return this
overall only adds an overhead of 1 line to the oops when there are
modules and zero overhead of no module is involved). The new provided
information is invaluable in may situations and it can be easily parsed
by ksymoops in a reliable manner.

Unable to handle kernel NULL pointer dereference at virtual address 00000000
 printing eip:
c39d906e
*pde = 00000000
Oops: 0002
2.4.19-rc3aa2 #3 SMP Sat Jul 27 05:06:19 CEST 2002
CPU:    0
EIP:    0010:[<c39d906e>]    Tainted: P 
EFLAGS: 00010246
eax: c39d9060   ebx: ffffffea   ecx: c034b350   edx: c10ad8a0
esi: 00000000   edi: 00000000   ebp: c39d9000   esp: c39dbf10
ds: 0018   es: 0018   ss: 0018
Process insmod (pid: 929, stackpage=c39db000)
Stack: 00000000 00000000 ffffffea c011f917 c39d9060 080862d0 000000e0 00000000 
       08086335 000000c5 00000060 00000060 00000004 c22caa40 c39d8000 c39dc000 
       00000060 c2260000 c39d9060 00000140 00000000 00000000 00000000 00000000 
Call Trace:    [<c011f917>] [<c39d9060>] [<c39d9060>] [<c01090e7>]
Modules: [(oops:<c39d9060>:<c39d9140>)]
Code: c7 05 00 00 00 00 00 00 00 00 83 0d 14 90 9d c3 08 e8 4c 1e 

diff -urNp z/arch/i386/kernel/traps.c 2.4.19rc3aa2/arch/i386/kernel/traps.c
--- z/arch/i386/kernel/traps.c	Sat Jul 27 03:13:07 2002
+++ 2.4.19rc3aa2/arch/i386/kernel/traps.c	Sat Jul 27 03:14:30 2002
@@ -113,6 +113,7 @@ static inline int kernel_text_address(un
 		 * module area. Of course it'd be better to test only
 		 * for the .text subset... */
 		if (mod_bound(addr, 0, mod)) {
+			module_oops_tracking_mark(mod);
 			retval = 1;
 			break;
 		}
@@ -201,6 +202,8 @@ void show_registers(struct pt_regs *regs
 	unsigned long esp;
 	unsigned short ss;
 
+	printk(oops_id);
+
 	esp = (unsigned long) (&regs->esp);
 	ss = __KERNEL_DS;
 	if (regs->xcs & 3) {
@@ -208,6 +211,8 @@ void show_registers(struct pt_regs *regs
 		esp = regs->esp;
 		ss = regs->xss & 0xffff;
 	}
+	module_oops_tracking_init();
+	kernel_text_address(regs->eip);
 	printk("CPU:    %d\nEIP:    %04x:[<%08lx>]    %s\nEFLAGS: %08lx\n",
 		smp_processor_id(), 0xffff & regs->xcs, regs->eip, print_tainted(), regs->eflags);
 	printk("eax: %08lx   ebx: %08lx   ecx: %08lx   edx: %08lx\n",
@@ -226,8 +231,9 @@ void show_registers(struct pt_regs *regs
 
 		printk("\nStack: ");
 		show_stack((unsigned long*)esp);
+		module_oops_tracking_print();
 
-		printk("\nCode: ");
+		printk("Code: ");
 		if(regs->eip < PAGE_OFFSET)
 			goto bad;
 
diff -urNp z/include/linux/kernel.h 2.4.19rc3aa2/include/linux/kernel.h
--- z/include/linux/kernel.h	Sat Jul 27 03:13:07 2002
+++ 2.4.19rc3aa2/include/linux/kernel.h	Sat Jul 27 04:57:04 2002
@@ -109,6 +109,8 @@ extern const char *print_tainted(void);
 
 extern void dump_stack(void);
 
+extern char *oops_id;
+
 #if DEBUG
 #define pr_debug(fmt,arg...) \
 	printk(KERN_DEBUG fmt,##arg)
diff -urNp z/include/linux/module.h 2.4.19rc3aa2/include/linux/module.h
--- z/include/linux/module.h	Sat Jul 27 03:13:07 2002
+++ 2.4.19rc3aa2/include/linux/module.h	Sat Jul 27 04:57:40 2002
@@ -110,6 +110,7 @@ struct module_info
 #define MOD_USED_ONCE		16
 #define MOD_JUST_FREED		32
 #define MOD_INITIALIZING	64
+#define MOD_OOPS_PRINT		128
 
 /* Values for query_module's which.  */
 
@@ -411,4 +412,14 @@ __attribute__((section("__ksymtab"))) =	
 #define SET_MODULE_OWNER(some_struct) do { } while (0)
 #endif
 
+#ifdef CONFIG_MODULES
+extern void module_oops_tracking_init(void);
+extern void module_oops_tracking_mark(struct module *);
+extern void module_oops_tracking_print(void);
+#else
+#define module_oops_tracking_init() do { } while (0)
+#define module_oops_tracking_mark(x) do { } while (0)
+#define module_oops_tracking_print() do { } while (0)
+#endif
+
 #endif /* _LINUX_MODULE_H */
diff -urNp z/init/version.c 2.4.19rc3aa2/init/version.c
--- z/init/version.c	Tue Jan 22 18:56:00 2002
+++ 2.4.19rc3aa2/init/version.c	Sat Jul 27 05:03:14 2002
@@ -24,3 +24,5 @@ struct new_utsname system_utsname = {
 const char *linux_banner = 
 	"Linux version " UTS_RELEASE " (" LINUX_COMPILE_BY "@"
 	LINUX_COMPILE_HOST ") (" LINUX_COMPILER ") " UTS_VERSION "\n";
+
+const char *oops_id = UTS_RELEASE " " UTS_VERSION "\n";
diff -urNp z/kernel/module.c 2.4.19rc3aa2/kernel/module.c
--- z/kernel/module.c	Sat Jul 27 03:13:07 2002
+++ 2.4.19rc3aa2/kernel/module.c	Sat Jul 27 02:38:24 2002
@@ -1242,6 +1242,50 @@ struct seq_operations ksyms_op = {
 	show:	s_show
 };
 
+/*
+ * The module tracking logic assumes the module list doesn't
+ * change under the oops. In case of a race we could get not
+ * the exact information about the affected modules, but it's
+ * almost impossible to trigger and it's a not interesting case.
+ * This code runs protected by the die_lock spinlock, the arch/
+ * caller takes care of it.
+ */
+void module_oops_tracking_init(void)
+{
+	struct module * mod;
+
+	for (mod = module_list; mod != &kernel_module; mod = mod->next)
+		mod->flags &= MOD_OOPS_PRINT;
+}
+
+void module_oops_tracking_mark(struct module * mod)
+{
+	mod->flags |= MOD_OOPS_PRINT;
+}
+
+void module_oops_tracking_print(void)
+{
+	struct module *mod;
+	int i = 0;
+
+	for (mod = module_list; mod != &kernel_module; mod = mod->next) {
+		if (!(mod->flags & MOD_OOPS_PRINT))
+			continue;
+		if (!i)
+			printk("Modules:");
+		if (i && !(i % 2))
+			printk("\n        ");
+		i++;
+
+		printk(" [(%s:<%p>:<%p>)]",
+		       mod->name,
+		       (char *) mod + mod->size_of_struct,
+		       (char *) mod + mod->size);
+	}
+	if (i)
+		printk("\n");
+}
+
 #else		/* CONFIG_MODULES */
 
 /* Dummy syscalls for people who don't want modules */

Andrea

Re: module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

[Andrea Arcangeli]

On Sat, Jul 27, 2002 at 10:19:31AM +1000, Keith Owens wrote:
> On Sat, 27 Jul 2002 00:37:50 +0200, 
> Andrea Arcangeli <andrea@suse.de> wrote:
> >I implemented what I need to track down oopses with modules. ksymoops
> >should learn about it too. This will also allow us to recognize
> >immediatly the kernel image used.
> >+#define MODULE_OOPS_TRACKING_NR_LONGS 10
> >+#define MODULE_OOPS_TRACKING_NR_BITS (BITS_PER_LONG * MODULE_OOPS_TRACKING_NR_LONGS)
> >+static unsigned long module_oops_tracking[MODULE_OOPS_TRACKING_NR_LONGS];
> >+void module_oops_tracking_mark(int nr)
> >+{
> >+	if (nr < MODULE_OOPS_TRACKING_NR_BITS)
> >+		set_bit(nr, module_oops_tracking);
> >+}
> >+
> >+static void __module_oops_tracking_print(int nr)
> >+{
> >+	struct module *mod;
> >+
> >+	for (mod = module_list; mod != &kernel_module; mod = mod->next) {
> >+		if (!nr--)
> >+			printk("	[(%s:<%p>:<%p>)]\n",
> >+			       mod->name,
> >+			       (char *) mod + mod->size_of_struct,
> >+			       (char *) mod + mod->size);
> >+	}
> >+	
> >+}
> 
> Instead of adding a separate bit map and scanning the module chain to
> convert a bit number to a module entry, add a new entry to mod->flags.
> 
>   #define MOD_OOPS_PRINTED 128
> 
> That simplifies the code and reduces the number of times you have to
> scan the module list.

ok, the prepare stage will be a bit more complicated but it seems
a worthwhile change, thanks.

> 
> Beware if Rusty's idea of discarding init code/data from modules ever
> takes off.  Then the text will not be contiguous, nor will it be at the
> start of the module.

well I assume it's not going to happen in 2.4 anyways and the module
information is really just necessary (we are lacking this needed
information for years now). Once the text won't be contigous anymore to
free init sections for modules too the same needed info on the
presistent text could be provided in a different manner. If you need
anything in the oops now to make life easier to ksymoops later just let
me know.

Andrea

Re: module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

[Keith Owens]

On Sat, 27 Jul 2002 00:37:50 +0200, 
Andrea Arcangeli <andrea@suse.de> wrote:
>I implemented what I need to track down oopses with modules. ksymoops
>should learn about it too. This will also allow us to recognize
>immediatly the kernel image used.
>+#define MODULE_OOPS_TRACKING_NR_LONGS 10
>+#define MODULE_OOPS_TRACKING_NR_BITS (BITS_PER_LONG * MODULE_OOPS_TRACKING_NR_LONGS)
>+static unsigned long module_oops_tracking[MODULE_OOPS_TRACKING_NR_LONGS];
>+void module_oops_tracking_mark(int nr)
>+{
>+	if (nr < MODULE_OOPS_TRACKING_NR_BITS)
>+		set_bit(nr, module_oops_tracking);
>+}
>+
>+static void __module_oops_tracking_print(int nr)
>+{
>+	struct module *mod;
>+
>+	for (mod = module_list; mod != &kernel_module; mod = mod->next) {
>+		if (!nr--)
>+			printk("	[(%s:<%p>:<%p>)]\n",
>+			       mod->name,
>+			       (char *) mod + mod->size_of_struct,
>+			       (char *) mod + mod->size);
>+	}
>+	
>+}

Instead of adding a separate bit map and scanning the module chain to
convert a bit number to a module entry, add a new entry to mod->flags.

  #define MOD_OOPS_PRINTED 128

That simplifies the code and reduces the number of times you have to
scan the module list.

Beware if Rusty's idea of discarding init code/data from modules ever
takes off.  Then the text will not be contiguous, nor will it be at the
start of the module.

Re: module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

[Andrea Arcangeli]

On Fri, Jul 26, 2002 at 05:31:27PM -0600, Cort Dougan wrote:
> I haven't found those cases, nope.  Even with them, it is nice to resolve
> to the nearest symbol when we can.  Printing the beginning and end of the
> module that you put in there is useful, though.
> 
> Any names for the stack trace are a mess, since formatting that is hard
> without scrolling off the screen and making the oops useless.  My patch was
> just a first cut to get a symbol name and module name for the EIP.  I think
> that's a good start and it seems your version actually removes some of the
> very simple functionality that I wanted to be able to use.
> 
> Do I follow what you're doing correctly or do I have it confused?

You follow it. The reason I'm dropping functionality is that I want the
functionality in userspace, not because your patch in-kernel was wasting
any resources, but because from userspace the functionality will do the
*right* thing always without me having to check if the symbol happened
to be right because it was exported (and still no idea why you've more
symbols than me in ksyms for modules). Also rarely I can get away with
just the EIP.  So in short the symbol isn't going to help because I'd
need to recheck with ksymoops anyways and I need the stack trace too
potentially part of other modules, so I prefer to provide via the oops
only the numeric information, but *all* of it :) to also reduce the oops
size.  If your main object is to skip the ksymoops step, then I think
even in such case you want to go to a full complete kksymoops instead of
the halfway approch. I think ksymoops + module oops tracking patch is
more than enough for the bugreports (modulo dprobes/lkcd etc...). For
developement using a true debugger to get stack traces and inspect ram
(i.e. uml or kgdb or kdb ) is probably superior to any other oops
functionalty anyways (so if your object is to avoid the ksymoops step
during developement I would suggest a real debugger that will save even
more time).

I like the strict module oops tracking in particular for pre-compiled
kernels where we don't even need to ask the user the system.map/vmlinux
in order to debug it, and so where it would be a total loss of global
ram resources to load in kernel ram of every machine all the symbols of
the whole kernel and modules. Furthmore this adds a critical needed
feature to have a chance to debug module oopses, so it's a must-have.

Nevertheless adding your ksym lookup for the EIP wouldn't hurt and it
wouldn't waste lines (columns doesn't matter near the EIP), so we could
merge the two things together, but as said above I don't feel the need
of it as far as ksymoops learns about resolving the eip through the
module information now included in the oops.

I updated the patch to reduce the number of lines of the oops, this is
incremental with the previous patch.

--- 2.4.19rc3aa2/kernel/module.c.~1~	Sat Jul 27 00:48:38 2002
+++ 2.4.19rc3aa2/kernel/module.c	Sat Jul 27 03:44:16 2002
@@ -1271,26 +1271,29 @@ static void __module_oops_tracking_print
 
 	for (mod = module_list; mod != &kernel_module; mod = mod->next) {
 		if (!nr--)
-			printk("	[(%s:<%p>:<%p>)]\n",
+			printk(" [(%s:<%p>:<%p>)]",
 			       mod->name,
 			       (char *) mod + mod->size_of_struct,
 			       (char *) mod + mod->size);
 	}
-	
 }
 
 void module_oops_tracking_print(void)
 {
 	int nr;
+	int i = 0;
 
-	printk("Module Oops Tracking:\n");
+	printk("Modules:");
 	nr = find_first_bit(module_oops_tracking, MODULE_OOPS_TRACKING_NR_BITS);
 	for (;;) {
 		if (nr == MODULE_OOPS_TRACKING_NR_BITS)
-			return;
+			break;
+		if (i && !(i++ % 2))
+			printk("\n        ");
 		__module_oops_tracking_print(nr);
 		nr = find_next_bit(module_oops_tracking, MODULE_OOPS_TRACKING_NR_BITS, nr+1);
 	}
+	printk("\n");
 }
 
 #else		/* CONFIG_MODULES */


Andrea

Re: module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

[Cort Dougan]

I haven't found those cases, nope.  Even with them, it is nice to resolve
to the nearest symbol when we can.  Printing the beginning and end of the
module that you put in there is useful, though.

Any names for the stack trace are a mess, since formatting that is hard
without scrolling off the screen and making the oops useless.  My patch was
just a first cut to get a symbol name and module name for the EIP.  I think
that's a good start and it seems your version actually removes some of the
very simple functionality that I wanted to be able to use.

Do I follow what you're doing correctly or do I have it confused?

} that's why, because of those cases. I thought you had those cases too
} right? And for ksymoops it's much simpler to avoid the reverse lookup.
} 
} I think either you go kksymoops, or you go my way + module tracking
} aware ksymoops (only one "k"), the intermediate approch is probably a
} nice way but handy only until a module tracking aware ksymoops exists.
} 
} Furhtmore your patch doesn't really provide all the info need, you
} only take care of the module where the EIP lives, you don't handle the
} case of multiple module addresses in the stack trace. And printing lots
} of symbols for the stack trace too (potentially to reverse all the time
} too) can overflow the screen.  Infact I also considered to print modules
} tracking info without \n in between even if it can overflow to save
} screen ram space. Maybe that's worhwhile, OTOH I wouldn't expect more
} than a few lines usually and the \n makes it more readable but I may
} change it to use better the screen space.

Re: module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

[Andrea Arcangeli]

On Fri, Jul 26, 2002 at 04:55:35PM -0600, Cort Dougan wrote:
> I don't see how this is significantly different from the patch I sent
> apart from removing some useful debugging.  Is there something I'm missing?
> 
> The patch I sent prints out the offset from the symbol name nearest
> (below) the EIP and the offset from that symbol.  I found that really
> useful and was what I use the patch for.  Is there a reason you don't want
> that?  I know you had some cases where all symbols weren't listed for you

that's why, because of those cases. I thought you had those cases too
right? And for ksymoops it's much simpler to avoid the reverse lookup.

I think either you go kksymoops, or you go my way + module tracking
aware ksymoops (only one "k"), the intermediate approch is probably a
nice way but handy only until a module tracking aware ksymoops exists.

Furhtmore your patch doesn't really provide all the info need, you
only take care of the module where the EIP lives, you don't handle the
case of multiple module addresses in the stack trace. And printing lots
of symbols for the stack trace too (potentially to reverse all the time
too) can overflow the screen.  Infact I also considered to print modules
tracking info without \n in between even if it can overflow to save
screen ram space. Maybe that's worhwhile, OTOH I wouldn't expect more
than a few lines usually and the \n makes it more readable but I may
change it to use better the screen space.

> but many of us do have those symbols we'd like to see.
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/


Andrea

Re: module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

[Cort Dougan]

I don't see how this is significantly different from the patch I sent
apart from removing some useful debugging.  Is there something I'm missing?

The patch I sent prints out the offset from the symbol name nearest
(below) the EIP and the offset from that symbol.  I found that really
useful and was what I use the patch for.  Is there a reason you don't want
that?  I know you had some cases where all symbols weren't listed for you
but many of us do have those symbols we'd like to see.

module oops tracking [Re: [PATCH] cheap lookup of symbol names on oops()]

[Andrea Arcangeli]

I implemented what I need to track down oopses with modules. ksymoops
should learn about it too. This will also allow us to recognize
immediatly the kernel image used.

here an example of oops in a module with the patch applied (only 1
module is affected so only 1 module is listed). I checked that
0xca40306e-0xca403060 gives the exact offset to lookup in the objdump -d
of the module object.

this patch will solve all the issues in being able to track down module
oopses and kernel image without introducing any waste of ram (nitpick:
except 40 bytes of ram). For user compiled kernels, if the user isn't
capable of saving System.map and vmlinux kksymoops remains a viable
alternative, but I don't feel it needed for pre-compiled kernel images
provided a compile-time database exists (also considering kksymoops
doesn't obviate the need of the vmlinux, really one can dump the asm off
the bzImage or even more simply from /dev/ram but saving vmlinux is
simpler than to ask the user to do that).

last thing: this will work well till 320 modules simultaneously loaded
on 32bit archs, or 640 for 64bit archs. More modules won't hurt but they
may not showup in the trace, elarging the limit is trivial, it will only
waste some more byte. I also considered another implementation that
basically used an array of "module idx" rather than the bitmap of all
the modules. That had the advantage of requiring ram only in function of
the modules present in the trace, but I didn't like to make too much
assumption on the number of modules in the trace, and with 1 module in
the trace I can track 32 real modules with the below implementation. So
there was not an huge saving, possibly using char instead of ints would
been viable but the below looks simpler too.

Unable to handle kernel NULL pointer dereference at virtual address 00000000
 printing eip:
ca40306e
*pde = 00000000
Oops: 0002
Linux version 2.4.19-rc3aa2 (andrea@dualathlon) (gcc version 3.1.1 20020618 (prerelease)) #17 SMP Fri Jul 26 23:25:11 CEST 2002
CPU:    1
EIP:    0010:[<ca40306e>]    Tainted: P
EFLAGS: 00010246
eax: ca403060   ebx: ffffffea   ecx: c0493d10   edx: c11ec080
esi: 00000000   edi: 00000000   ebp: ca403000   esp: ca433f10
ds: 0018   es: 0018   ss: 0018
Process insmod (pid: 1134, stackpage=ca433000)
Stack: 00000000 00000000 ffffffea c0120817 ca403060 08086ab0 000000e0 00000000
       08086b15 000000c5 00000060 00000060 00000004 c4359440 ca402000 ca438000
       00000060 c0492600 ca403060 00000140 00000000 00000000 00000000 00000000
Call Trace:    [<c0120817>] [<ca403060>] [<ca403060>] [<c01090e7>]
Module Oops Tracking:
        [(oops:<ca403060>:<ca403140>)]
Code: c7 05 00 00 00 00 00 00 00 00 83 0d 14 30 40 ca 08 e8 4c 7e

And here it is the patch:

diff -urNp ref/arch/i386/kernel/traps.c oops-x/arch/i386/kernel/traps.c
--- ref/arch/i386/kernel/traps.c	Fri Jul 26 23:01:38 2002
+++ oops-x/arch/i386/kernel/traps.c	Fri Jul 26 23:06:35 2002
@@ -103,16 +103,18 @@ static inline int kernel_text_address(un
 {
 	int retval = 0;
 	struct module *mod;
+	int nr;
 
 	if (addr >= (unsigned long) &_stext &&
 	    addr <= (unsigned long) &_etext)
 		return 1;
 
-	for (mod = module_list; mod != &kernel_module; mod = mod->next) {
+	for (nr = 0, mod = module_list; mod != &kernel_module; nr++, mod = mod->next) {
 		/* mod_bound tests for addr being inside the vmalloc'ed
 		 * module area. Of course it'd be better to test only
 		 * for the .text subset... */
 		if (mod_bound(addr, 0, mod)) {
+			module_oops_tracking_mark(nr);
 			retval = 1;
 			break;
 		}
@@ -201,6 +203,8 @@ void show_registers(struct pt_regs *regs
 	unsigned long esp;
 	unsigned short ss;
 
+	printk(linux_banner);
+
 	esp = (unsigned long) (&regs->esp);
 	ss = __KERNEL_DS;
 	if (regs->xcs & 3) {
@@ -208,6 +212,8 @@ void show_registers(struct pt_regs *regs
 		esp = regs->esp;
 		ss = regs->xss & 0xffff;
 	}
+	module_oops_tracking_init();
+	kernel_text_address(regs->eip);
 	printk("CPU:    %d\nEIP:    %04x:[<%08lx>]    %s\nEFLAGS: %08lx\n",
 		smp_processor_id(), 0xffff & regs->xcs, regs->eip, print_tainted(), regs->eflags);
 	printk("eax: %08lx   ebx: %08lx   ecx: %08lx   edx: %08lx\n",
@@ -226,8 +232,9 @@ void show_registers(struct pt_regs *regs
 
 		printk("\nStack: ");
 		show_stack((unsigned long*)esp);
+		module_oops_tracking_print();
 
-		printk("\nCode: ");
+		printk("Code: ");
 		if(regs->eip < PAGE_OFFSET)
 			goto bad;
 
diff -urNp ref/include/linux/kernel.h oops-x/include/linux/kernel.h
--- ref/include/linux/kernel.h	Fri Jul 26 23:01:52 2002
+++ oops-x/include/linux/kernel.h	Fri Jul 26 23:18:37 2002
@@ -109,6 +109,8 @@ extern const char *print_tainted(void);
 
 extern void dump_stack(void);
 
+extern char *linux_banner;
+
 #if DEBUG
 #define pr_debug(fmt,arg...) \
 	printk(KERN_DEBUG fmt,##arg)
diff -urNp ref/include/linux/module.h oops-x/include/linux/module.h
--- ref/include/linux/module.h	Wed Jul 24 21:52:27 2002
+++ oops-x/include/linux/module.h	Fri Jul 26 23:25:12 2002
@@ -411,4 +411,14 @@ __attribute__((section("__ksymtab"))) =	
 #define SET_MODULE_OWNER(some_struct) do { } while (0)
 #endif
 
+#ifdef CONFIG_MODULES
+extern void module_oops_tracking_init(void);
+extern void module_oops_tracking_mark(int);
+extern void module_oops_tracking_print(void);
+#else
+#define module_oops_tracking_init() do { } while (0)
+#define module_oops_tracking_mark(x) do { } while (0)
+#define module_oops_tracking_print() do { } while (0)
+#endif
+
 #endif /* _LINUX_MODULE_H */
diff -urNp ref/init/main.c oops-x/init/main.c
--- ref/init/main.c	Fri Jul 26 23:01:52 2002
+++ oops-x/init/main.c	Fri Jul 26 23:18:34 2002
@@ -81,7 +81,6 @@ extern int irda_device_init(void);
 #endif
 
 extern char _stext, _etext;
-extern char *linux_banner;
 
 static int init(void *);
 
diff -urNp ref/kernel/module.c oops-x/kernel/module.c
--- ref/kernel/module.c	Fri Jul 26 23:01:29 2002
+++ oops-x/kernel/module.c	Fri Jul 26 22:50:22 2002
@@ -1242,6 +1242,57 @@ struct seq_operations ksyms_op = {
 	show:	s_show
 };
 
+/*
+ * The module tracking logic assumes the module list doesn't
+ * change under the oops. In case of a race we could get not
+ * the exact information about the affected modules, but it's
+ * almost impossible to trigger and it's a not interesting case.
+ * This code runs protected by the die_lock spinlock, the arch/
+ * caller takes care of it.
+ */
+#define MODULE_OOPS_TRACKING_NR_LONGS 10
+#define MODULE_OOPS_TRACKING_NR_BITS (BITS_PER_LONG * MODULE_OOPS_TRACKING_NR_LONGS)
+static unsigned long module_oops_tracking[MODULE_OOPS_TRACKING_NR_LONGS];
+
+void module_oops_tracking_init(void)
+{
+	memset(module_oops_tracking, 0, sizeof(module_oops_tracking));
+}
+
+void module_oops_tracking_mark(int nr)
+{
+	if (nr < MODULE_OOPS_TRACKING_NR_BITS)
+		set_bit(nr, module_oops_tracking);
+}
+
+static void __module_oops_tracking_print(int nr)
+{
+	struct module *mod;
+
+	for (mod = module_list; mod != &kernel_module; mod = mod->next) {
+		if (!nr--)
+			printk("	[(%s:<%p>:<%p>)]\n",
+			       mod->name,
+			       (char *) mod + mod->size_of_struct,
+			       (char *) mod + mod->size);
+	}
+	
+}
+
+void module_oops_tracking_print(void)
+{
+	int nr;
+
+	printk("Module Oops Tracking:\n");
+	nr = find_first_bit(module_oops_tracking, MODULE_OOPS_TRACKING_NR_BITS);
+	for (;;) {
+		if (nr == MODULE_OOPS_TRACKING_NR_BITS)
+			return;
+		__module_oops_tracking_print(nr);
+		nr = find_next_bit(module_oops_tracking, MODULE_OOPS_TRACKING_NR_BITS, nr+1);
+	}
+}
+
 #else		/* CONFIG_MODULES */
 
 /* Dummy syscalls for people who don't want modules */

Andrea