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(-)

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 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
> 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>

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
>>
> 
>

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