[RFC][PATCH] ftrace: function graph trace context switches

From: Peter Zijlstra
Date: Mon Jan 26 2009 - 09:39:57 EST

On Mon, 2009-01-26 at 12:35 +0100, Peter Zijlstra wrote:
>
> Another something nice would be to have ctx switches like:
>
> foo-1 => bar-2 ran: ${time foo spend on the cpu} since: ${time bar
> spend away from the cpu}

Steve, Frederic, how's this?

(compile tested only)

---
include/linux/ftrace.h | 5 ++
kernel/sched_fair.c | 1 -
kernel/trace/Kconfig | 1 +
kernel/trace/trace.c | 51 +++++++++++++++++++
kernel/trace/trace.h | 10 ++++
kernel/trace/trace_functions_graph.c | 88 ++++++++++++++-------------------
6 files changed, 104 insertions(+), 52 deletions(-)

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 9f7880d..411b027 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -381,6 +381,11 @@ struct ftrace_graph_ret {
int depth;
};

+struct ftrace_graph_switch {
+ pid_t prev, next;
+ u64 ran, since;
+};
+
#ifdef CONFIG_FUNCTION_GRAPH_TRACER

/*
diff --git a/kernel/sched_fair.c b/kernel/sched_fair.c
index f34cf42..fa477ac 100644
--- a/kernel/sched_fair.c
+++ b/kernel/sched_fair.c
@@ -530,7 +530,6 @@ update_stats_wait_end(struct cfs_rq *cfs_rq, struct sched_entity *se)
schedstat_set(se->wait_count, se->wait_count + 1);
schedstat_set(se->wait_sum, se->wait_sum +
rq_of(cfs_rq)->clock - se->wait_start);
- schedstat_set(se->wait_start, 0);
}

static inline void
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index dde1d46..7aa1c13 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -67,6 +67,7 @@ config FUNCTION_GRAPH_TRACER
bool "Kernel Function Graph Tracer"
depends on HAVE_FUNCTION_GRAPH_TRACER
depends on FUNCTION_TRACER
+ select SCHEDSTATS
default y
help
Enable the kernel to trace a function at both its return
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 2129ab9..380a334 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -31,6 +31,7 @@
#include <linux/fs.h>
#include <linux/kprobes.h>
#include <linux/writeback.h>
+#include <linux/sched.h>

#include <linux/stacktrace.h>
#include <linux/ring_buffer.h>
@@ -820,6 +821,35 @@ static void __trace_graph_return(struct trace_array *tr,
entry->ret = *trace;
ring_buffer_unlock_commit(global_trace.buffer, event, irq_flags);
}
+
+static void __trace_graph_switch(struct trace_array *tr,
+ struct trace_array_cpu *data,
+ unsigned long flags, int pc,
+ struct task_struct *prev,
+ struct task_struct *next)
+{
+ struct ring_buffer_event *event;
+ struct ftrace_graph_switch_entry *entry;
+ unsigned long irq_flags;
+
+ if (unlikely(local_read(&__get_cpu_var(ftrace_cpu_disabled))))
+ return;
+
+ event = ring_buffer_lock_reserve(global_trace.buffer, sizeof(*entry),
+ &irq_flags);
+ if (!event)
+ return;
+ entry = ring_buffer_event_data(event);
+ tracing_generic_entry_update(&entry->ent, flags, pc);
+ entry->ent.type = TRACE_GRAPH_SWITCH;
+ entry->ctx.prev = prev->pid;
+ entry->ctx.next = next->pid;
+ entry->ctx.ran = prev->se.sum_exec_runtime -
+ prev->se.prev_sum_exec_runtime;
+ entry->ctx.since = next->se.exec_start - next->se.wait_start;
+
+ ring_buffer_unlock_commit(global_trace.buffer, event, irq_flags);
+}
#endif

void
@@ -1097,6 +1127,27 @@ void trace_graph_return(struct ftrace_graph_ret *trace)
atomic_dec(&data->disabled);
local_irq_restore(flags);
}
+
+void trace_graph_switch(struct task_struct *prev, struct task_struct *next)
+{
+ struct trace_array *tr = &global_trace;
+ struct trace_array_cpu *data;
+ unsigned long flags;
+ long disabled;
+ int cpu;
+ int pc;
+
+ local_irq_save(flags);
+ cpu = raw_smp_processor_id();
+ data = tr->data[cpu];
+ disabled = atomic_inc_return(&data->disabled);
+ if (likely(disabled == 1)) {
+ pc = preempt_count();
+ __trace_graph_switch(tr, data, flags, pc, prev, next);
+ }
+ atomic_dec(&data->disabled);
+ local_irq_restore(flags);
+}
#endif /* CONFIG_FUNCTION_GRAPH_TRACER */

enum trace_file_type {
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index b96037d..781fbce 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -27,6 +27,7 @@ enum trace_type {
TRACE_BOOT_RET,
TRACE_GRAPH_RET,
TRACE_GRAPH_ENT,
+ TRACE_GRAPH_SWITCH,
TRACE_USER_STACK,
TRACE_HW_BRANCHES,
TRACE_KMEM_ALLOC,
@@ -71,6 +72,12 @@ struct ftrace_graph_ret_entry {
struct trace_entry ent;
struct ftrace_graph_ret ret;
};
+
+struct ftrace_graph_switch_entry {
+ struct trace_entry ent;
+ struct ftrace_graph_switch ctx;
+};
+
extern struct tracer boot_tracer;

/*
@@ -295,6 +302,8 @@ extern void __ftrace_bad_type(void);
TRACE_GRAPH_ENT); \
IF_ASSIGN(var, ent, struct ftrace_graph_ret_entry, \
TRACE_GRAPH_RET); \
+ IF_ASSIGN(var, ent, struct ftrace_graph_switch_entry, \
+ TRACE_GRAPH_SWITCH); \
IF_ASSIGN(var, ent, struct hw_branch_entry, TRACE_HW_BRANCHES);\
IF_ASSIGN(var, ent, struct trace_power, TRACE_POWER); \
IF_ASSIGN(var, ent, struct kmemtrace_alloc_entry, \
@@ -438,6 +447,7 @@ void trace_function(struct trace_array *tr,

void trace_graph_return(struct ftrace_graph_ret *trace);
int trace_graph_entry(struct ftrace_graph_ent *trace);
+void trace_graph_switch(struct task_struct *prev, struct task_struct *next);

void tracing_start_cmdline_record(void);
void tracing_stop_cmdline_record(void);
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 66fc7b8..cf6494b 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -10,6 +10,7 @@
#include <linux/uaccess.h>
#include <linux/ftrace.h>
#include <linux/fs.h>
+#include <trace/sched.h>

#include "trace.h"
#include "trace_output.h"
@@ -158,28 +159,13 @@ print_graph_proc(struct trace_seq *s, pid_t pid)
return TRACE_TYPE_HANDLED;
}

-
-/* If the pid changed since the last trace, output this event */
static enum print_line_t
-verif_pid(struct trace_seq *s, pid_t pid, int cpu, pid_t *last_pids_cpu)
+print_graph_switch(struct ftrace_graph_switch_entry *field, struct trace_seq *s,
+ struct trace_iterator *iter)
{
- pid_t prev_pid;
- pid_t *last_pid;
+ int cpu = iter->cpu;
int ret;

- if (!last_pids_cpu)
- return TRACE_TYPE_HANDLED;
-
- last_pid = per_cpu_ptr(last_pids_cpu, cpu);
-
- if (*last_pid == pid)
- return TRACE_TYPE_HANDLED;
-
- prev_pid = *last_pid;
- *last_pid = pid;
-
- if (prev_pid == -1)
- return TRACE_TYPE_HANDLED;
/*
* Context-switch trace line:

@@ -197,7 +183,7 @@ verif_pid(struct trace_seq *s, pid_t pid, int cpu, pid_t *last_pids_cpu)
if (ret == TRACE_TYPE_PARTIAL_LINE)
TRACE_TYPE_PARTIAL_LINE;

- ret = print_graph_proc(s, prev_pid);
+ ret = print_graph_proc(s, field->ctx.prev);
if (ret == TRACE_TYPE_PARTIAL_LINE)
TRACE_TYPE_PARTIAL_LINE;

@@ -205,16 +191,21 @@ verif_pid(struct trace_seq *s, pid_t pid, int cpu, pid_t *last_pids_cpu)
if (!ret)
TRACE_TYPE_PARTIAL_LINE;

- ret = print_graph_proc(s, pid);
+ ret = print_graph_proc(s, field->ctx.next);
if (ret == TRACE_TYPE_PARTIAL_LINE)
TRACE_TYPE_PARTIAL_LINE;

+ ret = trace_seq_printf(s, " ran: %Lu, since: %Lu",
+ field->ctx.ran, field->ctx.since);
+ if (!ret)
+ TRACE_TYPE_PARTIAL_LINE;
+
ret = trace_seq_printf(s,
"\n ------------------------------------------\n\n");
if (!ret)
TRACE_TYPE_PARTIAL_LINE;

- return ret;
+ return TRACE_TYPE_HANDLED;
}

static bool
@@ -471,14 +462,9 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
{
int ret;
int cpu = iter->cpu;
- pid_t *last_entry = iter->private;
struct trace_entry *ent = iter->ent;
struct ftrace_graph_ent *call = &field->graph_ent;

- /* Pid */
- if (verif_pid(s, ent->pid, cpu, last_entry) == TRACE_TYPE_PARTIAL_LINE)
- return TRACE_TYPE_PARTIAL_LINE;
-
/* Interrupt */
ret = print_graph_irq(s, call->func, TRACE_GRAPH_ENT, cpu, ent->pid);
if (ret == TRACE_TYPE_PARTIAL_LINE)
@@ -523,12 +509,8 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
int i;
int ret;
int cpu = iter->cpu;
- pid_t *last_pid = iter->private;
unsigned long long duration = trace->rettime - trace->calltime;

- /* Pid */
- if (verif_pid(s, ent->pid, cpu, last_pid) == TRACE_TYPE_PARTIAL_LINE)
- return TRACE_TYPE_PARTIAL_LINE;

/* Absolute time */
if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) {
@@ -600,7 +582,6 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
int i;
int ret;
int cpu = iter->cpu;
- pid_t *last_pid = iter->private;

/* Absolute time */
if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) {
@@ -609,10 +590,6 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
return TRACE_TYPE_PARTIAL_LINE;
}

- /* Pid */
- if (verif_pid(s, ent->pid, cpu, last_pid) == TRACE_TYPE_PARTIAL_LINE)
- return TRACE_TYPE_PARTIAL_LINE;
-
/* Cpu */
if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
ret = print_graph_cpu(s, cpu);
@@ -677,6 +654,11 @@ print_graph_function(struct trace_iterator *iter)
struct trace_entry *entry = iter->ent;

switch (entry->type) {
+ case TRACE_GRAPH_SWITCH: {
+ struct ftrace_graph_switch_entry *field;
+ trace_assign_type(field, entry);
+ return print_graph_switch(field, s, iter);
+ }
case TRACE_GRAPH_ENT: {
struct ftrace_graph_ent_entry *field;
trace_assign_type(field, entry);
@@ -724,34 +706,38 @@ static void print_graph_headers(struct seq_file *s)
seq_printf(s, " | | | |\n");
}

-static void graph_trace_open(struct trace_iterator *iter)
+static void probe_sched_switch(struct rq *rq,
+ struct task_struct *prev,
+ struct task_struct *next)
{
- /* pid on the last trace processed */
- pid_t *last_pid = alloc_percpu(pid_t);
- int cpu;
+ trace_graph_switch(prev, next);
+}

- if (!last_pid)
- pr_warning("function graph tracer: not enough memory\n");
- else
- for_each_possible_cpu(cpu) {
- pid_t *pid = per_cpu_ptr(last_pid, cpu);
- *pid = -1;
- }
+static DEFINE_MUTEX(graph_trace_mutex);
+static int graph_trace_ref;

- iter->private = last_pid;
+static void graph_trace_start(struct trace_array *tr)
+{
+ mutex_lock(&graph_trace_mutex);
+ if (!(graph_trace_ref++))
+ register_trace_sched_switch(probe_sched_switch);
+ mutex_unlock(&graph_trace_mutex);
}

-static void graph_trace_close(struct trace_iterator *iter)
+static void graph_trace_stop(struct trace_array *tr)
{
- percpu_free(iter->private);
+ mutex_lock(&graph_trace_mutex);
+ if (!(--graph_trace_ref))
+ unregister_trace_sched_switch(probe_sched_switch);
+ mutex_unlock(&graph_trace_mutex);
}

static struct tracer graph_trace __read_mostly = {
.name = "function_graph",
- .open = graph_trace_open,
- .close = graph_trace_close,
.init = graph_trace_init,
.reset = graph_trace_reset,
+ .start = graph_trace_start,
+ .stop = graph_trace_stop,
.print_line = print_graph_function,
.print_header = print_graph_headers,
.flags = &tracer_flags,


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/