On Tue, Dec 07, 2021 at 01:16:25AM +0800, Boqun Feng wrote:
> 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>
Thank you both! I will add Boqun's Reviewed-by on the next rebase.
Thanx, Paul
> 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
> >
