random debug patches

PATCH In review Peter Zijlstra 4 participants 11 messages Mar 18, 2016 – Mar 19, 2016 Tracing

Share & tools

Peter Zijlstra

author

2016-03-18 15:32 UTC #0 lore raw

cover random debug patches

The only relation between these patches is that they are the result of me trying to hunt down fail. Other than that they're unrelated and can be independently applied.

Peter Zijlstra

author

2016-03-18 15:32 UTC #1 lore raw

PATCH 1/2 watchdog: Fix output

The pr_crap() functions generate idiotic output; use printk().

Broken output:

[ 3538.718135] NMI watchdog: BUG: soft lockup - CPU#2 stuck for 22s!  [perf_fuzzer:2646]
[ 3383.233583] NMI watchdog: Watchdog detected hard LOCKUP on cpu 27

Fixed output:

[14180.328194] BUG: soft lockup - CPU#2 stuck for 23s!  [perf_fuzzer:13650]
[ 1064.914925] BUG: NMI Watchdog detected hard LOCKUP on cpu 11

Cc Don Zickus <[email protected]>

Signed-off-by Peter Zijlstra (Intel) <[email protected]>

---
 kernel/watchdog.c |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

kernel/watchdog.c +2 -2

@@ -350,7 +350,7 @@ static void watchdog_overflow_callback(s
 		if (__this_cpu_read(hard_watchdog_warn) == true)
 			return;
 
-		pr_emerg("Watchdog detected hard LOCKUP on cpu %d", this_cpu);
+		printk(KERN_EMERG "BUG: NMI detected hard LOCKUP on cpu %d", this_cpu);
 		print_modules();
 		print_irqtrace_events(current);
 		if (regs)

@@ -467,7 +467,7 @@ static enum hrtimer_restart watchdog_tim
 			}
 		}
 
-		pr_emerg("BUG: soft lockup - CPU#%d stuck for %us! [%s:%d]\n",
+		printk(KERN_EMERG "BUG: soft lockup - CPU#%d stuck for %us! [%s:%d]\n",
 			smp_processor_id(), duration,
 			current->comm, task_pid_nr(current));
 		__this_cpu_write(softlockup_task_ptr_saved, current);

Don Zickus

2016-03-18 16:37 UTC #2 lore raw

Re: [PATCH 1/2] watchdog: Fix output

Quoted 11 lines · Peter Zijlstra

The pr_crap() functions generate idiotic output; use printk().

Broken output:

[ 3538.718135] NMI watchdog: BUG: soft lockup - CPU#2 stuck for 22s!  [perf_fuzzer:2646]
[ 3383.233583] NMI watchdog: Watchdog detected hard LOCKUP on cpu 27

Fixed output:

[14180.328194] BUG: soft lockup - CPU#2 stuck for 23s!  [perf_fuzzer:13650]
[ 1064.914925] BUG: NMI Watchdog detected hard LOCKUP on cpu 11

Would something like this be a better patch?

Cheers,
Don

kernel/watchdog.c +3 -3

index b3ace6e..e3302a0 100644
@@ -9,7 +9,7 @@
  * to those contributors as well.
  */
 
-#define pr_fmt(fmt) "NMI watchdog: " fmt
+#define pr_fmt(fmt) "Lockup detector: " fmt
 
 #include <linux/mm.h>
 #include <linux/cpu.h>

@@ -350,7 +350,7 @@ static void watchdog_overflow_callback(struct perf_event *event,
 		if (__this_cpu_read(hard_watchdog_warn) == true)
 			return;
 
-		pr_emerg("Watchdog detected hard LOCKUP on cpu %d", this_cpu);
+		pr_emerg("Detected hard LOCKUP on cpu %d", this_cpu);
 		print_modules();
 		print_irqtrace_events(current);
 		if (regs)

@@ -467,7 +467,7 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer)
 			}
 		}
 
-		pr_emerg("BUG: soft lockup - CPU#%d stuck for %us! [%s:%d]\n",
+		pr_emerg("Detected soft lockup - CPU#%d stuck for %us! [%s:%d]\n",
 			smp_processor_id(), duration,
 			current->comm, task_pid_nr(current));
 		__this_cpu_write(softlockup_task_ptr_saved, current);

Quoted 29 lines

Cc Don Zickus <[email protected]>

Signed-off-by Peter Zijlstra (Intel) <[email protected]>

---
 kernel/watchdog.c |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

kernel/watchdog.c +2 -2

@@ -350,7 +350,7 @@ static void watchdog_overflow_callback(s
 		if (__this_cpu_read(hard_watchdog_warn) == true)
 			return;
 
-		pr_emerg("Watchdog detected hard LOCKUP on cpu %d", this_cpu);
+		printk(KERN_EMERG "BUG: NMI detected hard LOCKUP on cpu %d", this_cpu);
 		print_modules();
 		print_irqtrace_events(current);
 		if (regs)

@@ -467,7 +467,7 @@ static enum hrtimer_restart watchdog_tim
 			}
 		}
 
-		pr_emerg("BUG: soft lockup - CPU#%d stuck for %us! [%s:%d]\n",
+		printk(KERN_EMERG "BUG: soft lockup - CPU#%d stuck for %us! [%s:%d]\n",
 			smp_processor_id(), duration,
 			current->comm, task_pid_nr(current));
 		__this_cpu_write(softlockup_task_ptr_saved, current);

Peter Zijlstra

author

2016-03-18 16:46 UTC #3 lore raw

Re: [PATCH 1/2] watchdog: Fix output

Quoted 15 lines · Don Zickus

Quoted 11 lines · Peter Zijlstra
The pr_crap() functions generate idiotic output; use printk().
Broken output:
[ 3538.718135] NMI watchdog: BUG: soft lockup - CPU#2 stuck for 22s!  [perf_fuzzer:2646]
[ 3383.233583] NMI watchdog: Watchdog detected hard LOCKUP on cpu 27
Fixed output:
[14180.328194] BUG: soft lockup - CPU#2 stuck for 23s!  [perf_fuzzer:13650]
[ 1064.914925] BUG: NMI Watchdog detected hard LOCKUP on cpu 11
Would something like this be a better patch?

kernel/watchdog.c

Quoted 5 lines

kernel/watchdog.c +2 -2

-#define pr_fmt(fmt) "NMI watchdog: " fmt
+#define pr_fmt(fmt) "Lockup detector: " fmt
 
-		pr_emerg("Watchdog detected hard LOCKUP on cpu %d", this_cpu);
+		pr_emerg("Detected hard LOCKUP on cpu %d", this_cpu);

That still results in something like:

Lockup detector: Detected hard LOCKUP on cpu 22

Which is still weird, doesn't mention NMI nor BUG (and when the NMI triggers it really rather frequently is a dead system).

Peter Zijlstra

author

2016-03-18 16:49 UTC #4 lore raw

Re: [PATCH 1/2] watchdog: Fix output

Quoted 5 lines · Peter Zijlstra

kernel/watchdog.c line 12
Quoted 4 lines · Don Zickus
Would something like this be a better patch?
kernel/watchdog.c +1 -1
-#define pr_fmt(fmt) "NMI watchdog: " fmt
+#define pr_fmt(fmt) "Lockup detector: " fmt

You might want to audit all the other pr_ nonsense in that file; a lot of the msgs don't particularly make sense when combined with the prefix.

Some are for the NMI thing, others for the soft lockup one.

I would just chuck pr_crap() altogether and use sensible text.

Joe Perches

2016-03-18 17:42 UTC #5 lore raw

Re: [PATCH 1/2] watchdog: Fix output

Quoted 13 lines · Peter Zijlstra

Quoted 7 lines · Peter Zijlstra
kernel/watchdog.c line 12
Quoted 5 lines · Don Zickus
Would something like this be a better patch?
kernel/watchdog.c +1 -1
-#define pr_fmt(fmt) "NMI watchdog: " fmt
+#define pr_fmt(fmt) "Lockup detector: " fmt
You might want to audit all the other pr_ nonsense in that file; a lot
of the msgs don't particularly make sense when combined with the prefix.

Quoted 3 lines

Some are for the NMI thing, others for the soft lockup one.
I would just chuck pr_crap() altogether and use sensible text.

or change to #define pr_fmt(fmt) fmt

and output whatever unprefixed content you want.

btw: the first printk/pr_emerg should add a newline

	pr_emerg("Watchdog detected hard LOCKUP on cpu %d", this_cpu);
sb:
	pr_emerg("Watchdog detected hard LOCKUP on cpu %d\n", this_cpu);

Don Zickus

2016-03-18 18:12 UTC #6 lore raw

Re: [PATCH 1/2] watchdog: Fix output

In reply to Peter Zijlstra

Quoted 10 lines · Peter Zijlstra

Quoted 5 lines · Peter Zijlstra
kernel/watchdog.c line 12
Quoted 4 lines · Don Zickus
Would something like this be a better patch?
kernel/watchdog.c +1 -1
-#define pr_fmt(fmt) "NMI watchdog: " fmt
+#define pr_fmt(fmt) "Lockup detector: " fmt
You might want to audit all the other pr_ nonsense in that file; a lot of the msgs don't particularly make sense when combined with the prefix.

Quoted 3 lines

Some are for the NMI thing, others for the soft lockup one.
I would just chuck pr_crap() altogether and use sensible text.

Hehe. I'll look into that next week. :-)

Cheers,
Don

Peter Zijlstra

author

2016-03-18 17:50 UTC #7 lore raw

Re: [PATCH 1/2] watchdog: Fix output

In reply to Don Zickus

Quoted 11 lines · Don Zickus

+++ b/kernel/watchdog.c

kernel/watchdog.c +1 -1

@@ -9,7 +9,7 @@
  * to those contributors as well.
  */
 
-#define pr_fmt(fmt) "NMI watchdog: " fmt
+#define pr_fmt(fmt) "Lockup detector: " fmt
 
 #include <linux/mm.h>
 #include <linux/cpu.h>

kernel/watchdog.c static void watchdog_overflow_callback(struct perf_event *event, · line 356

Quoted 8 lines

kernel/watchdog.c +1 -1

@@ -350,7 +350,7 @@ static void watchdog_overflow_callback(struct perf_event *event,
 		if (__this_cpu_read(hard_watchdog_warn) == true)
 			return;
 
-		pr_emerg("Watchdog detected hard LOCKUP on cpu %d", this_cpu);
+		pr_emerg("Detected hard LOCKUP on cpu %d", this_cpu);
 		print_modules();
 		print_irqtrace_events(current);
 		if (regs)

It was Jiri who made this mess by replacing WARN(), which has a very distinct format, with this custom stuff.

I think we should go back to the WARN() thing.

Jiri Kosina

2016-03-19 00:11 UTC #8 lore raw

Re: [PATCH 1/2] watchdog: Fix output

Quoted 9 lines · Peter Zijlstra

Quoted 9 lines

kernel/watchdog.c +1 -1

-#define pr_fmt(fmt) "NMI watchdog: " fmt
+#define pr_fmt(fmt) "Lockup detector: " fmt
 
 #include <linux/mm.h>
 #include <linux/cpu.h>

@@ -350,7 +350,7 @@ static void watchdog_overflow_callback(struct perf_event *event,
 		if (__this_cpu_read(hard_watchdog_warn) == true)
 			return;

Quoted 8 lines

kernel/watchdog.c static void watchdog_overflow_callback(struct perf_event *event, · line 356
Quoted 5 lines
kernel/watchdog.c +1 -1
-		pr_emerg("Watchdog detected hard LOCKUP on cpu %d", this_cpu);
+		pr_emerg("Detected hard LOCKUP on cpu %d", this_cpu);
 		print_modules();
 		print_irqtrace_events(current);
 		if (regs)
It was Jiri who made this mess by replacing WARN(), which has a very distinct format, with this custom stuff.

Right, this was in 55537871e ("kernel/watchdog.c: perform all-CPU backtrace in case of hard lockup").

To be really honest, I don't really have 100% reliable explanation why I did it this way; I *think* it was because otherwise, in case WARN is preserved, we'll either

- have different output format for current (warning) CPU and all the others (trigger_allbutself_cpu_backtrace())

- have duplicated backtrace for current CPU, one coming from WARN and one coming from the all-cpu backtrace

Quoted 1 line

I think we should go back to the WARN() thing.

I don't really have strong opinion on this, but someone should pick the poison from the two options above; I tried in the mentioned commit, but apparently not to general satisfaction :)

Thanks,

Signature · 2 lines

Jiri Kosina
SUSE Labs

Jiri Kosina

2016-03-19 00:39 UTC #9 lore raw

Re: [PATCH 1/2] watchdog: Fix output

Quoted 15 lines · Jiri Kosina

Quoted 2 lines
It was Jiri who made this mess by replacing WARN(), which has a very distinct format, with this custom stuff.
Right, this was in 55537871e ("kernel/watchdog.c: perform all-CPU backtrace in case of hard lockup").
To be really honest, I don't really have 100% reliable explanation why I did it this way; I *think* it was because otherwise, in case WARN is preserved, we'll either
- have different output format for current (warning) CPU and all the others (trigger_allbutself_cpu_backtrace())
or

Quoted 8 lines

- have duplicated backtrace for current CPU, one coming from WARN and one coming from the all-cpu backtrace
Quoted 1 line
I think we should go back to the WARN() thing.
I don't really have strong opinion on this, but someone should pick the poison from the two options above; I tried in the mentioned commit, but apparently not to general satisfaction :)

Hmm, or we can actually make the whole thing behave the way that was introduced by 55537871e only in case of sysctl_hardlockup_all_cpu_backtrace being set, and use WARN() otherwise.

I'll send out a patch for this during / after the weekend if noone else beats me to do it.

Signature · 2 lines

Jiri Kosina
SUSE Labs

Peter Zijlstra

author

2016-03-18 15:32 UTC #10 lore raw

PATCH 2/2 trace: Record and show NMI state

In reply to Peter Zijlstra

The latency tracer format has a nice column to indicate IRQ state, but this is not able to tell us about NMI state.

When tracing perf interrupt handlers (which often run in NMI context) it is very useful to see how the events nest.

Signed-off-by Peter Zijlstra (Intel) <[email protected]>

---
 kernel/trace/trace.c        |    1 +
 kernel/trace/trace.h        |    1 +
 kernel/trace/trace_output.c |   10 +++++++---
 3 files changed, 9 insertions(+), 3 deletions(-)

kernel/trace/trace.c +1 -0

@@ -1662,6 +1662,7 @@ tracing_generic_entry_update(struct trac
 #else
 		TRACE_FLAG_IRQS_NOSUPPORT |
 #endif
+		((pc & NMI_MASK    ) ? TRACE_FLAG_NMI     : 0) |
 		((pc & HARDIRQ_MASK) ? TRACE_FLAG_HARDIRQ : 0) |
 		((pc & SOFTIRQ_MASK) ? TRACE_FLAG_SOFTIRQ : 0) |
 		(tif_need_resched() ? TRACE_FLAG_NEED_RESCHED : 0) |

kernel/trace/trace.h +1 -0

@@ -125,6 +125,7 @@ enum trace_flag_type {
 	TRACE_FLAG_HARDIRQ		= 0x08,
 	TRACE_FLAG_SOFTIRQ		= 0x10,
 	TRACE_FLAG_PREEMPT_RESCHED	= 0x20,
+	TRACE_FLAG_NMI			= 0x40,
 };
 
 #define TRACE_BUF_SIZE		1024

kernel/trace/trace_output.c +7 -3

@@ -389,7 +389,9 @@ int trace_print_lat_fmt(struct trace_seq
 	char irqs_off;
 	int hardirq;
 	int softirq;
+	int nmi;
 
+	nmi = entry->flags & TRACE_FLAG_NMI;
 	hardirq = entry->flags & TRACE_FLAG_HARDIRQ;
 	softirq = entry->flags & TRACE_FLAG_SOFTIRQ;

@@ -415,10 +417,12 @@ int trace_print_lat_fmt(struct trace_seq
 	}
 
 	hardsoft_irq =
+		(nmi && hardirq)     ? 'Z' :
+		nmi                  ? 'z' :
 		(hardirq && softirq) ? 'H' :
-		hardirq ? 'h' :
-		softirq ? 's' :
-		'.';
+		hardirq              ? 'h' :
+		softirq              ? 's' :
+		                       '.' ;
 
 	trace_seq_printf(s, "%c%c%c",
 			 irqs_off, need_resched, hardsoft_irq);