[PATCH 0/2] [GIT PULL] tracing: stack tracing

[PATCH 0/2] [GIT PULL] tracing: stack tracing

[Steven Rostedt]

Ingo,

I based this on top of my last tip/tracing/urgent request. These are
enhancements and not fixes. But since the merge window is still open
and these are very small patches, I figured we try to get them in for
2.6.33.

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

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


Steven Rostedt (2):
      tracing: Add trace_dump_stack()
      tracing: Add stack trace to irqsoff tracer

----
 include/linux/kernel.h       |    2 ++
 kernel/trace/trace.c         |   16 ++++++++++++++++
 kernel/trace/trace_irqsoff.c |    2 ++
 3 files changed, 20 insertions(+), 0 deletions(-)

[PATCH 1/2] [PATCH 1/2] tracing: Add trace_dump_stack()

[Steven Rostedt]

[-- Attachment #1: 0001-tracing-Add-trace_dump_stack.patch --]
[-- Type: text/plain, Size: 2872 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

I've been asked a few times about how to find out what is calling
some location in the kernel. One way is to use dynamic function tracing
and implement the func_stack_trace. But this only finds out who is
calling a particular function. It does not tell you who is calling
that function and entering a specific if conditional.

I have myself implemented a quick version of trace_dump_stack() for
this purpose a few times, and just needed it now. This is when I realized
that this would be a good tool to have in the kernel like trace_printk().

Using trace_dump_stack() is similar to dump_stack() except that it
writes to the trace buffer instead and can be used in critical locations.

For example:

@@ -5485,8 +5485,12 @@ need_resched_nonpreemptible:
 	if (prev->state && !(preempt_count() & PREEMPT_ACTIVE)) {
 		if (unlikely(signal_pending_state(prev->state, prev)))
 			prev->state = TASK_RUNNING;
-		else
+		else {
 			deactivate_task(rq, prev, 1);
+			trace_printk("Deactivating task %s:%d\n",
+				     prev->comm, prev->pid);
+			trace_dump_stack();
+		}
 		switch_count = &prev->nvcsw;
 	}

Produces:

           <...>-3249  [001]   296.105269: schedule: Deactivating task ntpd:3249
           <...>-3249  [001]   296.105270: <stack trace>
 => schedule
 => schedule_hrtimeout_range
 => poll_schedule_timeout
 => do_select
 => core_sys_select
 => sys_select
 => system_call_fastpath

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/kernel.h |    2 ++
 kernel/trace/trace.c   |   16 ++++++++++++++++
 2 files changed, 18 insertions(+), 0 deletions(-)

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 3fa4c59..5ad4199 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -492,6 +492,8 @@ extern int
 __trace_printk(unsigned long ip, const char *fmt, ...)
 	__attribute__ ((format (printf, 2, 3)));
 
+extern void trace_dump_stack(void);
+
 /*
  * The double __builtin_constant_p is because gcc will give us an error
  * if we try to allocate the static variable to fmt if it is not a
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 88bd9ae..f531301 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1151,6 +1151,22 @@ void __trace_stack(struct trace_array *tr, unsigned long flags, int skip,
 	__ftrace_trace_stack(tr->buffer, flags, skip, pc);
 }
 
+/**
+ * trace_dump_stack - record a stack back trace in the trace buffer
+ */
+void trace_dump_stack(void)
+{
+	unsigned long flags;
+
+	if (tracing_disabled || tracing_selftest_running)
+		return 0;
+
+	local_save_flags(flags);
+
+	/* skipping 3 traces, seems to get us at the caller of this function */
+	__ftrace_trace_stack(global_trace.buffer, flags, 3, preempt_count());
+}
+
 void
 ftrace_trace_userstack(struct ring_buffer *buffer, unsigned long flags, int pc)
 {
-- 
1.6.5

[PATCH 2/2] [PATCH 2/2] tracing: Add stack trace to irqsoff tracer

[Steven Rostedt]

[-- Attachment #1: 0002-tracing-Add-stack-trace-to-irqsoff-tracer.patch --]
[-- Type: text/plain, Size: 3010 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

The irqsoff and friends tracers help in finding causes of latency in the
kernel. The also work with the function tracer to show what was happening
when interrupts or preemption are disabled. But the function tracer has
a bit of an overhead and can cause exagerated readings.

Currently, when tracing with /proc/sys/kernel/ftrace_enabled = 0, where the
function tracer is disabled, the information that is provided can end up
being useless. For example, a 2 and a half millisecond latency only showed:

 # tracer: preemptirqsoff
 #
 # preemptirqsoff latency trace v1.1.5 on 2.6.32
 # --------------------------------------------------------------------
 # latency: 2463 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
 #    -----------------
 #    | task: -4242 (uid:0 nice:0 policy:0 rt_prio:0)
 #    -----------------
 #  => started at: _spin_lock_irqsave
 #  => ended at:   remove_wait_queue
 #
 #
 #                  _------=> CPU#
 #                 / _-----=> irqs-off
 #                | / _----=> need-resched
 #                || / _---=> hardirq/softirq
 #                ||| / _--=> preempt-depth
 #                |||| /_--=> lock-depth
 #                |||||/     delay
 #  cmd     pid   |||||| time  |   caller
 #     \   /      ||||||   \   |   /
 hackbenc-4242    2d....    0us!: trace_hardirqs_off <-_spin_lock_irqsave
 hackbenc-4242    2...1. 2463us+: _spin_unlock_irqrestore <-remove_wait_queue
 hackbenc-4242    2...1. 2466us : trace_preempt_on <-remove_wait_queue

The above lets us know that hackbench with pid 2463 grabbed a spin lock
somewhere and enabled preemption at remove_wait_queue. This helps a little
but where this actually happened is not informative.

This patch adds the stack dump to the end of the irqsoff tracer. This provides
the following output:

 hackbenc-4242    2d....    0us!: trace_hardirqs_off <-_spin_lock_irqsave
 hackbenc-4242    2...1. 2463us+: _spin_unlock_irqrestore <-remove_wait_queue
 hackbenc-4242    2...1. 2466us : trace_preempt_on <-remove_wait_queue
 hackbenc-4242    2...1. 2467us : <stack trace>
  => sub_preempt_count
  => _spin_unlock_irqrestore
  => remove_wait_queue
  => free_poll_entry
  => poll_freewait
  => do_sys_poll
  => sys_poll
  => system_call_fastpath

Now we see that the culprit of this latency was the free_poll_entry code.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace_irqsoff.c |    2 ++
 1 files changed, 2 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 3aa7eaa..2974bc7 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -151,6 +151,8 @@ check_critical_timing(struct trace_array *tr,
 		goto out_unlock;
 
 	trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
+	/* Skip 5 functions to get to the irq/preempt enable function */
+	__trace_stack(tr, flags, 5, pc);
 
 	if (data->critical_sequence != max_sequence)
 		goto out_unlock;
-- 
1.6.5

Re: [PATCH 0/2] [GIT PULL] tracing: stack tracing

[Ingo Molnar]

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

> Ingo,
> 
> I based this on top of my last tip/tracing/urgent request. These are 
> enhancements and not fixes. But since the merge window is still open and 
> these are very small patches, I figured we try to get them in for 2.6.33.
> 
> Please pull the latest tip/tracing/core tree, which can be found at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
> tip/tracing/core
> 
> 
> Steven Rostedt (2):
>       tracing: Add trace_dump_stack()
>       tracing: Add stack trace to irqsoff tracer
> 
> ----
>  include/linux/kernel.h       |    2 ++
>  kernel/trace/trace.c         |   16 ++++++++++++++++
>  kernel/trace/trace_irqsoff.c |    2 ++
>  3 files changed, 20 insertions(+), 0 deletions(-)

Pulled, thanks Steve!

	Ingo

Re: [PATCH 0/2] [GIT PULL] tracing: stack tracing

[Ingo Molnar]

FYI, i noticed this new warning:

 kernel/trace/trace.c: In function 'trace_dump_stack':
 kernel/trace/trace.c:1161: warning: 'return' with a value, in function returning void

	Ingo

Re: [PATCH 0/2] [GIT PULL] tracing: stack tracing

[Steven Rostedt]

On Mon, 2009-12-14 at 17:27 +0100, Ingo Molnar wrote:
> FYI, i noticed this new warning:
> 
>  kernel/trace/trace.c: In function 'trace_dump_stack':
>  kernel/trace/trace.c:1161: warning: 'return' with a value, in function returning void

Hmm,

I could have sworn I tested for warnings, this must have slipped under
the radar :-/

I'll fix ASAP.

-- Steve

[PATCH][GIT PULL] tracing: Fix return of trace_dump_stack()

[Steven Rostedt]

Ingo,

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

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


Steven Rostedt (1):
      tracing: Fix return of trace_dump_stack()

----
 include/linux/kernel.h |    1 +
 kernel/trace/trace.c   |    2 +-
 2 files changed, 2 insertions(+), 1 deletions(-)
---------------------------
commit aa43d935e677296088fb9b9c2060abbad0ccf648
Author: Steven Rostedt <srostedt@redhat.com>
Date:   Mon Dec 14 15:58:33 2009 -0500

    tracing: Fix return of trace_dump_stack()
    
    The trace_dump_stack() returned a value for a void function.
    
    Also, added the missing stub for trace_dump_stack() when tracing is
    not configured.
    
    Reported-by: Ingo Molnar <mingo@elte.hu>
    LKML-Reference: <20091214162713.GA31060@elte.hu>
    Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 5ad4199..f1dc752 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -527,6 +527,7 @@ trace_printk(const char *fmt, ...) __attribute__ ((format (printf, 1, 2)));
 static inline void tracing_start(void) { }
 static inline void tracing_stop(void) { }
 static inline void ftrace_off_permanent(void) { }
+static inline void trace_dump_stack(void) { }
 static inline int
 trace_printk(const char *fmt, ...)
 {
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index f531301..1cf8734 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1159,7 +1159,7 @@ void trace_dump_stack(void)
 	unsigned long flags;
 
 	if (tracing_disabled || tracing_selftest_running)
-		return 0;
+		return;
 
 	local_save_flags(flags);
 

Re: [PATCH][GIT PULL] tracing: Fix return of trace_dump_stack()

[Ingo Molnar]

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

> Ingo,
> 
> Please pull the latest tip/tracing/urgent tree, which can be found at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
> tip/tracing/urgent
> 
> 
> Steven Rostedt (1):
>       tracing: Fix return of trace_dump_stack()
> 
> ----
>  include/linux/kernel.h |    1 +
>  kernel/trace/trace.c   |    2 +-
>  2 files changed, 2 insertions(+), 1 deletions(-)

Pulled, thanks Steve!

	Ingo

[tip:tracing/urgent] tracing: Fix return of trace_dump_stack()

[tip-bot for Steven Rostedt]

Commit-ID:  e36c54582c6f14adc9e10473e2aec2cc4f0acc03
Gitweb:     http://git.kernel.org/tip/e36c54582c6f14adc9e10473e2aec2cc4f0acc03
Author:     Steven Rostedt <srostedt@redhat.com>
AuthorDate: Mon, 14 Dec 2009 15:58:33 -0500
Committer:  Ingo Molnar <mingo@elte.hu>
CommitDate: Tue, 15 Dec 2009 08:36:11 +0100

tracing: Fix return of trace_dump_stack()

The trace_dump_stack() returned a value for a void function.

Also, added the missing stub for trace_dump_stack() when tracing is
not configured.

Reported-by: Ingo Molnar <mingo@elte.hu>
LKML-Reference: <20091214162713.GA31060@elte.hu>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
 include/linux/kernel.h |    1 +
 kernel/trace/trace.c   |    2 +-
 2 files changed, 2 insertions(+), 1 deletions(-)

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 5ad4199..f1dc752 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -527,6 +527,7 @@ trace_printk(const char *fmt, ...) __attribute__ ((format (printf, 1, 2)));
 static inline void tracing_start(void) { }
 static inline void tracing_stop(void) { }
 static inline void ftrace_off_permanent(void) { }
+static inline void trace_dump_stack(void) { }
 static inline int
 trace_printk(const char *fmt, ...)
 {
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index bd7b969..ee61915 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1158,7 +1158,7 @@ void trace_dump_stack(void)
 	unsigned long flags;
 
 	if (tracing_disabled || tracing_selftest_running)
-		return 0;
+		return;
 
 	local_save_flags(flags);