lkml.org 
[lkml]   [2015]   [Oct]   [8]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patches in this message
/
Date
From
SubjectRe: [PATCH] panic: release stale console lock to always get the logbuf printed out
On Wed 07-10-15 15:34:08, Andrew Morton wrote:
> (cc Jan)
>
> On Wed, 7 Oct 2015 19:02:22 +0200 Vitaly Kuznetsov <vkuznets@redhat.com> wrote:
>
> > In some cases we may end up killing the CPU holding the console lock
> > while still having valuable data in logbuf. E.g. I'm observing the
> > following:
> > - A crash is happening on one CPU and console_unlock() is being called on
> > some other.
> > - console_unlock() tries to print out the buffer before releasing the lock
> > and on slow console it takes time.
> > - in the meanwhile crashing CPU does lots of printk()-s with valuable data
> > (which go to the logbuf) and sends IPIs to all other CPUs.
> > - console_unlock() finishes printing previous chunk and enables interrupts
> > before trying to print out the rest, the CPU catches the IPI and never
> > releases console lock.
>
> Why doesn't the lock-owning CPU release the console lock? Because it
> was stopped by smp_send_stop() in panic()?
>
> I don't recall why we stop CPUs in panic(), and of course we didn't
> document the reason. I guess it makes sense from the "what else can we
> do" point of view, but I wonder if we can just do it later on - that
> would fix this problem?
>
> (dumb aside: why doesn't smp_send_stop() stop the calling CPU?)
>
> > This is not the only possible case: in VT/fb subsystems we have many other
> > console_lock()/console_unlock() users. Non-masked interrupts (or receiving
> > NMI in case of extreme slowness) will have the same result. Getting the
> > whole console buffer printed out on crash should be top priority.
>
> Yes, this is a pretty big hole in the logic.
>
> > --- a/kernel/panic.c
> > +++ b/kernel/panic.c
> > @@ -23,6 +23,7 @@
> > #include <linux/sysrq.h>
> > #include <linux/init.h>
> > #include <linux/nmi.h>
> > +#include <linux/console.h>
> >
> > #define PANIC_TIMER_STEP 100
> > #define PANIC_BLINK_SPD 18
> > @@ -147,6 +148,15 @@ void panic(const char *fmt, ...)
> >
> > bust_spinlocks(0);
> >
> > + /*
> > + * We may have ended up killing the CPU holding the lock and still have
> > + * some valuable data in console buffer. Try to acquire the lock and
> > + * release it regardless of the result. The release will also print the
> > + * buffers out.
> > + */
> > + console_trylock();
> > + console_unlock();
> > +
>
> "killing the CPU" is a bit vague. How's this look?
>
> --- a/kernel/panic.c~panic-release-stale-console-lock-to-always-get-the-logbuf-printed-out-fix
> +++ a/kernel/panic.c
> @@ -149,10 +149,10 @@ void panic(const char *fmt, ...)
> bust_spinlocks(0);
>
> /*
> - * We may have ended up killing the CPU holding the lock and still have
> - * some valuable data in console buffer. Try to acquire the lock and
> - * release it regardless of the result. The release will also print the
> - * buffers out.
> + * We may have ended up stopping the CPU holding the lock (in
> + * smp_send_stop()) while still having some valuable data in the console
> + * buffer. Try to acquire the lock then release it regardless of the
> + * result. The release will also print the buffers out.
> */
> console_trylock();
> console_unlock();
> _
>
>
> Does the console_trylock() guarantee that the console lock is now held?
> If the console_lock-holding CPU is still running then there's a window
> where the above code could enter console_unlock() when nobody's holding
> console_lock. If smp_send_stop() always works (synchronously) then
> that won't happen.

We have this mechanism using zap_locks() in kernel/printk/printk.c when
crash happens on the CPU holding console_sem. Can't we use the same
mechanism for this case? Something like adding:

zap_locks();
console_lock();
console_unlock();

to panic? If we picked up patch "kernel: Avoid softlockups in
stop_machine() during heavy printing" from my series (it's completely
independent, I've attached the latest version), the result would look less
hacky to me (attached). Thoughts?

Warning, the result is untested... I can do some testing and official
posting of the two patches if people agree we want to got down this path.

Honza
--
Jan Kara <jack@suse.com>
SUSE Labs, CR
From 950e36435598090c6b03b4659922d981c53aa75b Mon Sep 17 00:00:00 2001
From: Jan Kara <jack@suse.cz>
Date: Thu, 13 Mar 2014 15:07:49 +0100
Subject: [PATCH 3/5] kernel: Avoid softlockups in stop_machine() during heavy
printing

When there are lots of messages accumulated in printk buffer, printing
them (especially over serial console) can take a long time (tens of
seconds). stop_machine() will effectively make all cpus spin in
multi_cpu_stop() waiting for the CPU doing printing to print all the
messages which triggers NMI softlockup watchdog and RCU stall detector
which add even more to the messages to print. Since machine doesn't do
anything (except serving interrupts) during this time, also network
connections are dropped and other disturbances may happen.

Paper over the problem by waiting for printk buffer to be empty before
starting to stop CPUs. In theory a burst of new messages can be appended
to the printk buffer before CPUs enter multi_cpu_stop() so this isn't a 100%
solution but it works OK in practice and I'm not aware of a reasonably
simple better solution.

Signed-off-by: Jan Kara <jack@suse.cz>
---
include/linux/console.h | 11 +++++++++++
kernel/printk/printk.c | 25 +++++++++++++++++++++++++
kernel/stop_machine.c | 9 +++++++++
3 files changed, 45 insertions(+)

diff --git a/include/linux/console.h b/include/linux/console.h
index bd194343c346..96da462cdfeb 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -150,6 +150,17 @@ extern int console_trylock(void);
extern void console_unlock(void);
extern void console_conditional_schedule(void);
extern void console_unblank(void);
+#ifdef CONFIG_SMP
+extern void printk_log_buf_drain(void);
+#else
+/*
+ * In non-SMP kernels there won't be much to drain so save some code for tiny
+ * kernels.
+ */
+static inline void printk_log_buf_drain(void)
+{
+}
+#endif
extern struct tty_driver *console_device(int *);
extern void console_stop(struct console *);
extern void console_start(struct console *);
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index b249866260d7..b03431709965 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2488,6 +2488,31 @@ struct tty_driver *console_device(int *index)
return driver;
}

+/* For non-SMP kernels this function isn't used and would be pointless anyway */
+#ifdef CONFIG_SMP
+/*
+ * Wait until all messages accumulated in the printk buffer are printed to
+ * console. Note that as soon as this function returns, new messages may be
+ * added to the printk buffer by other CPUs.
+ */
+void printk_log_buf_drain(void)
+{
+ bool retry;
+ unsigned long flags;
+
+ while (1) {
+ raw_spin_lock_irqsave(&logbuf_lock, flags);
+ retry = console_seq != log_next_seq;
+ raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+ if (!retry || console_suspended)
+ break;
+ /* Cycle console_sem to wait for outstanding printing */
+ console_lock();
+ console_unlock();
+ }
+}
+#endif
+
/*
* Prevent further output on the passed console device so that (for example)
* serial drivers can disable console output before suspending a port, and can
diff --git a/kernel/stop_machine.c b/kernel/stop_machine.c
index 12484e5d5c88..e9496b4a3825 100644
--- a/kernel/stop_machine.c
+++ b/kernel/stop_machine.c
@@ -21,6 +21,7 @@
#include <linux/smpboot.h>
#include <linux/atomic.h>
#include <linux/lglock.h>
+#include <linux/console.h>

/*
* Structure to determine completion condition and record errors. May
@@ -543,6 +544,14 @@ static int __stop_machine(cpu_stop_fn_t fn, void *data, const struct cpumask *cp
return ret;
}

+ /*
+ * If there are lots of outstanding messages, printing them can take a
+ * long time and all cpus would be spinning waiting for the printing to
+ * finish thus triggering NMI watchdog, RCU lockups etc. Wait for the
+ * printing here to avoid these.
+ */
+ printk_log_buf_drain();
+
/* Set the initial state and stop all online cpus. */
set_state(&msdata, MULTI_STOP_PREPARE);
return stop_cpus(cpu_online_mask, multi_cpu_stop, &msdata);
--
2.1.4
From 5bba47bcb62b52a0a1eb78fbea4ac25a5a2852bf Mon Sep 17 00:00:00 2001
From: Jan Kara <jack@suse.com>
Date: Thu, 8 Oct 2015 10:51:42 +0200
Subject: [PATCH] panic: release stale console lock to always get the logbuf
printed out

In some cases we may end up killing the CPU holding the console lock
while still having valuable data in logbuf. E.g. Vitaly is observing the
following:

- A crash is happening on one CPU and console_unlock() is being called
on some other.

- console_unlock() tries to print out the buffer before releasing the
lock and on slow console it takes time.

- in the meanwhile crashing CPU does lots of printk()-s with valuable
data (which go to the logbuf) and sends IPIs to all other CPUs.

- console_unlock() finishes printing previous chunk and enables
interrupts before trying to print out the rest, the CPU catches the
IPI and never releases console lock.

This is not the only possible case: in VT/fb subsystems we have many
other console_lock()/console_unlock() users. Non-masked interrupts (or
receiving NMI in case of extreme slowness) will have the same result.
Getting the whole console buffer printed out on crash should be top
priority.

Base on original patch by Vitaly Kuznetsov.

Reported-by: Vitaly Kuznetsov <vkuznets@redhat.com>
Signed-off-by: Jan Kara <jack@suse.com>
---
include/linux/console.h | 4 ++--
kernel/panic.c | 8 ++++++++
kernel/printk/printk.c | 5 ++++-
kernel/stop_machine.c | 2 +-
4 files changed, 15 insertions(+), 4 deletions(-)

diff --git a/include/linux/console.h b/include/linux/console.h
index 96da462cdfeb..f40084802f3f 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -151,13 +151,13 @@ extern void console_unlock(void);
extern void console_conditional_schedule(void);
extern void console_unblank(void);
#ifdef CONFIG_SMP
-extern void printk_log_buf_drain(void);
+extern void printk_log_buf_drain(bool panic);
#else
/*
* In non-SMP kernels there won't be much to drain so save some code for tiny
* kernels.
*/
-static inline void printk_log_buf_drain(void)
+static inline void printk_log_buf_drain(bool panic)
{
}
#endif
diff --git a/kernel/panic.c b/kernel/panic.c
index 04e91ff7560b..d07ed830a9fb 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -23,6 +23,7 @@
#include <linux/sysrq.h>
#include <linux/init.h>
#include <linux/nmi.h>
+#include <linux/console.h>

#define PANIC_TIMER_STEP 100
#define PANIC_BLINK_SPD 18
@@ -147,6 +148,13 @@ void panic(const char *fmt, ...)

bust_spinlocks(0);

+ /*
+ * We may have ended up stopping the CPU doing printing (in
+ * smp_send_stop()) while still having some valuable data in the
+ * console buffer. Flush it out.
+ */
+ printk_log_buf_drain(true);
+
if (!panic_blink)
panic_blink = no_blink;

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 8e125e98f523..62be2890e6a0 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2401,11 +2401,14 @@ struct tty_driver *console_device(int *index)
* console. Note that as soon as this function returns, new messages may be
* added to the printk buffer by other CPUs.
*/
-void printk_log_buf_drain(void)
+void printk_log_buf_drain(bool panic)
{
bool retry;
unsigned long flags;

+ if (panic)
+ zap_locks();
+
while (1) {
raw_spin_lock_irqsave(&logbuf_lock, flags);
retry = console_seq != log_next_seq;
diff --git a/kernel/stop_machine.c b/kernel/stop_machine.c
index e9496b4a3825..50a03735893e 100644
--- a/kernel/stop_machine.c
+++ b/kernel/stop_machine.c
@@ -550,7 +550,7 @@ static int __stop_machine(cpu_stop_fn_t fn, void *data, const struct cpumask *cp
* finish thus triggering NMI watchdog, RCU lockups etc. Wait for the
* printing here to avoid these.
*/
- printk_log_buf_drain();
+ printk_log_buf_drain(false);

/* Set the initial state and stop all online cpus. */
set_state(&msdata, MULTI_STOP_PREPARE);
--
2.1.4
\
 
 \ /
  Last update: 2015-10-08 11:21    [W:0.226 / U:0.404 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site