[PATCH 0/3] [GIT PULL] updates for tip/tracing/ftrace

[PATCH 0/3] [GIT PULL] updates for tip/tracing/ftrace

[Steven Rostedt]

Ingo,

I rebased off of your latest tree. I'm still making some updates to the
function profiler. In doing so, I came across some changes that need to
be made in the function graph tracer. To keep those changes separate
from the function profiler, I'm posting these first.

Please pull the latest tip/tracing/ftrace tree, which can be found at:

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
tip/tracing/ftrace


Steven Rostedt (3):
      function-graph: moved the timestamp from arch to generic code
      function-graph: prevent more than one tracer registering
      function-graph: ignore times across schedule

----
 arch/x86/kernel/ftrace.c             |    6 +----
 include/linux/ftrace.h               |    3 +-
 include/linux/sched.h                |    2 +
 kernel/trace/ftrace.c                |   42 ++++++++++++++++++++++++++++++++++
 kernel/trace/trace_functions_graph.c |    8 ++++--
 5 files changed, 51 insertions(+), 10 deletions(-)
-- 

[PATCH 1/3] function-graph: moved the timestamp from arch to generic code

[Steven Rostedt]

[-- Attachment #1: 0001-function-graph-moved-the-timestamp-from-arch-to-gen.patch --]
[-- Type: text/plain, Size: 2814 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

This patch move the timestamp from happening in the arch specific
code into the general code. This allows for better control by the tracer
to time manipulation.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 arch/x86/kernel/ftrace.c             |    6 +-----
 include/linux/ftrace.h               |    3 +--
 kernel/trace/trace_functions_graph.c |    8 +++++---
 3 files changed, 7 insertions(+), 10 deletions(-)

diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
index 57b33ed..61df775 100644
--- a/arch/x86/kernel/ftrace.c
+++ b/arch/x86/kernel/ftrace.c
@@ -410,7 +410,6 @@ int ftrace_disable_ftrace_graph_caller(void)
 void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
 {
 	unsigned long old;
-	unsigned long long calltime;
 	int faulted;
 	struct ftrace_graph_ent trace;
 	unsigned long return_hooker = (unsigned long)
@@ -453,10 +452,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
 		return;
 	}
 
-	calltime = trace_clock_local();
-
-	if (ftrace_push_return_trace(old, calltime,
-				self_addr, &trace.depth) == -EBUSY) {
+	if (ftrace_push_return_trace(old, self_addr, &trace.depth) == -EBUSY) {
 		*parent = old;
 		return;
 	}
diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index db3fed6..1141248 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -369,8 +369,7 @@ struct ftrace_ret_stack {
 extern void return_to_handler(void);
 
 extern int
-ftrace_push_return_trace(unsigned long ret, unsigned long long time,
-			 unsigned long func, int *depth);
+ftrace_push_return_trace(unsigned long ret, unsigned long func, int *depth);
 extern void
 ftrace_pop_return_trace(struct ftrace_graph_ret *trace, unsigned long *ret);
 
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index e876816..d28687e 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -57,9 +57,9 @@ static struct tracer_flags tracer_flags = {
 
 /* Add a function return address to the trace stack on thread info.*/
 int
-ftrace_push_return_trace(unsigned long ret, unsigned long long time,
-			 unsigned long func, int *depth)
+ftrace_push_return_trace(unsigned long ret, unsigned long func, int *depth)
 {
+	unsigned long long calltime;
 	int index;
 
 	if (!current->ret_stack)
@@ -71,11 +71,13 @@ ftrace_push_return_trace(unsigned long ret, unsigned long long time,
 		return -EBUSY;
 	}
 
+	calltime = trace_clock_local();
+
 	index = ++current->curr_ret_stack;
 	barrier();
 	current->ret_stack[index].ret = ret;
 	current->ret_stack[index].func = func;
-	current->ret_stack[index].calltime = time;
+	current->ret_stack[index].calltime = calltime;
 	*depth = index;
 
 	return 0;
-- 
1.6.2

-- 

[PATCH 2/3] function-graph: prevent more than one tracer registering

[Steven Rostedt]

[-- Attachment #1: 0002-function-graph-prevent-more-than-one-tracer-registe.patch --]
[-- Type: text/plain, Size: 961 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Impact: prevent crash due to multiple function graph tracers

The function graph tracer can currently only handle a single tracer
being registered. If another tracer registers with the function
graph tracer it can crash the system.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/ftrace.c |    6 ++++++
 1 files changed, 6 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 7847806..c81a759 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -2643,6 +2643,12 @@ int register_ftrace_graph(trace_func_graph_ret_t retfunc,
 
 	mutex_lock(&ftrace_lock);
 
+	/* we currently allow only one tracer registered at a time */
+	if (atomic_read(&ftrace_graph_active)) {
+		ret = -EBUSY;
+		goto out;
+	}
+
 	ftrace_suspend_notifier.notifier_call = ftrace_suspend_notifier_call;
 	register_pm_notifier(&ftrace_suspend_notifier);
 
-- 
1.6.2

-- 

[PATCH 3/3] function-graph: ignore times across schedule

[Steven Rostedt]

[-- Attachment #1: 0003-function-graph-ignore-times-across-schedule.patch --]
[-- Type: text/plain, Size: 3688 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Impact: more accurate timings

The current method of function graph tracing does not take into
account the time spent when a task is not running. This shows functions
that call schedule have increased costs:

 3) + 18.664 us   |      }
 ------------------------------------------
 3)    <idle>-0    =>  kblockd-123
 ------------------------------------------

 3)               |      finish_task_switch() {
 3)   1.441 us    |        _spin_unlock_irq();
 3)   3.966 us    |      }
 3) ! 2959.433 us |    }
 3) ! 2961.465 us |  }

This patch uses the tracepoint in the scheduling context switch to
account for time that has elapsed while a task is scheduled out.
Now we see:

 ------------------------------------------
 3)    <idle>-0    =>  edac-po-1067
 ------------------------------------------

 3)               |      finish_task_switch() {
 3)   0.685 us    |        _spin_unlock_irq();
 3)   2.331 us    |      }
 3) + 41.439 us   |    }
 3) + 42.663 us   |  }

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 include/linux/sched.h |    2 ++
 kernel/trace/ftrace.c |   36 ++++++++++++++++++++++++++++++++++++
 2 files changed, 38 insertions(+), 0 deletions(-)

diff --git a/include/linux/sched.h b/include/linux/sched.h
index 89cd308..471e36d 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -1409,6 +1409,8 @@ struct task_struct {
 	int curr_ret_stack;
 	/* Stack of return addresses for return function tracing */
 	struct ftrace_ret_stack	*ret_stack;
+	/* time stamp for last schedule */
+	unsigned long long ftrace_timestamp;
 	/*
 	 * Number of functions that haven't been traced
 	 * because of depth overrun.
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index c81a759..0b90364 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -29,6 +29,8 @@
 #include <linux/list.h>
 #include <linux/hash.h>
 
+#include <trace/sched.h>
+
 #include <asm/ftrace.h>
 
 #include "trace.h"
@@ -2590,6 +2592,31 @@ free:
 	return ret;
 }
 
+static void
+ftrace_graph_probe_sched_switch(struct rq *__rq, struct task_struct *prev,
+				struct task_struct *next)
+{
+	unsigned long long timestamp;
+	int index;
+
+	timestamp = trace_clock_local();
+
+	prev->ftrace_timestamp = timestamp;
+
+	/* only process tasks that we timestamped */
+	if (!next->ftrace_timestamp)
+		return;
+
+	/*
+	 * Update all the counters in next to make up for the
+	 * time next was sleeping.
+	 */
+	timestamp -= next->ftrace_timestamp;
+
+	for (index = next->curr_ret_stack; index >= 0; index--)
+		next->ret_stack[index].calltime += timestamp;
+}
+
 /* Allocate a return stack for each task */
 static int start_graph_tracing(void)
 {
@@ -2611,6 +2638,13 @@ static int start_graph_tracing(void)
 		ret = alloc_retstack_tasklist(ret_stack_list);
 	} while (ret == -EAGAIN);
 
+	if (!ret) {
+		ret = register_trace_sched_switch(ftrace_graph_probe_sched_switch);
+		if (ret)
+			pr_info("ftrace_graph: Couldn't activate tracepoint"
+				" probe to kernel_sched_switch\n");
+	}
+
 	kfree(ret_stack_list);
 	return ret;
 }
@@ -2674,6 +2708,7 @@ void unregister_ftrace_graph(void)
 	mutex_lock(&ftrace_lock);
 
 	atomic_dec(&ftrace_graph_active);
+	unregister_trace_sched_switch(ftrace_graph_probe_sched_switch);
 	ftrace_graph_return = (trace_func_graph_ret_t)ftrace_stub;
 	ftrace_graph_entry = ftrace_graph_entry_stub;
 	ftrace_shutdown(FTRACE_STOP_FUNC_RET);
@@ -2694,6 +2729,7 @@ void ftrace_graph_init_task(struct task_struct *t)
 		t->curr_ret_stack = -1;
 		atomic_set(&t->tracing_graph_pause, 0);
 		atomic_set(&t->trace_overrun, 0);
+		t->ftrace_timestamp = 0;
 	} else
 		t->ret_stack = NULL;
 }
-- 
1.6.2

-- 

Re: [PATCH 3/3] function-graph: ignore times across schedule

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> From: Steven Rostedt <srostedt@redhat.com>
> 
> Impact: more accurate timings
> 
> The current method of function graph tracing does not take into
> account the time spent when a task is not running. This shows functions
> that call schedule have increased costs:
> 
>  3) + 18.664 us   |      }
>  ------------------------------------------
>  3)    <idle>-0    =>  kblockd-123
>  ------------------------------------------
> 
>  3)               |      finish_task_switch() {
>  3)   1.441 us    |        _spin_unlock_irq();
>  3)   3.966 us    |      }
>  3) ! 2959.433 us |    }
>  3) ! 2961.465 us |  }

dunno - i actually like how it shows the _real_ elapsed time. Why is 
this wrong?

	Ingo

Re: [PATCH 3/3] function-graph: ignore times across schedule

[Steven Rostedt]

On Tue, 24 Mar 2009, Ingo Molnar wrote:

> * Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > From: Steven Rostedt <srostedt@redhat.com>
> > 
> > Impact: more accurate timings
> > 
> > The current method of function graph tracing does not take into
> > account the time spent when a task is not running. This shows functions
> > that call schedule have increased costs:
> > 
> >  3) + 18.664 us   |      }
> >  ------------------------------------------
> >  3)    <idle>-0    =>  kblockd-123
> >  ------------------------------------------
> > 
> >  3)               |      finish_task_switch() {
> >  3)   1.441 us    |        _spin_unlock_irq();
> >  3)   3.966 us    |      }
> >  3) ! 2959.433 us |    }
> >  3) ! 2961.465 us |  }
> 
> dunno - i actually like how it shows the _real_ elapsed time. Why is 
> this wrong?

OK,

I'll include a trace option called "sleep-time" to allow the user to 
decide to show this or not.

-- Steve

[PATCH][GIT PULL] function-graph: add option for include sleep times

[Steven Rostedt]

Ingo,

Please pull the latest tip/tracing/ftrace tree, which can be found at:

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
tip/tracing/ftrace


Steven Rostedt (1):
      function-graph: add option for include sleep times

----
 kernel/trace/ftrace.c |    7 +++++++
 kernel/trace/trace.c  |    3 ++-
 kernel/trace/trace.h  |    1 +
 3 files changed, 10 insertions(+), 1 deletions(-)
---------------------------
commit be6f164a02f394675e2ac2077dd354cebef5b4c0
Author: Steven Rostedt <srostedt@redhat.com>
Date:   Tue Mar 24 11:06:24 2009 -0400

    function-graph: add option for include sleep times
    
    Impact: give user a choice to show times spent while sleeping
    
    The user may want to see the time a function spent sleeping.
    This patch adds the trace option "sleep-time" to allow that.
    The "sleep-time" option is default on.
    
     echo sleep-time > /debug/tracing/trace_options
    
    produces:
    
     ------------------------------------------
     2)  avahi-d-3428  =>    <idle>-0
     ------------------------------------------
    
     2)               |      finish_task_switch() {
     2)   0.621 us    |        _spin_unlock_irq();
     2)   2.202 us    |      }
     2) ! 1002.197 us |    }
     2) ! 1003.521 us |  }
    
    where as,
    
     echo nosleep-time > /debug/tracing/trace_options
    
    produces:
    
     0)    <idle>-0    =>  yum-upd-3416
     ------------------------------------------
    
     0)               |              finish_task_switch() {
     0)   0.643 us    |                _spin_unlock_irq();
     0)   2.342 us    |              }
     0) + 41.302 us   |            }
     0) + 42.453 us   |          }
    
    Signed-off-by: Steven Rostedt <srostedt@redhat.com>

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 0b90364..02d2de9 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -2599,6 +2599,13 @@ ftrace_graph_probe_sched_switch(struct rq *__rq, struct task_struct *prev,
 	unsigned long long timestamp;
 	int index;
 
+	/*
+	 * Does the user want to count the time a function was asleep.
+	 * If so, do not update the time stamps.
+	 */
+	if (trace_flags & TRACE_ITER_SLEEP_TIME)
+		return;
+
 	timestamp = trace_clock_local();
 
 	prev->ftrace_timestamp = timestamp;
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index f0e1337..67c6a21 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -255,7 +255,7 @@ static DECLARE_WAIT_QUEUE_HEAD(trace_wait);
 
 /* trace_flags holds trace_options default values */
 unsigned long trace_flags = TRACE_ITER_PRINT_PARENT | TRACE_ITER_PRINTK |
-	TRACE_ITER_ANNOTATE | TRACE_ITER_CONTEXT_INFO;
+	TRACE_ITER_ANNOTATE | TRACE_ITER_CONTEXT_INFO | TRACE_ITER_SLEEP_TIME;
 
 /**
  * trace_wake_up - wake up tasks waiting for trace input
@@ -316,6 +316,7 @@ static const char *trace_options[] = {
 	"context-info",
 	"latency-format",
 	"global-clock",
+	"sleep-time",
 	NULL
 };
 
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 7cfb741..d7410bb 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -683,6 +683,7 @@ enum trace_iterator_flags {
 	TRACE_ITER_CONTEXT_INFO		= 0x20000, /* Print pid/cpu/time */
 	TRACE_ITER_LATENCY_FMT		= 0x40000,
 	TRACE_ITER_GLOBAL_CLK		= 0x80000,
+	TRACE_ITER_SLEEP_TIME		= 0x100000,
 };
 
 /*

Re: [PATCH][GIT PULL] function-graph: add option for include sleep times

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> Ingo,
> 
> Please pull the latest tip/tracing/ftrace tree, which can be found at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
> tip/tracing/ftrace
> 
> 
> Steven Rostedt (1):
>       function-graph: add option for include sleep times
> 
> ----
>  kernel/trace/ftrace.c |    7 +++++++
>  kernel/trace/trace.c  |    3 ++-
>  kernel/trace/trace.h  |    1 +
>  3 files changed, 10 insertions(+), 1 deletions(-)

Pulled, thanks Steve!

	Ingo

Re: [PATCH][GIT PULL] function-graph: add option for include sleep times

[Frederic Weisbecker]

On Tue, Mar 24, 2009 at 11:28:09AM -0400, Steven Rostedt wrote:
> 
> Ingo,
> 
> Please pull the latest tip/tracing/ftrace tree, which can be found at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
> tip/tracing/ftrace
> 
> 
> Steven Rostedt (1):
>       function-graph: add option for include sleep times
> 
> ----
>  kernel/trace/ftrace.c |    7 +++++++
>  kernel/trace/trace.c  |    3 ++-
>  kernel/trace/trace.h  |    1 +
>  3 files changed, 10 insertions(+), 1 deletions(-)
> ---------------------------
> commit be6f164a02f394675e2ac2077dd354cebef5b4c0
> Author: Steven Rostedt <srostedt@redhat.com>
> Date:   Tue Mar 24 11:06:24 2009 -0400
> 
>     function-graph: add option for include sleep times
>     
>     Impact: give user a choice to show times spent while sleeping
>     
>     The user may want to see the time a function spent sleeping.
>     This patch adds the trace option "sleep-time" to allow that.
>     The "sleep-time" option is default on.
>     
>      echo sleep-time > /debug/tracing/trace_options


Yeah, I thinks it's better to let it be chosen.
Thanks for this series!

Frederic.


     
>     produces:
>     
>      ------------------------------------------
>      2)  avahi-d-3428  =>    <idle>-0
>      ------------------------------------------
>     
>      2)               |      finish_task_switch() {
>      2)   0.621 us    |        _spin_unlock_irq();
>      2)   2.202 us    |      }
>      2) ! 1002.197 us |    }
>      2) ! 1003.521 us |  }
>     
>     where as,
>     
>      echo nosleep-time > /debug/tracing/trace_options
>     
>     produces:
>     
>      0)    <idle>-0    =>  yum-upd-3416
>      ------------------------------------------
>     
>      0)               |              finish_task_switch() {
>      0)   0.643 us    |                _spin_unlock_irq();
>      0)   2.342 us    |              }
>      0) + 41.302 us   |            }
>      0) + 42.453 us   |          }
>     
>     Signed-off-by: Steven Rostedt <srostedt@redhat.com>
> 
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index 0b90364..02d2de9 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -2599,6 +2599,13 @@ ftrace_graph_probe_sched_switch(struct rq *__rq, struct task_struct *prev,
>  	unsigned long long timestamp;
>  	int index;
>  
> +	/*
> +	 * Does the user want to count the time a function was asleep.
> +	 * If so, do not update the time stamps.
> +	 */
> +	if (trace_flags & TRACE_ITER_SLEEP_TIME)
> +		return;
> +
>  	timestamp = trace_clock_local();
>  
>  	prev->ftrace_timestamp = timestamp;
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index f0e1337..67c6a21 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -255,7 +255,7 @@ static DECLARE_WAIT_QUEUE_HEAD(trace_wait);
>  
>  /* trace_flags holds trace_options default values */
>  unsigned long trace_flags = TRACE_ITER_PRINT_PARENT | TRACE_ITER_PRINTK |
> -	TRACE_ITER_ANNOTATE | TRACE_ITER_CONTEXT_INFO;
> +	TRACE_ITER_ANNOTATE | TRACE_ITER_CONTEXT_INFO | TRACE_ITER_SLEEP_TIME;
>  
>  /**
>   * trace_wake_up - wake up tasks waiting for trace input
> @@ -316,6 +316,7 @@ static const char *trace_options[] = {
>  	"context-info",
>  	"latency-format",
>  	"global-clock",
> +	"sleep-time",
>  	NULL
>  };
>  
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 7cfb741..d7410bb 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -683,6 +683,7 @@ enum trace_iterator_flags {
>  	TRACE_ITER_CONTEXT_INFO		= 0x20000, /* Print pid/cpu/time */
>  	TRACE_ITER_LATENCY_FMT		= 0x40000,
>  	TRACE_ITER_GLOBAL_CLK		= 0x80000,
> +	TRACE_ITER_SLEEP_TIME		= 0x100000,
>  };
>  
>  /*
> 
>