| Message ID | 20211130114433.2580590-9-elver@google.com (mailing list archive) |
|---|---|
| State | New |
| Headers | show |
| Series | kcsan: Support detecting a subset of missing memory barriers | expand |
Hi, On Tue, Nov 30, 2021 at 12:44:16PM +0100, Marco Elver wrote: > Also show the location the access was reordered to. An example report: > > | ================================================================== > | BUG: KCSAN: data-race in test_kernel_wrong_memorder / test_kernel_wrong_memorder > | > | read-write to 0xffffffffc01e61a8 of 8 bytes by task 2311 on cpu 5: > | test_kernel_wrong_memorder+0x57/0x90 > | access_thread+0x99/0xe0 > | kthread+0x2ba/0x2f0 > | ret_from_fork+0x22/0x30 > | > | read-write (reordered) to 0xffffffffc01e61a8 of 8 bytes by task 2310 on cpu 7: > | test_kernel_wrong_memorder+0x57/0x90 > | access_thread+0x99/0xe0 > | kthread+0x2ba/0x2f0 > | ret_from_fork+0x22/0x30 > | | > | +-> reordered to: test_kernel_wrong_memorder+0x80/0x90 > | Should this be "reordered from" instead of "reordered to"? For example, if the following case needs a smp_mb() between write to A and write to B, I think currently it will report as follow: foo() { WRITE_ONCE(A, 1); // let's say A's address is 0xaaaa bar() { WRITE_ONCE(B, 1); // Assume B's address is 0xbbbb // KCSAN find the problem here } } <report> | write (reordered) to 0xaaaa of ...: | bar+0x... // address of the write to B | foo+0x... // address of the callsite to bar() | ... | | | +-> reordered to: foo+0x... // address of the write to A But since the access reported here is the write to A, so it's a "reordered from" instead of "reordered to"? Regards, Boqun > | Reported by Kernel Concurrency Sanitizer on: > | CPU: 7 PID: 2310 Comm: access_thread Not tainted 5.14.0-rc1+ #18 > | Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014 > | ================================================================== > > Signed-off-by: Marco Elver <elver@google.com> > --- > kernel/kcsan/report.c | 35 +++++++++++++++++++++++------------ > 1 file changed, 23 insertions(+), 12 deletions(-) > > diff --git a/kernel/kcsan/report.c b/kernel/kcsan/report.c > index 1b0e050bdf6a..67794404042a 100644 > --- a/kernel/kcsan/report.c > +++ b/kernel/kcsan/report.c > @@ -308,10 +308,12 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries > > /* > * Skips to the first entry that matches the function of @ip, and then replaces > - * that entry with @ip, returning the entries to skip. > + * that entry with @ip, returning the entries to skip with @replaced containing > + * the replaced entry. > */ > static int > -replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned long ip) > +replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned long ip, > + unsigned long *replaced) > { > unsigned long symbolsize, offset; > unsigned long target_func; > @@ -330,6 +332,7 @@ replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned lon > func -= offset; > > if (func == target_func) { > + *replaced = stack_entries[skip]; > stack_entries[skip] = ip; > return skip; > } > @@ -342,9 +345,10 @@ replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned lon > } > > static int > -sanitize_stack_entries(unsigned long stack_entries[], int num_entries, unsigned long ip) > +sanitize_stack_entries(unsigned long stack_entries[], int num_entries, unsigned long ip, > + unsigned long *replaced) > { > - return ip ? replace_stack_entry(stack_entries, num_entries, ip) : > + return ip ? replace_stack_entry(stack_entries, num_entries, ip, replaced) : > get_stack_skipnr(stack_entries, num_entries); > } > > @@ -360,6 +364,14 @@ static int sym_strcmp(void *addr1, void *addr2) > return strncmp(buf1, buf2, sizeof(buf1)); > } > > +static void > +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); > +} > + > static void print_verbose_info(struct task_struct *task) > { > if (!task) > @@ -378,10 +390,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 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); > + 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_frame = 0; > int other_skipnr = 0; /* silence uninit warnings */ > > @@ -394,7 +408,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_info->ai.ip, &other_reordered_to); > other_frame = other_info->stack_entries[other_skipnr]; > > /* @value_change is only known for the other thread */ > @@ -434,10 +448,9 @@ static void print_report(enum kcsan_value_change value_change, > other_info->ai.cpu_id); > > /* Print the other thread's stack trace. */ > - stack_trace_print(other_info->stack_entries + other_skipnr, > + print_stack_trace(other_info->stack_entries + other_skipnr, > other_info->num_stack_entries - other_skipnr, > - 0); > - > + other_reordered_to); > if (IS_ENABLED(CONFIG_KCSAN_VERBOSE)) > print_verbose_info(other_info->task); > > @@ -451,9 +464,7 @@ static void print_report(enum kcsan_value_change value_change, > get_thread_desc(ai->task_pid), ai->cpu_id); > } > /* Print stack trace of this thread. */ > - stack_trace_print(stack_entries + skipnr, num_stack_entries - skipnr, > - 0); > - > + print_stack_trace(stack_entries + skipnr, num_stack_entries - skipnr, reordered_to); > if (IS_ENABLED(CONFIG_KCSAN_VERBOSE)) > print_verbose_info(current); > > -- > 2.34.0.rc2.393.gf8c9666880-goog >
On Mon, 6 Dec 2021 at 06:04, Boqun Feng <boqun.feng@gmail.com> wrote: > > Hi, > > On Tue, Nov 30, 2021 at 12:44:16PM +0100, Marco Elver wrote: > > Also show the location the access was reordered to. An example report: > > > > | ================================================================== > > | BUG: KCSAN: data-race in test_kernel_wrong_memorder / test_kernel_wrong_memorder > > | > > | read-write to 0xffffffffc01e61a8 of 8 bytes by task 2311 on cpu 5: > > | test_kernel_wrong_memorder+0x57/0x90 > > | access_thread+0x99/0xe0 > > | kthread+0x2ba/0x2f0 > > | ret_from_fork+0x22/0x30 > > | > > | read-write (reordered) to 0xffffffffc01e61a8 of 8 bytes by task 2310 on cpu 7: > > | test_kernel_wrong_memorder+0x57/0x90 > > | access_thread+0x99/0xe0 > > | kthread+0x2ba/0x2f0 > > | ret_from_fork+0x22/0x30 > > | | > > | +-> reordered to: test_kernel_wrong_memorder+0x80/0x90 > > | > > Should this be "reordered from" instead of "reordered to"? For example, > if the following case needs a smp_mb() between write to A and write to > B, I think currently it will report as follow: > > foo() { > WRITE_ONCE(A, 1); // let's say A's address is 0xaaaa > bar() { > WRITE_ONCE(B, 1); // Assume B's address is 0xbbbb > // KCSAN find the problem here > } > } > > <report> > | write (reordered) to 0xaaaa of ...: > | bar+0x... // address of the write to B > | foo+0x... // address of the callsite to bar() > | ... > | | > | +-> reordered to: foo+0x... // address of the write to A > > But since the access reported here is the write to A, so it's a > "reordered from" instead of "reordered to"? Perhaps I could have commented on this in the commit message to avoid the confusion, but per its updated comment replace_stack_entry() "skips to the first entry that matches the function of @ip, and then replaces that entry with @ip, returning the entries to skip with @replaced containing the replaced entry." When a reorder_access is set up, the ip to it is stored, which is what's passed to @ip of replace_stack_entry(). It effectively swaps the top frame where the race occurred with where the original access happened. This all works because the runtime is careful to only keep reorder_accesses valid until the original function where it occurred is left. So in your above example you need to swap "reordered to" and the top frame of the stack trace. The implementation is a little trickier of course, but I really wanted the main stack trace to look like any other non-reordered access, which starts from the original access, and only have the "reordered to" location be secondary information. The foundation for doing this this was put in place here: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=6c65eb75686f Thanks, -- Marco
On Mon, Dec 06, 2021 at 08:16:11AM +0100, Marco Elver wrote: > On Mon, 6 Dec 2021 at 06:04, Boqun Feng <boqun.feng@gmail.com> wrote: > > > > Hi, > > > > On Tue, Nov 30, 2021 at 12:44:16PM +0100, Marco Elver wrote: > > > Also show the location the access was reordered to. An example report: > > > > > > | ================================================================== > > > | BUG: KCSAN: data-race in test_kernel_wrong_memorder / test_kernel_wrong_memorder > > > | > > > | read-write to 0xffffffffc01e61a8 of 8 bytes by task 2311 on cpu 5: > > > | test_kernel_wrong_memorder+0x57/0x90 > > > | access_thread+0x99/0xe0 > > > | kthread+0x2ba/0x2f0 > > > | ret_from_fork+0x22/0x30 > > > | > > > | read-write (reordered) to 0xffffffffc01e61a8 of 8 bytes by task 2310 on cpu 7: > > > | test_kernel_wrong_memorder+0x57/0x90 > > > | access_thread+0x99/0xe0 > > > | kthread+0x2ba/0x2f0 > > > | ret_from_fork+0x22/0x30 > > > | | > > > | +-> reordered to: test_kernel_wrong_memorder+0x80/0x90 > > > | > > > > Should this be "reordered from" instead of "reordered to"? For example, > > if the following case needs a smp_mb() between write to A and write to > > B, I think currently it will report as follow: > > > > foo() { > > WRITE_ONCE(A, 1); // let's say A's address is 0xaaaa > > bar() { > > WRITE_ONCE(B, 1); // Assume B's address is 0xbbbb > > // KCSAN find the problem here > > } > > } > > > > <report> > > | write (reordered) to 0xaaaa of ...: > > | bar+0x... // address of the write to B > > | foo+0x... // address of the callsite to bar() > > | ... > > | | > > | +-> reordered to: foo+0x... // address of the write to A > > > > But since the access reported here is the write to A, so it's a > > "reordered from" instead of "reordered to"? > > Perhaps I could have commented on this in the commit message to avoid > the confusion, but per its updated comment replace_stack_entry() > "skips to the first entry that matches the function of @ip, and then > replaces that entry with @ip, returning the entries to skip with > @replaced containing the replaced entry." > > When a reorder_access is set up, the ip to it is stored, which is > what's passed to @ip of replace_stack_entry(). It effectively swaps > the top frame where the race occurred with where the original access > happened. This all works because the runtime is careful to only keep > reorder_accesses valid until the original function where it occurred > is left. > 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. > 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. 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? Regards, Boqun diff --git a/kernel/kcsan/report.c b/kernel/kcsan/report.c index 67794404042a..b495ed3aa637 100644 --- a/kernel/kcsan/report.c +++ b/kernel/kcsan/report.c @@ -324,7 +324,10 @@ replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned lon else goto fallback; - for (skip = 0; skip < num_entries; ++skip) { + skip = get_stack_skipnr(stack_entries, num_entries); + *replaced = stack_entries[skip]; + + for (;skip < num_entries; ++skip) { unsigned long func = stack_entries[skip]; if (!kallsyms_lookup_size_offset(func, &symbolsize, &offset)) @@ -332,7 +335,6 @@ replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned lon func -= offset; if (func == target_func) { - *replaced = stack_entries[skip]; stack_entries[skip] = ip; return skip; } > The implementation is a little trickier of course, but I really wanted > the main stack trace to look like any other non-reordered access, > which starts from the original access, and only have the "reordered > to" location be secondary information. > > The foundation for doing this this was put in place here: > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=6c65eb75686f > > Thanks, > -- Marco
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? Thanks, -- Marco ------ >8 ------ From: Marco Elver <elver@google.com> 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@google.com> --- 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 */
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@gmail.com> Regards, Boqun > Thanks, > -- Marco > > ------ >8 ------ > > From: Marco Elver <elver@google.com> > 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@google.com> > --- > 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 >
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@gmail.com> 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@google.com> > > 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@google.com> > > --- > > 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 > >
diff --git a/kernel/kcsan/report.c b/kernel/kcsan/report.c index 1b0e050bdf6a..67794404042a 100644 --- a/kernel/kcsan/report.c +++ b/kernel/kcsan/report.c @@ -308,10 +308,12 @@ static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries /* * Skips to the first entry that matches the function of @ip, and then replaces - * that entry with @ip, returning the entries to skip. + * that entry with @ip, returning the entries to skip with @replaced containing + * the replaced entry. */ static int -replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned long ip) +replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned long ip, + unsigned long *replaced) { unsigned long symbolsize, offset; unsigned long target_func; @@ -330,6 +332,7 @@ replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned lon func -= offset; if (func == target_func) { + *replaced = stack_entries[skip]; stack_entries[skip] = ip; return skip; } @@ -342,9 +345,10 @@ replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned lon } static int -sanitize_stack_entries(unsigned long stack_entries[], int num_entries, unsigned long ip) +sanitize_stack_entries(unsigned long stack_entries[], int num_entries, unsigned long ip, + unsigned long *replaced) { - return ip ? replace_stack_entry(stack_entries, num_entries, ip) : + return ip ? replace_stack_entry(stack_entries, num_entries, ip, replaced) : get_stack_skipnr(stack_entries, num_entries); } @@ -360,6 +364,14 @@ static int sym_strcmp(void *addr1, void *addr2) return strncmp(buf1, buf2, sizeof(buf1)); } +static void +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); +} + static void print_verbose_info(struct task_struct *task) { if (!task) @@ -378,10 +390,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 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); + 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_frame = 0; int other_skipnr = 0; /* silence uninit warnings */ @@ -394,7 +408,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_info->ai.ip, &other_reordered_to); other_frame = other_info->stack_entries[other_skipnr]; /* @value_change is only known for the other thread */ @@ -434,10 +448,9 @@ static void print_report(enum kcsan_value_change value_change, other_info->ai.cpu_id); /* Print the other thread's stack trace. */ - stack_trace_print(other_info->stack_entries + other_skipnr, + print_stack_trace(other_info->stack_entries + other_skipnr, other_info->num_stack_entries - other_skipnr, - 0); - + other_reordered_to); if (IS_ENABLED(CONFIG_KCSAN_VERBOSE)) print_verbose_info(other_info->task); @@ -451,9 +464,7 @@ static void print_report(enum kcsan_value_change value_change, get_thread_desc(ai->task_pid), ai->cpu_id); } /* Print stack trace of this thread. */ - stack_trace_print(stack_entries + skipnr, num_stack_entries - skipnr, - 0); - + print_stack_trace(stack_entries + skipnr, num_stack_entries - skipnr, reordered_to); if (IS_ENABLED(CONFIG_KCSAN_VERBOSE)) print_verbose_info(current);
Also show the location the access was reordered to. An example report: | ================================================================== | BUG: KCSAN: data-race in test_kernel_wrong_memorder / test_kernel_wrong_memorder | | read-write to 0xffffffffc01e61a8 of 8 bytes by task 2311 on cpu 5: | test_kernel_wrong_memorder+0x57/0x90 | access_thread+0x99/0xe0 | kthread+0x2ba/0x2f0 | ret_from_fork+0x22/0x30 | | read-write (reordered) to 0xffffffffc01e61a8 of 8 bytes by task 2310 on cpu 7: | test_kernel_wrong_memorder+0x57/0x90 | access_thread+0x99/0xe0 | kthread+0x2ba/0x2f0 | ret_from_fork+0x22/0x30 | | | +-> reordered to: test_kernel_wrong_memorder+0x80/0x90 | | Reported by Kernel Concurrency Sanitizer on: | CPU: 7 PID: 2310 Comm: access_thread Not tainted 5.14.0-rc1+ #18 | Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014 | ================================================================== Signed-off-by: Marco Elver <elver@google.com> --- kernel/kcsan/report.c | 35 +++++++++++++++++++++++------------ 1 file changed, 23 insertions(+), 12 deletions(-)