ftrace: Add dynamically allocated trampolines

arch/x86/kernel/ftrace.c +7 -0

+
+void arch_ftrace_update_trampoline(struct ftrace_ops *ops)
+{
+	unsigned char *new;
+	unsigned long start_offset;
+	unsigned long call_offset;
+	unsigned long offset;

Quoted 14 lines · Steven Rostedt

arch/x86/kernel/ftrace.c +14 -0

+
+void arch_ftrace_update_trampoline(struct ftrace_ops *ops)
+{
+	unsigned char *new;
+	unsigned long start_offset;
+	unsigned long call_offset;
+	unsigned long offset;
+	unsigned long ip;
+	int ret;
+
+	if (ops->trampoline) {
+		/*
+		 * The ftrace_ops caller may set up its own trampoline.
+		 * In such a case, this code must not modify it.

arch/x86/kernel/ftrace.c static unsigned char *ftrace_jmp_replace(unsigned long ip, unsigned long addr) · line 780

Quoted 3 lines

arch/x86/kernel/ftrace.c +3 -0

+		 */
+		if (!(ops->flags & FTRACE_OPS_FL_ALLOC_TRAMP))
+			return;

Just a question, what happen if the ftrace_ops caller sets up a trampoline which is not compatible to the ftrace's trampoline, and the ftrace_ops conflicts on a IP with other ftrace_ops? I guess in that case ftrace will use the loop callback on the IP, but since the trampoline is not compatible, the result will not be same, is that right? :)

From: "Steven Rostedt (Red Hat)" <[email protected]>

The current method of handling multiple function callbacks is to register a list function callback that calls all the other callbacks based on their hash tables and compare it to the function that the callback was called on. But this is very inefficient.

For example, if you are tracing all functions in the kernel and then add a kprobe to a function such that the kprobe uses ftrace, the mcount trampoline will switch from calling the function trace callback to calling the list callback that will iterate over all registered ftrace_ops (in this case, the function tracer and the kprobes callback). That means for every function being traced it checks the hash of the ftrace_ops for function tracing and kprobes, even though the kprobes is only set at a single function. The kprobes ftrace_ops is checked for every function being traced!

Instead of calling the list function for functions that are only being traced by a single callback, we can call a dynamically allocated trampoline that calls the callback directly. The function graph tracer already uses a direct call trampoline when it is being traced by itself but it is not dynamically allocated. It's trampoline is static in the kernel core. The infrastructure that called the function graph trampoline can also be used to call a dynamically allocated one.

For now, only ftrace_ops that are not dynamically allocated can have a trampoline. That is, users such as function tracer or stack tracer. kprobes and perf allocate their ftrace_ops, and until there's a safe way to free the trampoline, it can not be used. The dynamically allocated ftrace_ops may, although, use the trampoline if the kernel is not compiled with CONFIG_PREEMPT. But that will come later.

Signed-off-by Steven Rostedt <[email protected]>

---
 arch/x86/kernel/ftrace.c    | 157 ++++++++++++++++++++++++++++++++++++++++++--
 arch/x86/kernel/mcount_64.S |  26 ++++++--
 include/linux/ftrace.h      |   8 +++
 kernel/trace/ftrace.c       |  46 ++++++++++++-
 4 files changed, 224 insertions(+), 13 deletions(-)

arch/x86/kernel/ftrace.c +47 -6

index 3386dc9aa333..fcc256a33c1d 100644
@@ -17,9 +17,11 @@
 #include <linux/ftrace.h>
 #include <linux/percpu.h>
 #include <linux/sched.h>
+#include <linux/slab.h>
 #include <linux/init.h>
 #include <linux/list.h>
 #include <linux/module.h>
+#include <linux/moduleloader.h>
 
 #include <trace/syscall.h>
 

@@ -644,12 +646,6 @@ int __init ftrace_dyn_arch_init(void)
 {
 	return 0;
 }
-#endif
-
-#ifdef CONFIG_FUNCTION_GRAPH_TRACER
-
-#ifdef CONFIG_DYNAMIC_FTRACE
-extern void ftrace_graph_call(void);
 
 static unsigned char *ftrace_jmp_replace(unsigned long ip, unsigned long addr)
 {

@@ -665,6 +661,155 @@ static unsigned char *ftrace_jmp_replace(unsigned long ip, unsigned long addr)
 	return calc.code;
 }
 
+/* Currently only x86_64 supports dynamic trampolines */
+#ifdef CONFIG_X86_64
+
+/* Defined as markers to the end of the ftrace default trampolines */
+extern void ftrace_caller_end(void);
+extern void ftrace_regs_caller_end(void);
+extern void ftrace_return(void);
+extern void ftrace_caller_op_ptr(void);
+extern void ftrace_regs_caller_op_ptr(void);
+
+/* movq function_trace_op(%rip), %rdx */
+/* 0x48 0x8b 0x15 <offset-to-ftrace_trace_op (4 bytes)> */
+#define OP_REF_SIZE	7
+
+/*
+ * The ftrace_ops is passed to the function, we can pass
+ * in the ops directly as this trampoline will only call
+ * a function for a single ops.
+ */
+union ftrace_op_code_union {
+	char code[OP_REF_SIZE];
+	struct {
+		char op[3];
+		int offset;
+	} __attribute__((packed));
+};
+
+static unsigned long create_trampoline(struct ftrace_ops *ops)
+{
+	unsigned const char *jmp;
+	unsigned long start_offset;
+	unsigned long end_offset;
+	unsigned long op_offset;
+	unsigned long offset;
+	unsigned long size;
+	unsigned long ip;
+	unsigned long *ptr;
+	void *trampoline;
+	unsigned const char op_ref[] = { 0x48, 0x8b, 0x15 };
+	union ftrace_op_code_union op_ptr;
+	int ret;
+
+	if (ops->flags & FTRACE_OPS_FL_SAVE_REGS) {
+		start_offset = (unsigned long)ftrace_regs_caller;
+		end_offset = (unsigned long)ftrace_regs_caller_end;

[ NOT READY FOR INCLUSION! ]

Note, this is based off of my remove ftrace_start/stop() patch set.

I've been wanting to do this for years, and just never gotten around to it. But with all this talk of kpatch and kgraft live kernel patching using the ftrace infrastructure, it seems like a good time to do it.

The way the function callback mechanism works in ftrace is that if there's only one function callback registered, it will set the mcount/fentry trampoline to call that function directly. But as soon as you register another callback, the mcount trampoline calls a loop function that iterates over all the registered callbacks (ftrace_ops) checking their hash tables to see if the called function matches the ops before calling its callback. This happens even if the two registered functions are not even tracing the same function!

This really sucks if you are tracing all functions, and then add a kprobe or perf event that traces a single function. That will cause all the other functions being traced to perform the loop test.

Ideally, if only a single callback (ftrace_ops) is registered to a function, than that function should call a trampoline that will only call that one callback without doing any other tests.

This patch set adds this functionality to x86_64. If a callback is registered to a function and there's no other callback registered to that function that ftrace_ops will get its own trampoline allocated for it that will call the function directly.

Note, for dynamically allocated ftrace_ops (kprobes, perf, instance directory function tracing), the dynamic trampoline will only be created if CONFIG_PREEMPT is not set. That's because, until Paul finishes his rcu_call_task() code, there's no safe way to know if a task was preempted while on the trampoline and is waiting to run on it some more.

I need to write up a bunch of tests for this code, but currently it works on the few tests I did manually. I didn't even run this code yet under my full test suite, so it may very well have bugs in it that might be easily triggered. But I wanted to get the code out for review to see if anyone has any other idea to help enhance this feature.

If you want a git repo to play with this, you can get it from below. That repo will rebase often, so do not build against it.

Enjoy,

-- Steve

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
rfc/trampoline

Head SHA1: 4d781e010842a56f8e7c1bbe309e38075c277c45

Steven Rostedt (Red Hat) (3):
ftrace/x86: Add dynamic allocated trampoline for ftrace_ops ftrace/x86: Show trampoline call function in enabled_functions ftrace/x86: Allow !CONFIG_PREEMPT dynamic ops to use allocated trampolines

----

 arch/x86/kernel/ftrace.c    | 240 ++++++++++++++++++++++++++++++++++++++++++--
 arch/x86/kernel/mcount_64.S |  26 ++++-
 include/linux/ftrace.h      |   8 ++
 kernel/trace/ftrace.c       |  86 +++++++++++++++-
 4 files changed, 344 insertions(+), 16 deletions(-)

[ NOT READY FOR INCLUSION! ]

Note, this is based off of my remove ftrace_start/stop() patch set.

I've been wanting to do this for years, and just never gotten around to it. But with all this talk of kpatch and kgraft live kernel patching using the ftrace infrastructure, it seems like a good time to do it.

The way the function callback mechanism works in ftrace is that if there's only one function callback registered, it will set the mcount/fentry trampoline to call that function directly. But as soon as you register another callback, the mcount trampoline calls a loop function that iterates over all the registered callbacks (ftrace_ops) checking their hash tables to see if the called function matches the ops before calling its callback. This happens even if the two registered functions are not even tracing the same function!

This really sucks if you are tracing all functions, and then add a kprobe or perf event that traces a single function. That will cause all the other functions being traced to perform the loop test.

Ideally, if only a single callback (ftrace_ops) is registered to a function, than that function should call a trampoline that will only call that one callback without doing any other tests.

This patch set adds this functionality to x86_64. If a callback is registered to a function and there's no other callback registered to that function that ftrace_ops will get its own trampoline allocated for it that will call the function directly.

Note, for dynamically allocated ftrace_ops (kprobes, perf, instance directory function tracing), the dynamic trampoline will only be created if CONFIG_PREEMPT is not set. That's because, until Paul finishes his rcu_call_task() code, there's no safe way to know if a task was preempted while on the trampoline and is waiting to run on it some more.

I need to write up a bunch of tests for this code, but currently it works on the few tests I did manually. I didn't even run this code yet under my full test suite, so it may very well have bugs in it that might be easily triggered. But I wanted to get the code out for review to see if anyone has any other idea to help enhance this feature.

If you want a git repo to play with this, you can get it from below. That repo will rebase often, so do not build against it.

Enjoy,

-- Steve

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
rfc/trampoline

Head SHA1: 4d781e010842a56f8e7c1bbe309e38075c277c45

Steven Rostedt (Red Hat) (3):
ftrace/x86: Add dynamic allocated trampoline for ftrace_ops ftrace/x86: Show trampoline call function in enabled_functions ftrace/x86: Allow !CONFIG_PREEMPT dynamic ops to use allocated trampolines

----

 arch/x86/kernel/ftrace.c    | 240 ++++++++++++++++++++++++++++++++++++++++++--
 arch/x86/kernel/mcount_64.S |  26 ++++-
 include/linux/ftrace.h      |   8 ++
 kernel/trace/ftrace.c       |  86 +++++++++++++++-
 4 files changed, 344 insertions(+), 16 deletions(-)

Quoted 17 lines · Steven Rostedt

[ NOT READY FOR INCLUSION! ]

Note, this is based off of my remove ftrace_start/stop() patch set.

I've been wanting to do this for years, and just never gotten around to it. But with all this talk of kpatch and kgraft live kernel patching using the ftrace infrastructure, it seems like a good time to do it.

The way the function callback mechanism works in ftrace is that if there's only one function callback registered, it will set the mcount/fentry trampoline to call that function directly. But as soon as you register another callback, the mcount trampoline calls a loop function that iterates over all the registered callbacks (ftrace_ops) checking their hash tables to see if the called function matches the ops before calling its callback. This happens even if the two registered functions are not even tracing the same function!

Quoted 3 lines

This really sucks if you are tracing all functions, and then add a kprobe or perf event that traces a single function. That will cause all the other functions being traced to perform the loop test.

Ah, I've thought that ftrace already had different trampoline for loop and single and replaced each mcount-call instruction to appropriate one. But this series actually does that, doesn't this? :)

Quoted 10 lines

Ideally, if only a single callback (ftrace_ops) is registered to a function, than that function should call a trampoline that will only call that one callback without doing any other tests.

This patch set adds this functionality to x86_64. If a callback is registered to a function and there's no other callback registered to that function that ftrace_ops will get its own trampoline allocated for it that will call the function directly.

Quoted 5 lines

Note, for dynamically allocated ftrace_ops (kprobes, perf, instance directory function tracing), the dynamic trampoline will only be created if CONFIG_PREEMPT is not set. That's because, until Paul finishes his rcu_call_task() code, there's no safe way to know if a task was preempted while on the trampoline and is waiting to run on it some more.

Hmm, if we can declare "this ftrace_ops is permanent"(like finalizing) then we can allocate trampoline for such dynamic one. Since the kprobes actually doesn't need to free (or unregister) ftrace_ops, I can use it.

Quoted 7 lines

I need to write up a bunch of tests for this code, but currently it works on the few tests I did manually. I didn't even run this code yet under my full test suite, so it may very well have bugs in it that might be easily triggered. But I wanted to get the code out for review to see if anyone has any other idea to help enhance this feature.

Yeah, I'll review it.

Well, I guess the answer to that is what do you consider the trampoline? I'm currently considering it to be the assembly code that the mcount/fentry call jumps to. We only have two trampolines (three if you count the function graph code that will be called directly come 3.17). Those two are the normal ftrace_caller and the ftrace_regs_caller.

Quoted 5 lines · Steven Rostedt

Well, I guess the answer to that is what do you consider the trampoline? I'm currently considering it to be the assembly code that the mcount/fentry call jumps to. We only have two trampolines (three if you count the function graph code that will be called directly come 3.17). Those two are the normal ftrace_caller and the ftrace_regs_caller.

BTW, on those archs that support regs saving already, is there really a reson not to kill ftrace_caller and keep just ftrace_regs_caller?

[ NOT READY FOR INCLUSION! ]

Note, this is based off of my remove ftrace_start/stop() patch set.

I've been wanting to do this for years, and just never gotten around to it. But with all this talk of kpatch and kgraft live kernel patching using the ftrace infrastructure, it seems like a good time to do it.

The way the function callback mechanism works in ftrace is that if there's only one function callback registered, it will set the mcount/fentry trampoline to call that function directly. But as soon as you register another callback, the mcount trampoline calls a loop function that iterates over all the registered callbacks (ftrace_ops) checking their hash tables to see if the called function matches the ops before calling its callback. This happens even if the two registered functions are not even tracing the same function!

This really sucks if you are tracing all functions, and then add a kprobe or perf event that traces a single function. That will cause all the other functions being traced to perform the loop test.

[ NOT READY FOR INCLUSION! ]

Note, this is based off of my remove ftrace_start/stop() patch set.

I've been wanting to do this for years, and just never gotten around to it. But with all this talk of kpatch and kgraft live kernel patching using the ftrace infrastructure, it seems like a good time to do it.

The way the function callback mechanism works in ftrace is that if there's only one function callback registered, it will set the mcount/fentry trampoline to call that function directly. But as soon as you register another callback, the mcount trampoline calls a loop function that iterates over all the registered callbacks (ftrace_ops) checking their hash tables to see if the called function matches the ops before calling its callback. This happens even if the two registered functions are not even tracing the same function!

This really sucks if you are tracing all functions, and then add a kprobe or perf event that traces a single function. That will cause all the other functions being traced to perform the loop test.

Ideally, if only a single callback (ftrace_ops) is registered to a function, than that function should call a trampoline that will only call that one callback without doing any other tests.

This patch set adds this functionality to x86_64. If a callback is registered to a function and there's no other callback registered to that function that ftrace_ops will get its own trampoline allocated for it that will call the function directly.

Note, for dynamically allocated ftrace_ops (kprobes, perf, instance directory function tracing), the dynamic trampoline will only be created if CONFIG_PREEMPT is not set. That's because, until Paul finishes his rcu_call_task() code, there's no safe way to know if a task was preempted while on the trampoline and is waiting to run on it some more.

I need to write up a bunch of tests for this code, but currently it works on the few tests I did manually. I didn't even run this code yet under my full test suite, so it may very well have bugs in it that might be easily triggered. But I wanted to get the code out for review to see if anyone has any other idea to help enhance this feature.

If you want a git repo to play with this, you can get it from below. That repo will rebase often, so do not build against it.

Enjoy,

-- Steve

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
rfc/trampoline

Head SHA1: 4d781e010842a56f8e7c1bbe309e38075c277c45

Steven Rostedt (Red Hat) (3):
ftrace/x86: Add dynamic allocated trampoline for ftrace_ops ftrace/x86: Show trampoline call function in enabled_functions ftrace/x86: Allow !CONFIG_PREEMPT dynamic ops to use allocated trampolines

----

 arch/x86/kernel/ftrace.c    | 240 ++++++++++++++++++++++++++++++++++++++++++--
 arch/x86/kernel/mcount_64.S |  26 ++++-
 include/linux/ftrace.h      |   8 ++
 kernel/trace/ftrace.c       |  86 +++++++++++++++-
 4 files changed, 344 insertions(+), 16 deletions(-)

I did some testing with kpatch and I found one minor issue. The dynamically allocated trampoline seems to confuse dump_stack() somewhat.

I added a dump_stack() call in my ftrace_ops callback function (kpatch_ftrace_handler) which had a filter on meminfo_proc_show().

Quoted 5 lines · Josh Poimboeuf

I did some testing with kpatch and I found one minor issue. The dynamically allocated trampoline seems to confuse dump_stack() somewhat.

I added a dump_stack() call in my ftrace_ops callback function (kpatch_ftrace_handler) which had a filter on meminfo_proc_show().

Interesting. Are you using dwarf2 unwinder for stack dumping by any chance?

It seems to get things right here. Will look into it more tomorrow.

Quoted 5 lines · Josh Poimboeuf

I did some testing with kpatch and I found one minor issue. The dynamically allocated trampoline seems to confuse dump_stack() somewhat.

I added a dump_stack() call in my ftrace_ops callback function (kpatch_ftrace_handler) which had a filter on meminfo_proc_show().

Interesting. Are you using dwarf2 unwinder for stack dumping by any chance? It seems to get things right here. Will look into it more tomorrow.

Quoted 6 lines

Quoted 5 lines

I did some testing with kpatch and I found one minor issue. The dynamically allocated trampoline seems to confuse dump_stack() somewhat.

I added a dump_stack() call in my ftrace_ops callback function (kpatch_ftrace_handler) which had a filter on meminfo_proc_show().

Quoted 3 lines

Interesting. Are you using dwarf2 unwinder for stack dumping by any chance? It seems to get things right here. Will look into it more tomorrow.

Hmm, can dwarf2 unwinder work on the trampoline method? Since the trampoline just a copy of instructions which will not have CFI(which is stored in dwarf section), I guess it may not work... Frame pointer (push bp and save sp to bp on the entry) can work anyway.

Quoted 6 lines · Masami Hiramatsu

Quoted 6 lines

Quoted 5 lines

I did some testing with kpatch and I found one minor issue. The dynamically allocated trampoline seems to confuse dump_stack() somewhat.

I added a dump_stack() call in my ftrace_ops callback function (kpatch_ftrace_handler) which had a filter on meminfo_proc_show().

Quoted 8 lines

Quoted 3 lines

Interesting. Are you using dwarf2 unwinder for stack dumping by any chance? It seems to get things right here. Will look into it more tomorrow.

Hmm, can dwarf2 unwinder work on the trampoline method? Since the trampoline just a copy of instructions which will not have CFI(which is stored in dwarf section), I guess it may not work... Frame pointer (push bp and save sp to bp on the entry) can work anyway.

That was exactly my idea and that's why I asked, thanks for confirming.

I am afraid we'll have to declare dynamic trampolines incompatible with drawf2 stack dumping.

From 951d2aec17885a62905df6b910dc705d99c63993 Mon Sep 17 00:00:00 2001

Quoted 2 lines

From 951d2aec17885a62905df6b910dc705d99c63993 Mon Sep 17 00:00:00 2001

From: Josh Poimboeuf <[email protected]>
Date: Fri, 11 Jul 2014 08:58:33 -0500
Subject: [PATCH] x86/dumpstack: fix stack traces for generated code

If a function in the stack trace is dynamically generated, for example an ftrace dynamically generated trampoline, print_context_stack() gets confused and ends up showing all the following addresses as unreliable:

  [  934.546013]  [<ffffffff81700312>] dump_stack+0x45/0x56
  [  934.546020]  [<ffffffff8125f5b0>] ? meminfo_proc_open+0x30/0x30
  [  934.546027]  [<ffffffffa080a494>] kpatch_ftrace_handler+0x14/0xf0 [kpatch]
  [  934.546058]  [<ffffffff812143ae>] ? seq_read+0x2de/0x3b0
  [  934.546062]  [<ffffffff812143ae>] ? seq_read+0x2de/0x3b0
  [  934.546067]  [<ffffffff8125f5b5>] ? meminfo_proc_show+0x5/0x5e0
  [  934.546071]  [<ffffffff8125f5b5>] ? meminfo_proc_show+0x5/0x5e0
  [  934.546075]  [<ffffffff8121423a>] ? seq_read+0x16a/0x3b0
  [  934.546081]  [<ffffffff8125768d>] ? proc_reg_read+0x3d/0x80
  [  934.546088]  [<ffffffff811f0668>] ? vfs_read+0x98/0x170
  [  934.546093]  [<ffffffff811f1345>] ? SyS_read+0x55/0xd0
  [  934.546099]  [<ffffffff81707969>] ? system_call_fastpath+0x16/0x1b

Once it encounters an address which is not in the kernel's text area, it gets confused and stops updating the frame pointer.

The __kernel_text_address() check isn't needed when determining whether an address is reliable. It's only needed when deciding whether to print an unreliable address.

Here's the same stack trace with this patch:

  [ 1314.612287]  [<ffffffff81700312>] dump_stack+0x45/0x56
  [ 1314.612290]  [<ffffffff8125f5b0>] ? meminfo_proc_open+0x30/0x30
  [ 1314.612293]  [<ffffffffa080a494>] kpatch_ftrace_handler+0x14/0xf0 [kpatch]
  [ 1314.612306]  [<ffffffffa00160c4>] 0xffffffffa00160c3

  [ 1314.612309]  [<ffffffff812143ae>] ? seq_read+0x2de/0x3b0
  [ 1314.612311]  [<ffffffff812143ae>] ? seq_read+0x2de/0x3b0
  [ 1314.612312]  [<ffffffff8125f5b5>] ? meminfo_proc_show+0x5/0x5e0
  [ 1314.612314]  [<ffffffff8125f5b5>] ? meminfo_proc_show+0x5/0x5e0
  [ 1314.612315]  [<ffffffff8121423a>] ? seq_read+0x16a/0x3b0
  [ 1314.612318]  [<ffffffff8125768d>] proc_reg_read+0x3d/0x80
  [ 1314.612320]  [<ffffffff811f0668>] vfs_read+0x98/0x170
  [ 1314.612322]  [<ffffffff811f1345>] SyS_read+0x55/0xd0
  [ 1314.612324]  [<ffffffff81707969>] system_call_fastpath+0x16/0x1b
---
 arch/x86/kernel/dumpstack.c | 15 +++++++--------
 1 file changed, 7 insertions(+), 8 deletions(-)

arch/x86/kernel/dumpstack.c +7 -8

index b74ebc7..db0a33c 100644
@@ -102,14 +102,13 @@ print_context_stack(struct thread_info *tinfo,
 		unsigned long addr;
 
 		addr = *stack;
-		if (__kernel_text_address(addr)) {
-			if ((unsigned long) stack == bp + sizeof(long)) {
-				ops->address(data, addr, 1);
-				frame = frame->next_frame;
-				bp = (unsigned long) frame;
-			} else {
-				ops->address(data, addr, 0);
-			}
+		if ((unsigned long) stack == bp + sizeof(long)) {
+			ops->address(data, addr, 1);
+			frame = frame->next_frame;
+			bp = (unsigned long) frame;
+			print_ftrace_graph_addr(addr, data, ops, tinfo, graph);
+		} else if (__kernel_text_address(addr)) {
+			ops->address(data, addr, 0);
 			print_ftrace_graph_addr(addr, data, ops, tinfo, graph);
 		}
 		stack++;

(2014/07/11 23:29), Josh Poimboeuf wrote:
[...]

Quoted 23 lines

Quoted 2 lines

From 951d2aec17885a62905df6b910dc705d99c63993 Mon Sep 17 00:00:00 2001

From: Josh Poimboeuf <[email protected]>
Date: Fri, 11 Jul 2014 08:58:33 -0500
Subject: [PATCH] x86/dumpstack: fix stack traces for generated code

If a function in the stack trace is dynamically generated, for example an ftrace dynamically generated trampoline, print_context_stack() gets confused and ends up showing all the following addresses as unreliable:

  [  934.546013]  [<ffffffff81700312>] dump_stack+0x45/0x56
  [  934.546020]  [<ffffffff8125f5b0>] ? meminfo_proc_open+0x30/0x30
  [  934.546027]  [<ffffffffa080a494>] kpatch_ftrace_handler+0x14/0xf0 [kpatch]
  [  934.546058]  [<ffffffff812143ae>] ? seq_read+0x2de/0x3b0
  [  934.546062]  [<ffffffff812143ae>] ? seq_read+0x2de/0x3b0
  [  934.546067]  [<ffffffff8125f5b5>] ? meminfo_proc_show+0x5/0x5e0
  [  934.546071]  [<ffffffff8125f5b5>] ? meminfo_proc_show+0x5/0x5e0
  [  934.546075]  [<ffffffff8121423a>] ? seq_read+0x16a/0x3b0
  [  934.546081]  [<ffffffff8125768d>] ? proc_reg_read+0x3d/0x80
  [  934.546088]  [<ffffffff811f0668>] ? vfs_read+0x98/0x170
  [  934.546093]  [<ffffffff811f1345>] ? SyS_read+0x55/0xd0
  [  934.546099]  [<ffffffff81707969>] ? system_call_fastpath+0x16/0x1b

Quoted 2 lines

Once it encounters an address which is not in the kernel's text area, it gets confused and stops updating the frame pointer.

Right, this uses a module_alloc to get a memory for trampline, but it just allocates a page in executable vmalloc area. We need a hack in __kernel_text_address if we really want to use that.

Quoted 3 lines

The __kernel_text_address() check isn't needed when determining whether an address is reliable. It's only needed when deciding whether to print an unreliable address.

Yeah, I guess that is for the case that the frame pointer is broken.

Quoted 3 lines

Here's the same stack trace with this patch:

Quoted 4 lines

  [ 1314.612287]  [<ffffffff81700312>] dump_stack+0x45/0x56
  [ 1314.612290]  [<ffffffff8125f5b0>] ? meminfo_proc_open+0x30/0x30
  [ 1314.612293]  [<ffffffffa080a494>] kpatch_ftrace_handler+0x14/0xf0 [kpatch]
  [ 1314.612306]  [<ffffffffa00160c4>] 0xffffffffa00160c3

Here, this still has a wrong entry. Maybe the trampline doesn't setup frame pointer (bp) correctly.

Quoted 6 lines

  [ 1314.612309]  [<ffffffff812143ae>] ? seq_read+0x2de/0x3b0
  [ 1314.612311]  [<ffffffff812143ae>] ? seq_read+0x2de/0x3b0
  [ 1314.612312]  [<ffffffff8125f5b5>] ? meminfo_proc_show+0x5/0x5e0
  [ 1314.612314]  [<ffffffff8125f5b5>] ? meminfo_proc_show+0x5/0x5e0
  [ 1314.612315]  [<ffffffff8121423a>] ? seq_read+0x16a/0x3b0

Quoted 35 lines

  [ 1314.612318]  [<ffffffff8125768d>] proc_reg_read+0x3d/0x80
  [ 1314.612320]  [<ffffffff811f0668>] vfs_read+0x98/0x170
  [ 1314.612322]  [<ffffffff811f1345>] SyS_read+0x55/0xd0
  [ 1314.612324]  [<ffffffff81707969>] system_call_fastpath+0x16/0x1b
---
 arch/x86/kernel/dumpstack.c | 15 +++++++--------
 1 file changed, 7 insertions(+), 8 deletions(-)

arch/x86/kernel/dumpstack.c +7 -8

index b74ebc7..db0a33c 100644
@@ -102,14 +102,13 @@ print_context_stack(struct thread_info *tinfo,
 		unsigned long addr;
 
 		addr = *stack;
-		if (__kernel_text_address(addr)) {
-			if ((unsigned long) stack == bp + sizeof(long)) {
-				ops->address(data, addr, 1);
-				frame = frame->next_frame;
-				bp = (unsigned long) frame;
-			} else {
-				ops->address(data, addr, 0);
-			}
+		if ((unsigned long) stack == bp + sizeof(long)) {
+			ops->address(data, addr, 1);
+			frame = frame->next_frame;
+			bp = (unsigned long) frame;
+			print_ftrace_graph_addr(addr, data, ops, tinfo, graph);
+		} else if (__kernel_text_address(addr)) {
+			ops->address(data, addr, 0);
 			print_ftrace_graph_addr(addr, data, ops, tinfo, graph);
 		}
 		stack++;

Hi Masami,

Quoted 46 lines · Masami Hiramatsu

(2014/07/11 23:29), Josh Poimboeuf wrote:
[...]

Quoted 23 lines

Quoted 2 lines

From 951d2aec17885a62905df6b910dc705d99c63993 Mon Sep 17 00:00:00 2001

From: Josh Poimboeuf <[email protected]>
Date: Fri, 11 Jul 2014 08:58:33 -0500
Subject: [PATCH] x86/dumpstack: fix stack traces for generated code

If a function in the stack trace is dynamically generated, for example an ftrace dynamically generated trampoline, print_context_stack() gets confused and ends up showing all the following addresses as unreliable:

  [  934.546013]  [<ffffffff81700312>] dump_stack+0x45/0x56
  [  934.546020]  [<ffffffff8125f5b0>] ? meminfo_proc_open+0x30/0x30
  [  934.546027]  [<ffffffffa080a494>] kpatch_ftrace_handler+0x14/0xf0 [kpatch]
  [  934.546058]  [<ffffffff812143ae>] ? seq_read+0x2de/0x3b0
  [  934.546062]  [<ffffffff812143ae>] ? seq_read+0x2de/0x3b0
  [  934.546067]  [<ffffffff8125f5b5>] ? meminfo_proc_show+0x5/0x5e0
  [  934.546071]  [<ffffffff8125f5b5>] ? meminfo_proc_show+0x5/0x5e0
  [  934.546075]  [<ffffffff8121423a>] ? seq_read+0x16a/0x3b0
  [  934.546081]  [<ffffffff8125768d>] ? proc_reg_read+0x3d/0x80
  [  934.546088]  [<ffffffff811f0668>] ? vfs_read+0x98/0x170
  [  934.546093]  [<ffffffff811f1345>] ? SyS_read+0x55/0xd0
  [  934.546099]  [<ffffffff81707969>] ? system_call_fastpath+0x16/0x1b

Quoted 2 lines

Once it encounters an address which is not in the kernel's text area, it gets confused and stops updating the frame pointer.

Right, this uses a module_alloc to get a memory for trampline, but it just allocates a page in executable vmalloc area. We need a hack in __kernel_text_address if we really want to use that.

Quoted 3 lines

The __kernel_text_address() check isn't needed when determining whether an address is reliable. It's only needed when deciding whether to print an unreliable address.

Yeah, I guess that is for the case that the frame pointer is broken.

Quoted 7 lines

Here's the same stack trace with this patch:

  [ 1314.612287]  [<ffffffff81700312>] dump_stack+0x45/0x56
  [ 1314.612290]  [<ffffffff8125f5b0>] ? meminfo_proc_open+0x30/0x30
  [ 1314.612293]  [<ffffffffa080a494>] kpatch_ftrace_handler+0x14/0xf0 [kpatch]
  [ 1314.612306]  [<ffffffffa00160c4>] 0xffffffffa00160c3

Quoted 2 lines

Here, this still has a wrong entry. Maybe the trampline doesn't setup frame pointer (bp) correctly.

Hmm.. are you saying about the hex address above? I guess it's a valid entry in the (dynamic) trampoline, but has no symbol..

Quoted 5 lines

Quoted 5 lines

  [ 1314.612309]  [<ffffffff812143ae>] ? seq_read+0x2de/0x3b0
  [ 1314.612311]  [<ffffffff812143ae>] ? seq_read+0x2de/0x3b0
  [ 1314.612312]  [<ffffffff8125f5b5>] ? meminfo_proc_show+0x5/0x5e0
  [ 1314.612314]  [<ffffffff8125f5b5>] ? meminfo_proc_show+0x5/0x5e0
  [ 1314.612315]  [<ffffffff8121423a>] ? seq_read+0x16a/0x3b0

But these seem to be wrong - there're duplicate entries and they should show some of these functions (at least) correctly IMHO. I guess it's because the trampoline didn't save rbp to the stack right below the return address as dumpstack requires.

Quoted 11 lines · Namhyung Kim

Hi Masami,

Quoted 8 lines · Masami Hiramatsu

Quoted 6 lines · Josh Poimboeuf

Here's the same stack trace with this patch:

  [ 1314.612287]  [<ffffffff81700312>] dump_stack+0x45/0x56
  [ 1314.612290]  [<ffffffff8125f5b0>] ? meminfo_proc_open+0x30/0x30
  [ 1314.612293]  [<ffffffffa080a494>] kpatch_ftrace_handler+0x14/0xf0 [kpatch]
  [ 1314.612306]  [<ffffffffa00160c4>] 0xffffffffa00160c3

Quoted 5 lines

Quoted 2 lines

Here, this still has a wrong entry. Maybe the trampline doesn't setup frame pointer (bp) correctly.

Hmm.. are you saying about the hex address above? I guess it's a valid entry in the (dynamic) trampoline, but has no symbol..

Ah, indeed. (BTW, why is it one less than the address ...? printk's spec?)

2014-07-14 (월), 17:18 +0900, Masami Hiramatsu:

Quoted 12 lines

Quoted 11 lines · Namhyung Kim

Hi Masami,

Quoted 8 lines · Masami Hiramatsu

Quoted 6 lines · Josh Poimboeuf

Here's the same stack trace with this patch:

  [ 1314.612287]  [<ffffffff81700312>] dump_stack+0x45/0x56
  [ 1314.612290]  [<ffffffff8125f5b0>] ? meminfo_proc_open+0x30/0x30
  [ 1314.612293]  [<ffffffffa080a494>] kpatch_ftrace_handler+0x14/0xf0 [kpatch]
  [ 1314.612306]  [<ffffffffa00160c4>] 0xffffffffa00160c3

Quoted 7 lines

Quoted 5 lines

Quoted 2 lines

Here, this still has a wrong entry. Maybe the trampline doesn't setup frame pointer (bp) correctly.

Hmm.. are you saying about the hex address above? I guess it's a valid entry in the (dynamic) trampoline, but has no symbol..

Ah, indeed. (BTW, why is it one less than the address ...? printk's spec?)

Argh, it seems like a bug in printk's %pB format processing.. :-/

It subtract 1 from the address for stacktrace. Please see the commit 0f77a8d37825 ("vsprintf: Introduce %pB format specifier") and 71f9e59800e5 ("x86, dumpstack: Use %pB format specifier for stack trace") for details. But it should restore the original address when it failed to find a symbol for that address.

I'll send a fix soon.

[ NOT READY FOR INCLUSION! ]

Note, this is based off of my remove ftrace_start/stop() patch set.

The way the function callback mechanism works in ftrace is that if there's only one function callback registered, it will set the mcount/fentry trampoline to call that function directly. But as soon as you register another callback, the mcount trampoline calls a loop function that iterates over all the registered callbacks (ftrace_ops) checking their hash tables to see if the called function matches the ops before calling its callback. This happens even if the two registered functions are not even tracing the same function!

This really sucks if you are tracing all functions, and then add a kprobe or perf event that traces a single function. That will cause all the other functions being traced to perform the loop test.

Quoted 4 lines · Steven Rostedt

[ NOT READY FOR INCLUSION! ]

Note, this is based off of my remove ftrace_start/stop() patch set.

So I simply pulled your tree. I can't really comment these changes simply because I do not understand this code. But I am hunting for RHEL bug in (probably) this area, so I decided to take a look in a hope that may be this can help me to understand the current code ;)

Quoted 10 lines

The way the function callback mechanism works in ftrace is that if there's only one function callback registered, it will set the mcount/fentry trampoline to call that function directly. But as soon as you register another callback, the mcount trampoline calls a loop function that iterates over all the registered callbacks (ftrace_ops) checking their hash tables to see if the called function matches the ops before calling its callback. This happens even if the two registered functions are not even tracing the same function!

Quoted 3 lines

This really sucks if you are tracing all functions, and then add a kprobe or perf event that traces a single function. That will cause all the other functions being traced to perform the loop test.

But this is even worse or I missed something? I mean, currently even if you trace nothing and then add a KPROBE_FLAG_FTRACE kprobe, then kprobe_ftrace_handler() is called by ftrace_ops_list_func() ?

After these changes it seems that kprobe will use a trampoline.

And I can't understand even the basic code. Say, __ftrace_hash_rec_update:

		if (inc) {
			rec->flags++;
			if (FTRACE_WARN_ON(ftrace_rec_count(rec) == FTRACE_REF_MAX))
				return;

			/*
			 * If there's only a single callback registered to a
			 * function, and the ops has a trampoline registered
			 * for it, then we can call it directly.
			 */
			if (ftrace_rec_count(rec) == 1 && ops->trampoline) {
				rec->flags |= FTRACE_FL_TRAMP;
				ops->trampolines++;
			} else {
				/*
				 * If we are adding another function callback
				 * to this function, and the previous had a
				 * trampoline used, then we need to go back to
				 * the default trampoline.
				 */
				rec->flags &= ~FTRACE_FL_TRAMP;

				/* remove trampolines from any ops for this rec */
				ftrace_clear_tramps(rec);
			}

It seems that "else if (ftrace_rec_count(rec) == 2)" can avoid the unnecessary ftrace_clear_tramps() ? And not only unnecessary, ftrace_clear_tramps() decrements ->trampolines, can't this break the accounting?

		} else {
			if (FTRACE_WARN_ON(ftrace_rec_count(rec) == 0))
				return;
			rec->flags--;

			if (ops->trampoline && !ftrace_rec_count(rec))
				ftrace_remove_tramp(ops, rec);

I am wondering what should we do if ftrace_rec_count() becomes 1 again...

ftrace_save_ops_tramp_hash():

	do_for_each_ftrace_rec(pg, rec) {
		if (ftrace_rec_count(rec) == 1 &&
		    ftrace_ops_test(ops, rec->ip, rec)) {

			/* This record had better have a trampoline */
			if (FTRACE_WARN_ON(!(rec->flags & FTRACE_FL_TRAMP_EN)))
				return -1;

Yes, but I can't understand how this can work.

This ops can have ->trampolines > 0, but FTRACE_FL_TRAMP_EN can be cleared by another ftrace_ops?

Suppose there is a single tracer of this function, rec->flags = TRAMP | TRAMP_EN. Suppose also that it traces more than 1 function, so ->trampolines > 1.

Another tracer comes, __ftrace_hash_rec_update() clears TRAMP. But it should also do ftrace_check_record() and this should clear TRAMP_EN?

And yes, I can trigger this bug if I simply do "echo function > current_tracer" and then add/remove a KPROBE_FLAG_FTRACE kprobe.

And you know, when I try to read this code I can't distinguish ->trampoline from ->trampolines ;)

Quoted 15 lines · On Tue, 22 Jul 2014 18:47:07 +0200 Oleg Nesterov <[email protected]> wrote:

Quoted 12 lines · Steven Rostedt

The way the function callback mechanism works in ftrace is that if there's only one function callback registered, it will set the mcount/fentry trampoline to call that function directly. But as soon as you register another callback, the mcount trampoline calls a loop function that iterates over all the registered callbacks (ftrace_ops) checking their hash tables to see if the called function matches the ops before calling its callback. This happens even if the two registered functions are not even tracing the same function!

This really sucks if you are tracing all functions, and then add a kprobe or perf event that traces a single function. That will cause all the other functions being traced to perform the loop test.

Quoted 3 lines

But this is even worse or I missed something? I mean, currently even if you trace nothing and then add a KPROBE_FLAG_FTRACE kprobe, then kprobe_ftrace_handler() is called by ftrace_ops_list_func() ?

It shouldn't be. It should get called directly from the trampoline. The allocated trampoline should never call the list op. Well, it might during the conversion for safety, but after that, trampolines should only call the registered ftrace_ops->func directly.

Quoted 10 lines

ftrace_save_ops_tramp_hash():

	do_for_each_ftrace_rec(pg, rec) {
		if (ftrace_rec_count(rec) == 1 &&
		    ftrace_ops_test(ops, rec->ip, rec)) {

			/* This record had better have a trampoline */
			if (FTRACE_WARN_ON(!(rec->flags & FTRACE_FL_TRAMP_EN)))
				return -1;

Quoted 1 line

Yes, but I can't understand how this can work.

I wanted the back to 1 case to happen after we get the up to one case working. That is, I don't want to worry about it now ;-) As you can see, this code has enough things to try to keep straight without adding more complexity to the mix.

Quoted 23 lines · Steven Rostedt

Quoted 18 lines · On Tue, 22 Jul 2014 18:47:07 +0200 Oleg Nesterov <[email protected]> wrote:

Quoted 9 lines · Steven Rostedt

The way the function callback mechanism works in ftrace is that if there's only one function callback registered, it will set the mcount/fentry trampoline to call that function directly. But as soon as you register another callback, the mcount trampoline calls a loop function that iterates over all the registered callbacks (ftrace_ops) checking their hash tables to see if the called function matches the ops before calling its callback. This happens even if the two registered functions are not even tracing the same function!

Quoted 3 lines

This really sucks if you are tracing all functions, and then add a kprobe or perf event that traces a single function. That will cause all the other functions being traced to perform the loop test.

But this is even worse or I missed something? I mean, currently even if you trace nothing and then add a KPROBE_FLAG_FTRACE kprobe, then kprobe_ftrace_handler() is called by ftrace_ops_list_func() ?

Quoted 4 lines

It shouldn't be. It should get called directly from the trampoline. The allocated trampoline should never call the list op. Well, it might during the conversion for safety, but after that, trampolines should only call the registered ftrace_ops->func directly.

I meant the current code (I am reading 3.16-rc2). Even if we have a single KPROBE_FLAG_FTRACE kprobe, kprobe_ftrace_handler() won't be called directly.

Or I misunderstood your reply? Just in case, let me check...

With this stupid patch

	--- a/kernel/trace/ftrace.c
	+++ b/kernel/trace/ftrace.c
	@@ -4464,6 +4464,7 @@ __ftrace_ops_list_func(unsigned long ip, unsigned long parent_ip,
					printk("op=%p %pS\n", op, op);
					goto out;
				}
	+			pr_crit("LIST_FUNC -> %pf()\n",  op->func);
				op->func(ip, parent_ip, op, regs);
			}
		} while_for_each_ftrace_op(op);

I do

	# cd /sys/kernel/debug/tracing/
	# echo "p:xx SyS_prctl+0x1c" >| kprobe_events
	# cat ../kprobes/list
	ffffffff81056c4c  k  SyS_prctl+0x1c    [DISABLED][FTRACE]
	# echo 1 >| events/kprobes/xx/enable
	#
	# perl -e 'syscall 157,-1'
	# dmesg
	LIST_FUNC -> kprobe_ftrace_handler()

so it is really called by the loop test code.

And I guess that after your patches kprobe_ftrace_handler() should be called from the trampoline in this case.

Quoted 13 lines

Quoted 12 lines

ftrace_save_ops_tramp_hash():

	do_for_each_ftrace_rec(pg, rec) {
		if (ftrace_rec_count(rec) == 1 &&
		    ftrace_ops_test(ops, rec->ip, rec)) {

			/* This record had better have a trampoline */
			if (FTRACE_WARN_ON(!(rec->flags & FTRACE_FL_TRAMP_EN)))
				return -1;

Yes, but I can't understand how this can work.

Quoted 4 lines

I wanted the back to 1 case to happen after we get the up to one case working. That is, I don't want to worry about it now ;-) As you can see, this code has enough things to try to keep straight without adding more complexity to the mix.

Yes, I see... but note that this WARN_ON() looks wrong in any case. At least currently.

Quoted 24 lines · On Wed, 23 Jul 2014 14:08:05 +0200 Oleg Nesterov <[email protected]> wrote:

With this stupid patch

	--- a/kernel/trace/ftrace.c
	+++ b/kernel/trace/ftrace.c
	@@ -4464,6 +4464,7 @@ __ftrace_ops_list_func(unsigned long ip, unsigned long parent_ip,
					printk("op=%p %pS\n", op, op);
					goto out;
				}
	+			pr_crit("LIST_FUNC -> %pf()\n",  op->func);
				op->func(ip, parent_ip, op, regs);
			}
		} while_for_each_ftrace_op(op);

I do

	# cd /sys/kernel/debug/tracing/
	# echo "p:xx SyS_prctl+0x1c" >| kprobe_events
	# cat ../kprobes/list
	ffffffff81056c4c  k  SyS_prctl+0x1c    [DISABLED][FTRACE]
	# echo 1 >| events/kprobes/xx/enable
	#
	# perl -e 'syscall 157,-1'
	# dmesg
	LIST_FUNC -> kprobe_ftrace_handler()

Quoted 4 lines

so it is really called by the loop test code.

And I guess that after your patches kprobe_ftrace_handler() should be called from the trampoline in this case.

No it wont be. Not until we have Paul McKenney's task_rcu code that will return after all tasks have either gone through userspace or a schedule. Hmm, maybe on a !CONFIG_PREEMPT it will be OK. Oh, I can have that be OK now on !CONFIG_PREEMPT. Maybe I'll do that too.

kprobe ftrace_ops are allocated which sets the FTRACE_OPS_FL_DYNAMIC flag. You'll see that flag checked in update_ftrace_function(), and if it is set, it forces the ftrace_ops_list_func() to be used.

Why?

[...snip..]

	foo()
	  [mcount called --> ftrace_caller trampoline]
           ftrace_caller
             load ftrace_ops into parameter
             <interrupt>
             preempt_schedule()
       [new task]
       kfree(kprobe ftrace_ops);

Quoted 3 lines

kprobe ftrace_ops are allocated which sets the FTRACE_OPS_FL_DYNAMIC flag. You'll see that flag checked in update_ftrace_function(), and if it is set, it forces the ftrace_ops_list_func() to be used.

No? __register_ftrace_function() sets if !core_kernel_data(ops), and kprobe_ftrace_ops is not dynamic?

Quoted 4 lines

Why?

[...snip..]

Yes, thanks, I understand why, at least to some degree.

Quoted 8 lines

	foo()
	  [mcount called --> ftrace_caller trampoline]
           ftrace_caller
             load ftrace_ops into parameter
             <interrupt>
             preempt_schedule()
       [new task]
       kfree(kprobe ftrace_ops);

see above.

And to be sure, I compiled your rfc/trampoline kernel which I pulled yesterday with the same patch and did the same test. __ftrace_ops_list_func() prints nothing.

So I also added WARN_ON(1) into kprobe_ftrace_handler() to ensure that it is actually called, and yes, dmesg reports

	WARNING: ... kprobe_ftrace_handler+0x38/0x140()
	...
	Call Trace:
	 [<ffffffff8136a3eb>] dump_stack+0x5b/0xa8
	 [<ffffffff810423ec>] warn_slowpath_common+0x8c/0xc0
	 [<ffffffff8105772c>] ? SyS_prctl+0x1c/0x730
	 [<ffffffff8104243a>] warn_slowpath_null+0x1a/0x20
	 [<ffffffff810325c8>] kprobe_ftrace_handler+0x38/0x140
	 [<ffffffff8137148a>] ? retint_swapgs+0xe/0x13
	 [<ffffffff81057731>] ? SyS_prctl+0x21/0x730
	 [<ffffffff81057731>] ? SyS_prctl+0x21/0x730
	 [<ffffffff8122424e>] ? trace_hardirqs_on_thunk+0x3a/0x3f
	 [<ffffffff81370912>] ? system_call_fastpath+0x16/0x1b

after "perl -e 'syscall 157,-1'".

and, as expected, if I do "echo SyS_prctl >| set_ftrace_filter" and "echo function >| current_tracer", then the command above also triggers 2 printk's in __ftrace_ops_list_func() :

	LIST_FUNC -> function_trace_call()
	LIST_FUNC -> kprobe_ftrace_handler()

so it seems that your patches can potentially buy more than you think ;)

Oleg.