Re: soft lockup in serial8250_console_write(?)

Re: soft lockup in serial8250_console_write(?)

[Ingo Molnar]

[-- Attachment #1: Type: text/plain, Size: 571 bytes --]


* Randy.Dunlap <rdunlap@xenotime.net> wrote:

> Hi,
> 
> (x86_64; 2.6.16-rc6; serial console configured but nothing connected 
> to the serial port)
> 
> I'm seeing an occasional soft lockup, maybe in 
> serial8250_console_write(). (drivers/serial/8250.c)
> 
> This function calls wait_for_xmitr() [inline], which in worst case can 
> spin for 1.010 seconds.  Could this be the cause of a soft lockup?

hm, it shouldnt cause that. Could you try the attached patch [which is 
the next-gen softlockup detector], do you get the message even with that 
one applied?

	Ingo


[-- Attachment #2: softlockup-timer-driven.patch --]
[-- Type: text/plain, Size: 6040 bytes --]

below is the latest softdog-rework patch, with all fixes (including 
Nathan's hotplug CPU fix) merged.

--------
this patch makes the softlockup detector purely timer-interrupt driven,
removing softirq-context (timer) dependencies. This means that if the
softlockup watchdog triggers, it has truly observed a longer than 10
seconds scheduling delay of a SCHED_FIFO prio 99 task.

(the patch also turns off the softlockup detector during the initial
bootup phase and does small style fixes)

Signed-off-by: Ingo Molnar <mingo@elte.hu>

----

 include/linux/sched.h |    4 +--
 kernel/softlockup.c   |   55 ++++++++++++++++++++++++++++----------------------
 kernel/timer.c        |    2 -
 3 files changed, 34 insertions(+), 27 deletions(-)

Index: linux-rt.q/include/linux/sched.h
===================================================================
--- linux-rt.q.orig/include/linux/sched.h
+++ linux-rt.q/include/linux/sched.h
@@ -208,11 +208,11 @@ extern void update_process_times(int use
 extern void scheduler_tick(void);
 
 #ifdef CONFIG_DETECT_SOFTLOCKUP
-extern void softlockup_tick(struct pt_regs *regs);
+extern void softlockup_tick(void);
 extern void spawn_softlockup_task(void);
 extern void touch_softlockup_watchdog(void);
 #else
-static inline void softlockup_tick(struct pt_regs *regs)
+static inline void softlockup_tick(void)
 {
 }
 static inline void spawn_softlockup_task(void)
Index: linux-rt.q/kernel/softlockup.c
===================================================================
--- linux-rt.q.orig/kernel/softlockup.c
+++ linux-rt.q/kernel/softlockup.c
@@ -1,12 +1,11 @@
 /*
  * Detect Soft Lockups
  *
- * started by Ingo Molnar, (C) 2005, Red Hat
+ * started by Ingo Molnar, Copyright (C) 2005, 2006 Red Hat, Inc.
  *
  * this code detects soft lockups: incidents in where on a CPU
  * the kernel does not reschedule for 10 seconds or more.
  */
-
 #include <linux/mm.h>
 #include <linux/cpu.h>
 #include <linux/init.h>
@@ -17,13 +16,14 @@
 
 static DEFINE_SPINLOCK(print_lock);
 
-static DEFINE_PER_CPU(unsigned long, timestamp) = 0;
-static DEFINE_PER_CPU(unsigned long, print_timestamp) = 0;
+static DEFINE_PER_CPU(unsigned long, touch_timestamp);
+static DEFINE_PER_CPU(unsigned long, print_timestamp);
 static DEFINE_PER_CPU(struct task_struct *, watchdog_task);
 
 static int did_panic = 0;
-static int softlock_panic(struct notifier_block *this, unsigned long event,
-				void *ptr)
+
+static int
+softlock_panic(struct notifier_block *this, unsigned long event, void *ptr)
 {
 	did_panic = 1;
 
@@ -36,7 +36,7 @@ static struct notifier_block panic_block
 
 void touch_softlockup_watchdog(void)
 {
-	per_cpu(timestamp, raw_smp_processor_id()) = jiffies;
+	per_cpu(touch_timestamp, raw_smp_processor_id()) = jiffies;
 }
 EXPORT_SYMBOL(touch_softlockup_watchdog);
 
@@ -44,25 +44,35 @@ EXPORT_SYMBOL(touch_softlockup_watchdog)
  * This callback runs from the timer interrupt, and checks
  * whether the watchdog thread has hung or not:
  */
-void softlockup_tick(struct pt_regs *regs)
+void softlockup_tick(void)
 {
 	int this_cpu = smp_processor_id();
-	unsigned long timestamp = per_cpu(timestamp, this_cpu);
+	unsigned long touch_timestamp = per_cpu(touch_timestamp, this_cpu);
 
-	if (per_cpu(print_timestamp, this_cpu) == timestamp)
+	/* prevent double reports: */
+	if (per_cpu(print_timestamp, this_cpu) == touch_timestamp ||
+		did_panic ||
+			!per_cpu(watchdog_task, this_cpu))
 		return;
 
-	/* Do not cause a second panic when there already was one */
-	if (did_panic)
+	/* do not print during early bootup: */
+	if (unlikely(system_state != SYSTEM_RUNNING)) {
+		touch_softlockup_watchdog();
 		return;
+	}
 
-	if (time_after(jiffies, timestamp + 10*HZ)) {
-		per_cpu(print_timestamp, this_cpu) = timestamp;
+	/* Wake up the high-prio watchdog task every second: */
+	if (time_after(jiffies, touch_timestamp + HZ))
+		wake_up_process(per_cpu(watchdog_task, this_cpu));
+
+	/* Warn about unreasonable 10+ seconds delays: */
+	if (time_after(jiffies, touch_timestamp + 10*HZ)) {
+		per_cpu(print_timestamp, this_cpu) = touch_timestamp;
 
 		spin_lock(&print_lock);
 		printk(KERN_ERR "BUG: soft lockup detected on CPU#%d!\n",
 			this_cpu);
-		show_regs(regs);
+		dump_stack();
 		spin_unlock(&print_lock);
 	}
 }
@@ -77,18 +87,16 @@ static int watchdog(void * __bind_cpu)
 	sched_setscheduler(current, SCHED_FIFO, &param);
 	current->flags |= PF_NOFREEZE;
 
-	set_current_state(TASK_INTERRUPTIBLE);
-
 	/*
-	 * Run briefly once per second - if this gets delayed for
-	 * more than 10 seconds then the debug-printout triggers
-	 * in softlockup_tick():
+	 * Run briefly once per second to reset the softlockup timestamp.
+	 * If this gets delayed for more than 10 seconds then the
+	 * debug-printout triggers in softlockup_tick().
 	 */
 	while (!kthread_should_stop()) {
-		msleep_interruptible(1000);
+		set_current_state(TASK_INTERRUPTIBLE);
 		touch_softlockup_watchdog();
+		schedule();
 	}
-	__set_current_state(TASK_RUNNING);
 
 	return 0;
 }
@@ -110,11 +118,11 @@ cpu_callback(struct notifier_block *nfb,
 			printk("watchdog for %i failed\n", hotcpu);
 			return NOTIFY_BAD;
 		}
+  		per_cpu(touch_timestamp, hotcpu) = jiffies;
   		per_cpu(watchdog_task, hotcpu) = p;
 		kthread_bind(p, hotcpu);
  		break;
 	case CPU_ONLINE:
-
 		wake_up_process(per_cpu(watchdog_task, hotcpu));
 		break;
 #ifdef CONFIG_HOTPLUG_CPU
@@ -146,4 +154,3 @@ __init void spawn_softlockup_task(void)
 
 	notifier_chain_register(&panic_notifier_list, &panic_block);
 }
-
Index: linux-rt.q/kernel/timer.c
===================================================================
--- linux-rt.q.orig/kernel/timer.c
+++ linux-rt.q/kernel/timer.c
@@ -914,6 +914,7 @@ static void run_timer_softirq(struct sof
 void run_local_timers(void)
 {
 	raise_softirq(TIMER_SOFTIRQ);
+	softlockup_tick();
 }
 
 /*
@@ -944,7 +945,6 @@ void do_timer(struct pt_regs *regs)
 	/* prevent loading jiffies before storing new jiffies_64 value. */
 	barrier();
 	update_times();
-	softlockup_tick(regs);
 }
 
 #ifdef __ARCH_WANT_SYS_ALARM

soft lockup in serial8250_console_write(?)

[Randy.Dunlap]

Hi,

(x86_64; 2.6.16-rc6;
serial console configured but nothing connected to the serial port)

I'm seeing an occasional soft lockup, maybe in serial8250_console_write().
(drivers/serial/8250.c)

This function calls wait_for_xmitr() [inline], which in worst case
can spin for 1.010 seconds.  Could this be the cause of a soft lockup?


[  101.448855] BUG: soft lockup detected on CPU#0!
[  101.448858] CPU 0:
[  101.448860] Modules linked in:
[  101.448863] Pid: 1, comm: swapper Not tainted 2.6.16-rc6 #3
[  101.448866] RIP: 0010:[<ffffffff8013009b>] <ffffffff8013009b>{__do_softirq+75}
[  101.448874] RSP: 0000:ffffffff804dc9a8  EFLAGS: 00000206
[  101.448877] RAX: ffff81007f63dfd8 RBX: ffffffff804dc8f8 RCX: 000000000000000a
[  101.448880] RDX: 0000000000000022 RSI: 0000000000000002 RDI: ffff81007f622740
[  101.448883] RBP: ffffffff8010aef0 R08: 0000000000000083 R09: ffff81007f287638
[  101.448886] R10: 0000000000000002 R11: 0000000000000000 R12: ffffffff804dc9c8
[  101.448889] R13: ffffffff80529d00 R14: 0000000000000022 R15: ffffffff8010d34d
[  101.448892] FS:  0000000000000000(0000) GS:ffffffff80529000(0000) knlGS:0000000000000000
[  101.448895] CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
[  101.448898] CR2: 0000000000000000 CR3: 0000000000101000 CR4: 00000000000006e0
[  101.448900] 
[  101.448900] Call Trace: <IRQ> <ffffffff8010bb92>{call_softirq+30}
[  101.448908]        <ffffffff8010d309>{do_softirq+49} <ffffffff8012fe63>{irq_exit+72}
[  101.448915]        <ffffffff80115ab1>{smp_apic_timer_interrupt+75} <ffffffff8010b536>{apic_timer_interrupt+98} <EOI>
[  101.448923]        <ffffffff8028607e>{serial8250_console_write+516} <ffffffff8012add7>{release_console_sem+335}
[  101.448936]        <ffffffff8012b188>{register_console+433} <ffffffff803134cb>{usb_serial_console_init+51}
[  101.448943]        <ffffffff80312556>{usb_serial_probe+3989} <ffffffff8012b8c3>{vprintk+721}
[  101.448956]        <ffffffff803a3bb7>{_spin_unlock_irq+9} <ffffffff8012b93f>{printk+103}
[  101.448964]        <ffffffff8013a084>{call_usermodehelper_keys+274} <ffffffff802f1dc8>{usb_probe_interface+223}
[  101.448975]        <ffffffff8028f1ff>{driver_probe_device+90} <ffffffff8028f35c>{__driver_attach+135}
[  101.448983]        <ffffffff8028f2d5>{__driver_attach+0} <ffffffff8028e726>{bus_for_each_dev+73}
[  101.448990]        <ffffffff8028f094>{driver_attach+28} <ffffffff8028ea48>{bus_add_driver+114}
[  101.448996]        <ffffffff8028f7f9>{driver_register+180} <ffffffff802f1c7a>{usb_register_driver+134}
[  101.449003]        <ffffffff803112e6>{usb_serial_register+570} <ffffffff805550fc>{belkin_sa_init+39}
[  101.449012]        <ffffffff8010820b>{init+451} <ffffffff8010b842>{child_rip+8}
[  101.449020]        <ffffffff80108048>{init+0} <ffffffff8010b83a>{child_rip+0}

---

Re: soft lockup in serial8250_console_write(?)

[Randy.Dunlap]

On Tue, 14 Mar 2006 22:40:49 +0100 Ingo Molnar wrote:

> 
> * Randy.Dunlap <rdunlap@xenotime.net> wrote:
> 
> > Hi,
> > 
> > (x86_64; 2.6.16-rc6; serial console configured but nothing connected 
> > to the serial port)
> > 
> > I'm seeing an occasional soft lockup, maybe in 
> > serial8250_console_write(). (drivers/serial/8250.c)
> > 
> > This function calls wait_for_xmitr() [inline], which in worst case can 
> > spin for 1.010 seconds.  Could this be the cause of a soft lockup?
> 
> hm, it shouldnt cause that. Could you try the attached patch [which is 
> the next-gen softlockup detector], do you get the message even with that 
> one applied?

5/5 good boots with your new patch.
5/5 soft lockups without it.

Is this scheduled for post-2.6.16 ?

Thanks,
---
~Randy

Re: soft lockup in serial8250_console_write(?)

[Ingo Molnar]

* Randy.Dunlap <rdunlap@xenotime.net> wrote:

> > > This function calls wait_for_xmitr() [inline], which in worst case can 
> > > spin for 1.010 seconds.  Could this be the cause of a soft lockup?
> > 
> > hm, it shouldnt cause that. Could you try the attached patch [which is 
> > the next-gen softlockup detector], do you get the message even with that 
> > one applied?
> 
> 5/5 good boots with your new patch.
> 5/5 soft lockups without it.
> 
> Is this scheduled for post-2.6.16 ?

yes, in theory. Andrew?

	Ingo

Re: soft lockup in serial8250_console_write(?)

[Andrew Morton]

Ingo Molnar <mingo@elte.hu> wrote:
>
> 
> * Randy.Dunlap <rdunlap@xenotime.net> wrote:
> 
> > > > This function calls wait_for_xmitr() [inline], which in worst case can 
> > > > spin for 1.010 seconds.  Could this be the cause of a soft lockup?
> > > 
> > > hm, it shouldnt cause that. Could you try the attached patch [which is 
> > > the next-gen softlockup detector], do you get the message even with that 
> > > one applied?
> > 
> > 5/5 good boots with your new patch.
> > 5/5 soft lockups without it.
> > 
> > Is this scheduled for post-2.6.16 ?
> 
> yes, in theory. Andrew?
> 

Which?  timer-irq-driven-soft-watchdog-cleanups.patch?  Yup.