PATCH - kernel trace mechanism for KDB
Subsystems (3)
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 00000000INSTALL
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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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