diff options
Diffstat (limited to 'kernel/trace/trace_irqsoff.c')
-rw-r--r-- | kernel/trace/trace_irqsoff.c | 402 |
1 files changed, 402 insertions, 0 deletions
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); | ||