[PATCH v2 0/3] CSD-lock diagnostics enhancements

[PATCH v2 0/3] CSD-lock diagnostics enhancements

[Neeraj Upadhyay]

Hello!

This series adds following changes to the CSD-lock diagnostics (rebased on v6.10):

1.      locking/csd_lock: Print large numbers as negatives.

2.      locking/csd_lock: Provide an indication of ongoing CSD-lock stall.

3.      locking/csd-lock: Use backoff for repeated reports of same
        incident.

This is the second version of this patchset. Previous version can be found at [1]

Changes since v1:
- Rebase on v6.10
- Fix n_csd_lock_stuck atomic op in csd_lock_wait_toolong (Rik van Riel)
- Apply Rik van Riel's Reviewed-by.

Once reviewed/acked, current plan is to take this through RCU tree during v6.12 merge window,
as RCU commit "7d2ba698ad85 rcu: Summarize RCU CPU stall warnings during CSD-lock stalls" [2]
has dependency on these changes. If there are any concerns with taking these through RCU tree,
please raise those concerns.



[1] https://lore.kernel.org/lkml/20240713165642.GA215331@neeraj.linux/
[2] https://git.kernel.org/pub/scm/linux/kernel/git/neeraj.upadhyay/linux-rcu.git/commit/?h=rcustall.13.07.24a&id=7d2ba698ad85984656e9732d87b8e040a23baa55

Thanks
Neeraj

------------------------------------------------------------------------

 include/linux/smp.h |  6 ++++++
 kernel/smp.c        | 30 +++++++++++++++++++++++++-----
 2 files changed, 31 insertions(+), 5 deletions(-)

[PATCH v2 1/3] locking/csd_lock: Print large numbers as negatives

[neeraj.upadhyay]

From: "Paul E. McKenney" <paulmck@kernel.org>

The CSD-lock-hold diagnostics from CONFIG_CSD_LOCK_WAIT_DEBUG are
printed in nanoseconds as unsigned long longs, which is a bit obtuse for
human readers when timing bugs result in negative CSD-lock hold times.
Yes, there are some people to whom it is immediately obvious that
18446744073709551615 is really -1, but for the rest of us...

Therefore, print these numbers as signed long longs, making the negative
hold times immediately apparent.

Reported-by: Rik van Riel <riel@surriel.com>
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Cc: Imran Khan <imran.f.khan@oracle.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Leonardo Bras <leobras@redhat.com>
Cc: "Peter Zijlstra (Intel)" <peterz@infradead.org>
Cc: Rik van Riel <riel@surriel.com>
Reviewed-by: Rik van Riel <riel@surriel.com>
Signed-off-by: Neeraj Upadhyay <neeraj.upadhyay@kernel.org>
---
 kernel/smp.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/kernel/smp.c b/kernel/smp.c
index f085ebcdf9e7..81f7083a53e2 100644
--- a/kernel/smp.c
+++ b/kernel/smp.c
@@ -248,8 +248,8 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
 	cpu_cur_csd = smp_load_acquire(&per_cpu(cur_csd, cpux)); /* Before func and info. */
 	/* How long since this CSD lock was stuck. */
 	ts_delta = ts2 - ts0;
-	pr_alert("csd: %s non-responsive CSD lock (#%d) on CPU#%d, waiting %llu ns for CPU#%02d %pS(%ps).\n",
-		 firsttime ? "Detected" : "Continued", *bug_id, raw_smp_processor_id(), ts_delta,
+	pr_alert("csd: %s non-responsive CSD lock (#%d) on CPU#%d, waiting %lld ns for CPU#%02d %pS(%ps).\n",
+		 firsttime ? "Detected" : "Continued", *bug_id, raw_smp_processor_id(), (s64)ts_delta,
 		 cpu, csd->func, csd->info);
 	/*
 	 * If the CSD lock is still stuck after 5 minutes, it is unlikely
-- 
2.40.1

[PATCH v2 2/3] locking/csd_lock: Provide an indication of ongoing CSD-lock stall

[neeraj.upadhyay]

From: "Paul E. McKenney" <paulmck@kernel.org>

If a CSD-lock stall goes on long enough, it will cause an RCU CPU
stall warning.  This additional warning provides much additional
console-log traffic and little additional information.  Therefore,
provide a new csd_lock_is_stuck() function that returns true if there
is an ongoing CSD-lock stall.  This function will be used by the RCU
CPU stall warnings to provide a one-line indication of the stall when
this function returns true.

[ neeraj.upadhyay: Apply Rik van Riel feedback. ]

Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Cc: Imran Khan <imran.f.khan@oracle.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Leonardo Bras <leobras@redhat.com>
Cc: "Peter Zijlstra (Intel)" <peterz@infradead.org>
Cc: Rik van Riel <riel@surriel.com>
Signed-off-by: Neeraj Upadhyay <neeraj.upadhyay@kernel.org>
---
 include/linux/smp.h |  6 ++++++
 kernel/smp.c        | 16 ++++++++++++++++
 2 files changed, 22 insertions(+)

diff --git a/include/linux/smp.h b/include/linux/smp.h
index fcd61dfe2af3..3871bd32018f 100644
--- a/include/linux/smp.h
+++ b/include/linux/smp.h
@@ -294,4 +294,10 @@ int smpcfd_prepare_cpu(unsigned int cpu);
 int smpcfd_dead_cpu(unsigned int cpu);
 int smpcfd_dying_cpu(unsigned int cpu);
 
+#ifdef CONFIG_CSD_LOCK_WAIT_DEBUG
+bool csd_lock_is_stuck(void);
+#else
+static inline bool csd_lock_is_stuck(void) { return false; }
+#endif
+
 #endif /* __LINUX_SMP_H */
diff --git a/kernel/smp.c b/kernel/smp.c
index 81f7083a53e2..9385cc05de53 100644
--- a/kernel/smp.c
+++ b/kernel/smp.c
@@ -207,6 +207,19 @@ static int csd_lock_wait_getcpu(call_single_data_t *csd)
 	return -1;
 }
 
+static atomic_t n_csd_lock_stuck;
+
+/**
+ * csd_lock_is_stuck - Has a CSD-lock acquisition been stuck too long?
+ *
+ * Returns @true if a CSD-lock acquisition is stuck and has been stuck
+ * long enough for a "non-responsive CSD lock" message to be printed.
+ */
+bool csd_lock_is_stuck(void)
+{
+	return !!atomic_read(&n_csd_lock_stuck);
+}
+
 /*
  * Complain if too much time spent waiting.  Note that only
  * the CSD_TYPE_SYNC/ASYNC types provide the destination CPU,
@@ -228,6 +241,7 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
 		cpu = csd_lock_wait_getcpu(csd);
 		pr_alert("csd: CSD lock (#%d) got unstuck on CPU#%02d, CPU#%02d released the lock.\n",
 			 *bug_id, raw_smp_processor_id(), cpu);
+		atomic_dec(&n_csd_lock_stuck);
 		return true;
 	}
 
@@ -251,6 +265,8 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
 	pr_alert("csd: %s non-responsive CSD lock (#%d) on CPU#%d, waiting %lld ns for CPU#%02d %pS(%ps).\n",
 		 firsttime ? "Detected" : "Continued", *bug_id, raw_smp_processor_id(), (s64)ts_delta,
 		 cpu, csd->func, csd->info);
+	if (firsttime)
+		atomic_inc(&n_csd_lock_stuck);
 	/*
 	 * If the CSD lock is still stuck after 5 minutes, it is unlikely
 	 * to become unstuck. Use a signed comparison to avoid triggering
-- 
2.40.1

Re: [PATCH v2 2/3] locking/csd_lock: Provide an indication of ongoing CSD-lock stall

[Leonardo Bras]

On Mon, Jul 22, 2024 at 07:07:34PM +0530, neeraj.upadhyay@kernel.org wrote:
> From: "Paul E. McKenney" <paulmck@kernel.org>
> 
> If a CSD-lock stall goes on long enough, it will cause an RCU CPU
> stall warning.  This additional warning provides much additional
> console-log traffic and little additional information.  Therefore,
> provide a new csd_lock_is_stuck() function that returns true if there
> is an ongoing CSD-lock stall.  This function will be used by the RCU
> CPU stall warnings to provide a one-line indication of the stall when
> this function returns true.

I think it would be nice to also add the RCU usage here, as for the 
function being declared but not used.

> 
> [ neeraj.upadhyay: Apply Rik van Riel feedback. ]
> 
> Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> Cc: Imran Khan <imran.f.khan@oracle.com>
> Cc: Ingo Molnar <mingo@kernel.org>
> Cc: Leonardo Bras <leobras@redhat.com>
> Cc: "Peter Zijlstra (Intel)" <peterz@infradead.org>
> Cc: Rik van Riel <riel@surriel.com>
> Signed-off-by: Neeraj Upadhyay <neeraj.upadhyay@kernel.org>
> ---
>  include/linux/smp.h |  6 ++++++
>  kernel/smp.c        | 16 ++++++++++++++++
>  2 files changed, 22 insertions(+)
> 
> diff --git a/include/linux/smp.h b/include/linux/smp.h
> index fcd61dfe2af3..3871bd32018f 100644
> --- a/include/linux/smp.h
> +++ b/include/linux/smp.h
> @@ -294,4 +294,10 @@ int smpcfd_prepare_cpu(unsigned int cpu);
>  int smpcfd_dead_cpu(unsigned int cpu);
>  int smpcfd_dying_cpu(unsigned int cpu);
>  
> +#ifdef CONFIG_CSD_LOCK_WAIT_DEBUG
> +bool csd_lock_is_stuck(void);
> +#else
> +static inline bool csd_lock_is_stuck(void) { return false; }
> +#endif
> +
>  #endif /* __LINUX_SMP_H */
> diff --git a/kernel/smp.c b/kernel/smp.c
> index 81f7083a53e2..9385cc05de53 100644
> --- a/kernel/smp.c
> +++ b/kernel/smp.c
> @@ -207,6 +207,19 @@ static int csd_lock_wait_getcpu(call_single_data_t *csd)
>  	return -1;
>  }
>  
> +static atomic_t n_csd_lock_stuck;
> +
> +/**
> + * csd_lock_is_stuck - Has a CSD-lock acquisition been stuck too long?
> + *
> + * Returns @true if a CSD-lock acquisition is stuck and has been stuck
> + * long enough for a "non-responsive CSD lock" message to be printed.
> + */
> +bool csd_lock_is_stuck(void)
> +{
> +	return !!atomic_read(&n_csd_lock_stuck);
> +}
> +
>  /*
>   * Complain if too much time spent waiting.  Note that only
>   * the CSD_TYPE_SYNC/ASYNC types provide the destination CPU,
> @@ -228,6 +241,7 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
>  		cpu = csd_lock_wait_getcpu(csd);
>  		pr_alert("csd: CSD lock (#%d) got unstuck on CPU#%02d, CPU#%02d released the lock.\n",
>  			 *bug_id, raw_smp_processor_id(), cpu);
> +		atomic_dec(&n_csd_lock_stuck);
>  		return true;
>  	}
>  
> @@ -251,6 +265,8 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
>  	pr_alert("csd: %s non-responsive CSD lock (#%d) on CPU#%d, waiting %lld ns for CPU#%02d %pS(%ps).\n",
>  		 firsttime ? "Detected" : "Continued", *bug_id, raw_smp_processor_id(), (s64)ts_delta,
>  		 cpu, csd->func, csd->info);
> +	if (firsttime)
> +		atomic_inc(&n_csd_lock_stuck);
>  	/*
>  	 * If the CSD lock is still stuck after 5 minutes, it is unlikely
>  	 * to become unstuck. Use a signed comparison to avoid triggering
> -- 
> 2.40.1
> 

IIUC we have a single atomic counter for the whole system, which is 
modified in csd_lock_wait_toolong() and read in RCU stall warning.

I think it should not be an issue regarding cache bouncing because in worst 
case scenario we would have 2 modify / cpu each csd_lock_timeout (which is 
5 seconds by default).

Thanks!
Leo

Re: [PATCH v2 2/3] locking/csd_lock: Provide an indication of ongoing CSD-lock stall

[Paul E. McKenney]

On Wed, Jul 31, 2024 at 06:35:35PM -0300, Leonardo Bras wrote:
> On Mon, Jul 22, 2024 at 07:07:34PM +0530, neeraj.upadhyay@kernel.org wrote:
> > From: "Paul E. McKenney" <paulmck@kernel.org>
> > 
> > If a CSD-lock stall goes on long enough, it will cause an RCU CPU
> > stall warning.  This additional warning provides much additional
> > console-log traffic and little additional information.  Therefore,
> > provide a new csd_lock_is_stuck() function that returns true if there
> > is an ongoing CSD-lock stall.  This function will be used by the RCU
> > CPU stall warnings to provide a one-line indication of the stall when
> > this function returns true.
> 
> I think it would be nice to also add the RCU usage here, as for the 
> function being declared but not used.

These are external functions, and the commit that uses it is just a few
farther along in the stack.  Or do we now have some tool that complains
if an external function is not used anywhere?

> > [ neeraj.upadhyay: Apply Rik van Riel feedback. ]
> > 
> > Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> > Cc: Imran Khan <imran.f.khan@oracle.com>
> > Cc: Ingo Molnar <mingo@kernel.org>
> > Cc: Leonardo Bras <leobras@redhat.com>
> > Cc: "Peter Zijlstra (Intel)" <peterz@infradead.org>
> > Cc: Rik van Riel <riel@surriel.com>
> > Signed-off-by: Neeraj Upadhyay <neeraj.upadhyay@kernel.org>
> > ---
> >  include/linux/smp.h |  6 ++++++
> >  kernel/smp.c        | 16 ++++++++++++++++
> >  2 files changed, 22 insertions(+)
> > 
> > diff --git a/include/linux/smp.h b/include/linux/smp.h
> > index fcd61dfe2af3..3871bd32018f 100644
> > --- a/include/linux/smp.h
> > +++ b/include/linux/smp.h
> > @@ -294,4 +294,10 @@ int smpcfd_prepare_cpu(unsigned int cpu);
> >  int smpcfd_dead_cpu(unsigned int cpu);
> >  int smpcfd_dying_cpu(unsigned int cpu);
> >  
> > +#ifdef CONFIG_CSD_LOCK_WAIT_DEBUG
> > +bool csd_lock_is_stuck(void);
> > +#else
> > +static inline bool csd_lock_is_stuck(void) { return false; }
> > +#endif
> > +
> >  #endif /* __LINUX_SMP_H */
> > diff --git a/kernel/smp.c b/kernel/smp.c
> > index 81f7083a53e2..9385cc05de53 100644
> > --- a/kernel/smp.c
> > +++ b/kernel/smp.c
> > @@ -207,6 +207,19 @@ static int csd_lock_wait_getcpu(call_single_data_t *csd)
> >  	return -1;
> >  }
> >  
> > +static atomic_t n_csd_lock_stuck;
> > +
> > +/**
> > + * csd_lock_is_stuck - Has a CSD-lock acquisition been stuck too long?
> > + *
> > + * Returns @true if a CSD-lock acquisition is stuck and has been stuck
> > + * long enough for a "non-responsive CSD lock" message to be printed.
> > + */
> > +bool csd_lock_is_stuck(void)
> > +{
> > +	return !!atomic_read(&n_csd_lock_stuck);
> > +}
> > +
> >  /*
> >   * Complain if too much time spent waiting.  Note that only
> >   * the CSD_TYPE_SYNC/ASYNC types provide the destination CPU,
> > @@ -228,6 +241,7 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
> >  		cpu = csd_lock_wait_getcpu(csd);
> >  		pr_alert("csd: CSD lock (#%d) got unstuck on CPU#%02d, CPU#%02d released the lock.\n",
> >  			 *bug_id, raw_smp_processor_id(), cpu);
> > +		atomic_dec(&n_csd_lock_stuck);
> >  		return true;
> >  	}
> >  
> > @@ -251,6 +265,8 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
> >  	pr_alert("csd: %s non-responsive CSD lock (#%d) on CPU#%d, waiting %lld ns for CPU#%02d %pS(%ps).\n",
> >  		 firsttime ? "Detected" : "Continued", *bug_id, raw_smp_processor_id(), (s64)ts_delta,
> >  		 cpu, csd->func, csd->info);
> > +	if (firsttime)
> > +		atomic_inc(&n_csd_lock_stuck);
> >  	/*
> >  	 * If the CSD lock is still stuck after 5 minutes, it is unlikely
> >  	 * to become unstuck. Use a signed comparison to avoid triggering
> > -- 
> > 2.40.1
> > 
> 
> IIUC we have a single atomic counter for the whole system, which is 
> modified in csd_lock_wait_toolong() and read in RCU stall warning.
> 
> I think it should not be an issue regarding cache bouncing because in worst 
> case scenario we would have 2 modify / cpu each csd_lock_timeout (which is 
> 5 seconds by default).

If it does become a problem, there are ways of taking care of it.
Just a little added complexity.  ;-)

> Thanks!

And thank you for looking this over!

							Thanx, Paul

Re: [PATCH v2 2/3] locking/csd_lock: Provide an indication of ongoing CSD-lock stall

[Leonardo Bras]

On Wed, Jul 31, 2024 at 03:08:29PM -0700, Paul E. McKenney wrote:
> On Wed, Jul 31, 2024 at 06:35:35PM -0300, Leonardo Bras wrote:
> > On Mon, Jul 22, 2024 at 07:07:34PM +0530, neeraj.upadhyay@kernel.org wrote:
> > > From: "Paul E. McKenney" <paulmck@kernel.org>
> > > 
> > > If a CSD-lock stall goes on long enough, it will cause an RCU CPU
> > > stall warning.  This additional warning provides much additional
> > > console-log traffic and little additional information.  Therefore,
> > > provide a new csd_lock_is_stuck() function that returns true if there
> > > is an ongoing CSD-lock stall.  This function will be used by the RCU
> > > CPU stall warnings to provide a one-line indication of the stall when
> > > this function returns true.
> > 
> > I think it would be nice to also add the RCU usage here, as for the 
> > function being declared but not used.
> 

Hi Paul,

> These are external functions, and the commit that uses it is just a few
> farther along in the stack.

Oh, I see. I may have received just part of this patchset.

I found it weird a series of 3 to have a 4th patch, and did not think that 
it could have more, so I did not check the ML. :)

>  Or do we now have some tool that complains
> if an external function is not used anywhere?

Not really, I was just interested in the patchset but it made no sense in 
my head to add a function & not use it. On top of that, it did not occur to 
me that it was getting included on a different patchset. 

Thanks!
Leo


> 
> > > [ neeraj.upadhyay: Apply Rik van Riel feedback. ]
> > > 
> > > Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> > > Cc: Imran Khan <imran.f.khan@oracle.com>
> > > Cc: Ingo Molnar <mingo@kernel.org>
> > > Cc: Leonardo Bras <leobras@redhat.com>
> > > Cc: "Peter Zijlstra (Intel)" <peterz@infradead.org>
> > > Cc: Rik van Riel <riel@surriel.com>
> > > Signed-off-by: Neeraj Upadhyay <neeraj.upadhyay@kernel.org>
> > > ---
> > >  include/linux/smp.h |  6 ++++++
> > >  kernel/smp.c        | 16 ++++++++++++++++
> > >  2 files changed, 22 insertions(+)
> > > 
> > > diff --git a/include/linux/smp.h b/include/linux/smp.h
> > > index fcd61dfe2af3..3871bd32018f 100644
> > > --- a/include/linux/smp.h
> > > +++ b/include/linux/smp.h
> > > @@ -294,4 +294,10 @@ int smpcfd_prepare_cpu(unsigned int cpu);
> > >  int smpcfd_dead_cpu(unsigned int cpu);
> > >  int smpcfd_dying_cpu(unsigned int cpu);
> > >  
> > > +#ifdef CONFIG_CSD_LOCK_WAIT_DEBUG
> > > +bool csd_lock_is_stuck(void);
> > > +#else
> > > +static inline bool csd_lock_is_stuck(void) { return false; }
> > > +#endif
> > > +
> > >  #endif /* __LINUX_SMP_H */
> > > diff --git a/kernel/smp.c b/kernel/smp.c
> > > index 81f7083a53e2..9385cc05de53 100644
> > > --- a/kernel/smp.c
> > > +++ b/kernel/smp.c
> > > @@ -207,6 +207,19 @@ static int csd_lock_wait_getcpu(call_single_data_t *csd)
> > >  	return -1;
> > >  }
> > >  
> > > +static atomic_t n_csd_lock_stuck;
> > > +
> > > +/**
> > > + * csd_lock_is_stuck - Has a CSD-lock acquisition been stuck too long?
> > > + *
> > > + * Returns @true if a CSD-lock acquisition is stuck and has been stuck
> > > + * long enough for a "non-responsive CSD lock" message to be printed.
> > > + */
> > > +bool csd_lock_is_stuck(void)
> > > +{
> > > +	return !!atomic_read(&n_csd_lock_stuck);
> > > +}
> > > +
> > >  /*
> > >   * Complain if too much time spent waiting.  Note that only
> > >   * the CSD_TYPE_SYNC/ASYNC types provide the destination CPU,
> > > @@ -228,6 +241,7 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
> > >  		cpu = csd_lock_wait_getcpu(csd);
> > >  		pr_alert("csd: CSD lock (#%d) got unstuck on CPU#%02d, CPU#%02d released the lock.\n",
> > >  			 *bug_id, raw_smp_processor_id(), cpu);
> > > +		atomic_dec(&n_csd_lock_stuck);
> > >  		return true;
> > >  	}
> > >  
> > > @@ -251,6 +265,8 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
> > >  	pr_alert("csd: %s non-responsive CSD lock (#%d) on CPU#%d, waiting %lld ns for CPU#%02d %pS(%ps).\n",
> > >  		 firsttime ? "Detected" : "Continued", *bug_id, raw_smp_processor_id(), (s64)ts_delta,
> > >  		 cpu, csd->func, csd->info);
> > > +	if (firsttime)
> > > +		atomic_inc(&n_csd_lock_stuck);
> > >  	/*
> > >  	 * If the CSD lock is still stuck after 5 minutes, it is unlikely
> > >  	 * to become unstuck. Use a signed comparison to avoid triggering
> > > -- 
> > > 2.40.1
> > > 
> > 
> > IIUC we have a single atomic counter for the whole system, which is 
> > modified in csd_lock_wait_toolong() and read in RCU stall warning.
> > 
> > I think it should not be an issue regarding cache bouncing because in worst 
> > case scenario we would have 2 modify / cpu each csd_lock_timeout (which is 
> > 5 seconds by default).
> 
> If it does become a problem, there are ways of taking care of it.
> Just a little added complexity.  ;-)
> 
> > Thanks!
> 
> And thank you for looking this over!
> 
> 							Thanx, Paul
> 

[PATCH v2 3/3] locking/csd-lock: Use backoff for repeated reports of same incident

[neeraj.upadhyay]

From: "Paul E. McKenney" <paulmck@kernel.org>

Currently, the CSD-lock diagnostics in CONFIG_CSD_LOCK_WAIT_DEBUG=y
kernels are emitted at five-second intervals.  Although this has proven
to be a good time interval for the first diagnostic, if the target CPU
keeps interrupts disabled for way longer than five seconds, the ratio
of useful new information to pointless repetition increases considerably.

Therefore, back off the time period for repeated reports of the same
incident, increasing linearly with the number of reports and logarithmicly
with the number of online CPUs.

[ paulmck: Apply Dan Carpenter feedback. ]

Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Cc: Imran Khan <imran.f.khan@oracle.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Leonardo Bras <leobras@redhat.com>
Cc: "Peter Zijlstra (Intel)" <peterz@infradead.org>
Cc: Rik van Riel <riel@surriel.com>
Reviewed-by: Rik van Riel <riel@surriel.com>
Signed-off-by: Neeraj Upadhyay <neeraj.upadhyay@kernel.org>
---
 kernel/smp.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

diff --git a/kernel/smp.c b/kernel/smp.c
index 9385cc05de53..dfcde438ef63 100644
--- a/kernel/smp.c
+++ b/kernel/smp.c
@@ -225,7 +225,7 @@ bool csd_lock_is_stuck(void)
  * the CSD_TYPE_SYNC/ASYNC types provide the destination CPU,
  * so waiting on other types gets much less information.
  */
-static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, int *bug_id)
+static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, int *bug_id, unsigned long *nmessages)
 {
 	int cpu = -1;
 	int cpux;
@@ -248,7 +248,9 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
 	ts2 = sched_clock();
 	/* How long since we last checked for a stuck CSD lock.*/
 	ts_delta = ts2 - *ts1;
-	if (likely(ts_delta <= csd_lock_timeout_ns || csd_lock_timeout_ns == 0))
+	if (likely(ts_delta <= csd_lock_timeout_ns * (*nmessages + 1) *
+			       (!*nmessages ? 1 : (ilog2(num_online_cpus()) / 2 + 1)) ||
+		   csd_lock_timeout_ns == 0))
 		return false;
 
 	firsttime = !*bug_id;
@@ -265,6 +267,7 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
 	pr_alert("csd: %s non-responsive CSD lock (#%d) on CPU#%d, waiting %lld ns for CPU#%02d %pS(%ps).\n",
 		 firsttime ? "Detected" : "Continued", *bug_id, raw_smp_processor_id(), (s64)ts_delta,
 		 cpu, csd->func, csd->info);
+	(*nmessages)++;
 	if (firsttime)
 		atomic_inc(&n_csd_lock_stuck);
 	/*
@@ -305,12 +308,13 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
  */
 static void __csd_lock_wait(call_single_data_t *csd)
 {
+	unsigned long nmessages = 0;
 	int bug_id = 0;
 	u64 ts0, ts1;
 
 	ts1 = ts0 = sched_clock();
 	for (;;) {
-		if (csd_lock_wait_toolong(csd, ts0, &ts1, &bug_id))
+		if (csd_lock_wait_toolong(csd, ts0, &ts1, &bug_id, &nmessages))
 			break;
 		cpu_relax();
 	}
-- 
2.40.1

Re: [PATCH v2 3/3] locking/csd-lock: Use backoff for repeated reports of same incident

[Leonardo Bras]

On Mon, Jul 22, 2024 at 07:07:35PM +0530, neeraj.upadhyay@kernel.org wrote:
> From: "Paul E. McKenney" <paulmck@kernel.org>
> 
> Currently, the CSD-lock diagnostics in CONFIG_CSD_LOCK_WAIT_DEBUG=y
> kernels are emitted at five-second intervals.  Although this has proven
> to be a good time interval for the first diagnostic, if the target CPU
> keeps interrupts disabled for way longer than five seconds, the ratio
> of useful new information to pointless repetition increases considerably.
> 
> Therefore, back off the time period for repeated reports of the same
> incident, increasing linearly with the number of reports and logarithmicly
> with the number of online CPUs.
> 
> [ paulmck: Apply Dan Carpenter feedback. ]
> 
> Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> Cc: Imran Khan <imran.f.khan@oracle.com>
> Cc: Ingo Molnar <mingo@kernel.org>
> Cc: Leonardo Bras <leobras@redhat.com>
> Cc: "Peter Zijlstra (Intel)" <peterz@infradead.org>
> Cc: Rik van Riel <riel@surriel.com>
> Reviewed-by: Rik van Riel <riel@surriel.com>
> Signed-off-by: Neeraj Upadhyay <neeraj.upadhyay@kernel.org>
> ---
>  kernel/smp.c | 10 +++++++---
>  1 file changed, 7 insertions(+), 3 deletions(-)
> 
> diff --git a/kernel/smp.c b/kernel/smp.c
> index 9385cc05de53..dfcde438ef63 100644
> --- a/kernel/smp.c
> +++ b/kernel/smp.c
> @@ -225,7 +225,7 @@ bool csd_lock_is_stuck(void)
>   * the CSD_TYPE_SYNC/ASYNC types provide the destination CPU,
>   * so waiting on other types gets much less information.
>   */
> -static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, int *bug_id)
> +static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, int *bug_id, unsigned long *nmessages)
>  {
>  	int cpu = -1;
>  	int cpux;
> @@ -248,7 +248,9 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
>  	ts2 = sched_clock();
>  	/* How long since we last checked for a stuck CSD lock.*/
>  	ts_delta = ts2 - *ts1;
> -	if (likely(ts_delta <= csd_lock_timeout_ns || csd_lock_timeout_ns == 0))
> +	if (likely(ts_delta <= csd_lock_timeout_ns * (*nmessages + 1) *
> +			       (!*nmessages ? 1 : (ilog2(num_online_cpus()) / 2 + 1)) ||
> +		   csd_lock_timeout_ns == 0))

I think this is a nice change.

OTOH above condition is quite hard to read IMHO.

IIUC you want, for csd_lock_timeout_ns 5s, and num_online_cpus = 64
1st message: after 5s
2nd message: after 5 * 2 * (6 / 2 + 1) = 10 * 4 = 40s
3rd message: after 5 * 3 * 4 = 60s
...
Is that correct?


I think this could be achieved with:

	/* How long since we last checked for a stuck CSD lock.*/
	ts_delta = ts2 - *ts1;
+	if (*nmessages)
+		csd_lock_timeout_ns *= (*nmessages + 1) * (ilog2(num_online_cpus()) / 2 + 1)
	if (likely(ts_delta <= csd_lock_timeout_ns || csd_lock_timeout_ns == 0))
		return false;

Does that look better?

Thanks!
Leo

>  
>  	firsttime = !*bug_id;
> @@ -265,6 +267,7 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
>  	pr_alert("csd: %s non-responsive CSD lock (#%d) on CPU#%d, waiting %lld ns for CPU#%02d %pS(%ps).\n",
>  		 firsttime ? "Detected" : "Continued", *bug_id, raw_smp_processor_id(), (s64)ts_delta,
>  		 cpu, csd->func, csd->info);
> +	(*nmessages)++;
>  	if (firsttime)
>  		atomic_inc(&n_csd_lock_stuck);
>  	/*
> @@ -305,12 +308,13 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
>   */
>  static void __csd_lock_wait(call_single_data_t *csd)
>  {
> +	unsigned long nmessages = 0;
>  	int bug_id = 0;
>  	u64 ts0, ts1;
>  
>  	ts1 = ts0 = sched_clock();
>  	for (;;) {
> -		if (csd_lock_wait_toolong(csd, ts0, &ts1, &bug_id))
> +		if (csd_lock_wait_toolong(csd, ts0, &ts1, &bug_id, &nmessages))
>  			break;
>  		cpu_relax();
>  	}
> -- 
> 2.40.1
> 

[PATCH v2 4/3] smp: print only local CPU info when sched_clock goes backward

[neeraj.upadhyay]

From: Rik van Riel <riel@surriel.com>

About 40% of all csd_lock warnings observed in our fleet appear to
be due to sched_clock() going backward in time (usually only a little
bit), resulting in ts0 being larger than ts2.

When the local CPU is at fault, we should print out a message reflecting
that, rather than trying to get the remote CPU's stack trace.

Signed-off-by: Rik van Riel <riel@surriel.com>
Tested-by: "Paul E. McKenney" <paulmck@kernel.org>
Signed-off-by: Neeraj Upadhyay <neeraj.upadhyay@kernel.org>
---
 kernel/smp.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/kernel/smp.c b/kernel/smp.c
index dfcde438ef63..143ae26f96a2 100644
--- a/kernel/smp.c
+++ b/kernel/smp.c
@@ -253,6 +253,14 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
 		   csd_lock_timeout_ns == 0))
 		return false;
 
+	if (ts0 > ts2) {
+		/* Our own sched_clock went backward; don't blame another CPU. */
+		ts_delta = ts0 - ts2;
+		pr_alert("sched_clock on CPU %d went backward by %llu ns\n", raw_smp_processor_id(), ts_delta);
+		*ts1 = ts2;
+		return false;
+	}
+
 	firsttime = !*bug_id;
 	if (firsttime)
 		*bug_id = atomic_inc_return(&csd_bug_count);
-- 
2.40.1

Re: [PATCH v2 4/3] smp: print only local CPU info when sched_clock goes backward

[Leonardo Bras]

On Wed, Jul 24, 2024 at 10:36:52PM +0530, neeraj.upadhyay@kernel.org wrote:
> From: Rik van Riel <riel@surriel.com>
> 
> About 40% of all csd_lock warnings observed in our fleet appear to
> be due to sched_clock() going backward in time (usually only a little
> bit), resulting in ts0 being larger than ts2.
> 
> When the local CPU is at fault, we should print out a message reflecting
> that, rather than trying to get the remote CPU's stack trace.
> 
> Signed-off-by: Rik van Riel <riel@surriel.com>
> Tested-by: "Paul E. McKenney" <paulmck@kernel.org>
> Signed-off-by: Neeraj Upadhyay <neeraj.upadhyay@kernel.org>
> ---
>  kernel/smp.c | 8 ++++++++
>  1 file changed, 8 insertions(+)
> 
> diff --git a/kernel/smp.c b/kernel/smp.c
> index dfcde438ef63..143ae26f96a2 100644
> --- a/kernel/smp.c
> +++ b/kernel/smp.c
> @@ -253,6 +253,14 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
>  		   csd_lock_timeout_ns == 0))
>  		return false;
>

Hello Rik,
Thanks for this contribution!
Seems a really nice bug you found here :)

Your solution seems very efficient, but I noticed a few (possible) issues here:
  
> +	if (ts0 > ts2) {
> +		/* Our own sched_clock went backward; don't blame another CPU. */
> +		ts_delta = ts0 - ts2;
> +		pr_alert("sched_clock on CPU %d went backward by %llu ns\n", raw_smp_processor_id(), ts_delta);

This ns number is not necessarely correct, since a few calls to 
csd_lock_wait_toolong() may have happened before the clock going backwards.

As an example we could have, for a 15ms backwards movement
05ms: csd: [...] waiting 5000 ns for CPU#X
10ms: csd: [...] waiting 10000 ns for CPU#X
12ms: sched_clock on CPU X went backward by 3000 ns
						^ wrong
17ms: csd: [...] waiting 5000 ns for CPU#X
			  ^reset waiting.

> +		*ts1 = ts2;

Second point here, above line just resets the counter, so we start printing 
messages again, with the wrong waiting time. (see 17ms above)

> +		return false;
> +	}
> +


Suggestion A: Save the last ts2 it succeeds, and in case of 
the clock going backwards, adjust ts0 and ts1 to the new clock.
This way the waiting time does not reset, and the backwards amount is 
correct:

########
diff --git a/kernel/smp.c b/kernel/smp.c
index aaffecdad319..e8788f7e1a78 100644
--- a/kernel/smp.c
+++ b/kernel/smp.c
@@ -213,7 +213,8 @@ static int csd_lock_wait_getcpu(call_single_data_t *csd)
  * the CSD_TYPE_SYNC/ASYNC types provide the destination CPU,
  * so waiting on other types gets much less information.
  */
-static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, int *bug_id)
+static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 *ts0, u64 *ts1, u64 *ts_save,
+                                 int *bug_id)
 {
        int cpu = -1;
        int cpux;
@@ -233,10 +234,21 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
        }
 
        ts2 = sched_clock();
+
        /* How long since we last checked for a stuck CSD lock.*/
        ts_delta = ts2 - *ts1;
-       if (likely(ts_delta <= csd_lock_timeout_ns || csd_lock_timeout_ns == 0))
+       if (likely(ts_delta <= csd_lock_timeout_ns || csd_lock_timeout_ns == 0)) {
+               *ts_save = ts2;
                return false;
+       }
+
+       if (unlikely((s64)ts_delta < 0)) {
+		/* How much clock went backwards */
+               ts_delta = *ts_save - ts2;
+               pr_alert("sched_clock on CPU %d went backward by %llu ns\n",
+                        raw_smp_processor_id(), ts_delta);
+               *ts0 -= ts_delta;
+               *ts1 -= ts_delta;
+       }
+	*ts_save = ts2;
 
        firsttime = !*bug_id;
        if (firsttime)
@@ -248,7 +260,7 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
                cpux = cpu;
        cpu_cur_csd = smp_load_acquire(&per_cpu(cur_csd, cpux)); /* Before func and info. */
        /* How long since this CSD lock was stuck. */
-       ts_delta = ts2 - ts0;
+       ts_delta = ts2 - *ts0;
        pr_alert("csd: %s non-responsive CSD lock (#%d) on CPU#%d, waiting %llu ns for CPU#%02d %pS(%ps).\n",
                 firsttime ? "Detected" : "Continued", *bug_id, raw_smp_processor_id(), ts_delta,
                 cpu, csd->func, csd->info);
@@ -291,11 +303,11 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
 static void __csd_lock_wait(call_single_data_t *csd)
 {
        int bug_id = 0;
-       u64 ts0, ts1;
+       u64 ts0, ts1, ts_s = 0;
 
        ts1 = ts0 = sched_clock();
        for (;;) {
-               if (csd_lock_wait_toolong(csd, ts0, &ts1, &bug_id))
+               if (csd_lock_wait_toolong(csd, &ts0, &ts1, &ts_s, &bug_id))
                        break;
                cpu_relax();
        }
##########

Suggestion B: Compare to ts_save to ts2 before calculating ts_delta.
Pros: 	Much better detection of clock goin backwards
Cons: 	Overhead for the fastpath
	More detections -> more messages, which is not necessarily good.

##########
+++ b/kernel/smp.c
@@ -234,6 +234,15 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 *ts0, u64 *ts1, u
        }
 
        ts2 = sched_clock();
+       if (unlikely(*ts_save > ts2)){
+               /* How much clock went backwards */
+               ts_delta = *ts_save - ts2;
+               pr_alert("sched_clock on CPU %d went backward by %llu ns\n",
+                       raw_smp_processor_id(), ts_delta);
+               *ts0 -= ts_delta;
+               *ts1 -= ts_delta;
+       }
+       *ts_save = ts2;
 
        /* How long since we last checked for a stuck CSD lock.*/
        ts_delta = ts2 - *ts1;
##########


What do you think?

Thanks!
Leo