Messages in this thread |  | | Date | Tue, 29 Jan 2013 15:54:24 +0100 | From | Jan Kara <> | Subject | Re: [PATCH] printk: Avoid softlockups in console_unlock() |
| |
On Mon 21-01-13 22:00:08, Jan Kara wrote: > On Thu 17-01-13 15:50:29, Andrew Morton wrote: > > On Fri, 18 Jan 2013 00:46:14 +0100 > > Jan Kara <jack@suse.cz> wrote: > > > > > On Thu 17-01-13 13:39:17, Andrew Morton wrote: > > > > On Thu, 17 Jan 2013 22:04:42 +0100 > > > > Jan Kara <jack@suse.cz> wrote: > > > > > > > > > ... > > > > > > > > > > So I played a bit with this. To make things easier for me I added > > > > > artificial mdelay(len*10) (effectively simulating console able to print 100 > > > > > characters per second) just after call_console_drivers() so that I can > > > > > trigger issues even on a machine easily available to me. Booting actually > > > > > doesn't trigger any problems because there aren't enough things happening > > > > > in parallel on common machine during boot but > > > > > echo t >/proc/sysrq-trigger & > > > > > for i in /lib/modules/3.8.0-rc3-0-default/kernel/fs/*/*.ko; do > > > > > name=`basename $i`; name=${name%.ko}; modprobe $name > > > > > done > > > > > easily triggers the problem (as modprobe uses both RCU & IPIs to signal all > > > > > CPUs). > > > > > > > > > > Adding > > > > > touch_nmi_watchdog(); > > > > > touch_all_softlockup_watchdogs(); > > > > > rcu_cpu_stall_reset(); > > > > > > > > I'm not sure that touch_all_softlockup_watchdogs() is needed? > > > > touch_nmi_watchdog() itself calls touch_softlockup_watchdog(). > > > It is. I've tried without it and the machine died a horrible death > > > because softlockup reports added to already too heavy printk traffic. The > > > problem is that CPU doing printing cannot handle IPIs thus if someone calls > > > e.g. smp_call_function_many() that function will spin waiting for IPIs on > > > all CPUs to finish. And that doesn't happen until printing is done so > > > CPU doing smp_call_function_many() gets locked up as well. > > > > erk. I trust we'll have a nice comment explaining this mechanism ;) > So I was testing the attached patch which does what we discussed. The bad > news is I was able to trigger a situation (twice) when suddently sda > disappeared and thus all IO requests failed with EIO. There is no trace of > what's happened in the kernel log. I'm guessing that disabled interrupts on > the printing CPU caused scsi layer to time out for some request and fail the > device. So where do we go from here? Andrew? I guess this fell off your radar via the "hrm, strange, need to have a closer look later" path? Currently I'd be inclined to return to my original solution...
Honza
> From 9373cb89d434519089a1a6a0955aef08c814d70f Mon Sep 17 00:00:00 2001 > From: Jan Kara <jack@suse.cz> > Date: Mon, 21 Jan 2013 20:30:20 +0100 > Subject: [PATCH] printk: Avoid softlockup reports during heavy printk traffic > > A CPU can be caught in console_unlock() for a long time (tens of seconds are > reported by our customers) when other CPUs are using printk heavily and serial > console makes printing slow. This triggers softlockup warnings because > interrupts are disabled for the whole time console_unlock() runs (e.g. > vprintk() calls console_unlock() with interrupts disabled). > > It doesn't trigger hardlockup reports because serial drivers already call > touch_nmi_watchdog() but that's not enough in some cases. For example if some > process uses on_each_cpu(), smp_call_function() will block until IPI on the > printing CPU is processed and that doesn't happen for tens of seconds so the > CPU where on_each_cpu() is executing is locked up as well. > > Postponing the printing to a worker thread was deemed too risky (see discussion > in the thread starting with https://lkml.org/lkml/2013/1/15/438) so here we > take a less risky approach and just silence all the watchdogs. We have to be > careful not to make them completely useless by touching them too often so we > touch the watchdogs only every 1000 characters we print in one console_unlock() > call. That should really happen only during boot, when printing sysrq-t output, > or in similarly extreme situations. > > Signed-off-by: Jan Kara <jack@suse.cz> > --- > kernel/printk.c | 23 +++++++++++++++++++++++ > 1 files changed, 23 insertions(+), 0 deletions(-) > > diff --git a/kernel/printk.c b/kernel/printk.c > index 357f714..1cbae2b 100644 > --- a/kernel/printk.c > +++ b/kernel/printk.c > @@ -2043,6 +2043,7 @@ void console_unlock(void) > unsigned long flags; > bool wake_klogd = false; > bool retry; > + unsigned int printed = 0; > > if (console_suspended) { > up(&console_sem); > @@ -2103,8 +2104,30 @@ skip: > > stop_critical_timings(); /* don't trace print latency */ > call_console_drivers(level, text, len); > + printed += len; > start_critical_timings(); > local_irq_restore(flags); > + > + /* > + * If we already printed too much, touch watchdogs. The limit > + * is set high enough so that it happens really rarely (and > + * printk traffic doesn't render lockup watchdogs useless) but > + * low enough so that even slower serial console doesn't cause > + * lockup reports. 9600 baud serial console prints 1000 chars > + * in about 1 second... > + */ > + if (printed > 1000) { > + touch_nmi_watchdog(); > + /* > + * This is needed because other CPUs may be waiting on > + * this CPU to process IPI so they are stalled as well. > + */ > + touch_all_softlockup_watchdogs(); > + local_irq_save(flags); > + rcu_cpu_stall_reset(); > + local_irq_restore(flags); > + printed = 0; > + } > } > console_locked = 0; > mutex_release(&console_lock_dep_map, 1, _RET_IP_); > -- > 1.7.1 >
-- Jan Kara <jack@suse.cz> SUSE Labs, CR
|  |