tracing/function-graph-tracer: signal interrupts entry/exit points on outpout
PATCH 1/2 tracing/function-graph-tracer: signal interrupts entry/exit points on outpout
Impact: provide interrupt detection on output
Suggested by Ingo.
If a hardirq is raised, we want it to be signaled on output, so this patch adds two arrows on the output to find entry and exit points of a hardirq.
Unfortunately, there are many interrupt entrypoints and these can be differents from one arch to another.
The approach here is one of the easiest, but doesn't shine by its scalability:
we have an array of the interrupt entrypoints names that we compare with the symbol of the current traced function, if it matches, we draw the arrow.
Ie:
1) | unlock_buffer() {
1) | wake_up_bit() {
1) | bit_waitqueue() {
1) 0.872 us | __phys_addr();
1) 2.722 us | }
1) | __wake_up_bit() {
=================>
1) | do_IRQ() {
1) | exit_idle() {
1) | irq_enter() {
1) 0.790 us | idle_cpu();
1) 2.346 us | }
1) | handle_edge_irq() {
1) 1.098 us | _spin_lock();
1) | ack_apic_edge() {
1) 0.722 us | irq_complete_move();
1) 0.737 us | move_native_irq();
1) 0.707 us | native_apic_mem_write();
1) 5.249 us | }
1) 0.879 us | _spin_unlock();
1) | handle_IRQ_event() {
1) | timer_interrupt() {
1) | tick_handle_oneshot_broadcast() {
1) 1.165 us | _spin_lock();
1) | ktime_get() {
1) | ktime_get_ts() {
1) | getnstimeofday() {
1) 1.782 us | read_hpet();
1) 3.542 us | }
1) 0.744 us | set_normalized_timespec();
1) 6.640 us | }
1) 8.226 us | }
1) | tick_do_broadcast() {
1) | lapic_timer_broadcast() {
1) 0.879 us | flat_send_IPI_mask();
1) 2.467 us | }
1) 4.045 us | }
1) 0.864 us | _spin_unlock();
1) + 18.431 us | }
1) + 20.047 us | }
1) + 21.611 us | }
1) 0.940 us | note_interrupt();
1) 1.008 us | _spin_lock();
1) 0.992 us | _spin_unlock();
1) + 38.711 us | }
1) | irq_exit() {
1) 0.752 us | idle_cpu();
1) 2.609 us | }
1) + 48.952 us | }
<=================
1) + 55.314 us | }
1) + 60.983 us | }
1) + 62.976 us | }
1) + 64.984 us | }---
arch/x86/kernel/ftrace.c +18 -0
@@ -324,6 +324,24 @@ int __init ftrace_dyn_arch_init(void *data)#ifdef CONFIG_FUNCTION_GRAPH_TRACER +/* Used during output to find the interrupts entry/exit points */ +const char *ftrace_graph_irq_entries[] = { +"smp_call_function_single_interrupt" , +"xen_call_function_single_interrupt" , +"wrapper_smp_local_timer_interrupt" , +"smp_irq_move_cleanup_interrupt" , +"smp_call_function_interrupt" , +"xen_call_function_interrupt" , +"smp_apic_timer_interrupt" , +"uv_bau_message_interrupt" , +"mce_threshold_interrupt" , +"smp_spurious_interrupt" , +"smp_thermal_interrupt" , +"smp_error_interrupt" , +"do_IRQ" , +NULL +}; +#ifdef CONFIG_DYNAMIC_FTRACE extern void ftrace_graph_call (void );
include/linux/ftrace.h +3 -0
@@ -411,6 +411,9 @@ static inline void unpause_graph_tracing(void) {atomic_dec (¤t->tracing_graph_pause); } + +/* Contains the entrypoints to hardirq (arch defined) */ +extern const char *ftrace_graph_irq_entries[];#else #define __notrace_funcgraph
kernel/trace/trace_functions_graph.c +36 -0
@@ -10,6 +10,8 @@#include <linux/uaccess.h> #include <linux/ftrace.h> #include <linux/fs.h> +#include <linux/module.h> +#include <linux/kallsyms.h> #include "trace.h"
@@ -64,6 +66,31 @@ static void graph_trace_reset(struct trace_array *tr)unregister_ftrace_graph (); } +/* Signal enter into or exit from an interrupt */ +static enum print_line_t +print_graph_interrupt (struct trace_seq *s,unsigned long addr, +enum trace_type type) +{ +char symbol[KSYM_NAME_LEN ]; +const char *arrow; +int ret; +int i; + +kallsyms_lookup (addr,NULL ,NULL ,NULL , symbol); +for (i =0 ; ftrace_graph_irq_entries[i]; i++) +if (!strcmp (symbol, ftrace_graph_irq_entries[i])) { +if (type ==TRACE_GRAPH_ENT ) + arrow =" =================>\n" ; +else + arrow =" <=================\n" ; + ret =trace_seq_printf (s, arrow); +if (!ret) +return TRACE_TYPE_PARTIAL_LINE ; +break ; + } +return TRACE_TYPE_HANDLED ; +} +static inline int log10_cpu (int nb) {if (nb /100 )
@@ -385,6 +412,10 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,int ret;struct trace_entry *ent = iter->ent; + ret =print_graph_interrupt (s, field->graph_ent.func,TRACE_GRAPH_ENT ); +if (ret ==TRACE_TYPE_PARTIAL_LINE ) +return TRACE_TYPE_PARTIAL_LINE ; +/* Pid */ if (verif_pid (s, ent->pid, cpu) ==TRACE_TYPE_PARTIAL_LINE )return TRACE_TYPE_PARTIAL_LINE ;
@@ -474,6 +505,11 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,if (!ret)return TRACE_TYPE_PARTIAL_LINE ; } + + ret =print_graph_interrupt (s, trace->func,TRACE_GRAPH_RET ); +if (ret ==TRACE_TYPE_PARTIAL_LINE ) +return TRACE_TYPE_PARTIAL_LINE ; +return TRACE_TYPE_HANDLED ; }
Signature · 1 line
1.6.0.4
Quoted 15 lines · Frederic Weisbecker
Impact: provide interrupt detection on output
Suggested by Ingo.
If a hardirq is raised, we want it to be signaled on output, so this patch adds two arrows on the output to find entry and exit points of a hardirq.Unfortunately, there are many interrupt entrypoints and these can be differents from one arch to another.
The approach here is one of the easiest, but doesn't shine by its scalability:
we have an array of the interrupt entrypoints names that we compare with the symbol of the current traced function, if it matches, we draw the arrow.Ie:
Quoted 8 lines
1) | unlock_buffer() { 1) | wake_up_bit() { 1) | bit_waitqueue() { 1) 0.872 us | __phys_addr(); 1) 2.722 us | } 1) | __wake_up_bit() {1) ==>
__wake_up_bit(){
1) |do_IRQ(){
Would be much nicer, the current proposal is lost when grepping and adds a weird visual break in the output.
2008/12/8 Peter Zijlstra <[email protected]>:
Quoted 25 lines · Frederic Weisbecker
Quoted 15 lines
Impact: provide interrupt detection on output
Suggested by Ingo.
If a hardirq is raised, we want it to be signaled on output, so this patch adds two arrows on the output to find entry and exit points of a hardirq.Unfortunately, there are many interrupt entrypoints and these can be differents from one arch to another.
The approach here is one of the easiest, but doesn't shine by its scalability:
we have an array of the interrupt entrypoints names that we compare with the symbol of the current traced function, if it matches, we draw the arrow.Ie:
Quoted 8 lines
1) | unlock_buffer() { 1) | wake_up_bit() { 1) | bit_waitqueue() { 1) 0.872 us | __phys_addr(); 1) 2.722 us | } 1) | __wake_up_bit() {1) ==>
__wake_up_bit(){
1) |do_IRQ(){
Quoted 2 lines
Would be much nicer, the current proposal is lost when grepping and adds a weird visual break in the output.
Ok, I will apply it like this in the V2.
Thanks!
Quoted 26 lines · Frédéric Weisbecker
2008/12/8 Peter Zijlstra <[email protected]>:
Quoted 25 lines · Frederic Weisbecker
Quoted 23 lines
Impact: provide interrupt detection on output
Suggested by Ingo.
If a hardirq is raised, we want it to be signaled on output, so this patch adds two arrows on the output to find entry and exit points of a hardirq.Unfortunately, there are many interrupt entrypoints and these can be differents from one arch to another.
The approach here is one of the easiest, but doesn't shine by its scalability:
we have an array of the interrupt entrypoints names that we compare with the symbol of the current traced function, if it matches, we draw the arrow.Ie:
1) | unlock_buffer() { 1) | wake_up_bit() { 1) | bit_waitqueue() { 1) 0.872 us | __phys_addr(); 1) 2.722 us | } 1) | __wake_up_bit() {1) ==>
__wake_up_bit(){
1) |do_IRQ(){
Quoted 6 lines
Quoted 2 lines
Would be much nicer, the current proposal is lost when grepping and adds a weird visual break in the output.
Ok, I will apply it like this in the V2.
Thanks!
note that since the IRQ marker always comes on an entry record, there's space in the usecs field for something like:
1) 2.722 us | }
1) | __wake_up_bit() {
1) [IRQ#123] ==> __wake_up_bit() {right?
Ingo
2008/12/8 Ingo Molnar <[email protected]>:
Quoted 36 lines · Frédéric Weisbecker
Quoted 27 lines
2008/12/8 Peter Zijlstra <[email protected]>:
Quoted 25 lines · Frederic Weisbecker
Quoted 23 lines
Impact: provide interrupt detection on output
Suggested by Ingo.
If a hardirq is raised, we want it to be signaled on output, so this patch adds two arrows on the output to find entry and exit points of a hardirq.Unfortunately, there are many interrupt entrypoints and these can be differents from one arch to another.
The approach here is one of the easiest, but doesn't shine by its scalability:
we have an array of the interrupt entrypoints names that we compare with the symbol of the current traced function, if it matches, we draw the arrow.Ie:
1) | unlock_buffer() { 1) | wake_up_bit() { 1) | bit_waitqueue() { 1) 0.872 us | __phys_addr(); 1) 2.722 us | } 1) | __wake_up_bit() {1) ==>
__wake_up_bit(){
1) |do_IRQ(){Quoted 6 lines
Quoted 2 lines
Would be much nicer, the current proposal is lost when grepping and adds a weird visual break in the output.
Ok, I will apply it like this in the V2.
Thanks!
Quoted 8 lines
note that since the IRQ marker always comes on an entry record, there's space in the usecs field for something like:
1) 2.722 us | } 1) | __wake_up_bit() { 1) [IRQ#123] ==> __wake_up_bit() {right?
Heh, I wanted to display the irq number inside the arrow but didn't think someone would find it useful.
Ok, will apply that too :-)
Quoted 6 lines · Frederic Weisbecker
arch/x86/kernel/ftrace.c +6
-0+/* Used during output to find the interrupts entry/exit points */ +const char *ftrace_graph_irq_entries[] = { +"smp_call_function_single_interrupt" , +"xen_call_function_single_interrupt" , +"wrapper_smp_local_timer_interrupt" , +"smp_irq_move_cleanup_interrupt" ,
arch/x86/kernel/ftrace.c int __init ftrace_dyn_arch_init(void *data) · line 342
Quoted 10 lines
arch/x86/kernel/ftrace.c +10
-0+"smp_call_function_interrupt" , +"xen_call_function_interrupt" , +"smp_apic_timer_interrupt" , +"uv_bau_message_interrupt" , +"mce_threshold_interrupt" , +"smp_spurious_interrupt" , +"smp_thermal_interrupt" , +"smp_error_interrupt" , +"do_IRQ" , +NULL
hm, couldnt we move these symbols to a separate section, and then only check for [section.start ... section.end] instead of this ugly and slow array?
Missing a few annotations initially is no big deal - we wont have pretty-print. do_IRQ() and smp_apic_timer_interrupt is what matters most in practice. "__irqentry" section annotation or so, which puts them into .text.irqentry or so - and then irqentry_start/end are extracted via appropriate glue in the arch/x86/kernel/vmlinux* linker script.
Ingo
2008/12/8 Ingo Molnar <[email protected]>:
Quoted 24 lines · Frederic Weisbecker
Quoted 7 lines
arch/x86/kernel/ftrace.c +6
-0+/* Used during output to find the interrupts entry/exit points */ +const char *ftrace_graph_irq_entries[] = { +"smp_call_function_single_interrupt" , +"xen_call_function_single_interrupt" , +"wrapper_smp_local_timer_interrupt" , +"smp_irq_move_cleanup_interrupt" ,arch/x86/kernel/ftrace.c int __init ftrace_dyn_arch_init(void *data) · line 342
Quoted 10 lines
arch/x86/kernel/ftrace.c +10
-0+"smp_call_function_interrupt" , +"xen_call_function_interrupt" , +"smp_apic_timer_interrupt" , +"uv_bau_message_interrupt" , +"mce_threshold_interrupt" , +"smp_spurious_interrupt" , +"smp_thermal_interrupt" , +"smp_error_interrupt" , +"do_IRQ" , +NULL hm, couldnt we move these symbols to a separate section, and then only check for [section.start ... section.end] instead of this ugly and slow array?
Quoted 5 lines
Missing a few annotations initially is no big deal - we wont have pretty-print.
do_IRQ()andsmp_apic_timer_interruptis what matters most in practice. "__irqentry" section annotation or so, which puts them into .text.irqentry or so - and then irqentry_start/end are extracted via appropriate glue in thearch/x86/kernel/vmlinux*linker script.
I found it a bit ugly too while I wrote it :-(
I like this idea of a section, I will just have to verify if it is between the start and the end of
it to check if its an irq entry.
But I think that even if the others than do_IRQ and smp_apic_timer_interrupt are more rare,
they should be annotated for this new section (and it seems there are new coming interrupts
like smp_perf_counter_interrupt() in perf counter....)... Perhaps someone would profile them...
Hm?
Quoted 40 lines · Frédéric Weisbecker
2008/12/8 Ingo Molnar <[email protected]>:
Quoted 24 lines · Frederic Weisbecker
Quoted 7 lines
arch/x86/kernel/ftrace.c +6
-0+/* Used during output to find the interrupts entry/exit points */ +const char *ftrace_graph_irq_entries[] = { +"smp_call_function_single_interrupt" , +"xen_call_function_single_interrupt" , +"wrapper_smp_local_timer_interrupt" , +"smp_irq_move_cleanup_interrupt" ,arch/x86/kernel/ftrace.c int __init ftrace_dyn_arch_init(void *data) · line 342
Quoted 10 lines
arch/x86/kernel/ftrace.c +10
-0+"smp_call_function_interrupt" , +"xen_call_function_interrupt" , +"smp_apic_timer_interrupt" , +"uv_bau_message_interrupt" , +"mce_threshold_interrupt" , +"smp_spurious_interrupt" , +"smp_thermal_interrupt" , +"smp_error_interrupt" , +"do_IRQ" , +NULL hm, couldnt we move these symbols to a separate section, and then only check for [section.start ... section.end] instead of this ugly and slow array?
Quoted 5 lines
Missing a few annotations initially is no big deal - we wont have pretty-print.
do_IRQ()andsmp_apic_timer_interruptis what matters most in practice. "__irqentry" section annotation or so, which puts them into .text.irqentry or so - and then irqentry_start/end are extracted via appropriate glue in thearch/x86/kernel/vmlinux*linker script.I found it a bit ugly too while I wrote it :-( I like this idea of a section, I will just have to verify if it is between the start and the end of it to check if its an irq entry. But I think that even if the others than
do_IRQandsmp_apic_timer_interruptare more rare, they should be annotated for this new section (and it seems there are new coming interrupts likesmp_perf_counter_interrupt()in perf counter....)... Perhaps someone would profile them...
Quoted 1 line
Hm?
not annotating an IRQ entry is not a big problem in practice: people will notice them in traces that they are not annotated, will send a feature request, we annotate them. If they are not noticed, it means they are rare in one way or another, and dont matter in practice. So this is a self-maintaining concept.
Ingo