diff options
| -rw-r--r-- | arch/x86/kernel/process_64.c | 3 | ||||
| -rw-r--r-- | arch/x86/lib/Makefile | 1 | ||||
| -rw-r--r-- | arch/x86/lib/thunk_32.S | 47 | ||||
| -rw-r--r-- | arch/x86/lib/thunk_64.S | 19 | ||||
| -rw-r--r-- | include/asm-x86/irqflags.h | 24 | ||||
| -rw-r--r-- | include/linux/ftrace.h | 8 | ||||
| -rw-r--r-- | include/linux/irqflags.h | 12 | ||||
| -rw-r--r-- | kernel/fork.c | 2 | ||||
| -rw-r--r-- | kernel/lockdep.c | 23 | ||||
| -rw-r--r-- | kernel/printk.c | 2 | ||||
| -rw-r--r-- | kernel/trace/Kconfig | 18 | ||||
| -rw-r--r-- | kernel/trace/Makefile | 1 | ||||
| -rw-r--r-- | kernel/trace/trace_irqsoff.c | 402 |
13 files changed, 531 insertions, 31 deletions
diff --git a/arch/x86/kernel/process_64.c b/arch/x86/kernel/process_64.c index e2319f39988b..dd349c92f051 100644 --- a/arch/x86/kernel/process_64.c +++ b/arch/x86/kernel/process_64.c | |||
| @@ -165,7 +165,10 @@ void cpu_idle(void) | |||
| 165 | */ | 165 | */ |
| 166 | local_irq_disable(); | 166 | local_irq_disable(); |
| 167 | enter_idle(); | 167 | enter_idle(); |
| 168 | /* Don't trace irqs off for idle */ | ||
| 169 | stop_critical_timings(); | ||
| 168 | idle(); | 170 | idle(); |
| 171 | start_critical_timings(); | ||
| 169 | /* In many cases the interrupt that ended idle | 172 | /* In many cases the interrupt that ended idle |
| 170 | has already called exit_idle. But some idle | 173 | has already called exit_idle. But some idle |
| 171 | loops can be woken up without interrupt. */ | 174 | loops can be woken up without interrupt. */ |
diff --git a/arch/x86/lib/Makefile b/arch/x86/lib/Makefile index 76f60f52a885..84aa2883fe15 100644 --- a/arch/x86/lib/Makefile +++ b/arch/x86/lib/Makefile | |||
| @@ -5,6 +5,7 @@ | |||
| 5 | obj-$(CONFIG_SMP) := msr-on-cpu.o | 5 | obj-$(CONFIG_SMP) := msr-on-cpu.o |
| 6 | 6 | ||
| 7 | lib-y := delay_$(BITS).o | 7 | lib-y := delay_$(BITS).o |
| 8 | lib-y += thunk_$(BITS).o | ||
| 8 | lib-y += usercopy_$(BITS).o getuser_$(BITS).o putuser_$(BITS).o | 9 | lib-y += usercopy_$(BITS).o getuser_$(BITS).o putuser_$(BITS).o |
| 9 | lib-y += memcpy_$(BITS).o | 10 | lib-y += memcpy_$(BITS).o |
| 10 | 11 | ||
diff --git a/arch/x86/lib/thunk_32.S b/arch/x86/lib/thunk_32.S new file mode 100644 index 000000000000..650b11e00ecc --- /dev/null +++ b/arch/x86/lib/thunk_32.S | |||
| @@ -0,0 +1,47 @@ | |||
| 1 | /* | ||
| 2 | * Trampoline to trace irqs off. (otherwise CALLER_ADDR1 might crash) | ||
| 3 | * Copyright 2008 by Steven Rostedt, Red Hat, Inc | ||
| 4 | * (inspired by Andi Kleen's thunk_64.S) | ||
| 5 | * Subject to the GNU public license, v.2. No warranty of any kind. | ||
| 6 | */ | ||
| 7 | |||
| 8 | #include <linux/linkage.h> | ||
| 9 | |||
| 10 | #define ARCH_TRACE_IRQS_ON \ | ||
| 11 | pushl %eax; \ | ||
| 12 | pushl %ecx; \ | ||
| 13 | pushl %edx; \ | ||
| 14 | call trace_hardirqs_on; \ | ||
| 15 | popl %edx; \ | ||
| 16 | popl %ecx; \ | ||
| 17 | popl %eax; | ||
| 18 | |||
| 19 | #define ARCH_TRACE_IRQS_OFF \ | ||
| 20 | pushl %eax; \ | ||
| 21 | pushl %ecx; \ | ||
| 22 | pushl %edx; \ | ||
| 23 | call trace_hardirqs_off; \ | ||
| 24 | popl %edx; \ | ||
| 25 | popl %ecx; \ | ||
| 26 | popl %eax; | ||
| 27 | |||
| 28 | #ifdef CONFIG_TRACE_IRQFLAGS | ||
| 29 | /* put return address in eax (arg1) */ | ||
| 30 | .macro thunk_ra name,func | ||
| 31 | .globl \name | ||
| 32 | \name: | ||
| 33 | pushl %eax | ||
| 34 | pushl %ecx | ||
| 35 | pushl %edx | ||
| 36 | /* Place EIP in the arg1 */ | ||
| 37 | movl 3*4(%esp), %eax | ||
| 38 | call \func | ||
| 39 | popl %edx | ||
| 40 | popl %ecx | ||
| 41 | popl %eax | ||
| 42 | ret | ||
| 43 | .endm | ||
| 44 | |||
| 45 | thunk_ra trace_hardirqs_on_thunk,trace_hardirqs_on_caller | ||
| 46 | thunk_ra trace_hardirqs_off_thunk,trace_hardirqs_off_caller | ||
| 47 | #endif | ||
diff --git a/arch/x86/lib/thunk_64.S b/arch/x86/lib/thunk_64.S index e009251d4e9f..bf9a7d5a5428 100644 --- a/arch/x86/lib/thunk_64.S +++ b/arch/x86/lib/thunk_64.S | |||
| @@ -2,6 +2,7 @@ | |||
| 2 | * Save registers before calling assembly functions. This avoids | 2 | * Save registers before calling assembly functions. This avoids |
| 3 | * disturbance of register allocation in some inline assembly constructs. | 3 | * disturbance of register allocation in some inline assembly constructs. |
| 4 | * Copyright 2001,2002 by Andi Kleen, SuSE Labs. | 4 | * Copyright 2001,2002 by Andi Kleen, SuSE Labs. |
| 5 | * Added trace_hardirqs callers - Copyright 2007 Steven Rostedt, Red Hat, Inc. | ||
| 5 | * Subject to the GNU public license, v.2. No warranty of any kind. | 6 | * Subject to the GNU public license, v.2. No warranty of any kind. |
| 6 | */ | 7 | */ |
| 7 | 8 | ||
| @@ -42,8 +43,22 @@ | |||
| 42 | #endif | 43 | #endif |
| 43 | 44 | ||
| 44 | #ifdef CONFIG_TRACE_IRQFLAGS | 45 | #ifdef CONFIG_TRACE_IRQFLAGS |
| 45 | thunk trace_hardirqs_on_thunk,trace_hardirqs_on | 46 | /* put return address in rdi (arg1) */ |
| 46 | thunk trace_hardirqs_off_thunk,trace_hardirqs_off | 47 | .macro thunk_ra name,func |
| 48 | .globl \name | ||
| 49 | \name: | ||
| 50 | CFI_STARTPROC | ||
| 51 | SAVE_ARGS | ||
| 52 | /* SAVE_ARGS pushs 9 elements */ | ||
| 53 | /* the next element would be the rip */ | ||
| 54 | movq 9*8(%rsp), %rdi | ||
| 55 | call \func | ||
| 56 | jmp restore | ||
| 57 | CFI_ENDPROC | ||
| 58 | .endm | ||
| 59 | |||
| 60 | thunk_ra trace_hardirqs_on_thunk,trace_hardirqs_on_caller | ||
| 61 | thunk_ra trace_hardirqs_off_thunk,trace_hardirqs_off_caller | ||
| 47 | #endif | 62 | #endif |
| 48 | 63 | ||
| 49 | #ifdef CONFIG_DEBUG_LOCK_ALLOC | 64 | #ifdef CONFIG_DEBUG_LOCK_ALLOC |
diff --git a/include/asm-x86/irqflags.h b/include/asm-x86/irqflags.h index c242527f970e..24d71b1eb189 100644 --- a/include/asm-x86/irqflags.h +++ b/include/asm-x86/irqflags.h | |||
| @@ -179,8 +179,6 @@ static inline void trace_hardirqs_fixup(void) | |||
| 179 | * have a reliable stack. x86_64 only. | 179 | * have a reliable stack. x86_64 only. |
| 180 | */ | 180 | */ |
| 181 | #define SWAPGS_UNSAFE_STACK swapgs | 181 | #define SWAPGS_UNSAFE_STACK swapgs |
| 182 | #define ARCH_TRACE_IRQS_ON call trace_hardirqs_on_thunk | ||
| 183 | #define ARCH_TRACE_IRQS_OFF call trace_hardirqs_off_thunk | ||
| 184 | #define ARCH_LOCKDEP_SYS_EXIT call lockdep_sys_exit_thunk | 182 | #define ARCH_LOCKDEP_SYS_EXIT call lockdep_sys_exit_thunk |
| 185 | #define ARCH_LOCKDEP_SYS_EXIT_IRQ \ | 183 | #define ARCH_LOCKDEP_SYS_EXIT_IRQ \ |
| 186 | TRACE_IRQS_ON; \ | 184 | TRACE_IRQS_ON; \ |
| @@ -192,24 +190,6 @@ static inline void trace_hardirqs_fixup(void) | |||
| 192 | TRACE_IRQS_OFF; | 190 | TRACE_IRQS_OFF; |
| 193 | 191 | ||
| 194 | #else | 192 | #else |
| 195 | #define ARCH_TRACE_IRQS_ON \ | ||
| 196 | pushl %eax; \ | ||
| 197 | pushl %ecx; \ | ||
| 198 | pushl %edx; \ | ||
| 199 | call trace_hardirqs_on; \ | ||
| 200 | popl %edx; \ | ||
| 201 | popl %ecx; \ | ||
| 202 | popl %eax; | ||
| 203 | |||
| 204 | #define ARCH_TRACE_IRQS_OFF \ | ||
| 205 | pushl %eax; \ | ||
| 206 | pushl %ecx; \ | ||
| 207 | pushl %edx; \ | ||
| 208 | call trace_hardirqs_off; \ | ||
| 209 | popl %edx; \ | ||
| 210 | popl %ecx; \ | ||
| 211 | popl %eax; | ||
| 212 | |||
| 213 | #define ARCH_LOCKDEP_SYS_EXIT \ | 193 | #define ARCH_LOCKDEP_SYS_EXIT \ |
| 214 | pushl %eax; \ | 194 | pushl %eax; \ |
| 215 | pushl %ecx; \ | 195 | pushl %ecx; \ |
| @@ -223,8 +203,8 @@ static inline void trace_hardirqs_fixup(void) | |||
| 223 | #endif | 203 | #endif |
| 224 | 204 | ||
| 225 | #ifdef CONFIG_TRACE_IRQFLAGS | 205 | #ifdef CONFIG_TRACE_IRQFLAGS |
| 226 | # define TRACE_IRQS_ON ARCH_TRACE_IRQS_ON | 206 | # define TRACE_IRQS_ON call trace_hardirqs_on_thunk; |
| 227 | # define TRACE_IRQS_OFF ARCH_TRACE_IRQS_OFF | 207 | # define TRACE_IRQS_OFF call trace_hardirqs_off_thunk; |
| 228 | #else | 208 | #else |
| 229 | # define TRACE_IRQS_ON | 209 | # define TRACE_IRQS_ON |
| 230 | # define TRACE_IRQS_OFF | 210 | # define TRACE_IRQS_OFF |
diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h index db8a5e7abe41..0a20445dcbcc 100644 --- a/include/linux/ftrace.h +++ b/include/linux/ftrace.h | |||
| @@ -50,4 +50,12 @@ extern void mcount(void); | |||
| 50 | # define CALLER_ADDR5 0UL | 50 | # define CALLER_ADDR5 0UL |
| 51 | #endif | 51 | #endif |
| 52 | 52 | ||
| 53 | #ifdef CONFIG_IRQSOFF_TRACER | ||
| 54 | extern void notrace time_hardirqs_on(unsigned long a0, unsigned long a1); | ||
| 55 | extern void notrace time_hardirqs_off(unsigned long a0, unsigned long a1); | ||
| 56 | #else | ||
| 57 | # define time_hardirqs_on(a0, a1) do { } while (0) | ||
| 58 | # define time_hardirqs_off(a0, a1) do { } while (0) | ||
| 59 | #endif | ||
| 60 | |||
| 53 | #endif /* _LINUX_FTRACE_H */ | 61 | #endif /* _LINUX_FTRACE_H */ |
diff --git a/include/linux/irqflags.h b/include/linux/irqflags.h index e600c4e9b8c5..5b711d4e9fd9 100644 --- a/include/linux/irqflags.h +++ b/include/linux/irqflags.h | |||
| @@ -12,10 +12,10 @@ | |||
| 12 | #define _LINUX_TRACE_IRQFLAGS_H | 12 | #define _LINUX_TRACE_IRQFLAGS_H |
| 13 | 13 | ||
| 14 | #ifdef CONFIG_TRACE_IRQFLAGS | 14 | #ifdef CONFIG_TRACE_IRQFLAGS |
| 15 | extern void trace_hardirqs_on(void); | ||
| 16 | extern void trace_hardirqs_off(void); | ||
| 17 | extern void trace_softirqs_on(unsigned long ip); | 15 | extern void trace_softirqs_on(unsigned long ip); |
| 18 | extern void trace_softirqs_off(unsigned long ip); | 16 | extern void trace_softirqs_off(unsigned long ip); |
| 17 | extern void trace_hardirqs_on(void); | ||
| 18 | extern void trace_hardirqs_off(void); | ||
| 19 | # define trace_hardirq_context(p) ((p)->hardirq_context) | 19 | # define trace_hardirq_context(p) ((p)->hardirq_context) |
| 20 | # define trace_softirq_context(p) ((p)->softirq_context) | 20 | # define trace_softirq_context(p) ((p)->softirq_context) |
| 21 | # define trace_hardirqs_enabled(p) ((p)->hardirqs_enabled) | 21 | # define trace_hardirqs_enabled(p) ((p)->hardirqs_enabled) |
| @@ -41,6 +41,14 @@ | |||
| 41 | # define INIT_TRACE_IRQFLAGS | 41 | # define INIT_TRACE_IRQFLAGS |
| 42 | #endif | 42 | #endif |
| 43 | 43 | ||
| 44 | #ifdef CONFIG_IRQSOFF_TRACER | ||
| 45 | extern void stop_critical_timings(void); | ||
| 46 | extern void start_critical_timings(void); | ||
| 47 | #else | ||
| 48 | # define stop_critical_timings() do { } while (0) | ||
| 49 | # define start_critical_timings() do { } while (0) | ||
| 50 | #endif | ||
| 51 | |||
| 44 | #ifdef CONFIG_TRACE_IRQFLAGS_SUPPORT | 52 | #ifdef CONFIG_TRACE_IRQFLAGS_SUPPORT |
| 45 | 53 | ||
| 46 | #include <asm/irqflags.h> | 54 | #include <asm/irqflags.h> |
diff --git a/kernel/fork.c b/kernel/fork.c index 19908b26cf80..d66d676dc362 100644 --- a/kernel/fork.c +++ b/kernel/fork.c | |||
| @@ -909,7 +909,7 @@ static struct task_struct *copy_process(unsigned long clone_flags, | |||
| 909 | 909 | ||
| 910 | rt_mutex_init_task(p); | 910 | rt_mutex_init_task(p); |
| 911 | 911 | ||
| 912 | #ifdef CONFIG_TRACE_IRQFLAGS | 912 | #if defined(CONFIG_TRACE_IRQFLAGS) && defined(CONFIG_LOCKDEP) |
| 913 | DEBUG_LOCKS_WARN_ON(!p->hardirqs_enabled); | 913 | DEBUG_LOCKS_WARN_ON(!p->hardirqs_enabled); |
| 914 | DEBUG_LOCKS_WARN_ON(!p->softirqs_enabled); | 914 | DEBUG_LOCKS_WARN_ON(!p->softirqs_enabled); |
| 915 | #endif | 915 | #endif |
diff --git a/kernel/lockdep.c b/kernel/lockdep.c index 81a4e4a3f087..e21924365ea3 100644 --- a/kernel/lockdep.c +++ b/kernel/lockdep.c | |||
| @@ -39,6 +39,7 @@ | |||
| 39 | #include <linux/irqflags.h> | 39 | #include <linux/irqflags.h> |
| 40 | #include <linux/utsname.h> | 40 | #include <linux/utsname.h> |
| 41 | #include <linux/hash.h> | 41 | #include <linux/hash.h> |
| 42 | #include <linux/ftrace.h> | ||
| 42 | 43 | ||
| 43 | #include <asm/sections.h> | 44 | #include <asm/sections.h> |
| 44 | 45 | ||
| @@ -982,7 +983,7 @@ check_noncircular(struct lock_class *source, unsigned int depth) | |||
| 982 | return 1; | 983 | return 1; |
| 983 | } | 984 | } |
| 984 | 985 | ||
| 985 | #ifdef CONFIG_TRACE_IRQFLAGS | 986 | #if defined(CONFIG_TRACE_IRQFLAGS) && defined(CONFIG_PROVE_LOCKING) |
| 986 | /* | 987 | /* |
| 987 | * Forwards and backwards subgraph searching, for the purposes of | 988 | * Forwards and backwards subgraph searching, for the purposes of |
| 988 | * proving that two subgraphs can be connected by a new dependency | 989 | * proving that two subgraphs can be connected by a new dependency |
| @@ -1680,7 +1681,7 @@ valid_state(struct task_struct *curr, struct held_lock *this, | |||
| 1680 | static int mark_lock(struct task_struct *curr, struct held_lock *this, | 1681 | static int mark_lock(struct task_struct *curr, struct held_lock *this, |
| 1681 | enum lock_usage_bit new_bit); | 1682 | enum lock_usage_bit new_bit); |
| 1682 | 1683 | ||
| 1683 | #ifdef CONFIG_TRACE_IRQFLAGS | 1684 | #if defined(CONFIG_TRACE_IRQFLAGS) && defined(CONFIG_PROVE_LOCKING) |
| 1684 | 1685 | ||
| 1685 | /* | 1686 | /* |
| 1686 | * print irq inversion bug: | 1687 | * print irq inversion bug: |
| @@ -2013,11 +2014,13 @@ void early_boot_irqs_on(void) | |||
| 2013 | /* | 2014 | /* |
| 2014 | * Hardirqs will be enabled: | 2015 | * Hardirqs will be enabled: |
| 2015 | */ | 2016 | */ |
| 2016 | void trace_hardirqs_on(void) | 2017 | void notrace trace_hardirqs_on_caller(unsigned long a0) |
| 2017 | { | 2018 | { |
| 2018 | struct task_struct *curr = current; | 2019 | struct task_struct *curr = current; |
| 2019 | unsigned long ip; | 2020 | unsigned long ip; |
| 2020 | 2021 | ||
| 2022 | time_hardirqs_on(CALLER_ADDR0, a0); | ||
| 2023 | |||
| 2021 | if (unlikely(!debug_locks || current->lockdep_recursion)) | 2024 | if (unlikely(!debug_locks || current->lockdep_recursion)) |
| 2022 | return; | 2025 | return; |
| 2023 | 2026 | ||
| @@ -2055,16 +2058,23 @@ void trace_hardirqs_on(void) | |||
| 2055 | curr->hardirq_enable_event = ++curr->irq_events; | 2058 | curr->hardirq_enable_event = ++curr->irq_events; |
| 2056 | debug_atomic_inc(&hardirqs_on_events); | 2059 | debug_atomic_inc(&hardirqs_on_events); |
| 2057 | } | 2060 | } |
| 2061 | EXPORT_SYMBOL(trace_hardirqs_on_caller); | ||
| 2058 | 2062 | ||
| 2063 | void notrace trace_hardirqs_on(void) | ||
| 2064 | { | ||
| 2065 | trace_hardirqs_on_caller(CALLER_ADDR0); | ||
| 2066 | } | ||
| 2059 | EXPORT_SYMBOL(trace_hardirqs_on); | 2067 | EXPORT_SYMBOL(trace_hardirqs_on); |
| 2060 | 2068 | ||
| 2061 | /* | 2069 | /* |
| 2062 | * Hardirqs were disabled: | 2070 | * Hardirqs were disabled: |
| 2063 | */ | 2071 | */ |
| 2064 | void trace_hardirqs_off(void) | 2072 | void notrace trace_hardirqs_off_caller(unsigned long a0) |
| 2065 | { | 2073 | { |
| 2066 | struct task_struct *curr = current; | 2074 | struct task_struct *curr = current; |
| 2067 | 2075 | ||
| 2076 | time_hardirqs_off(CALLER_ADDR0, a0); | ||
| 2077 | |||
| 2068 | if (unlikely(!debug_locks || current->lockdep_recursion)) | 2078 | if (unlikely(!debug_locks || current->lockdep_recursion)) |
| 2069 | return; | 2079 | return; |
| 2070 | 2080 | ||
| @@ -2082,7 +2092,12 @@ void trace_hardirqs_off(void) | |||
| 2082 | } else | 2092 | } else |
| 2083 | debug_atomic_inc(&redundant_hardirqs_off); | 2093 | debug_atomic_inc(&redundant_hardirqs_off); |
| 2084 | } | 2094 | } |
| 2095 | EXPORT_SYMBOL(trace_hardirqs_off_caller); | ||
| 2085 | 2096 | ||
| 2097 | void notrace trace_hardirqs_off(void) | ||
| 2098 | { | ||
| 2099 | trace_hardirqs_off_caller(CALLER_ADDR0); | ||
| 2100 | } | ||
| 2086 | EXPORT_SYMBOL(trace_hardirqs_off); | 2101 | EXPORT_SYMBOL(trace_hardirqs_off); |
| 2087 | 2102 | ||
| 2088 | /* | 2103 | /* |
diff --git a/kernel/printk.c b/kernel/printk.c index 8fb01c32aa3b..ae7d5b9e535d 100644 --- a/kernel/printk.c +++ b/kernel/printk.c | |||
| @@ -1041,7 +1041,9 @@ void release_console_sem(void) | |||
| 1041 | _log_end = log_end; | 1041 | _log_end = log_end; |
| 1042 | con_start = log_end; /* Flush */ | 1042 | con_start = log_end; /* Flush */ |
| 1043 | spin_unlock(&logbuf_lock); | 1043 | spin_unlock(&logbuf_lock); |
| 1044 | stop_critical_timings(); /* don't trace print latency */ | ||
| 1044 | call_console_drivers(_con_start, _log_end); | 1045 | call_console_drivers(_con_start, _log_end); |
| 1046 | start_critical_timings(); | ||
| 1045 | local_irq_restore(flags); | 1047 | local_irq_restore(flags); |
| 1046 | } | 1048 | } |
| 1047 | console_locked = 0; | 1049 | console_locked = 0; |
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig index 892ecc94a82b..896df1cf6adc 100644 --- a/kernel/trace/Kconfig +++ b/kernel/trace/Kconfig | |||
| @@ -26,6 +26,24 @@ config FTRACE | |||
| 26 | (the bootup default), then the overhead of the instructions is very | 26 | (the bootup default), then the overhead of the instructions is very |
| 27 | small and not measurable even in micro-benchmarks. | 27 | small and not measurable even in micro-benchmarks. |
| 28 | 28 | ||
| 29 | config IRQSOFF_TRACER | ||
| 30 | bool "Interrupts-off Latency Tracer" | ||
| 31 | default n | ||
| 32 | depends on TRACE_IRQFLAGS_SUPPORT | ||
| 33 | depends on GENERIC_TIME | ||
| 34 | select TRACE_IRQFLAGS | ||
| 35 | select TRACING | ||
| 36 | select TRACER_MAX_TRACE | ||
| 37 | help | ||
| 38 | This option measures the time spent in irqs-off critical | ||
| 39 | sections, with microsecond accuracy. | ||
| 40 | |||
| 41 | The default measurement method is a maximum search, which is | ||
| 42 | disabled by default and can be runtime (re-)started | ||
| 43 | via: | ||
| 44 | |||
| 45 | echo 0 > /debugfs/tracing/tracing_max_latency | ||
| 46 | |||
| 29 | config SCHED_TRACER | 47 | config SCHED_TRACER |
| 30 | bool "Scheduling Latency Tracer" | 48 | bool "Scheduling Latency Tracer" |
| 31 | depends on DEBUG_KERNEL | 49 | depends on DEBUG_KERNEL |
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile index 5508cdb19aea..46be8647fb65 100644 --- a/kernel/trace/Makefile +++ b/kernel/trace/Makefile | |||
| @@ -3,6 +3,7 @@ obj-$(CONFIG_FTRACE) += libftrace.o | |||
| 3 | obj-$(CONFIG_TRACING) += trace.o | 3 | obj-$(CONFIG_TRACING) += trace.o |
| 4 | obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o | 4 | obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o |
| 5 | obj-$(CONFIG_FTRACE) += trace_functions.o | 5 | obj-$(CONFIG_FTRACE) += trace_functions.o |
| 6 | obj-$(CONFIG_IRQSOFF_TRACER) += trace_irqsoff.o | ||
| 6 | obj-$(CONFIG_SCHED_TRACER) += trace_sched_wakeup.o | 7 | obj-$(CONFIG_SCHED_TRACER) += trace_sched_wakeup.o |
| 7 | 8 | ||
| 8 | libftrace-y := ftrace.o | 9 | libftrace-y := ftrace.o |
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c new file mode 100644 index 000000000000..a9131b0cf1a5 --- /dev/null +++ b/kernel/trace/trace_irqsoff.c | |||
| @@ -0,0 +1,402 @@ | |||
| 1 | /* | ||
| 2 | * trace irqs off criticall timings | ||
| 3 | * | ||
| 4 | * Copyright (C) 2007-2008 Steven Rostedt <srostedt@redhat.com> | ||
| 5 | * Copyright (C) 2008 Ingo Molnar <mingo@redhat.com> | ||
| 6 | * | ||
| 7 | * From code in the latency_tracer, that is: | ||
| 8 | * | ||
| 9 | * Copyright (C) 2004-2006 Ingo Molnar | ||
| 10 | * Copyright (C) 2004 William Lee Irwin III | ||
| 11 | */ | ||
| 12 | #include <linux/kallsyms.h> | ||
| 13 | #include <linux/debugfs.h> | ||
| 14 | #include <linux/uaccess.h> | ||
| 15 | #include <linux/module.h> | ||
| 16 | #include <linux/ftrace.h> | ||
| 17 | #include <linux/fs.h> | ||
| 18 | |||
| 19 | #include "trace.h" | ||
| 20 | |||
| 21 | static struct trace_array *irqsoff_trace __read_mostly; | ||
| 22 | static int tracer_enabled __read_mostly; | ||
| 23 | |||
| 24 | /* | ||
| 25 | * Sequence count - we record it when starting a measurement and | ||
| 26 | * skip the latency if the sequence has changed - some other section | ||
| 27 | * did a maximum and could disturb our measurement with serial console | ||
| 28 | * printouts, etc. Truly coinciding maximum latencies should be rare | ||
| 29 | * and what happens together happens separately as well, so this doesnt | ||
| 30 | * decrease the validity of the maximum found: | ||
| 31 | */ | ||
| 32 | static __cacheline_aligned_in_smp unsigned long max_sequence; | ||
| 33 | |||
| 34 | #ifdef CONFIG_FTRACE | ||
| 35 | /* | ||
| 36 | * irqsoff uses its own tracer function to keep the overhead down: | ||
| 37 | */ | ||
| 38 | static void notrace | ||
| 39 | irqsoff_tracer_call(unsigned long ip, unsigned long parent_ip) | ||
| 40 | { | ||
| 41 | struct trace_array *tr = irqsoff_trace; | ||
| 42 | struct trace_array_cpu *data; | ||
| 43 | unsigned long flags; | ||
| 44 | long disabled; | ||
| 45 | int cpu; | ||
| 46 | |||
| 47 | if (likely(!tracer_enabled)) | ||
| 48 | return; | ||
| 49 | |||
| 50 | local_save_flags(flags); | ||
| 51 | |||
| 52 | if (!irqs_disabled_flags(flags)) | ||
| 53 | return; | ||
| 54 | |||
| 55 | cpu = raw_smp_processor_id(); | ||
| 56 | data = tr->data[cpu]; | ||
| 57 | disabled = atomic_inc_return(&data->disabled); | ||
| 58 | |||
| 59 | if (likely(disabled == 1)) | ||
| 60 | ftrace(tr, data, ip, parent_ip, flags); | ||
| 61 | |||
| 62 | atomic_dec(&data->disabled); | ||
| 63 | } | ||
| 64 | |||
| 65 | static struct ftrace_ops trace_ops __read_mostly = | ||
| 66 | { | ||
| 67 | .func = irqsoff_tracer_call, | ||
| 68 | }; | ||
| 69 | #endif /* CONFIG_FTRACE */ | ||
| 70 | |||
| 71 | /* | ||
| 72 | * Should this new latency be reported/recorded? | ||
| 73 | */ | ||
| 74 | static int notrace report_latency(cycle_t delta) | ||
| 75 | { | ||
| 76 | if (tracing_thresh) { | ||
| 77 | if (delta < tracing_thresh) | ||
| 78 | return 0; | ||
| 79 | } else { | ||
| 80 | if (delta <= tracing_max_latency) | ||
| 81 | return 0; | ||
| 82 | } | ||
| 83 | return 1; | ||
| 84 | } | ||
| 85 | |||
| 86 | static void notrace | ||
| 87 | check_critical_timing(struct trace_array *tr, | ||
| 88 | struct trace_array_cpu *data, | ||
| 89 | unsigned long parent_ip, | ||
| 90 | int cpu) | ||
| 91 | { | ||
| 92 | unsigned long latency, t0, t1; | ||
| 93 | cycle_t T0, T1, T2, delta; | ||
| 94 | unsigned long flags; | ||
| 95 | |||
| 96 | /* | ||
| 97 | * usecs conversion is slow so we try to delay the conversion | ||
| 98 | * as long as possible: | ||
| 99 | */ | ||
| 100 | T0 = data->preempt_timestamp; | ||
| 101 | T1 = now(cpu); | ||
| 102 | delta = T1-T0; | ||
| 103 | |||
| 104 | local_save_flags(flags); | ||
| 105 | |||
| 106 | if (!report_latency(delta)) | ||
| 107 | goto out; | ||
| 108 | |||
| 109 | ftrace(tr, data, CALLER_ADDR0, parent_ip, flags); | ||
| 110 | /* | ||
| 111 | * Update the timestamp, because the trace entry above | ||
| 112 | * might change it (it can only get larger so the latency | ||
| 113 | * is fair to be reported): | ||
| 114 | */ | ||
| 115 | T2 = now(cpu); | ||
| 116 | |||
| 117 | delta = T2-T0; | ||
| 118 | |||
| 119 | latency = nsecs_to_usecs(delta); | ||
| 120 | |||
| 121 | if (data->critical_sequence != max_sequence) | ||
| 122 | goto out; | ||
| 123 | |||
| 124 | tracing_max_latency = delta; | ||
| 125 | t0 = nsecs_to_usecs(T0); | ||
| 126 | t1 = nsecs_to_usecs(T1); | ||
| 127 | |||
| 128 | data->critical_end = parent_ip; | ||
| 129 | |||
| 130 | update_max_tr_single(tr, current, cpu); | ||
| 131 | |||
| 132 | if (tracing_thresh) | ||
| 133 | printk(KERN_INFO "(%16s-%-5d|#%d): %lu us critical section " | ||
| 134 | "violates %lu us threshold.\n" | ||
| 135 | " => started at timestamp %lu: ", | ||
| 136 | current->comm, current->pid, | ||
| 137 | raw_smp_processor_id(), | ||
| 138 | latency, nsecs_to_usecs(tracing_thresh), t0); | ||
| 139 | else | ||
| 140 | printk(KERN_INFO "(%16s-%-5d|#%d):" | ||
| 141 | " new %lu us maximum-latency " | ||
| 142 | "critical section.\n => started at timestamp %lu: ", | ||
| 143 | current->comm, current->pid, | ||
| 144 | raw_smp_processor_id(), | ||
| 145 | latency, t0); | ||
| 146 | |||
| 147 | print_symbol(KERN_CONT "<%s>\n", data->critical_start); | ||
| 148 | printk(KERN_CONT " => ended at timestamp %lu: ", t1); | ||
| 149 | print_symbol(KERN_CONT "<%s>\n", data->critical_end); | ||
| 150 | dump_stack(); | ||
| 151 | t1 = nsecs_to_usecs(now(cpu)); | ||
| 152 | printk(KERN_CONT " => dump-end timestamp %lu\n\n", t1); | ||
| 153 | |||
| 154 | max_sequence++; | ||
| 155 | |||
| 156 | out: | ||
| 157 | data->critical_sequence = max_sequence; | ||
| 158 | data->preempt_timestamp = now(cpu); | ||
| 159 | tracing_reset(data); | ||
| 160 | ftrace(tr, data, CALLER_ADDR0, parent_ip, flags); | ||
| 161 | } | ||
| 162 | |||
| 163 | static inline void notrace | ||
| 164 | start_critical_timing(unsigned long ip, unsigned long parent_ip) | ||
| 165 | { | ||
| 166 | int cpu; | ||
| 167 | struct trace_array *tr = irqsoff_trace; | ||
| 168 | struct trace_array_cpu *data; | ||
| 169 | unsigned long flags; | ||
| 170 | |||
| 171 | if (likely(!tracer_enabled)) | ||
| 172 | return; | ||
| 173 | |||
| 174 | cpu = raw_smp_processor_id(); | ||
| 175 | data = tr->data[cpu]; | ||
| 176 | |||
| 177 | if (unlikely(!data) || unlikely(!data->trace) || | ||
| 178 | data->critical_start || atomic_read(&data->disabled)) | ||
| 179 | return; | ||
| 180 | |||
| 181 | atomic_inc(&data->disabled); | ||
| 182 | |||
| 183 | data->critical_sequence = max_sequence; | ||
| 184 | data->preempt_timestamp = now(cpu); | ||
| 185 | data->critical_start = parent_ip; | ||
| 186 | tracing_reset(data); | ||
| 187 | |||
| 188 | local_save_flags(flags); | ||
| 189 | ftrace(tr, data, ip, parent_ip, flags); | ||
| 190 | |||
| 191 | atomic_dec(&data->disabled); | ||
| 192 | } | ||
| 193 | |||
| 194 | static inline void notrace | ||
| 195 | stop_critical_timing(unsigned long ip, unsigned long parent_ip) | ||
| 196 | { | ||
| 197 | int cpu; | ||
| 198 | struct trace_array *tr = irqsoff_trace; | ||
| 199 | struct trace_array_cpu *data; | ||
| 200 | unsigned long flags; | ||
| 201 | |||
| 202 | if (likely(!tracer_enabled)) | ||
| 203 | return; | ||
| 204 | |||
| 205 | cpu = raw_smp_processor_id(); | ||
| 206 | data = tr->data[cpu]; | ||
| 207 | |||
| 208 | if (unlikely(!data) || unlikely(!data->trace) || | ||
| 209 | !data->critical_start || atomic_read(&data->disabled)) | ||
| 210 | return; | ||
| 211 | |||
| 212 | atomic_inc(&data->disabled); | ||
| 213 | local_save_flags(flags); | ||
| 214 | ftrace(tr, data, ip, parent_ip, flags); | ||
| 215 | check_critical_timing(tr, data, parent_ip, cpu); | ||
| 216 | data->critical_start = 0; | ||
| 217 | atomic_dec(&data->disabled); | ||
| 218 | } | ||
| 219 | |||
| 220 | void notrace start_critical_timings(void) | ||
| 221 | { | ||
| 222 | unsigned long flags; | ||
| 223 | |||
| 224 | local_save_flags(flags); | ||
| 225 | |||
| 226 | if (irqs_disabled_flags(flags)) | ||
| 227 | start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); | ||
| 228 | } | ||
| 229 | |||
| 230 | void notrace stop_critical_timings(void) | ||
| 231 | { | ||
| 232 | unsigned long flags; | ||
| 233 | |||
| 234 | local_save_flags(flags); | ||
| 235 | |||
| 236 | if (irqs_disabled_flags(flags)) | ||
| 237 | stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); | ||
| 238 | } | ||
| 239 | |||
| 240 | #ifdef CONFIG_PROVE_LOCKING | ||
| 241 | void notrace time_hardirqs_on(unsigned long a0, unsigned long a1) | ||
| 242 | { | ||
| 243 | unsigned long flags; | ||
| 244 | |||
| 245 | local_save_flags(flags); | ||
| 246 | |||
| 247 | if (irqs_disabled_flags(flags)) | ||
| 248 | stop_critical_timing(a0, a1); | ||
| 249 | } | ||
| 250 | |||
| 251 | void notrace time_hardirqs_off(unsigned long a0, unsigned long a1) | ||
| 252 | { | ||
| 253 | unsigned long flags; | ||
| 254 | |||
| 255 | local_save_flags(flags); | ||
| 256 | |||
| 257 | if (irqs_disabled_flags(flags)) | ||
| 258 | start_critical_timing(a0, a1); | ||
| 259 | } | ||
| 260 | |||
| 261 | #else /* !CONFIG_PROVE_LOCKING */ | ||
| 262 | |||
| 263 | /* | ||
| 264 | * Stubs: | ||
| 265 | */ | ||
| 266 | |||
| 267 | void early_boot_irqs_off(void) | ||
| 268 | { | ||
| 269 | } | ||
| 270 | |||
| 271 | void early_boot_irqs_on(void) | ||
| 272 | { | ||
| 273 | } | ||
| 274 | |||
| 275 | void trace_softirqs_on(unsigned long ip) | ||
| 276 | { | ||
| 277 | } | ||
| 278 | |||
| 279 | void trace_softirqs_off(unsigned long ip) | ||
| 280 | { | ||
| 281 | } | ||
| 282 | |||
| 283 | inline void print_irqtrace_events(struct task_struct *curr) | ||
| 284 | { | ||
| 285 | } | ||
| 286 | |||
| 287 | /* | ||
| 288 | * We are only interested in hardirq on/off events: | ||
| 289 | */ | ||
| 290 | void notrace trace_hardirqs_on(void) | ||
| 291 | { | ||
| 292 | unsigned long flags; | ||
| 293 | |||
| 294 | local_save_flags(flags); | ||
| 295 | |||
| 296 | if (irqs_disabled_flags(flags)) | ||
| 297 | stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); | ||
| 298 | } | ||
| 299 | EXPORT_SYMBOL(trace_hardirqs_on); | ||
| 300 | |||
| 301 | void notrace trace_hardirqs_off(void) | ||
| 302 | { | ||
| 303 | unsigned long flags; | ||
| 304 | |||
| 305 | local_save_flags(flags); | ||
| 306 | |||
| 307 | if (irqs_disabled_flags(flags)) | ||
| 308 | start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); | ||
| 309 | } | ||
| 310 | EXPORT_SYMBOL(trace_hardirqs_off); | ||
| 311 | |||
| 312 | void notrace trace_hardirqs_on_caller(unsigned long caller_addr) | ||
| 313 | { | ||
| 314 | unsigned long flags; | ||
| 315 | |||
| 316 | local_save_flags(flags); | ||
| 317 | |||
| 318 | if (irqs_disabled_flags(flags)) | ||
| 319 | stop_critical_timing(CALLER_ADDR0, caller_addr); | ||
| 320 | } | ||
| 321 | EXPORT_SYMBOL(trace_hardirqs_on_caller); | ||
| 322 | |||
| 323 | void notrace trace_hardirqs_off_caller(unsigned long caller_addr) | ||
| 324 | { | ||
| 325 | unsigned long flags; | ||
| 326 | |||
| 327 | local_save_flags(flags); | ||
| 328 | |||
| 329 | if (irqs_disabled_flags(flags)) | ||
| 330 | start_critical_timing(CALLER_ADDR0, caller_addr); | ||
| 331 | } | ||
| 332 | EXPORT_SYMBOL(trace_hardirqs_off_caller); | ||
| 333 | |||
| 334 | #endif /* CONFIG_PROVE_LOCKING */ | ||
| 335 | |||
| 336 | static void start_irqsoff_tracer(struct trace_array *tr) | ||
| 337 | { | ||
| 338 | tracer_enabled = 1; | ||
| 339 | register_ftrace_function(&trace_ops); | ||
| 340 | } | ||
| 341 | |||
| 342 | static void stop_irqsoff_tracer(struct trace_array *tr) | ||
| 343 | { | ||
| 344 | unregister_ftrace_function(&trace_ops); | ||
| 345 | tracer_enabled = 0; | ||
| 346 | } | ||
| 347 | |||
| 348 | static void irqsoff_tracer_init(struct trace_array *tr) | ||
| 349 | { | ||
| 350 | irqsoff_trace = tr; | ||
| 351 | /* make sure that the tracer is visibel */ | ||
| 352 | smp_wmb(); | ||
| 353 | |||
| 354 | if (tr->ctrl) | ||
| 355 | start_irqsoff_tracer(tr); | ||
| 356 | } | ||
| 357 | |||
| 358 | static void irqsoff_tracer_reset(struct trace_array *tr) | ||
| 359 | { | ||
| 360 | if (tr->ctrl) | ||
| 361 | stop_irqsoff_tracer(tr); | ||
| 362 | } | ||
| 363 | |||
| 364 | static void irqsoff_tracer_ctrl_update(struct trace_array *tr) | ||
| 365 | { | ||
| 366 | if (tr->ctrl) | ||
| 367 | start_irqsoff_tracer(tr); | ||
| 368 | else | ||
| 369 | stop_irqsoff_tracer(tr); | ||
| 370 | } | ||
| 371 | |||
| 372 | static void notrace irqsoff_tracer_open(struct trace_iterator *iter) | ||
| 373 | { | ||
| 374 | /* stop the trace while dumping */ | ||
| 375 | if (iter->tr->ctrl) | ||
| 376 | stop_irqsoff_tracer(iter->tr); | ||
| 377 | } | ||
| 378 | |||
| 379 | static void notrace irqsoff_tracer_close(struct trace_iterator *iter) | ||
| 380 | { | ||
| 381 | if (iter->tr->ctrl) | ||
| 382 | start_irqsoff_tracer(iter->tr); | ||
| 383 | } | ||
| 384 | |||
| 385 | static struct tracer irqsoff_tracer __read_mostly = | ||
| 386 | { | ||
| 387 | .name = "irqsoff", | ||
| 388 | .init = irqsoff_tracer_init, | ||
| 389 | .reset = irqsoff_tracer_reset, | ||
| 390 | .open = irqsoff_tracer_open, | ||
| 391 | .close = irqsoff_tracer_close, | ||
| 392 | .ctrl_update = irqsoff_tracer_ctrl_update, | ||
| 393 | .print_max = 1, | ||
| 394 | }; | ||
| 395 | |||
| 396 | __init static int init_irqsoff_tracer(void) | ||
| 397 | { | ||
| 398 | register_tracer(&irqsoff_tracer); | ||
| 399 | |||
| 400 | return 0; | ||
| 401 | } | ||
| 402 | device_initcall(init_irqsoff_tracer); | ||
