| Message ID | 20241002051347.4239-3-tatsuya.s2862@gmail.com (mailing list archive) |
|---|---|
| State | Superseded |
| Headers | show |
| Series | [v3] ftrace: Hide a extra entry in stack trace | expand |
On Wed, 2 Oct 2024 14:13:48 +0900 Tatsuya S <tatsuya.s2862@gmail.com> wrote: > A extra entry is shown on stack trace(CONFIG_UNWINDER_ORC=y). > > [003] ..... 110.171589: vfs_write <-__x64_sys_write > [003] ..... 110.171600: <stack trace> > => XXXXXXXXX (Wrong function name) BTW, instead of X'ing it out, can you show what that extra function was. Just saying "Wrong function name" doesn't give me any idea of what happened. > => vfs_write > => ksys_write > => do_syscall_64 > => entry_SYSCALL_64_after_hwframe > > To resolve this, increment skip for __ftrace_trace_stack() in > function_stack_trace_call(). > The reason why skip is incremented for __ftrace_trace_stack() > is because __ftrace_trace_stack() in stack trace is the only function > that wasn't skipped from anywhere. Is that the function that was "wrong"? -- Steve > > Signed-off-by: Tatsuya S <tatsuya.s2862@gmail.com> > --- > V2 -> V3: Changed the place to increment skip number > V1 -> V2: Fixed redundant code > > kernel/trace/trace_functions.c | 24 +++++++++++------------- > 1 file changed, 11 insertions(+), 13 deletions(-) > > diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c > index 3b0cea37e029..27089d8e65d4 100644 > --- a/kernel/trace/trace_functions.c > +++ b/kernel/trace/trace_functions.c > @@ -203,23 +203,21 @@ function_trace_call(unsigned long ip, unsigned long parent_ip, > ftrace_test_recursion_unlock(bit); > } > > -#ifdef CONFIG_UNWINDER_ORC > -/* > - * Skip 2: > - * > - * function_stack_trace_call() > - * ftrace_call() > - */ > -#define STACK_SKIP 2 > -#else > /* > * Skip 3: > - * __trace_stack() > - * function_stack_trace_call() > - * ftrace_call() > + * Skipped functions if CONFIG_UNWINDER_ORC is defined > + * > + * __ftrace_trace_stack() > + * function_stack_trace_call() > + * ftrace_call() > + * > + * Otherwise > + * > + * __trace_stack() > + * function_stack_trace_call() > + * ftrace_call() > */ > #define STACK_SKIP 3 > -#endif > > static void > function_stack_trace_call(unsigned long ip, unsigned long parent_ip,
On 10/2/24 10:56 PM, Steven Rostedt wrote: > On Wed, 2 Oct 2024 14:13:48 +0900 > Tatsuya S <tatsuya.s2862@gmail.com> wrote: > >> A extra entry is shown on stack trace(CONFIG_UNWINDER_ORC=y). >> >> [003] ..... 110.171589: vfs_write <-__x64_sys_write >> [003] ..... 110.171600: <stack trace> >> => XXXXXXXXX (Wrong function name) > > BTW, instead of X'ing it out, can you show what that extra function was. > Just saying "Wrong function name" doesn't give me any idea of what happened. This is changed each shutdown. For example, client_init_data, hidpp_driver_init, rfcomm_init. The same function name was displayed each time if system was not shutdown. And I added "nokaslr" to the kernel command line and boot, got same result. > >> => vfs_write >> => ksys_write >> => do_syscall_64 >> => entry_SYSCALL_64_after_hwframe >> >> To resolve this, increment skip for __ftrace_trace_stack() in >> function_stack_trace_call(). >> The reason why skip is incremented for __ftrace_trace_stack() >> is because __ftrace_trace_stack() in stack trace is the only function >> that wasn't skipped from anywhere. > > Is that the function that was "wrong"? Unrelated? > > -- Steve > >> >> Signed-off-by: Tatsuya S <tatsuya.s2862@gmail.com> >> --- >> V2 -> V3: Changed the place to increment skip number >> V1 -> V2: Fixed redundant code >> >> kernel/trace/trace_functions.c | 24 +++++++++++------------- >> 1 file changed, 11 insertions(+), 13 deletions(-) >> >> diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c >> index 3b0cea37e029..27089d8e65d4 100644 >> --- a/kernel/trace/trace_functions.c >> +++ b/kernel/trace/trace_functions.c >> @@ -203,23 +203,21 @@ function_trace_call(unsigned long ip, unsigned long parent_ip, >> ftrace_test_recursion_unlock(bit); >> } >> >> -#ifdef CONFIG_UNWINDER_ORC >> -/* >> - * Skip 2: >> - * >> - * function_stack_trace_call() >> - * ftrace_call() >> - */ >> -#define STACK_SKIP 2 >> -#else >> /* >> * Skip 3: >> - * __trace_stack() >> - * function_stack_trace_call() >> - * ftrace_call() >> + * Skipped functions if CONFIG_UNWINDER_ORC is defined >> + * >> + * __ftrace_trace_stack() >> + * function_stack_trace_call() >> + * ftrace_call() >> + * >> + * Otherwise >> + * >> + * __trace_stack() >> + * function_stack_trace_call() >> + * ftrace_call() >> */ >> #define STACK_SKIP 3 >> -#endif >> >> static void >> function_stack_trace_call(unsigned long ip, unsigned long parent_ip, > thanks
On Thu, 3 Oct 2024 00:28:28 +0900 Tatsuya S <tatsuya.s2862@gmail.com> wrote: > > Tatsuya S <tatsuya.s2862@gmail.com> wrote: > > > >> A extra entry is shown on stack trace(CONFIG_UNWINDER_ORC=y). > >> > >> [003] ..... 110.171589: vfs_write <-__x64_sys_write > >> [003] ..... 110.171600: <stack trace> > >> => XXXXXXXXX (Wrong function name) > > > > BTW, instead of X'ing it out, can you show what that extra function was. > > Just saying "Wrong function name" doesn't give me any idea of what happened. > This is changed each shutdown. > For example, client_init_data, hidpp_driver_init, rfcomm_init. > > The same function name was displayed each time if system was not shutdown. > > And I added "nokaslr" to the kernel command line and boot, got same result. So I'm trying to understand this part. Where is the function coming from then? The skip is there to skip over the functions that are calling the stack trace. It shouldn't be garbage, as the stack walk shouldn't be giving us that. Now I'm even more curious to what is going wrong. -- Steve
On Wed, 2 Oct 2024 14:13:48 +0900 Tatsuya S <tatsuya.s2862@gmail.com> wrote: > A extra entry is shown on stack trace(CONFIG_UNWINDER_ORC=y). > > [003] ..... 110.171589: vfs_write <-__x64_sys_write > [003] ..... 110.171600: <stack trace> > => XXXXXXXXX (Wrong function name) > => vfs_write > => ksys_write > => do_syscall_64 > => entry_SYSCALL_64_after_hwframe > > To resolve this, increment skip for __ftrace_trace_stack() in > function_stack_trace_call(). > The reason why skip is incremented for __ftrace_trace_stack() > is because __ftrace_trace_stack() in stack trace is the only function > that wasn't skipped from anywhere. Hi Tatsuya, Can you focus on making test cases which checks what combinations caused this wrong values and what does not? Also it should be checked with various kconfigs. That is more valuable than making add-hoc fixes. Thank you, > > Signed-off-by: Tatsuya S <tatsuya.s2862@gmail.com> > --- > V2 -> V3: Changed the place to increment skip number > V1 -> V2: Fixed redundant code > > kernel/trace/trace_functions.c | 24 +++++++++++------------- > 1 file changed, 11 insertions(+), 13 deletions(-) > > diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c > index 3b0cea37e029..27089d8e65d4 100644 > --- a/kernel/trace/trace_functions.c > +++ b/kernel/trace/trace_functions.c > @@ -203,23 +203,21 @@ function_trace_call(unsigned long ip, unsigned long parent_ip, > ftrace_test_recursion_unlock(bit); > } > > -#ifdef CONFIG_UNWINDER_ORC > -/* > - * Skip 2: > - * > - * function_stack_trace_call() > - * ftrace_call() > - */ > -#define STACK_SKIP 2 > -#else > /* > * Skip 3: > - * __trace_stack() > - * function_stack_trace_call() > - * ftrace_call() > + * Skipped functions if CONFIG_UNWINDER_ORC is defined > + * > + * __ftrace_trace_stack() > + * function_stack_trace_call() > + * ftrace_call() > + * > + * Otherwise > + * > + * __trace_stack() > + * function_stack_trace_call() > + * ftrace_call() > */ > #define STACK_SKIP 3 > -#endif > > static void > function_stack_trace_call(unsigned long ip, unsigned long parent_ip, > -- > 2.46.2 >
On 10/4/24 11:17 PM, Masami Hiramatsu (Google) wrote: > On Wed, 2 Oct 2024 14:13:48 +0900 > Tatsuya S <tatsuya.s2862@gmail.com> wrote: > >> A extra entry is shown on stack trace(CONFIG_UNWINDER_ORC=y). >> >> [003] ..... 110.171589: vfs_write <-__x64_sys_write >> [003] ..... 110.171600: <stack trace> >> => XXXXXXXXX (Wrong function name) >> => vfs_write >> => ksys_write >> => do_syscall_64 >> => entry_SYSCALL_64_after_hwframe >> >> To resolve this, increment skip for __ftrace_trace_stack() in >> function_stack_trace_call(). >> The reason why skip is incremented for __ftrace_trace_stack() >> is because __ftrace_trace_stack() in stack trace is the only function >> that wasn't skipped from anywhere. > > Hi Tatsuya, > > Can you focus on making test cases which checks what combinations caused > this wrong values and what does not? Also it should be checked with > various kconfigs. That is more valuable than making add-hoc fixes. > > Thank you, OK, thank you for advise. Curiously, now when test under the same conditions, address(like 0xffffffffa1413099) within trampoline code appears in XXXXXXXXX. Unrelated function name is not displayed now... The following is the script used: echo > trace echo 'vfs_write' > set_ftrace_filter echo function > current_tracer echo 1 > options/func_stack_trace echo 1 > tracing_on read echo 0 > tracing_on cat trace echo nop > current_tracer --- Thanks > >> >> Signed-off-by: Tatsuya S <tatsuya.s2862@gmail.com> >> --- >> V2 -> V3: Changed the place to increment skip number >> V1 -> V2: Fixed redundant code >> >> kernel/trace/trace_functions.c | 24 +++++++++++------------- >> 1 file changed, 11 insertions(+), 13 deletions(-) >> >> diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c >> index 3b0cea37e029..27089d8e65d4 100644 >> --- a/kernel/trace/trace_functions.c >> +++ b/kernel/trace/trace_functions.c >> @@ -203,23 +203,21 @@ function_trace_call(unsigned long ip, unsigned long parent_ip, >> ftrace_test_recursion_unlock(bit); >> } >> >> -#ifdef CONFIG_UNWINDER_ORC >> -/* >> - * Skip 2: >> - * >> - * function_stack_trace_call() >> - * ftrace_call() >> - */ >> -#define STACK_SKIP 2 >> -#else >> /* >> * Skip 3: >> - * __trace_stack() >> - * function_stack_trace_call() >> - * ftrace_call() >> + * Skipped functions if CONFIG_UNWINDER_ORC is defined >> + * >> + * __ftrace_trace_stack() >> + * function_stack_trace_call() >> + * ftrace_call() >> + * >> + * Otherwise >> + * >> + * __trace_stack() >> + * function_stack_trace_call() >> + * ftrace_call() >> */ >> #define STACK_SKIP 3 >> -#endif >> >> static void >> function_stack_trace_call(unsigned long ip, unsigned long parent_ip, >> -- >> 2.46.2 >> > >
diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c index 3b0cea37e029..27089d8e65d4 100644 --- a/kernel/trace/trace_functions.c +++ b/kernel/trace/trace_functions.c @@ -203,23 +203,21 @@ function_trace_call(unsigned long ip, unsigned long parent_ip, ftrace_test_recursion_unlock(bit); } -#ifdef CONFIG_UNWINDER_ORC -/* - * Skip 2: - * - * function_stack_trace_call() - * ftrace_call() - */ -#define STACK_SKIP 2 -#else /* * Skip 3: - * __trace_stack() - * function_stack_trace_call() - * ftrace_call() + * Skipped functions if CONFIG_UNWINDER_ORC is defined + * + * __ftrace_trace_stack() + * function_stack_trace_call() + * ftrace_call() + * + * Otherwise + * + * __trace_stack() + * function_stack_trace_call() + * ftrace_call() */ #define STACK_SKIP 3 -#endif static void function_stack_trace_call(unsigned long ip, unsigned long parent_ip,
A extra entry is shown on stack trace(CONFIG_UNWINDER_ORC=y). [003] ..... 110.171589: vfs_write <-__x64_sys_write [003] ..... 110.171600: <stack trace> => XXXXXXXXX (Wrong function name) => vfs_write => ksys_write => do_syscall_64 => entry_SYSCALL_64_after_hwframe To resolve this, increment skip for __ftrace_trace_stack() in function_stack_trace_call(). The reason why skip is incremented for __ftrace_trace_stack() is because __ftrace_trace_stack() in stack trace is the only function that wasn't skipped from anywhere. Signed-off-by: Tatsuya S <tatsuya.s2862@gmail.com> --- V2 -> V3: Changed the place to increment skip number V1 -> V2: Fixed redundant code kernel/trace/trace_functions.c | 24 +++++++++++------------- 1 file changed, 11 insertions(+), 13 deletions(-)