On Mon, Dec 06, 2021 at 05:04:20PM +0100, Marco Elver wrote:
> On Mon, Dec 06, 2021 at 10:31PM +0800, Boqun Feng wrote:
> [...]
> > Thanks for the explanation, I was missing the swap here. However...
> >
> > > So in your above example you need to swap "reordered to" and the top
> > > frame of the stack trace.
> > >
>
> Apologies, I wasn't entirely precise ... what you say below is correct.
>
> > IIUC, the report for my above example will be:
> >
> > | write (reordered) to 0xaaaa of ...:
> > | foo+0x... // address of the write to A
> > | ...
> > | |
> > | +-> reordered to: foo+0x... // address of the callsite to bar() in foo()
> >
> > , right? Because in replace_stack_entry(), it's not the top frame where
> > the race occurred that gets swapped, it's the frame which belongs to the
> > same function as the original access that gets swapped. In other words,
> > when KCSAN finds the problem, top entries of the calling stack are:
> >
> > [0] bar+0x.. // address of the write to B
> > [1] foo+0x.. // address of the callsite to bar() in foo()
> >
> > after replace_stack_entry(), they changes to:
> >
> > [0] bar+0x.. // address of the write to B
> > skip ->[1] foo+0x.. // address of the write to A
> >
> > , as a result the report won't mention bar() at all.
>
> Correct.
>
> > And I think a better report will be:
> >
> > | write (reordered) to 0xaaaa of ...:
> > | foo+0x... // address of the write to A
> > | ...
> > | |
> > | +-> reordered to: bar+0x... // address of the write to B in bar()
> >
> > because it tells users the exact place the accesses get reordered. That
> > means maybe we want something as below? Not completely tested, but I
> > play with scope checking a bit, seems it gives what I want. Thoughts?
>
> This is problematic because it makes it much harder to actually figure
> out what's going on, given "reordered to" isn't a full stack trace. So
> if you're deep in some call hierarchy, seeing a random "reordered to"
> line is quite useless. What I want to see, at the very least, is the ip
> to the same function where the original access happened.
>
> We could of course try and generate a full stack trace at "reordered
> to", but this would entail
>
> a) allocating 2x unsigned long[64] on the stack (or moving to
> static storage),
> b) further increasing the report length,
> c) an even larger number of possibly distinct reports for the
> same issue; this makes deduplication even harder.
>
> The reason I couldn't justify all that is that when I looked through
> several dozen "reordered to" reports, I never found anything other than
> the ip in the function frame of the original access useful. That, and in
> most cases the "reordered to" location was in the same function or in an
> inlined function.
>
> The below patch would do what you'd want I think.
>
> My opinion is to err on the side of simplicity until there is evidence
> we need it. Of course, if you have a compelling reason that we need it
> from the beginning, happy to send it as a separate patch on top.
>
> What do you think?
>
Totally agreed. It's better to keep it simple until people report that
they want to see more information to resolve the issues. And thanks for
looking into the "double stack traces", that looks good to me too.
For the original patch, feel free to add:
Reviewed-by: Boqun Feng <boqun.feng@xxxxxxxxx>
Regards,
Boqun
> Thanks,
> -- Marco
>
> ------ >8 ------
>
> From: Marco Elver <elver@xxxxxxxxxx>
> Date: Mon, 6 Dec 2021 16:35:02 +0100
> Subject: [PATCH] kcsan: Show full stack trace of reordered-to accesses
>
> Change reports involving reordered accesses to show the full stack trace
> of "reordered to" accesses. For example:
>
> | ==================================================================
> | BUG: KCSAN: data-race in test_kernel_wrong_memorder / test_kernel_wrong_memorder
> |
> | read-write to 0xffffffffc02d01e8 of 8 bytes by task 2481 on cpu 2:
> | test_kernel_wrong_memorder+0x57/0x90
> | access_thread+0xb7/0x100
> | kthread+0x2ed/0x320
> | ret_from_fork+0x22/0x30
> |
> | read-write (reordered) to 0xffffffffc02d01e8 of 8 bytes by task 2480 on cpu 0:
> | test_kernel_wrong_memorder+0x57/0x90
> | access_thread+0xb7/0x100
> | kthread+0x2ed/0x320
> | ret_from_fork+0x22/0x30
> | |
> | +-> reordered to: test_delay+0x31/0x110
> | test_kernel_wrong_memorder+0x80/0x90
> |
> | Reported by Kernel Concurrency Sanitizer on:
> | CPU: 0 PID: 2480 Comm: access_thread Not tainted 5.16.0-rc1+ #2
> | Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
> | ==================================================================
>
> Signed-off-by: Marco Elver <elver@xxxxxxxxxx>
> ---
> kernel/kcsan/report.c | 33 +++++++++++++++++++++++----------
> 1 file changed, 23 insertions(+), 10 deletions(-)
>
> diff --git a/kernel/kcsan/report.c b/kernel/kcsan/report.c
> index 67794404042a..a8317d5f5123 100644
> --- a/kernel/kcsan/report.c
> +++ b/kernel/kcsan/report.c
> @@ -317,22 +317,29 @@ replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned lon
> {
> unsigned long symbolsize, offset;
> unsigned long target_func;
> - int skip;
> + int skip, i;
>
> if (kallsyms_lookup_size_offset(ip, &symbolsize, &offset))
> target_func = ip - offset;
> else
> goto fallback;
>
> - for (skip = 0; skip < num_entries; ++skip) {
> + skip = get_stack_skipnr(stack_entries, num_entries);
> + for (i = 0; skip < num_entries; ++skip, ++i) {
> unsigned long func = stack_entries[skip];
>
> if (!kallsyms_lookup_size_offset(func, &symbolsize, &offset))
> goto fallback;
> func -= offset;
>
> + replaced[i] = stack_entries[skip];
> if (func == target_func) {
> - *replaced = stack_entries[skip];
> + /*
> + * There must be at least 1 entry left in the original
> + * @stack_entries, so we know that we will never occupy
> + * more than @num_entries - 1 of @replaced.
> + */
> + replaced[i + 1] = 0;
> stack_entries[skip] = ip;
> return skip;
> }
> @@ -341,6 +348,7 @@ replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned lon
> fallback:
> /* Should not happen; the resulting stack trace is likely misleading. */
> WARN_ONCE(1, "Cannot find frame for %pS in stack trace", (void *)ip);
> + replaced[0] = 0;
> return get_stack_skipnr(stack_entries, num_entries);
> }
>
> @@ -365,11 +373,16 @@ static int sym_strcmp(void *addr1, void *addr2)
> }
>
> static void
> -print_stack_trace(unsigned long stack_entries[], int num_entries, unsigned long reordered_to)
> +print_stack_trace(unsigned long stack_entries[], int num_entries, unsigned long *reordered_to)
> {
> stack_trace_print(stack_entries, num_entries, 0);
> - if (reordered_to)
> - pr_err(" |\n +-> reordered to: %pS\n", (void *)reordered_to);
> + if (reordered_to[0]) {
> + int i;
> +
> + pr_err(" |\n +-> reordered to: %pS\n", (void *)reordered_to[0]);
> + for (i = 1; i < NUM_STACK_ENTRIES && reordered_to[i]; ++i)
> + pr_err(" %pS\n", (void *)reordered_to[i]);
> + }
> }
>
> static void print_verbose_info(struct task_struct *task)
> @@ -390,12 +403,12 @@ static void print_report(enum kcsan_value_change value_change,
> struct other_info *other_info,
> u64 old, u64 new, u64 mask)
> {
> - unsigned long reordered_to = 0;
> + unsigned long reordered_to[NUM_STACK_ENTRIES] = { 0 };
> unsigned long stack_entries[NUM_STACK_ENTRIES] = { 0 };
> int num_stack_entries = stack_trace_save(stack_entries, NUM_STACK_ENTRIES, 1);
> - int skipnr = sanitize_stack_entries(stack_entries, num_stack_entries, ai->ip, &reordered_to);
> + int skipnr = sanitize_stack_entries(stack_entries, num_stack_entries, ai->ip, reordered_to);
> unsigned long this_frame = stack_entries[skipnr];
> - unsigned long other_reordered_to = 0;
> + unsigned long other_reordered_to[NUM_STACK_ENTRIES] = { 0 };
> unsigned long other_frame = 0;
> int other_skipnr = 0; /* silence uninit warnings */
>
> @@ -408,7 +421,7 @@ static void print_report(enum kcsan_value_change value_change,
> if (other_info) {
> other_skipnr = sanitize_stack_entries(other_info->stack_entries,
> other_info->num_stack_entries,
> - other_info->ai.ip, &other_reordered_to);
> + other_info->ai.ip, other_reordered_to);
> other_frame = other_info->stack_entries[other_skipnr];
>
> /* @value_change is only known for the other thread */
> --
> 2.34.1.400.ga245620fadb-goog
>
