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.
On Wed, 31 Mar 2021 13:52:45 +0200
Vasily Gorbik <[email protected]> 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);
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 <[email protected]>
On Wed, 31 Mar 2021 22:51:15 +0200
Vasily Gorbik <[email protected]> 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 <[email protected]>
Want to give a "tested-by" too?
-- Steve
On Wed, Mar 31, 2021 at 05:09:00PM -0400, Steven Rostedt wrote:
> On Wed, 31 Mar 2021 22:51:15 +0200
> Vasily Gorbik <[email protected]> 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 <[email protected]>
>
> 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 <[email protected]> # s390 only
On Thu, 1 Apr 2021 00:02:57 +0200
Vasily Gorbik <[email protected]> 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 <[email protected]> # s390 only
Thanks,
-- Steve