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
39 return ((trace_type & TRACER_PREEMPT_OFF) && preempt_count());
42 # define preempt_trace() (0)
45 #ifdef CONFIG_IRQSOFF_TRACER
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 trace_function(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 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;
139 T1 = ftrace_now(cpu);
142 local_save_flags(flags);
144 if (!report_latency(delta))
147 spin_lock_irqsave(&max_trace_lock, flags);
149 /* check if we are still the max latency */
150 if (!report_latency(delta))
153 trace_function(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);
168 if (!runqueue_is_locked()) {
169 if (tracing_thresh) {
170 printk(KERN_INFO "(%16s-%-5d|#%d): %lu us critical"
171 " section violates %lu us threshold.\n",
172 current->comm, current->pid,
173 raw_smp_processor_id(),
174 latency, nsecs_to_usecs(tracing_thresh));
176 printk(KERN_INFO "(%16s-%-5d|#%d): new %lu us"
177 " maximum-latency critical section.\n",
178 current->comm, current->pid,
179 raw_smp_processor_id(),
187 spin_unlock_irqrestore(&max_trace_lock, flags);
190 data->critical_sequence = max_sequence;
191 data->preempt_timestamp = ftrace_now(cpu);
193 trace_function(tr, data, CALLER_ADDR0, parent_ip, flags);
197 start_critical_timing(unsigned long ip, unsigned long parent_ip)
200 struct trace_array *tr = irqsoff_trace;
201 struct trace_array_cpu *data;
204 if (likely(!tracer_enabled))
207 if (__get_cpu_var(tracing_cpu))
210 cpu = raw_smp_processor_id();
211 data = tr->data[cpu];
213 if (unlikely(!data) || unlikely(!head_page(data)) ||
214 atomic_read(&data->disabled))
217 atomic_inc(&data->disabled);
219 data->critical_sequence = max_sequence;
220 data->preempt_timestamp = ftrace_now(cpu);
221 data->critical_start = parent_ip ? : ip;
224 local_save_flags(flags);
226 trace_function(tr, data, ip, parent_ip, flags);
228 __get_cpu_var(tracing_cpu) = 1;
230 atomic_dec(&data->disabled);
234 stop_critical_timing(unsigned long ip, unsigned long parent_ip)
237 struct trace_array *tr = irqsoff_trace;
238 struct trace_array_cpu *data;
241 /* Always clear the tracing cpu on stopping the trace */
242 if (unlikely(__get_cpu_var(tracing_cpu)))
243 __get_cpu_var(tracing_cpu) = 0;
250 cpu = raw_smp_processor_id();
251 data = tr->data[cpu];
253 if (unlikely(!data) || unlikely(!head_page(data)) ||
254 !data->critical_start || atomic_read(&data->disabled))
257 atomic_inc(&data->disabled);
258 local_save_flags(flags);
259 trace_function(tr, data, ip, parent_ip, flags);
260 check_critical_timing(tr, data, parent_ip ? : ip, cpu);
261 data->critical_start = 0;
262 atomic_dec(&data->disabled);
265 /* start and stop critical timings used to for stoppage (in idle) */
266 void start_critical_timings(void)
268 if (preempt_trace() || irq_trace())
269 start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
272 void stop_critical_timings(void)
274 if (preempt_trace() || irq_trace())
275 stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
278 #ifdef CONFIG_IRQSOFF_TRACER
279 #ifdef CONFIG_PROVE_LOCKING
280 void time_hardirqs_on(unsigned long a0, unsigned long a1)
282 if (!preempt_trace() && irq_trace())
283 stop_critical_timing(a0, a1);
286 void time_hardirqs_off(unsigned long a0, unsigned long a1)
288 if (!preempt_trace() && irq_trace())
289 start_critical_timing(a0, a1);
292 #else /* !CONFIG_PROVE_LOCKING */
298 void early_boot_irqs_off(void)
302 void early_boot_irqs_on(void)
306 void trace_softirqs_on(unsigned long ip)
310 void trace_softirqs_off(unsigned long ip)
314 inline void print_irqtrace_events(struct task_struct *curr)
319 * We are only interested in hardirq on/off events:
321 void trace_hardirqs_on(void)
323 if (!preempt_trace() && irq_trace())
324 stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
326 EXPORT_SYMBOL(trace_hardirqs_on);
328 void trace_hardirqs_off(void)
330 if (!preempt_trace() && irq_trace())
331 start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
333 EXPORT_SYMBOL(trace_hardirqs_off);
335 void trace_hardirqs_on_caller(unsigned long caller_addr)
337 if (!preempt_trace() && irq_trace())
338 stop_critical_timing(CALLER_ADDR0, caller_addr);
340 EXPORT_SYMBOL(trace_hardirqs_on_caller);
342 void trace_hardirqs_off_caller(unsigned long caller_addr)
344 if (!preempt_trace() && irq_trace())
345 start_critical_timing(CALLER_ADDR0, caller_addr);
347 EXPORT_SYMBOL(trace_hardirqs_off_caller);
349 #endif /* CONFIG_PROVE_LOCKING */
350 #endif /* CONFIG_IRQSOFF_TRACER */
352 #ifdef CONFIG_PREEMPT_TRACER
353 void trace_preempt_on(unsigned long a0, unsigned long a1)
355 stop_critical_timing(a0, a1);
358 void trace_preempt_off(unsigned long a0, unsigned long a1)
360 start_critical_timing(a0, a1);
362 #endif /* CONFIG_PREEMPT_TRACER */
364 static void start_irqsoff_tracer(struct trace_array *tr)
366 register_ftrace_function(&trace_ops);
370 static void stop_irqsoff_tracer(struct trace_array *tr)
373 unregister_ftrace_function(&trace_ops);
376 static void __irqsoff_tracer_init(struct trace_array *tr)
379 /* make sure that the tracer is visibel */
383 start_irqsoff_tracer(tr);
386 static void irqsoff_tracer_reset(struct trace_array *tr)
389 stop_irqsoff_tracer(tr);
392 static void irqsoff_tracer_ctrl_update(struct trace_array *tr)
395 start_irqsoff_tracer(tr);
397 stop_irqsoff_tracer(tr);
400 static void irqsoff_tracer_open(struct trace_iterator *iter)
402 /* stop the trace while dumping */
404 stop_irqsoff_tracer(iter->tr);
407 static void irqsoff_tracer_close(struct trace_iterator *iter)
410 start_irqsoff_tracer(iter->tr);
413 #ifdef CONFIG_IRQSOFF_TRACER
414 static void irqsoff_tracer_init(struct trace_array *tr)
416 trace_type = TRACER_IRQS_OFF;
418 __irqsoff_tracer_init(tr);
420 static struct tracer irqsoff_tracer __read_mostly =
423 .init = irqsoff_tracer_init,
424 .reset = irqsoff_tracer_reset,
425 .open = irqsoff_tracer_open,
426 .close = irqsoff_tracer_close,
427 .ctrl_update = irqsoff_tracer_ctrl_update,
429 #ifdef CONFIG_FTRACE_SELFTEST
430 .selftest = trace_selftest_startup_irqsoff,
433 # define register_irqsoff(trace) register_tracer(&trace)
435 # define register_irqsoff(trace) do { } while (0)
438 #ifdef CONFIG_PREEMPT_TRACER
439 static void preemptoff_tracer_init(struct trace_array *tr)
441 trace_type = TRACER_PREEMPT_OFF;
443 __irqsoff_tracer_init(tr);
446 static struct tracer preemptoff_tracer __read_mostly =
448 .name = "preemptoff",
449 .init = preemptoff_tracer_init,
450 .reset = irqsoff_tracer_reset,
451 .open = irqsoff_tracer_open,
452 .close = irqsoff_tracer_close,
453 .ctrl_update = irqsoff_tracer_ctrl_update,
455 #ifdef CONFIG_FTRACE_SELFTEST
456 .selftest = trace_selftest_startup_preemptoff,
459 # define register_preemptoff(trace) register_tracer(&trace)
461 # define register_preemptoff(trace) do { } while (0)
464 #if defined(CONFIG_IRQSOFF_TRACER) && \
465 defined(CONFIG_PREEMPT_TRACER)
467 static void preemptirqsoff_tracer_init(struct trace_array *tr)
469 trace_type = TRACER_IRQS_OFF | TRACER_PREEMPT_OFF;
471 __irqsoff_tracer_init(tr);
474 static struct tracer preemptirqsoff_tracer __read_mostly =
476 .name = "preemptirqsoff",
477 .init = preemptirqsoff_tracer_init,
478 .reset = irqsoff_tracer_reset,
479 .open = irqsoff_tracer_open,
480 .close = irqsoff_tracer_close,
481 .ctrl_update = irqsoff_tracer_ctrl_update,
483 #ifdef CONFIG_FTRACE_SELFTEST
484 .selftest = trace_selftest_startup_preemptirqsoff,
488 # define register_preemptirqsoff(trace) register_tracer(&trace)
490 # define register_preemptirqsoff(trace) do { } while (0)
493 __init static int init_irqsoff_tracer(void)
495 register_irqsoff(irqsoff_tracer);
496 register_preemptoff(preemptoff_tracer);
497 register_preemptirqsoff(preemptirqsoff_tracer);
501 device_initcall(init_irqsoff_tracer);