Skip to contentSkip to conversation

PATCH - kernel trace mechanism for KDB

PATCH Jim Houston 1 participant 1 message Jan 28, 2002

Subsystems (3)
lore
Share & tools
lore
#0 lore raw

Hi!

The attached patch implements a kernel trace mechanism as an addition to kdb. It's set up to build a kernel with the -finstrument-functions compiler option. By default it gathers data on every function call and return. It also includes logic to filter the data collected, capturing data only for selected functions or all but selected functions.

Each entry in the trace includes a timestamp, the called function and the calling address. Function calls also include the frame pointer and 3 words from the stack that might be arguments.

Here is a sample of the output:

63 ret 6.803 us 0xc0121140 (spin_lock) 0xc012011c (__wake_up+0x2c) 64 call 6.899 us 0xc0121140 (spin_lock) 0xc012011c (__wake_up+0x2c)

         fp=c045de84 args = c044d560 00000003 00000045
 65 call 6.970 us 0xc01200f0 (__wake_up)  0xc0225176 (put_queue+0x26)
         fp=c045dea0 args = c045dec4 c0224eab 00000045
 66 call 7.072 us 0xc0225150 (put_queue)  0xc0224eab (handle_scancode+0xab)
         fp=c045dea8 args = 00000045 c00001c8 00000000

INSTALL

Install kernel and kdb:

      linux-2.4.17 kernel
      kdb-v2.1-2.4.17-common-2.bz2
      kdb-v2.1-2.4.17-i386-1.bz2.

Apply this patch.

Run the script "scripts/inline-fix.pl" included in this patch. This changes "extern inline" to "static inline" globally.

Install modutils-2.4.12.tar, and patch it using the file "patch_kallsyms" which was dropped in the kernel tree. Build kallsyms and install.

Enable the "Trace kernel function calls" configuration option.

How to use it.

At the kdb prompt:

tr <offset> Displays the contents of the trace buffer.

trd Default to not collecting trace data
tre <function list> Add functions which should be traced.

tre Default to trace everything
trd <function list> Add function to exception list not to be traced

trp Display trace enable/disable status list of
exceptions.

trc Clear list of functions with tracing explictly
enabled or disabled.

Why change kallsyms?

The symbol table that kallsyms creates doesn't include information for symbols which have several static definitions. This change preserves these local definitions. Using -finstrument-functions means that inline functions get a static version created in every file that calls them.

Multiple symbols with the same name, eh?

With the patch the symbol table now has multiple entries for the same name. It does the right thing for address to name translations but just picks the first entry when it is asked to find an address from a name. It would be nice if kdb could warn when there are multiple defintions for the same symbol.

Oh no not the stupid extern inline thread again...

The -finstrument-functions option generates calls to the functions __cyg_profile_func_enter and __cyg_profile_func_exit for each function passing the address of the function and the caller.
This is done even for inline functions. This results in taking the address of inline functions which would normally always be inlined. For functions declared "extern inline" this results in undefined symbol errors. For "static inline" it causes a static version to be compiled in each object file that uses the inline function. Given this choice, multiple copies beats link errors so the inline-fix.pl script make the global change from extern to static inline.

Why defeat inlining?

With functions inlined and compiled with -finstrument-functions the return address gets confusing. If function 'A' calls 'B' which has 'C' inlined, the trace shows 'C' called by 'A'. I turned of inlining by adding "-fno-inline" in the toplevel makefile. If your are tracing every function call you probably don't get much performance benifit out of inlining anyway.

Why did I do this?

I wrote this code while chasing a bug on an old off-brand laptop which locks up with a combination of X and PCMCIA network cards. I was able to reproduce the problem with the trace running sending the trace data to an unused corner of the video ram (which survives reset). Now I know that the lockup happens in the Xserver sigh:-)

What is the performance impact?

On a 1 GHz. Athlon it doesn't seem slow. I have been running it as my normal kernel for a few weeks. On average it takes 70 cycles per call or return with a trace buffer which fits in cache. E.g. getpid() takes 422 cycle instead of 280. It is painfully slow running on an old pentium with the trace going to real memory.

I hope that others will find this trace mechanism useful. I'm sending this to both the SGI kdb mailing list and the linux kernel mailing list. I hope that it might become a standard part of kdb.

Jim Houston
[email protected]

Documentation/Configure.help +5 -0
diff -urN -X /home/jim/dontdiff linux.orig/Documentation/Configure.help linux/Documentation/Configure.help
@@ -18976,6 +18976,11 @@
   this option. See "man kallsyms" for the data format, it adds 10-20%
   to the size of the kernel and the loaded modules. If unsure, say N.
 
+Trace kernel function calls
+CONFIG_INSTRUMENT_FUNC
+  Compile kernel with -finstrument-functions.  This allows a function
+  level trace of kernel code.
+
 ISDN support
 CONFIG_ISDN
   ISDN ("Integrated Services Digital Networks", called RNIS in France)
Makefile +3 -0
diff -urN -X /home/jim/dontdiff linux.orig/Makefile linux/Makefile
@@ -97,6 +97,9 @@
 ifndef CONFIG_FRAME_POINTER
 CFLAGS += -fomit-frame-pointer
 endif
+ifeq ($(CONFIG_INSTRUMENT_FUNC),y)
+CFLAGS += -finstrument-functions -fno-inline
+endif
 AFLAGS := -D__ASSEMBLY__ $(CPPFLAGS)
 
 #
arch/i386/boot/compressed/misc.c +15 -0
diff -urN -X /home/jim/dontdiff linux.orig/arch/i386/boot/compressed/misc.c linux/arch/i386/boot/compressed/misc.c
@@ -381,3 +381,18 @@
 	if (high_loaded) close_output_buffer_if_we_run_high(mv);
 	return high_loaded;
 }
+
+#ifdef CONFIG_INSTRUMENT_FUNC
+void __cyg_profile_func_enter(void *, void *)
+        __attribute__ ((no_instrument_function));
+void __cyg_profile_func_exit(void *, void *)
+        __attribute__ ((no_instrument_function));                               
+
+void __cyg_profile_func_enter(void *a1, void *a2)
+{
+}
+
+void __cyg_profile_func_exit(void *a1, void *a2)
+{
+}
+#endif
arch/i386/config.in +1 -0
diff -urN -X /home/jim/dontdiff linux.orig/arch/i386/config.in linux/arch/i386/config.in
@@ -419,6 +419,7 @@
       bool '    KDB off by default' CONFIG_KDB_OFF
       comment '  Load all symbols for debugging is required for KDB'
       define_bool CONFIG_KALLSYMS y
+      bool '  Trace kernel function calls' CONFIG_INSTRUMENT_FUNC
    else
       bool '  Load all symbols for debugging' CONFIG_KALLSYMS
    fi
arch/i386/kdb/kdbasupport.c +4 -0
diff -urN -X /home/jim/dontdiff linux.orig/arch/i386/kdb/kdbasupport.c linux/arch/i386/kdb/kdbasupport.c
@@ -1030,6 +1030,8 @@
 }
 
 #ifdef KDB_HAVE_LONGJMP
+int kdba_setjmp(kdb_jmp_buf *jb)
+	__attribute__ ((no_instrument_function));
 int
 kdba_setjmp(kdb_jmp_buf *jb)
 {
@@ -1059,6 +1061,8 @@
 	return 0;
 }
 
+void kdba_longjmp(kdb_jmp_buf *jb, int reason)
+	__attribute__ ((no_instrument_function));
 void
 kdba_longjmp(kdb_jmp_buf *jb, int reason)
 {
drivers/parport/parport_pc.c +6 -0
diff -urN -X /home/jim/dontdiff linux.orig/drivers/parport/parport_pc.c linux/drivers/parport/parport_pc.c
@@ -256,6 +256,11 @@
 	parport_generic_irq(irq, (struct parport *) dev_id, regs);
 }
 
+/*
+ * Actually it cause problems to have both static inline and a
+ * global version.
+ */
+#if 0
 void parport_pc_write_data(struct parport *p, unsigned char d)
 {
 	outb (d, DATA (p));
@@ -343,6 +348,7 @@
 {
 	__parport_pc_frob_control (p, 0x20, 0x20);
 }
+#endif
 
 void parport_pc_init_state(struct pardevice *dev, struct parport_state *s)
 {
include/asm-i386/current.h +2 -0
diff -urN -X /home/jim/dontdiff linux.orig/include/asm-i386/current.h linux/include/asm-i386/current.h
@@ -4,6 +4,8 @@
 struct task_struct;
 
 static inline struct task_struct * get_current(void)
+	__attribute__ ((no_instrument_function));
+static inline struct task_struct * get_current(void)
 {
 	struct task_struct *current;
 	__asm__("andl %%esp,%0; ":"=r" (current) : "0" (~8191UL));
kdb/Makefile +3 -0
diff -urN -X /home/jim/dontdiff linux.orig/kdb/Makefile linux/kdb/Makefile
@@ -2,6 +2,9 @@
 export-objs	:= kdbmain.o kdb_io.o
 obj-y		:= kdb_bt.o kdb_bp.o kdb_id.o kdbsupport.o gen-kdb_cmds.o kdbmain.o kdb_io.o
 
+obj-$(CONFIG_INSTRUMENT_FUNC) += kdb_tr.o
+CFLAGS_kdb_tr.o += -finline
+
 subdir-$(CONFIG_KDB_MODULES) := modules
 obj-y += $(addsuffix /vmlinux-obj.o, $(subdir-y))
 
kdb/kdb_tr.c +601 -0

601 lines not on this page · raw message

kdb/kdb_tr.h +89 -0

89 lines not on this page · raw message

kdb/kdbmain.c +31 -0
diff -urN -X /home/jim/dontdiff linux.orig/kdb/kdbmain.c linux/kdb/kdbmain.c
@@ -91,6 +91,13 @@
 kdb_jmp_buf	kdbjmpbuf[NR_CPUS];
 #endif	/* KDB_HAVE_LONGJMP */
 
+#if defined(CONFIG_INSTRUMENT_FUNC)
+/* Hooks to automaticly disable kernel trace on entry to kdb */
+extern void kdb_trc_disable(void);
+extern void kdb_trc_continue(void);
+extern void kdb_trc_init(void);
+#endif /* CONFIG_INSTRUMENT_FUNC */
+
 	/*
 	 * kdb_commands describes the available commands.
 	 */
@@ -1212,6 +1219,11 @@
 	if (!kdb_on)
 		return 0;
 
+#if defined(CONFIG_INSTRUMENT_FUNC)
+	/* disable kernel trace while in kdb */
+	kdb_trc_disable();
+#endif
+
 	KDB_DEBUG_STATE("kdb 1", reason);
 	KDB_STATE_CLEAR(SUPPRESS);
 
@@ -1228,6 +1240,10 @@
 	if ((reason == KDB_REASON_BREAK || reason == KDB_REASON_DEBUG)
 	 && db_result == KDB_DB_NOBPT) {
 		KDB_DEBUG_STATE("kdb 2", reason);
+		/* re-enable kernel trace */
+#if defined(CONFIG_INSTRUMENT_FUNC)
+		kdb_trc_continue();
+#endif
 		return 0;	/* Not one of mine */
 	}
 
@@ -1305,11 +1321,19 @@
 			}
 			if (!recover) {
 				kdb_printf("     Cannot recover, allowing event to proceed\n");
+				/* re-enable kernel trace */
+#if defined(CONFIG_INSTRUMENT_FUNC)
+				kdb_trc_continue();
+#endif
 				return(0);
 			}
 		}
 	} else if (!KDB_IS_RUNNING()) {
 		kdb_printf("kdb: CPU switch without kdb running, I'm confused\n");
+		/* re-enable kernel trace */
+#if defined(CONFIG_INSTRUMENT_FUNC)
+		kdb_trc_continue();
+#endif
 		return(0);
 	}
 
@@ -1434,6 +1458,10 @@
 
 	KDB_STATE_CLEAR(RECURSE);
 	KDB_DEBUG_STATE("kdb 17", reason);
+	/* re-enable kernel trace */
+#if defined(CONFIG_INSTRUMENT_FUNC)
+	kdb_trc_continue();
+#endif
 	return(result != 0);
 }
 
@@ -2711,6 +2739,9 @@
 #endif
 #if defined(CONFIG_MAGIC_SYSRQ)
 	kdb_register_repeat("sr", kdb_sr, "<key>",	"Magic SysRq key", 0, KDB_REPEAT_NONE);
+#endif
+#if defined(CONFIG_INSTRUMENT_FUNC)
+	kdb_trc_init();
 #endif
 }
 
kernel/ksyms.c +18 -0
diff -urN -X /home/jim/dontdiff linux.orig/kernel/ksyms.c linux/kernel/ksyms.c
@@ -571,3 +571,21 @@
 
 EXPORT_SYMBOL(tasklist_lock);
 EXPORT_SYMBOL(pidhash);
+
+#ifdef CONFIG_INSTRUMENT_FUNC
+extern void __br_lock_usage_bug(void);
+extern void __this_fixmap_does_not_exist(void);
+extern void __cyg_profile_func_enter(void *, void *);
+extern void __cyg_profile_func_exit(void *, void *);
+extern void __trace_user(void *, void *);
+extern void __trace_stop();
+extern void *trcp;
+
+EXPORT_SYMBOL(__br_lock_usage_bug);
+EXPORT_SYMBOL(__this_fixmap_does_not_exist);
+EXPORT_SYMBOL_NOVERS(__cyg_profile_func_enter);
+EXPORT_SYMBOL_NOVERS(__cyg_profile_func_exit);
+EXPORT_SYMBOL(__trace_user);
+EXPORT_SYMBOL(__trace_stop);
+EXPORT_SYMBOL(trcp);
+#endif
patch_kallsyms +35 -0
diff -urN -X /home/jim/dontdiff linux.orig/patch_kallsyms linux/patch_kallsyms
@@ -0,0 +1,35 @@
+--- modutils-2.4.12/obj/obj_kallsyms.c.orig	Thu Jan  4 20:45:19 2001
++++ modutils-2.4.12/obj/obj_kallsyms.c	Tue Jan 15 05:17:43 2002
+@@ -250,6 +250,8 @@
+ 	for (sym = fin->symtab[i]; sym ; sym = sym->next) {
+ 	    if (!sym || sym->secidx >= fin->header.e_shnum)
+ 		continue;
++	    if (ELFW(ST_BIND)(sym->info) == STB_LOCAL)
++		continue;
+ 	    if ((a_sym.section_off = fin_to_allsym_map[sym->secidx]) == -1)
+ 		continue;
+ 	    if (strcmp(sym->name, "gcc2_compiled.") == 0 ||
+@@ -263,6 +265,23 @@
+ 	    append_string(sym->name, &strings, &strings_size, &strings_left);
+ 	    ++a_hdr->symbols;
+ 	}
++    }
++    for (i = 0; i < fin->local_symtab_size; ++i) {
++	struct obj_symbol *sym = fin->local_symtab[i];
++	    if (!sym || sym->secidx >= fin->header.e_shnum)
++		continue;
++	    if ((a_sym.section_off = fin_to_allsym_map[sym->secidx]) == -1)
++		continue;
++	    if (strcmp(sym->name, "gcc2_compiled.") == 0 ||
++		strncmp(sym->name, "__insmod_", 9) == 0)
++		continue;
++	    a_sym.symbol_addr = sym->value;
++	    if (fin->header.e_type == ET_REL)
++		a_sym.symbol_addr += fin->sections[sym->secidx]->header.sh_addr;
++	    a_sym.name_off = strings_size - strings_left;
++	    append_symbol(&a_sym, &symbols, &symbols_size, &symbols_left);
++	    append_string(sym->name, &strings, &strings_size, &strings_left);
++	    ++a_hdr->symbols;
+     }
+     free(fin_to_allsym_map);
+ 
scripts/inline-fix.pl +91 -0

91 lines not on this page · raw message