Skip to contentSkip to conversation

powerpc/watchdog: provide more data in watchdog messages

PATCH In review Nicholas Piggin 2 participants 4 messages May 5, 2018 – May 10, 2018 PowerPC

lore
Share & tools
lore

Nicholas Piggin

author reviewer
#0 lore raw

v2 cover powerpc/watchdog: provide more data in watchdog messages

Since v1, Balbir's feedback:
- Split into two patches
- Added human-readable intervals as well as TB timestamps.

Nicholas Piggin (2):
powerpc/watchdog: don't update the watchdog timestamp if a lockup is
detected
powerpc/watchdog: provide more data in watchdog messages

 arch/powerpc/kernel/watchdog.c | 30 +++++++++++++++++++++++++-----
 1 file changed, 25 insertions(+), 5 deletions(-)
Signature · 1 line
2.17.0
author reviewer
#1 lore raw

PATCH v2 1/2 powerpc/watchdog: don't update the watchdog timestamp if a lockup is detected

The watchdog heartbeat timestamp is updated when the local heartbeat timer fires (or touch_nmi_watchdog() is called).

This is an interesting data point, so don't overwrite it when the soft-NMI interrupt detects a hard lockup. That code came from a pre- merge version to prevent hard lockup messages flood, but that's taken care of with the stuck CPU logic now, so there is no reason to update the heartbeat timestamp here.

Signed-off-by Nicholas Piggin <[email protected]>
---
 arch/powerpc/kernel/watchdog.c | 2 --
 1 file changed, 2 deletions(-)
arch/powerpc/kernel/watchdog.c +0 -2
index 6256dc3b0087..0bc701f9ab35 100644
@@ -245,8 +245,6 @@ void soft_nmi_interrupt(struct pt_regs *regs)
 
 	tb = get_tb();
 	if (tb - per_cpu(wd_timer_tb, cpu) >= wd_panic_timeout_tb) {
-		per_cpu(wd_timer_tb, cpu) = tb;
-
 		wd_smp_lock(&flags);
 		if (cpumask_test_cpu(cpu, &wd_smp_cpus_stuck)) {
 			wd_smp_unlock(&flags);
Signature · 1 line
2.17.0
#2 lore raw

Re: [v2, 1/2] powerpc/watchdog: don't update the watchdog timestamp if a lockup is detected

Quoted 10 lines · Nicholas Piggin

The watchdog heartbeat timestamp is updated when the local heartbeat timer fires (or touch_nmi_watchdog() is called).

This is an interesting data point, so don't overwrite it when the soft-NMI interrupt detects a hard lockup. That code came from a pre- merge version to prevent hard lockup messages flood, but that's taken care of with the stuck CPU logic now, so there is no reason to update the heartbeat timestamp here.

Signed-off-by Nicholas Piggin <[email protected]>

Series applied to powerpc next, thanks.

https://git.kernel.org/powerpc/c/5a951c4e7e8df5d6df52bace1b4ff3

cheers

author reviewer
#3 lore raw

PATCH v2 2/2 powerpc/watchdog: provide more data in watchdog messages

In reply to Nicholas Piggin

Provide timebase and timebase of last heartbeat in watchdog lockup messages. Also provide a stack trace of when a CPU becomes un-stuck, which can be useful -- it could be where irqs are re-enabled, so it may be the end of the critical section which is responsible for the latency which is useful information.

Signed-off-by Nicholas Piggin <[email protected]>
---
 arch/powerpc/kernel/watchdog.c | 28 +++++++++++++++++++++++++---
 1 file changed, 25 insertions(+), 3 deletions(-)
arch/powerpc/kernel/watchdog.c +25 -3
index 0bc701f9ab35..a99951e8199e 100644
@@ -111,7 +111,13 @@ static inline void wd_smp_unlock(unsigned long *flags)
 
 static void wd_lockup_ipi(struct pt_regs *regs)
 {
-	pr_emerg("CPU %d Hard LOCKUP\n", raw_smp_processor_id());
+	int cpu = raw_smp_processor_id();
+	u64 tb = get_tb();
+
+	pr_emerg("CPU %d Hard LOCKUP\n", cpu);
+	pr_emerg("CPU %d TB:%lld, last heartbeat TB:%lld (%lldms ago)\n",
+		 cpu, tb, per_cpu(wd_timer_tb, cpu),
+		 tb_to_ns(tb - per_cpu(wd_timer_tb, cpu)) / 1000000);
 	print_modules();
 	print_irqtrace_events(current);
 	if (regs)

@@ -154,6 +160,9 @@ static void watchdog_smp_panic(int cpu, u64 tb)
 
 	pr_emerg("CPU %d detected hard LOCKUP on other CPUs %*pbl\n",
 		 cpu, cpumask_pr_args(&wd_smp_cpus_pending));
+	pr_emerg("CPU %d TB:%lld, last SMP heartbeat TB:%lld (%lldms ago)\n",
+		 cpu, tb, wd_smp_last_reset_tb,
+		 tb_to_ns(tb - wd_smp_last_reset_tb) / 1000000);
 
 	if (!sysctl_hardlockup_all_cpu_backtrace) {
 		/*

@@ -194,10 +203,19 @@ static void wd_smp_clear_cpu_pending(int cpu, u64 tb)
 {
 	if (!cpumask_test_cpu(cpu, &wd_smp_cpus_pending)) {
 		if (unlikely(cpumask_test_cpu(cpu, &wd_smp_cpus_stuck))) {
+			struct pt_regs *regs = get_irq_regs();
 			unsigned long flags;
 
-			pr_emerg("CPU %d became unstuck\n", cpu);
 			wd_smp_lock(&flags);
+
+			pr_emerg("CPU %d became unstuck TB:%lld\n",
+				 cpu, tb);
+			print_irqtrace_events(current);
+			if (regs)
+				show_regs(regs);
+			else
+				dump_stack();
+
 			cpumask_clear_cpu(cpu, &wd_smp_cpus_stuck);
 			wd_smp_unlock(&flags);
 		}

@@ -252,7 +270,11 @@ void soft_nmi_interrupt(struct pt_regs *regs)
 		}
 		set_cpu_stuck(cpu, tb);
 
-		pr_emerg("CPU %d self-detected hard LOCKUP @ %pS\n", cpu, (void *)regs->nip);
+		pr_emerg("CPU %d self-detected hard LOCKUP @ %pS\n",
+			 cpu, (void *)regs->nip);
+		pr_emerg("CPU %d TB:%lld, last heartbeat TB:%lld (%lldms ago)\n",
+			 cpu, tb, per_cpu(wd_timer_tb, cpu),
+			 tb_to_ns(tb - per_cpu(wd_timer_tb, cpu)) / 1000000);
 		print_modules();
 		print_irqtrace_events(current);
 		show_regs(regs);
Signature · 1 line
2.17.0