[PATCH] smp/call: Detect stuck CSD locks

[Ingo Molnar]

* Chris J Arges <chris.j.arges@xxxxxxxxxxxxx> wrote:

> Ingo,
> 
> I think tracking IPI calls from 'generic_exec_single' would make a lot
> of sense. When you say poll for completion do you mean a loop after
> 'arch_send_call_function_single_ipi' in kernel/smp.c? My main concern
> would be to not alter the timings too much so we can still reproduce the
> original problem.
> 
> Another approach:
> If we want to check for non-ACKed IPIs a possibility would be to add a
> timestamp field to 'struct call_single_data' and just record jiffies
> when the IPI gets called. Then have a per-cpu kthread check the
> 'call_single_queue' percpu list periodically if (jiffies - timestamp) >
> THRESHOLD. When we reach that condition print the stale entry in
> call_single_queue, backtrace, then re-send the IPI.
> 
> Let me know what makes the most sense to hack on.

Well, the thing is, putting this polling into an async kernel thread 
loses a lot of data context and right of reference that we might need 
to re-send an IPI.

And if the context is not lost we might as well send it from the 
original, still-looping context - which is a lot simpler as well.

( ... and on a deadlocked non-CONFIG_PREEMPT kernel the kernel thread
  won't run at all, so it won't be able to detect deadlocks. )

So I'd really suggest instrumenting the already existing CSD polling, 
which is already a slowpath, so it won't impact timing much.
 
I'd suggest the following, rather unintrusive approach:

 - first just take a jiffies timestamp and generate a warning message 
   if more than 10 seconds elapsed after sending the IPI, without 
   having heard from it.

 - then the IPI is resent. This means adding a bit of a control flow 
   to csd_lock_wait().

Something like the patch below, which implements both steps:

  - It will detect and print CSD deadlocks both in the single- and 
    multi- function call APIs, and in the pre-IPI CSD lock wait case 
    as well.

  - It will resend an IPI if possible

  - It generates various messages in the deadlock case that should 
    give us some idea about how the deadlock played out and whether it 
    got resolved.

The timeout is set to 10 seconds, that should be plenty even in a 
virtualization environment.

Only very lightly tested under a simple lkvm bootup: I verified that 
the boilerplate message is displayed, and that it doesn't generate 
false positive messages in light loads - but I haven't checked whether 
the deadlock detection works at all.

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 = jiffies_to_msecs(jiffies);
+
+	if (unlikely(!csd_bug_count)) {
+		csd_bug_count++;
+		printk("csd: CSD deadlock debugging initiated!\n");
+	}
+
+	while (csd->flags & CSD_FLAG_LOCK) {
+		ts1 = jiffies_to_msecs(jiffies);
+
+		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);
 		}
 	}
 }
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/