[PATCH 1/2] 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
@ 2008-12-08  0:54 Frederic Weisbecker
  2008-12-08  6:19 ` Peter Zijlstra
  2008-12-08 12:22 ` Ingo Molnar
  0 siblings, 2 replies; 8+ messages in thread
From: Frederic Weisbecker @ 2008-12-08  0:54 UTC (permalink / raw)
  To: Ingo Molnar; +Cc: Steven Rostedt, Peter Zijlstra, Linux Kernel

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   |                              }

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---

diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
index 1b43086..26b4d6a 100644
--- a/arch/x86/kernel/ftrace.c
+++ b/arch/x86/kernel/ftrace.c
@@ -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);
 
diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 11cac81..36065e8 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -411,6 +411,9 @@ static inline void unpause_graph_tracing(void)
 {
 	atomic_dec(&current->tracing_graph_pause);
 }
+
+/* Contains the entrypoints to hardirq (arch defined) */
+extern const char *ftrace_graph_irq_entries[];
 #else
 
 #define __notrace_funcgraph
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 32b7fb9..7ea446d 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -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;
 }
 
-- 
1.6.0.4


^ permalink raw reply related	[flat|nested] 8+ messages in thread