[PATCH] locking/csd-lock: Report how long a stuck CSD lock took to recover

[PATCH] locking/csd-lock: Report how long a stuck CSD lock took to recover

[Breno Leitao]

The CSD lock debug output is a useful way to catch IPI stalls, but when
the lock finally recovers it only says that it did:

  smp: csd: CSD lock (#1) got unstuck on CPU#32, CPU#123 released the lock.

How long the target took to answer is left out, even though
csd_lock_wait_toolong() already has the timestamp the wait started from.

At Meta's fleet, that line fired 211K times in the last 24 hours, so
plenty of stalls get reported with no indication of how long they
lasted.

Print how long the lock was stuck, and, when an IPI was re-sent, how
long after that re-send the target released, as:

  smp: csd: CSD lock (#1) got unstuck on CPU#00, CPU#01 released the lock after 8000854660 ns, 3000825778 ns after the last IPI re-send.

Signed-off-by: Breno Leitao <leitao@debian.org>
---
 kernel/smp.c | 30 +++++++++++++++++++++++++-----
 1 file changed, 25 insertions(+), 5 deletions(-)

diff --git a/kernel/smp.c b/kernel/smp.c
index b696bcc60c08f..c09d5ca0c7ed6 100644
--- a/kernel/smp.c
+++ b/kernel/smp.c
@@ -236,12 +236,31 @@ bool csd_lock_is_stuck(void)
 	return !!atomic_read(&n_csd_lock_stuck);
 }
 
+/*
+ * Report a CSD lock that came back.  @ts_start is when the wait began and
+ * @ts_unstuck is when the release was noticed, both from
+ * ktime_get_mono_fast_ns().  A zero @ts_resend means no IPI was re-sent, so
+ * there is no re-send delta to report.
+ */
+static void csd_lock_print_unstuck(int bug_id, int cpu, u64 ts_start, u64 ts_unstuck,
+				   u64 ts_resend)
+{
+	if (ts_resend)
+		pr_alert("csd: CSD lock (#%d) got unstuck on CPU#%02d, CPU#%02d released the lock after %lld ns, %lld ns after the last IPI re-send.\n",
+			 bug_id, raw_smp_processor_id(), cpu, (s64)(ts_unstuck - ts_start),
+			 (s64)(ts_unstuck - ts_resend));
+	else
+		pr_alert("csd: CSD lock (#%d) got unstuck on CPU#%02d, CPU#%02d released the lock after %lld ns.\n",
+			 bug_id, raw_smp_processor_id(), cpu, (s64)(ts_unstuck - ts_start));
+}
+
 /*
  * Complain if too much time spent waiting.  Note that only
  * 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, unsigned long *nmessages)
+static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, u64 *ts_resend,
+				  int *bug_id, unsigned long *nmessages)
 {
 	int cpu = -1;
 	int cpux;
@@ -254,9 +273,9 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
 	if (!(flags & CSD_FLAG_LOCK)) {
 		if (!unlikely(*bug_id))
 			return true;
+		ts2 = ktime_get_mono_fast_ns();
 		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);
+		csd_lock_print_unstuck(*bug_id, cpu, ts0, ts2, *ts_resend);
 		atomic_dec(&n_csd_lock_stuck);
 		return true;
 	}
@@ -320,6 +339,7 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, in
 		if (!cpu_cur_csd) {
 			pr_alert("csd: Re-sending CSD lock (#%d) IPI from CPU#%02d to CPU#%02d\n", *bug_id, raw_smp_processor_id(), cpu);
 			arch_send_call_function_single_ipi(cpu);
+			*ts_resend = ktime_get_mono_fast_ns();
 		}
 	}
 	if (firsttime)
@@ -339,14 +359,14 @@ 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;
+	u64 ts0, ts1, ts_resend = 0;
 	int bug_id = 0;
-	u64 ts0, ts1;
 
 	guard(preempt)();
 
 	ts1 = ts0 = ktime_get_mono_fast_ns();
 	for (;;) {
-		if (csd_lock_wait_toolong(csd, ts0, &ts1, &bug_id, &nmessages))
+		if (csd_lock_wait_toolong(csd, ts0, &ts1, &ts_resend, &bug_id, &nmessages))
 			break;
 		cpu_relax();
 	}

---
base-commit: 0f6da28aab51b16762ed82e8fdeaa5042da45b08
change-id: 20260805-csd-stall-duration-3385343d7a08

Best regards,
--  
Breno Leitao <leitao@debian.org>

Re: [PATCH] locking/csd-lock: Report how long a stuck CSD lock took to recover

[Dmitry Ilvokhin]

On Wed, Aug 05, 2026 at 05:51:54AM -0700, Breno Leitao wrote:
>  /*
>   * Complain if too much time spent waiting.  Note that only
>   * 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, unsigned long *nmessages)
> +static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, u64 *ts_resend,
> +				  int *bug_id, unsigned long *nmessages)

nit: csd_lock_wait_toolong() has too many arguments now to my liking.
This was already a bit awkward before, maybe it is time for a small
clean up. Does it make sense to pack timestamps, bug_id and nmessages
into a struct and pass it around instead?

That could go in as a separate cleanup ahead of this one.

Other than that, it looks reasonable to me.

With or without that:

Reviewed-by: Dmitry Ilvokhin <d@ilvokhin.com>

Re: [PATCH] locking/csd-lock: Report how long a stuck CSD lock took to recover

[Breno Leitao]

On Fri, Aug 07, 2026 at 10:57:21AM +0000, Dmitry Ilvokhin wrote:
> On Wed, Aug 05, 2026 at 05:51:54AM -0700, Breno Leitao wrote:
> > -static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, int *bug_id, unsigned long *nmessages)
> > +static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, u64 *ts_resend,
> > +				  int *bug_id, unsigned long *nmessages)
> 
> nit: csd_lock_wait_toolong() has too many arguments now to my liking.
> This was already a bit awkward before, maybe it is time for a small
> clean up. Does it make sense to pack timestamps, bug_id and nmessages
> into a struct and pass it around instead?

I would say so. Also, those parameters (tsX) were a bit hard to
understand, and when I create the other function, I've tried to keep it
a bit more sane (ts_start, ts_unstuck, ts_resend) instead of tsX. 

> That could go in as a separate cleanup ahead of this one.

I am more than happy to do it. Let's see what Paul says.

> Other than that, it looks reasonable to me.
> 
> With or without that:
> 
> Reviewed-by: Dmitry Ilvokhin <d@ilvokhin.com>

Thanks for the review,
--breno

Re: [PATCH] locking/csd-lock: Report how long a stuck CSD lock took to recover

[Paul E. McKenney]

On Fri, Aug 07, 2026 at 06:16:33AM -0700, Breno Leitao wrote:
> On Fri, Aug 07, 2026 at 10:57:21AM +0000, Dmitry Ilvokhin wrote:
> > On Wed, Aug 05, 2026 at 05:51:54AM -0700, Breno Leitao wrote:
> > > -static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, int *bug_id, unsigned long *nmessages)
> > > +static bool csd_lock_wait_toolong(call_single_data_t *csd, u64 ts0, u64 *ts1, u64 *ts_resend,
> > > +				  int *bug_id, unsigned long *nmessages)
> > 
> > nit: csd_lock_wait_toolong() has too many arguments now to my liking.
> > This was already a bit awkward before, maybe it is time for a small
> > clean up. Does it make sense to pack timestamps, bug_id and nmessages
> > into a struct and pass it around instead?
> 
> I would say so. Also, those parameters (tsX) were a bit hard to
> understand, and when I create the other function, I've tried to keep it
> a bit more sane (ts_start, ts_unstuck, ts_resend) instead of tsX. 
> 
> > That could go in as a separate cleanup ahead of this one.
> 
> I am more than happy to do it. Let's see what Paul says.

When I split that function out, I was thinking of it strictly as an
internal interface.  But with the continued evolution, it would not
hurt to make it easier to deal with.  I have no objection to packing
them into a struct.

							Thanx, Paul

> > Other than that, it looks reasonable to me.
> > 
> > With or without that:
> > 
> > Reviewed-by: Dmitry Ilvokhin <d@ilvokhin.com>
> 
> Thanks for the review,
> --breno