tracing: userspace stacktraces

Hi,

I am resending my patches, differrences from previous send:
* fixed some style issues
* introduce seq_print_user_ip helper
* make mangle_path global and document
* use mangle_path instead of abusing seq_file in trace_seq_path
* fix subject line and commit messages

These patches apply on top of tip/master,
commit 50598e26c1360d4c0edcabc50035d084ee8d3d70

Török Edwin (2):
tracing: add support for userspace stacktraces in tracing/iter_ctrl
tracing: identify which executable object the userspace address
belongs to

 Documentation/ftrace.txt     |   16 ++++-
 arch/x86/kernel/stacktrace.c |   57 +++++++++++++++
 fs/seq_file.c                |   14 ++++-
 include/linux/seq_file.h     |    1 +
 include/linux/stacktrace.h   |    8 ++
 kernel/trace/trace.c         |  165 ++++++++++++++++++++++++++++++++++++++++++
 kernel/trace/trace.h         |   10 +++
 7 files changed, 269 insertions(+), 2 deletions(-)

Impact: add new (default-off) tracing visualization feature

Usage example:

mount -t debugfs nodev /sys/kernel/debug
cd /sys/kernel/debug/tracing
echo userstacktrace >iter_ctrl
echo sched_switch >current_tracer
echo 1 >tracing_enabled
.... run application ...
echo 0 >tracing_enabled

Then read one of 'trace','latency_trace','trace_pipe'.

To get the best output you can compile your userspace programs with frame pointers (at least glibc + the app you are tracing).

---
 Documentation/ftrace.txt     |    5 ++-
 arch/x86/kernel/stacktrace.c |   57 +++++++++++++++++++++++++
 include/linux/stacktrace.h   |    8 ++++
 kernel/trace/trace.c         |   93 ++++++++++++++++++++++++++++++++++++++++++
 kernel/trace/trace.h         |    9 ++++
 5 files changed, 171 insertions(+), 1 deletions(-)

index 753f4de..79a80f7 100644
@@ -324,7 +324,7 @@ output. To see what is available, simply cat the file:
 
   cat /debug/tracing/trace_options
   print-parent nosym-offset nosym-addr noverbose noraw nohex nobin \
- noblock nostacktrace nosched-tree
+ noblock nostacktrace nosched-tree nouserstacktrace
 
 To disable one of the options, echo in the option prepended with "no".
 

@@ -378,6 +378,9 @@ Here are the available options:
 		When a trace is recorded, so is the stack of functions.
 		This allows for back traces of trace sites.
 
+  userstacktrace - This option changes the trace.
+		   It records a stacktrace of the current userspace thread.
+
   sched-tree - TBD (any users??)
 
 

index 6b8e54a..46704a5 100644
@@ -18,9 +18,17 @@ extern void save_stack_trace_tsk(struct task_struct *tsk,
 				struct stack_trace *trace);
 
 extern void print_stack_trace(struct stack_trace *trace, int spaces);
+
+#ifdef CONFIG_X86
+extern void save_stack_trace_user(struct stack_trace *trace);
+#else
+# define save_stack_trace_user(trace)              do { } while (0)
+#endif
+
 #else
 # define save_stack_trace(trace)			do { } while (0)
 # define save_stack_trace_tsk(tsk, trace)		do { } while (0)
+# define save_stack_trace_user(trace)              do { } while (0)
 # define print_stack_trace(trace, spaces)		do { } while (0)
 #endif
 

index 2cb12fd..17bb4c8 100644
@@ -26,6 +26,7 @@ enum trace_type {
 	TRACE_BOOT_CALL,
 	TRACE_BOOT_RET,
 	TRACE_FN_RET,
+	TRACE_USER_STACK,
 
 	__TRACE_LAST_TYPE
 };

@@ -42,6 +43,7 @@ struct trace_entry {
 	unsigned char		flags;
 	unsigned char		preempt_count;
 	int			pid;
+	int			tgid;
 };
 
 /*

@@ -99,6 +101,11 @@ struct stack_entry {
 	unsigned long		caller[FTRACE_STACK_ENTRIES];
 };
 
+struct userstack_entry {
+	struct trace_entry	ent;
+	unsigned long		caller[FTRACE_STACK_ENTRIES];
+};
+
 /*
  * ftrace_printk entry:
  */

@@ -240,6 +247,7 @@ extern void __ftrace_bad_type(void);
 		IF_ASSIGN(var, ent, struct ctx_switch_entry, 0);	\
 		IF_ASSIGN(var, ent, struct trace_field_cont, TRACE_CONT); \
 		IF_ASSIGN(var, ent, struct stack_entry, TRACE_STACK);	\
+		IF_ASSIGN(var, ent, struct userstack_entry, TRACE_USER_STACK);\
 		IF_ASSIGN(var, ent, struct print_entry, TRACE_PRINT);	\
 		IF_ASSIGN(var, ent, struct special_entry, 0);		\
 		IF_ASSIGN(var, ent, struct trace_mmiotrace_rw,		\

@@ -500,6 +508,7 @@ enum trace_iterator_flags {
 	TRACE_ITER_PREEMPTONLY		= 0x800,
 	TRACE_ITER_BRANCH		= 0x1000,
 	TRACE_ITER_ANNOTATE		= 0x2000,
+	TRACE_ITER_USERSTACKTRACE       = 0x4000
 };
 
 /*

1.5.6.5

User stack tracing is just implemented for x86, but it is not x86 specific. Introduce a generic config flag, that is currently enabled only for x86. When other arches implements it, they will have to SELECT USER_STACKTRACE_SUPPORT

---
 arch/x86/Kconfig           |    1 +
 include/linux/stacktrace.h |    2 +-
 kernel/trace/Kconfig       |    3 +++
 3 files changed, 5 insertions(+), 1 deletions(-)

index 7a146ba..e49a4fd 100644
@@ -36,6 +36,7 @@ config X86
 	select HAVE_ARCH_TRACEHOOK
 	select HAVE_GENERIC_DMA_COHERENT if X86_32
 	select HAVE_EFFICIENT_UNALIGNED_ACCESS
+	select USER_STACKTRACE_SUPPORT
 
 config ARCH_DEFCONFIG
 	string

index fd42d68..1a8cecc 100644
@@ -16,7 +16,7 @@ extern void save_stack_trace_tsk(struct task_struct *tsk,
 
 extern void print_stack_trace(struct stack_trace *trace, int spaces);
 
-#ifdef CONFIG_X86
+#ifdef CONFIG_USER_STACKTRACE_SUPPORT
 extern void save_stack_trace_user(struct stack_trace *trace);
 #else
 # define save_stack_trace_user(trace)              do { } while (0)

index b8378fa..87fc34a 100644
@@ -3,6 +3,9 @@
 #  select HAVE_FUNCTION_TRACER:
 #
 
+config USER_STACKTRACE_SUPPORT
+	bool
+
 config NOP_TRACER
 	bool
 

1.5.6.5

Impact: modify+improve the userstacktrace tracing visualization feature

Store thread group leader id, and use it to lookup the address in the process's map. We could have looked up the address on thread's map, but the thread might not exist by the time we are called. The process might not exist either, but if you are reading trace_pipe, that is unlikely.

Example usage:

mount -t debugfs nodev /sys/kernel/debug
cd /sys/kernel/debug/tracing
echo userstacktrace >iter_ctrl
echo sym-userobj >iter_ctrl
echo sched_switch >current_tracer
echo 1 >tracing_enabled
cat trace_pipe >/tmp/trace&
.... run application ...
echo 0 >tracing_enabled
cat /tmp/trace

You'll see stack entries like:

/lib/libpthread-2.7.so[+0xd370]

You can convert them to function/line using:

addr2line -fie /lib/libpthread-2.7.so 0xd370

Or:

addr2line -fie /usr/lib/debug/libpthread-2.7.so 0xd370

For non-PIC/PIE executables this won't work:

a.out[+0x73b]

You need to run the following: addr2line -fie a.out 0x40073b (where 0x400000 is the default load address of a.out)

---
 Documentation/ftrace.txt |   13 ++++++-
 fs/seq_file.c            |   14 +++++++-
 include/linux/seq_file.h |    1 +
 kernel/trace/trace.c     |   86 ++++++++++++++++++++++++++++++++++++++++++----
 kernel/trace/trace.h     |    3 +-
 5 files changed, 107 insertions(+), 10 deletions(-)

index 79a80f7..35a78bc 100644
@@ -324,7 +324,7 @@ output. To see what is available, simply cat the file:
 
   cat /debug/tracing/trace_options
   print-parent nosym-offset nosym-addr noverbose noraw nohex nobin \
- noblock nostacktrace nosched-tree nouserstacktrace
+ noblock nostacktrace nosched-tree nouserstacktrace nosym-userobj
 
 To disable one of the options, echo in the option prepended with "no".
 

@@ -381,6 +381,17 @@ Here are the available options:
   userstacktrace - This option changes the trace.
 		   It records a stacktrace of the current userspace thread.
 
+  sym-userobj - when user stacktrace are enabled, look up which object the
+		address belongs to, and print a relative address
+		This is especially useful when ASLR is on, otherwise you don't
+		get a chance to resolve the address to object/file/line after the app is no
+		longer running
+
+		The lookup is performed when you read trace,trace_pipe,latency_trace. Example:
+
+		a.out-1623  [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
+x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
+
   sched-tree - TBD (any users??)
 
 

index eba2eab..e063077 100644
@@ -357,7 +357,18 @@ int seq_printf(struct seq_file *m, const char *f, ...)
 }
 EXPORT_SYMBOL(seq_printf);
 
-static char *mangle_path(char *s, char *p, char *esc)
+/**
+ * 	mangle_path - mangle and copy path to buffer beginning
+ * 	@s - buffer start
+ * 	@p - beginning of path in above buffer
+ *      @esc - set of characters that need escaping
+ *
+ *      Copy the path from @p to @s, replacing each occurrence of character from
+ *      @esc with usual octal escape.
+ *      Returns pointer past last written character in @s, or NULL in case of
+ *      failure.
+ */
+char *mangle_path(char *s, char *p, char *esc)
 {
 	while (s <= p) {
 		char c = *p++;

@@ -376,6 +387,7 @@ static char *mangle_path(char *s, char *p, char *esc)
 	}
 	return NULL;
 }
+EXPORT_SYMBOL(mangle_path);
 
 /*
  * return the absolute path of 'dentry' residing in mount 'mnt'.

index dc50bcc..b3dfa72 100644
@@ -34,6 +34,7 @@ struct seq_operations {
 
 #define SEQ_SKIP 1
 
+char *mangle_path(char *s, char *p, char *esc);
 int seq_open(struct file *, const struct seq_operations *);
 ssize_t seq_read(struct file *, char __user *, size_t, loff_t *);
 loff_t seq_lseek(struct file *, loff_t, int);

index 17bb4c8..28c15c2 100644
@@ -508,7 +508,8 @@ enum trace_iterator_flags {
 	TRACE_ITER_PREEMPTONLY		= 0x800,
 	TRACE_ITER_BRANCH		= 0x1000,
 	TRACE_ITER_ANNOTATE		= 0x2000,
-	TRACE_ITER_USERSTACKTRACE       = 0x4000
+	TRACE_ITER_USERSTACKTRACE       = 0x4000,
+	TRACE_ITER_SYM_USEROBJ          = 0x8000
 };
 
 /*

1.5.6.5

Note, i've split these bits out into a separate patch - see it attached below.

Ingo

------------------>

From: =?utf-8?q?T=C3=B6r=C3=B6k=20Edwin?= <[email protected]>
Date: Sat, 22 Nov 2008 13:28:48 +0200
Subject: [PATCH] vfs, seqfile: make mangle_path() global
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit

Impact: expose new VFS API

make mangle_path() available, as per the suggestions of Christoph Hellwig and Al Viro:

http://lkml.org/lkml/2008/11/4/338

---
 fs/seq_file.c            |   14 +++++++++++++-
 include/linux/seq_file.h |    1 +
 2 files changed, 14 insertions(+), 1 deletions(-)

index eba2eab..f5b61cc 100644
@@ -357,7 +357,18 @@ int seq_printf(struct seq_file *m, const char *f, ...)
 }
 EXPORT_SYMBOL(seq_printf);
 
-static char *mangle_path(char *s, char *p, char *esc)
+/**
+ * 	mangle_path - mangle and copy path to buffer beginning
+ * 	@s - buffer start
+ * 	@p - beginning of path in above buffer
+ *      @esc - set of characters that need escaping
+ *
+ *      Copy the path from @p to @s, replacing each occurrence of character from
+ *      @esc with usual octal escape.
+ *      Returns pointer past last written character in @s, or NULL in case of
+ *      failure.
+ */
+char *mangle_path(char *s, char *p, char *esc)
 {
 	while (s <= p) {
 		char c = *p++;

@@ -376,6 +387,7 @@ static char *mangle_path(char *s, char *p, char *esc)
 	}
 	return NULL;
 }
+EXPORT_SYMBOL_GPL(mangle_path);
 
 /*
  * return the absolute path of 'dentry' residing in mount 'mnt'.

index dc50bcc..b3dfa72 100644
@@ -34,6 +34,7 @@ struct seq_operations {
 
 #define SEQ_SKIP 1
 
+char *mangle_path(char *s, char *p, char *esc);
 int seq_open(struct file *, const struct seq_operations *);
 ssize_t seq_read(struct file *, char __user *, size_t, loff_t *);
 loff_t seq_lseek(struct file *, loff_t, int);

---
 fs/seq_file.c |    8 ++++----
 1 files changed, 4 insertions(+), 4 deletions(-)

index f5b61cc..f03220d 100644
@@ -358,10 +358,10 @@ int seq_printf(struct seq_file *m, const char *f, ...)
 EXPORT_SYMBOL(seq_printf);
 
 /**
- * 	mangle_path - mangle and copy path to buffer beginning
- * 	@s - buffer start
- * 	@p - beginning of path in above buffer
- *      @esc - set of characters that need escaping
+ *	mangle_path -	mangle and copy path to buffer beginning
+ *	@s: buffer start
+ *	@p: beginning of path in above buffer
+ *	@esc: set of characters that need escaping
  *
  *      Copy the path from @p to @s, replacing each occurrence of character from
  *      @esc with usual octal escape.

1.5.6.5

ACK, except that I wouldn't use _GPL in the export - it's trivial to reproduce, so we are not protecting anything here. And all that code has been moved verbatim from seq_path(), which is mine *and* exported without _GPL nonsense.

As far as I'm concerned, all these helpers are as general-purpose as atoi() et.al. - library functions damn close to being non-copyrightable due both to triviality and to being absolutely straightforward implementations - tell anybody to implement it and that's what you'll get.

I'm not fond of proprietary modules, to put it mildly, but let's not get completely ridiculous. In this case it's as dumb as schools trying to ban aspirin in the name of War On Some Drugs.

thanks!

okay, fair enough. Would the commit below be fine with you?

Also, since we depend on this commit, would it be fine with you if we carried the trivial patch in tip/tracing/*?

Ingo

---------------->

From: Ingo Molnar <[email protected]>
Date: Fri, 28 Nov 2008 18:03:22 +0100
Subject: [PATCH] vfs, seqfile: export mangle_path() generally

mangle_path() is trivial enough to make export restrictions on it pointless - so change the export from EXPORT_SYMBOL_GPL to EXPORT_SYMBOL.

---
 fs/seq_file.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

index f03220d..16c2115 100644
@@ -387,7 +387,7 @@ char *mangle_path(char *s, char *p, char *esc)
 	}
 	return NULL;
 }
-EXPORT_SYMBOL_GPL(mangle_path);
+EXPORT_SYMBOL(mangle_path);
 
 /*
  * return the absolute path of 'dentry' residing in mount 'mnt'.

---
 arch/x86/kernel/stacktrace.c |   51 +++++++++++++++++++++++------------------
 include/linux/stacktrace.h   |    2 +-
 kernel/trace/trace.c         |    7 ++---
 3 files changed, 33 insertions(+), 27 deletions(-)

index b151530..10786af 100644
@@ -89,7 +89,7 @@ EXPORT_SYMBOL_GPL(save_stack_trace_tsk);
 
 struct stack_frame {
 	const void __user	*next_fp;
-	unsigned long		return_address;
+	unsigned long		ret_addr;
 };
 
 static int copy_stack_frame(const void __user *fp, struct stack_frame *frame)

@@ -108,33 +108,40 @@ static int copy_stack_frame(const void __user *fp, struct stack_frame *frame)
 	return ret;
 }
 
+static inline void __save_stack_trace_user(struct stack_trace *trace)
+{
+	const struct pt_regs *regs = task_pt_regs(current);
+	const void __user *fp = (const void __user *)regs->bp;
+
+	if (trace->nr_entries < trace->max_entries)
+		trace->entries[trace->nr_entries++] = regs->ip;
+
+	while (trace->nr_entries < trace->max_entries) {
+		struct stack_frame frame;
+
+		frame.next_fp = NULL;
+		frame.ret_addr = 0;
+		if (!copy_stack_frame(fp, &frame))
+			break;
+		if ((unsigned long)fp < regs->sp)
+			break;
+		if (frame.ret_addr) {
+			trace->entries[trace->nr_entries++] =
+				frame.ret_addr;
+		}
+		if (fp == frame.next_fp)
+			break;
+		fp = frame.next_fp;
+	}
+}
+
 void save_stack_trace_user(struct stack_trace *trace)
 {
 	/*
 	 * Trace user stack if we are not a kernel thread
 	 */
 	if (current->mm) {
-		const struct pt_regs *regs = task_pt_regs(current);
-		const void __user *fp = (const void __user *)regs->bp;
-
-		if (trace->nr_entries < trace->max_entries)
-			trace->entries[trace->nr_entries++] = regs->ip;
-
-		while (trace->nr_entries < trace->max_entries) {
-			struct stack_frame frame;
-			frame.next_fp = NULL;
-			frame.return_address = 0;
-			if (!copy_stack_frame(fp, &frame))
-				break;
-			if ((unsigned long)fp < regs->sp)
-				break;
-			if (frame.return_address)
-				trace->entries[trace->nr_entries++] =
-					frame.return_address;
-			if (fp == frame.next_fp)
-				break;
-			fp = frame.next_fp;
-		}
+		__save_stack_trace_user(trace);
 	}
 	if (trace->nr_entries < trace->max_entries)
 		trace->entries[trace->nr_entries++] = ULONG_MAX;

index 68de514..fd42d68 100644
@@ -25,7 +25,7 @@ extern void save_stack_trace_user(struct stack_trace *trace);
 #else
 # define save_stack_trace(trace)			do { } while (0)
 # define save_stack_trace_tsk(tsk, trace)		do { } while (0)
-# define save_stack_trace_user(trace)              do { } while (0)
+# define save_stack_trace_user(trace)			do { } while (0)
 # define print_stack_trace(trace, spaces)		do { } while (0)
 #endif
 

index 62776b7..dedf35f 100644
@@ -948,9 +948,9 @@ static void ftrace_trace_userstack(struct trace_array *tr,
 		   struct trace_array_cpu *data,
 		   unsigned long flags, int pc)
 {
+	struct ring_buffer_event *event;
 	struct userstack_entry *entry;
 	struct stack_trace trace;
-	struct ring_buffer_event *event;
 	unsigned long irq_flags;
 
 	if (!(trace_flags & TRACE_ITER_USERSTACKTRACE))

@@ -1471,8 +1471,7 @@ static inline int seq_print_user_ip(struct trace_seq *s, struct mm_struct *mm,
 	if (file) {
 		ret = trace_seq_path(s, &file->f_path);
 		if (ret)
-			ret = trace_seq_printf(s, "[+0x%lx]",
-					ip - vmstart);
+			ret = trace_seq_printf(s, "[+0x%lx]", ip - vmstart);
 	}
 	if (ret && ((sym_flags & TRACE_ITER_SYM_ADDR) || !file))
 		ret = trace_seq_printf(s, " <" IP_FMT ">", ip);

@@ -1485,7 +1484,7 @@ seq_print_userip_objs(const struct userstack_entry *entry, struct trace_seq *s,
 {
 	struct mm_struct *mm = NULL;
 	int ret = 1;
-	unsigned i;
+	unsigned int i;
 
 	if (trace_flags & TRACE_ITER_SYM_USEROBJ) {
 		struct task_struct *task;

1.5.6.5

Hold mmap_sem while looking up/accessing vma. Hold the RCU lock while using the task we looked up.

---
 kernel/trace/trace.c |    9 ++++++---
 1 files changed, 6 insertions(+), 3 deletions(-)

index dedf35f..4c3bd82 100644
@@ -1462,11 +1462,15 @@ static inline int seq_print_user_ip(struct trace_seq *s, struct mm_struct *mm,
 	int ret = 1;
 
 	if (mm) {
-		const struct vm_area_struct *vma = find_vma(mm, ip);
+		const struct vm_area_struct *vma;
+
+		down_read(&mm->mmap_sem);
+		vma = find_vma(mm, ip);
 		if (vma) {
 			file = vma->vm_file;
 			vmstart = vma->vm_start;
 		}
+		up_read(&mm->mmap_sem);
 	}
 	if (file) {
 		ret = trace_seq_path(s, &file->f_path);

@@ -1494,10 +1498,9 @@ seq_print_userip_objs(const struct userstack_entry *entry, struct trace_seq *s,
 		 */
 		rcu_read_lock();
 		task = find_task_by_vpid(entry->ent.tgid);
-		rcu_read_unlock();
-
 		if (task)
 			mm = get_task_mm(task);
+		rcu_read_unlock();
 	}
 
 	for (i = 0; i < FTRACE_STACK_ENTRIES; i++) {

1.5.6.5

I'll move the (file) inside the mmap_sem too, since file is part of vma, and you need mmap_sem to access the vma
nobody can modify (file) if they don't hold mmap_sem.
Am I right?

--Edwin

yeah - you can use the mm lock for that as the vma holds a reference to the file. This works as long as none of the seq functions called with this lock held can provoke a user pagefault (they shouldnt, but i havent checked in detail).

Ingo

It calls d_path, that access only kernel structures AFAICT, so it can't provoke a *user* pagefault.
Not sure about kernel pagefaults, but they shouldn't matter.

Best regards,
--Edwin

yeah - kernel pagefaults can happen in rare circumstances here but they are all atomic and transparent to most other parts of the kernel so they indeed do not matter.

Ingo

---
 kernel/trace/trace.c |   10 +++++-----
 1 files changed, 5 insertions(+), 5 deletions(-)

index 4c3bd82..48d1536 100644
@@ -1470,13 +1470,13 @@ static inline int seq_print_user_ip(struct trace_seq *s, struct mm_struct *mm,
 			file = vma->vm_file;
 			vmstart = vma->vm_start;
 		}
+		if (file) {
+			ret = trace_seq_path(s, &file->f_path);
+			if (ret)
+				ret = trace_seq_printf(s, "[+0x%lx]", ip - vmstart);
+		}
 		up_read(&mm->mmap_sem);
 	}
-	if (file) {
-		ret = trace_seq_path(s, &file->f_path);
-		if (ret)
-			ret = trace_seq_printf(s, "[+0x%lx]", ip - vmstart);
-	}
 	if (ret && ((sym_flags & TRACE_ITER_SYM_ADDR) || !file))
 		ret = trace_seq_printf(s, " <" IP_FMT ">", ip);
 	return ret;

1.5.6.5

Can you suggest an actual distribution & architecture where this facility may be tested/used? It appears to require frame-pointer stuff that AFAIK is not generally turned on for user-space.

- FChE

Debian unstable, x86-32 (I tested on Intel Core Duo). Out of the box, no rebuild of glibc needed.

Here is a sample output:

# echo sched_switch >current_tracer
# echo userstacktrace >trace_options
# echo sym-userobj >trace_options
# echo 1>tracing_enabled
# cat trace_pipe >/tmp/test&
$ ~/a.out
# echo 0 >tracing_enabled

(You can also use other tracers besides sched_switch.)

           bash-6554  [000]   377.837014:   6554:120:S   + [001]  6216:120:S
            bash-6554  [000]   377.837015:  <b7f40424> <-

/lib/i686/cmov/libc-2.7.so[+0x6af77] <- /lib/i686/cmov/libc-2.7.so[+0x6a81a] <- /lib/i686/cmov/libc-2.7.so[+0x5e7e9] <- /bin/bash[+0x5f955] <- /bin/bash[+0x2822a] <- /bin/bash[+0x2bf21] <- /bin/bash[+0x2a403]
....
a.out-7442 [000] 386.221719: 7442:120:R ==> [000] 1344:115:R

           a.out-7442  [000]   386.221720: /lib/ld-2.7.so[+0xbed09631]

<- /lib/ld-2.7.so[+0xbecd4f28] <- /lib/ld-2.7.so[+0xbece9c36] <- /lib/ld-2.7.so[+0xbeca5603] <- /lib/ld-2.7.so[+0xbeca3403] <- /lib/ld-2.7.so[+0xbeca1983] <- /lib/ld-2.7.so[+0xbec93fab] <- /lib/ld-2.7.so[+0xbec93aa5]
a.out-7442 [000] 386.224544: 7442:120:R + [000] 1:120:S

           a.out-7442  [000]   386.224545: /home/edwin/a.out[+0x377] <-
/home/edwin/a.out[+0x38f] <- /lib/i686/cmov/libc-2.7.so[+0x16455] <-
/home/edwin/a.out[+0x2e1]
           a.out-7442  [000]   386.224562:   7442:120:R ==> [000]    
1:120:R
...
           a.out-7442  [000]   386.224562: /home/edwin/a.out[+0x377] <-
/home/edwin/a.out[+0x38f] <- /lib/i686/cmov/libc-2.7.so[+0x16455] <-
/home/edwin/a.out[+0x2e1]
Xorg-5895  [001]   388.180034:   5895:120:R   + [001]  6214:120:S
            Xorg-5895  [001]   388.180035:  <b805f424> <-

/usr/bin/Xorg[+0x17addf] <- /usr/bin/Xorg[+0x1768cb] <- /usr/bin/Xorg[+0x46e10] <- /usr/bin/Xorg[+0x2d795] <- /lib/i686/cmov/libc-2.7.so[+0x16455] <- /usr/bin/Xorg[+0x2ca81]

If I run the little (and inefficient) perl script below I get:

            bash-6554  [000]   377.837015 

<b7f40424>/lib/i686/cmov/libc-2.7.so[+0x6af77] <- /lib/i686/cmov/libc-2.7.so[+0x6a81a] <- /lib/i686/cmov/libc-2.7.so[+0x5e7e9] <- /bin/bash[+0x5f955] <- /bin/bash[+0x2822a] <- /bin/bash[+0x2bf21] <- /bin/bash[+0x2a403]
<- a.out-7442 [000] 386.221720
/lib/ld-2.7.so[+0xbed09631] <- /lib/ld-2.7.so[+0xbecd4f28] <- /lib/ld-2.7.so[+0xbece9c36] <- /lib/ld-2.7.so[+0xbeca5603] <- /lib/ld-2.7.so[+0xbeca3403] <- /lib/ld-2.7.so[+0xbeca1983] <- /lib/ld-2.7.so[+0xbec93fab] <- /lib/ld-2.7.so[+0xbec93aa5]
<- a.out-7442 [000] 386.224545/home/edwin/ll.c:2 <-
/home/edwin/ll.c:9 <- /lib/i686/cmov/libc-2.7.so[+0x16455] <- /home/edwin/a.out[+0x2e1]
<- a.out-7442 [000] 386.224562/home/edwin/ll.c:2 <-
/home/edwin/ll.c:9 <- /lib/i686/cmov/libc-2.7.so[+0x16455] <- /home/edwin/a.out[+0x2e1]
<- Xorg-5895 [001] 388.180035
<b805f424>/usr/bin/Xorg[+0x17addf] <- /usr/bin/Xorg[+0x1768cb] <- /usr/bin/Xorg[+0x46e10] <- /usr/bin/Xorg[+0x2d795] <- /lib/i686/cmov/libc-2.7.so[+0x16455] <- /usr/bin/Xorg[+0x2ca81]

If I use a glibc with debug symbols (by installing the distro package libc6-dbg, and using LD_LIBRARY_PATH=/usr/lib/debug), I can even get libc line numbers:

           a.out-18077 [001] 4154503532.435531:  18077:120:S ==>
[001]     0:140:R
           a.out-18077 [001] 4154503532.435532:

/usr/lib/debug/libc-2.7.so[+0x35424] <- /lib/ld-2.7.so[+0xbeca5186] <- /lib/ld-2.7.so[+0xbeca3403] <- /lib/ld-2.7.so[+0xbeca1983] <- /lib/ld-2.7.so[+0xbec93fab] <- /lib/ld-2.7.so[+0xbec93aa5] <- <49406455> <- /lib/ld-2.7.so[+0xbec91521]

           a.out-18077 [001] 4154503532.481759:  18077:120:R   + [001] 
6214:120:S
           a.out-18077 [001] 4154503532.481760:

/usr/lib/debug/libpthread-2.7.so[+0x72f5] <- /home/edwin/a.out[+0x456] <- /home/edwin/a.out[+0x47a] <- /usr/lib/debug/libc-2.7.so[+0x16455] <- /home/edwin/a.out[+0x3b1]

a.out-18077 [001]
4154503532.435532/build/buildd/glibc-2.7/build-tree/glibc-2.7/stdlib/../stdlib/strtod_l.c:375 <- /lib/ld-2.7.so[+0xbeca5186] <- /lib/ld-2.7.so[+0xbeca3403] <- /lib/ld-2.7.so[+0xbeca1983] <- /lib/ld-2.7.so[+0xbec93fab] <- /lib/ld-2.7.so[+0xbec93aa5] <- <49406455>/lib/ld-2.7.so[+0xbec91521]
<- a.out-18077 [001]
4154503532.481760/build/buildd/glibc-2.7/build-tree/glibc-2.7/nptl/pthread_mutex_lock.c:87 <- /home/edwin/ll.c:7 <- /home/edwin/ll.c:14 <- /build/buildd/glibc-2.7/build-tree/glibc-2.7/csu/libc-start.c:254 <- /home/edwin/a.out[+0x3b1]

It is not turned on for glibc on x86_64, but even there you can at least get the return address to user-space
(which in case of a system call is not very useful since it is inside libc, but could be useful for pagefault tracing for example).

#!/usr/bin/perl
my %cache;

while (<>) {
        next unless / <- /;
        my @list = split(/:| <- /);
        foreach my $entry (@list) {
                if ($entry =~ /(\/[^[]+)\[\+0x([a-f0-9]+)\]/) {
                        if (defined $cache{$entry}) {
                                print $cache{$entry};
                        } else {
                                my $file = $1;
                                my $addr = hex $2;
                                if (not ($file =~ /.so/)) {
                                        $addr = 0x8048000 + $addr;
                                }
                                $addr = sprintf "0x%x", $addr;
                                $res = `addr2line -e $file $addr`;
                                $res =~ s/\n//;
                                if ($res =~ /\?\?/) {
                                        $res = $entry;
                                }
                                $cache{$entry} = $res;
                                print $res;
                        }
                        print " <- "
                } else {
                        print $entry;
                }
        }
}

Best regards,
--Edwin

gentoo, just rebuild world with frame pointers ;-)

Hi -

Well, that only goes so far. If this feature turns out unable to work without distributors recompiling all their stuff on, for example, x86-64, then expectations need to be reset.

- FChE

Who says you need a distributor to recompile stuff.. there are plenty people running gentoo, and it doesn't take all that long to rebuild world on these multi-socket quad core boxen we have today ;-)

Although with gcc getting ever slower and desktop software ever more bloated who knows,.. but then its your own fault if you install gnome and such, gentoo comes lean and mean from the stage3 cage.

I wish more distros would be as easy to rebuild as gentoo is, its a real feature.

My assumption is that this feature will be used to trace individual applications, and not the system as a whole.
Then you only need libc to be recompiled with frame pointers on, and your own application/your own application's libraries.

That is what I want to use it for, and there isn't another solution that allows me to do this.
Sure I can trace userspace alone using ptrace (which has its own overhead), and the kernel alone by using ftrace, but I can't combine those traces in a meaningful manner.
If/when the kernel will support dwarf unwinding, it will only need to provide an alternate implementation for save_stack_trace_user.

Even without frame pointers you can at least get the return address to userspace, which may be inside your application for page faults.

If I need to do system-wide tracing, I can use my 32-bit chroot [*], or boot my laptop which is 32-bit.

I don't think that this feature should get rejected just because it is not easily usable from x86_64.

[*] I haven't tested yet if tracing 32-bit applications from a 64-bit kernel works. It probably won't, and I'll need to use a different struct stack_frame with 32-bit addresses.

Another approach I've though of would be to deliver a signal to userspace on demand, and have the signal handler do the backtrace, but that would unnecesary overhead.

Best regards,
--Edwin

Yes.

Correct, that would be stupid.

Your patches are nice. Right now they are in tracing/core and linux-next already.

Ingo

Thanks. I can move on to the lock latency tracing ;)

I'll send out a draft of tracepoints that I would need to trace lock latency.
I'll try to put them in same place as lockstat (but not necesarely depending on lockstat being enabled).

Once we reach a lock-tracepoints patch that all agree upon, I can (try to) write a ftrace-lock-latency that will have a histogram view (as you've suggested similar to what the likely/unlikely tracer already does), but also show separate counts per unique kernel/user stacktrace.

Or I could add the tracepoints inside lockstat (now that it has contend with points feature), and use the information already gathered by lockstat, but augment it with finer grained counts per kernel/user stacktrace. (again there would be an ftrace plugin that would register with the tracepoints, and show
the per stacktrace statistic in /sys/kernel/debug/tracing/trace).

Which approach should I try first?

Although my goal would be to be able to use this feature by simply turning on a flag at runtime (whether something in /proc or /sys/kernel/debug),
rather than rebooting to a different kernel, it may be easier to implement this at first by using what lockstat already provides, and later improving it
to work w/o lockstat.

What do you think?

Best regards,
--Edwin

that's a bit more contentious ...

yes. The less intrusive your patch is, the more you utilize and generalize existing facilities, the better. You could split the Kconfig of LOCKSTAT into two bits: LOCKSTAT (core) and LOCKSTAT_PROC, where the proc bits are enabled separately.

Your tracing approach could then reuse much of core LOCKSTAT (without even touching the code) and just plain "select LOCKSTAT" - without creating /proc/lockdep_stats.

Peter, what do you think?

Ingo

Ping? I may have some time to work on this in the weekend ...

Best regards,
--Edwin

applied to tip/tracing/stack-tracer - thanks Edwin!

I've got a few comments about certain details - please send delta patches on top of these patches to fix those.

Ingo

Thanks for the review Ingo,

The last commit I see is f8d56f1771e4867acc461146764b4feeb5245669, Sun

Oct 26 16:42:18 2008 -0700, am I looking at the wrong place?

http://git.kernel.org/?p=linux/kernel/git/tip/linux-2.6-tip.git;a=shortlog;h=tracing/stack-tracer

Best regards,
--Edwin

ok - i've pushed out a new tip/tracing/stack-tracer branch.

(have not pushed out the tip/master integration yet - i'm still testing things)

Ingo