diff options
author | Steven Rostedt <srostedt@redhat.com> | 2008-05-12 15:20:42 -0400 |
---|---|---|
committer | Thomas Gleixner <tglx@linutronix.de> | 2008-05-23 14:32:46 -0400 |
commit | 81d68a96a39844853b37f20cc8282d9b65b78ef3 (patch) | |
tree | bbc05f415930c15fb5a1004620bd77585fcec43a | |
parent | 352ad25aa4a189c667cb2af333948d34692a2d27 (diff) |
ftrace: trace irq disabled critical timings
This patch adds latency tracing for critical timings
(how long interrupts are disabled for).
"irqsoff" is added to /debugfs/tracing/available_tracers
Note:
tracing_max_latency
also holds the max latency for irqsoff (in usecs).
(default to large number so one must start latency tracing)
tracing_thresh
threshold (in usecs) to always print out if irqs off
is detected to be longer than stated here.
If irq_thresh is non-zero, then max_irq_latency
is ignored.
Here's an example of a trace with ftrace_enabled = 0
=======
preemption latency trace v1.1.5 on 2.6.24-rc7
Signed-off-by: Ingo Molnar <mingo@elte.hu>
--------------------------------------------------------------------
latency: 100 us, #3/3, CPU#1 | (M:rt VP:0, KP:0, SP:0 HP:0 #P:2)
-----------------
| task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
-----------------
=> started at: _spin_lock_irqsave+0x2a/0xb7
=> ended at: _spin_unlock_irqrestore+0x32/0x5f
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
swapper-0 1d.s3 0us+: _spin_lock_irqsave+0x2a/0xb7 (e1000_update_stats+0x47/0x64c [e1000])
swapper-0 1d.s3 100us : _spin_unlock_irqrestore+0x32/0x5f (e1000_update_stats+0x641/0x64c [e1000])
swapper-0 1d.s3 100us : trace_hardirqs_on_caller+0x75/0x89 (_spin_unlock_irqrestore+0x32/0x5f)
vim:ft=help
=======
And this is a trace with ftrace_enabled == 1
=======
preemption latency trace v1.1.5 on 2.6.24-rc7
--------------------------------------------------------------------
latency: 102 us, #12/12, CPU#1 | (M:rt VP:0, KP:0, SP:0 HP:0 #P:2)
-----------------
| task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
-----------------
=> started at: _spin_lock_irqsave+0x2a/0xb7
=> ended at: _spin_unlock_irqrestore+0x32/0x5f
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
swapper-0 1dNs3 0us+: _spin_lock_irqsave+0x2a/0xb7 (e1000_update_stats+0x47/0x64c [e1000])
swapper-0 1dNs3 46us : e1000_read_phy_reg+0x16/0x225 [e1000] (e1000_update_stats+0x5e2/0x64c [e1000])
swapper-0 1dNs3 46us : e1000_swfw_sync_acquire+0x10/0x99 [e1000] (e1000_read_phy_reg+0x49/0x225 [e1000])
swapper-0 1dNs3 46us : e1000_get_hw_eeprom_semaphore+0x12/0xa6 [e1000] (e1000_swfw_sync_acquire+0x36/0x99 [e1000])
swapper-0 1dNs3 47us : __const_udelay+0x9/0x47 (e1000_read_phy_reg+0x116/0x225 [e1000])
swapper-0 1dNs3 47us+: __delay+0x9/0x50 (__const_udelay+0x45/0x47)
swapper-0 1dNs3 97us : preempt_schedule+0xc/0x84 (__delay+0x4e/0x50)
swapper-0 1dNs3 98us : e1000_swfw_sync_release+0xc/0x55 [e1000] (e1000_read_phy_reg+0x211/0x225 [e1000])
swapper-0 1dNs3 99us+: e1000_put_hw_eeprom_semaphore+0x9/0x35 [e1000] (e1000_swfw_sync_release+0x50/0x55 [e1000])
swapper-0 1dNs3 101us : _spin_unlock_irqrestore+0xe/0x5f (e1000_update_stats+0x641/0x64c [e1000])
swapper-0 1dNs3 102us : _spin_unlock_irqrestore+0x32/0x5f (e1000_update_stats+0x641/0x64c [e1000])
swapper-0 1dNs3 102us : trace_hardirqs_on_caller+0x75/0x89 (_spin_unlock_irqrestore+0x32/0x5f)
vim:ft=help
=======
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
-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); | ||