From: "Steven Rostedt (Red Hat)" <[email protected]>
When trigger_all_cpu_backtrace() is called on x86, it will trigger an
NMI on each CPU and call show_regs(). But this can lead to a hard lock
up if the NMI comes in on another printk().
In order to avoid this, when the NMI triggers, it switches the printk
routine for that CPU to call a NMI safe printk function that records the
printk in a per_cpu seq_buf descriptor. After all NMIs have finished
recording its data, the trace_seqs are printed in a safe context.
Link: http://lkml.kernel.org/p/[email protected]
Acked-by: Paul E. McKenney <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
---
arch/x86/kernel/apic/hw_nmi.c | 90 ++++++++++++++++++++++++++++++++++++++++---
1 file changed, 85 insertions(+), 5 deletions(-)
diff --git a/arch/x86/kernel/apic/hw_nmi.c b/arch/x86/kernel/apic/hw_nmi.c
index 6a1e71bde323..6e7bb0bc6fcd 100644
--- a/arch/x86/kernel/apic/hw_nmi.c
+++ b/arch/x86/kernel/apic/hw_nmi.c
@@ -18,6 +18,7 @@
#include <linux/nmi.h>
#include <linux/module.h>
#include <linux/delay.h>
+#include <linux/seq_buf.h>
#ifdef CONFIG_HARDLOCKUP_DETECTOR
u64 hw_nmi_get_sample_period(int watchdog_thresh)
@@ -29,14 +30,35 @@ u64 hw_nmi_get_sample_period(int watchdog_thresh)
#ifdef arch_trigger_all_cpu_backtrace
/* For reliability, we're prepared to waste bits here. */
static DECLARE_BITMAP(backtrace_mask, NR_CPUS) __read_mostly;
+static cpumask_var_t printtrace_mask;
+
+#define NMI_BUF_SIZE 4096
+
+struct nmi_seq_buf {
+ unsigned char buffer[NMI_BUF_SIZE];
+ struct seq_buf seq;
+};
+
+/* Safe printing in NMI context */
+static DEFINE_PER_CPU(struct nmi_seq_buf, nmi_print_seq);
/* "in progress" flag of arch_trigger_all_cpu_backtrace */
static unsigned long backtrace_flag;
+static void print_seq_line(struct nmi_seq_buf *s, int last, int pos)
+{
+ const char *buf = s->buffer + last;
+
+ printk("%.*s", (pos - last) + 1, buf);
+}
+
void arch_trigger_all_cpu_backtrace(bool include_self)
{
+ struct nmi_seq_buf *s;
+ int len;
+ int cpu;
int i;
- int cpu = get_cpu();
+ int this_cpu = get_cpu();
if (test_and_set_bit(0, &backtrace_flag)) {
/*
@@ -49,7 +71,17 @@ void arch_trigger_all_cpu_backtrace(bool include_self)
cpumask_copy(to_cpumask(backtrace_mask), cpu_online_mask);
if (!include_self)
- cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask));
+ cpumask_clear_cpu(this_cpu, to_cpumask(backtrace_mask));
+
+ cpumask_copy(printtrace_mask, to_cpumask(backtrace_mask));
+ /*
+ * Set up per_cpu seq_buf buffers that the NMIs running on the other
+ * CPUs will write to.
+ */
+ for_each_cpu(cpu, to_cpumask(backtrace_mask)) {
+ s = &per_cpu(nmi_print_seq, cpu);
+ seq_buf_init(&s->seq, s->buffer, NMI_BUF_SIZE);
+ }
if (!cpumask_empty(to_cpumask(backtrace_mask))) {
pr_info("sending NMI to %s CPUs:\n",
@@ -65,11 +97,57 @@ void arch_trigger_all_cpu_backtrace(bool include_self)
touch_softlockup_watchdog();
}
+ /*
+ * Now that all the NMIs have triggered, we can dump out their
+ * back traces safely to the console.
+ */
+ for_each_cpu(cpu, printtrace_mask) {
+ int last_i = 0;
+
+ s = &per_cpu(nmi_print_seq, cpu);
+ len = s->seq.len;
+ if (!len)
+ continue;
+
+ /* Print line by line. */
+ for (i = 0; i < len; i++) {
+ if (s->buffer[i] == '\n') {
+ print_seq_line(s, last_i, i);
+ last_i = i + 1;
+ }
+ }
+ if (last_i < i - 1) {
+ print_seq_line(s, last_i, i);
+ pr_cont("\n");
+ }
+ }
+
clear_bit(0, &backtrace_flag);
smp_mb__after_atomic();
put_cpu();
}
+/*
+ * It is not safe to call printk() directly from NMI handlers.
+ * It may be fine if the NMI detected a lock up and we have no choice
+ * but to do so, but doing a NMI on all other CPUs to get a back trace
+ * can be done with a sysrq-l. We don't want that to lock up, which
+ * can happen if the NMI interrupts a printk in progress.
+ *
+ * Instead, we redirect the vprintk() to this nmi_vprintk() that writes
+ * the content into a per cpu seq_buf buffer. Then when the NMIs are
+ * all done, we can safely dump the contents of the seq_buf to a printk()
+ * from a non NMI context.
+ */
+static int nmi_vprintk(const char *fmt, va_list args)
+{
+ struct nmi_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
+ unsigned int len = s->seq.len;
+
+ seq_buf_vprintf(&s->seq, fmt, args);
+ return s->seq.len - len;
+}
+
static int
arch_trigger_all_cpu_backtrace_handler(unsigned int cmd, struct pt_regs *regs)
{
@@ -78,12 +156,14 @@ arch_trigger_all_cpu_backtrace_handler(unsigned int cmd, struct pt_regs *regs)
cpu = smp_processor_id();
if (cpumask_test_cpu(cpu, to_cpumask(backtrace_mask))) {
- static arch_spinlock_t lock = __ARCH_SPIN_LOCK_UNLOCKED;
+ printk_func_t printk_func_save = this_cpu_read(printk_func);
- arch_spin_lock(&lock);
+ /* Replace printk to write into the NMI seq */
+ this_cpu_write(printk_func, nmi_vprintk);
printk(KERN_WARNING "NMI backtrace for cpu %d\n", cpu);
show_regs(regs);
- arch_spin_unlock(&lock);
+ this_cpu_write(printk_func, printk_func_save);
+
cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask));
return NMI_HANDLED;
}
--
2.1.1
On Tue, 4 Nov 2014, Steven Rostedt wrote:
> From: "Steven Rostedt (Red Hat)" <[email protected]>
>
> When trigger_all_cpu_backtrace() is called on x86, it will trigger an
> NMI on each CPU and call show_regs(). But this can lead to a hard lock
> up if the NMI comes in on another printk().
>
> In order to avoid this, when the NMI triggers, it switches the printk
> routine for that CPU to call a NMI safe printk function that records the
> printk in a per_cpu seq_buf descriptor. After all NMIs have finished
> recording its data, the trace_seqs are printed in a safe context.
>
> Link: http://lkml.kernel.org/p/[email protected]
>
> Acked-by: Paul E. McKenney <[email protected]>
> Signed-off-by: Steven Rostedt <[email protected]>
I've been running the whole machinery that used to trigger very quickly
the complete hardlock of the machine (*) for the whole evening/night, and
it's still running flawlessly.
Plus, as I said previously, I agree with the whole idea (given the
general nastiness of the problem and given the fact this simply has to be
fixed without pointless delays).
I.e FWIW
Tested-by: Jiri Kosina <[email protected]>
Acked-by: Jiri Kosina <[email protected]>
for the whole series.
(*) heavy printk() workload (**) + sysrq-l in parallel
(**) iptables logging every incoming packet + flood ping from another
machine
Thanks,
--
Jiri Kosina
SUSE Labs
On Wed, 5 Nov 2014 00:05:12 +0100 (CET)
Jiri Kosina <[email protected]> wrote:
> On Tue, 4 Nov 2014, Steven Rostedt wrote:
>
> > From: "Steven Rostedt (Red Hat)" <[email protected]>
> >
> > When trigger_all_cpu_backtrace() is called on x86, it will trigger an
> > NMI on each CPU and call show_regs(). But this can lead to a hard lock
> > up if the NMI comes in on another printk().
> >
> > In order to avoid this, when the NMI triggers, it switches the printk
> > routine for that CPU to call a NMI safe printk function that records the
> > printk in a per_cpu seq_buf descriptor. After all NMIs have finished
> > recording its data, the trace_seqs are printed in a safe context.
Hmm, I need to update the change log to say seq_bufs instead of
trace_seqs.
> >
> > Link: http://lkml.kernel.org/p/[email protected]
> >
> > Acked-by: Paul E. McKenney <[email protected]>
> > Signed-off-by: Steven Rostedt <[email protected]>
>
> I've been running the whole machinery that used to trigger very quickly
> the complete hardlock of the machine (*) for the whole evening/night, and
> it's still running flawlessly.
>
> Plus, as I said previously, I agree with the whole idea (given the
> general nastiness of the problem and given the fact this simply has to be
> fixed without pointless delays).
>
> I.e FWIW
>
> Tested-by: Jiri Kosina <[email protected]>
> Acked-by: Jiri Kosina <[email protected]>
>
> for the whole series.
Thanks! I'll update the commits.
-- Steve
>
> (*) heavy printk() workload (**) + sysrq-l in parallel
> (**) iptables logging every incoming packet + flood ping from another
> machine
>
> Thanks,
>
On Tue 2014-11-04 10:52:49, Steven Rostedt wrote:
> From: "Steven Rostedt (Red Hat)" <[email protected]>
>
> When trigger_all_cpu_backtrace() is called on x86, it will trigger an
> NMI on each CPU and call show_regs(). But this can lead to a hard lock
> up if the NMI comes in on another printk().
>
> In order to avoid this, when the NMI triggers, it switches the printk
> routine for that CPU to call a NMI safe printk function that records the
> printk in a per_cpu seq_buf descriptor. After all NMIs have finished
> recording its data, the trace_seqs are printed in a safe context.
>
> Link: http://lkml.kernel.org/p/[email protected]
>
> Acked-by: Paul E. McKenney <[email protected]>
> Signed-off-by: Steven Rostedt <[email protected]>
> ---
> arch/x86/kernel/apic/hw_nmi.c | 90 ++++++++++++++++++++++++++++++++++++++++---
> 1 file changed, 85 insertions(+), 5 deletions(-)
>
> diff --git a/arch/x86/kernel/apic/hw_nmi.c b/arch/x86/kernel/apic/hw_nmi.c
> index 6a1e71bde323..6e7bb0bc6fcd 100644
> --- a/arch/x86/kernel/apic/hw_nmi.c
> +++ b/arch/x86/kernel/apic/hw_nmi.c
> @@ -18,6 +18,7 @@
> #include <linux/nmi.h>
> #include <linux/module.h>
> #include <linux/delay.h>
> +#include <linux/seq_buf.h>
>
> #ifdef CONFIG_HARDLOCKUP_DETECTOR
> u64 hw_nmi_get_sample_period(int watchdog_thresh)
> @@ -29,14 +30,35 @@ u64 hw_nmi_get_sample_period(int watchdog_thresh)
> #ifdef arch_trigger_all_cpu_backtrace
> /* For reliability, we're prepared to waste bits here. */
> static DECLARE_BITMAP(backtrace_mask, NR_CPUS) __read_mostly;
> +static cpumask_var_t printtrace_mask;
> +
> +#define NMI_BUF_SIZE 4096
> +
> +struct nmi_seq_buf {
> + unsigned char buffer[NMI_BUF_SIZE];
> + struct seq_buf seq;
> +};
> +
> +/* Safe printing in NMI context */
> +static DEFINE_PER_CPU(struct nmi_seq_buf, nmi_print_seq);
>
> /* "in progress" flag of arch_trigger_all_cpu_backtrace */
> static unsigned long backtrace_flag;
>
> +static void print_seq_line(struct nmi_seq_buf *s, int last, int pos)
I would rename the arguments:
"last -> first"
"pos -> last"
or maybe better would be to pass first positon and len.
> +{
> + const char *buf = s->buffer + last;
> +
> + printk("%.*s", (pos - last) + 1, buf);
> +}
> +{
> + const char *buf = s->buffer + last;
> +
> + printk("%.*s", (pos - last) + 1, buf);
> +}
> +
> void arch_trigger_all_cpu_backtrace(bool include_self)
> {
> + struct nmi_seq_buf *s;
> + int len;
> + int cpu;
> int i;
> - int cpu = get_cpu();
> + int this_cpu = get_cpu();
>
> if (test_and_set_bit(0, &backtrace_flag)) {
> /*
> @@ -49,7 +71,17 @@ void arch_trigger_all_cpu_backtrace(bool include_self)
>
> cpumask_copy(to_cpumask(backtrace_mask), cpu_online_mask);
> if (!include_self)
> - cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask));
> + cpumask_clear_cpu(this_cpu, to_cpumask(backtrace_mask));
> +
> + cpumask_copy(printtrace_mask, to_cpumask(backtrace_mask));
> + /*
> + * Set up per_cpu seq_buf buffers that the NMIs running on the other
> + * CPUs will write to.
> + */
> + for_each_cpu(cpu, to_cpumask(backtrace_mask)) {
> + s = &per_cpu(nmi_print_seq, cpu);
> + seq_buf_init(&s->seq, s->buffer, NMI_BUF_SIZE);
> + }
>
> if (!cpumask_empty(to_cpumask(backtrace_mask))) {
> pr_info("sending NMI to %s CPUs:\n",
> @@ -65,11 +97,57 @@ void arch_trigger_all_cpu_backtrace(bool include_self)
> touch_softlockup_watchdog();
> }
>
> + /*
> + * Now that all the NMIs have triggered, we can dump out their
> + * back traces safely to the console.
> + */
> + for_each_cpu(cpu, printtrace_mask) {
> + int last_i = 0;
> +
> + s = &per_cpu(nmi_print_seq, cpu);
> + len = s->seq.len;
If there is an seq_buf overflow, the len might be size + 1, so we need to do:
len = min(s->seq.len, s->size);
Well, we should create a function for this in seq_buf.h.
Alternatively, we might reconsider the overflow state,
use len == size and extra "overflow" flag in the seq_buf struct.
> + if (!len)
> + continue;
> +
> + /* Print line by line. */
> + for (i = 0; i < len; i++) {
> + if (s->buffer[i] == '\n') {
> + print_seq_line(s, last_i, i);
> + last_i = i + 1;
> + }
> + }
>
> + if (last_i < i - 1) {
IMHO, this should be:
if (last_i < i)
because last_i = i + 1. Otherwise, we would ignore state when there is
one character after a new line. For example, imagine the following:
buffer = "a\nb";
len = 3;
it will end with:
last_i = 2;
i = 3;
and we still need to print the "b".
> + print_seq_line(s, last_i, i);
If I get it correctly, (i == len) here and "printk_seq_line"
print_seq_line() prints the characters including "pos" value.
So, we should call:
print_seq_line(s, last_i, i - 1)
> + pr_cont("\n");
> + }
> + }
> +
I hope that I have got it correctly. It is getting late here and I
feel tired to see the off-by-one problems clearly ;-)
Best Regards,
Petr
On Thu, 6 Nov 2014 19:41:55 +0100
Petr Mladek <[email protected]> wrote:
> > /* "in progress" flag of arch_trigger_all_cpu_backtrace */
> > static unsigned long backtrace_flag;
> >
> > +static void print_seq_line(struct nmi_seq_buf *s, int last, int pos)
>
> I would rename the arguments:
>
> "last -> first"
> "pos -> last"
>
> or maybe better would be to pass first positon and len.
I switched it to "start" and "end" to not be confused by the last_i
that is being passed in.
>
> > +{
> > + const char *buf = s->buffer + last;
> > +
> > + printk("%.*s", (pos - last) + 1, buf);
> > +}
>
> >
> > + /*
> > + * Now that all the NMIs have triggered, we can dump out their
> > + * back traces safely to the console.
> > + */
> > + for_each_cpu(cpu, printtrace_mask) {
> > + int last_i = 0;
> > +
> > + s = &per_cpu(nmi_print_seq, cpu);
> > + len = s->seq.len;
>
> If there is an seq_buf overflow, the len might be size + 1, so we need to do:
>
> len = min(s->seq.len, s->size);
>
> Well, we should create a function for this in seq_buf.h.
> Alternatively, we might reconsider the overflow state,
> use len == size and extra "overflow" flag in the seq_buf struct.
>
>
> > + if (!len)
> > + continue;
> > +
> > + /* Print line by line. */
> > + for (i = 0; i < len; i++) {
> > + if (s->buffer[i] == '\n') {
> > + print_seq_line(s, last_i, i);
> > + last_i = i + 1;
> > + }
> > + }
> >
> > + if (last_i < i - 1) {
>
> IMHO, this should be:
>
> if (last_i < i)
>
> because last_i = i + 1. Otherwise, we would ignore state when there is
> one character after a new line. For example, imagine the following:
>
> buffer = "a\nb";
> len = 3;
>
> it will end with:
>
> last_i = 2;
> i = 3;
>
> and we still need to print the "b".
Well, we really don't *need* to ;-)
But for correctness sake, I agree, it should be last_i < i.
>
> > + print_seq_line(s, last_i, i);
>
> If I get it correctly, (i == len) here and "printk_seq_line"
> print_seq_line() prints the characters including "pos" value.
> So, we should call:
>
> print_seq_line(s, last_i, i - 1)
Right that was wrong. Actually, I think the best answer would be:
print_seq_line(s, last_i, len - 1);
This removes the variable 'i'. Probably should add a comment here too
that reminds the reviewer that print_seq_line() prints up to and
including the last index.
Note, my current code also has:
len = seq_buf_used(&s->seq);
where we don't need to worry about the semantics of seq_buf internals.
-- Steve
>
> > + pr_cont("\n");
> > + }
> > + }
> > +
>
On Fri 2014-11-07 13:56:09, Steven Rostedt wrote:
> On Thu, 6 Nov 2014 19:41:55 +0100
> Petr Mladek <[email protected]> wrote:
>
> > > /* "in progress" flag of arch_trigger_all_cpu_backtrace */
> > > static unsigned long backtrace_flag;
> > >
> > > +static void print_seq_line(struct nmi_seq_buf *s, int last, int pos)
> >
> > I would rename the arguments:
> >
> > "last -> first"
> > "pos -> last"
> >
> > or maybe better would be to pass first positon and len.
>
> I switched it to "start" and "end" to not be confused by the last_i
> that is being passed in.
I like it.
> >
> > > +{
> > > + const char *buf = s->buffer + last;
> > > +
> > > + printk("%.*s", (pos - last) + 1, buf);
> > > +}
> >
>
>
>
> > >
> > > + /*
> > > + * Now that all the NMIs have triggered, we can dump out their
> > > + * back traces safely to the console.
> > > + */
> > > + for_each_cpu(cpu, printtrace_mask) {
> > > + int last_i = 0;
> > > +
> > > + s = &per_cpu(nmi_print_seq, cpu);
> > > + len = s->seq.len;
> >
> > If there is an seq_buf overflow, the len might be size + 1, so we need to do:
> >
> > len = min(s->seq.len, s->size);
> >
> > Well, we should create a function for this in seq_buf.h.
> > Alternatively, we might reconsider the overflow state,
> > use len == size and extra "overflow" flag in the seq_buf struct.
> >
> >
> > > + if (!len)
> > > + continue;
> > > +
> > > + /* Print line by line. */
> > > + for (i = 0; i < len; i++) {
> > > + if (s->buffer[i] == '\n') {
> > > + print_seq_line(s, last_i, i);
> > > + last_i = i + 1;
> > > + }
> > > + }
> > >
> > > + if (last_i < i - 1) {
> >
> > IMHO, this should be:
> >
> > if (last_i < i)
> >
> > because last_i = i + 1. Otherwise, we would ignore state when there is
> > one character after a new line. For example, imagine the following:
> >
> > buffer = "a\nb";
> > len = 3;
> >
> > it will end with:
> >
> > last_i = 2;
> > i = 3;
> >
> > and we still need to print the "b".
>
> Well, we really don't *need* to ;-)
>
> But for correctness sake, I agree, it should be last_i < i.
I agree that one more character does not make much difference but
it might save someones day :-)
> >
> > > + print_seq_line(s, last_i, i);
> >
> > If I get it correctly, (i == len) here and "printk_seq_line"
> > print_seq_line() prints the characters including "pos" value.
> > So, we should call:
> >
> > print_seq_line(s, last_i, i - 1)
>
> Right that was wrong. Actually, I think the best answer would be:
>
> print_seq_line(s, last_i, len - 1);
Yup
> This removes the variable 'i'. Probably should add a comment here too
> that reminds the reviewer that print_seq_line() prints up to and
> including the last index.
Yes, the comment is worth having.
> Note, my current code also has:
>
> len = seq_buf_used(&s->seq);
>
> where we don't need to worry about the semantics of seq_buf internals.
Perfect
Thanks a lot for working on it. Please, resend this patch once you are
happy with it.
Best Regards,
Petr