| Message ID | 20181130150956.27620-1-anders.roxell@linaro.org |
|---|---|
| State | New |
| Headers | show |
| Series | [1/3] stackleak: mark stackleak_track_stack() as notrace | expand |
On Fri, 30 Nov 2018 16:09:56 +0100 Anders Roxell <anders.roxell@linaro.org> wrote: > Both of those functions end up calling ftrace_modify_code(), which is > expensive because it changes the page tables and flush caches. > Microseconds add up because this is called in a loop for each dyn_ftrace > record, and this triggers the softlockup watchdog unless we let it sleep > occasionally. > Rework so that we call cond_resched() before going into the > ftrace_modify_code() function. > > Co-developed-by: Arnd Bergmann <arnd@arndb.de> > Signed-off-by: Arnd Bergmann <arnd@arndb.de> > Signed-off-by: Anders Roxell <anders.roxell@linaro.org> I'm fine with this patch, but I'm not placing an ack on this patch just because I don't know the repercussions of such a change. I'll let you folks take full responsibility ;-) -- Steve > --- > arch/arm64/kernel/ftrace.c | 10 ++++++++++ > 1 file changed, 10 insertions(+) > > diff --git a/arch/arm64/kernel/ftrace.c b/arch/arm64/kernel/ftrace.c > index de1a397d2d3f..9da38da58df7 100644 > --- a/arch/arm64/kernel/ftrace.c > +++ b/arch/arm64/kernel/ftrace.c > @@ -130,6 +130,11 @@ int ftrace_make_call(struct dyn_ftrace *rec, unsigned long addr) > old = aarch64_insn_gen_nop(); > new = aarch64_insn_gen_branch_imm(pc, addr, AARCH64_INSN_BRANCH_LINK); > > + /* This function can take a long time when sanitizers are enabled, so > + * lets make sure we allow RCU processing. > + */ > + cond_resched(); > + > return ftrace_modify_code(pc, old, new, true); > } > > @@ -188,6 +193,11 @@ int ftrace_make_nop(struct module *mod, struct dyn_ftrace *rec, > > new = aarch64_insn_gen_nop(); > > + /* This function can take a long time when sanitizers are enabled, so > + * lets make sure we allow RCU processing. > + */ > + cond_resched(); > + > return ftrace_modify_code(pc, old, new, validate); > } >
Hi Anders, On Fri, Nov 30, 2018 at 04:09:56PM +0100, Anders Roxell wrote: > Both of those functions end up calling ftrace_modify_code(), which is > expensive because it changes the page tables and flush caches. > Microseconds add up because this is called in a loop for each dyn_ftrace > record, and this triggers the softlockup watchdog unless we let it sleep > occasionally. > Rework so that we call cond_resched() before going into the > ftrace_modify_code() function. > > Co-developed-by: Arnd Bergmann <arnd@arndb.de> > Signed-off-by: Arnd Bergmann <arnd@arndb.de> > Signed-off-by: Anders Roxell <anders.roxell@linaro.org> > --- > arch/arm64/kernel/ftrace.c | 10 ++++++++++ > 1 file changed, 10 insertions(+) It sounds like you're running into issues with the existing code, but I'd like to understand a bit more about exactly what you're seeing. Which part of the ftrace patching is proving to be expensive? The page table manipulation only happens once per module when using PLTs, and the cache maintenance is just a single line per patch site without an IPI. Is it the loop in ftrace_replace_code() that is causing the hassle? Will
On Mon, Dec 3, 2018 at 8:22 PM Will Deacon <will.deacon@arm.com> wrote: > > Hi Anders, > > On Fri, Nov 30, 2018 at 04:09:56PM +0100, Anders Roxell wrote: > > Both of those functions end up calling ftrace_modify_code(), which is > > expensive because it changes the page tables and flush caches. > > Microseconds add up because this is called in a loop for each dyn_ftrace > > record, and this triggers the softlockup watchdog unless we let it sleep > > occasionally. > > Rework so that we call cond_resched() before going into the > > ftrace_modify_code() function. > > > > Co-developed-by: Arnd Bergmann <arnd@arndb.de> > > Signed-off-by: Arnd Bergmann <arnd@arndb.de> > > Signed-off-by: Anders Roxell <anders.roxell@linaro.org> > > --- > > arch/arm64/kernel/ftrace.c | 10 ++++++++++ > > 1 file changed, 10 insertions(+) > > It sounds like you're running into issues with the existing code, but I'd > like to understand a bit more about exactly what you're seeing. Which part > of the ftrace patching is proving to be expensive? > > The page table manipulation only happens once per module when using PLTs, > and the cache maintenance is just a single line per patch site without an > IPI. > > Is it the loop in ftrace_replace_code() that is causing the hassle? Yes: with an allmodconfig kernel, the ftrace selftest calls ftrace_replace_code to look >40000 through ftrace_make_call/ftrace_make_nop, and these end up calling static int __kprobes __aarch64_insn_write(void *addr, __le32 insn) { void *waddr = addr; unsigned long flags = 0; int ret; raw_spin_lock_irqsave(&patch_lock, flags); waddr = patch_map(addr, FIX_TEXT_POKE0); ret = probe_kernel_write(waddr, &insn, AARCH64_INSN_SIZE); patch_unmap(FIX_TEXT_POKE0); raw_spin_unlock_irqrestore(&patch_lock, flags); return ret; } int __kprobes aarch64_insn_patch_text_nosync(void *addr, u32 insn) { u32 *tp = addr; int ret; /* A64 instructions must be word aligned */ if ((uintptr_t)tp & 0x3) return -EINVAL; ret = aarch64_insn_write(tp, insn); if (ret == 0) __flush_icache_range((uintptr_t)tp, (uintptr_t)tp + AARCH64_INSN_SIZE); return ret; } which seems to be where the main cost is. This is with inside of qemu, and with lots of debugging options (in particular kcov and ubsan) enabled, that make each function call more expensive. Arnd
On Mon, 3 Dec 2018 22:51:52 +0100 Arnd Bergmann <arnd@arndb.de> wrote: > On Mon, Dec 3, 2018 at 8:22 PM Will Deacon <will.deacon@arm.com> wrote: > > > > Hi Anders, > > > > On Fri, Nov 30, 2018 at 04:09:56PM +0100, Anders Roxell wrote: > > > Both of those functions end up calling ftrace_modify_code(), which is > > > expensive because it changes the page tables and flush caches. > > > Microseconds add up because this is called in a loop for each dyn_ftrace > > > record, and this triggers the softlockup watchdog unless we let it sleep > > > occasionally. > > > Rework so that we call cond_resched() before going into the > > > ftrace_modify_code() function. > > > > > > Co-developed-by: Arnd Bergmann <arnd@arndb.de> > > > Signed-off-by: Arnd Bergmann <arnd@arndb.de> > > > Signed-off-by: Anders Roxell <anders.roxell@linaro.org> > > > --- > > > arch/arm64/kernel/ftrace.c | 10 ++++++++++ > > > 1 file changed, 10 insertions(+) > > > > It sounds like you're running into issues with the existing code, but I'd > > like to understand a bit more about exactly what you're seeing. Which part > > of the ftrace patching is proving to be expensive? > > > > The page table manipulation only happens once per module when using PLTs, > > and the cache maintenance is just a single line per patch site without an > > IPI. > > > > Is it the loop in ftrace_replace_code() that is causing the hassle? > > Yes: with an allmodconfig kernel, the ftrace selftest calls ftrace_replace_code > to look >40000 through ftrace_make_call/ftrace_make_nop, and these > end up calling > > static int __kprobes __aarch64_insn_write(void *addr, __le32 insn) > { > void *waddr = addr; > unsigned long flags = 0; > int ret; > > raw_spin_lock_irqsave(&patch_lock, flags); > waddr = patch_map(addr, FIX_TEXT_POKE0); > > ret = probe_kernel_write(waddr, &insn, AARCH64_INSN_SIZE); > > patch_unmap(FIX_TEXT_POKE0); > raw_spin_unlock_irqrestore(&patch_lock, flags); > > return ret; > } > int __kprobes aarch64_insn_patch_text_nosync(void *addr, u32 insn) > { > u32 *tp = addr; > int ret; > > /* A64 instructions must be word aligned */ > if ((uintptr_t)tp & 0x3) > return -EINVAL; > > ret = aarch64_insn_write(tp, insn); > if (ret == 0) > __flush_icache_range((uintptr_t)tp, > (uintptr_t)tp + AARCH64_INSN_SIZE); > > return ret; > } > > which seems to be where the main cost is. This is with inside of > qemu, and with lots of debugging options (in particular > kcov and ubsan) enabled, that make each function call > more expensive. I was thinking more about this. Would something like this work? -- Steve diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c index 8ef9fc226037..42e89397778b 100644 --- a/kernel/trace/ftrace.c +++ b/kernel/trace/ftrace.c @@ -2393,11 +2393,14 @@ void __weak ftrace_replace_code(int enable) { struct dyn_ftrace *rec; struct ftrace_page *pg; + bool schedulable; int failed; if (unlikely(ftrace_disabled)) return; + schedulable = !irqs_disabled() & !preempt_count(); + do_for_each_ftrace_rec(pg, rec) { if (rec->flags & FTRACE_FL_DISABLED) @@ -2409,6 +2412,8 @@ void __weak ftrace_replace_code(int enable) /* Stop processing */ return; } + if (schedulable) + cond_resched(); } while_for_each_ftrace_rec(); }
Hi Steve, Arnd, On Tue, Dec 04, 2018 at 12:50:12AM -0500, Steven Rostedt wrote: > On Mon, 3 Dec 2018 22:51:52 +0100 > Arnd Bergmann <arnd@arndb.de> wrote: > > On Mon, Dec 3, 2018 at 8:22 PM Will Deacon <will.deacon@arm.com> wrote: > > > On Fri, Nov 30, 2018 at 04:09:56PM +0100, Anders Roxell wrote: > > > > Both of those functions end up calling ftrace_modify_code(), which is > > > > expensive because it changes the page tables and flush caches. > > > > Microseconds add up because this is called in a loop for each dyn_ftrace > > > > record, and this triggers the softlockup watchdog unless we let it sleep > > > > occasionally. > > > > Rework so that we call cond_resched() before going into the > > > > ftrace_modify_code() function. > > > > > > > > Co-developed-by: Arnd Bergmann <arnd@arndb.de> > > > > Signed-off-by: Arnd Bergmann <arnd@arndb.de> > > > > Signed-off-by: Anders Roxell <anders.roxell@linaro.org> > > > > --- > > > > arch/arm64/kernel/ftrace.c | 10 ++++++++++ > > > > 1 file changed, 10 insertions(+) > > > > > > It sounds like you're running into issues with the existing code, but I'd > > > like to understand a bit more about exactly what you're seeing. Which part > > > of the ftrace patching is proving to be expensive? > > > > > > The page table manipulation only happens once per module when using PLTs, > > > and the cache maintenance is just a single line per patch site without an > > > IPI. > > > > > > Is it the loop in ftrace_replace_code() that is causing the hassle? > > > > Yes: with an allmodconfig kernel, the ftrace selftest calls ftrace_replace_code > > to look >40000 through ftrace_make_call/ftrace_make_nop, and these > > end up calling Ok, 40000 invocations would do it! > > static int __kprobes __aarch64_insn_write(void *addr, __le32 insn) > > { > > void *waddr = addr; > > unsigned long flags = 0; > > int ret; > > > > raw_spin_lock_irqsave(&patch_lock, flags); > > waddr = patch_map(addr, FIX_TEXT_POKE0); > > > > ret = probe_kernel_write(waddr, &insn, AARCH64_INSN_SIZE); > > > > patch_unmap(FIX_TEXT_POKE0); > > raw_spin_unlock_irqrestore(&patch_lock, flags); > > > > return ret; > > } > > int __kprobes aarch64_insn_patch_text_nosync(void *addr, u32 insn) > > { > > u32 *tp = addr; > > int ret; > > > > /* A64 instructions must be word aligned */ > > if ((uintptr_t)tp & 0x3) > > return -EINVAL; > > > > ret = aarch64_insn_write(tp, insn); > > if (ret == 0) > > __flush_icache_range((uintptr_t)tp, > > (uintptr_t)tp + AARCH64_INSN_SIZE); > > > > return ret; > > } > > > > which seems to be where the main cost is. This is with inside of > > qemu, and with lots of debugging options (in particular > > kcov and ubsan) enabled, that make each function call > > more expensive. > > I was thinking more about this. Would something like this work? > > -- Steve > > diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c > index 8ef9fc226037..42e89397778b 100644 > --- a/kernel/trace/ftrace.c > +++ b/kernel/trace/ftrace.c > @@ -2393,11 +2393,14 @@ void __weak ftrace_replace_code(int enable) > { > struct dyn_ftrace *rec; > struct ftrace_page *pg; > + bool schedulable; > int failed; > > if (unlikely(ftrace_disabled)) > return; > > + schedulable = !irqs_disabled() & !preempt_count(); Looks suspiciously like a bitwise preemptible() to me! > + > do_for_each_ftrace_rec(pg, rec) { > > if (rec->flags & FTRACE_FL_DISABLED) > @@ -2409,6 +2412,8 @@ void __weak ftrace_replace_code(int enable) > /* Stop processing */ > return; > } > + if (schedulable) > + cond_resched(); > } while_for_each_ftrace_rec(); > } If this solves the problem in core code, them I'm all for it. Otherwise, I was thinking of rolling our own ftrace_replace_code() for arm64, but that's going to involve a fair amount of duplication. Will
On Tue, 4 Dec 2018 11:12:43 +0000 Will Deacon <will.deacon@arm.com> wrote: > > diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c > > index 8ef9fc226037..42e89397778b 100644 > > --- a/kernel/trace/ftrace.c > > +++ b/kernel/trace/ftrace.c > > @@ -2393,11 +2393,14 @@ void __weak ftrace_replace_code(int enable) > > { > > struct dyn_ftrace *rec; > > struct ftrace_page *pg; > > + bool schedulable; > > int failed; > > > > if (unlikely(ftrace_disabled)) > > return; > > > > + schedulable = !irqs_disabled() & !preempt_count(); > > Looks suspiciously like a bitwise preemptible() to me! Ah, thanks. Yeah, that should have been &&. But what did you expect. I didn't even compile this ;-) > > > + > > do_for_each_ftrace_rec(pg, rec) { > > > > if (rec->flags & FTRACE_FL_DISABLED) > > @@ -2409,6 +2412,8 @@ void __weak ftrace_replace_code(int enable) > > /* Stop processing */ > > return; > > } > > + if (schedulable) > > + cond_resched(); > > } while_for_each_ftrace_rec(); > > } > > If this solves the problem in core code, them I'm all for it. Otherwise, I > was thinking of rolling our own ftrace_replace_code() for arm64, but that's > going to involve a fair amount of duplication. > If it does, then I'll add it. Or take a patch for it ;-) My main concern is that this can be called from non schedulable context. -- Steve
On Tue, 4 Dec 2018 at 18:26, Steven Rostedt <rostedt@goodmis.org> wrote: > > On Tue, 4 Dec 2018 11:12:43 +0000 > Will Deacon <will.deacon@arm.com> wrote: > > > > diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c > > > index 8ef9fc226037..42e89397778b 100644 > > > --- a/kernel/trace/ftrace.c > > > +++ b/kernel/trace/ftrace.c > > > @@ -2393,11 +2393,14 @@ void __weak ftrace_replace_code(int enable) > > > { > > > struct dyn_ftrace *rec; > > > struct ftrace_page *pg; > > > + bool schedulable; > > > int failed; > > > > > > if (unlikely(ftrace_disabled)) > > > return; > > > > > > + schedulable = !irqs_disabled() & !preempt_count(); > > > > Looks suspiciously like a bitwise preemptible() to me! > > Ah, thanks. Yeah, that should have been &&. But what did you expect. > I didn't even compile this ;-) > > > > > > + > > > do_for_each_ftrace_rec(pg, rec) { > > > > > > if (rec->flags & FTRACE_FL_DISABLED) > > > @@ -2409,6 +2412,8 @@ void __weak ftrace_replace_code(int enable) > > > /* Stop processing */ > > > return; > > > } > > > + if (schedulable) > > > + cond_resched(); > > > } while_for_each_ftrace_rec(); > > > } > > > > If this solves the problem in core code, them I'm all for it. Otherwise, I > > was thinking of rolling our own ftrace_replace_code() for arm64, but that's > > going to involve a fair amount of duplication. > > > > If it does, then I'll add it. Or take a patch for it ;-) I tested your patch. it worked. I'll send a patch shortly. Cheers, Anders
On Tue, 4 Dec 2018 19:07:16 +0100 Anders Roxell <anders.roxell@linaro.org> wrote: > > > > + schedulable = !irqs_disabled() & !preempt_count(); > > > > > > Looks suspiciously like a bitwise preemptible() to me! > > > > Ah, thanks. Yeah, that should have been &&. But what did you expect. > > I didn't even compile this ;-) > > > > If it does, then I'll add it. Or take a patch for it ;-) > > I tested your patch. it worked. > > I'll send a patch shortly. > Thanks. Please add a comment above the schedulable test stating that some archs call this with interrupts or preemption disabled, but other archs don't and this can cause a tremendous unneeded latency. -- Steve
diff --git a/arch/arm64/kernel/ftrace.c b/arch/arm64/kernel/ftrace.c index de1a397d2d3f..9da38da58df7 100644 --- a/arch/arm64/kernel/ftrace.c +++ b/arch/arm64/kernel/ftrace.c @@ -130,6 +130,11 @@ int ftrace_make_call(struct dyn_ftrace *rec, unsigned long addr) old = aarch64_insn_gen_nop(); new = aarch64_insn_gen_branch_imm(pc, addr, AARCH64_INSN_BRANCH_LINK); + /* This function can take a long time when sanitizers are enabled, so + * lets make sure we allow RCU processing. + */ + cond_resched(); + return ftrace_modify_code(pc, old, new, true); } @@ -188,6 +193,11 @@ int ftrace_make_nop(struct module *mod, struct dyn_ftrace *rec, new = aarch64_insn_gen_nop(); + /* This function can take a long time when sanitizers are enabled, so + * lets make sure we allow RCU processing. + */ + cond_resched(); + return ftrace_modify_code(pc, old, new, validate); }