Message-ID: <20200820144931.GA4120397@elver.google.com>
Date:   Thu, 20 Aug 2020 16:49:31 +0200
From:   Marco Elver <elver@...gle.com>
To:     Steven Rostedt <rostedt@...dmis.org>
Cc:     Peter Zijlstra <peterz@...radead.org>,
        linux-kernel@...r.kernel.org, mingo@...nel.org, will@...nel.org,
        npiggin@...il.com, jgross@...e.com, paulmck@...nel.org,
        rjw@...ysocki.net, joel@...lfernandes.org, svens@...ux.ibm.com,
        tglx@...utronix.de
Subject: Re: [PATCH 0/9] TRACE_IRQFLAGS wreckage

On Thu, Aug 20, 2020 at 10:36AM -0400, Steven Rostedt wrote:
> 
> I tested this series on top of tip/master and triggered the below
> warning when running the irqsoff tracer boot up test (config attached).
> 
> -- Steve
> 
>  Testing tracer irqsoff: 
>  
>  =============================
>  WARNING: suspicious RCU usage
>  5.9.0-rc1-test+ #92 Not tainted
>  -----------------------------
>  include/trace/events/lock.h:13 suspicious rcu_dereference_check() usage!
>  
>  other info that might help us debug this:
>  
>  
>  rcu_scheduler_active = 2, debug_locks = 1
>  RCU used illegally from extended quiescent state!
>  no locks held by swapper/2/0.
>  
>  stack backtrace:
>  CPU: 2 PID: 0 Comm: swapper/2 Not tainted 5.9.0-rc1-test+ #92
>  Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v03.03 07/14/2016
>  Call Trace:
>   dump_stack+0x8d/0xc0
>   lock_acquire.cold+0x23/0x2c
>   ? default_idle_call+0x4d/0x210
>   _raw_spin_lock_irqsave+0x50/0xa0
>   ? check_critical_timing+0x69/0x160
>   check_critical_timing+0x69/0x160
>   ? default_idle_call+0x4d/0x210
>   stop_critical_timings+0xdd/0xf0
>   default_idle_call+0x4d/0x210
>   do_idle+0x1f6/0x260
>   cpu_startup_entry+0x19/0x20
>   start_secondary+0x110/0x140
>   secondary_startup_64+0xb6/0xc0

Ah, I was just trying to figure out if it's due to KCSAN instrumentation
or not. I ran into a similar warning due to tracing of prandom_u32(),
that also triggered lockdep warnings (all warnings attached).

Otherwise, this survived syzkaller testing until I enabled KCSAN. :-/

The first thing KCSAN wants is to just guard against recursion due to
tracing even if KCSAN instrumentation is disabled for the function. This
recursion seems to be new.

I got further with the below patch for KCSAN. Unfortunately there are a
bunch of merge conflicts with latest KCSAN on -rcu tree if you were to
attach the patch to your series, so not sure what the best strategy here
is.

Config is also attached.

Thanks,
-- Marco

------ >8 ------

From 5b12649cbcf0c7d164e6995c40ce88a4e3e86f28 Mon Sep 17 00:00:00 2001
From: Marco Elver <elver@...gle.com>
Date: Thu, 6 Aug 2020 14:19:10 +0200
Subject: [PATCH] kcsan: Avoid recursion due to tracing

We can observe recursion due to calling library functions that are being
traced from kcsan_setup_watchpoint(). This can happen even though
instrumentation is disabled for such functions.

For example in lib/random32.o (where instrumentation is disabled), we
may still get recursion with recent changes to tracing:

 prandom_u32+0x11/0xe0
 kcsan_setup_watchpoint+0x32/0x580
 rcu_is_watching+0x21/0x60
 rcu_read_lock_sched_held+0x26/0xa0
 trace_prandom_u32+0x7e/0x190
 prandom_u32+0xa8/0xe0
 kcsan_setup_watchpoint+0x32/0x580
 rcu_is_watching+0x21/0x60
 rcu_read_lock_sched_held+0x26/0xa0
 trace_prandom_u32+0x7e/0x190
 prandom_u32+0xa8/0xe0
 kcsan_setup_watchpoint+0x32/0x580
 ...

Avoid the recursion by disabling KCSAN in the following regions in
kcsan_setup_watchpoint():

	- after checking if KCSAN is enabled, to before delay initiation;
	- after the delay, until the end of the function.

The exception that remains is udelay(), where we want to keep KCSAN
enabled as otherwise we would miss races between nested interrupts.

Signed-off-by: Marco Elver <elver@...gle.com>
---
 kernel/kcsan/core.c | 52 +++++++++++++++++++++++++++++++++------------
 1 file changed, 38 insertions(+), 14 deletions(-)

diff --git a/kernel/kcsan/core.c b/kernel/kcsan/core.c
index 9147ff6a12e5..c5a295afdb94 100644
--- a/kernel/kcsan/core.c
+++ b/kernel/kcsan/core.c
@@ -261,14 +261,15 @@ should_watch(const volatile void *ptr, size_t size, int type, struct kcsan_ctx *
 		return false;
 
 	/*
-	 * NOTE: If we get here, kcsan_skip must always be reset in slow path
-	 * via reset_kcsan_skip() to avoid underflow.
+	 * Note: If we get here, kcsan_skip must always be reset in slow path to
+	 * avoid underflow.
 	 */
 
 	/* this operation should be watched */
 	return true;
 }
 
+/* Requires: KCSAN is disabled, to avoid prandom_u32() recursion. */
 static inline void reset_kcsan_skip(void)
 {
 	long skip_count = kcsan_skip_watch -
@@ -283,12 +284,23 @@ static __always_inline bool kcsan_is_enabled(void)
 	return READ_ONCE(kcsan_enabled) && get_ctx()->disable_count == 0;
 }
 
-static inline unsigned int get_delay(void)
+/*
+ * Introduce delay depending on context and configuration.
+ * Requires: KCSAN is disabled, to avoid prandom_u32() recursion.
+ */
+static void delay_access(void)
 {
 	unsigned int delay = in_task() ? kcsan_udelay_task : kcsan_udelay_interrupt;
-	return delay - (IS_ENABLED(CONFIG_KCSAN_DELAY_RANDOMIZE) ?
-				prandom_u32_max(delay) :
-				0);
+
+	/*
+	 * Call prandom_u32_max() with KCSAN disabled, as tracing may be
+	 * enabled, which would cause recursion.
+	 */
+	delay -= IS_ENABLED(CONFIG_KCSAN_DELAY_RANDOMIZE) ? prandom_u32_max(delay) : 0;
+
+	kcsan_enable_current();
+	udelay(delay);
+	kcsan_disable_current();
 }
 
 void kcsan_save_irqtrace(struct task_struct *task)
@@ -386,17 +398,30 @@ kcsan_setup_watchpoint(const volatile void *ptr, size_t size, int type)
 	} expect_value;
 	unsigned long access_mask;
 	enum kcsan_value_change value_change = KCSAN_VALUE_CHANGE_MAYBE;
-	unsigned long ua_flags = user_access_save();
+	unsigned long ua_flags = 0;
 	unsigned long irq_flags = 0;
 
 	/*
 	 * Always reset kcsan_skip counter in slow-path to avoid underflow; see
-	 * should_watch().
+	 * should_watch(). This write is redundant if KCSAN is enabled, as we
+	 * call reset_kcsan_skip() below, yet we cannot call reset_kcsan_skip()
+	 * here to avoid prandom_u32() recursion.
 	 */
-	reset_kcsan_skip();
-
+	this_cpu_write(kcsan_skip, kcsan_skip_watch);
 	if (!kcsan_is_enabled())
-		goto out;
+		return;
+
+	ua_flags = user_access_save();
+
+	/*
+	 * Disable KCSAN to ensure that library functions we call do not result
+	 * in recursion. This can still occur even if instrumentation is
+	 * disabled for these functions, but tracing is enabled.
+	 */
+	kcsan_disable_current();
+
+	/* Randomized reset, after enabled-check to avoid recursion. */
+	reset_kcsan_skip();
 
 	/*
 	 * Special atomic rules: unlikely to be true, so we check them here in
@@ -458,19 +483,17 @@ kcsan_setup_watchpoint(const volatile void *ptr, size_t size, int type)
 	}
 
 	if (IS_ENABLED(CONFIG_KCSAN_DEBUG)) {
-		kcsan_disable_current();
 		pr_err("KCSAN: watching %s, size: %zu, addr: %px [slot: %d, encoded: %lx]\n",
 		       is_write ? "write" : "read", size, ptr,
 		       watchpoint_slot((unsigned long)ptr),
 		       encode_watchpoint((unsigned long)ptr, size, is_write));
-		kcsan_enable_current();
 	}
 
 	/*
 	 * Delay this thread, to increase probability of observing a racy
 	 * conflicting access.
 	 */
-	udelay(get_delay());
+	delay_access();
 
 	/*
 	 * Re-read value, and check if it is as expected; if not, we infer a
@@ -563,6 +586,7 @@ kcsan_setup_watchpoint(const volatile void *ptr, size_t size, int type)
 		local_irq_restore(irq_flags);
 	kcsan_restore_irqtrace(current);
 out:
+	kcsan_enable_current_nowarn();
 	user_access_restore(ua_flags);
 }
 
-- 
2.28.0.297.g1956fa8f8d-goog

View attachment "dmesg.txt" of type "text/plain" (17969 bytes)

View attachment ".config" of type "text/plain" (209999 bytes)

Powered by blists - more mailing lists