Index: linux/Documentation/kfi.txt =================================================================== --- linux.orig/Documentation/kfi.txt 2005-03-24 10:49:44.466757856 -0800 +++ linux/Documentation/kfi.txt 2005-04-08 17:13:00.474314871 -0700 @@ -0,0 +1,342 @@ + Kernel Function Instrumentation + -- a kernel tracing system -- + +Introduction +============ +Kernel Function Instrumentation (KFI) is a kernel function tracing system, +which uses the "-finstrument-functions" capability of the gcc compiler to add +instrumentation callouts to every function entry and exit. The KFI system +provides for capturing these callouts and generating a trace of events, with +timing details. This is about the most intrusive tracing mechanism +imaginable, and WILL screw up timings of precise events and your overall +performance. Thus, KFI is NOT appropriate for use to debug race conditions, +measure scheduler performance, etc. + +However, KFI is excellent at providing a good timing overview of straightline +procedures, allowing you to see where time is spent in functions and +sub-routines in the kernel. This is similar to what oprofile is used for. +However, the major differences between profiling and KFI are that 1) KFI is +(IMNSHO) easier to set up and use (e.g. this version of KFI requires no +special user-space program to be compiled for the target), and 2) KFI shows +you exactly what happens on a particular run of the kernel, rather than giving +you statistics of what happens on average during kernel operation. + +The main mode of operation with KFI is to use the system with a dynamic trace +configuration. That is, you can set a trace configuration after kernel +startup, using the /proc/kfi interface, and retrieve trace data immediately. +However, another (special) mode of operation is available, called STATIC_RUN +mode, where the configuration for a KFI run is configured and compiled +statically into the kernel. This mode is useful for getting a trace of kernel +operation during system bootup (before user space is running). + +The KFI configuration lets you specify how to automatically start and stop a +trace, whether to include interrupts as part of the trace, and whether to +filter the trace data by various criteria (for minimum function duration, only +certain listed functions, etc.) KFI trace data is retrieved by reading from +/proc/kfi_trace after the trace is complete. + +Finally, tools are supplied to convert numeric trace data to kernel symbols, +and to process and analyze the data in a KFI trace. + +Quick overview for using KFI in regular mode: + - compile your kernel with support for KFI + - boot the kernel + - write a configuration to /proc/kfi + - start the trace + - read the trace data from /proc/kfi_trace + - process the data + - use scripts/addr2sym to convert addresses to function names + - use scripts/kd to analyze trace data + +Quick overview for using KFI in STATIC_RUN mode: + - edit the configuration in kernel/kfistatic.conf + - compile your kernel with support for KFI (and KFI_STATIC_RUN) + - boot the kernel (the run should be triggered during bootup) + - read the trace data from /proc/kfi_trace + - process the data + - use scripts/addr2sym to convert addresses to function names + - use scripts/kd to analyze trace data + +Compiling the kernel for using KFI +================================== +Set the following in your kernel .config: + +CONFIG_KFI=y +CONFIG_KFI_STATIC_RUN=y + +Under 'make menuconfig' these options on are the "Kernel Hacking" +menu. + +If you are doing a STATIC_RUN, edit the file kernel/kfistatic.conf (if +desired) to change time filters, triggers, etc. + +Build the kernel, and install it to boot on your target machine. + +Save the System.map file from this build, as it will be +used later to resolve function addresses to function names. + +Initiate a KFI run +================== +If you are running in STATIC_RUN mode, upon booting the +kernel, the trace should be run (depending on the trigger +and filter settings in kernel/kfistatic.conf). + +If you are running in normal mode, then boot the kernel, +and initiate a run by writing a KFI configuration to +/proc/kfi. + +You can get the status of the current trace by reading /proc/kfi + +Traces go through a state transition in order to actually +start collecting data. This is to allow trace collection to +be separated from trace setup and preparation. The trace +configuration specifies a start trigger, which will initiate +the collection of data. When the configuration is written +to KFI, it is not ready to run yet. Making the trace ready +to run is called "priming" it. + +Therefore, the normal sequence of events for a trace run is: + 1. the user writes the configuration to KFI (via /proc/kfi) + 2. the user prepares for trace (if necessary) + 3. the user primes the trace + * echo "prime" >/proc/kfi + 4. a kernel event occurs which starts the trace (the start trigger fires) + 5. trace data is collected + 6. a kernel event (or buffer exhaustion) stops the trace (the stop trigger + fires, or the buffer runs out) + +It is possible to force the start or end of a trace using the /proc/kfi +interface. This overrides steps 4 or 6, which are normally performed by +triggers in the trace configuration. + To manually start a trace: echo "start" >/proc/kfi + To manually stop a trace: echo "stop" >/proc/kfi + +To see the status of the currently configured trace: + * cat /proc/kfi + +Read the KFI data +================= +When the trace is running, the trace data is accumulated in a buffer inside +the kernel. Once the trace data is collected, it is retrieved by reading +/proc/kfi_trace. Usually, you will want to save the data to a file for +later analysis. + + * cat /proc/kfi_trace > /tmp/kfi.log + +Process the data +================ +Copy the kfi.log file from the target to your host development +system (on which the kernel source resides), for example, into the +/tmp directory. + +The raw kfi.log file will only have numeric function addresses +To translate these addresses to symbols, use the System.map file +from your previous kernel build. + +cd to your kernel source top-level directory and run scripts/addr2sym to +translate addresses to symbols: + +$ scripts/addr2sym /tmp/kfi.log -m System.map > /tmp/kfi.lst + +An example fragment of output from addr2sym on a TI OMAP Innovator, +Entry and Delta value are times in microseconds (time since boot and +time spent between function entry and exit, respectively)... + +************************* + Entry Delta PID Function Called At +-------- -------- ----- ------------------------- -------------------------- + 23662 1333 0 con_init console_init+0x78 + 25375 209045 0 calibrate_delay start_kernel+0xf0 + 234425 106067 0 mem_init start_kernel+0x130 + 234432 105278 0 free_all_bootmem_node mem_init+0xc8 + 234435 105270 0 free_all_bootmem_core free_all_bootmem_node+0x28 + 340498 4005 0 kmem_cache_sizes_init start_kernel+0x134 +************************* + +In the above, calibrate_delay took about 209 msecs. + +mem_init took 106 msecs, the majority of which (105 msecs) was in +free_all_bootmem_core (which is called by free_all_bootmem_node, which +is called by mem_init). + +The large time consumers can often be pinpointed by looking for leaps +in the entry times in the Entry column, as shown above. + +CPU-yielding functions like schedule_timeout, switch_to, kernel_thread, +etc. can have large Delta values due intervening scheduling activity, +but these can often be quickly filtered out by following the "leaps +in the entry times in the Entry column" above. + +A sample of name-resolved kfi output is provided with this +distribution, in the file "kfisample.lst". + +Analyzing data with kd +====================== + +You can use the program "kd" to further process the data. (It is very helpful +at this point to have resolved the names of the functions in the log file, but +it is not strictly necessary.) This function reads a KFI log file and +determines the time spent locally in a function versus the time spent in +sub-routines. It sorts the functions by the total time spent in the function, +and can display various extra pieces of information about each function +(number of times called, average call time, etc.) + +Use "./kd -h" for more usage help. + +As of this writing, KFI and kd do not correctly account for scheduling +jumps. The time reported by kfi for function duration is just wall +time from entry to exit. I'm working on a new routine to account +for gaps caused by scheduling intermediary processes, but it's not +done yet. + +For examples of what kd can show, try the following commands +on the sample kfi output file: + +[show all functions sorted by time] +$ ./kd kfisample.lst | less + +[show only 10 top time-consuming functions] +$ ./kd -c 10 kfisample.lst + +[show only functions lasting longer than 100 milliseconds] +$ ./kd -t 100000 kfisample.lst + +[show each function's most time-consuming child, and the number +of times it was called. (You may want to make your terminal +wider for this output.)] +$ ./kd -f Fcatlmn sample.lst + +=========================================================== + +KFI configuration language +========================== +This is the configuration language supported for kfistatic.conf, and +by /proc/kfi. + +The configuration for a single run is inside a block that starts with 'begin' +and ends with 'end'. Inside the block are triggers, filters, and +miscellaneous entries. When writing the configuration to /proc/kfi, +then the keyword "new" should appear before the block 'begin' keyword. + +triggers +-------- + either "start" or "stop", and then one of: + entry + exit + time +syntax: +trigger start|stop entry|exit|time + +Start time is relative to booting. Stop time is relative to +trace start time. + +filters +------- + maxtime + mintime + noints + onlyints + funclist fend + +syntax: +filter noints|onlyints|maxtime|mintime|funclist fend + +The funclist specifies a list of functions which will be traced. +When a funclist is specified, only those functions are traced, and +all other functions are ignored. + +When specifying a configuration via /proc/kfi, the 'fend' keyword +must be used to indicated the end of the function list. When the +configuration is specified via kfistatic.conf, no 'fend' keyword +should be used. + +miscellaneous +------------- +logsize + specify the size of the log for this run + +# other options that may be supported in the future: +# +# autorepeat +# Repeat trace indefinitely. That is, on trace trigger stop, prime the trace +# to run again, but leave the data in the buffer. Trace will stop autorepeating +# if the trace is NOT in overwrite mode, and the buffer becomes full. + +# overwrite +# Overwrite old data in the trace buffer. This converts the trace buffer to +# a circular buffer, and does not stop the trace when the buffer becomes full. +# In overwrite mode, the end of the trace is available if the buffer is +# not large enough to hold the entire trace. In NOT overwrite mode (regular +# mode) the beginning of the trace is available if the buffer is not large +# enough to hold the entire trace. + +# untimed +# Do not time function duration. Normally, the log contains only function +# entry events, with the start time and duration of the function. In +# untimed mode, the log contains entry AND exit events, with the start +# time for each event. Calculation of function duration must be done by +# a log post-processing tool. + +# prime +# Immediately prime the trace for execution. "Priming" a trace means making +# it ready to run. A trace loaded without the "prime" command will not be +# enabled until the user issues a separate "prime" command through the +# /proc interface. + +# prime entry ?? +# primt exit ?? +# prime time ?? + +Configuration Samples (used with /proc/kfi) +=============================================== +# record all functions longer that 500 microseconds, during bootup +# don't worry about interrupts +new +begin + trigger start entry start_kernel + trigger stop exit to_userspace + filter maxtime 500 + filter mintime 0 + filter noints +end + +# record short routines called by do_fork +# use a small log +new +begin + trigger start entry do_fork + trigger stop exit do_fork + filter maxtime 400 + filter mintime 10 + filter noints + logsize 100 +end + +# record interrupts for 5 milliseconds, starting 5 seconds after booting +new +begin + trigger start time 5000000 + trigger stop time 5000 + filter onlyints +end + +# record all calls to schedule after 10 seconds +new +begin + trigger start time 10000000 + filter funclist schedule fend +end + +To do list: + * should support TIMED or UNTIMED traces. + (current mode is equivalent to TIMED mode) + in untimed mode, you get both entry and exit events, and + only start time for each event - duration can be calculated in + postprocessing + - also, in untimed mode, you cannot use a time filter + in timed mode, you only get entry events, with start time and duration + * add: tracetype timed|untimed + * modify kd to support untimed mode + * should support traces that auto-repeat until a secondary trigger + * good for catching calltraces from a single routine, multiple times + * write new script 'kt' to generate call tree from a (timed trace) log Index: linux/Makefile =================================================================== --- linux.orig/Makefile 2005-04-08 12:11:43.930295791 -0700 +++ linux/Makefile 2005-04-08 12:11:44.392249574 -0700 @@ -524,6 +524,10 @@ CFLAGS += -fomit-frame-pointer endif +ifdef CONFIG_KFI +CFLAGS += -finstrument-functions +endif + ifdef CONFIG_DEBUG_INFO CFLAGS += -g endif Index: linux/arch/arm/Kconfig.debug =================================================================== --- linux.orig/arch/arm/Kconfig.debug 2005-04-08 12:11:44.188269982 -0700 +++ linux/arch/arm/Kconfig.debug 2005-04-08 12:11:44.392249574 -0700 @@ -105,4 +105,22 @@ The uncompressor code port configuration is now handled by CONFIG_S3C2410_LOWLEVEL_UART_PORT. +config KFI + bool "Kernel Function Instrumentation" + help + Say Y here to turn on kernel function instrumentation. + FIXTHIS - need more help here + Say N here if you are unsure. + +config KFI_STATIC_RUN + bool "Static Instrumentation Configs" + depends on KFI + help + Say Y here to compile the KFI configuration statically + into the kernel. This is needed if you plan to use KFI + to get information about function timings on kernel bootup + (prior to the kernel starting user space). To do this, you + need to put a valid kfistatic.conf file in the directory + drivers/char. + endmenu Index: linux/arch/arm/boot/compressed/Makefile =================================================================== --- linux.orig/arch/arm/boot/compressed/Makefile 2005-04-08 12:11:43.741314697 -0700 +++ linux/arch/arm/boot/compressed/Makefile 2005-04-08 12:11:44.392249574 -0700 @@ -79,7 +79,7 @@ targets := vmlinux vmlinux.lds piggy.gz piggy.o $(FONT) \ head.o misc.o $(OBJS) -EXTRA_CFLAGS := -fpic +EXTRA_CFLAGS := -fpic -fno-instrument-functions EXTRA_AFLAGS := # Supply ZRELADDR, INITRD_PHYS and PARAMS_PHYS to the decompressor via Index: linux/arch/i386/Kconfig.debug =================================================================== --- linux.orig/arch/i386/Kconfig.debug 2005-04-08 12:10:40.463645555 -0700 +++ linux/arch/i386/Kconfig.debug 2005-04-08 12:11:44.393249474 -0700 @@ -65,4 +65,36 @@ depends on X86_LOCAL_APIC && !X86_VISWS default y +config KFI + bool "Kernel Function Instrumentation" + help + Say Y here to turn on kernel function instrumentation. + FIXTHIS - need more help here + Say N here if you are unsure. + +config KFI_STATIC_RUN + bool "Static Instrumentation Configs" + depends on KFI + help + Say Y here to compile the KFI configuration statically + into the kernel. This is needed if you plan to use KFI + to get information about function timings on kernel bootup + (prior to the kernel starting user space). To do this, you + need to put a valid kfistatic.conf file in the directory + drivers/char. + +config KFI_CLOCK_SCALE + int "Scaling factor for early initialization of kfi clock" + depends on KFI + default 0 + help + Enter the number used for clock scaling early in the machine + bootup sequence. This is required on many platforms in order + for KFI to work correctly before time_init(). You need to investigate + your kernel source to find out what data element or routine this + number is used with, and experiment to find the correct value to + use here. + + If unsure what to do, leave as 0! + endmenu Index: linux/arch/i386/boot/compressed/Makefile =================================================================== --- linux.orig/arch/i386/boot/compressed/Makefile 2005-04-08 12:10:40.462645655 -0700 +++ linux/arch/i386/boot/compressed/Makefile 2005-04-08 12:11:44.393249474 -0700 @@ -6,6 +6,9 @@ targets := vmlinux vmlinux.bin vmlinux.bin.gz head.o misc.o piggy.o EXTRA_AFLAGS := -traditional +ifdef CONFIG_KFI +EXTRA_CFLAGS := -fno-instrument-functions +endif LDFLAGS_vmlinux := -Ttext $(IMAGE_OFFSET) -e startup_32 Index: linux/arch/i386/kernel/timers/timer_tsc.c =================================================================== --- linux.orig/arch/i386/kernel/timers/timer_tsc.c 2005-04-08 12:10:40.462645655 -0700 +++ linux/arch/i386/kernel/timers/timer_tsc.c 2005-04-08 12:11:44.393249474 -0700 @@ -64,7 +64,7 @@ static unsigned long cyc2ns_scale; #define CYC2NS_SCALE_FACTOR 10 /* 2^10, carefully chosen */ -static inline void set_cyc2ns_scale(unsigned long cpu_mhz) +extern void set_cyc2ns_scale(unsigned long cpu_mhz) { cyc2ns_scale = (1000 << CYC2NS_SCALE_FACTOR)/cpu_mhz; } Index: linux/arch/ppc/Kconfig.debug =================================================================== --- linux.orig/arch/ppc/Kconfig.debug 2005-04-08 12:11:44.346254176 -0700 +++ linux/arch/ppc/Kconfig.debug 2005-04-08 12:11:44.393249474 -0700 @@ -46,4 +46,22 @@ depends on IBM_OCP || FSL_OCP || XILINX_OCP default y +config KFI + bool "Kernel Function Instrumentation" + help + Say Y here to turn on kernel function instrumentation. + FIXTHIS - need more help here + Say N here if you are unsure. + +config KFI_STATIC_RUN + bool "Static Instrumentation Configs" + depends on KFI + help + Say Y here to compile the KFI configuration statically + into the kernel. This is needed if you plan to use KFI + to get information about function timings on kernel bootup + (prior to the kernel starting user space). To do this, you + need to put a valid kfistatic.conf file in the directory + drivers/char. + endmenu Index: linux/arch/ppc/boot/Makefile =================================================================== --- linux.orig/arch/ppc/boot/Makefile 2005-04-08 12:10:40.461645755 -0700 +++ linux/arch/ppc/boot/Makefile 2005-04-08 12:11:44.394249374 -0700 @@ -13,6 +13,10 @@ CFLAGS += -fno-builtin -D__BOOTER__ -Iarch/$(ARCH)/boot/include HOSTCFLAGS += -Iarch/$(ARCH)/boot/include +ifdef CONFIG_KFI +EXTRA_CFLAGS := -fno-instrument-functions +endif + BOOT_TARGETS = zImage zImage.initrd znetboot znetboot.initrd bootdir-y := simple Index: linux/arch/ppc/boot/common/Makefile =================================================================== --- linux.orig/arch/ppc/boot/common/Makefile 2005-04-08 12:10:40.461645755 -0700 +++ linux/arch/ppc/boot/common/Makefile 2005-04-08 12:11:44.394249374 -0700 @@ -7,6 +7,9 @@ # # Tom Rini January 2001 # +ifdef CONFIG_KFI +EXTRA_CFLAGS := -fno-instrument-functions +endif lib-y := string.o util.o misc-common.o \ serial_stub.o bootinfo.o Index: linux/arch/ppc/boot/lib/Makefile =================================================================== --- linux.orig/arch/ppc/boot/lib/Makefile 2005-04-08 12:10:40.461645755 -0700 +++ linux/arch/ppc/boot/lib/Makefile 2005-04-08 12:11:44.394249374 -0700 @@ -5,6 +5,10 @@ CFLAGS_kbd.o := -Idrivers/char CFLAGS_vreset.o := -I$(srctree)/arch/ppc/boot/include +ifdef CONFIG_KFI +EXTRA_CFLAGS := -fno-instrument-functions +endif + zlib := infblock.c infcodes.c inffast.c inflate.c inftrees.c infutil.c lib-y += $(zlib:.c=.o) div64.o Index: linux/arch/ppc/boot/simple/Makefile =================================================================== --- linux.orig/arch/ppc/boot/simple/Makefile 2005-04-08 12:10:40.461645755 -0700 +++ linux/arch/ppc/boot/simple/Makefile 2005-04-08 12:11:44.394249374 -0700 @@ -21,6 +21,10 @@ # XXX_memory.o file for this to work, as well as editing the # misc-$(CONFIG_MACHINE) variable. +ifdef CONFIG_KFI +EXTRA_CFLAGS := -fno-instrument-functions +endif + boot := arch/ppc/boot common := $(boot)/common utils := $(boot)/utils Index: linux/fs/proc/proc_misc.c =================================================================== --- linux.orig/fs/proc/proc_misc.c 2005-04-08 12:10:40.468645055 -0700 +++ linux/fs/proc/proc_misc.c 2005-04-08 12:11:44.395249274 -0700 @@ -512,6 +512,21 @@ return proc_calc_metrics(page, start, off, count, eof, len); } +#ifdef CONFIG_KFI +extern struct seq_operations kfi_trace_op; +static int kfi_trace_open(struct inode *inode, struct file *file) +{ + return seq_open(file, &kfi_trace_op); +} +static struct file_operations proc_kfi_trace_operations = { + .open = kfi_trace_open, + .read = seq_read, + .llseek = seq_lseek, + .release = seq_release, +}; +#endif + + #ifdef CONFIG_MAGIC_SYSRQ /* * writing 'C' to /proc/sysrq-trigger is like sysrq-C @@ -591,6 +606,9 @@ #ifdef CONFIG_SCHEDSTATS create_seq_entry("schedstat", 0, &proc_schedstat_operations); #endif +#ifdef CONFIG_KFI + create_seq_entry("kfi_trace", 0, &proc_kfi_trace_operations); +#endif #ifdef CONFIG_PROC_KCORE proc_root_kcore = create_proc_entry("kcore", S_IRUSR, NULL); if (proc_root_kcore) { @@ -599,6 +617,7 @@ (size_t)high_memory - PAGE_OFFSET + PAGE_SIZE; } #endif + #ifdef CONFIG_MAGIC_SYSRQ entry = create_proc_entry("sysrq-trigger", S_IWUSR, NULL); if (entry) Index: linux/include/asm-ppc/delay.h =================================================================== --- linux.orig/include/asm-ppc/delay.h 2005-04-08 12:10:40.467645155 -0700 +++ linux/include/asm-ppc/delay.h 2005-04-08 12:11:44.395249274 -0700 @@ -2,6 +2,7 @@ #ifndef _PPC_DELAY_H #define _PPC_DELAY_H +#include /* for inline weirdness */ #include /* Index: linux/include/asm-ppc/processor.h =================================================================== --- linux.orig/include/asm-ppc/processor.h 2005-04-08 12:10:40.467645155 -0700 +++ linux/include/asm-ppc/processor.h 2005-04-08 17:11:50.893248810 -0700 @@ -10,6 +10,7 @@ #include #include +#include /* for inline weirdness */ #include #include Index: linux/include/linux/init.h =================================================================== --- linux.orig/include/linux/init.h 2005-04-08 12:10:40.467645155 -0700 +++ linux/include/linux/init.h 2005-04-08 12:11:44.396249174 -0700 @@ -229,6 +229,14 @@ #define __devexitdata __exitdata #endif +#ifndef __ASSEMBLY__ +#define __instrument +#define __noinstrument __attribute__ ((no_instrument_function)) +#ifdef CONFIG_KFI +extern int kfi_dump_log(char* buf); +#endif +#endif + /* Functions marked as __devexit may be discarded at kernel link time, depending on config options. Newer versions of binutils detect references from retained sections to discarded sections and flag an error. Pointers to Index: linux/include/linux/kfi.h =================================================================== --- linux.orig/include/linux/kfi.h 2005-03-24 10:49:44.466757856 -0800 +++ linux/include/linux/kfi.h 2005-04-08 12:11:44.396249174 -0700 @@ -0,0 +1,83 @@ +#ifndef _LINUX_KFI_H +#define _LINUX_KFI_H + +#define KFI_MODE_TIMED 0x01 +#define KFI_MODE_AUTO_REPEAT 0x02 +#define KFI_MODE_STOP_ON_FULL 0x04 + +typedef struct kfi_entry { + void *va; /* VA of instrumented function */ + void *call_site; /* where this func was called */ + unsigned long time; /* function entry time since trigger start time, + in usec */ + unsigned long delta; /* delta time from entry to exit, in usec */ + int pid; +} kfi_entry_t; + +#define INTR_CONTEXT -1 + +#define TRIGGER_START_ON_ENTRY 0x01 +#define TRIGGER_START_ON_EXIT 0x02 +#define TRIGGER_STOP_ON_ENTRY 0x04 +#define TRIGGER_STOP_ON_EXIT 0x08 + +typedef enum kfi_trigger_type { + TRIGGER_NONE = 0, + TRIGGER_TIME, + TRIGGER_FUNC_ENTRY, + TRIGGER_FUNC_EXIT, + TRIGGER_PROC, + TRIGGER_USER, + TRIGGER_LOG_FULL +} kfi_trigger_type_t; + +typedef struct kfi_trigger { + enum kfi_trigger_type type; + union { + unsigned long time; // time since boot, in usec + void * func_addr; + }; + unsigned long mark; // time at which this trigger occured +} kfi_trigger_t; + +#define MAX_RUN_LOG_ENTRIES 10000 +#define MAX_FUNC_LIST_ENTRIES 512 + +typedef struct kfi_filters { + unsigned long min_delta; + unsigned long max_delta; + int no_ints; + int only_ints; + void** func_list; + int func_list_size; + struct { + int delta; + int no_ints; + int only_ints; + int func_list; + } cnt; +} kfi_filters_t; + +typedef struct kfi_run { + int primed; /* is this run ready to start */ + int triggered; /* has this run started */ + int complete; /* has this run ended */ + int flags; + /* int trigger_flag; */ + struct kfi_trigger start_trigger; + struct kfi_trigger stop_trigger; + struct kfi_filters filters; + struct kfi_entry* log; + int num_entries; + int next_entry; + int id; + int notfound; +} kfi_run_t; + +#if CONFIG_KFI_CLOCK_SCALE +extern void setup_early_kfi_clock(void); +#else +#define setup_early_kfi_clock() +#endif + +#endif // _LINUX_KFI_H Index: linux/include/linux/preempt.h =================================================================== --- linux.orig/include/linux/preempt.h 2005-04-08 12:10:40.467645155 -0700 +++ linux/include/linux/preempt.h 2005-04-08 12:11:44.396249174 -0700 @@ -8,9 +8,10 @@ #include #include +#include #ifdef CONFIG_DEBUG_PREEMPT - extern void fastcall add_preempt_count(int val); + extern void fastcall __noinstrument add_preempt_count(int val); extern void fastcall sub_preempt_count(int val); #else # define add_preempt_count(val) do { preempt_count() += (val); } while (0) Index: linux/init/main.c =================================================================== --- linux.orig/init/main.c 2005-04-08 12:10:40.466645255 -0700 +++ linux/init/main.c 2005-04-08 17:11:27.393590600 -0700 @@ -46,6 +46,7 @@ #include #include #include +#include #include #include @@ -421,6 +422,7 @@ * Interrupts are still disabled. Do necessary setups, then * enable them */ + setup_early_kfi_clock(); lock_kernel(); page_address_init(); printk(linux_banner); @@ -514,6 +516,7 @@ rest_init(); } + static int __initdata initcall_debug; static int __init initcall_debug_setup(char *str) @@ -622,6 +625,12 @@ #endif } +#ifdef CONFIG_KFI_STATIC_RUN +void to_userspace(void) +{ +} +#endif /* CONFIG_KFI_STATIC_RUN */ + static int init(void * unused) { lock_kernel(); @@ -676,6 +685,11 @@ (void) sys_dup(0); (void) sys_dup(0); + +#ifdef CONFIG_KFI_STATIC_RUN + /* This is a stub function, for use as a stop trigger */ + to_userspace(); +#endif /* CONFIG_KFI_STATIC_RUN */ /* * We try each of these until one succeeds. Index: linux/kernel/Makefile =================================================================== --- linux.orig/kernel/Makefile 2005-04-08 12:11:43.952293590 -0700 +++ linux/kernel/Makefile 2005-04-08 17:15:21.536257497 -0700 @@ -26,6 +26,8 @@ obj-$(CONFIG_KPROBES) += kprobes.o obj-$(CONFIG_KGDB) += kgdb.o obj-$(CONFIG_SYSFS) += ksysfs.o +obj-$(CONFIG_KFI) += kfi.o +obj-$(CONFIG_KFI_STATIC_RUN) += kfistatic.o obj-$(CONFIG_GENERIC_HARDIRQS) += irq/ ifneq ($(CONFIG_IA64),y) @@ -50,3 +52,11 @@ targets += config_data.h $(obj)/config_data.h: $(obj)/config_data.gz FORCE $(call if_changed,ikconfiggz) + +# Files generated that shall be removed upon make clean +clean-files := kfistatic.c + +$(obj)/kfistatic.o: $(obj)/kfistatic.c + +$(obj)/kfistatic.c: $(src)/kfistatic.conf + $(srctree)/scripts/mkkfirun.pl $< > $@ Index: linux/kernel/kfi.c =================================================================== --- linux.orig/kernel/kfi.c 2005-03-24 10:49:44.466757856 -0800 +++ linux/kernel/kfi.c 2005-04-08 17:12:50.151343586 -0700 @@ -0,0 +1,1286 @@ +/* + * kernel/kfi.c + * + * Kernel Function Instrumentation + * + * Copyright (C) 2002 MontaVista Software + * Copyright 2005 Sony Corporation + * + * Support for Function Instrumentation/Profiling feature of + * GCC (-finstrument-functions). + */ + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + + +#define COMMAND_BUFFER_LEN 2048 + +#ifdef CONFIG_KFI_STATIC_RUN +extern struct kfi_run kfi_run0; +static struct kfi_run* run_curr = &kfi_run0; +#else +int kfi_run0; +static struct kfi_run* run_curr = 0; +#endif + +static int in_entry_exit = 0; + +//static spinlock_t kfi_lock = SPIN_LOCK_UNLOCKED; +DECLARE_WAIT_QUEUE_HEAD(kfi_wait); + +#define GENERIC_KFIREADCLOCK 1 + +#ifndef GENERIC_KFIREADCLOCK +/* + * Use arch-specific kfi_readclock() and kfi_clock_to_usecs() routines + */ + +/* + * !! Set the following for your machine!! + * + * CLOCK_FREQ is a hardcoded value for the frequency of + * whatever clock you are using for kfi_readclock() + * It would be nice to use a probed clock freq (cpu_hz) + * here, but it isn't set early enough for some boot + * measurements. + * Hint: for x86, boot once and look at /proc/cpuinfo + */ +// Tim's old laptop +//#define CLOCK_FREQ 645206000ULL +// Tim's HP desktop +//#define CLOCK_FREQ 2992332000ULL +// Ebony board +#define CLOCK_FREQ 400000000ULL + +/* + * CLOCK_SHIFT is used to bring the clock frequency into + * a manageable range. For my 3 GHz machine, I decided + * to divide the cpu cycle clock by 8. This throws + * away some clock precision, but makes some of the + * other math faster and helps us stay in 32 bits. + */ +#define CLOCK_SHIFT 3 + +/* + * This weird scaling makes it possible to use shifts instead + * of divisions, for the conversion to microseconds + */ +#define CLOCK_SCALE (((CLOCK_FREQ*1000000)/(1024*1024))>>CLOCK_SHIFT) + +#ifdef CONFIG_X86_TSC +#include /* for rdtscll macro */ +static inline unsigned long kfi_readclock(void) +{ + unsigned long long ticks; + + rdtscll(ticks); + return (unsigned long)((ticks>>CLOCK_SHIFT) & 0xffffffff); +} +#endif + +#if defined(CONFIG_PPC32) +#include /* for get_tbu macro */ +/* copied from sched_clock for ppc */ +static inline unsigned long kfi_readclock(void) +{ + unsigned long lo, hi, hi2; + unsigned long long ticks; + + do { + hi = get_tbu(); + lo = get_tbl(); + hi2 = get_tbu(); + } while (hi2 != hi); + ticks = ((unsigned long long) hi << 32) | lo; + return (unsigned long)((ticks>>CLOCK_SHIFT) & 0xffffffff); +} +#endif + +static inline unsigned long kfi_clock_to_usecs(unsigned long clock) +{ + /* math to stay in 32 bits. Try to avoid over and underflows */ + if (clock<4096) + return (clock<<20)/CLOCK_SCALE; + if (clock<(4096<<5)) + return (clock<<15)/(CLOCK_SCALE>>5); + if (clock<(4096<<10)) + return (clock<<10)/(CLOCK_SCALE>>10); + if (clock<(4096<<15)) + return (clock<<5)/(CLOCK_SCALE>>15); + else + return clock/(CLOCK_SCALE>>20); +} +#endif + +#ifdef GENERIC_KFIREADCLOCK +/* + * Define a genefic kfi_readclock routine. + * This should work well enough for platforms where sched_clock() + * gives good (sub-microsecond) precision. + * + * There are valid reasons to use other routines, including: + * - when using kfi for boot timings + * - on most platforms, sched_clock() does not work correctly until + * after time_init() + * - reduced overhead for obtaining a microsecond value + * (This may be incorrect, since at most this adds one + * 64-bit-by-32-bit divide, in addition to the shift that + * is inside sched_clock(). KFI does enough other stuff + * that this one divide is not probably not a major factor + * in kfi overhead.) + */ +static inline unsigned long __noinstrument kfi_readclock(void) +{ + unsigned long long t; + + t = sched_clock(); + /* convert to microseconds */ + do_div(t,1000); + return (unsigned long)t; +} + +static inline unsigned long __noinstrument kfi_clock_to_usecs(unsigned long clock) +{ + return clock; +} + + +#if CONFIG_KFI_CLOCK_SCALE +extern void set_cyc2ns_scale(unsigned long cpu_mhz); + +/* + * Do whatever is required to prepare for calling sched_clock very + * early in the boot sequence. + */ +extern void setup_early_kfi_clock(void) +{ + set_cyc2ns_scale(CONFIG_KFI_CLOCK_SCALE); +} +#endif /* CONFIG_KFI_CLOCK_SCALE */ + +#endif /* GENERIC_KFI_READCLOCK */ + +static unsigned long usecs_since_boot = 0; +static unsigned long last_machine_cycles = 0; + +static inline unsigned long __noinstrument update_usecs_since_boot(void) +{ + unsigned long machine_cycles, delta; + + machine_cycles = kfi_readclock(); + delta = machine_cycles - last_machine_cycles; + delta = kfi_clock_to_usecs(delta); + /* + * check for clock going backwards - this may happen + * because the clock is reset during startup + * initialization of the timer. + * In this case, we lose the correct value for this + * entry - but that's better than moving usecs_since_boot + * backwards and causing negative durations in the log. + */ + if (delta > 0x8000000) { + delta = 0; + } + usecs_since_boot += delta; + + last_machine_cycles = machine_cycles; + return usecs_since_boot; +} + +static inline struct kfi_entry* __noinstrument new_entry(struct kfi_run* run) +{ + struct kfi_entry* entry; + + if (run->next_entry >= run->num_entries) + return NULL; + + entry = &run->log[run->next_entry]; + run->next_entry++; + return entry; +} + + +static inline int __noinstrument find_entry(struct kfi_run* run, void *this_fn, + unsigned int pid) +{ + int i; + + for (i = run->next_entry-1; i >= 0; i--) { + struct kfi_entry* entry = &run->log[i]; + if (entry->va == this_fn && + entry->pid == pid && + entry->delta == 0) + return i; + } + + return -1; +} + + +static inline void __noinstrument free_entry(struct kfi_run* run, int loc) +{ + int i; + run->next_entry--; + for (i = loc; i < run->next_entry; i++) + run->log[i] = run->log[i+1]; +} + + +static inline int __noinstrument in_func_list(struct kfi_filters* filters, + void* func) +{ + int i; + + for (i=0; i < filters->func_list_size; i++) { + if (filters->func_list[i] == func) + return 1; + } + + return 0; +} + +/* + * filter_out: return 1 if function should NOT be logged + * Can be because function is NOT on the filter list, or because + * of context (interrupt or not) + */ +static inline int __noinstrument filter_out(struct kfi_filters* filters, + void *this_fn) +{ + int in_intr; + + if (filters->func_list && !in_func_list(filters, this_fn)) { + filters->cnt.func_list++; + return 1; + } + + in_intr = in_interrupt(); + + if (filters->no_ints && in_intr) { + filters->cnt.no_ints++; + return 1; + } + + if (filters->only_ints && !in_intr) { + filters->cnt.only_ints++; + return 1; + } + + return 0; +} + + +static inline void __noinstrument do_func_entry(struct kfi_run* run, void *this_fn, + void *call_site) +{ + struct kfi_entry* entry; + + if (!(entry = new_entry(run))) { + run->complete = 1; + run->stop_trigger.mark = update_usecs_since_boot(); + run->stop_trigger.type = TRIGGER_LOG_FULL; + return; + } + + entry->va = this_fn; + entry->call_site = call_site; + entry->pid = in_interrupt() ? INTR_CONTEXT : current->pid; + + entry->delta = 0; + entry->time = update_usecs_since_boot() - run->start_trigger.mark; +} + +static inline void __noinstrument do_func_exit(struct kfi_run* run, void *this_fn, + void *call_site) +{ + struct kfi_entry* entry; + unsigned long exittime; + unsigned long delta; + int entry_i; + + if ((entry_i = find_entry(run, this_fn, in_interrupt() ? + INTR_CONTEXT : current->pid)) < 0) { + run->notfound++; + return; + } + + entry = &run->log[entry_i]; + + // calc delta + exittime = update_usecs_since_boot() - run->start_trigger.mark; + delta = exittime - entry->time; + + if ((run->filters.min_delta && delta < run->filters.min_delta) || + (run->filters.max_delta && delta > run->filters.max_delta)) { + run->filters.cnt.delta++; + free_entry(run, entry_i); + } else { + entry->delta = delta; + } +} + + +static inline int __noinstrument test_trigger(struct kfi_run* run, int start_trigger, + int func_entry, void* func_addr) +{ + unsigned long time, base_time; + int ret = 0; + struct kfi_trigger* t; + + t = start_trigger ? &run->start_trigger : &run->stop_trigger; + + switch (t->type) { + case TRIGGER_TIME: + time = update_usecs_since_boot(); + if (start_trigger) { + /* trigger start time based from boot */ + base_time = 0; + } else { + /* trigger stop time based from start trigger time */ + base_time = run->start_trigger.mark; + } + + if (time >= base_time + t->time) { + t->mark = time; // mark trigger time + ret = 1; + } + break; + case TRIGGER_FUNC_ENTRY: + if (func_entry && func_addr == t->func_addr) { + time = update_usecs_since_boot(); + t->mark = time; // mark trigger time + ret = 1; + } + break; + case TRIGGER_FUNC_EXIT: + if (!func_entry && func_addr == t->func_addr) { + time = update_usecs_since_boot(); + t->mark = time; // mark trigger time + ret = 1; + } + break; + default: + break; + } + + return ret; +} + + +static inline void __noinstrument func_entry_exit(void *this_fn, void *call_site, + int func_entry) +{ + unsigned long flags; + struct kfi_run* run; + + local_irq_save(flags); + if (in_entry_exit) { + local_irq_restore(flags); + return; + } + in_entry_exit = 1; + + update_usecs_since_boot(); + + run = run_curr; + + if (!run || run->complete) { + goto entry_exit_byebye; + } + + if (!run->triggered) { + /* test for start trigger */ + if (!run->primed || !(run->triggered = test_trigger(run, 1, + func_entry, + this_fn))) { + goto entry_exit_byebye; + } + } + + if (!filter_out(&run->filters, this_fn)) { + if (func_entry) + do_func_entry(run, this_fn, call_site); + else + do_func_exit(run, this_fn, call_site); + } + + if (!run->complete) { + /* test for stop trigger */ + run->complete = test_trigger(run, 0, + func_entry, + this_fn); + } + + if (run->complete) { + /* FIXTHIS - test for auto-restart */ + } + + entry_exit_byebye: + in_entry_exit = 0; + local_irq_restore(flags); +} + + +void __noinstrument __cyg_profile_func_enter (void *this_fn, void *call_site) +{ + func_entry_exit(this_fn, call_site, 1); +} + +void __noinstrument __cyg_profile_func_exit (void *this_fn, void *call_site) +{ + func_entry_exit(this_fn, call_site, 0); +} + + +#define dump_str(buf, len, fmt, arg...) \ + if (buf) len += sprintf(buf + len, fmt, ## arg); \ + else len += printk(KERN_EMERG fmt, ## arg) + +static int __noinstrument print_trigger(char* buf, int len, + struct kfi_trigger* t, int start_trigger) +{ + char trigbuf[80]; + + switch (t->type) { + case TRIGGER_USER: + sprintf(trigbuf, "system call\n"); + break; + case TRIGGER_TIME: + sprintf(trigbuf, "time at %lu usec from %s\n", + t->time, start_trigger ? "boot" : "start trigger"); + break; + case TRIGGER_FUNC_ENTRY: + sprintf(trigbuf, "entry to function 0x%08lx\n", + (unsigned long)t->func_addr); + break; + case TRIGGER_FUNC_EXIT: + sprintf(trigbuf, "exit from function 0x%08lx\n", + (unsigned long)t->func_addr); + break; + case TRIGGER_LOG_FULL: + sprintf(trigbuf, "log full\n"); + break; + default: + sprintf(trigbuf, "?\n"); + break; + } + + dump_str(buf, len, "Logging %s at %lu usec by %s", + (start_trigger ? "started" : "stopped"), + t->mark, trigbuf); + + return len; +} + +static void __noinstrument print_trigger2(struct seq_file *m, + struct kfi_trigger* t, int start_trigger) +{ + char trigbuf[80]; + + switch (t->type) { + case TRIGGER_USER: + sprintf(trigbuf, "user action\n"); + break; + case TRIGGER_TIME: + sprintf(trigbuf, "time at %lu usec from %s\n", + t->time, start_trigger ? "boot" : "start trigger"); + break; + case TRIGGER_FUNC_ENTRY: + sprintf(trigbuf, "entry to function 0x%08lx\n", + (unsigned long)t->func_addr); + break; + case TRIGGER_FUNC_EXIT: + sprintf(trigbuf, "exit from function 0x%08lx\n", + (unsigned long)t->func_addr); + break; + case TRIGGER_LOG_FULL: + sprintf(trigbuf, "log full\n"); + break; + default: + sprintf(trigbuf, "?\n"); + break; + } + + seq_printf(m, "Logging %s at %lu usec by %s", + (start_trigger ? "started" : "stopped"), + t->mark, trigbuf); + return; +} + +int __noinstrument kfi_dump_log(char* buf) +{ + int i, len = 0; + struct kfi_run* run = run_curr; + struct kfi_filters* filters = &run->filters; + + if (!run) { + dump_str(buf, len, "\nNo logging run registered\n"); + return len; + } + + if (!run->triggered) { + dump_str(buf, len, "\nLogging not yet triggered\n"); + return len; + } + + if (!run->complete) { + dump_str(buf, len, "\nLogging is running\n"); + return len; + } + + dump_str(buf, len, "\nKernel Instrumentation Run ID %d\n\n", + run->id); + + dump_str(buf, len, "Filters:\n"); + if (filters->func_list_size) { + dump_str(buf, len, "\t%d-entry function list\n", + filters->func_list_size); + } + if (filters->min_delta) { + dump_str(buf, len, "\t%ld usecs minimum execution time\n", + filters->min_delta); + } + if (filters->max_delta) { + dump_str(buf, len, "\t%ld usecs maximum execution time\n", + filters->max_delta); + } + if (filters->no_ints) { + dump_str(buf, len, "\tno functions in interrupt context\n"); + } + if (filters->only_ints) { + dump_str(buf, len, + "\tno functions NOT in interrupt context\n"); + } + if (filters->func_list) { + dump_str(buf, len, "\tfunction list\n"); + } + + dump_str(buf, len, "\nFilter Counters:\n"); + + if (filters->min_delta || filters->max_delta) { + dump_str(buf, len, "\nExecution time filter count = %d\n", + filters->cnt.delta); + } + if (filters->no_ints) { + dump_str(buf, len, + "No Interrupt functions filter count = %d\n", + filters->cnt.no_ints); + } + if (filters->only_ints) { + dump_str(buf, len, + "Only Interrupt functions filter count = %d\n", + filters->cnt.only_ints); + } + if (filters->func_list_size) { + dump_str(buf, len, "Function List filter count = %d\n", + filters->cnt.func_list); + } + dump_str(buf, len, "Total entries filtered = %d\n", + filters->cnt.delta + + filters->cnt.no_ints + + filters->cnt.only_ints + + filters->cnt.func_list); + dump_str(buf, len, "Entries not found = %d\n", run->notfound); + dump_str(buf, len, "\nNumber of entries after filters = %d\n\n", + run->next_entry); + + len += print_trigger(buf, len, &run->start_trigger, 1); + len += print_trigger(buf, len, &run->stop_trigger, 0); + + /* print out header */ + dump_str(buf, len, "\n"); + dump_str(buf, len, + " Entry Delta PID Function Caller\n"); + dump_str(buf, len, + "-------- -------- -------- -------- --------\n"); + + for (i=0; i < run->next_entry; i++) { + dump_str(buf, len, "%8lu %8lu %7d%s %08x %08x\n", + run->log[i].time, + run->log[i].delta, + run->log[i].pid, + (run->log[i].pid == INTR_CONTEXT) ? "i" : " ", + (unsigned int)run->log[i].va, + (unsigned int)run->log[i].call_site); + } + + return len; +} + +/* DEPRECATED +int __noinstrument kfi_read_proc(char *buf, char **start, off_t fpos, + int length, int *eof, void *data) +{ + int len = kfi_dump_log(buf); + + if (fpos >= len) { + *start = buf; + *eof = 1; + return 0; + } + *start = buf + fpos; + if ((len -= fpos) > length) + return length; + *eof = 1; + return len; +} +*/ + +/* + * start of /proc/kfi control handler stuff + */ + +static struct proc_dir_entry *kfi_proc_file; + +#define tok_match(tok, str) (strncmp(tok, str, strlen(str))==0) + +/* move pos to next white space */ +static void __noinstrument skip_token(const char **pos) +{ + size_t non_white_count; + + /* return pointer to next white space, or \0 */ + if (*pos) { + non_white_count = strcspn(*pos, " \t\n"); + *pos = *pos + non_white_count; + } +} + +/* + * return pointer to next non-white-space, + * advancing position to next white space following that + */ +static const char __noinstrument *next_token(const char **pos) +{ + size_t white_count; + const char *tok; + + /* return pointer to next non-white space, or \0 */ + if (*pos) { + white_count = strspn(*pos, " \t\n"); + *pos = *pos + white_count; + } + tok = *pos; + skip_token(pos); + return tok; + +} + +static int __noinstrument parse_func(const char **pos, void **func_addr) +{ + int ret; + + ret = sscanf(*pos, "%x", (int *)func_addr); + skip_token(pos); + if (ret != 1) { + return -EINVAL; + } else { + return 0; + } +} + +/* + * parse_trigger: syntax is: trigger start|stop entry|exit|time arg + * arg for time is decimal number (usecs) + * arg for entry or exit is hexadecimal (function address) + */ +static int __noinstrument parse_trigger(const char **pos, struct kfi_run *run) +{ + const char *tok; + struct kfi_trigger *trigger; + int ret, rcode = 0; + + /* parse event-type (start or stop) */ + tok = next_token(pos); + if tok_match(tok, "start") { + trigger = &run->start_trigger; + } else { + if tok_match(tok, "stop") { + trigger = &run->stop_trigger; + } else { + printk("Error: missing trigger event-type\n"); + return -EINVAL; + } + } + + /* parse type (entry, exit, time)*/ + tok = next_token(pos); + if tok_match(tok, "time") { + trigger->type = TRIGGER_TIME; + tok = next_token(pos); + ret = sscanf(tok, "%lu", &trigger->time); + if (ret != 1) { + printk("Error: can't parse trigger time\n"); + rcode = -EINVAL; + } + } else { + if tok_match(tok, "entry") { + trigger->type = TRIGGER_FUNC_ENTRY; + rcode = parse_func(pos, &trigger->func_addr); + } else { + if tok_match(tok, "exit") { + trigger->type = TRIGGER_FUNC_EXIT; + rcode = parse_func(pos, &trigger->func_addr); + } + } + if (rcode) + printk("Error: can't parse trigger function\n"); + } + return rcode; +} + +/* + * parse_filter: syntax is: filter mintime|maxtime|noints|onlyints|funclist [args] + * arg for time (mintime or maxtime) is decimal number (usecs) + * arg for funclist is list of function addresses, followed by "fend" + * e.g. filter funclist c0008000 c0008110 fend + */ +static int __noinstrument parse_filter(const char **pos, struct kfi_run *run) +{ + const char *tok; + const char **pos_save; + int i, ret, rcode = 0; + int parsed = 0; + + /* parse filter type */ + tok = next_token(pos); + if tok_match(tok, "noints") { + run->filters.no_ints = 1; + parsed = 1; + } + if tok_match(tok, "onlyints") { + run->filters.only_ints = 1; + parsed = 1; + } + if tok_match(tok, "mintime") { + tok = next_token(pos); + ret = sscanf(tok, "%lu", &run->filters.min_delta); + if (ret != 1) { + printk("Error: can't parse filter mintime\n"); + rcode = -EINVAL; + } + parsed = 1; + } + if tok_match(tok, "maxtime") { + tok = next_token(pos); + ret = sscanf(tok, "%lu", &run->filters.max_delta); + if (ret != 1) { + printk("Error: can't parse filter maxtime\n"); + rcode = -EINVAL; + } + parsed = 1; + } + if tok_match(tok, "funclist") { + pos_save = pos; + + /* count number of functions */ + i = 0; + tok = next_token(pos); + while (*pos && !tok_match(tok, "fend")) { + i++; + skip_token(pos); + tok = next_token(pos); + } + if (!tok_match(tok, "fend")) { + printk("Error: missing \"fend\" in filter funclist\n"); + return -EINVAL; + } + /* allocate space for functions */ + run->filters.func_list = kmalloc( sizeof(void *) * i, GFP_KERNEL); + run->filters.func_list_size = i; + + /* parse functions */ + pos = pos_save; /* rewind to beginning of funclist */ + tok = next_token(pos); + i = 0; + while (**pos && !tok_match(tok, "fend")) { + rcode = parse_func(&tok, &run->filters.func_list[i]); + i++; + if (rcode) { + printk("Error: can't parse function %d in filter " + "funclist\n", i+1); + break; + } + tok = next_token(pos); + } + parsed = 1; + } + + if (!parsed) { + printk("Error: unknown filter type. (tok=%s)\n", tok); + rcode = -EINVAL; + } + + return rcode; +} + + +static int __noinstrument kfi_parse_config(const char *config, struct kfi_run *run) +{ + const char *tok; + int ret, rcode; + const char **pos; + + pos = &config; + tok = next_token(pos); + while (**pos && !tok_match(tok, "end")) { + if (tok_match(tok, "trigger")) { + rcode = parse_trigger(pos, run); + if (rcode) { + return rcode; + } + } + if (tok_match(tok, "filter")) { + rcode = parse_filter(pos, run); + if (rcode) { + return rcode; + } + } + if (tok_match(tok, "logsize")) { + tok = next_token(pos); + ret = sscanf(tok, "%d", &run->num_entries); + if (ret != 1) { + printk("Error: bad logsize.\n"); + return -EINVAL; + } + if (run->num_entries > MAX_RUN_LOG_ENTRIES) { + printk("Error: logsize too big.\n"); + return -EINVAL; + } + } + tok = next_token(pos); + } + if (!tok_match(tok, "end")) { + printk("Error: missing \"end\" statement\n"); + return -EINVAL; + } + return 0; +} + +static int __noinstrument print_trigger_config(char *buf, int len, char *ss, struct kfi_trigger *t) +{ + + char *ts = " trigger"; + + switch (t->type) { + case TRIGGER_TIME: + dump_str(buf, len, "%s %s time %lu\n", ts, ss, t->time); + break; + case TRIGGER_FUNC_ENTRY: + dump_str(buf, len, "%s %s entry 0x%08lX\n", ts, ss, + (unsigned long)t->func_addr); + break; + case TRIGGER_FUNC_EXIT: + dump_str(buf, len, "%s %s exit 0x%08lX\n", ts, ss, + (unsigned long)t->func_addr); + break; + case TRIGGER_NONE: + dump_str(buf, len, "%s %s not set\n", ts, ss); + break; + case TRIGGER_PROC: + case TRIGGER_USER: + case TRIGGER_LOG_FULL: + default: + dump_str(buf, len, "%s %s ???\n", ts, ss); + break; + } + return len; +} + +static int __noinstrument dump_config(char *buf, struct kfi_run *run) +{ + int i, len = 0; + + /* print status information */ + dump_str(buf, len, "status: run id %d, %sprimed, %striggered, %scomplete\n\n", + run->id, run->primed?"":"not ", run->triggered?"":"not ", + run->complete?"":"not "); + + //run->flags = KFI_MODE_TIMED; /* and NOT KFI_MODE_OVERWRITE */ + dump_str(buf, len, "config:\n"); + dump_str(buf, len, " mode %d\n", run->flags); + + /* triggers */ + len = print_trigger_config(buf, len, "start", &run->start_trigger); + len = print_trigger_config(buf, len, "stop", &run->stop_trigger); + + /* filters */ + dump_str(buf, len, " filter mintime %lu\n", run->filters.min_delta); + dump_str(buf, len, " filter maxtime %lu\n", run->filters.max_delta); + if (run->filters.no_ints) { + dump_str(buf, len, " filter noints\n"); + } + if (run->filters.only_ints) { + dump_str(buf, len, " filter onlyints\n"); + } + if (run->filters.func_list) { + dump_str(buf, len, " filter funclist "); + for (i=0; ifilters.func_list_size; i++ ) { + dump_str(buf, len, "0x%08lX ", + (unsigned long)run->filters.func_list[i]); + } + dump_str(buf, len, "fend\n"); + } + + /* misc stuff */ + dump_str(buf, len, " logsize %d\n", run->num_entries); + return len; +} + + +static int __noinstrument kfi_new_run(const char *run_config_str) +{ + unsigned long flags; + int rcode; + + struct kfi_run *run; + + run = (struct kfi_run*)kmalloc(sizeof(struct kfi_run), GFP_KERNEL); + if (!run) { + printk(KERN_ERR "Error allocating space for new kfi_run struct\n"); + return -ENOMEM; + } + + /* set up a new run by parsing config_str */ + /* set default configuration to handle any un-set entries */ + run->primed = run->triggered = run->complete = 0; + run->flags = KFI_MODE_TIMED; /* and NOT KFI_MODE_OVERWRITE */ + run->start_trigger.type = TRIGGER_NONE; + run->start_trigger.func_addr = NULL; + run->stop_trigger.type = TRIGGER_NONE; + run->stop_trigger.func_addr = NULL; + run->filters.min_delta = 0; + run->filters.max_delta = 0; + run->filters.no_ints = 0; + run->filters.only_ints = 0; + run->filters.func_list = NULL; + run->filters.func_list_size = 0; + run->num_entries = MAX_RUN_LOG_ENTRIES; + run->next_entry = 0; + + rcode = kfi_parse_config(run_config_str, run); + if (rcode) { + kfree(run); + printk("KFI: Could not configure new kfi run"); + return rcode; + } + + /* sanity check some of the values before getting too far */ + if (run->num_entries > MAX_RUN_LOG_ENTRIES) { + printk("KFI: Specified log size is too big (>%d)\n", MAX_RUN_LOG_ENTRIES); + return -EINVAL; + } + /* reset stat counters */ + memset(&run->filters.cnt, 0, sizeof(run->filters.cnt)); + run->notfound = 0; + + /* allocate log */ + //printk("num_entries= %d\n", run->num_entries); + run->log = (struct kfi_entry *) + kmalloc(sizeof(struct kfi_entry) * run->num_entries, GFP_KERNEL); + if (run->log == NULL) { + printk("KFI: Could not allocate %d bytes for kfi log.\n", + sizeof(struct kfi_entry) * run->num_entries); + rcode = -ENOMEM; + goto free_stuff_out; + } + printk("log=%p\n", run->log); + memset(run->log, 0, sizeof(struct kfi_entry) * run->num_entries); + + /* set the run id */ + if (!run_curr) { + run->id = 0; + } else { + run->id = run_curr->id + 1; + } + + dump_config(NULL, run); + + /* install then new run as current run */ + local_irq_save(flags); + if (run_curr && run_curr != (struct kfirun *)&kfi_run0) { + /* free the old run, if it wasn't a static run */ + if (run_curr->filters.func_list) { + kfree(run_curr->filters.func_list); + } + kfree(run_curr->log); + kfree(run_curr); + } + run_curr = run; + local_irq_restore(flags); + printk("KFI: new kfi run installed\n"); + return 0; + +free_stuff_out: + kfree(run->filters.func_list); + kfree(run->log); + kfree(run); + return rcode; +} + +/* + * start the current run + */ +static int __noinstrument kfi_start(void) +{ + unsigned long flags; + struct kfi_run* run; + + local_irq_save(flags); + run = run_curr; + /* missing, done, or already started? */ + if (!run || run->complete || run->triggered) { + local_irq_restore(flags); + return -EINVAL; + } + run->triggered = 1; + run->start_trigger.mark = update_usecs_since_boot(); + run->start_trigger.type = TRIGGER_USER; + local_irq_restore(flags); + return 0; +} + +static int __noinstrument kfi_prime(void) +{ + unsigned long flags; + struct kfi_run* run; + + local_irq_save(flags); + run = run_curr; + /* missing, or currently running? */ + if (!run || (run->triggered && !run->complete)) { + local_irq_restore(flags); + return -EINVAL; + } + run->primed = 1; + local_irq_restore(flags); + return 0; +} + +/* + * stop the current run + */ +static int __noinstrument kfi_stop(void) +{ + unsigned long flags; + struct kfi_run* run; + + local_irq_save(flags); + run = run_curr; + /* missing or already done? */ + if (!run || run->complete) { + local_irq_restore(flags); + return -EINVAL; + } + run->complete = 1; + run->stop_trigger.mark = update_usecs_since_boot(); + run->stop_trigger.type = TRIGGER_USER; + local_irq_restore(flags); + return 0; +} + +static int __noinstrument proc_read_kfi(char *page, char **start, off_t off, int count, int *eof, + void *data) +{ + int len; + struct kfi_run* run = run_curr; + + if (!run) { + len = 0; + dump_str(page, len, "No logging run registered\n"); + } else { + len = dump_config(page, run); + } + return len; +} + +static int __noinstrument proc_write_kfi(struct file *file, const char *buffer, + unsigned long count, void *data) +{ + int rcode = 0; + static char cmd_buffer[COMMAND_BUFFER_LEN]; + + if (count > COMMAND_BUFFER_LEN) { + return -EINVAL; + } + + /* FIXTHIS - do I need a verify_area() here? */ + if (copy_from_user(cmd_buffer, buffer, count)) { + return -EFAULT; + } + cmd_buffer[count] = '\0'; + + if (strncmp(cmd_buffer, "prime", 5)==0 ) { + rcode = kfi_prime(); + } + + if (strncmp(cmd_buffer, "start", 5)==0 ) { + rcode = kfi_start(); + } + + if (strncmp(cmd_buffer, "stop", 4)==0 ) { + rcode = kfi_stop(); + } + + if (strncmp(cmd_buffer, "new", 3)==0 ) { + rcode = kfi_new_run(cmd_buffer+3); + } + + if (rcode) { + return rcode; + } else { + return count; + } +} + +/* + * stuff for /proc/kfi_trace + */ +static DECLARE_MUTEX(out_mutex); + +static void * __noinstrument k_start(struct seq_file *m, loff_t *pos) +{ + loff_t n = *pos; + struct kfi_run* run = run_curr; + struct kfi_filters* filters = &run->filters; + + down(&out_mutex); + /* + * if the file is being newly read, stop any current trace + */ + if (!n) { + // FIXTHIS - stop trace + } + + if (!n) { + /* print out header */ + if (!run) { + seq_printf(m, "No logging run registered\n"); + return NULL; + } + + seq_printf(m, "\nKernel Instrumentation Run ID %d\n\n", + run->id); + + print_trigger2(m, &run->start_trigger, 1); + print_trigger2(m, &run->stop_trigger, 0); + + seq_puts(m, "\nFilter Counters:\n"); + + if (filters->min_delta || filters->max_delta) { + seq_printf(m, "\nExecution time filter count = %d\n", + filters->cnt.delta); + } + if (filters->no_ints) { + seq_printf(m, + "No Interrupt functions filter count = %d\n", + filters->cnt.no_ints); + } + if (filters->only_ints) { + seq_printf(m, + "Only Interrupt functions filter count = %d\n", + filters->cnt.only_ints); + } + if (filters->func_list_size) { + seq_printf(m, "Function List filter count = %d\n", + filters->cnt.func_list); + } + seq_printf(m, "Total entries filtered = %d\n", + filters->cnt.delta + filters->cnt.no_ints + + filters->cnt.only_ints + filters->cnt.func_list); + seq_printf(m, "Entries not found = %d\n", run->notfound); + + seq_printf(m, "\nNumber of entries after filters = %d\n\n", + run->next_entry); + + seq_puts(m, "\n Entry Delta PID Function Caller\n"); + seq_puts(m, "-------- -------- -------- ---------------- ------------\n"); + } + if (n >= run->next_entry) { + return NULL; + } + return run->log + n; +} + +static void * __noinstrument k_next(struct seq_file *m, void *p, loff_t *pos) +{ + struct kfi_run* run = run_curr; + + if (++*pos >= run->next_entry) { + return NULL; + } + return run->log + *pos; +} + +static void __noinstrument k_stop(struct seq_file *m, void *p) +{ + up(&out_mutex); +} + +static int __noinstrument k_show(struct seq_file *m, void *p) +{ + struct kfi_entry *entry; + + entry = p; + seq_printf(m, "%8lu %8lu %7d%s 0x%08x 0x%08x\n", + entry->time, entry->delta, entry->pid, + (entry->pid == INTR_CONTEXT) ? "i" : " ", + (unsigned int)entry->va, + (unsigned int)entry->call_site); + return 0; +} + +struct seq_operations kfi_trace_op = { + .start = k_start, + .next = k_next, + .stop = k_stop, + .show = k_show +}; + +/* + * end of stuff for /proc/kfi_trace + */ + +static int __init __noinstrument kfi_init(void) +{ + int rcode = 0; + + kfi_proc_file = create_proc_entry("kfi", 0644, NULL); + if (kfi_proc_file==NULL) { + rcode = -ENOMEM; + goto out; + } + + kfi_proc_file->data = NULL; + kfi_proc_file->read_proc = proc_read_kfi; + kfi_proc_file->write_proc = proc_write_kfi; + kfi_proc_file->owner = THIS_MODULE; +out: + return rcode; +} + +static void __exit __noinstrument kfi_exit(void) +{ + remove_proc_entry("kfi", NULL); +} + +module_init(kfi_init); +module_exit(kfi_exit); + +EXPORT_SYMBOL(__cyg_profile_func_enter); +EXPORT_SYMBOL(__cyg_profile_func_exit); + Index: linux/kernel/kfistatic.conf =================================================================== --- linux.orig/kernel/kfistatic.conf 2005-03-24 10:49:44.466757856 -0800 +++ linux/kernel/kfistatic.conf 2005-04-08 16:53:18.234107048 -0700 @@ -0,0 +1,40 @@ +# record all functions longer that 500 microseconds, during bootup +# don't worry about interrupts +begin + trigger start entry start_kernel + trigger stop exit to_userspace + filter mintime 500 + filter maxtime 0 + filter noints +end + +# get a full trace of time_init (ignoring interrupts) +begin + trigger start entry time_init + trigger stop exit time_init + filter noints +end + +# record short routines called by do_fork +# use a small log +#begin +# trigger start entry do_fork +# trigger stop exit do_fork +# filter mintime 10 +# filter maxtime 400 +# filter noints +# logsize 100 +#end + +# record interrupts for .5 milliseconds, 20 seconds after booting +#begin +# trigger start time 5000000 +# trigger stop time 500 +# filter onlyints +#end + +# record all schedules after 10 seconds +#begin +# trigger start time 10000000 +# filter funclist schedule +#end Index: linux/kernel/sched.c =================================================================== --- linux.orig/kernel/sched.c 2005-04-08 12:11:43.956293190 -0700 +++ linux/kernel/sched.c 2005-04-08 17:11:51.074230774 -0700 @@ -2627,7 +2627,7 @@ #if defined(CONFIG_PREEMPT) && defined(CONFIG_DEBUG_PREEMPT) -void fastcall add_preempt_count(int val) +void fastcall __noinstrument add_preempt_count(int val) { /* * Underflow? Index: linux/kernel/softirq.c =================================================================== --- linux.orig/kernel/softirq.c 2005-04-08 12:10:40.465645355 -0700 +++ linux/kernel/softirq.c 2005-04-08 17:11:51.075230675 -0700 @@ -161,7 +161,7 @@ /* * Exit an interrupt context. Process softirqs if needed and possible: */ -void irq_exit(void) +void __noinstrument irq_exit(void) { account_system_vtime(current); sub_preempt_count(IRQ_EXIT_OFFSET); Index: linux/kernel/sys.c =================================================================== --- linux.orig/kernel/sys.c 2005-04-08 12:10:40.463645555 -0700 +++ linux/kernel/sys.c 2005-04-08 12:11:44.401248674 -0700 @@ -32,6 +32,10 @@ #include #include +#ifdef CONFIG_KFI_DUMP +#include +#endif + #ifndef SET_UNALIGN_CTL # define SET_UNALIGN_CTL(a,b) (-EINVAL) #endif @@ -387,6 +391,9 @@ notifier_call_chain(&reboot_notifier_list, SYS_RESTART, NULL); system_state = SYSTEM_RESTART; device_shutdown(); +#ifdef CONFIG_KFI_DUMP + kfi_dump_log(NULL); +#endif printk(KERN_EMERG "Restarting system.\n"); machine_restart(NULL); break; @@ -403,6 +410,9 @@ notifier_call_chain(&reboot_notifier_list, SYS_HALT, NULL); system_state = SYSTEM_HALT; device_shutdown(); +#ifdef CONFIG_KFI_DUMP + kfi_dump_log(NULL); +#endif printk(KERN_EMERG "System halted.\n"); machine_halt(); unlock_kernel(); @@ -413,6 +423,9 @@ notifier_call_chain(&reboot_notifier_list, SYS_POWER_OFF, NULL); system_state = SYSTEM_POWER_OFF; device_shutdown(); +#ifdef CONFIG_KFI_DUMP + kfi_dump_log(NULL); +#endif printk(KERN_EMERG "Power down.\n"); machine_power_off(); unlock_kernel(); @@ -429,6 +442,9 @@ notifier_call_chain(&reboot_notifier_list, SYS_RESTART, buffer); system_state = SYSTEM_RESTART; device_shutdown(); +#ifdef CONFIG_KFI_DUMP + kfi_dump_log(NULL); +#endif printk(KERN_EMERG "Restarting system with command '%s'.\n", buffer); machine_restart(buffer); break; Index: linux/scripts/addr2sym =================================================================== --- linux.orig/scripts/addr2sym 2005-03-24 10:49:44.466757856 -0800 +++ linux/scripts/addr2sym 2005-04-08 12:11:44.402248574 -0700 @@ -0,0 +1,154 @@ +#!/usr/bin/python + +# addr2sym.py - resolve addresses to symbols, using a map file +# Reads a log file, and map file, and substitutes function +# names and offsets for numeric values in the log. +# The re-written log file is sent to standard out. +# +# A normal usage looks like: +# cat boot.log | addr2sym -m linux-2.6.7/System.map >boot.lst +# +import sys +import fileinput +import string +import re + +def startswith(str, pattern): + if string.find(str, pattern)==0: + return 1 + else: + return 0 + +# returns function map (key=addr, value=funcname) and +# a list of function tuples (addr, funcname) +def read_map(filename): + global map_low, map_high + funcmap = {} + funclist = [] + try: + f = open(filename) + except: + print "Error: Cannot read map file:", filename + usage() + + for line in f.readlines(): + (addr_str, symtype, funcname) = string.split(line, None, 3) + funcmap["0x"+addr_str] = funcname + addr = eval("0x"+addr_str+"L") + funclist.append((addr, funcname)) + + return (funcmap, funclist) + +# return string with function and offset for a given address +def lookup_sym(funcmap, funclist, addr_str): + + try: + return funcmap[addr_str] + except: + pass + + # no exact match found, now do binary search for closest function + + # convert address from string to number + addr = eval(addr_str+"L") + + # if address is outside range of addresses in the + # map file, just return the address without converting it + if addr < funclist[0][0] or addr > funclist[-1][0]: + return addr_str + + # do a binary search in funclist for the function + # use a collapsing range to find the closest addr + lower = 0 + upper = len(funclist)-1 + while (lower != upper-1): + guess_index = lower + (upper-lower)/2 + guess_addr = funclist[guess_index][0] + if addr < guess_addr: + upper = guess_index + if addr >= guess_addr: + lower = guess_index + + offset = addr-funclist[lower][0] + name = funclist[lower][1] + return "%s+0x%x" % (name, offset) + +def usage(): + print "Usage: addr2sym outfile" + print "\nexample:" + print "addr2sym boot.lst" + sys.exit(1) + +def main(): + # user must have "-m mapfile" at a minimum + if len(sys.argv)<3: + print "Error: no map file specified" + usage() + + mapfilename = "" + i = 0 + while i < len(sys.argv): + if sys.argv[i]=="-m": + try: + mapfilename = sys.argv[i+1] + # remove the args from the argument list + sys.argv[i:i+2]=[] + except: + pass + i = i+1 + + if not mapfilename: + print "Error: missing map file name" + usage() + + # read function names and addresses from map file + (funcmap, funclist) = read_map(mapfilename) + + for line in fileinput.input(): + # strip trailing \n, if present + if line[-1]=='\n': + line = line[:-1] + + # convert all hex numbers to symbols plus offsets + # try to preserve column spacing in the output + tmp = line + new_line = "" + m = re.match(r".*?(0x[0-9abcdef]+)(\s*)", tmp) + while m: + #print "m.groups=<%s>" % str(m.groups()) + + # addr is match for re group 1, look it up + addr_str = tmp[m.start(1): m.end(1)] + func = lookup_sym(funcmap, funclist, addr_str) + + # add function name to line, in place of address + new_line = new_line + tmp[:m.start(1)] + func + end = m.end(1) + + # pad line to keep columns the same + if len(m.groups())>1: + end = m.end(2) + pad_count = (m.end(2)-m.start(1))-len(func) + if pad_count < 1: pad_count=1 + new_line = new_line + " "*pad_count + + # scan remainder of line + tmp = tmp[end:] + m = re.match(r".*?(0x[0-9abcdef]+)(\s*)", tmp) + + # FIXTHIS - convert pid + #in_int = 0 + #if pid[-1] == 'i': + # pid = pid[:-1] + # in_int = 1 + + + # FIXTHIS - convert 0 duration to "no exit" + #if delta=="0": delta="no exit" + + if new_line: + line = new_line + print line + +if __name__=="__main__": + main() Index: linux/scripts/kd =================================================================== --- linux.orig/scripts/kd 2005-03-24 10:49:44.466757856 -0800 +++ linux/scripts/kd 2005-04-08 17:13:07.124652144 -0700 @@ -0,0 +1,350 @@ +#!/usr/bin/env python +# +# kd (kfi-dump): +# Read data from an kfi dump, and format various ways. +# +# ToDo: +# - show function call tree +# - show functions sorted by time spent in them +# - show functions sorted by time (without sub-routines) +# + +major_version = 0 +minor_version = 1 + +import sys +import string + +def usage(): + print """usage: kd [] + +This program parses the output from a set of kfi message lines + +Options: + -h, --help Show this usage help. + -c Only show the most time-consuming functions + -t