Re: [PATCH v3 08/25] kcsan: Show location access was reordered to

[Boqun Feng <boqun.feng@gmail.com>]

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
>