linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
From: "Paul E. McKenney" <paulmck@kernel.org>
To: linux-kernel@vger.kernel.org, kasan-dev@googlegroups.com,
	kernel-team@fb.com, mingo@kernel.org
Cc: elver@google.com, andreyknvl@google.com, glider@google.com,
	dvyukov@google.com, cai@lca.pw, boqun.feng@gmail.com,
	Mark Rutland <mark.rutland@arm.com>,
	"Paul E . McKenney" <paulmck@kernel.org>
Subject: [PATCH tip/core/rcu 09/10] kcsan: Report observed value changes
Date: Tue, 11 May 2021 16:24:00 -0700	[thread overview]
Message-ID: <20210511232401.2896217-9-paulmck@kernel.org> (raw)
In-Reply-To: <20210511231149.GA2895263@paulmck-ThinkPad-P17-Gen-1>

From: Mark Rutland <mark.rutland@arm.com>

When a thread detects that a memory location was modified without its
watchpoint being hit, the report notes that a change was detected, but
does not provide concrete values for the change. Knowing the concrete
values can be very helpful in tracking down any racy writers (e.g. as
specific values may only be written in some portions of code, or under
certain conditions).

When we detect a modification, let's report the concrete old/new values,
along with the access's mask of relevant bits (and which relevant bits
were modified). This can make it easier to identify potential racy
writers. As the snapshots are at most 8 bytes, we can only report values
for acceses up to this size, but this appears to cater for the common
case.

When we detect a race via a watchpoint, we may or may not have concrete
values for the modification. To be helpful, let's attempt to log them
when we do as they can be ignored where irrelevant.

The resulting reports appears as follows, with values zero-padded to the
access width:

| ==================================================================
| BUG: KCSAN: data-race in el0_svc_common+0x34/0x25c arch/arm64/kernel/syscall.c:96
|
| race at unknown origin, with read to 0xffff00007ae6aa00 of 8 bytes by task 223 on cpu 1:
|  el0_svc_common+0x34/0x25c arch/arm64/kernel/syscall.c:96
|  do_el0_svc+0x48/0xec arch/arm64/kernel/syscall.c:178
|  el0_svc arch/arm64/kernel/entry-common.c:226 [inline]
|  el0_sync_handler+0x1a4/0x390 arch/arm64/kernel/entry-common.c:236
|  el0_sync+0x140/0x180 arch/arm64/kernel/entry.S:674
|
| value changed: 0x0000000000000000 -> 0x0000000000000002
|
| Reported by Kernel Concurrency Sanitizer on:
| CPU: 1 PID: 223 Comm: syz-executor.1 Not tainted 5.8.0-rc3-00094-ga73f923ecc8e-dirty #3
| Hardware name: linux,dummy-virt (DT)
| ==================================================================

If an access mask is set, it is shown underneath the "value changed"
line as "bits changed: 0x<bits changed> with mask 0x<non-zero mask>".

Signed-off-by: Mark Rutland <mark.rutland@arm.com>
[ elver@google.com: align "value changed" and "bits changed" lines,
  which required massaging the message; do not print bits+mask if no
  mask set. ]
Signed-off-by: Marco Elver <elver@google.com>
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
---
 kernel/kcsan/core.c   |  5 +++--
 kernel/kcsan/kcsan.h  |  6 ++++--
 kernel/kcsan/report.c | 31 ++++++++++++++++++++++++++-----
 3 files changed, 33 insertions(+), 9 deletions(-)

diff --git a/kernel/kcsan/core.c b/kernel/kcsan/core.c
index 6fe1513e1e6a..26709ea65c71 100644
--- a/kernel/kcsan/core.c
+++ b/kernel/kcsan/core.c
@@ -557,7 +557,8 @@ kcsan_setup_watchpoint(const volatile void *ptr, size_t size, int type)
 			atomic_long_inc(&kcsan_counters[KCSAN_COUNTER_ASSERT_FAILURES]);
 
 		kcsan_report_known_origin(ptr, size, type, value_change,
-					  watchpoint - watchpoints);
+					  watchpoint - watchpoints,
+					  old, new, access_mask);
 	} else if (value_change == KCSAN_VALUE_CHANGE_TRUE) {
 		/* Inferring a race, since the value should not have changed. */
 
@@ -566,7 +567,7 @@ kcsan_setup_watchpoint(const volatile void *ptr, size_t size, int type)
 			atomic_long_inc(&kcsan_counters[KCSAN_COUNTER_ASSERT_FAILURES]);
 
 		if (IS_ENABLED(CONFIG_KCSAN_REPORT_RACE_UNKNOWN_ORIGIN) || is_assert)
-			kcsan_report_unknown_origin(ptr, size, type);
+			kcsan_report_unknown_origin(ptr, size, type, old, new, access_mask);
 	}
 
 	/*
diff --git a/kernel/kcsan/kcsan.h b/kernel/kcsan/kcsan.h
index 572f119a19eb..f36e25c497ed 100644
--- a/kernel/kcsan/kcsan.h
+++ b/kernel/kcsan/kcsan.h
@@ -129,12 +129,14 @@ void kcsan_report_set_info(const volatile void *ptr, size_t size, int access_typ
  * thread.
  */
 void kcsan_report_known_origin(const volatile void *ptr, size_t size, int access_type,
-			       enum kcsan_value_change value_change, int watchpoint_idx);
+			       enum kcsan_value_change value_change, int watchpoint_idx,
+			       u64 old, u64 new, u64 mask);
 
 /*
  * No other thread was observed to race with the access, but the data value
  * before and after the stall differs. Reports a race of "unknown origin".
  */
-void kcsan_report_unknown_origin(const volatile void *ptr, size_t size, int access_type);
+void kcsan_report_unknown_origin(const volatile void *ptr, size_t size, int access_type,
+				 u64 old, u64 new, u64 mask);
 
 #endif /* _KERNEL_KCSAN_KCSAN_H */
diff --git a/kernel/kcsan/report.c b/kernel/kcsan/report.c
index 50cee2357885..e37e4386f86d 100644
--- a/kernel/kcsan/report.c
+++ b/kernel/kcsan/report.c
@@ -327,7 +327,8 @@ static void print_verbose_info(struct task_struct *task)
 
 static void print_report(enum kcsan_value_change value_change,
 			 const struct access_info *ai,
-			 const struct other_info *other_info)
+			 const struct other_info *other_info,
+			 u64 old, u64 new, u64 mask)
 {
 	unsigned long stack_entries[NUM_STACK_ENTRIES] = { 0 };
 	int num_stack_entries = stack_trace_save(stack_entries, NUM_STACK_ENTRIES, 1);
@@ -407,6 +408,24 @@ static void print_report(enum kcsan_value_change value_change,
 	if (IS_ENABLED(CONFIG_KCSAN_VERBOSE))
 		print_verbose_info(current);
 
+	/* Print observed value change. */
+	if (ai->size <= 8) {
+		int hex_len = ai->size * 2;
+		u64 diff = old ^ new;
+
+		if (mask)
+			diff &= mask;
+		if (diff) {
+			pr_err("\n");
+			pr_err("value changed: 0x%0*llx -> 0x%0*llx\n",
+			       hex_len, old, hex_len, new);
+			if (mask) {
+				pr_err(" bits changed: 0x%0*llx with mask 0x%0*llx\n",
+				       hex_len, diff, hex_len, mask);
+			}
+		}
+	}
+
 	/* Print report footer. */
 	pr_err("\n");
 	pr_err("Reported by Kernel Concurrency Sanitizer on:\n");
@@ -584,7 +603,8 @@ void kcsan_report_set_info(const volatile void *ptr, size_t size, int access_typ
 }
 
 void kcsan_report_known_origin(const volatile void *ptr, size_t size, int access_type,
-			       enum kcsan_value_change value_change, int watchpoint_idx)
+			       enum kcsan_value_change value_change, int watchpoint_idx,
+			       u64 old, u64 new, u64 mask)
 {
 	const struct access_info ai = prepare_access_info(ptr, size, access_type);
 	struct other_info *other_info = &other_infos[watchpoint_idx];
@@ -608,7 +628,7 @@ void kcsan_report_known_origin(const volatile void *ptr, size_t size, int access
 	 * be done once we know the full stack trace in print_report().
 	 */
 	if (value_change != KCSAN_VALUE_CHANGE_FALSE)
-		print_report(value_change, &ai, other_info);
+		print_report(value_change, &ai, other_info, old, new, mask);
 
 	release_report(&flags, other_info);
 out:
@@ -616,7 +636,8 @@ void kcsan_report_known_origin(const volatile void *ptr, size_t size, int access
 	kcsan_enable_current();
 }
 
-void kcsan_report_unknown_origin(const volatile void *ptr, size_t size, int access_type)
+void kcsan_report_unknown_origin(const volatile void *ptr, size_t size, int access_type,
+				 u64 old, u64 new, u64 mask)
 {
 	const struct access_info ai = prepare_access_info(ptr, size, access_type);
 	unsigned long flags;
@@ -625,7 +646,7 @@ void kcsan_report_unknown_origin(const volatile void *ptr, size_t size, int acce
 	lockdep_off(); /* See kcsan_report_known_origin(). */
 
 	raw_spin_lock_irqsave(&report_lock, flags);
-	print_report(KCSAN_VALUE_CHANGE_TRUE, &ai, NULL);
+	print_report(KCSAN_VALUE_CHANGE_TRUE, &ai, NULL, old, new, mask);
 	raw_spin_unlock_irqrestore(&report_lock, flags);
 
 	lockdep_on();
-- 
2.31.1.189.g2e36527f23


  parent reply	other threads:[~2021-05-11 23:24 UTC|newest]

Thread overview: 40+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2021-05-11 23:11 [PATCH tip/core/rcu 0/26] Torture-test updates for v5.14 Paul E. McKenney
2021-05-11 23:11 ` [PATCH tip/core/rcu 01/26] torture: Fix remaining erroneous torture.sh instance of $* Paul E. McKenney
2021-05-11 23:11 ` [PATCH tip/core/rcu 02/26] torture: Add "scenarios" option to kvm.sh --dryrun parameter Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 03/26] torture: Make kvm-again.sh use "scenarios" rather than "batches" file Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 04/26] refscale: Allow CPU hotplug to be enabled Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 05/26] rcuscale: " Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 06/26] torture: Add kvm-remote.sh script for distributed rcutorture test runs Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 07/26] refscale: Add acqrel, lock, and lock-irq Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 08/26] rcutorture: Abstract read-lock-held checks Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 09/26] torture: Fix grace-period rate output Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 10/26] torture: Abstract end-of-run summary Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 11/26] torture: Make kvm.sh use abstracted kvm-end-run-stats.sh Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 12/26] torture: Make the build machine control N in "make -jN" Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 13/26] torture: Make kvm-find-errors.sh account for kvm-remote.sh Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 14/26] rcutorture: Judge RCU priority boosting on grace periods, not callbacks Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 15/26] torture: Correctly fetch number of CPUs for non-English languages Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 16/26] torture: Set kvm.sh language to English Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 17/26] rcutorture: Delay-based false positives for RCU priority boosting tests Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 18/26] rcutorture: Consolidate rcu_torture_boost() timing and statistics Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 19/26] rcutorture: Make rcu_torture_boost_failed() check for GP end Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 20/26] rcutorture: Add BUSTED-BOOST to test RCU priority boosting tests Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 21/26] rcutorture: Forgive RCU boost failures when CPUs don't pass through QS Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 22/26] rcutorture: Don't count CPU-stalled time against priority boosting Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 23/26] torture: Make kvm-remote.sh account for network failure in pathname checks Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 24/26] torture: Don't cap remote runs by build-system number of CPUs Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 25/26] rcutorture: Move mem_dump_obj() tests into separate function Paul E. McKenney
2021-05-11 23:12 ` [PATCH tip/core/rcu 26/26] rcu: Don't penalize priority boosting when there is nothing to boost Paul E. McKenney
2021-05-11 23:23 ` [PATCH tip/core/rcu 01/10] kcsan: Add pointer to access-marking.txt to data_race() bullet Paul E. McKenney
2021-05-13 10:47   ` Akira Yokosawa
2021-05-13 10:53     ` Marco Elver
2021-05-13 17:50       ` Paul E. McKenney
2021-05-11 23:23 ` [PATCH tip/core/rcu 02/10] kcsan: Simplify value change detection Paul E. McKenney
2021-05-11 23:23 ` [PATCH tip/core/rcu 03/10] kcsan: Distinguish kcsan_report() calls Paul E. McKenney
2021-05-11 23:23 ` [PATCH tip/core/rcu 04/10] kcsan: Refactor passing watchpoint/other_info Paul E. McKenney
2021-05-11 23:23 ` [PATCH tip/core/rcu 05/10] kcsan: Fold panic() call into print_report() Paul E. McKenney
2021-05-11 23:23 ` [PATCH tip/core/rcu 06/10] kcsan: Refactor access_info initialization Paul E. McKenney
2021-05-11 23:23 ` [PATCH tip/core/rcu 07/10] kcsan: Remove reporting indirection Paul E. McKenney
2021-05-11 23:23 ` [PATCH tip/core/rcu 08/10] kcsan: Remove kcsan_report_type Paul E. McKenney
2021-05-11 23:24 ` Paul E. McKenney [this message]
2021-05-11 23:24 ` [PATCH tip/core/rcu 10/10] kcsan: Document "value changed" line Paul E. McKenney

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20210511232401.2896217-9-paulmck@kernel.org \
    --to=paulmck@kernel.org \
    --cc=andreyknvl@google.com \
    --cc=boqun.feng@gmail.com \
    --cc=cai@lca.pw \
    --cc=dvyukov@google.com \
    --cc=elver@google.com \
    --cc=glider@google.com \
    --cc=kasan-dev@googlegroups.com \
    --cc=kernel-team@fb.com \
    --cc=linux-kernel@vger.kernel.org \
    --cc=mark.rutland@arm.com \
    --cc=mingo@kernel.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).