Re: [linux-next:master] [rcutorture] ddd062f753: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]

["Paul E. McKenney" <paulmck@kernel.org>]

On Tue, Apr 22, 2025 at 01:01:58PM +0800, Oliver Sang wrote:
> hi, Paul,
> 
> On Mon, Apr 21, 2025 at 09:34:34AM -0700, Paul E. McKenney wrote:
> > On Mon, Apr 21, 2025 at 03:39:41PM +0800, kernel test robot wrote:
> > > 
> > > 
> > > Hello,
> > > 
> > > kernel test robot noticed "WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]" on:
> > > 
> > > commit: ddd062f7536cc09fe7ff1a66816601984bc68af8 ("rcutorture: Complain if an ->up_read() is delayed more than 10 seconds")
> > > https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
> > > 
> > > [test failed on linux-next/master f660850bc246fef15ba78c81f686860324396628]
> > > 
> > > in testcase: rcutorture
> > > version: 
> > > with following parameters:
> > > 
> > > 	runtime: 300s
> > > 	test: cpuhotplug
> > > 	torture_type: srcud
> > > 
> > > 
> > > 
> > > config: x86_64-randconfig-123-20250415
> > > compiler: clang-20
> > > test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
> > > 
> > > (please refer to attached dmesg/kmsg for entire log/backtrace)
> > > 
> > > 
> > > +-------------------------------------------------------------------------+------------+------------+
> > > |                                                                         | 1b983c34d5 | ddd062f753 |
> > > +-------------------------------------------------------------------------+------------+------------+
> > > | WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]      | 0          | 24         |
> > > | RIP:rcu_torture_updown[rcutorture]                                      | 0          | 24         |
> > > +-------------------------------------------------------------------------+------------+------------+
> > > 
> > > 
> > > If you fix the issue in a separate patch/commit (i.e. not just a new version of
> > > the same patch/commit), kindly add following tags
> > > | Reported-by: kernel test robot <oliver.sang@intel.com>
> > > | Closes: https://lore.kernel.org/oe-lkp/202504211513.23f21a0-lkp@intel.com
> > > 
> > > 
> > > The kernel config and materials to reproduce are available at:
> > > https://download.01.org/0day-ci/archive/20250421/202504211513.23f21a0-lkp@intel.com
> > 
> > Good catch, and thank you for your testing efforts!
> > 
> > Does the patch at the end of this email help?
> 
> sorry but the patch does not help. one dmesg is attached.

And idiot here failed to check for the exact same problem at the point
where the timer is queued, so thank you for bearing with me.

Does the patch at the end of this email (in addition to the previous
patch) get the job done?

							Thanx, Paul

[ . . . ]

> > diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> > index 3dd213bfc6662..53f0860b3748d 100644
> > --- a/kernel/rcu/rcutorture.c
> > +++ b/kernel/rcu/rcutorture.c
> > @@ -2557,6 +2557,7 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> >  static int
> >  rcu_torture_updown(void *arg)
> >  {
> > +	unsigned long j;
> >  	struct rcu_torture_one_read_state_updown *rtorsup;
> >  
> >  	VERBOSE_TOROUT_STRING("rcu_torture_updown task started");
> > @@ -2564,8 +2565,9 @@ rcu_torture_updown(void *arg)
> >  		for (rtorsup = updownreaders; rtorsup < &updownreaders[n_up_down]; rtorsup++) {
> >  			if (torture_must_stop())
> >  				break;
> > +			j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
> >  			if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
> > -				WARN_ON_ONCE(time_after(jiffies, rtorsup->rtorsu_j + 10 * HZ));
> > +				WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
> >  				continue;
> >  			}
> >  			rcu_torture_updown_one(rtorsup);


diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index abe48ff48f54c..7268e33086eb4 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -2449,6 +2449,7 @@ struct rcu_torture_one_read_state_updown {
 	struct hrtimer rtorsu_hrt;
 	bool rtorsu_inuse;
 	int rtorsu_cpu;
+	ktime_t rtorsu_kt;
 	unsigned long rtorsu_j;
 	unsigned long rtorsu_ndowns;
 	unsigned long rtorsu_nups;
@@ -2548,12 +2549,14 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
 		schedule_timeout_idle(HZ);
 		return;
 	}
-	rtorsup->rtorsu_j = jiffies;
 	smp_store_release(&rtorsup->rtorsu_inuse, true);
 	t = torture_random(&rtorsup->rtorsu_trs) & 0xfffff; // One per million.
 	if (t < 10 * 1000)
 		t = 200 * 1000 * 1000;
 	hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
+	smp_mb(); // Sample jiffies after posting hrtimer.
+	rtorsup->rtorsu_j = jiffies;  // Not used by hrtimer handler.
+	rtorsup->rtorsu_kt = t;
 }
 
 /*
@@ -2574,7 +2577,8 @@ rcu_torture_updown(void *arg)
 				break;
 			j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
 			if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
-				WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
+				WARN_ONCE(time_after(j, rtorsup->rtorsu_j + 1 + HZ * 10),
+					  "hrtimer queued at jiffies %lu for %lld ns took %lu jiffies\n", rtorsup->rtorsu_j, rtorsup->rtorsu_kt, j - rtorsup->rtorsu_j);
 				continue;
 			}
 			rcu_torture_updown_one(rtorsup);