LKML Archive on lore.kernel.org help / color / mirror / Atom feed
* [PATCH][RFC] trace: profile likely and unlikely annotations [not found] ` <20081028001340.GB9797@mit.edu> @ 2008-10-28 4:12 ` Steven Rostedt 2008-10-28 4:23 ` Arjan van de Ven ` (2 more replies) 0 siblings, 3 replies; 17+ messages in thread From: Steven Rostedt @ 2008-10-28 4:12 UTC (permalink / raw) To: LKML Cc: Mike Snitzer, Theodore Tso, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Arjan van de Ven, Frederic Weisbecker Andrew Morton recently suggested having an in-kernel way to profile likely and unlikely macros. This patch achieves that goal. When configured, every(*) likely and unlikely macro gets a counter attached to it. When the condition is hit, the hit and misses of that condition are recorded. These numbers can later be retrieved by: /debugfs/tracing/profile_likely - All likely markers /debugfs/tracing/profile_unlikely - All unlikely markers. # cat /debug/tracing/profile_unlikely | \ awk '{ if ((($1 + 1.0)/ ($2 + 1.0)) > 0.5) { print $0; }}' |head -15 Hit Missed Function --- ------ -------- 36278 44749 __switch_to+0x129/0x55d 70064 10964 __switch_to+0xcd/0x55d 70060 10964 __switch_to+0x63/0x55d 2628 0 syscall_trace_leave+0x0/0x154 1 0 native_smp_prepare_cpus+0x3e9/0x485 287349 98809 place_entity+0xac/0x11c 141308 236748 calc_delta_mine+0x8b/0x109 55091 0 enqueue_task+0x0/0x9b 71724 52117 pick_next_task_fair+0x0/0xc1 11 5 yield_task_fair+0x0/0x13b 1269 0 pre_schedule_rt+0x0/0x98 46392 1265 pick_next_task_rt+0x0/0x12f 51523 0 dequeue_task+0x57/0x114 # cat /debug/tracing/profile_likely | \ awk '{ if ((($2 + 1.0)/ ($1 + 1.0)) > 0.5) { print $0; }}' Hit Missed Function --- ------ -------- 43316 37700 schedule+0x6e7/0xdb2 23032 12997 schedule+0xa9b/0xdb2 0 7 __cancel_work_timer+0x4b/0x292 885 1683 update_wall_time+0x27b/0x4fd 0 369948 audit_syscall_exit+0x131/0x403 19 370851 audit_free+0x0/0x27e 0 368981 audit_syscall_entry+0x1a4/0x226 19 900 audit_free+0xf0/0x27e 0 973 audit_alloc+0xa6/0x13c 0 6 move_masked_irq+0x2b/0x174 12878 223023 page_evictable+0x9a/0x1f1 9 7 flush_cpu_slab+0x0/0x143 634634 324186 kmem_cache_free+0x79/0x139 3142 61979 dentry_lru_del_init+0x0/0x89 948 1166 load_elf_binary+0xa00/0x18ad 102 82 disk_part_iter_next+0x0/0xf1 0 11 tcp_mss_split_point+0x0/0xbd As you can see by the above, there's a bit of work to do in rethinking the use of some unlikelys and likelys. Note: the unlikely case had 60 hits that were more than 50%. (*) Not ever unlikely is recorded, those that are used by vsyscalls (a few of them) had to be marked as unlikely_notrace(). Signed-off-by: Steven Rostedt <srostedt@redhat.com> --- arch/x86/kernel/vsyscall_64.c | 5 - include/asm-generic/vmlinux.lds.h | 14 +++ include/linux/compiler.h | 38 ++++++++ include/linux/seqlock.h | 3 kernel/trace/Kconfig | 16 +++ kernel/trace/Makefile | 2 kernel/trace/trace_unlikely.c | 163 ++++++++++++++++++++++++++++++++++++++ 7 files changed, 237 insertions(+), 4 deletions(-) Index: linux-tip.git/kernel/trace/Makefile =================================================================== --- linux-tip.git.orig/kernel/trace/Makefile 2008-10-27 23:11:52.000000000 -0400 +++ linux-tip.git/kernel/trace/Makefile 2008-10-27 23:12:08.000000000 -0400 @@ -26,4 +26,6 @@ obj-$(CONFIG_FUNCTION_PROFILER) += trace obj-$(CONFIG_MMIOTRACE) += trace_mmiotrace.o obj-$(CONFIG_BOOT_TRACER) += trace_boot.o +obj-$(CONFIG_TRACE_UNLIKELY_PROFILE) += trace_unlikely.o + libftrace-y := ftrace.o Index: linux-tip.git/arch/x86/kernel/vsyscall_64.c =================================================================== --- linux-tip.git.orig/arch/x86/kernel/vsyscall_64.c 2008-10-27 23:11:52.000000000 -0400 +++ linux-tip.git/arch/x86/kernel/vsyscall_64.c 2008-10-27 23:12:44.000000000 -0400 @@ -124,7 +124,8 @@ static __always_inline void do_vgettimeo seq = read_seqbegin(&__vsyscall_gtod_data.lock); vread = __vsyscall_gtod_data.clock.vread; - if (unlikely(!__vsyscall_gtod_data.sysctl_enabled || !vread)) { + if (unlikely_notrace(!__vsyscall_gtod_data.sysctl_enabled || + !vread)) { gettimeofday(tv,NULL); return; } @@ -165,7 +166,7 @@ time_t __vsyscall(1) vtime(time_t *t) { struct timeval tv; time_t result; - if (unlikely(!__vsyscall_gtod_data.sysctl_enabled)) + if (unlikely_notrace(!__vsyscall_gtod_data.sysctl_enabled)) return time_syscall(t); vgettimeofday(&tv, NULL); Index: linux-tip.git/include/asm-generic/vmlinux.lds.h =================================================================== --- linux-tip.git.orig/include/asm-generic/vmlinux.lds.h 2008-10-27 23:11:52.000000000 -0400 +++ linux-tip.git/include/asm-generic/vmlinux.lds.h 2008-10-27 23:12:08.000000000 -0400 @@ -45,6 +45,17 @@ #define MCOUNT_REC() #endif +#ifdef CONFIG_TRACE_UNLIKELY_PROFILE +#define LIKELY_PROFILE() VMLINUX_SYMBOL(__start_likely_profile) = .; \ + *(_ftrace_likely) \ + VMLINUX_SYMBOL(__stop_likely_profile) = .; \ + VMLINUX_SYMBOL(__start_unlikely_profile) = .; \ + *(_ftrace_unlikely) \ + VMLINUX_SYMBOL(__stop_unlikely_profile) = .; +#else +#define LIKELY_PROFILE() +#endif + /* .data section */ #define DATA_DATA \ *(.data) \ @@ -62,7 +73,8 @@ VMLINUX_SYMBOL(__stop___markers) = .; \ VMLINUX_SYMBOL(__start___tracepoints) = .; \ *(__tracepoints) \ - VMLINUX_SYMBOL(__stop___tracepoints) = .; + VMLINUX_SYMBOL(__stop___tracepoints) = .; \ + LIKELY_PROFILE() #define RO_DATA(align) \ . = ALIGN((align)); \ Index: linux-tip.git/include/linux/compiler.h =================================================================== --- linux-tip.git.orig/include/linux/compiler.h 2008-10-27 23:11:52.000000000 -0400 +++ linux-tip.git/include/linux/compiler.h 2008-10-28 00:00:50.000000000 -0400 @@ -59,8 +59,46 @@ extern void __chk_io_ptr(const volatile * specific implementations come from the above header files */ +#ifdef CONFIG_TRACE_UNLIKELY_PROFILE +struct ftrace_likely_data { + unsigned long ip; + unsigned long hit; + unsigned long missed; +}; +void ftrace_likely_update(struct ftrace_likely_data *f, int val); + +#define likely_notrace(x) __builtin_expect(!!(x), 1) +#define unlikely_notrace(x) __builtin_expect(!!(x), 0) + +/* Can't use _THIS_IP_ because it screws up header dependencies */ +#define __THIS_IP__ ({ __label__ __here; __here: (unsigned long)&&__here; }) + +#define likely(x) ({ \ + int ______r; \ + static struct ftrace_likely_data ______f \ + __attribute__((__aligned__(4))) \ + __attribute__((section("_ftrace_likely"))); \ + if (unlikely_notrace(!______f.ip)) \ + ______f.ip = __THIS_IP__; \ + ______r = likely_notrace(x); \ + ftrace_likely_update(&______f, ______r); \ + ______r; \ + }) +#define unlikely(x) ({ \ + int ______r; \ + static struct ftrace_likely_data ______f \ + __attribute__((__aligned__(4))) \ + __attribute__((section("_ftrace_unlikely"))); \ + if (unlikely_notrace(!______f.ip)) \ + ______f.ip = __THIS_IP__; \ + ______r = unlikely_notrace(x); \ + ftrace_likely_update(&______f, ______r); \ + ______r; \ + }) +#else #define likely(x) __builtin_expect(!!(x), 1) #define unlikely(x) __builtin_expect(!!(x), 0) +#endif /* Optimization barrier */ #ifndef barrier Index: linux-tip.git/kernel/trace/Kconfig =================================================================== --- linux-tip.git.orig/kernel/trace/Kconfig 2008-10-27 23:11:52.000000000 -0400 +++ linux-tip.git/kernel/trace/Kconfig 2008-10-27 23:12:08.000000000 -0400 @@ -138,6 +138,22 @@ config BOOT_TRACER selected, because the self-tests are an initcall as well and that would invalidate the boot trace. ) +config TRACE_UNLIKELY_PROFILE + bool "Trace likely/unlikely profiler" + depends on DEBUG_KERNEL + select TRACING + help + This tracer profiles all the the likely and unlikely macros + in the kernel. It will display the results in: + + /debugfs/tracing/profile_likely + /debugfs/tracing/profile_unlikely + + Note: this will add a significant overhead, only turn this + on if you need to profile the system's use of these macros. + + Say N if unsure. + config STACK_TRACER bool "Trace max stack" depends on HAVE_FUNCTION_TRACER Index: linux-tip.git/kernel/trace/trace_unlikely.c =================================================================== --- /dev/null 1970-01-01 00:00:00.000000000 +0000 +++ linux-tip.git/kernel/trace/trace_unlikely.c 2008-10-27 23:13:53.000000000 -0400 @@ -0,0 +1,163 @@ +/* + * unlikely profiler + * + * Copyright (C) 2008 Steven Rostedt <srostedt@redhat.com> + */ +#include <linux/kallsyms.h> +#include <linux/seq_file.h> +#include <linux/spinlock.h> +#include <linux/debugfs.h> +#include <linux/uaccess.h> +#include <linux/module.h> +#include <linux/ftrace.h> +#include <linux/hash.h> +#include <linux/fs.h> +#include <asm/local.h> +#include "trace.h" + +void ftrace_likely_update(struct ftrace_likely_data *f, int val) +{ + /* FIXME: Make this atomic! */ + if (val) + f->hit++; + else + f->missed++; +} +EXPORT_SYMBOL(ftrace_likely_update); + +struct ftrace_pointer { + void *start; + void *stop; +}; + +static void * +t_next(struct seq_file *m, void *v, loff_t *pos) +{ + struct ftrace_pointer *f = m->private; + struct ftrace_likely_data *p = v; + + (*pos)++; + + if (v == (void *)1) + return f->start; + + ++p; + + if ((void *)p >= (void *)f->stop) + return NULL; + + return p; +} + +static void *t_start(struct seq_file *m, loff_t *pos) +{ + void *t = (void *)1; + loff_t l = 0; + + for (; t && l < *pos; t = t_next(m, t, &l)) + ; + + return t; +} + +static void t_stop(struct seq_file *m, void *p) +{ +} + +static int trace_lookup_sym(struct seq_file *m, unsigned long addr) +{ +#ifdef CONFIG_KALLSYMS + char str[KSYM_SYMBOL_LEN]; + + sprint_symbol(str, addr); + + return seq_printf(m, "%s\n", str); +#else + return seq_printf(m, "%p\n", (void *)addr); +#endif +} + +static int t_show(struct seq_file *m, void *v) +{ + struct ftrace_likely_data *p = v; + + if (v == (void *)1) { + seq_printf(m, " Hit Missed Function\n" + " --- ------ --------\n"); + return 0; + } + + /* skip null records */ + if (!p->ip) + return 0; + + seq_printf(m, " %8lu %8lu ", p->hit, p->missed); + trace_lookup_sym(m, p->ip); + return 0; +} + +static struct seq_operations tracing_likely_seq_ops = { + .start = t_start, + .next = t_next, + .stop = t_stop, + .show = t_show, +}; + +static int tracing_likely_open(struct inode *inode, struct file *file) +{ + int ret; + + ret = seq_open(file, &tracing_likely_seq_ops); + if (!ret) { + struct seq_file *m = file->private_data; + m->private = (void *)inode->i_private; + } + + return ret; +} + +static struct file_operations tracing_likely_fops = { + .open = tracing_likely_open, + .read = seq_read, + .llseek = seq_lseek, +}; + +extern unsigned long __start_likely_profile[]; +extern unsigned long __stop_likely_profile[]; +extern unsigned long __start_unlikely_profile[]; +extern unsigned long __stop_unlikely_profile[]; + +static struct ftrace_pointer ftrace_likely_pos = { + .start = __start_likely_profile, + .stop = __stop_likely_profile, +}; + +static struct ftrace_pointer ftrace_unlikely_pos = { + .start = __start_unlikely_profile, + .stop = __stop_unlikely_profile, +}; + +static __init int ftrace_unlikely_init(void) +{ + struct dentry *d_tracer; + struct dentry *entry; + + d_tracer = tracing_init_dentry(); + + entry = debugfs_create_file("profile_likely", 0444, d_tracer, + &ftrace_likely_pos, + &tracing_likely_fops); + if (!entry) + pr_warning("Could not create debugfs 'profile_likely' entry\n"); + + entry = debugfs_create_file("profile_unlikely", 0444, d_tracer, + &ftrace_unlikely_pos, + &tracing_likely_fops); + if (!entry) + pr_warning("Could not create debugfs" + " 'profile_unlikely' entry\n"); + + return 0; +} + +device_initcall(ftrace_unlikely_init); Index: linux-tip.git/include/linux/seqlock.h =================================================================== --- linux-tip.git.orig/include/linux/seqlock.h 2008-10-27 23:11:52.000000000 -0400 +++ linux-tip.git/include/linux/seqlock.h 2008-10-27 23:12:08.000000000 -0400 @@ -90,7 +90,8 @@ static __always_inline unsigned read_seq repeat: ret = sl->sequence; smp_rmb(); - if (unlikely(ret & 1)) { + /* Used in vsyscall, need notrace version */ + if (unlikely_notrace(ret & 1)) { cpu_relax(); goto repeat; } ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH][RFC] trace: profile likely and unlikely annotations 2008-10-28 4:12 ` [PATCH][RFC] trace: profile likely and unlikely annotations Steven Rostedt @ 2008-10-28 4:23 ` Arjan van de Ven 2008-10-28 4:39 ` Andrew Morton 2008-10-28 14:37 ` Theodore Tso 2 siblings, 0 replies; 17+ messages in thread From: Arjan van de Ven @ 2008-10-28 4:23 UTC (permalink / raw) To: Steven Rostedt Cc: LKML, Mike Snitzer, Theodore Tso, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Frederic Weisbecker On Tue, 28 Oct 2008 00:12:48 -0400 (EDT) Steven Rostedt <rostedt@goodmis.org> wrote: > > Andrew Morton recently suggested having an in-kernel way to profile > likely and unlikely macros. This patch achieves that goal. alternatively we remove likely/unlikely ;) or maybe only ban it from drivers or something. -- Arjan van de Ven Intel Open Source Technology Centre For development, discussion and tips for power savings, visit http://www.lesswatts.org ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH][RFC] trace: profile likely and unlikely annotations 2008-10-28 4:12 ` [PATCH][RFC] trace: profile likely and unlikely annotations Steven Rostedt 2008-10-28 4:23 ` Arjan van de Ven @ 2008-10-28 4:39 ` Andrew Morton 2008-10-28 14:37 ` Theodore Tso 2 siblings, 0 replies; 17+ messages in thread From: Andrew Morton @ 2008-10-28 4:39 UTC (permalink / raw) To: Steven Rostedt Cc: LKML, Mike Snitzer, Theodore Tso, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Arjan van de Ven, Frederic Weisbecker On Tue, 28 Oct 2008 00:12:48 -0400 (EDT) Steven Rostedt <rostedt@goodmis.org> wrote: > (*) Not ever unlikely is recorded, those that are used by vsyscalls > (a few of them) had to be marked as unlikely_notrace(). Yes, it took continuous maintenance to weed this stuff out of profile-likely-unlikely-macros.patch. I'd suggest that you take a peek at this patch and make sure that you've addressed all the sites which had to be fixed up while maintaining this one. (I've been maintaining this for 2-1/2 years. Sniff) From: Daniel Walker <dwalker@mvista.com> -ENOCHANGELOG! Creates /proc/likely_prof. [randy.dunlap@oracle.com: profile_likely: export do_check_likely] [akpm@linux-foundation.org: fixes and general maintenance] [dwalker@mvista.com: likely_prof changed to use proc_create] [12o3l@tiscali.nl: likeliness accounting change and cleanup] [adobriyan@gmail.com: proc: remove proc_root from drivers] [12o3l@tiscali.nl: update to test_and_set_bit_lock / clear_bit_unlock] [dwalker@mvista.com: likely-profiling: disable ftrace] Signed-off-by: Daniel Walker <dwalker@mvista.com> Signed-off-by: Hua Zhong <hzhong@gmail.com> Cc: Andi Kleen <andi@firstfloor.org> Signed-off-by: Roel Kluin <12o3l@tiscali.nl> Signed-off-by: Alexey Dobriyan <adobriyan@gmail.com> Signed-off-by: Andrew Morton <akpm@linux-foundation.org> --- arch/x86/kernel/vsyscall_64.c | 2 arch/x86/vdso/vclock_gettime.c | 2 include/linux/compiler.h | 36 +++++++ lib/Kconfig.debug | 8 + lib/Makefile | 5 + lib/likely_prof.c | 150 +++++++++++++++++++++++++++++++ 6 files changed, 203 insertions(+) diff -puN arch/x86/kernel/vsyscall_64.c~profile-likely-unlikely-macros arch/x86/kernel/vsyscall_64.c --- a/arch/x86/kernel/vsyscall_64.c~profile-likely-unlikely-macros +++ a/arch/x86/kernel/vsyscall_64.c @@ -17,6 +17,8 @@ * want per guest time just set the kernel.vsyscall64 sysctl to 0. */ +#define SUPPRESS_LIKELY_PROFILING + #include <linux/time.h> #include <linux/init.h> #include <linux/kernel.h> diff -puN arch/x86/vdso/vclock_gettime.c~profile-likely-unlikely-macros arch/x86/vdso/vclock_gettime.c --- a/arch/x86/vdso/vclock_gettime.c~profile-likely-unlikely-macros +++ a/arch/x86/vdso/vclock_gettime.c @@ -9,6 +9,8 @@ * Also alternative() doesn't work. */ +#define SUPPRESS_LIKELY_PROFILING + #include <linux/kernel.h> #include <linux/posix-timers.h> #include <linux/time.h> diff -puN include/linux/compiler.h~profile-likely-unlikely-macros include/linux/compiler.h --- a/include/linux/compiler.h~profile-likely-unlikely-macros +++ a/include/linux/compiler.h @@ -53,6 +53,41 @@ extern void __chk_io_ptr(const volatile # include <linux/compiler-intel.h> #endif +#if defined(CONFIG_PROFILE_LIKELY) && !defined(SUPPRESS_LIKELY_PROFILING) && \ + !(defined(CONFIG_MODULE_UNLOAD) && defined(MODULE)) +struct likeliness { + char *const file; + unsigned long caller; + unsigned int count[2]; + struct likeliness *next; + unsigned int label; +}; + +extern int do_check_likely(struct likeliness *likeliness, unsigned int exp); + +#define LP_IS_EXPECTED 1 +#define LP_UNSEEN 4 +#define LP_LINE_SHIFT 3 + +#define __check_likely(exp, is_likely) \ + ({ \ + static struct likeliness likeliness = { \ + .file = __FILE__, \ + .label = __LINE__ << LP_LINE_SHIFT | \ + LP_UNSEEN | is_likely, \ + }; \ + do_check_likely(&likeliness, !!(exp)); \ + }) + +/* + * We check for constant values with __builtin_constant_p() since + * it's not interesting to profile them, and there is a compiler + * bug in gcc 3.x which blows up during constant evalution when + * CONFIG_PROFILE_LIKELY is turned on. + */ +#define likely(x) (__builtin_constant_p(x) ? (!!(x)) : __check_likely((x), 1)) +#define unlikely(x) (__builtin_constant_p(x) ? (!!(x)) : __check_likely((x), 0)) +#else /* * Generic compiler-dependent macros required for kernel * build go below this comment. Actual compiler/compiler version @@ -61,6 +96,7 @@ extern void __chk_io_ptr(const volatile #define likely(x) __builtin_expect(!!(x), 1) #define unlikely(x) __builtin_expect(!!(x), 0) +#endif /* Optimization barrier */ #ifndef barrier diff -puN lib/Kconfig.debug~profile-likely-unlikely-macros lib/Kconfig.debug --- a/lib/Kconfig.debug~profile-likely-unlikely-macros +++ a/lib/Kconfig.debug @@ -568,6 +568,14 @@ config DEBUG_SYNCHRO_TEST See Documentation/synchro-test.txt. +config PROFILE_LIKELY + bool "Record return values from likely/unlikely macros" + default n + help + Adds profiling on likely/unlikly macros . To see the + results of the profiling you can view the following, + /proc/likely_prof + config BOOT_PRINTK_DELAY bool "Delay each boot printk message by N milliseconds" depends on DEBUG_KERNEL && PRINTK && GENERIC_CALIBRATE_DELAY diff -puN lib/Makefile~profile-likely-unlikely-macros lib/Makefile --- a/lib/Makefile~profile-likely-unlikely-macros +++ a/lib/Makefile @@ -22,6 +22,9 @@ obj-y += bcd.o div64.o sort.o parser.o h bust_spinlocks.o hexdump.o kasprintf.o bitmap.o scatterlist.o \ string_helpers.o +# likely profiling can cause recursion in ftrace, so don't trace it. +CFLAGS_REMOVE_likely_prof.o = -pg + ifeq ($(CONFIG_DEBUG_KOBJECT),y) CFLAGS_kobject.o += -DDEBUG CFLAGS_kobject_uevent.o += -DDEBUG @@ -82,6 +85,8 @@ obj-$(CONFIG_HAVE_ARCH_TRACEHOOK) += sys obj-$(CONFIG_DYNAMIC_PRINTK_DEBUG) += dynamic_printk.o +obj-$(CONFIG_PROFILE_LIKELY) += likely_prof.o + hostprogs-y := gen_crc32table clean-files := crc32table.h diff -puN /dev/null lib/likely_prof.c --- /dev/null +++ a/lib/likely_prof.c @@ -0,0 +1,150 @@ +/* + * This code should enable profiling the likely and unlikely macros. + * + * Output goes in /proc/likely_prof + * + * Authors: + * Daniel Walker <dwalker@mvista.com> + * Hua Zhong <hzhong@gmail.com> + * Andrew Morton <akpm@osdl.org> + */ + +#include <linux/init.h> +#include <linux/module.h> +#include <linux/types.h> +#include <linux/fs.h> +#include <linux/seq_file.h> +#include <linux/proc_fs.h> +#include <linux/kallsyms.h> + +#include <asm/bug.h> +#include <asm/atomic.h> + +static struct likeliness *likeliness_head; + +int do_check_likely(struct likeliness *likeliness, unsigned int ret) +{ + static unsigned long likely_lock; + + likeliness->count[ret]++; + + if (likeliness->label & LP_UNSEEN) { + /* + * We don't simply use a spinlock because internally to the + * spinlock there is a call to unlikely which causes recursion. + * We opted for this method because we didn't need a preempt/irq + * disable and it was a bit cleaner then using internal __raw + * spinlock calls. + */ + if (!test_and_set_bit_lock(0, &likely_lock)) { + if (likeliness->label & LP_UNSEEN) { + likeliness->label &= (~LP_UNSEEN); + likeliness->next = likeliness_head; + likeliness_head = likeliness; + likeliness->caller = (unsigned long) + __builtin_return_address(0); + } + clear_bit_unlock(0, &likely_lock); + } + } + + return ret; +} +EXPORT_SYMBOL(do_check_likely); + +static void * lp_seq_start(struct seq_file *out, loff_t *pos) +{ + + if (!*pos) { + + seq_printf(out, "Likely Profiling Results\n"); + seq_printf(out, " --------------------------------------------" + "------------------------\n"); + seq_printf(out, "[+- ]Type | # True | # False | Function@" + "Filename:Line\n"); + + out->private = likeliness_head; + } + + return out->private; +} + +static void *lp_seq_next(struct seq_file *out, void *p, loff_t *pos) +{ + struct likeliness *entry = p; + + if (entry->next) { + ++(*pos); + out->private = entry->next; + } else + out->private = NULL; + + return out->private; +} + +static int lp_seq_show(struct seq_file *out, void *p) +{ + struct likeliness *entry = p; + unsigned int pos = entry->count[1]; + unsigned int neg = entry->count[0]; + char function[KSYM_SYMBOL_LEN]; + + /* + * Balanced if the suggestion was false in less than 5% of the tests + */ + if (!(entry->label & LP_IS_EXPECTED)) { + if (pos + neg < 20 * pos) + seq_printf(out, "+"); + else + seq_printf(out, " "); + + seq_printf(out, "unlikely "); + } else { + if (pos + neg < 20 * neg) + seq_printf(out, "-"); + else + seq_printf(out, " "); + + seq_printf(out, "likely "); + } + + sprint_symbol(function, entry->caller); + seq_printf(out, "|%9u|%9u|\t%s@%s:%u\n", pos, neg, function, + entry->file, entry->label >> LP_LINE_SHIFT); + + return 0; +} + +static void lp_seq_stop(struct seq_file *m, void *p) +{ +} + +static struct seq_operations likely_profiling_ops = { + .start = lp_seq_start, + .next = lp_seq_next, + .stop = lp_seq_stop, + .show = lp_seq_show +}; + +static int lp_results_open(struct inode *inode, struct file *file) +{ + return seq_open(file, &likely_profiling_ops); +} + +static struct file_operations proc_likely_operations = { + .open = lp_results_open, + .read = seq_read, + .llseek = seq_lseek, + .release = seq_release, +}; + +static int __init init_likely(void) +{ + struct proc_dir_entry *entry = + proc_create("likely_prof", 0, NULL, &proc_likely_operations); + if (!entry) + return 1; + + return 0; +} +__initcall(init_likely); _ ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH][RFC] trace: profile likely and unlikely annotations 2008-10-28 4:12 ` [PATCH][RFC] trace: profile likely and unlikely annotations Steven Rostedt 2008-10-28 4:23 ` Arjan van de Ven 2008-10-28 4:39 ` Andrew Morton @ 2008-10-28 14:37 ` Theodore Tso 2008-10-28 14:48 ` Arjan van de Ven 2008-10-28 14:49 ` [PATCH][RFC] " Steven Rostedt 2 siblings, 2 replies; 17+ messages in thread From: Theodore Tso @ 2008-10-28 14:37 UTC (permalink / raw) To: Steven Rostedt Cc: LKML, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Arjan van de Ven, Frederic Weisbecker On Tue, Oct 28, 2008 at 12:12:48AM -0400, Steven Rostedt wrote: > > Andrew Morton recently suggested having an in-kernel way to profile > likely and unlikely macros. This patch achieves that goal. Maybe I'm confused, but when I read through the patch, it looks like that 'hit' is incremented whenever the condition is true, and 'missed' is incremented whenever the condition is false, correct? Is that what you intended? So for profile_unlikely, "missed" is good, and "hit" is bad, and for profile_likely, "hit" is good, and "missed" is bad. That seems horribly confusing. If that wasn't what you intended, the meaning of "hit" and "missed" seems to be highly confusing, either way. Can we perhaps use some other terminology? Simply using "True" and "False" would be better, since there's no possible confusion what the labels mean. > +#define unlikely(x) ({ \ > + int ______r; \ > + static struct ftrace_likely_data ______f \ > + __attribute__((__aligned__(4))) \ > + __attribute__((section("_ftrace_unlikely"))); \ > + if (unlikely_notrace(!______f.ip)) \ > + ______f.ip = __THIS_IP__; \ > + ______r = unlikely_notrace(x); \ > + ftrace_likely_update(&______f, ______r); \ > + ______r; \ > + }) Note that unlikely(x) calls ftrace_likely_update(), which does this: > +void ftrace_likely_update(struct ftrace_likely_data *f, int val) > +{ > + /* FIXME: Make this atomic! */ > + if (val) > + f->hit++; > + else > + f->missed++; > +} > +EXPORT_SYMBOL(ftrace_likely_update); So that seems to mean that if unlikely(x) is false, then _____r is 0, which means we increment f->missed. Or am I missing something? I would have thought that if unlikely(x) is false, that's *good*, since it means the unlikely label was correct. And normally, when people think about cache hits vs cache misses, hits are good and misses are bad. Which is why I think the terminology is highly confusing... - Ted ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH][RFC] trace: profile likely and unlikely annotations 2008-10-28 14:37 ` Theodore Tso @ 2008-10-28 14:48 ` Arjan van de Ven 2008-10-28 14:51 ` Steven Rostedt 2008-10-28 14:49 ` [PATCH][RFC] " Steven Rostedt 1 sibling, 1 reply; 17+ messages in thread From: Arjan van de Ven @ 2008-10-28 14:48 UTC (permalink / raw) To: Theodore Tso Cc: Steven Rostedt, LKML, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Frederic Weisbecker On Tue, 28 Oct 2008 10:37:20 -0400 Theodore Tso <tytso@mit.edu> wrote: > On Tue, Oct 28, 2008 at 12:12:48AM -0400, Steven Rostedt wrote: > > > > Andrew Morton recently suggested having an in-kernel way to profile > > likely and unlikely macros. This patch achieves that goal. > > Maybe I'm confused, but when I read through the patch, it looks like > that 'hit' is incremented whenever the condition is true, and 'missed' > is incremented whenever the condition is false, correct? > > Is that what you intended? So for profile_unlikely, "missed" is good, > and "hit" is bad, and for profile_likely, "hit" is good, and "missed" > is bad. That seems horribly confusing. > > If that wasn't what you intended, the meaning of "hit" and "missed" > seems to be highly confusing, either way. Can we perhaps use some > other terminology? Simply using "True" and "False" would be better, > since there's no possible confusion what the labels mean. or "correct" and "incorrect" -- Arjan van de Ven Intel Open Source Technology Centre For development, discussion and tips for power savings, visit http://www.lesswatts.org ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH][RFC] trace: profile likely and unlikely annotations 2008-10-28 14:48 ` Arjan van de Ven @ 2008-10-28 14:51 ` Steven Rostedt 2008-10-29 16:35 ` [PATCH 1/2 v2][RFC] " Steven Rostedt 0 siblings, 1 reply; 17+ messages in thread From: Steven Rostedt @ 2008-10-28 14:51 UTC (permalink / raw) To: Arjan van de Ven Cc: Theodore Tso, LKML, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Frederic Weisbecker On Tue, 28 Oct 2008, Arjan van de Ven wrote: > On Tue, 28 Oct 2008 10:37:20 -0400 > Theodore Tso <tytso@mit.edu> wrote: > > > On Tue, Oct 28, 2008 at 12:12:48AM -0400, Steven Rostedt wrote: > > > > > > Andrew Morton recently suggested having an in-kernel way to profile > > > likely and unlikely macros. This patch achieves that goal. > > > > Maybe I'm confused, but when I read through the patch, it looks like > > that 'hit' is incremented whenever the condition is true, and 'missed' > > is incremented whenever the condition is false, correct? > > > > Is that what you intended? So for profile_unlikely, "missed" is good, > > and "hit" is bad, and for profile_likely, "hit" is good, and "missed" > > is bad. That seems horribly confusing. > > > > If that wasn't what you intended, the meaning of "hit" and "missed" > > seems to be highly confusing, either way. Can we perhaps use some > > other terminology? Simply using "True" and "False" would be better, > > since there's no possible confusion what the labels mean. > > or "correct" and "incorrect" This means that the code will need to be different for both. Or at least a way to differentiate between the two. Not that hard, but I wanted to make the code as trivial as possible. -- Steve ^ permalink raw reply [flat|nested] 17+ messages in thread
* [PATCH 1/2 v2][RFC] trace: profile likely and unlikely annotations 2008-10-28 14:51 ` Steven Rostedt @ 2008-10-29 16:35 ` Steven Rostedt 2008-10-29 16:38 ` [PATCH 2/2 v2][RFC] ftrace: unlikely annotation tracer Steven Rostedt ` (2 more replies) 0 siblings, 3 replies; 17+ messages in thread From: Steven Rostedt @ 2008-10-29 16:35 UTC (permalink / raw) To: LKML Cc: Arjan van de Ven, Theodore Tso, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Frederic Weisbecker, Daniel Walker Andrew Morton recently suggested having an in-kernel way to profile likely and unlikely macros. This patch achieves that goal. When configured, every(*) likely and unlikely macro gets a counter attached to it. When the condition is hit, the hit and misses of that condition are recorded. These numbers can later be retrieved by: /debugfs/tracing/profile_likely - All likely markers /debugfs/tracing/profile_unlikely - All unlikely markers. # cat /debug/tracing/profile_unlikely | \ awk '{if (($1 || $2) && (($2+0.1)/($1+0.1) > 0.25)) { print $0; }}' | \ head -20 correct incorrect Function File Line ------- --------- -------- ---- ---- 46894 38216 __switch_to process_64.c 624 11951 73138 __switch_to process_64.c 594 11951 73097 __switch_to process_64.c 590 117873 35049 need_resched sched.h 2103 1345 711 syscall_get_error syscall.h 51 0 2510 syscall_trace_leave ptrace.c 1568 0 1 native_smp_prepare_cpus smpboot.c 1231 91635 276125 calc_delta_fair sched_fair.c 411 219028 113449 calc_delta_mine sched.c 1279 0 58048 sched_info_queued sched_stats.h 222 55449 71591 pick_next_task_fair sched_fair.c 1394 10 5 yield_task_fair sched_fair.c 983 7117 2553 rt_policy sched.c 144 0 1220 pre_schedule_rt sched_rt.c 1260 1216 52402 pick_next_task_rt sched_rt.c 884 0 48009 sched_info_dequeued sched_stats.h 177 0 14 sched_move_task sched.c 8707 0 14 sched_move_task sched.c 8697 # cat /debug/tracing/profile_likely | \ awk '{if (($1 || $2) && (($2+0.1)/($1+0.1) > 0.25)) { print $0; }}' correct incorrect Function File Line ------- --------- -------- ---- ---- 42987 40240 pick_next_task sched.c 4407 21419 18103 switch_mm mmu_context_64.h 18 0 7 __cancel_work_timer workqueue.c 560 861 3960 clocksource_adjust timekeeping.c 456 390 1913 clocksource_adjust timekeeping.c 450 0 363683 audit_syscall_exit auditsc.c 1570 30 364573 audit_get_context auditsc.c 732 0 362744 audit_syscall_entry auditsc.c 1541 30 879 audit_free auditsc.c 1446 0 952 audit_alloc auditsc.c 862 2606 952 audit_alloc auditsc.c 858 0 6 move_masked_irq migration.c 20 4465 2091 __grab_cache_page filemap.c 2212 9495 2787 iov_iter_advance filemap.c 1884 3121 899 __set_page_dirty page-writeback.c 1134 12874 221371 mapping_unevictable pagemap.h 50 4 10 __flush_cpu_slab slub.c 1466 635239 320760 slab_free slub.c 1731 3105 61055 dentry_lru_del_init dcache.c 153 942 1156 load_elf_binary binfmt_elf.c 904 102 82 disk_put_part genhd.h 206 0 1 tcp_mss_split_point tcp_output.c 1126 As you can see by the above, there's a bit of work to do in rethinking the use of some unlikelys and likelys. Note: the unlikely case had 76 hits that were more than 25%. Note: After submitting my first version of this patch, Andrew Morton showed me a version written by Daniel Walker, where I picked up the following ideas from: 1) Using __builtin_constant_p to avoid profiling fixed values. 2) Using __FILE__ instead of instruction pointers. 3) Using the preprocessor to stop all profiling of likely annotations from vsyscall_64.c. Thanks to Andrew Morton, Arjan van de Ven, Theodore Tso and Ingo Molnar for their feed back on this patch. (*) Not ever unlikely is recorded, those that are used by vsyscalls (a few of them) had to have profiling disabled. Signed-off-by: Steven Rostedt <srostedt@redhat.com> --- arch/x86/kernel/vsyscall_64.c | 8 + include/asm-generic/vmlinux.lds.h | 14 +++ include/linux/compiler.h | 61 ++++++++++++++ kernel/trace/Kconfig | 16 +++ kernel/trace/Makefile | 2 kernel/trace/trace_unlikely.c | 157 ++++++++++++++++++++++++++++++++++++++ 6 files changed, 255 insertions(+), 3 deletions(-) Index: linux-tip.git/kernel/trace/Makefile =================================================================== --- linux-tip.git.orig/kernel/trace/Makefile 2008-10-29 11:30:05.000000000 -0400 +++ linux-tip.git/kernel/trace/Makefile 2008-10-29 12:32:40.000000000 -0400 @@ -25,4 +25,6 @@ obj-$(CONFIG_STACK_TRACER) += trace_stac obj-$(CONFIG_MMIOTRACE) += trace_mmiotrace.o obj-$(CONFIG_BOOT_TRACER) += trace_boot.o +obj-$(CONFIG_TRACE_UNLIKELY_PROFILE) += trace_unlikely.o + libftrace-y := ftrace.o Index: linux-tip.git/arch/x86/kernel/vsyscall_64.c =================================================================== --- linux-tip.git.orig/arch/x86/kernel/vsyscall_64.c 2008-10-29 11:30:05.000000000 -0400 +++ linux-tip.git/arch/x86/kernel/vsyscall_64.c 2008-10-29 11:30:12.000000000 -0400 @@ -17,6 +17,14 @@ * want per guest time just set the kernel.vsyscall64 sysctl to 0. */ +/* Protect userspace from profiling */ +#ifdef CONFIG_TRACE_UNLIKELY_PROFILE +# undef likely +# undef unlikely +# define likely(x) likely_notrace(x) +# define unlikely(x) unlikely_notrace(x) +#endif + #include <linux/time.h> #include <linux/init.h> #include <linux/kernel.h> Index: linux-tip.git/include/asm-generic/vmlinux.lds.h =================================================================== --- linux-tip.git.orig/include/asm-generic/vmlinux.lds.h 2008-10-29 11:30:06.000000000 -0400 +++ linux-tip.git/include/asm-generic/vmlinux.lds.h 2008-10-29 11:30:12.000000000 -0400 @@ -45,6 +45,17 @@ #define MCOUNT_REC() #endif +#ifdef CONFIG_TRACE_UNLIKELY_PROFILE +#define LIKELY_PROFILE() VMLINUX_SYMBOL(__start_likely_profile) = .; \ + *(_ftrace_likely) \ + VMLINUX_SYMBOL(__stop_likely_profile) = .; \ + VMLINUX_SYMBOL(__start_unlikely_profile) = .; \ + *(_ftrace_unlikely) \ + VMLINUX_SYMBOL(__stop_unlikely_profile) = .; +#else +#define LIKELY_PROFILE() +#endif + /* .data section */ #define DATA_DATA \ *(.data) \ @@ -62,7 +73,8 @@ VMLINUX_SYMBOL(__stop___markers) = .; \ VMLINUX_SYMBOL(__start___tracepoints) = .; \ *(__tracepoints) \ - VMLINUX_SYMBOL(__stop___tracepoints) = .; + VMLINUX_SYMBOL(__stop___tracepoints) = .; \ + LIKELY_PROFILE() #define RO_DATA(align) \ . = ALIGN((align)); \ Index: linux-tip.git/include/linux/compiler.h =================================================================== --- linux-tip.git.orig/include/linux/compiler.h 2008-10-29 11:30:06.000000000 -0400 +++ linux-tip.git/include/linux/compiler.h 2008-10-29 11:32:05.000000000 -0400 @@ -59,8 +59,65 @@ extern void __chk_io_ptr(const volatile * specific implementations come from the above header files */ -#define likely(x) __builtin_expect(!!(x), 1) -#define unlikely(x) __builtin_expect(!!(x), 0) +#ifdef CONFIG_TRACE_UNLIKELY_PROFILE +struct ftrace_likely_data { + const char *func; + const char *file; + unsigned line; + unsigned long correct; + unsigned long incorrect; +}; +void ftrace_likely_update(struct ftrace_likely_data *f, int val, int expect); + +#define likely_notrace(x) __builtin_expect(!!(x), 1) +#define unlikely_notrace(x) __builtin_expect(!!(x), 0) + +#define likely_check(x) ({ \ + int ______r; \ + static struct ftrace_likely_data \ + __attribute__((__aligned__(4))) \ + __attribute__((section("_ftrace_likely"))) \ + ______f = { \ + .func = __func__, \ + .file = __FILE__, \ + .line = __LINE__, \ + }; \ + ______f.line = __LINE__; \ + ______r = likely_notrace(x); \ + ftrace_likely_update(&______f, ______r, 1); \ + ______r; \ + }) +#define unlikely_check(x) ({ \ + int ______r; \ + static struct ftrace_likely_data \ + __attribute__((__aligned__(4))) \ + __attribute__((section("_ftrace_unlikely"))) \ + ______f = { \ + .func = __func__, \ + .file = __FILE__, \ + .line = __LINE__, \ + }; \ + ______f.line = __LINE__; \ + ______r = unlikely_notrace(x); \ + ftrace_likely_update(&______f, ______r, 0); \ + ______r; \ + }) + +/* + * Using __builtin_constant_p(x) to ignore cases where the return + * value is always the same. This idea is taken from a similar patch + * written by Daniel Walker. + */ +# ifndef likely +# define likely(x) (__builtin_constant_p(x) ? !!(x) : likely_check(x)) +# endif +# ifndef unlikely +# define unlikely(x) (__builtin_constant_p(x) ? !!(x) : unlikely_check(x)) +# endif +#else +# define likely(x) __builtin_expect(!!(x), 1) +# define unlikely(x) __builtin_expect(!!(x), 0) +#endif /* Optimization barrier */ #ifndef barrier Index: linux-tip.git/kernel/trace/Kconfig =================================================================== --- linux-tip.git.orig/kernel/trace/Kconfig 2008-10-29 11:30:10.000000000 -0400 +++ linux-tip.git/kernel/trace/Kconfig 2008-10-29 12:32:40.000000000 -0400 @@ -138,6 +138,22 @@ config BOOT_TRACER selected, because the self-tests are an initcall as well and that would invalidate the boot trace. ) +config TRACE_UNLIKELY_PROFILE + bool "Trace likely/unlikely profiler" + depends on DEBUG_KERNEL + select TRACING + help + This tracer profiles all the the likely and unlikely macros + in the kernel. It will display the results in: + + /debugfs/tracing/profile_likely + /debugfs/tracing/profile_unlikely + + Note: this will add a significant overhead, only turn this + on if you need to profile the system's use of these macros. + + Say N if unsure. + config STACK_TRACER bool "Trace max stack" depends on HAVE_FUNCTION_TRACER Index: linux-tip.git/kernel/trace/trace_unlikely.c =================================================================== --- /dev/null 1970-01-01 00:00:00.000000000 +0000 +++ linux-tip.git/kernel/trace/trace_unlikely.c 2008-10-29 12:32:40.000000000 -0400 @@ -0,0 +1,157 @@ +/* + * unlikely profiler + * + * Copyright (C) 2008 Steven Rostedt <srostedt@redhat.com> + */ +#include <linux/kallsyms.h> +#include <linux/seq_file.h> +#include <linux/spinlock.h> +#include <linux/debugfs.h> +#include <linux/uaccess.h> +#include <linux/module.h> +#include <linux/ftrace.h> +#include <linux/hash.h> +#include <linux/fs.h> +#include <asm/local.h> +#include "trace.h" + +void ftrace_likely_update(struct ftrace_likely_data *f, int val, int expect) +{ + /* FIXME: Make this atomic! */ + if (val == expect) + f->correct++; + else + f->incorrect++; +} +EXPORT_SYMBOL(ftrace_likely_update); + +struct ftrace_pointer { + void *start; + void *stop; +}; + +static void * +t_next(struct seq_file *m, void *v, loff_t *pos) +{ + struct ftrace_pointer *f = m->private; + struct ftrace_likely_data *p = v; + + (*pos)++; + + if (v == (void *)1) + return f->start; + + ++p; + + if ((void *)p >= (void *)f->stop) + return NULL; + + return p; +} + +static void *t_start(struct seq_file *m, loff_t *pos) +{ + void *t = (void *)1; + loff_t l = 0; + + for (; t && l < *pos; t = t_next(m, t, &l)) + ; + + return t; +} + +static void t_stop(struct seq_file *m, void *p) +{ +} + +static int t_show(struct seq_file *m, void *v) +{ + struct ftrace_likely_data *p = v; + const char *f; + + if (v == (void *)1) { + seq_printf(m, " correct incorrect" + " Function " + " File Line\n" + " ------- ---------" + " -------- " + " ---- ----\n"); + return 0; + } + + /* Only print the file, not the path */ + f = p->file + strlen(p->file); + while (f >= p->file && *f != '/') + f--; + f++; + + seq_printf(m, " %8lu %8lu ", p->correct, p->incorrect); + seq_printf(m, "%-30.30s %-20.20s %d\n", p->func, f, p->line); + return 0; +} + +static struct seq_operations tracing_likely_seq_ops = { + .start = t_start, + .next = t_next, + .stop = t_stop, + .show = t_show, +}; + +static int tracing_likely_open(struct inode *inode, struct file *file) +{ + int ret; + + ret = seq_open(file, &tracing_likely_seq_ops); + if (!ret) { + struct seq_file *m = file->private_data; + m->private = (void *)inode->i_private; + } + + return ret; +} + +static struct file_operations tracing_likely_fops = { + .open = tracing_likely_open, + .read = seq_read, + .llseek = seq_lseek, +}; + +extern unsigned long __start_likely_profile[]; +extern unsigned long __stop_likely_profile[]; +extern unsigned long __start_unlikely_profile[]; +extern unsigned long __stop_unlikely_profile[]; + +static struct ftrace_pointer ftrace_likely_pos = { + .start = __start_likely_profile, + .stop = __stop_likely_profile, +}; + +static struct ftrace_pointer ftrace_unlikely_pos = { + .start = __start_unlikely_profile, + .stop = __stop_unlikely_profile, +}; + +static __init int ftrace_unlikely_init(void) +{ + struct dentry *d_tracer; + struct dentry *entry; + + d_tracer = tracing_init_dentry(); + + entry = debugfs_create_file("profile_likely", 0444, d_tracer, + &ftrace_likely_pos, + &tracing_likely_fops); + if (!entry) + pr_warning("Could not create debugfs 'profile_likely' entry\n"); + + entry = debugfs_create_file("profile_unlikely", 0444, d_tracer, + &ftrace_unlikely_pos, + &tracing_likely_fops); + if (!entry) + pr_warning("Could not create debugfs" + " 'profile_unlikely' entry\n"); + + return 0; +} + +device_initcall(ftrace_unlikely_init); ^ permalink raw reply [flat|nested] 17+ messages in thread
* [PATCH 2/2 v2][RFC] ftrace: unlikely annotation tracer 2008-10-29 16:35 ` [PATCH 1/2 v2][RFC] " Steven Rostedt @ 2008-10-29 16:38 ` Steven Rostedt 2008-10-29 16:40 ` [PATCH 1/2 v2][RFC] trace: profile likely and unlikely annotations Arjan van de Ven 2008-10-29 22:39 ` [PATCH 1/2 v3][RFC] " Steven Rostedt 2 siblings, 0 replies; 17+ messages in thread From: Steven Rostedt @ 2008-10-29 16:38 UTC (permalink / raw) To: LKML Cc: Arjan van de Ven, Theodore Tso, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Frederic Weisbecker, Daniel Walker This patch adds a way to record the instances of the likely and unlikely condition annotations. When "unlikely" is set in /debugfs/tracing/iter_ctrl the unlikely conditions will be added to any of the ftrace tracers. For example: irqbalance-2662 [002] 41127.102858: [correct] debug_mutex_free_waiter 51 <idle>-0 [001] 41127.102858: [correct] add_preempt_count 4307 irqbalance-2662 [002] 41127.102859: [INCORRECT] debug_smp_processor_id 15 <idle>-0 [001] 41127.102860: [correct] add_preempt_count 4316 irqbalance-2662 [002] 41127.102861: [correct] slab_alloc 1608 Which shows the normal tracer heading, as well as whether the condition was correct "[correct]" or was mistaken "[INCORRECT]", followed by the function and line number. Signed-off-by: Steven Rostedt <srostedt@redhat.com> --- kernel/Makefile | 5 + kernel/trace/Kconfig | 22 +++++++ kernel/trace/Makefile | 5 + kernel/trace/ring_buffer.c | 11 +++ kernel/trace/trace.c | 37 +++++++++++ kernel/trace/trace.h | 43 +++++++++++++ kernel/trace/trace_unlikely.c | 130 ++++++++++++++++++++++++++++++++++++++++++ 7 files changed, 253 insertions(+) Index: linux-tip.git/kernel/trace/Kconfig =================================================================== --- linux-tip.git.orig/kernel/trace/Kconfig 2008-10-29 12:32:30.000000000 -0400 +++ linux-tip.git/kernel/trace/Kconfig 2008-10-29 12:32:35.000000000 -0400 @@ -154,6 +154,28 @@ config TRACE_UNLIKELY_PROFILE Say N if unsure. +config TRACING_UNLIKELY + bool + help + Selected by tracers that will trace the likely and unlikely + conditions. This prevents the tracers themselves from being + profiled. Profiling the tracing infrastructure can only happen + when the likelys and unlikelys are not being traced. + +config UNLIKELY_TRACER + bool "Trace likely/unlikely instances" + depends on TRACE_UNLIKELY_PROFILE + select TRACING_UNLIKELY + help + This is traces the events of likely and unlikely condition + calls in the kernel. The difference between this and the + "Trace likely/unlikely profiler" is that this is not a + histogram of the callers, but actually places the calling + events into a running buffer to see when and where the + events happened, as well as their results. + + Say N if unsure. + config STACK_TRACER bool "Trace max stack" depends on HAVE_FUNCTION_TRACER Index: linux-tip.git/kernel/Makefile =================================================================== --- linux-tip.git.orig/kernel/Makefile 2008-10-29 12:32:30.000000000 -0400 +++ linux-tip.git/kernel/Makefile 2008-10-29 12:32:35.000000000 -0400 @@ -24,6 +24,11 @@ CFLAGS_REMOVE_sched_clock.o = -pg CFLAGS_REMOVE_sched.o = -mno-spe -pg endif +ifdef CONFIG_TRACING_UNLIKELY +# Do not profile tracepoint if we are tracing the unlikely conditions +CFLAGS_tracepoint.o += '-Dunlikely(x)=unlikely_notrace(x)' +endif + obj-$(CONFIG_FREEZER) += freezer.o obj-$(CONFIG_PROFILING) += profile.o obj-$(CONFIG_SYSCTL_SYSCALL_CHECK) += sysctl_check.o Index: linux-tip.git/kernel/trace/Makefile =================================================================== --- linux-tip.git.orig/kernel/trace/Makefile 2008-10-29 12:32:30.000000000 -0400 +++ linux-tip.git/kernel/trace/Makefile 2008-10-29 12:32:35.000000000 -0400 @@ -10,6 +10,11 @@ CFLAGS_trace_selftest_dynamic.o = -pg obj-y += trace_selftest_dynamic.o endif +ifdef CONFIG_TRACING_UNLIKELY +KBUILD_CFLAGS += '-Dlikely(x)=likely_notrace(x)' +KBUILD_CFLAGS += '-Dunlikely(x)=unlikely_notrace(x)' +endif + obj-$(CONFIG_FUNCTION_TRACER) += libftrace.o obj-$(CONFIG_RING_BUFFER) += ring_buffer.o Index: linux-tip.git/kernel/trace/trace_unlikely.c =================================================================== --- linux-tip.git.orig/kernel/trace/trace_unlikely.c 2008-10-29 12:32:30.000000000 -0400 +++ linux-tip.git/kernel/trace/trace_unlikely.c 2008-10-29 12:32:35.000000000 -0400 @@ -15,8 +15,138 @@ #include <asm/local.h> #include "trace.h" +#ifdef CONFIG_UNLIKELY_TRACER + +static int unlikely_tracing_enabled __read_mostly; +static DEFINE_MUTEX(unlikely_tracing_mutex); +static DEFINE_PER_CPU(atomic_t, unlikely_trace_disabled); +static struct trace_array *unlikely_tracer; + +void trace_unlikely_stop(void) +{ + /* preemption should be disabled */ + int cpu = smp_processor_id(); + + atomic_inc(&per_cpu(unlikely_trace_disabled, cpu)); +} + +void trace_unlikely_start(void) +{ + /* preemption should be disabled */ + int cpu = smp_processor_id(); + + atomic_dec(&per_cpu(unlikely_trace_disabled, cpu)); +} + +static void +probe_likely_condition(struct ftrace_likely_data *f, int val, int expect) +{ + struct trace_array *tr = unlikely_tracer; + struct ring_buffer_event *event; + struct trace_unlikely *entry; + unsigned long flags, irq_flags; + int cpu, resched, pc; + + if (unlikely(!tr)) + return; + + pc = preempt_count(); + /* Can be called within schedule */ + resched = need_resched(); + preempt_disable_notrace(); + cpu = raw_smp_processor_id(); + if (atomic_inc_return(&per_cpu(unlikely_trace_disabled, cpu)) != 1) + goto out; + + event = ring_buffer_lock_reserve(tr->buffer, sizeof(*entry), + &irq_flags); + if (!event) + goto out; + + local_save_flags(flags); + entry = ring_buffer_event_data(event); + tracing_generic_entry_update(&entry->ent, flags, pc); + entry->ent.type = TRACE_UNLIKELY; + + /* + * I would love to save just the ftrace_likely_data pointer, but + * this code can also be used by modules. Ugly things can happen + * if the module is unloaded, and then we go and read the + * pointer. This is slower, but much safer. + */ + + strncpy(entry->func, f->func, TRACE_FUNC_SIZE); + strncpy(entry->file, f->file, TRACE_FILE_SIZE); + entry->func[TRACE_FUNC_SIZE] = 0; + entry->file[TRACE_FILE_SIZE] = 0; + entry->line = f->line; + entry->correct = val == expect; + + ring_buffer_unlock_commit(tr->buffer, event, irq_flags); + + out: + atomic_dec(&per_cpu(unlikely_trace_disabled, cpu)); + if (resched) + preempt_enable_no_resched_notrace(); + else + preempt_enable_notrace(); +} + +static inline +void trace_likely_condition(struct ftrace_likely_data *f, int val, int expect) +{ + if (!unlikely_tracing_enabled) + return; + + probe_likely_condition(f, val, expect); +} + +int enable_unlikely_tracing(struct trace_array *tr) +{ + int ret = 0; + + mutex_lock(&unlikely_tracing_mutex); + unlikely_tracer = tr; + /* + * Must be seen before enabling. The reader is a condition + * where we do not need a matching rmb() + */ + smp_wmb(); + unlikely_tracing_enabled++; + mutex_unlock(&unlikely_tracing_mutex); + + return ret; +} + +void disable_unlikely_tracing(void) +{ + mutex_lock(&unlikely_tracing_mutex); + + if (!unlikely_tracing_enabled) + goto out_unlock; + + unlikely_tracing_enabled--; + + out_unlock: + mutex_unlock(&unlikely_tracing_mutex); +} +#else +static inline +void trace_likely_condition(struct ftrace_likely_data *f, int val, int expect) +{ +} +#endif /* CONFIG_UNLIKELY_TRACER */ + void ftrace_likely_update(struct ftrace_likely_data *f, int val, int expect) { + /* + * I would love to have a trace point here instead, but the + * trace point code is so inundated with unlikely and likely + * conditions that the recursive nightmare that exists is too + * much to try to get working. At least for now. + */ + trace_likely_condition(f, val, expect); + /* FIXME: Make this atomic! */ if (val == expect) f->correct++; Index: linux-tip.git/kernel/trace/trace.c =================================================================== --- linux-tip.git.orig/kernel/trace/trace.c 2008-10-29 12:32:30.000000000 -0400 +++ linux-tip.git/kernel/trace/trace.c 2008-10-29 12:32:35.000000000 -0400 @@ -235,6 +235,9 @@ static const char *trace_options[] = { "stacktrace", "sched-tree", "ftrace_printk", +#ifdef CONFIG_UNLIKELY_TRACER + "unlikely", +#endif NULL }; @@ -1457,6 +1460,17 @@ print_lat_fmt(struct trace_iterator *ite trace_seq_print_cont(s, iter); break; } + case TRACE_UNLIKELY: { + struct trace_unlikely *field; + + trace_assign_type(field, entry); + + trace_seq_printf(s, "[%s] %-30.30s %d\n", + field->correct ? "correct" : "INCORRECT", + field->func, + field->line); + break; + } default: trace_seq_printf(s, "Unknown type %d\n", entry->type); } @@ -1593,6 +1607,17 @@ static enum print_line_t print_trace_fmt trace_seq_print_cont(s, iter); break; } + case TRACE_UNLIKELY: { + struct trace_unlikely *field; + + trace_assign_type(field, entry); + + trace_seq_printf(s, "[%s] %-30.30s %d\n", + field->correct ? "correct" : "INCORRECT", + field->func, + field->line); + break; + } } return TRACE_TYPE_HANDLED; } @@ -1675,6 +1700,10 @@ static enum print_line_t print_raw_fmt(s trace_seq_print_cont(s, iter); break; } + case TRACE_UNLIKELY: { + /* IGNORE */ + break; + }; } return TRACE_TYPE_HANDLED; } @@ -2362,8 +2391,14 @@ tracing_ctrl_write(struct file *filp, co tr->ctrl = val; + if (!val) + trace_unlikely_disable(); + if (current_trace && current_trace->ctrl_update) current_trace->ctrl_update(tr); + + if (val) + trace_unlikely_enable(tr); } mutex_unlock(&trace_types_lock); @@ -2425,6 +2460,7 @@ tracing_set_trace_write(struct file *fil if (t == current_trace) goto out; + trace_unlikely_disable(); if (current_trace && current_trace->reset) current_trace->reset(tr); @@ -2432,6 +2468,7 @@ tracing_set_trace_write(struct file *fil if (t->init) t->init(tr); + trace_unlikely_enable(tr); out: mutex_unlock(&trace_types_lock); Index: linux-tip.git/kernel/trace/trace.h =================================================================== --- linux-tip.git.orig/kernel/trace/trace.h 2008-10-29 12:32:30.000000000 -0400 +++ linux-tip.git/kernel/trace/trace.h 2008-10-29 12:32:35.000000000 -0400 @@ -21,6 +21,7 @@ enum trace_type { TRACE_SPECIAL, TRACE_MMIO_RW, TRACE_MMIO_MAP, + TRACE_UNLIKELY, TRACE_BOOT, __TRACE_LAST_TYPE @@ -117,6 +118,16 @@ struct trace_boot { struct boot_trace initcall; }; +#define TRACE_FUNC_SIZE 30 +#define TRACE_FILE_SIZE 20 +struct trace_unlikely { + struct trace_entry ent; + unsigned line; + char func[TRACE_FUNC_SIZE+1]; + char file[TRACE_FILE_SIZE+1]; + char correct; +}; + /* * trace_flag_type is an enumeration that holds different * states when a trace occurs. These are: @@ -217,6 +228,7 @@ extern void __ftrace_bad_type(void); IF_ASSIGN(var, ent, struct trace_mmiotrace_map, \ TRACE_MMIO_MAP); \ IF_ASSIGN(var, ent, struct trace_boot, TRACE_BOOT); \ + IF_ASSIGN(var, ent, struct trace_unlikely, TRACE_UNLIKELY); \ __ftrace_bad_type(); \ } while (0) @@ -413,8 +425,39 @@ enum trace_iterator_flags { TRACE_ITER_STACKTRACE = 0x100, TRACE_ITER_SCHED_TREE = 0x200, TRACE_ITER_PRINTK = 0x400, +#ifdef CONFIG_UNLIKELY_TRACER + TRACE_ITER_UNLIKELY = 0x800, +#endif }; extern struct tracer nop_trace; +#ifdef CONFIG_UNLIKELY_TRACER +extern int enable_unlikely_tracing(struct trace_array *tr); +extern void disable_unlikely_tracing(void); +static inline int trace_unlikely_enable(struct trace_array *tr) +{ + if (trace_flags & TRACE_ITER_UNLIKELY) + return enable_unlikely_tracing(tr); + return 0; +} +static inline void trace_unlikely_disable(void) +{ + /* due to races, always disable */ + disable_unlikely_tracing(); +} +extern void trace_unlikely_stop(void); +extern void trace_unlikely_start(void); +#else +static inline int trace_unlikely_enable(struct trace_array *tr) +{ + return 0; +} +static inline void trace_unlikely_disable(void) +{ +} +static inline void trace_unlikely_stop(void) { } +static inline void trace_unlikely_start(void) { } +#endif /* CONFIG_UNLIKELY_TRACER */ + #endif /* _LINUX_KERNEL_TRACE_H */ Index: linux-tip.git/kernel/trace/ring_buffer.c =================================================================== --- linux-tip.git.orig/kernel/trace/ring_buffer.c 2008-10-29 12:32:30.000000000 -0400 +++ linux-tip.git/kernel/trace/ring_buffer.c 2008-10-29 12:32:35.000000000 -0400 @@ -16,6 +16,8 @@ #include <linux/list.h> #include <linux/fs.h> +#include "trace.h" + /* Up this if you want to test the TIME_EXTENTS and normalization */ #define DEBUG_SHIFT 0 @@ -1139,7 +1141,14 @@ ring_buffer_lock_reserve(struct ring_buf if (length > BUF_PAGE_SIZE) goto out; + /* + * Ugly, but the unlikely tracing will enter back into + * the ring buffer code. Namely through the timestamp, causing + * a triggering of the "again" loop, that will be infinite. + */ + trace_unlikely_stop(); event = rb_reserve_next_event(cpu_buffer, RINGBUF_TYPE_DATA, length); + trace_unlikely_start(); if (!event) goto out; @@ -1251,8 +1260,10 @@ int ring_buffer_write(struct ring_buffer goto out; event_length = rb_calculate_event_length(length); + trace_unlikely_stop(); event = rb_reserve_next_event(cpu_buffer, RINGBUF_TYPE_DATA, event_length); + trace_unlikely_start(); if (!event) goto out; ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH 1/2 v2][RFC] trace: profile likely and unlikely annotations 2008-10-29 16:35 ` [PATCH 1/2 v2][RFC] " Steven Rostedt 2008-10-29 16:38 ` [PATCH 2/2 v2][RFC] ftrace: unlikely annotation tracer Steven Rostedt @ 2008-10-29 16:40 ` Arjan van de Ven 2008-10-29 22:39 ` [PATCH 1/2 v3][RFC] " Steven Rostedt 2 siblings, 0 replies; 17+ messages in thread From: Arjan van de Ven @ 2008-10-29 16:40 UTC (permalink / raw) To: Steven Rostedt Cc: LKML, Theodore Tso, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Frederic Weisbecker, Daniel Walker On Wed, 29 Oct 2008 12:35:44 -0400 (EDT) Steven Rostedt <rostedt@goodmis.org> wrote: > > Andrew Morton recently suggested having an in-kernel way to profile > likely and unlikely macros. This patch achieves that goal. > > When configured, every(*) likely and unlikely macro gets a counter > attached to it. When the condition is hit, the hit and misses of that > condition are recorded. These numbers can later be retrieved by: > > /debugfs/tracing/profile_likely - All likely markers > /debugfs/tracing/profile_unlikely - All unlikely markers. > I like the general approach it'd be very convenient if the debugfs files also had a percentage-incorrect (or percentage-correct, either way) listed, so that we humans can focus straight on which ones are outliers rather than having to do math in our heads first... -- Arjan van de Ven Intel Open Source Technology Centre For development, discussion and tips for power savings, visit http://www.lesswatts.org ^ permalink raw reply [flat|nested] 17+ messages in thread
* [PATCH 1/2 v3][RFC] trace: profile likely and unlikely annotations 2008-10-29 16:35 ` [PATCH 1/2 v2][RFC] " Steven Rostedt 2008-10-29 16:38 ` [PATCH 2/2 v2][RFC] ftrace: unlikely annotation tracer Steven Rostedt 2008-10-29 16:40 ` [PATCH 1/2 v2][RFC] trace: profile likely and unlikely annotations Arjan van de Ven @ 2008-10-29 22:39 ` Steven Rostedt 2008-10-29 22:40 ` [PATCH 2/2 v3][RFC] ftrace: unlikely annotation tracer Steven Rostedt 2008-10-30 14:32 ` [PATCH 1/2 v3][RFC] trace: profile likely and unlikely annotations Jörn Engel 2 siblings, 2 replies; 17+ messages in thread From: Steven Rostedt @ 2008-10-29 22:39 UTC (permalink / raw) To: LKML Cc: Arjan van de Ven, Theodore Tso, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Frederic Weisbecker, Daniel Walker, Linus Torvalds [ changes since v2: Added Arjan's recommendation about calculating a percentage of failures in the output. Question: Do people prefer the "func file line" notation or the kallsyms "func+0x<offset>" notation? ] Andrew Morton recently suggested having an in-kernel way to profile likely and unlikely macros. This patch achieves that goal. When configured, every(*) likely and unlikely macro gets a counter attached to it. When the condition is hit, the hit and misses of that condition are recorded. These numbers can later be retrieved by: /debugfs/tracing/profile_likely - All likely markers /debugfs/tracing/profile_unlikely - All unlikely markers. # cat /debug/tracing/profile_unlikely | head correct incorrect % Function File Line ------- --------- - -------- ---- ---- 2494 0 0 do_arch_prctl process_64.c 832 0 0 0 do_arch_prctl process_64.c 804 2988 0 0 IS_ERR err.h 34 124668 6133 4 __switch_to process_64.c 673 130811 0 0 __switch_to process_64.c 639 69768 61064 87 __switch_to process_64.c 624 15557 115251 100 __switch_to process_64.c 594 15555 115227 100 __switch_to process_64.c 590 # cat /debug/tracing/profile_unlikely | \ awk '{ if ($3 > 25) print $0; }' |head -20 59851 49675 82 __switch_to process_64.c 624 12688 96800 100 __switch_to process_64.c 594 12688 96778 100 __switch_to process_64.c 590 152290 49467 32 need_resched sched.h 2103 1385 1034 74 syscall_get_error syscall.h 51 0 2967 100 syscall_trace_leave ptrace.c 1568 0 1 100 native_smp_prepare_cpus smpboot.c 1231 304770 92199 30 update_curr sched_fair.c 489 113195 297065 100 calc_delta_fair sched_fair.c 411 227018 123309 54 calc_delta_mine sched.c 1279 0 70299 100 sched_info_queued sched_stats.h 222 67434 100268 100 pick_next_task_fair sched_fair.c 1394 7 9 100 yield_task_fair sched_fair.c 983 7215 3321 46 rt_policy sched.c 144 0 1611 100 pre_schedule_rt sched_rt.c 1260 1607 66013 100 pick_next_task_rt sched_rt.c 884 0 60198 100 sched_info_dequeued sched_stats.h 177 0 15 100 sched_move_task sched.c 8707 0 15 100 sched_move_task sched.c 8697 68373 50822 74 schedule sched.c 4467 # cat /debug/tracing/profile_likely | awk '{ if ($3 > 25) print $0; }' 54665 53649 98 pick_next_task sched.c 4407 25344 23614 93 switch_mm mmu_context_64.h 18 0 7 100 __cancel_work_timer workqueue.c 560 1202 1354 100 clocksource_adjust timekeeping.c 456 0 441888 100 audit_syscall_exit auditsc.c 1570 22 442776 100 audit_get_context auditsc.c 732 0 440930 100 audit_syscall_entry auditsc.c 1541 22 889 100 audit_free auditsc.c 1446 0 962 100 audit_alloc auditsc.c 862 2614 962 36 audit_alloc auditsc.c 858 0 6 100 move_masked_irq migration.c 20 4482 2110 47 __grab_cache_page filemap.c 2212 9575 2787 29 iov_iter_advance filemap.c 1884 3121 905 28 __set_page_dirty page-writeback.c 1134 12882 222991 100 mapping_unevictable pagemap.h 50 4 11 100 __flush_cpu_slab slub.c 1466 664688 320446 48 slab_free slub.c 1731 2962 61920 100 dentry_lru_del_init dcache.c 153 950 1157 100 load_elf_binary binfmt_elf.c 904 102 82 80 disk_put_part genhd.h 206 0 4 100 tcp_mss_split_point tcp_output.c 1126 As you can see by the above, there's a bit of work to do in rethinking the use of some unlikelys and likelys. Note: the unlikely case had 77 hits that were more than 25%. Note: After submitting my first version of this patch, Andrew Morton showed me a version written by Daniel Walker, where I picked up the following ideas from: 1) Using __builtin_constant_p to avoid profiling fixed values. 2) Using __FILE__ instead of instruction pointers. 3) Using the preprocessor to stop all profiling of likely annotations from vsyscall_64.c. Thanks to Andrew Morton, Arjan van de Ven, Theodore Tso and Ingo Molnar for their feed back on this patch. (*) Not ever unlikely is recorded, those that are used by vsyscalls (a few of them) had to have profiling disabled. Signed-off-by: Steven Rostedt <srostedt@redhat.com> --- arch/x86/kernel/vsyscall_64.c | 8 + include/asm-generic/vmlinux.lds.h | 14 ++- include/linux/compiler.h | 61 +++++++++++++ kernel/trace/Kconfig | 16 +++ kernel/trace/Makefile | 2 kernel/trace/trace_unlikely.c | 167 ++++++++++++++++++++++++++++++++++++++ 6 files changed, 265 insertions(+), 3 deletions(-) Index: linux-tip.git/kernel/trace/Makefile =================================================================== --- linux-tip.git.orig/kernel/trace/Makefile 2008-10-29 12:38:54.000000000 -0400 +++ linux-tip.git/kernel/trace/Makefile 2008-10-29 18:31:26.000000000 -0400 @@ -25,4 +25,6 @@ obj-$(CONFIG_STACK_TRACER) += trace_stac obj-$(CONFIG_MMIOTRACE) += trace_mmiotrace.o obj-$(CONFIG_BOOT_TRACER) += trace_boot.o +obj-$(CONFIG_TRACE_UNLIKELY_PROFILE) += trace_unlikely.o + libftrace-y := ftrace.o Index: linux-tip.git/arch/x86/kernel/vsyscall_64.c =================================================================== --- linux-tip.git.orig/arch/x86/kernel/vsyscall_64.c 2008-10-29 12:38:54.000000000 -0400 +++ linux-tip.git/arch/x86/kernel/vsyscall_64.c 2008-10-29 16:13:00.000000000 -0400 @@ -17,6 +17,14 @@ * want per guest time just set the kernel.vsyscall64 sysctl to 0. */ +/* Protect userspace from profiling */ +#ifdef CONFIG_TRACE_UNLIKELY_PROFILE +# undef likely +# undef unlikely +# define likely(x) likely_notrace(x) +# define unlikely(x) unlikely_notrace(x) +#endif + #include <linux/time.h> #include <linux/init.h> #include <linux/kernel.h> Index: linux-tip.git/include/asm-generic/vmlinux.lds.h =================================================================== --- linux-tip.git.orig/include/asm-generic/vmlinux.lds.h 2008-10-29 12:38:54.000000000 -0400 +++ linux-tip.git/include/asm-generic/vmlinux.lds.h 2008-10-29 16:13:00.000000000 -0400 @@ -45,6 +45,17 @@ #define MCOUNT_REC() #endif +#ifdef CONFIG_TRACE_UNLIKELY_PROFILE +#define LIKELY_PROFILE() VMLINUX_SYMBOL(__start_likely_profile) = .; \ + *(_ftrace_likely) \ + VMLINUX_SYMBOL(__stop_likely_profile) = .; \ + VMLINUX_SYMBOL(__start_unlikely_profile) = .; \ + *(_ftrace_unlikely) \ + VMLINUX_SYMBOL(__stop_unlikely_profile) = .; +#else +#define LIKELY_PROFILE() +#endif + /* .data section */ #define DATA_DATA \ *(.data) \ @@ -62,7 +73,8 @@ VMLINUX_SYMBOL(__stop___markers) = .; \ VMLINUX_SYMBOL(__start___tracepoints) = .; \ *(__tracepoints) \ - VMLINUX_SYMBOL(__stop___tracepoints) = .; + VMLINUX_SYMBOL(__stop___tracepoints) = .; \ + LIKELY_PROFILE() #define RO_DATA(align) \ . = ALIGN((align)); \ Index: linux-tip.git/include/linux/compiler.h =================================================================== --- linux-tip.git.orig/include/linux/compiler.h 2008-10-29 12:38:54.000000000 -0400 +++ linux-tip.git/include/linux/compiler.h 2008-10-29 16:13:00.000000000 -0400 @@ -59,8 +59,65 @@ extern void __chk_io_ptr(const volatile * specific implementations come from the above header files */ -#define likely(x) __builtin_expect(!!(x), 1) -#define unlikely(x) __builtin_expect(!!(x), 0) +#ifdef CONFIG_TRACE_UNLIKELY_PROFILE +struct ftrace_likely_data { + const char *func; + const char *file; + unsigned line; + unsigned long correct; + unsigned long incorrect; +}; +void ftrace_likely_update(struct ftrace_likely_data *f, int val, int expect); + +#define likely_notrace(x) __builtin_expect(!!(x), 1) +#define unlikely_notrace(x) __builtin_expect(!!(x), 0) + +#define likely_check(x) ({ \ + int ______r; \ + static struct ftrace_likely_data \ + __attribute__((__aligned__(4))) \ + __attribute__((section("_ftrace_likely"))) \ + ______f = { \ + .func = __func__, \ + .file = __FILE__, \ + .line = __LINE__, \ + }; \ + ______f.line = __LINE__; \ + ______r = likely_notrace(x); \ + ftrace_likely_update(&______f, ______r, 1); \ + ______r; \ + }) +#define unlikely_check(x) ({ \ + int ______r; \ + static struct ftrace_likely_data \ + __attribute__((__aligned__(4))) \ + __attribute__((section("_ftrace_unlikely"))) \ + ______f = { \ + .func = __func__, \ + .file = __FILE__, \ + .line = __LINE__, \ + }; \ + ______f.line = __LINE__; \ + ______r = unlikely_notrace(x); \ + ftrace_likely_update(&______f, ______r, 0); \ + ______r; \ + }) + +/* + * Using __builtin_constant_p(x) to ignore cases where the return + * value is always the same. This idea is taken from a similar patch + * written by Daniel Walker. + */ +# ifndef likely +# define likely(x) (__builtin_constant_p(x) ? !!(x) : likely_check(x)) +# endif +# ifndef unlikely +# define unlikely(x) (__builtin_constant_p(x) ? !!(x) : unlikely_check(x)) +# endif +#else +# define likely(x) __builtin_expect(!!(x), 1) +# define unlikely(x) __builtin_expect(!!(x), 0) +#endif /* Optimization barrier */ #ifndef barrier Index: linux-tip.git/kernel/trace/Kconfig =================================================================== --- linux-tip.git.orig/kernel/trace/Kconfig 2008-10-29 16:12:53.000000000 -0400 +++ linux-tip.git/kernel/trace/Kconfig 2008-10-29 18:31:26.000000000 -0400 @@ -138,6 +138,22 @@ config BOOT_TRACER selected, because the self-tests are an initcall as well and that would invalidate the boot trace. ) +config TRACE_UNLIKELY_PROFILE + bool "Trace likely/unlikely profiler" + depends on DEBUG_KERNEL + select TRACING + help + This tracer profiles all the the likely and unlikely macros + in the kernel. It will display the results in: + + /debugfs/tracing/profile_likely + /debugfs/tracing/profile_unlikely + + Note: this will add a significant overhead, only turn this + on if you need to profile the system's use of these macros. + + Say N if unsure. + config STACK_TRACER bool "Trace max stack" depends on HAVE_FUNCTION_TRACER Index: linux-tip.git/kernel/trace/trace_unlikely.c =================================================================== --- /dev/null 1970-01-01 00:00:00.000000000 +0000 +++ linux-tip.git/kernel/trace/trace_unlikely.c 2008-10-29 18:31:26.000000000 -0400 @@ -0,0 +1,167 @@ +/* + * unlikely profiler + * + * Copyright (C) 2008 Steven Rostedt <srostedt@redhat.com> + */ +#include <linux/kallsyms.h> +#include <linux/seq_file.h> +#include <linux/spinlock.h> +#include <linux/debugfs.h> +#include <linux/uaccess.h> +#include <linux/module.h> +#include <linux/ftrace.h> +#include <linux/hash.h> +#include <linux/fs.h> +#include <asm/local.h> +#include "trace.h" + +void ftrace_likely_update(struct ftrace_likely_data *f, int val, int expect) +{ + /* FIXME: Make this atomic! */ + if (val == expect) + f->correct++; + else + f->incorrect++; +} +EXPORT_SYMBOL(ftrace_likely_update); + +struct ftrace_pointer { + void *start; + void *stop; +}; + +static void * +t_next(struct seq_file *m, void *v, loff_t *pos) +{ + struct ftrace_pointer *f = m->private; + struct ftrace_likely_data *p = v; + + (*pos)++; + + if (v == (void *)1) + return f->start; + + ++p; + + if ((void *)p >= (void *)f->stop) + return NULL; + + return p; +} + +static void *t_start(struct seq_file *m, loff_t *pos) +{ + void *t = (void *)1; + loff_t l = 0; + + for (; t && l < *pos; t = t_next(m, t, &l)) + ; + + return t; +} + +static void t_stop(struct seq_file *m, void *p) +{ +} + +static int t_show(struct seq_file *m, void *v) +{ + struct ftrace_likely_data *p = v; + const char *f; + unsigned long percent; + + if (v == (void *)1) { + seq_printf(m, " correct incorrect %% " + " Function " + " File Line\n" + " ------- --------- - " + " -------- " + " ---- ----\n"); + return 0; + } + + /* Only print the file, not the path */ + f = p->file + strlen(p->file); + while (f >= p->file && *f != '/') + f--; + f++; + + if (p->correct) { + percent = p->incorrect * 100; + percent /= p->correct; + /* No need to see huge numbers */ + if (percent > 100) + percent = 100; + } else + percent = p->incorrect ? 100 : 0; + + seq_printf(m, "%8lu %8lu %3lu ", p->correct, p->incorrect, percent); + seq_printf(m, "%-30.30s %-20.20s %d\n", p->func, f, p->line); + return 0; +} + +static struct seq_operations tracing_likely_seq_ops = { + .start = t_start, + .next = t_next, + .stop = t_stop, + .show = t_show, +}; + +static int tracing_likely_open(struct inode *inode, struct file *file) +{ + int ret; + + ret = seq_open(file, &tracing_likely_seq_ops); + if (!ret) { + struct seq_file *m = file->private_data; + m->private = (void *)inode->i_private; + } + + return ret; +} + +static struct file_operations tracing_likely_fops = { + .open = tracing_likely_open, + .read = seq_read, + .llseek = seq_lseek, +}; + +extern unsigned long __start_likely_profile[]; +extern unsigned long __stop_likely_profile[]; +extern unsigned long __start_unlikely_profile[]; +extern unsigned long __stop_unlikely_profile[]; + +static struct ftrace_pointer ftrace_likely_pos = { + .start = __start_likely_profile, + .stop = __stop_likely_profile, +}; + +static struct ftrace_pointer ftrace_unlikely_pos = { + .start = __start_unlikely_profile, + .stop = __stop_unlikely_profile, +}; + +static __init int ftrace_unlikely_init(void) +{ + struct dentry *d_tracer; + struct dentry *entry; + + d_tracer = tracing_init_dentry(); + + entry = debugfs_create_file("profile_likely", 0444, d_tracer, + &ftrace_likely_pos, + &tracing_likely_fops); + if (!entry) + pr_warning("Could not create debugfs 'profile_likely' entry\n"); + + entry = debugfs_create_file("profile_unlikely", 0444, d_tracer, + &ftrace_unlikely_pos, + &tracing_likely_fops); + if (!entry) + pr_warning("Could not create debugfs" + " 'profile_unlikely' entry\n"); + + return 0; +} + +device_initcall(ftrace_unlikely_init); ^ permalink raw reply [flat|nested] 17+ messages in thread
* [PATCH 2/2 v3][RFC] ftrace: unlikely annotation tracer 2008-10-29 22:39 ` [PATCH 1/2 v3][RFC] " Steven Rostedt @ 2008-10-29 22:40 ` Steven Rostedt 2008-10-30 14:32 ` [PATCH 1/2 v3][RFC] trace: profile likely and unlikely annotations Jörn Engel 1 sibling, 0 replies; 17+ messages in thread From: Steven Rostedt @ 2008-10-29 22:40 UTC (permalink / raw) To: LKML Cc: Arjan van de Ven, Theodore Tso, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Frederic Weisbecker, Daniel Walker, Linus Torvalds [ Changes since v2: Changed to a "func:file:line-num" format. ] This patch adds a way to record the instances of the likely and unlikely condition annotations. When "unlikely" is set in /debugfs/tracing/iter_ctrl the unlikely conditions will be added to any of the ftrace tracers. For example: bash-3471 [003] 357.014755: [INCORRECT] sched_info_dequeued:sched_stats.h:177 bash-3471 [003] 357.014756: [correct] update_curr:sched_fair.c:489 bash-3471 [003] 357.014758: [correct] calc_delta_fair:sched_fair.c:411 bash-3471 [003] 357.014759: [correct] account_group_exec_runtime:sched_stats.h:356 bash-3471 [003] 357.014761: [correct] update_curr:sched_fair.c:489 bash-3471 [003] 357.014763: [INCORRECT] calc_delta_fair:sched_fair.c:411 bash-3471 [003] 357.014765: [correct] calc_delta_mine:sched.c:1279 Which shows the normal tracer heading, as well as whether the condition was correct "[correct]" or was mistaken "[INCORRECT]", followed by the function, file name and line number. Signed-off-by: Steven Rostedt <srostedt@redhat.com> --- kernel/Makefile | 5 + kernel/trace/Kconfig | 22 ++++++ kernel/trace/Makefile | 5 + kernel/trace/ring_buffer.c | 11 +++ kernel/trace/trace.c | 39 +++++++++++ kernel/trace/trace.h | 43 +++++++++++++ kernel/trace/trace_unlikely.c | 137 ++++++++++++++++++++++++++++++++++++++++++ 7 files changed, 262 insertions(+) Index: linux-tip.git/kernel/trace/Kconfig =================================================================== --- linux-tip.git.orig/kernel/trace/Kconfig 2008-10-29 17:01:11.000000000 -0400 +++ linux-tip.git/kernel/trace/Kconfig 2008-10-29 17:46:37.000000000 -0400 @@ -154,6 +154,28 @@ config TRACE_UNLIKELY_PROFILE Say N if unsure. +config TRACING_UNLIKELY + bool + help + Selected by tracers that will trace the likely and unlikely + conditions. This prevents the tracers themselves from being + profiled. Profiling the tracing infrastructure can only happen + when the likelys and unlikelys are not being traced. + +config UNLIKELY_TRACER + bool "Trace likely/unlikely instances" + depends on TRACE_UNLIKELY_PROFILE + select TRACING_UNLIKELY + help + This is traces the events of likely and unlikely condition + calls in the kernel. The difference between this and the + "Trace likely/unlikely profiler" is that this is not a + histogram of the callers, but actually places the calling + events into a running buffer to see when and where the + events happened, as well as their results. + + Say N if unsure. + config STACK_TRACER bool "Trace max stack" depends on HAVE_FUNCTION_TRACER Index: linux-tip.git/kernel/Makefile =================================================================== --- linux-tip.git.orig/kernel/Makefile 2008-10-29 17:01:11.000000000 -0400 +++ linux-tip.git/kernel/Makefile 2008-10-29 17:46:37.000000000 -0400 @@ -24,6 +24,11 @@ CFLAGS_REMOVE_sched_clock.o = -pg CFLAGS_REMOVE_sched.o = -mno-spe -pg endif +ifdef CONFIG_TRACING_UNLIKELY +# Do not profile tracepoint if we are tracing the unlikely conditions +CFLAGS_tracepoint.o += '-Dunlikely(x)=unlikely_notrace(x)' +endif + obj-$(CONFIG_FREEZER) += freezer.o obj-$(CONFIG_PROFILING) += profile.o obj-$(CONFIG_SYSCTL_SYSCALL_CHECK) += sysctl_check.o Index: linux-tip.git/kernel/trace/Makefile =================================================================== --- linux-tip.git.orig/kernel/trace/Makefile 2008-10-29 17:01:11.000000000 -0400 +++ linux-tip.git/kernel/trace/Makefile 2008-10-29 17:46:37.000000000 -0400 @@ -10,6 +10,11 @@ CFLAGS_trace_selftest_dynamic.o = -pg obj-y += trace_selftest_dynamic.o endif +ifdef CONFIG_TRACING_UNLIKELY +KBUILD_CFLAGS += '-Dlikely(x)=likely_notrace(x)' +KBUILD_CFLAGS += '-Dunlikely(x)=unlikely_notrace(x)' +endif + obj-$(CONFIG_FUNCTION_TRACER) += libftrace.o obj-$(CONFIG_RING_BUFFER) += ring_buffer.o Index: linux-tip.git/kernel/trace/trace_unlikely.c =================================================================== --- linux-tip.git.orig/kernel/trace/trace_unlikely.c 2008-10-29 17:25:31.000000000 -0400 +++ linux-tip.git/kernel/trace/trace_unlikely.c 2008-10-29 18:03:30.000000000 -0400 @@ -15,8 +15,145 @@ #include <asm/local.h> #include "trace.h" +#ifdef CONFIG_UNLIKELY_TRACER + +static int unlikely_tracing_enabled __read_mostly; +static DEFINE_MUTEX(unlikely_tracing_mutex); +static DEFINE_PER_CPU(atomic_t, unlikely_trace_disabled); +static struct trace_array *unlikely_tracer; + +void trace_unlikely_stop(void) +{ + /* preemption should be disabled */ + int cpu = smp_processor_id(); + + atomic_inc(&per_cpu(unlikely_trace_disabled, cpu)); +} + +void trace_unlikely_start(void) +{ + /* preemption should be disabled */ + int cpu = smp_processor_id(); + + atomic_dec(&per_cpu(unlikely_trace_disabled, cpu)); +} + +static void +probe_likely_condition(struct ftrace_likely_data *f, int val, int expect) +{ + struct trace_array *tr = unlikely_tracer; + struct ring_buffer_event *event; + struct trace_unlikely *entry; + unsigned long flags, irq_flags; + int cpu, resched, pc; + const char *p; + + /* + * I would love to save just the ftrace_likely_data pointer, but + * this code can also be used by modules. Ugly things can happen + * if the module is unloaded, and then we go and read the + * pointer. This is slower, but much safer. + */ + + if (unlikely(!tr)) + return; + + pc = preempt_count(); + /* Can be called within schedule */ + resched = need_resched(); + preempt_disable_notrace(); + cpu = raw_smp_processor_id(); + if (atomic_inc_return(&per_cpu(unlikely_trace_disabled, cpu)) != 1) + goto out; + + event = ring_buffer_lock_reserve(tr->buffer, sizeof(*entry), + &irq_flags); + if (!event) + goto out; + + local_save_flags(flags); + entry = ring_buffer_event_data(event); + tracing_generic_entry_update(&entry->ent, flags, pc); + entry->ent.type = TRACE_UNLIKELY; + + /* Strip off the path, only save the file */ + p = f->file + strlen(f->file); + while (p >= f->file && *p != '/') + p--; + p++; + + strncpy(entry->func, f->func, TRACE_FUNC_SIZE); + strncpy(entry->file, p, TRACE_FILE_SIZE); + entry->func[TRACE_FUNC_SIZE] = 0; + entry->file[TRACE_FILE_SIZE] = 0; + entry->line = f->line; + entry->correct = val == expect; + + ring_buffer_unlock_commit(tr->buffer, event, irq_flags); + + out: + atomic_dec(&per_cpu(unlikely_trace_disabled, cpu)); + if (resched) + preempt_enable_no_resched_notrace(); + else + preempt_enable_notrace(); +} + +static inline +void trace_likely_condition(struct ftrace_likely_data *f, int val, int expect) +{ + if (!unlikely_tracing_enabled) + return; + + probe_likely_condition(f, val, expect); +} + +int enable_unlikely_tracing(struct trace_array *tr) +{ + int ret = 0; + + mutex_lock(&unlikely_tracing_mutex); + unlikely_tracer = tr; + /* + * Must be seen before enabling. The reader is a condition + * where we do not need a matching rmb() + */ + smp_wmb(); + unlikely_tracing_enabled++; + mutex_unlock(&unlikely_tracing_mutex); + + return ret; +} + +void disable_unlikely_tracing(void) +{ + mutex_lock(&unlikely_tracing_mutex); + + if (!unlikely_tracing_enabled) + goto out_unlock; + + unlikely_tracing_enabled--; + + out_unlock: + mutex_unlock(&unlikely_tracing_mutex); +} +#else +static inline +void trace_likely_condition(struct ftrace_likely_data *f, int val, int expect) +{ +} +#endif /* CONFIG_UNLIKELY_TRACER */ + void ftrace_likely_update(struct ftrace_likely_data *f, int val, int expect) { + /* + * I would love to have a trace point here instead, but the + * trace point code is so inundated with unlikely and likely + * conditions that the recursive nightmare that exists is too + * much to try to get working. At least for now. + */ + trace_likely_condition(f, val, expect); + /* FIXME: Make this atomic! */ if (val == expect) f->correct++; Index: linux-tip.git/kernel/trace/trace.c =================================================================== --- linux-tip.git.orig/kernel/trace/trace.c 2008-10-29 17:01:11.000000000 -0400 +++ linux-tip.git/kernel/trace/trace.c 2008-10-29 18:04:04.000000000 -0400 @@ -235,6 +235,9 @@ static const char *trace_options[] = { "stacktrace", "sched-tree", "ftrace_printk", +#ifdef CONFIG_UNLIKELY_TRACER + "unlikely", +#endif NULL }; @@ -1457,6 +1460,18 @@ print_lat_fmt(struct trace_iterator *ite trace_seq_print_cont(s, iter); break; } + case TRACE_UNLIKELY: { + struct trace_unlikely *field; + + trace_assign_type(field, entry); + + trace_seq_printf(s, "[%s] %s:%s:%d\n", + field->correct ? "correct" : "INCORRECT", + field->func, + field->file, + field->line); + break; + } default: trace_seq_printf(s, "Unknown type %d\n", entry->type); } @@ -1593,6 +1608,18 @@ static enum print_line_t print_trace_fmt trace_seq_print_cont(s, iter); break; } + case TRACE_UNLIKELY: { + struct trace_unlikely *field; + + trace_assign_type(field, entry); + + trace_seq_printf(s, "[%s] %s:%s:%d\n", + field->correct ? "correct" : "INCORRECT", + field->func, + field->file, + field->line); + break; + } } return TRACE_TYPE_HANDLED; } @@ -1675,6 +1702,10 @@ static enum print_line_t print_raw_fmt(s trace_seq_print_cont(s, iter); break; } + case TRACE_UNLIKELY: { + /* IGNORE */ + break; + }; } return TRACE_TYPE_HANDLED; } @@ -2362,8 +2393,14 @@ tracing_ctrl_write(struct file *filp, co tr->ctrl = val; + if (!val) + trace_unlikely_disable(); + if (current_trace && current_trace->ctrl_update) current_trace->ctrl_update(tr); + + if (val) + trace_unlikely_enable(tr); } mutex_unlock(&trace_types_lock); @@ -2425,6 +2462,7 @@ tracing_set_trace_write(struct file *fil if (t == current_trace) goto out; + trace_unlikely_disable(); if (current_trace && current_trace->reset) current_trace->reset(tr); @@ -2432,6 +2470,7 @@ tracing_set_trace_write(struct file *fil if (t->init) t->init(tr); + trace_unlikely_enable(tr); out: mutex_unlock(&trace_types_lock); Index: linux-tip.git/kernel/trace/trace.h =================================================================== --- linux-tip.git.orig/kernel/trace/trace.h 2008-10-29 17:01:11.000000000 -0400 +++ linux-tip.git/kernel/trace/trace.h 2008-10-29 17:46:37.000000000 -0400 @@ -21,6 +21,7 @@ enum trace_type { TRACE_SPECIAL, TRACE_MMIO_RW, TRACE_MMIO_MAP, + TRACE_UNLIKELY, TRACE_BOOT, __TRACE_LAST_TYPE @@ -117,6 +118,16 @@ struct trace_boot { struct boot_trace initcall; }; +#define TRACE_FUNC_SIZE 30 +#define TRACE_FILE_SIZE 20 +struct trace_unlikely { + struct trace_entry ent; + unsigned line; + char func[TRACE_FUNC_SIZE+1]; + char file[TRACE_FILE_SIZE+1]; + char correct; +}; + /* * trace_flag_type is an enumeration that holds different * states when a trace occurs. These are: @@ -217,6 +228,7 @@ extern void __ftrace_bad_type(void); IF_ASSIGN(var, ent, struct trace_mmiotrace_map, \ TRACE_MMIO_MAP); \ IF_ASSIGN(var, ent, struct trace_boot, TRACE_BOOT); \ + IF_ASSIGN(var, ent, struct trace_unlikely, TRACE_UNLIKELY); \ __ftrace_bad_type(); \ } while (0) @@ -413,8 +425,39 @@ enum trace_iterator_flags { TRACE_ITER_STACKTRACE = 0x100, TRACE_ITER_SCHED_TREE = 0x200, TRACE_ITER_PRINTK = 0x400, +#ifdef CONFIG_UNLIKELY_TRACER + TRACE_ITER_UNLIKELY = 0x800, +#endif }; extern struct tracer nop_trace; +#ifdef CONFIG_UNLIKELY_TRACER +extern int enable_unlikely_tracing(struct trace_array *tr); +extern void disable_unlikely_tracing(void); +static inline int trace_unlikely_enable(struct trace_array *tr) +{ + if (trace_flags & TRACE_ITER_UNLIKELY) + return enable_unlikely_tracing(tr); + return 0; +} +static inline void trace_unlikely_disable(void) +{ + /* due to races, always disable */ + disable_unlikely_tracing(); +} +extern void trace_unlikely_stop(void); +extern void trace_unlikely_start(void); +#else +static inline int trace_unlikely_enable(struct trace_array *tr) +{ + return 0; +} +static inline void trace_unlikely_disable(void) +{ +} +static inline void trace_unlikely_stop(void) { } +static inline void trace_unlikely_start(void) { } +#endif /* CONFIG_UNLIKELY_TRACER */ + #endif /* _LINUX_KERNEL_TRACE_H */ Index: linux-tip.git/kernel/trace/ring_buffer.c =================================================================== --- linux-tip.git.orig/kernel/trace/ring_buffer.c 2008-10-29 17:01:11.000000000 -0400 +++ linux-tip.git/kernel/trace/ring_buffer.c 2008-10-29 17:46:37.000000000 -0400 @@ -16,6 +16,8 @@ #include <linux/list.h> #include <linux/fs.h> +#include "trace.h" + /* Up this if you want to test the TIME_EXTENTS and normalization */ #define DEBUG_SHIFT 0 @@ -1151,7 +1153,14 @@ ring_buffer_lock_reserve(struct ring_buf if (length > BUF_PAGE_SIZE) goto out; + /* + * Ugly, but the unlikely tracing will enter back into + * the ring buffer code. Namely through the timestamp, causing + * a triggering of the "again" loop, that will be infinite. + */ + trace_unlikely_stop(); event = rb_reserve_next_event(cpu_buffer, RINGBUF_TYPE_DATA, length); + trace_unlikely_start(); if (!event) goto out; @@ -1263,8 +1272,10 @@ int ring_buffer_write(struct ring_buffer goto out; event_length = rb_calculate_event_length(length); + trace_unlikely_stop(); event = rb_reserve_next_event(cpu_buffer, RINGBUF_TYPE_DATA, event_length); + trace_unlikely_start(); if (!event) goto out; ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH 1/2 v3][RFC] trace: profile likely and unlikely annotations 2008-10-29 22:39 ` [PATCH 1/2 v3][RFC] " Steven Rostedt 2008-10-29 22:40 ` [PATCH 2/2 v3][RFC] ftrace: unlikely annotation tracer Steven Rostedt @ 2008-10-30 14:32 ` Jörn Engel 2008-10-30 14:55 ` Theodore Tso 1 sibling, 1 reply; 17+ messages in thread From: Jörn Engel @ 2008-10-30 14:32 UTC (permalink / raw) To: Steven Rostedt Cc: LKML, Arjan van de Ven, Theodore Tso, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Frederic Weisbecker, Daniel Walker, Linus Torvalds On Wed, 29 October 2008 18:39:55 -0400, Steven Rostedt wrote: > > 69768 61064 87 __switch_to process_64.c 624 > 15557 115251 100 __switch_to process_64.c 594 > 15555 115227 100 __switch_to process_64.c 590 I may be out of school for a while, but that math sure looks odd. > + if (p->correct) { > + percent = p->incorrect * 100; > + percent /= p->correct; percent /= p->correct + p->incorect; > + /* No need to see huge numbers */ > + if (percent > 100) > + percent = 100; > + } else > + percent = p->incorrect ? 100 : 0; Jörn -- To my face you have the audacity to advise me to become a thief - the worst kind of thief that is conceivable, a thief of spiritual things, a thief of ideas! It is insufferable, intolerable! -- M. Binet in Scarabouche ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH 1/2 v3][RFC] trace: profile likely and unlikely annotations 2008-10-30 14:32 ` [PATCH 1/2 v3][RFC] trace: profile likely and unlikely annotations Jörn Engel @ 2008-10-30 14:55 ` Theodore Tso 2008-10-30 15:10 ` Steven Rostedt 0 siblings, 1 reply; 17+ messages in thread From: Theodore Tso @ 2008-10-30 14:55 UTC (permalink / raw) To: Jörn Engel Cc: Steven Rostedt, LKML, Arjan van de Ven, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Frederic Weisbecker, Daniel Walker, Linus Torvalds On Thu, Oct 30, 2008 at 03:32:39PM +0100, Jörn Engel wrote: > On Wed, 29 October 2008 18:39:55 -0400, Steven Rostedt wrote: > > > > 69768 61064 87 __switch_to process_64.c 624 > > 15557 115251 100 __switch_to process_64.c 594 > > 15555 115227 100 __switch_to process_64.c 590 > > I may be out of school for a while, but that math sure looks odd. > > > + if (p->correct) { > > + percent = p->incorrect * 100; > > + percent /= p->correct; > percent /= p->correct + p->incorect; And once you do the above fix, I don't think what is below is necessary any more. :-) > > + /* No need to see huge numbers */ > > + if (percent > 100) > > + percent = 100; I would also calculate the percent correct rather than the percent incorrect, on the general theory that 100% good, 0% bad is easier for my little brain to understand, but that's just a minor thing... - Ted ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH 1/2 v3][RFC] trace: profile likely and unlikely annotations 2008-10-30 14:55 ` Theodore Tso @ 2008-10-30 15:10 ` Steven Rostedt 0 siblings, 0 replies; 17+ messages in thread From: Steven Rostedt @ 2008-10-30 15:10 UTC (permalink / raw) To: Theodore Tso Cc: Jörn Engel, LKML, Arjan van de Ven, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Frederic Weisbecker, Daniel Walker, Linus Torvalds On Thu, 30 Oct 2008, Theodore Tso wrote: > On Thu, Oct 30, 2008 at 03:32:39PM +0100, J?rn Engel wrote: > > On Wed, 29 October 2008 18:39:55 -0400, Steven Rostedt wrote: > > > > > > 69768 61064 87 __switch_to process_64.c 624 > > > 15557 115251 100 __switch_to process_64.c 594 > > > 15555 115227 100 __switch_to process_64.c 590 > > > > I may be out of school for a while, but that math sure looks odd. > > > > > + if (p->correct) { > > > + percent = p->incorrect * 100; > > > + percent /= p->correct; > > percent /= p->correct + p->incorect; > > And once you do the above fix, I don't think what is below is > necessary any more. :-) Bah! Total brain-fart. Thanks ;-) > > > > + /* No need to see huge numbers */ > > > + if (percent > 100) > > > + percent = 100; > > I would also calculate the percent correct rather than the percent > incorrect, on the general theory that 100% good, 0% bad is easier for > my little brain to understand, but that's just a minor thing... I thought about whether or not to show percent correct or precent incorrect. I chose, incorrect, just because it is easier to spot the trouble makers. You can say, lets allow 25% incorrect, better than saying lets have a minimum of 75%. I think the mind can pick out those that go over a number better than it can see those that are under a number. Thanks, -- Steve ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH][RFC] trace: profile likely and unlikely annotations 2008-10-28 14:37 ` Theodore Tso 2008-10-28 14:48 ` Arjan van de Ven @ 2008-10-28 14:49 ` Steven Rostedt 2008-10-28 18:29 ` Theodore Tso 1 sibling, 1 reply; 17+ messages in thread From: Steven Rostedt @ 2008-10-28 14:49 UTC (permalink / raw) To: Theodore Tso Cc: LKML, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Arjan van de Ven, Frederic Weisbecker On Tue, 28 Oct 2008, Theodore Tso wrote: > On Tue, Oct 28, 2008 at 12:12:48AM -0400, Steven Rostedt wrote: > > > > Andrew Morton recently suggested having an in-kernel way to profile > > likely and unlikely macros. This patch achieves that goal. > > Maybe I'm confused, but when I read through the patch, it looks like > that 'hit' is incremented whenever the condition is true, and 'missed' > is incremented whenever the condition is false, correct? Correct. > > Is that what you intended? So for profile_unlikely, "missed" is good, > and "hit" is bad, and for profile_likely, "hit" is good, and "missed" > is bad. That seems horribly confusing. Correct. Yeah, I figured I'd get complaints about this (hence the RFC). If you look at my awk example, you will also notice that I switched the $1 and $2 around when reading the other file. This can be confusing either way. I did this to reuse the code for both outputs. > > If that wasn't what you intended, the meaning of "hit" and "missed" > seems to be highly confusing, either way. Can we perhaps use some > other terminology? Simply using "True" and "False" would be better, > since there's no possible confusion what the labels mean. So renaming 'hit' and 'miss' to 'True' and 'False' would be good enough? That is, it will still mean that a 'True' is bad for unlikely but good for a likely? > > > +#define unlikely(x) ({ \ > > + int ______r; \ > > + static struct ftrace_likely_data ______f \ > > + __attribute__((__aligned__(4))) \ > > + __attribute__((section("_ftrace_unlikely"))); \ > > + if (unlikely_notrace(!______f.ip)) \ > > + ______f.ip = __THIS_IP__; \ > > + ______r = unlikely_notrace(x); \ > > + ftrace_likely_update(&______f, ______r); \ > > + ______r; \ > > + }) > > Note that unlikely(x) calls ftrace_likely_update(), which does this: > > > +void ftrace_likely_update(struct ftrace_likely_data *f, int val) > > +{ > > + /* FIXME: Make this atomic! */ > > + if (val) > > + f->hit++; > > + else > > + f->missed++; > > +} > > +EXPORT_SYMBOL(ftrace_likely_update); > > > So that seems to mean that if unlikely(x) is false, then _____r is 0, > which means we increment f->missed. Or am I missing something? > > I would have thought that if unlikely(x) is false, that's *good*, > since it means the unlikely label was correct. And normally, when > people think about cache hits vs cache misses, hits are good and > misses are bad. Which is why I think the terminology is highly > confusing... OK, I'm fine with changing the terminology. v2 will do: s/hit/True/ s/missed/False/ Fine with you? -- Steve ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH][RFC] trace: profile likely and unlikely annotations 2008-10-28 14:49 ` [PATCH][RFC] " Steven Rostedt @ 2008-10-28 18:29 ` Theodore Tso 2008-10-28 18:41 ` Steven Rostedt 0 siblings, 1 reply; 17+ messages in thread From: Theodore Tso @ 2008-10-28 18:29 UTC (permalink / raw) To: Steven Rostedt Cc: LKML, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Arjan van de Ven, Frederic Weisbecker On Tue, Oct 28, 2008 at 10:49:16AM -0400, Steven Rostedt wrote: > > OK, I'm fine with changing the terminology. v2 will do: > > s/hit/True/ > s/missed/False/ > > Fine with you? I'm OK with either that, or with Arjan's suggestion of "Correct" and "Incorrect" --- although that would changing a line in the definition of #define unlikely(x): ftrace_likely_update(&______f, !______r); Either "True" / "False" or "Correct" / "Incorrect" has the advantage of being unambiguous. "Correct" / "Incorrect" has the advantage that people don't have to think about the fact that for /proc/profile_unlikely, high numbers of "False" is a good thing, where as for /proc/profile_likely, high numbers of "True" is a good thing. With "Correct" / "Incorrect" it's easier to undersatnd that high numbers of "Correct" is good. So I can see why Arjan suggested Correct/Incorrect, although I can live with either. - Ted ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH][RFC] trace: profile likely and unlikely annotations 2008-10-28 18:29 ` Theodore Tso @ 2008-10-28 18:41 ` Steven Rostedt 0 siblings, 0 replies; 17+ messages in thread From: Steven Rostedt @ 2008-10-28 18:41 UTC (permalink / raw) To: Theodore Tso Cc: LKML, Mike Snitzer, Andrew Morton, Ingo Molnar, Thomas Gleixner, Peter Zijlstra, Arjan van de Ven, Frederic Weisbecker On Tue, 28 Oct 2008, Theodore Tso wrote: > On Tue, Oct 28, 2008 at 10:49:16AM -0400, Steven Rostedt wrote: > > > > OK, I'm fine with changing the terminology. v2 will do: > > > > s/hit/True/ > > s/missed/False/ > > > > Fine with you? > > I'm OK with either that, or with Arjan's suggestion of "Correct" and > "Incorrect" --- although that would changing a line in the definition > of #define unlikely(x): > > ftrace_likely_update(&______f, !______r); > > Either "True" / "False" or "Correct" / "Incorrect" has the advantage > of being unambiguous. "Correct" / "Incorrect" has the advantage that > people don't have to think about the fact that for > /proc/profile_unlikely, high numbers of "False" is a good thing, where > as for /proc/profile_likely, high numbers of "True" is a good thing. > With "Correct" / "Incorrect" it's easier to undersatnd that high > numbers of "Correct" is good. > > So I can see why Arjan suggested Correct/Incorrect, although I can > live with either. I'm almost done with v2. Using Arjan's version (Correct/Incorrect) was actually a trivial change. -- Steve ^ permalink raw reply [flat|nested] 17+ messages in thread
end of thread, other threads:[~2008-10-30 15:10 UTC | newest]
Thread overview: 17+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
[not found] <170fa0d20810271529g3c64ae89me29ed8b65a9c3b5e@mail.gmail.com>
[not found] ` <alpine.DEB.1.10.0810271918390.19731@gandalf.stny.rr.com>
[not found] ` <20081028001340.GB9797@mit.edu>
2008-10-28 4:12 ` [PATCH][RFC] trace: profile likely and unlikely annotations Steven Rostedt
2008-10-28 4:23 ` Arjan van de Ven
2008-10-28 4:39 ` Andrew Morton
2008-10-28 14:37 ` Theodore Tso
2008-10-28 14:48 ` Arjan van de Ven
2008-10-28 14:51 ` Steven Rostedt
2008-10-29 16:35 ` [PATCH 1/2 v2][RFC] " Steven Rostedt
2008-10-29 16:38 ` [PATCH 2/2 v2][RFC] ftrace: unlikely annotation tracer Steven Rostedt
2008-10-29 16:40 ` [PATCH 1/2 v2][RFC] trace: profile likely and unlikely annotations Arjan van de Ven
2008-10-29 22:39 ` [PATCH 1/2 v3][RFC] " Steven Rostedt
2008-10-29 22:40 ` [PATCH 2/2 v3][RFC] ftrace: unlikely annotation tracer Steven Rostedt
2008-10-30 14:32 ` [PATCH 1/2 v3][RFC] trace: profile likely and unlikely annotations Jörn Engel
2008-10-30 14:55 ` Theodore Tso
2008-10-30 15:10 ` Steven Rostedt
2008-10-28 14:49 ` [PATCH][RFC] " Steven Rostedt
2008-10-28 18:29 ` Theodore Tso
2008-10-28 18:41 ` Steven Rostedt
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).