x86: Avoid intermixing cpu dump_stack output on multi-processor systems

When multiple cpus on a multi-processor system call dump_stack() at the same time, the backtrace lines get intermixed, making the output worthless. Add a lock so each cpu stack dump comes out as a coherent set.

For example, when a multi-processor system is NMIed, all of the cpus call dump_stack() at the same time, resulting in output for all of cpus getting intermixed, making it impossible to tell what any individual cpu was doing. With this patch each cpu prints its stack lines as a coherent set, so one can see what each cpu was doing.

It has been tested on a 4069 cpu system.

Signed-off-by Russ Anderson <[email protected]>

Quoted 12 lines · Russ Anderson

When multiple cpus on a multi-processor system call dump_stack() at the same time, the backtrace lines get intermixed, making the output worthless. Add a lock so each cpu stack dump comes out as a coherent set.

For example, when a multi-processor system is NMIed, all of the cpus call dump_stack() at the same time, resulting in output for all of cpus getting intermixed, making it impossible to tell what any individual cpu was doing. With this patch each cpu prints its stack lines as a coherent set, so one can see what each cpu was doing.

Quoted 3 lines

It has been tested on a 4069 cpu system.

Signed-off-by Russ Anderson <[email protected]>

I don't think this is a good idea. What if an interrupt comes and calls this at the same time? Sure you can mask irqs but NMIs can call that too. In this case I prefer to have a messy report rather than a deadlock on the debug path.

May be something like that:

static atomic_t dump_lock = ATOMIC_INIT(-1);

static void dump_stack(void)

{
	int was_locked;
	int old;
	int cpu;

	preempt_disable();
retry:
	cpu = smp_processor_id();
	old = atomic_cmpxchg(&dump_lock, -1, cpu);
	if (old == -1) {
		was_locked = 0;
	} else if (old == cpu) {
		was_locked = 1;
	} else {
		cpu_relax();
		goto retry;
	}

	__dump_trace();

	if (!was_locked)
		atomic_set(&dump_lock, -1);

	preempt_enable();
}

You could also use a spinlock with irq disabled and test in_nmi() but we could have a dump_trace() in an NMI before the nmi count is incremented. So the above is perhaps more robust.
--

When multiple cpus on a multi-processor system call dump_stack() at the same time, the backtrace lines get intermixed, making the output worthless. Add a lock so each cpu stack dump comes out as a coherent set.

For example, when a multi-processor system is NMIed, all of the cpus call dump_stack() at the same time, resulting in output for all of cpus getting intermixed, making it impossible to tell what any individual cpu was doing. With this patch each cpu prints its stack lines as a coherent set, so one can see what each cpu was doing.

It has been tested on a 4069 cpu system.

Signed-off-by Russ Anderson <[email protected]>

---
 arch/x86/kernel/dumpstack.c |    3 +++
 1 file changed, 3 insertions(+)

Index: linux/arch/x86/kernel/dumpstack.c
===================================================================

arch/x86/kernel/dumpstack.c +3 -0

@@ -186,7 +186,9 @@ void dump_stack(void)
 {
 	unsigned long bp;
 	unsigned long stack;
+	static DEFINE_SPINLOCK(lock);	/* Serialise the printks */
 
+	spin_lock(&lock);
 	bp = stack_frame(current, NULL);
 	printk("Pid: %d, comm: %.20s %s %s %.*s\n",
 		current->pid, current->comm, print_tainted(),

@@ -194,6 +196,7 @@ void dump_stack(void)
 		(int)strcspn(init_utsname()->version, " "),
 		init_utsname()->version);
 	show_trace(NULL, NULL, &stack, bp);
+	spin_unlock(&lock);
 }
 EXPORT_SYMBOL(dump_stack);
 

Signature · 7 lines

Russ Anderson, OS RAS/Partitioning Project Lead  
SGI - Silicon Graphics Inc          [email protected]
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Quoted 11 lines · Russ Anderson

When multiple cpus on a multi-processor system call dump_stack() at the same time, the backtrace lines get intermixed, making the output worthless. Add a lock so each cpu stack dump comes out as a coherent set.

For example, when a multi-processor system is NMIed, all of the cpus call dump_stack() at the same time, resulting in output for all of cpus getting intermixed, making it impossible to tell what any individual cpu was doing. With this patch each cpu prints its stack lines as a coherent set, so one can see what each cpu was doing.

For this particular test case, it sounds like you are doing what trigger_all_cpu_backtrace() is doing? It doesn't solve the general problem, but probably your particular usage?

Cheers,
Don

Quoted 39 lines

It has been tested on a 4069 cpu system.

Signed-off-by Russ Anderson <[email protected]>

---
 arch/x86/kernel/dumpstack.c |    3 +++
 1 file changed, 3 insertions(+)

Index: linux/arch/x86/kernel/dumpstack.c
===================================================================

arch/x86/kernel/dumpstack.c +3 -0

@@ -186,7 +186,9 @@ void dump_stack(void)
 {
 	unsigned long bp;
 	unsigned long stack;
+	static DEFINE_SPINLOCK(lock);	/* Serialise the printks */
 
+	spin_lock(&lock);
 	bp = stack_frame(current, NULL);
 	printk("Pid: %d, comm: %.20s %s %s %.*s\n",
 		current->pid, current->comm, print_tainted(),

@@ -194,6 +196,7 @@ void dump_stack(void)
 		(int)strcspn(init_utsname()->version, " "),
 		init_utsname()->version);
 	show_trace(NULL, NULL, &stack, bp);
+	spin_unlock(&lock);
 }
 EXPORT_SYMBOL(dump_stack);
 

Signature · 7 lines

Russ Anderson, OS RAS/Partitioning Project Lead  
SGI - Silicon Graphics Inc          [email protected]
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Quoted 13 lines · Don Zickus

Quoted 11 lines · Russ Anderson

When multiple cpus on a multi-processor system call dump_stack() at the same time, the backtrace lines get intermixed, making the output worthless. Add a lock so each cpu stack dump comes out as a coherent set.

For example, when a multi-processor system is NMIed, all of the cpus call dump_stack() at the same time, resulting in output for all of cpus getting intermixed, making it impossible to tell what any individual cpu was doing. With this patch each cpu prints its stack lines as a coherent set, so one can see what each cpu was doing.

Quoted 3 lines

For this particular test case, it sounds like you are doing what trigger_all_cpu_backtrace() is doing? It doesn't solve the general problem, but probably your particular usage?

In this case, I am just using the hardware NMI, which sends the NMI signal to each logical cpu. Since each cpu receives the NMI at nearly the exact same time, they end up in dump_stack() at the same time. Without some form of locking, trace lines from different cpus end up intermixed, making it impossible to tell what any individual cpu was doing.

Quoted 18 lines · Russ Anderson

Quoted 13 lines · Don Zickus

Quoted 11 lines · Russ Anderson

When multiple cpus on a multi-processor system call dump_stack() at the same time, the backtrace lines get intermixed, making the output worthless. Add a lock so each cpu stack dump comes out as a coherent set.

For example, when a multi-processor system is NMIed, all of the cpus call dump_stack() at the same time, resulting in output for all of cpus getting intermixed, making it impossible to tell what any individual cpu was doing. With this patch each cpu prints its stack lines as a coherent set, so one can see what each cpu was doing.

Quoted 3 lines

For this particular test case, it sounds like you are doing what trigger_all_cpu_backtrace() is doing? It doesn't solve the general problem, but probably your particular usage?

Quoted 6 lines

In this case, I am just using the hardware NMI, which sends the NMI signal to each logical cpu. Since each cpu receives the NMI at nearly the exact same time, they end up in dump_stack() at the same time. Without some form of locking, trace lines from different cpus end up intermixed, making it impossible to tell what any individual cpu was doing.

I forgot the original reasons for having the NMI go to each CPU instead of just the boot CPU (commit 78c06176), but it seems like if you revert that patch and have the nmi handler just call trigger_all_cpu_backtrace() instead (which does stack trace locking for pretty output), that would solve your problem, no? That locking is safe because it is only called in the NMI context.

Whereas the lock you are proposing can be called in a mixture of NMI and IRQ which could cause deadlocks I believe.

Cheers,
Don

Quoted 7 lines

Quoted 6 lines

In this case, I am just using the hardware NMI, which sends the NMI signal to each logical cpu. Since each cpu receives the NMI at nearly the exact same time, they end up in dump_stack() at the same time. Without some form of locking, trace lines from different cpus end up intermixed, making it impossible to tell what any individual cpu was doing.

Quoted 6 lines

I forgot the original reasons for having the NMI go to each CPU instead of just the boot CPU (commit 78c06176), but it seems like if you revert that patch and have the nmi handler just call trigger_all_cpu_backtrace() instead (which does stack trace locking for pretty output), that would solve your problem, no? That locking is safe because it is only called in the NMI context.

We want NMI to hit all the cpus at the same time to get a coherent snapshot of what is happening in the system at one point in time. Sending an IPI one cpu at a time skews the results, and doesn't

really solve the problem of multiple cpus going into dump_stack() at the same time. NMI isn't the only possible caller of dump_stack().

FWIW, "Wait for up to 10 seconds for all CPUs to do the backtrace" on a 4096 cpu system isn't long enough. :-)

Quoted 3 lines

Whereas the lock you are proposing can be called in a mixture of NMI and IRQ which could cause deadlocks I believe.

Since this is a lock just around the dump_stack printk, would checking for forward progress and a timeout to catch any possible deadlock be sufficient? In the unlikely case of a deadlock the lock gets broken and some of the cpu backtraces get intermixed. That is still a huge improvement over the current case where all of the backtraces get intermixed.

Quoted 14 lines · Russ Anderson

Quoted 7 lines

Quoted 6 lines

In this case, I am just using the hardware NMI, which sends the NMI signal to each logical cpu. Since each cpu receives the NMI at nearly the exact same time, they end up in dump_stack() at the same time. Without some form of locking, trace lines from different cpus end up intermixed, making it impossible to tell what any individual cpu was doing.

Quoted 6 lines

I forgot the original reasons for having the NMI go to each CPU instead of just the boot CPU (commit 78c06176), but it seems like if you revert that patch and have the nmi handler just call trigger_all_cpu_backtrace() instead (which does stack trace locking for pretty output), that would solve your problem, no? That locking is safe because it is only called in the NMI context.

Quoted 3 lines

We want NMI to hit all the cpus at the same time to get a coherent snapshot of what is happening in the system at one point in time. Sending an IPI one cpu at a time skews the results, and doesn't

Oh, I thought it was broadcasting, but I see the apic_uv code serializes it. Though getting all those hardware locks in the nmi handler has to be time consuming? But I know you guys did some tricks to speed that up.

Quoted 2 lines

really solve the problem of multiple cpus going into dump_stack() at the same time. NMI isn't the only possible caller of dump_stack().

I am curious, your NMI handler has locking wrapped around dump_stack, shouldn't that serialize the output the way you want it? Why isn't that working?

Quoted 2 lines

FWIW, "Wait for up to 10 seconds for all CPUs to do the backtrace" on a 4096 cpu system isn't long enough. :-)

Good point. :-)

Quoted 10 lines

Quoted 3 lines

Whereas the lock you are proposing can be called in a mixture of NMI and IRQ which could cause deadlocks I believe.

Since this is a lock just around the dump_stack printk, would checking for forward progress and a timeout to catch any possible deadlock be sufficient? In the unlikely case of a deadlock the lock gets broken and some of the cpu backtraces get intermixed. That is still a huge improvement over the current case where all of the backtraces get intermixed.

I saw your new patch based on Frederick's input. It seems to take care of deadlock situations though you run into the starving lock problem that ticketed spinlocks solved. Which is why I am curious why moving the locking one layer up to the NMI handler (which is where it is currently), didn't fix your problem.

Quoted 3 lines

I am curious, your NMI handler has locking wrapped around dump_stack, shouldn't that serialize the output the way you want it? Why isn't that working?

Yes, you're right, it does. It is working. I'd forgotten that the community kernel has uv_nmi_lock in uv_handle_nmi. Must be working too much with distro kernels. :-) But that doesn't help for all the other code paths than call dump_stack.

Quoted 18 lines

Quoted 4 lines

FWIW, "Wait for up to 10 seconds for all CPUs to do the backtrace" on a 4096 cpu system isn't long enough. :-)

Good point. :-)

Quoted 10 lines

Quoted 3 lines

Whereas the lock you are proposing can be called in a mixture of NMI and IRQ which could cause deadlocks I believe.

Since this is a lock just around the dump_stack printk, would checking for forward progress and a timeout to catch any possible deadlock be sufficient? In the unlikely case of a deadlock the lock gets broken and some of the cpu backtraces get intermixed. That is still a huge improvement over the current case where all of the backtraces get intermixed.

Quoted 5 lines

I saw your new patch based on Frederick's input. It seems to take care of deadlock situations though you run into the starving lock problem that ticketed spinlocks solved. Which is why I am curious why moving the locking one layer up to the NMI handler (which is where it is currently), didn't fix your problem.

Locking in dump_stack would remove the need for uv_nmi_lock.