2 * trace irqs off critical 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 static int save_lat_flag
;
37 static void stop_irqsoff_tracer(struct trace_array
*tr
, int graph
);
38 static int start_irqsoff_tracer(struct trace_array
*tr
, int graph
);
40 #ifdef CONFIG_PREEMPT_TRACER
44 return ((trace_type
& TRACER_PREEMPT_OFF
) && preempt_count());
47 # define preempt_trace() (0)
50 #ifdef CONFIG_IRQSOFF_TRACER
54 return ((trace_type
& TRACER_IRQS_OFF
) &&
58 # define irq_trace() (0)
61 #define TRACE_DISPLAY_GRAPH 1
63 static struct tracer_opt trace_opts
[] = {
64 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
65 /* display latency trace as call graph */
66 { TRACER_OPT(display
-graph
, TRACE_DISPLAY_GRAPH
) },
71 static struct tracer_flags tracer_flags
= {
76 #define is_graph() (tracer_flags.val & TRACE_DISPLAY_GRAPH)
79 * Sequence count - we record it when starting a measurement and
80 * skip the latency if the sequence has changed - some other section
81 * did a maximum and could disturb our measurement with serial console
82 * printouts, etc. Truly coinciding maximum latencies should be rare
83 * and what happens together happens separately as well, so this doesnt
84 * decrease the validity of the maximum found:
86 static __cacheline_aligned_in_smp
unsigned long max_sequence
;
88 #ifdef CONFIG_FUNCTION_TRACER
90 * irqsoff uses its own tracer function to keep the overhead down:
93 irqsoff_tracer_call(unsigned long ip
, unsigned long parent_ip
)
95 struct trace_array
*tr
= irqsoff_trace
;
96 struct trace_array_cpu
*data
;
102 * Does not matter if we preempt. We test the flags
103 * afterward, to see if irqs are disabled or not.
104 * If we preempt and get a false positive, the flags
107 cpu
= raw_smp_processor_id();
108 if (likely(!per_cpu(tracing_cpu
, cpu
)))
111 local_save_flags(flags
);
112 /* slight chance to get a false positive on tracing_cpu */
113 if (!irqs_disabled_flags(flags
))
116 data
= tr
->data
[cpu
];
117 disabled
= atomic_inc_return(&data
->disabled
);
119 if (likely(disabled
== 1))
120 trace_function(tr
, ip
, parent_ip
, flags
, preempt_count());
122 atomic_dec(&data
->disabled
);
125 static struct ftrace_ops trace_ops __read_mostly
=
127 .func
= irqsoff_tracer_call
,
129 #endif /* CONFIG_FUNCTION_TRACER */
131 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
132 static int irqsoff_set_flag(u32 old_flags
, u32 bit
, int set
)
136 if (!(bit
& TRACE_DISPLAY_GRAPH
))
139 if (!(is_graph() ^ set
))
142 stop_irqsoff_tracer(irqsoff_trace
, !set
);
144 for_each_possible_cpu(cpu
)
145 per_cpu(tracing_cpu
, cpu
) = 0;
147 tracing_max_latency
= 0;
148 tracing_reset_online_cpus(irqsoff_trace
);
150 return start_irqsoff_tracer(irqsoff_trace
, set
);
153 static int irqsoff_graph_entry(struct ftrace_graph_ent
*trace
)
155 struct trace_array
*tr
= irqsoff_trace
;
156 struct trace_array_cpu
*data
;
163 cpu
= raw_smp_processor_id();
164 if (likely(!per_cpu(tracing_cpu
, cpu
)))
167 local_save_flags(flags
);
168 /* slight chance to get a false positive on tracing_cpu */
169 if (!irqs_disabled_flags(flags
))
172 data
= tr
->data
[cpu
];
173 disabled
= atomic_inc_return(&data
->disabled
);
175 if (likely(disabled
== 1)) {
176 pc
= preempt_count();
177 ret
= __trace_graph_entry(tr
, trace
, flags
, pc
);
181 atomic_dec(&data
->disabled
);
185 static void irqsoff_graph_return(struct ftrace_graph_ret
*trace
)
187 struct trace_array
*tr
= irqsoff_trace
;
188 struct trace_array_cpu
*data
;
194 cpu
= raw_smp_processor_id();
195 if (likely(!per_cpu(tracing_cpu
, cpu
)))
198 local_save_flags(flags
);
199 /* slight chance to get a false positive on tracing_cpu */
200 if (!irqs_disabled_flags(flags
))
203 data
= tr
->data
[cpu
];
204 disabled
= atomic_inc_return(&data
->disabled
);
206 if (likely(disabled
== 1)) {
207 pc
= preempt_count();
208 __trace_graph_return(tr
, trace
, flags
, pc
);
211 atomic_dec(&data
->disabled
);
214 static void irqsoff_trace_open(struct trace_iterator
*iter
)
217 graph_trace_open(iter
);
221 static void irqsoff_trace_close(struct trace_iterator
*iter
)
224 graph_trace_close(iter
);
227 #define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_CPU | \
228 TRACE_GRAPH_PRINT_PROC)
230 static enum print_line_t
irqsoff_print_line(struct trace_iterator
*iter
)
232 u32 flags
= GRAPH_TRACER_FLAGS
;
234 if (trace_flags
& TRACE_ITER_LATENCY_FMT
)
235 flags
|= TRACE_GRAPH_PRINT_DURATION
;
237 flags
|= TRACE_GRAPH_PRINT_ABS_TIME
;
240 * In graph mode call the graph tracer output function,
241 * otherwise go with the TRACE_FN event handler
244 return print_graph_function_flags(iter
, flags
);
246 return TRACE_TYPE_UNHANDLED
;
249 static void irqsoff_print_header(struct seq_file
*s
)
252 struct trace_iterator
*iter
= s
->private;
253 u32 flags
= GRAPH_TRACER_FLAGS
;
255 if (trace_flags
& TRACE_ITER_LATENCY_FMT
) {
256 /* print nothing if the buffers are empty */
257 if (trace_empty(iter
))
260 print_trace_header(s
, iter
);
261 flags
|= TRACE_GRAPH_PRINT_DURATION
;
263 flags
|= TRACE_GRAPH_PRINT_ABS_TIME
;
265 print_graph_headers_flags(s
, flags
);
267 trace_default_header(s
);
271 trace_graph_function(struct trace_array
*tr
,
272 unsigned long ip
, unsigned long flags
, int pc
)
274 u64 time
= trace_clock_local();
275 struct ftrace_graph_ent ent
= {
279 struct ftrace_graph_ret ret
= {
286 __trace_graph_entry(tr
, &ent
, flags
, pc
);
287 __trace_graph_return(tr
, &ret
, flags
, pc
);
291 __trace_function(struct trace_array
*tr
,
292 unsigned long ip
, unsigned long parent_ip
,
293 unsigned long flags
, int pc
)
296 trace_function(tr
, ip
, parent_ip
, flags
, pc
);
298 trace_graph_function(tr
, parent_ip
, flags
, pc
);
299 trace_graph_function(tr
, ip
, flags
, pc
);
304 #define __trace_function trace_function
306 static int irqsoff_set_flag(u32 old_flags
, u32 bit
, int set
)
311 static int irqsoff_graph_entry(struct ftrace_graph_ent
*trace
)
316 static enum print_line_t
irqsoff_print_line(struct trace_iterator
*iter
)
318 return TRACE_TYPE_UNHANDLED
;
321 static void irqsoff_graph_return(struct ftrace_graph_ret
*trace
) { }
322 static void irqsoff_print_header(struct seq_file
*s
) { }
323 static void irqsoff_trace_open(struct trace_iterator
*iter
) { }
324 static void irqsoff_trace_close(struct trace_iterator
*iter
) { }
325 #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
328 * Should this new latency be reported/recorded?
330 static int report_latency(cycle_t delta
)
332 if (tracing_thresh
) {
333 if (delta
< tracing_thresh
)
336 if (delta
<= tracing_max_latency
)
343 check_critical_timing(struct trace_array
*tr
,
344 struct trace_array_cpu
*data
,
345 unsigned long parent_ip
,
348 cycle_t T0
, T1
, delta
;
352 T0
= data
->preempt_timestamp
;
353 T1
= ftrace_now(cpu
);
356 local_save_flags(flags
);
358 pc
= preempt_count();
360 if (!report_latency(delta
))
363 spin_lock_irqsave(&max_trace_lock
, flags
);
365 /* check if we are still the max latency */
366 if (!report_latency(delta
))
369 __trace_function(tr
, CALLER_ADDR0
, parent_ip
, flags
, pc
);
370 /* Skip 5 functions to get to the irq/preempt enable function */
371 __trace_stack(tr
, flags
, 5, pc
);
373 if (data
->critical_sequence
!= max_sequence
)
376 data
->critical_end
= parent_ip
;
378 if (likely(!is_tracing_stopped())) {
379 tracing_max_latency
= delta
;
380 update_max_tr_single(tr
, current
, cpu
);
386 spin_unlock_irqrestore(&max_trace_lock
, flags
);
389 data
->critical_sequence
= max_sequence
;
390 data
->preempt_timestamp
= ftrace_now(cpu
);
391 __trace_function(tr
, CALLER_ADDR0
, parent_ip
, flags
, pc
);
395 start_critical_timing(unsigned long ip
, unsigned long parent_ip
)
398 struct trace_array
*tr
= irqsoff_trace
;
399 struct trace_array_cpu
*data
;
402 if (likely(!tracer_enabled
))
405 cpu
= raw_smp_processor_id();
407 if (per_cpu(tracing_cpu
, cpu
))
410 data
= tr
->data
[cpu
];
412 if (unlikely(!data
) || atomic_read(&data
->disabled
))
415 atomic_inc(&data
->disabled
);
417 data
->critical_sequence
= max_sequence
;
418 data
->preempt_timestamp
= ftrace_now(cpu
);
419 data
->critical_start
= parent_ip
? : ip
;
421 local_save_flags(flags
);
423 __trace_function(tr
, ip
, parent_ip
, flags
, preempt_count());
425 per_cpu(tracing_cpu
, cpu
) = 1;
427 atomic_dec(&data
->disabled
);
431 stop_critical_timing(unsigned long ip
, unsigned long parent_ip
)
434 struct trace_array
*tr
= irqsoff_trace
;
435 struct trace_array_cpu
*data
;
438 cpu
= raw_smp_processor_id();
439 /* Always clear the tracing cpu on stopping the trace */
440 if (unlikely(per_cpu(tracing_cpu
, cpu
)))
441 per_cpu(tracing_cpu
, cpu
) = 0;
448 data
= tr
->data
[cpu
];
450 if (unlikely(!data
) ||
451 !data
->critical_start
|| atomic_read(&data
->disabled
))
454 atomic_inc(&data
->disabled
);
456 local_save_flags(flags
);
457 __trace_function(tr
, ip
, parent_ip
, flags
, preempt_count());
458 check_critical_timing(tr
, data
, parent_ip
? : ip
, cpu
);
459 data
->critical_start
= 0;
460 atomic_dec(&data
->disabled
);
463 /* start and stop critical timings used to for stoppage (in idle) */
464 void start_critical_timings(void)
466 if (preempt_trace() || irq_trace())
467 start_critical_timing(CALLER_ADDR0
, CALLER_ADDR1
);
469 EXPORT_SYMBOL_GPL(start_critical_timings
);
471 void stop_critical_timings(void)
473 if (preempt_trace() || irq_trace())
474 stop_critical_timing(CALLER_ADDR0
, CALLER_ADDR1
);
476 EXPORT_SYMBOL_GPL(stop_critical_timings
);
478 #ifdef CONFIG_IRQSOFF_TRACER
479 #ifdef CONFIG_PROVE_LOCKING
480 void time_hardirqs_on(unsigned long a0
, unsigned long a1
)
482 if (!preempt_trace() && irq_trace())
483 stop_critical_timing(a0
, a1
);
486 void time_hardirqs_off(unsigned long a0
, unsigned long a1
)
488 if (!preempt_trace() && irq_trace())
489 start_critical_timing(a0
, a1
);
492 #else /* !CONFIG_PROVE_LOCKING */
498 void early_boot_irqs_off(void)
502 void early_boot_irqs_on(void)
506 void trace_softirqs_on(unsigned long ip
)
510 void trace_softirqs_off(unsigned long ip
)
514 inline void print_irqtrace_events(struct task_struct
*curr
)
519 * We are only interested in hardirq on/off events:
521 void trace_hardirqs_on(void)
523 if (!preempt_trace() && irq_trace())
524 stop_critical_timing(CALLER_ADDR0
, CALLER_ADDR1
);
526 EXPORT_SYMBOL(trace_hardirqs_on
);
528 void trace_hardirqs_off(void)
530 if (!preempt_trace() && irq_trace())
531 start_critical_timing(CALLER_ADDR0
, CALLER_ADDR1
);
533 EXPORT_SYMBOL(trace_hardirqs_off
);
535 void trace_hardirqs_on_caller(unsigned long caller_addr
)
537 if (!preempt_trace() && irq_trace())
538 stop_critical_timing(CALLER_ADDR0
, caller_addr
);
540 EXPORT_SYMBOL(trace_hardirqs_on_caller
);
542 void trace_hardirqs_off_caller(unsigned long caller_addr
)
544 if (!preempt_trace() && irq_trace())
545 start_critical_timing(CALLER_ADDR0
, caller_addr
);
547 EXPORT_SYMBOL(trace_hardirqs_off_caller
);
549 #endif /* CONFIG_PROVE_LOCKING */
550 #endif /* CONFIG_IRQSOFF_TRACER */
552 #ifdef CONFIG_PREEMPT_TRACER
553 void trace_preempt_on(unsigned long a0
, unsigned long a1
)
556 stop_critical_timing(a0
, a1
);
559 void trace_preempt_off(unsigned long a0
, unsigned long a1
)
562 start_critical_timing(a0
, a1
);
564 #endif /* CONFIG_PREEMPT_TRACER */
566 static int start_irqsoff_tracer(struct trace_array
*tr
, int graph
)
571 ret
= register_ftrace_function(&trace_ops
);
573 ret
= register_ftrace_graph(&irqsoff_graph_return
,
574 &irqsoff_graph_entry
);
576 if (!ret
&& tracing_is_enabled())
584 static void stop_irqsoff_tracer(struct trace_array
*tr
, int graph
)
589 unregister_ftrace_function(&trace_ops
);
591 unregister_ftrace_graph();
594 static void __irqsoff_tracer_init(struct trace_array
*tr
)
596 save_lat_flag
= trace_flags
& TRACE_ITER_LATENCY_FMT
;
597 trace_flags
|= TRACE_ITER_LATENCY_FMT
;
599 tracing_max_latency
= 0;
601 /* make sure that the tracer is visible */
603 tracing_reset_online_cpus(tr
);
605 if (start_irqsoff_tracer(tr
, is_graph()))
606 printk(KERN_ERR
"failed to start irqsoff tracer\n");
609 static void irqsoff_tracer_reset(struct trace_array
*tr
)
611 stop_irqsoff_tracer(tr
, is_graph());
614 trace_flags
&= ~TRACE_ITER_LATENCY_FMT
;
617 static void irqsoff_tracer_start(struct trace_array
*tr
)
622 static void irqsoff_tracer_stop(struct trace_array
*tr
)
627 #ifdef CONFIG_IRQSOFF_TRACER
628 static int irqsoff_tracer_init(struct trace_array
*tr
)
630 trace_type
= TRACER_IRQS_OFF
;
632 __irqsoff_tracer_init(tr
);
635 static struct tracer irqsoff_tracer __read_mostly
=
638 .init
= irqsoff_tracer_init
,
639 .reset
= irqsoff_tracer_reset
,
640 .start
= irqsoff_tracer_start
,
641 .stop
= irqsoff_tracer_stop
,
643 .print_header
= irqsoff_print_header
,
644 .print_line
= irqsoff_print_line
,
645 .flags
= &tracer_flags
,
646 .set_flag
= irqsoff_set_flag
,
647 #ifdef CONFIG_FTRACE_SELFTEST
648 .selftest
= trace_selftest_startup_irqsoff
,
650 .open
= irqsoff_trace_open
,
651 .close
= irqsoff_trace_close
,
653 # define register_irqsoff(trace) register_tracer(&trace)
655 # define register_irqsoff(trace) do { } while (0)
658 #ifdef CONFIG_PREEMPT_TRACER
659 static int preemptoff_tracer_init(struct trace_array
*tr
)
661 trace_type
= TRACER_PREEMPT_OFF
;
663 __irqsoff_tracer_init(tr
);
667 static struct tracer preemptoff_tracer __read_mostly
=
669 .name
= "preemptoff",
670 .init
= preemptoff_tracer_init
,
671 .reset
= irqsoff_tracer_reset
,
672 .start
= irqsoff_tracer_start
,
673 .stop
= irqsoff_tracer_stop
,
675 .print_header
= irqsoff_print_header
,
676 .print_line
= irqsoff_print_line
,
677 .flags
= &tracer_flags
,
678 .set_flag
= irqsoff_set_flag
,
679 #ifdef CONFIG_FTRACE_SELFTEST
680 .selftest
= trace_selftest_startup_preemptoff
,
682 .open
= irqsoff_trace_open
,
683 .close
= irqsoff_trace_close
,
685 # define register_preemptoff(trace) register_tracer(&trace)
687 # define register_preemptoff(trace) do { } while (0)
690 #if defined(CONFIG_IRQSOFF_TRACER) && \
691 defined(CONFIG_PREEMPT_TRACER)
693 static int preemptirqsoff_tracer_init(struct trace_array
*tr
)
695 trace_type
= TRACER_IRQS_OFF
| TRACER_PREEMPT_OFF
;
697 __irqsoff_tracer_init(tr
);
701 static struct tracer preemptirqsoff_tracer __read_mostly
=
703 .name
= "preemptirqsoff",
704 .init
= preemptirqsoff_tracer_init
,
705 .reset
= irqsoff_tracer_reset
,
706 .start
= irqsoff_tracer_start
,
707 .stop
= irqsoff_tracer_stop
,
709 .print_header
= irqsoff_print_header
,
710 .print_line
= irqsoff_print_line
,
711 .flags
= &tracer_flags
,
712 .set_flag
= irqsoff_set_flag
,
713 #ifdef CONFIG_FTRACE_SELFTEST
714 .selftest
= trace_selftest_startup_preemptirqsoff
,
716 .open
= irqsoff_trace_open
,
717 .close
= irqsoff_trace_close
,
720 # define register_preemptirqsoff(trace) register_tracer(&trace)
722 # define register_preemptirqsoff(trace) do { } while (0)
725 __init
static int init_irqsoff_tracer(void)
727 register_irqsoff(irqsoff_tracer
);
728 register_preemptoff(preemptoff_tracer
);
729 register_preemptirqsoff(preemptirqsoff_tracer
);
733 device_initcall(init_irqsoff_tracer
);