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 <j...@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 <j...@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 <j...@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 <j...@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 <j...@suse.cz>
SUSE Labs, CR
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
