2 * trace irqs off criticall timings
4 * Copyright (C) 2007-2008 Steven Rostedt <srostedt@redhat.com>
5 * Copyright (C) 2008 Ingo Molnar <mingo@redhat.com>
7 * From code in the latency_tracer, that is:
9 * Copyright (C) 2004-2006 Ingo Molnar
10 * Copyright (C) 2004 William Lee Irwin III
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>
21 static struct trace_array *irqsoff_trace __read_mostly;
22 static int tracer_enabled __read_mostly;
24 static DEFINE_PER_CPU(int, tracing_cpu);
26 static DEFINE_SPINLOCK(max_trace_lock);
29 TRACER_IRQS_OFF = (1 << 1),
30 TRACER_PREEMPT_OFF = (1 << 2),
33 static int trace_type __read_mostly;
35 #ifdef CONFIG_PREEMPT_TRACER
36 static inline int notrace
39 return ((trace_type & TRACER_PREEMPT_OFF) && preempt_count());
42 # define preempt_trace() (0)
45 #ifdef CONFIG_IRQSOFF_TRACER
46 static inline int notrace
49 return ((trace_type & TRACER_IRQS_OFF) &&
53 # define irq_trace() (0)
57 * Sequence count - we record it when starting a measurement and
58 * skip the latency if the sequence has changed - some other section
59 * did a maximum and could disturb our measurement with serial console
60 * printouts, etc. Truly coinciding maximum latencies should be rare
61 * and what happens together happens separately as well, so this doesnt
62 * decrease the validity of the maximum found:
64 static __cacheline_aligned_in_smp unsigned long max_sequence;
68 * irqsoff uses its own tracer function to keep the overhead down:
71 irqsoff_tracer_call(unsigned long ip, unsigned long parent_ip)
73 struct trace_array *tr = irqsoff_trace;
74 struct trace_array_cpu *data;
80 * Does not matter if we preempt. We test the flags
81 * afterward, to see if irqs are disabled or not.
82 * If we preempt and get a false positive, the flags
85 cpu = raw_smp_processor_id();
86 if (likely(!per_cpu(tracing_cpu, cpu)))
89 local_save_flags(flags);
90 /* slight chance to get a false positive on tracing_cpu */
91 if (!irqs_disabled_flags(flags))
95 disabled = atomic_inc_return(&data->disabled);
97 if (likely(disabled == 1))
98 ftrace(tr, data, ip, parent_ip, flags);
100 atomic_dec(&data->disabled);
103 static struct ftrace_ops trace_ops __read_mostly =
105 .func = irqsoff_tracer_call,
107 #endif /* CONFIG_FTRACE */
110 * Should this new latency be reported/recorded?
112 static int notrace report_latency(cycle_t delta)
114 if (tracing_thresh) {
115 if (delta < tracing_thresh)
118 if (delta <= tracing_max_latency)
125 check_critical_timing(struct trace_array *tr,
126 struct trace_array_cpu *data,
127 unsigned long parent_ip,
130 unsigned long latency, t0, t1;
131 cycle_t T0, T1, delta;
135 * usecs conversion is slow so we try to delay the conversion
136 * as long as possible:
138 T0 = data->preempt_timestamp;
142 local_save_flags(flags);
144 if (!report_latency(delta))
147 spin_lock(&max_trace_lock);
149 /* check if we are still the max latency */
150 if (!report_latency(delta))
153 ftrace(tr, data, CALLER_ADDR0, parent_ip, flags);
155 latency = nsecs_to_usecs(delta);
157 if (data->critical_sequence != max_sequence)
160 tracing_max_latency = delta;
161 t0 = nsecs_to_usecs(T0);
162 t1 = nsecs_to_usecs(T1);
164 data->critical_end = parent_ip;
166 update_max_tr_single(tr, current, cpu);
169 printk(KERN_INFO "(%16s-%-5d|#%d): %lu us critical section "
170 "violates %lu us threshold.\n"
171 " => started at timestamp %lu: ",
172 current->comm, current->pid,
173 raw_smp_processor_id(),
174 latency, nsecs_to_usecs(tracing_thresh), t0);
176 printk(KERN_INFO "(%16s-%-5d|#%d):"
177 " new %lu us maximum-latency "
178 "critical section.\n => started at timestamp %lu: ",
179 current->comm, current->pid,
180 raw_smp_processor_id(),
183 print_symbol(KERN_CONT "<%s>\n", data->critical_start);
184 printk(KERN_CONT " => ended at timestamp %lu: ", t1);
185 print_symbol(KERN_CONT "<%s>\n", data->critical_end);
187 t1 = nsecs_to_usecs(now(cpu));
188 printk(KERN_CONT " => dump-end timestamp %lu\n\n", t1);
193 spin_unlock(&max_trace_lock);
196 data->critical_sequence = max_sequence;
197 data->preempt_timestamp = now(cpu);
199 ftrace(tr, data, CALLER_ADDR0, parent_ip, flags);
202 static inline void notrace
203 start_critical_timing(unsigned long ip, unsigned long parent_ip)
206 struct trace_array *tr = irqsoff_trace;
207 struct trace_array_cpu *data;
210 if (likely(!tracer_enabled))
213 if (__get_cpu_var(tracing_cpu))
216 cpu = raw_smp_processor_id();
217 data = tr->data[cpu];
219 if (unlikely(!data) || unlikely(!data->trace) ||
220 atomic_read(&data->disabled))
223 atomic_inc(&data->disabled);
225 data->critical_sequence = max_sequence;
226 data->preempt_timestamp = now(cpu);
227 data->critical_start = parent_ip ? : ip;
230 local_save_flags(flags);
232 ftrace(tr, data, ip, parent_ip, flags);
234 __get_cpu_var(tracing_cpu) = 1;
236 atomic_dec(&data->disabled);
239 static inline void notrace
240 stop_critical_timing(unsigned long ip, unsigned long parent_ip)
243 struct trace_array *tr = irqsoff_trace;
244 struct trace_array_cpu *data;
247 /* Always clear the tracing cpu on stopping the trace */
248 if (unlikely(__get_cpu_var(tracing_cpu)))
249 __get_cpu_var(tracing_cpu) = 0;
256 cpu = raw_smp_processor_id();
257 data = tr->data[cpu];
259 if (unlikely(!data) || unlikely(!data->trace) ||
260 !data->critical_start || atomic_read(&data->disabled))
263 atomic_inc(&data->disabled);
264 local_save_flags(flags);
265 ftrace(tr, data, ip, parent_ip, flags);
266 check_critical_timing(tr, data, parent_ip ? : ip, cpu);
267 data->critical_start = 0;
268 atomic_dec(&data->disabled);
271 /* start and stop critical timings used to for stoppage (in idle) */
272 void notrace start_critical_timings(void)
274 if (preempt_trace() || irq_trace())
275 start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
278 void notrace stop_critical_timings(void)
280 if (preempt_trace() || irq_trace())
281 stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
284 #ifdef CONFIG_IRQSOFF_TRACER
285 #ifdef CONFIG_PROVE_LOCKING
286 void notrace time_hardirqs_on(unsigned long a0, unsigned long a1)
288 if (!preempt_trace() && irq_trace())
289 stop_critical_timing(a0, a1);
292 void notrace time_hardirqs_off(unsigned long a0, unsigned long a1)
294 if (!preempt_trace() && irq_trace())
295 start_critical_timing(a0, a1);
298 #else /* !CONFIG_PROVE_LOCKING */
304 void early_boot_irqs_off(void)
308 void early_boot_irqs_on(void)
312 void trace_softirqs_on(unsigned long ip)
316 void trace_softirqs_off(unsigned long ip)
320 inline void print_irqtrace_events(struct task_struct *curr)
325 * We are only interested in hardirq on/off events:
327 void notrace trace_hardirqs_on(void)
329 if (!preempt_trace() && irq_trace())
330 stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
332 EXPORT_SYMBOL(trace_hardirqs_on);
334 void notrace trace_hardirqs_off(void)
336 if (!preempt_trace() && irq_trace())
337 start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
339 EXPORT_SYMBOL(trace_hardirqs_off);
341 void notrace trace_hardirqs_on_caller(unsigned long caller_addr)
343 if (!preempt_trace() && irq_trace())
344 stop_critical_timing(CALLER_ADDR0, caller_addr);
346 EXPORT_SYMBOL(trace_hardirqs_on_caller);
348 void notrace trace_hardirqs_off_caller(unsigned long caller_addr)
350 if (!preempt_trace() && irq_trace())
351 start_critical_timing(CALLER_ADDR0, caller_addr);
353 EXPORT_SYMBOL(trace_hardirqs_off_caller);
355 #endif /* CONFIG_PROVE_LOCKING */
356 #endif /* CONFIG_IRQSOFF_TRACER */
358 #ifdef CONFIG_PREEMPT_TRACER
359 void notrace trace_preempt_on(unsigned long a0, unsigned long a1)
361 stop_critical_timing(a0, a1);
364 void notrace trace_preempt_off(unsigned long a0, unsigned long a1)
366 start_critical_timing(a0, a1);
368 #endif /* CONFIG_PREEMPT_TRACER */
370 static void start_irqsoff_tracer(struct trace_array *tr)
372 register_ftrace_function(&trace_ops);
376 static void stop_irqsoff_tracer(struct trace_array *tr)
379 unregister_ftrace_function(&trace_ops);
382 static void __irqsoff_tracer_init(struct trace_array *tr)
385 /* make sure that the tracer is visibel */
389 start_irqsoff_tracer(tr);
392 static void irqsoff_tracer_reset(struct trace_array *tr)
395 stop_irqsoff_tracer(tr);
398 static void irqsoff_tracer_ctrl_update(struct trace_array *tr)
401 start_irqsoff_tracer(tr);
403 stop_irqsoff_tracer(tr);
406 static void notrace irqsoff_tracer_open(struct trace_iterator *iter)
408 /* stop the trace while dumping */
410 stop_irqsoff_tracer(iter->tr);
413 static void notrace irqsoff_tracer_close(struct trace_iterator *iter)
416 start_irqsoff_tracer(iter->tr);
419 #ifdef CONFIG_IRQSOFF_TRACER
420 static void irqsoff_tracer_init(struct trace_array *tr)
422 trace_type = TRACER_IRQS_OFF;
424 __irqsoff_tracer_init(tr);
426 static struct tracer irqsoff_tracer __read_mostly =
429 .init = irqsoff_tracer_init,
430 .reset = irqsoff_tracer_reset,
431 .open = irqsoff_tracer_open,
432 .close = irqsoff_tracer_close,
433 .ctrl_update = irqsoff_tracer_ctrl_update,
435 #ifdef CONFIG_FTRACE_SELFTEST
436 .selftest = trace_selftest_startup_irqsoff,
439 # define register_irqsoff(trace) register_tracer(&trace)
441 # define register_irqsoff(trace) do { } while (0)
444 #ifdef CONFIG_PREEMPT_TRACER
445 static void preemptoff_tracer_init(struct trace_array *tr)
447 trace_type = TRACER_PREEMPT_OFF;
449 __irqsoff_tracer_init(tr);
452 static struct tracer preemptoff_tracer __read_mostly =
454 .name = "preemptoff",
455 .init = preemptoff_tracer_init,
456 .reset = irqsoff_tracer_reset,
457 .open = irqsoff_tracer_open,
458 .close = irqsoff_tracer_close,
459 .ctrl_update = irqsoff_tracer_ctrl_update,
461 #ifdef CONFIG_FTRACE_SELFTEST
462 .selftest = trace_selftest_startup_preemptoff,
465 # define register_preemptoff(trace) register_tracer(&trace)
467 # define register_preemptoff(trace) do { } while (0)
470 #if defined(CONFIG_IRQSOFF_TRACER) && \
471 defined(CONFIG_PREEMPT_TRACER)
473 static void preemptirqsoff_tracer_init(struct trace_array *tr)
475 trace_type = TRACER_IRQS_OFF | TRACER_PREEMPT_OFF;
477 __irqsoff_tracer_init(tr);
480 static struct tracer preemptirqsoff_tracer __read_mostly =
482 .name = "preemptirqsoff",
483 .init = preemptirqsoff_tracer_init,
484 .reset = irqsoff_tracer_reset,
485 .open = irqsoff_tracer_open,
486 .close = irqsoff_tracer_close,
487 .ctrl_update = irqsoff_tracer_ctrl_update,
489 #ifdef CONFIG_FTRACE_SELFTEST
490 .selftest = trace_selftest_startup_preemptirqsoff,
494 # define register_preemptirqsoff(trace) register_tracer(&trace)
496 # define register_preemptirqsoff(trace) do { } while (0)
499 __init static int init_irqsoff_tracer(void)
501 register_irqsoff(irqsoff_tracer);
502 register_preemptoff(preemptoff_tracer);
503 register_preemptirqsoff(preemptirqsoff_tracer);
507 device_initcall(init_irqsoff_tracer);