[PATCH 0/2] RT: Enhance PREEMPT_TRACE with deeper stacks

[PATCH 0/2] RT: Enhance PREEMPT_TRACE with deeper stacks

[Gregory Haskins]

This series changes the PREEMPT-TRACE behavior for reporting critical
sections.  The previous code reported 2 frames per section.  The new code uses
the save_stack_trace facility to save an arbitrary number of frames (currently
set to 5 via a #define)

For what its worth, these patches assisted me with debugging some issues in
-rt.  The second patch is really a workaround for where X86_64 frame-pointers
apparently are not working under certain circumstances.

Signed-off-by: Gregory Haskins <ghaskins@novell.com>

[PATCH 1/2] Adds full stack to critical-section tracing

[Gregory Haskins]

---

 include/linux/sched.h  |    7 +++++--
 kernel/latency_trace.c |   18 +++++++++++-------
 2 files changed, 16 insertions(+), 9 deletions(-)

diff --git a/include/linux/sched.h b/include/linux/sched.h
index 8ebb43c..233d26c 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -1306,10 +1306,13 @@ struct task_struct {
 #endif
 
 #define MAX_PREEMPT_TRACE 25
+#define MAX_PREEMPT_TRACE_DEPTH 5
 
 #ifdef CONFIG_PREEMPT_TRACE
-	unsigned long preempt_trace_eip[MAX_PREEMPT_TRACE];
-	unsigned long preempt_trace_parent_eip[MAX_PREEMPT_TRACE];
+	struct {
+		struct stack_trace trace;
+		unsigned long      data[MAX_PREEMPT_TRACE_DEPTH];
+	} preempt_trace[MAX_PREEMPT_TRACE];
 #endif
 
 #define MAX_LOCK_STACK	MAX_PREEMPT_TRACE
diff --git a/kernel/latency_trace.c b/kernel/latency_trace.c
index 1113744..9b83262 100644
--- a/kernel/latency_trace.c
+++ b/kernel/latency_trace.c
@@ -2049,8 +2049,15 @@ void notrace add_preempt_count(unsigned int val)
 	if (val <= 10) {
 		unsigned int idx = preempt_count() & PREEMPT_MASK;
 		if (idx < MAX_PREEMPT_TRACE) {
-			current->preempt_trace_eip[idx] = eip;
-			current->preempt_trace_parent_eip[idx] = parent_eip;
+			struct stack_trace *trace;
+
+			trace = &current->preempt_trace[idx].trace;
+			trace->nr_entries = 0;
+			trace->max_entries = MAX_PREEMPT_TRACE_DEPTH;
+			trace->skip = 0;
+			trace->entries = current->preempt_trace[idx].data;
+
+			save_stack_trace(trace);
 		}
 	}
 #endif
@@ -2708,11 +2715,8 @@ static void print_preempt_trace(struct task_struct *task)
 	printk("| %d-level deep critical section nesting:\n", lim);
 	printk("----------------------------------------\n");
 	for (i = 1; i <= lim; i++) {
-		printk(".. [<%08lx>] .... ", task->preempt_trace_eip[i]);
-		print_symbol("%s\n", task->preempt_trace_eip[i]);
-		printk(".....[<%08lx>] ..   ( <= ",
-				task->preempt_trace_parent_eip[i]);
-		print_symbol("%s)\n", task->preempt_trace_parent_eip[i]);
+		printk("  ---- Critial Section #%d ----\n", i);
+		print_stack_trace(&task->preempt_trace[i].trace, 5);
 	}
 	printk("\n");
 }

[PATCH 2/2] Some stacks show up untracable, so fall back to old method in this case

[Gregory Haskins]

Signed-off-by: Gregory Haskins <ghaskins@novell.com>
---

 arch/x86_64/kernel/stacktrace.c |   10 ++++++++--
 include/linux/stacktrace.h      |    1 +
 kernel/latency_trace.c          |   12 ++++++++++++
 3 files changed, 21 insertions(+), 2 deletions(-)

diff --git a/arch/x86_64/kernel/stacktrace.c b/arch/x86_64/kernel/stacktrace.c
index cb91091..054f627 100644
--- a/arch/x86_64/kernel/stacktrace.c
+++ b/arch/x86_64/kernel/stacktrace.c
@@ -24,7 +24,7 @@ static int save_stack_stack(void *data, char *name)
 	return -1;
 }
 
-static void save_stack_address(void *data, unsigned long addr)
+static void _save_stack_address(void *data, unsigned long addr)
 {
 	struct stack_trace *trace = (struct stack_trace *)data;
 	if (trace->skip > 0) {
@@ -39,7 +39,7 @@ static struct stacktrace_ops save_stack_ops = {
 	.warning = save_stack_warning,
 	.warning_symbol = save_stack_warning_symbol,
 	.stack = save_stack_stack,
-	.address = save_stack_address,
+	.address = _save_stack_address,
 };
 
 /*
@@ -52,3 +52,9 @@ void save_stack_trace(struct stack_trace *trace)
 		trace->entries[trace->nr_entries++] = ULONG_MAX;
 }
 EXPORT_SYMBOL(save_stack_trace);
+
+void save_stack_address(struct stack_trace *trace, unsigned long addr)
+{
+	_save_stack_address(trace, addr);
+}
+EXPORT_SYMBOL(save_stack_address);
diff --git a/include/linux/stacktrace.h b/include/linux/stacktrace.h
index e7fa657..5acad27 100644
--- a/include/linux/stacktrace.h
+++ b/include/linux/stacktrace.h
@@ -9,6 +9,7 @@ struct stack_trace {
 };
 
 extern void save_stack_trace(struct stack_trace *trace);
+extern void save_stack_address(struct stack_trace *trace, unsigned long addr);
 
 extern void print_stack_trace(struct stack_trace *trace, int spaces);
 #else
diff --git a/kernel/latency_trace.c b/kernel/latency_trace.c
index 9b83262..82c04ac 100644
--- a/kernel/latency_trace.c
+++ b/kernel/latency_trace.c
@@ -2058,6 +2058,18 @@ void notrace add_preempt_count(unsigned int val)
 			trace->entries = current->preempt_trace[idx].data;
 
 			save_stack_trace(trace);
+
+			/*
+			 * If we couldnt get our trace, the first entry will
+			 * have the ULONG_MAX marker.  In that case, we
+			 * rewind and save our simple two level stack
+			 */
+			if ((trace->nr_entries == 1)
+			    && (trace->entries[0] == ULONG_MAX)) {
+				trace->nr_entries = 0;
+				save_stack_address(trace, eip);
+				save_stack_address(trace, parent_eip);
+			}
 		}
 	}
 #endif

Re: [PATCH 1/2] Adds full stack to critical-section tracing

[Daniel Walker]

On Fri, 2007-08-10 at 08:14 -0600, Gregory Haskins wrote:
> ---
> 
>  include/linux/sched.h  |    7 +++++--
>  kernel/latency_trace.c |   18 +++++++++++-------
>  2 files changed, 16 insertions(+), 9 deletions(-)
> 
> diff --git a/include/linux/sched.h b/include/linux/sched.h
> index 8ebb43c..233d26c 100644
> --- a/include/linux/sched.h
> +++ b/include/linux/sched.h
> @@ -1306,10 +1306,13 @@ struct task_struct {
>  #endif
>  
>  #define MAX_PREEMPT_TRACE 25
> +#define MAX_PREEMPT_TRACE_DEPTH 5
>  
>  #ifdef CONFIG_PREEMPT_TRACE
> -	unsigned long preempt_trace_eip[MAX_PREEMPT_TRACE];
> -	unsigned long preempt_trace_parent_eip[MAX_PREEMPT_TRACE];
> +	struct {
> +		struct stack_trace trace;
> +		unsigned long      data[MAX_PREEMPT_TRACE_DEPTH];
> +	} preempt_trace[MAX_PREEMPT_TRACE];

These changes need some fixing .. The "struct stack_trace"
infrastructure is based on CONFIG_STACKTRACE , so at least you would
want to ifdef your changes on that config options ..

I modified you patch to include the ifdefs,

ftp://source.mvista.com/pub/dwalker/misc/debug-preempt-5-levels-of-stack-frames.patch

The other problem I noticed is that the save_stack_trace(trace); seems
kind of heavy weight to be calling from inside add_preempt_count. If
your only going to a depth of 5 you could potentially use there macros,

#ifdef CONFIG_FRAME_POINTER
# ifndef CONFIG_ARM
#  define CALLER_ADDR0 ((unsigned long)__builtin_return_address(0))
#  define CALLER_ADDR1 ((unsigned long)__builtin_return_address(1))
#  define CALLER_ADDR2 ((unsigned long)__builtin_return_address(2))
#  define CALLER_ADDR3 ((unsigned long)__builtin_return_address(3))
#  define CALLER_ADDR4 ((unsigned long)__builtin_return_address(4))
#  define CALLER_ADDR5 ((unsigned long)__builtin_return_address(5))
# else

Daniel