lkml.org 
[lkml]   [2015]   [Dec]   [22]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patches in this message
/
Date
From
SubjectRe: [PATCH 1/7] printk: Hand over printing to console if printing too long
On Thu 10-12-15 23:52:51, Sergey Senozhatsky wrote:
> Hello,
>
> *** in this email and in every later emails ***
> Sorry, if I messed up with Cc list or message-ids. It's suprisingly
> hard to jump in into a loop that has never been in your inbox. It took
> some `googling' effort.
>
> I haven't tested the patch set yet, I just 'ported' it to linux-next.
> I reverted 073696a8bc7779b ("printk: do cond_resched() between lines while
> outputting to consoles") as a first step, but it comes in later again. I can
> send out the updated series (off list is OK).
>
> > Currently, console_unlock() prints messages from kernel printk buffer to
> > console while the buffer is non-empty. When serial console is attached,
> > printing is slow and thus other CPUs in the system have plenty of time
> > to append new messages to the buffer while one CPU is printing. Thus the
> > CPU can spend unbounded amount of time doing printing in console_unlock().
> > This is especially serious problem if the printk() calling
> > console_unlock() was called with interrupts disabled.
> >
> > In practice users have observed a CPU can spend tens of seconds printing
> > in console_unlock() (usually during boot when hundreds of SCSI devices
> > are discovered) resulting in RCU stalls (CPU doing printing doesn't
> > reach quiescent state for a long time), softlockup reports (IPIs for the
> > printing CPU don't get served and thus other CPUs are spinning waiting
> > for the printing CPU to process IPIs), and eventually a machine death
> > (as messages from stalls and lockups append to printk buffer faster than
> > we are able to print). So these machines are unable to boot with serial
> > console attached. Also during artificial stress testing SATA disk
> > disappears from the system because its interrupts aren't served for too
> > long.
> >
> > This patch implements a mechanism where after printing specified number
> > of characters (tunable as a kernel parameter printk.offload_chars), CPU
> > doing printing asks for help by waking up one of dedicated kthreads. As
> > soon as the printing CPU notices kthread got scheduled and is spinning
> > on print_lock dedicated for that purpose, it drops console_sem,
> > print_lock, and exits console_unlock(). Kthread then takes over printing
> > instead. This way no CPU should spend printing too long even if there
> > is heavy printk traffic.
> >
> > Signed-off-by: Jan Kara <jack@suse.cz>
>
> I think we better use raw_spin_lock as a print_lock; and, apart from that,
> seems that we don't re-init in zap_lock(). So I ended up with the following
> patch on top of yours (to be folded):
>
> - use raw_spin_lock
> - do not forget to re-init `print_lock' in zap_locks()

Thanks for looking into my patches and sorry for replying with a delay. As
I wrote in my previous email [1] even the referenced patches are not quite
enough. Over last few days I have worked on redoing the stuff as we
discussed with Linus and Andrew at Kernel Summit and I have new patches
which are working fine for me. I still want to test them on some machines
having real issues with udev during boot but so far stress-testing with
serial console slowed down to ~1000 chars/sec on other machines and VMs
looks promising.

I'm attaching them in case you want to have a look. They are on top of
Tejun's patch adding cond_resched() (which is essential). I'll officially
submit the patches once the testing is finished (but I'm not sure when I
get to the problematic HW...).

Honza

[1] http://www.spinics.net/lists/stable/msg111535.html
--
Jan Kara <jack@suse.com>
SUSE Labs, CR
From 2e9675abbfc0df4a24a8c760c58e8150b9a31259 Mon Sep 17 00:00:00 2001
From: Jan Kara <jack@suse.cz>
Date: Mon, 21 Dec 2015 13:10:31 +0100
Subject: [PATCH 1/2] printk: Make printk() completely async

Currently, printk() sometimes waits for message to be printed to console
and sometimes it does not (when console_sem is held by some other
process). In case printk() grabs console_sem and starts printing to
console, it prints messages from kernel printk buffer until the buffer
is empty. When serial console is attached, printing is slow and thus
other CPUs in the system have plenty of time to append new messages to
the buffer while one CPU is printing. Thus the CPU can spend unbounded
amount of time doing printing in console_unlock(). This is especially
serious problem if the printk() calling console_unlock() was called with
interrupts disabled.

In practice users have observed a CPU can spend tens of seconds printing
in console_unlock() (usually during boot when hundreds of SCSI devices
are discovered) resulting in RCU stalls (CPU doing printing doesn't
reach quiescent state for a long time), softlockup reports (IPIs for the
printing CPU don't get served and thus other CPUs are spinning waiting
for the printing CPU to process IPIs), and eventually a machine death
(as messages from stalls and lockups append to printk buffer faster than
we are able to print). So these machines are unable to boot with serial
console attached. Another observed issue is that due to slow printk,
hardware discovery is slow and udev times out before kernel manages to
discover all the attached HW. Also during artificial stress testing SATA
disk disappears from the system because its interrupts aren't served for
too long.

This patch makes printk() completely asynchronous (similar to what
printk_deferred() did until now). It appends message to the kernel
printk buffer and queues work to do the printing to console. This has
the advantage that printing always happens from a schedulable contex and
thus we don't lockup any particular CPU or even interrupts. Also it has
the advantage that printk() is fast and thus kernel booting is not
slowed down by slow serial console. Disadvantage of this method is that
in case of crash there is higher chance that important messages won't
appear in console output (we may need working scheduling to print
message to console). We somewhat mitigate this risk by switching printk
to the original method of immediate printing to console if oops is in
progress. Also for debugging purposes we provide printk.synchronous
kernel parameter which resorts to the original printk behavior.

Signed-off-by: Jan Kara <jack@suse.cz>
---
Documentation/kernel-parameters.txt | 10 +++
kernel/printk/printk.c | 144 +++++++++++++++++++++---------------
2 files changed, 95 insertions(+), 59 deletions(-)

diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
index 742f69d18fc8..4cf1bddeffc7 100644
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -3000,6 +3000,16 @@ bytes respectively. Such letter suffixes can also be entirely omitted.
printk.time= Show timing data prefixed to each printk message line
Format: <bool> (1/Y/y=enable, 0/N/n=disable)

+ printk.synchronous=
+ By default kernel messages are printed to console
+ asynchronously (except during early boot or when oops
+ is happening). That avoids kernel stalling behind slow
+ serial console and thus avoids softlockups, interrupt
+ timeouts, or userspace timing out during heavy printing.
+ However for debugging problems, printing messages to
+ console immediately may be desirable. This option
+ enables such behavior.
+
processor.max_cstate= [HW,ACPI]
Limit processor to maximum C-state
max_cstate=9 overrides any DMI blacklist limit.
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 299c2f0e7350..d455d1bd0d2c 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -283,6 +283,73 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
static char *log_buf = __log_buf;
static u32 log_buf_len = __LOG_BUF_LEN;

+/*
+ * When true, printing to console will happen synchronously unless someone else
+ * is already printing messages.
+ */
+static bool __read_mostly printk_sync;
+module_param_named(synchronous, printk_sync, bool, S_IRUGO | S_IWUSR);
+MODULE_PARM_DESC(synchronous, "make printing to console synchronous");
+
+#define PRINTK_PENDING_WAKEUP 0x01
+#define PRINTK_PENDING_OUTPUT 0x02
+
+static DEFINE_PER_CPU(int, printk_pending);
+
+static void printing_work_func(struct work_struct *work)
+{
+ console_lock();
+ console_unlock();
+}
+
+static DECLARE_WORK(printing_work, printing_work_func);
+
+static void wake_up_klogd_work_func(struct irq_work *irq_work)
+{
+ int pending = __this_cpu_xchg(printk_pending, 0);
+
+ /*
+ * We just schedule regular work to do the printing from irq work. We
+ * don't want to do printing here directly as that happens with
+ * interrupts disabled and thus is bad for interrupt latency. We also
+ * don't want to queue regular work from vprintk_emit() as that gets
+ * called in various difficult contexts where schedule_work() could
+ * deadlock.
+ */
+ if (pending & PRINTK_PENDING_OUTPUT)
+ schedule_work(&printing_work);
+
+ if (pending & PRINTK_PENDING_WAKEUP)
+ wake_up_interruptible(&log_wait);
+}
+
+static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
+ .func = wake_up_klogd_work_func,
+ .flags = IRQ_WORK_LAZY,
+};
+
+void wake_up_klogd(void)
+{
+ preempt_disable();
+ if (waitqueue_active(&log_wait)) {
+ this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
+ irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
+ }
+ preempt_enable();
+}
+
+int printk_deferred(const char *fmt, ...)
+{
+ va_list args;
+ int r;
+
+ va_start(args, fmt);
+ r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
+ va_end(args);
+
+ return r;
+}
+
/* Return log buffer address */
char *log_buf_addr_get(void)
{
@@ -1668,15 +1735,14 @@ asmlinkage int vprintk_emit(int facility, int level,
unsigned long flags;
int this_cpu;
int printed_len = 0;
- bool in_sched = false;
+ bool sync_print = printk_sync;
/* cpu currently holding logbuf_lock in this function */
static unsigned int logbuf_cpu = UINT_MAX;

if (level == LOGLEVEL_SCHED) {
level = LOGLEVEL_DEFAULT;
- in_sched = true;
+ sync_print = false;
}
-
boot_delay_msec(level);
printk_delay();

@@ -1803,10 +1869,24 @@ asmlinkage int vprintk_emit(int facility, int level,
logbuf_cpu = UINT_MAX;
raw_spin_unlock(&logbuf_lock);
lockdep_on();
+ /*
+ * By default we print message to console asynchronously so that kernel
+ * doesn't get stalled due to slow serial console. That can lead to
+ * softlockups, lost interrupts, or userspace timing out under heavy
+ * printing load.
+ *
+ * However we resort to synchronous printing of messages during early
+ * boot, when oops is in progress, or when synchronous printing was
+ * explicitely requested by kernel parameter.
+ */
+ if (keventd_up() && !oops_in_progress && !sync_print) {
+ __this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
+ irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
+ } else
+ sync_print = true;
local_irq_restore(flags);

- /* If called from the scheduler, we can not call up(). */
- if (!in_sched) {
+ if (sync_print) {
lockdep_off();
/*
* Disable preemption to avoid being preempted while holding
@@ -2688,60 +2768,6 @@ late_initcall(printk_late_init);

#if defined CONFIG_PRINTK
/*
- * Delayed printk version, for scheduler-internal messages:
- */
-#define PRINTK_PENDING_WAKEUP 0x01
-#define PRINTK_PENDING_OUTPUT 0x02
-
-static DEFINE_PER_CPU(int, printk_pending);
-
-static void wake_up_klogd_work_func(struct irq_work *irq_work)
-{
- int pending = __this_cpu_xchg(printk_pending, 0);
-
- if (pending & PRINTK_PENDING_OUTPUT) {
- /* If trylock fails, someone else is doing the printing */
- if (console_trylock())
- console_unlock();
- }
-
- if (pending & PRINTK_PENDING_WAKEUP)
- wake_up_interruptible(&log_wait);
-}
-
-static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
- .func = wake_up_klogd_work_func,
- .flags = IRQ_WORK_LAZY,
-};
-
-void wake_up_klogd(void)
-{
- preempt_disable();
- if (waitqueue_active(&log_wait)) {
- this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
- irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
- }
- preempt_enable();
-}
-
-int printk_deferred(const char *fmt, ...)
-{
- va_list args;
- int r;
-
- preempt_disable();
- va_start(args, fmt);
- r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
- va_end(args);
-
- __this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
- irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
- preempt_enable();
-
- return r;
-}
-
-/*
* printk rate limiting, lifted from the networking subsystem.
*
* This enforces a rate limit: not more than 10 kernel messages
--
2.6.2
From be116ae18f15f0d2d05ddf0b53eaac184943d312 Mon Sep 17 00:00:00 2001
From: Jan Kara <jack@suse.cz>
Date: Mon, 21 Dec 2015 14:26:13 +0100
Subject: [PATCH 2/2] printk: Skip messages on oops

When there are too many messages in the kernel printk buffer it can take
very long to print them to console (especially when using slow serial
console). This is undesirable during oops so when we encounter oops and
there are more than 100 messages to print, print just the newest 100
messages and then the oops message.

Signed-off-by: Jan Kara <jack@suse.cz>
---
kernel/printk/printk.c | 34 +++++++++++++++++++++++++++++++++-
1 file changed, 33 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index d455d1bd0d2c..fc67ab70e9c7 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -262,6 +262,9 @@ static u64 console_seq;
static u32 console_idx;
static enum log_flags console_prev;

+/* current record sequence when oops happened */
+static u64 oops_start_seq;
+
/* the next printk record to read after the last 'clear' command */
static u64 clear_seq;
static u32 clear_idx;
@@ -1783,6 +1786,8 @@ asmlinkage int vprintk_emit(int facility, int level,
NULL, 0, recursion_msg,
strlen(recursion_msg));
}
+ if (oops_in_progress && !sync_print && !oops_start_seq)
+ oops_start_seq = log_next_seq;

/*
* The printf needs to come first; we need the syslog
@@ -2292,6 +2297,12 @@ out:
raw_spin_unlock_irqrestore(&logbuf_lock, flags);
}

+/*
+ * When oops happens and there are more messages to be printed in the printk
+ * buffer that this, skip some mesages and print only this many newest messages.
+ */
+#define PRINT_MSGS_BEFORE_OOPS 100
+
/**
* console_unlock - unlock the console system
*
@@ -2348,7 +2359,28 @@ again:
seen_seq = log_next_seq;
}

- if (console_seq < log_first_seq) {
+ /*
+ * If oops happened and there are more than
+ * PRINT_MSGS_BEFORE_OOPS messages pending before oops message,
+ * skip them to make oops appear faster.
+ */
+ if (oops_start_seq &&
+ console_seq + PRINT_MSGS_BEFORE_OOPS < oops_start_seq) {
+ len = sprintf(text,
+ "** %u printk messages dropped due to oops ** ",
+ (unsigned)(oops_start_seq - console_seq -
+ PRINT_MSGS_BEFORE_OOPS));
+ if (console_seq < log_first_seq) {
+ console_seq = log_first_seq;
+ console_idx = log_first_idx;
+ }
+ while (console_seq <
+ oops_start_seq - PRINT_MSGS_BEFORE_OOPS) {
+ console_idx = log_next(console_idx);
+ console_seq++;
+ }
+ console_prev = 0;
+ } else if (console_seq < log_first_seq) {
len = sprintf(text, "** %u printk messages dropped ** ",
(unsigned)(log_first_seq - console_seq));

--
2.6.2
\
 
 \ /
  Last update: 2015-12-22 15:01    [W:0.254 / U:0.088 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site