Re: [PATCH] smp/call: Detect stuck CSD locks

[Ingo Molnar <mingo@kernel.org>]

* Linus Torvalds <torvalds@linux-foundation.org> wrote:

> On Mon, Apr 6, 2015 at 9:58 AM, Chris J Arges
> <chris.j.arges@canonical.com> wrote:
> >
> > I noticed that with this patch it never reached 'csd: Detected
> > non-responsive CSD lock...' because it seems that ts_delta never reached
> > CSD_LOCK_TIMEOUT. I tried adjusting the TIMEOUT value and still got a
> > hang without reaching this statement. I made the ts0,ts1 values global
> > and put a counter into the while loop and found that the loop iterated
> > about 670 million times before the softlockup was detected. In addition
> > ts0 and ts1 both had the same values upon soft lockup, and thus would
> > never trip the CSD_LOCK_TIMEOUT check.
> 
> Sounds like jiffies stops updating. Which doesn't sound unreasonable 
> for when there is some IPI problem.

Yeah - although it weakens the 'IPI lost spuriously' hypothesis: we 
ought to have irqs enabled here which normally doesn't stop jiffies 
from updating, and the timer interrupt stopping suggests a much deeper 
problem than just some lost IPI ...

> 
> How about just changing the debug patch to count iterations, and 
> print out a warning when it reaches ten million or so.

Yeah, or replace jiffies_to_ms() with:

	sched_clock()/1000000

sched_clock() should be safe to call in these codepaths.

Like the attached patch. (Totally untested.)

Thanks,

	Ingo

---

 kernel/smp.c | 51 ++++++++++++++++++++++++++++++++++++++++++++++-----
 1 file changed, 46 insertions(+), 5 deletions(-)

diff --git a/kernel/smp.c b/kernel/smp.c
index f38a1e692259..e0eec1ab3ef2 100644
--- a/kernel/smp.c
+++ b/kernel/smp.c
@@ -98,22 +98,63 @@ void __init call_function_init(void)
 	register_cpu_notifier(&hotplug_cfd_notifier);
 }
 
+/* Locking timeout in ms: */
+#define CSD_LOCK_TIMEOUT (10*1000ULL)
+
+/* Print this ID in every printk line we output, to be able to easily sort them apart: */
+static int csd_bug_count;
+
 /*
  * csd_lock/csd_unlock used to serialize access to per-cpu csd resources
  *
  * For non-synchronous ipi calls the csd can still be in use by the
  * previous function call. For multi-cpu calls its even more interesting
  * as we'll have to ensure no other cpu is observing our csd.
+ *
+ * ( The overhead of deadlock detection is not a big problem, this is a
+ *   cpu_relax() loop that is actively wasting CPU cycles to poll for
+ *   completion. )
  */
-static void csd_lock_wait(struct call_single_data *csd)
+static void csd_lock_wait(struct call_single_data *csd, int cpu)
 {
-	while (csd->flags & CSD_FLAG_LOCK)
+	int bug_id = 0;
+	u64 ts0, ts1, ts_delta;
+
+	ts0 = sched_clock()/1000000;
+
+	if (unlikely(!csd_bug_count)) {
+		csd_bug_count++;
+		printk("csd: CSD deadlock debugging initiated!\n");
+	}
+
+	while (csd->flags & CSD_FLAG_LOCK) {
+		ts1 = sched_clock()/1000000;
+
+		ts_delta = ts1-ts0;
+		if (unlikely(ts_delta >= CSD_LOCK_TIMEOUT)) { /* Uh oh, it took too long. Why? */
+
+			bug_id = csd_bug_count;
+			csd_bug_count++;
+
+			ts0 = ts1; /* Re-start the timeout detection */
+
+			printk("csd: Detected non-responsive CSD lock (#%d) on CPU#%02d, waiting %Ld.%03Ld secs for CPU#%02d\n",
+				bug_id, raw_smp_processor_id(), ts_delta/1000ULL, ts_delta % 1000ULL, cpu);
+			if (cpu >= 0) {
+				printk("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);
+			}
+			dump_stack();
+		}
 		cpu_relax();
+	}
+	if (unlikely(bug_id))
+		printk("csd: CSD lock (#%d) got unstuck on CPU#%02d, CPU#%02d released the lock after all. Phew!\n", bug_id, raw_smp_processor_id(), cpu);
 }
 
 static void csd_lock(struct call_single_data *csd)
 {
-	csd_lock_wait(csd);
+	csd_lock_wait(csd, -1);
 	csd->flags |= CSD_FLAG_LOCK;
 
 	/*
@@ -191,7 +232,7 @@ static int generic_exec_single(int cpu, struct call_single_data *csd,
 		arch_send_call_function_single_ipi(cpu);
 
 	if (wait)
-		csd_lock_wait(csd);
+		csd_lock_wait(csd, cpu);
 
 	return 0;
 }
@@ -446,7 +487,7 @@ void smp_call_function_many(const struct cpumask *mask,
 			struct call_single_data *csd;
 
 			csd = per_cpu_ptr(cfd->csd, cpu);
-			csd_lock_wait(csd);
+			csd_lock_wait(csd, cpu);
 		}
 	}
 }