User stacktrace garbage when USER_STACKTRACE_SUPPORT is not enabled

User stacktrace garbage when USER_STACKTRACE_SUPPORT is not enabled

[Vasily Gorbik]

Hi Steven,

At least on s390 since commit cbc3b92ce037 ("tracing: Set kernel_stack's
caller size properly") kernel stack trace contains 8 garbage values in the end.
I assume those are supposed to be filled by ftrace_trace_userstack, which is
only implemented on x86.

            sshd-804   [050]  1997.252608: kernel_stack:         <stack trace>
=> trampoline_probe_handler (549628c94)
=> kprobe_handler (549629260)
=> kprobe_exceptions_notify (549629370)
=> notify_die (549686e5e)
=> illegal_op (54960d440)
=> __do_pgm_check (54a106b08)
=> pgm_check_handler (54a112cc8)
=> kretprobe_trampoline (549629438)
=> kretprobe_trampoline (549629436)
=> do_syscall (549611ee6)
=> __do_syscall (54a106ccc)
=> system_call (54a112b5a)
=> 769010000000322
=> 22125e4d8
=> 22125e8f8
=> e000054100040100
=> _end (3220000000c)
=> 2
=> 20f892ec00000002
=> 20f898b800000002

kernel/trace/trace_entries.h:
159 #define FTRACE_STACK_ENTRIES    8
160
161 FTRACE_ENTRY(kernel_stack, stack_entry,
162
163         TRACE_STACK,
164
165         F_STRUCT(
166                 __field(        int,            size    )
167                 __array(        unsigned long,  caller, FTRACE_STACK_ENTRIES    )
168         ),

Is there any reason to keep those 8 extra values in the caller array if
CONFIG_USER_STACKTRACE_SUPPORT is not enabled? Any advice how to fix that
gracefully? It seems to work if I simply set FTRACE_STACK_ENTRIES to 0 when
CONFIG_USER_STACKTRACE_SUPPORT is not enabled.

Re: User stacktrace garbage when USER_STACKTRACE_SUPPORT is not enabled

[Steven Rostedt]

On Wed, 31 Mar 2021 13:52:45 +0200
Vasily Gorbik <gor@linux.ibm.com> wrote:

> Hi Steven,
> 
> At least on s390 since commit cbc3b92ce037 ("tracing: Set kernel_stack's
> caller size properly") kernel stack trace contains 8 garbage values in the end.
> I assume those are supposed to be filled by ftrace_trace_userstack, which is
> only implemented on x86.

You assume wrong ;-)

No, the kernel_stack trace does not do anything for user stack unless the
architecture does something with it, and x86 does not do anything with it
when running kernel stack.


> 
>             sshd-804   [050]  1997.252608: kernel_stack:         <stack trace>
> => trampoline_probe_handler (549628c94)
> => kprobe_handler (549629260)
> => kprobe_exceptions_notify (549629370)
> => notify_die (549686e5e)
> => illegal_op (54960d440)
> => __do_pgm_check (54a106b08)
> => pgm_check_handler (54a112cc8)
> => kretprobe_trampoline (549629438)
> => kretprobe_trampoline (549629436)
> => do_syscall (549611ee6)
> => __do_syscall (54a106ccc)
> => system_call (54a112b5a)
> => 769010000000322
> => 22125e4d8
> => 22125e8f8
> => e000054100040100
> => _end (3220000000c)
> => 2
> => 20f892ec00000002
> => 20f898b800000002  
> 
> kernel/trace/trace_entries.h:
> 159 #define FTRACE_STACK_ENTRIES    8
> 160
> 161 FTRACE_ENTRY(kernel_stack, stack_entry,
> 162
> 163         TRACE_STACK,
> 164
> 165         F_STRUCT(
> 166                 __field(        int,            size    )
> 167                 __array(        unsigned long,  caller, FTRACE_STACK_ENTRIES    )
> 168         ),
> 
> Is there any reason to keep those 8 extra values in the caller array if
> CONFIG_USER_STACKTRACE_SUPPORT is not enabled? Any advice how to fix that
> gracefully? It seems to work if I simply set FTRACE_STACK_ENTRIES to 0 when
> CONFIG_USER_STACKTRACE_SUPPORT is not enabled.

Note, the above is just a holder for user space parsing. It plays no role
in how the kernel reports the data from the /sys/kernel/tracing/trace file.

Here's the code that does the actual work (from kernel/tracing/trace.c)

	fstack = this_cpu_ptr(ftrace_stacks.stacks) + stackidx;
	size = ARRAY_SIZE(fstack->calls);

	if (regs) {
		nr_entries = stack_trace_save_regs(regs, fstack->calls,
						   size, skip);
	} else {
		nr_entries = stack_trace_save(fstack->calls, size, skip);
	}

	size = nr_entries * sizeof(unsigned long);
	event = __trace_buffer_lock_reserve(buffer, TRACE_STACK,
					    sizeof(*entry) + size, trace_ctx);
	if (!event)
		goto out;
	entry = ring_buffer_event_data(event);

	memcpy(&entry->caller, fstack->calls, size);
	entry->size = nr_entries;

ftrace_stacks.stacks is a per cpu variable of size PAGE_SIZE and divided by
4, so it can be used in normal, softirq, interrupt and NMI context.
Depending on if regs is passed in (and I'll assume it is not here), then
stack_trace_save() is called. Which looks like this:

unsigned int stack_trace_save(unsigned long *store, unsigned int size,
			      unsigned int skipnr)
{
	stack_trace_consume_fn consume_entry = stack_trace_consume_entry;
	struct stacktrace_cookie c = {
		.store	= store,
		.size	= size,
		.skip	= skipnr + 1,
	};

	arch_stack_walk(consume_entry, &c, current, NULL);
	return c.len;
}

arch_stack_walk() is arch specific, and it does whatever s390 does for
stack walks, and the number of entries is returned by c.len, and that value
determines what is seen.

But after writing all of the above, I think I found a bug! It's this:

	size = nr_entries * sizeof(unsigned long);
	event = __trace_buffer_lock_reserve(buffer, TRACE_STACK,
					    sizeof(*entry) + size, trace_ctx);


I said the above commit did not play a role in output, but it does play a
role in creating the struct stack_trace entry. And by making it a fixed
array (even though it's not used) it added 8 more entries to the stack!

This should fix the problem:

-- Steve

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 3c605957bb5c..507a30bf26e4 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2985,7 +2985,8 @@ static void __ftrace_trace_stack(struct trace_buffer *buffer,
 
 	size = nr_entries * sizeof(unsigned long);
 	event = __trace_buffer_lock_reserve(buffer, TRACE_STACK,
-					    sizeof(*entry) + size, trace_ctx);
+				    (sizeof(*entry) - sizeof(entry->caller)) + size,
+				    trace_ctx);
 	if (!event)
 		goto out;
 	entry = ring_buffer_event_data(event);

Re: User stacktrace garbage when USER_STACKTRACE_SUPPORT is not enabled

[Vasily Gorbik]

On Wed, Mar 31, 2021 at 10:37:49AM -0400, Steven Rostedt wrote:
> But after writing all of the above, I think I found a bug! It's this:
> 
> 	size = nr_entries * sizeof(unsigned long);
> 	event = __trace_buffer_lock_reserve(buffer, TRACE_STACK,
> 					    sizeof(*entry) + size, trace_ctx);
> 
> 
> I said the above commit did not play a role in output, but it does play a
> role in creating the struct stack_trace entry. And by making it a fixed
> array (even though it's not used) it added 8 more entries to the stack!
> 
> This should fix the problem:
> 
> -- Steve
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 3c605957bb5c..507a30bf26e4 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -2985,7 +2985,8 @@ static void __ftrace_trace_stack(struct trace_buffer *buffer,
>  
>  	size = nr_entries * sizeof(unsigned long);
>  	event = __trace_buffer_lock_reserve(buffer, TRACE_STACK,
> -					    sizeof(*entry) + size, trace_ctx);
> +				    (sizeof(*entry) - sizeof(entry->caller)) + size,
> +				    trace_ctx);
>  	if (!event)
>  		goto out;
>  	entry = ring_buffer_event_data(event);

It does! Thanks for the explanation and for the fix. I wonder why nobody
noticed and complained about that since v5.6.

Acked-by: Vasily Gorbik <gor@linux.ibm.com>

Re: User stacktrace garbage when USER_STACKTRACE_SUPPORT is not enabled

[Steven Rostedt]

On Wed, 31 Mar 2021 22:51:15 +0200
Vasily Gorbik <gor@linux.ibm.com> wrote:

> It does! Thanks for the explanation and for the fix. I wonder why nobody
> noticed and complained about that since v5.6.

Because it didn't lose data, just added extra junk.

> 
> Acked-by: Vasily Gorbik <gor@linux.ibm.com>

Want to give a "tested-by" too?

-- Steve

Re: User stacktrace garbage when USER_STACKTRACE_SUPPORT is not enabled

[Vasily Gorbik]

On Wed, Mar 31, 2021 at 05:09:00PM -0400, Steven Rostedt wrote:
> On Wed, 31 Mar 2021 22:51:15 +0200
> Vasily Gorbik <gor@linux.ibm.com> wrote:
> 
> > It does! Thanks for the explanation and for the fix. I wonder why nobody
> > noticed and complained about that since v5.6.
> 
> Because it didn't lose data, just added extra junk.
> 
> > 
> > Acked-by: Vasily Gorbik <gor@linux.ibm.com>
> 
> Want to give a "tested-by" too?

I only tested it on s390 (manually + ftrace selftest), quite frankly.
If it qualifies:

Tested-by: Vasily Gorbik <gor@linux.ibm.com> # s390 only

Re: User stacktrace garbage when USER_STACKTRACE_SUPPORT is not enabled

[Steven Rostedt]

On Thu, 1 Apr 2021 00:02:57 +0200
Vasily Gorbik <gor@linux.ibm.com> wrote:

> I only tested it on s390 (manually + ftrace selftest), quite frankly.
> If it qualifies:

You reported the bug, thus tested-by from the reporter always
qualifies ;-)


> 
> Tested-by: Vasily Gorbik <gor@linux.ibm.com> # s390 only

Thanks,

-- Steve