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.

---
 Documentation/kernel-parameters.txt |  10 +++
 kernel/printk/printk.c              | 146 +++++++++++++++++++++---------------
 2 files changed, 97 insertions(+), 59 deletions(-)

index 9a53c929f017..4d33376a9904 100644
@@ -3068,6 +3068,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.

2.6.2

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.

---
 kernel/printk/printk.c | 34 +++++++++++++++++++++++++++++++++-
 1 file changed, 33 insertions(+), 1 deletion(-)

index 73ec760a4bc8..03f5278b47b4 100644
@@ -267,6 +267,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;

@@ -1785,6 +1788,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 					 NULL, 0, recursion_msg,
 					 strlen(recursion_msg));
 	}
+	if (oops_in_progress && !printk_sync && !oops_start_seq)
+		oops_start_seq = log_next_seq;
 
 	/*
 	 * The printf needs to come first; we need the syslog

@@ -2295,6 +2300,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
  *

@@ -2351,7 +2362,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

---
 kernel/printk/printk.c | 35 ++++++++++++++++++++++++++++++++++-
 1 file changed, 34 insertions(+), 1 deletion(-)

index 03f5278b47b4..8ac60219059a 100644
@@ -2300,6 +2300,21 @@ out:
 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
 }
 
+static void printk_echo(char *fmt, ...)
+{
+	unsigned long flags;
+	va_list args;
+	char buf[128];
+	int len = 0;
+
+	va_start(args, fmt);
+	len += vsprintf(buf + len, fmt, args);
+	va_end(args);
+	local_irq_save(flags);
+	call_console_drivers(0, NULL, 0, buf, len);
+	local_irq_restore(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.

@@ -2437,9 +2452,9 @@ skip:
 		call_console_drivers(level, ext_text, ext_len, text, len);
 		start_critical_timings();
 		local_irq_restore(flags);
-
 		if (do_cond_resched)
 			cond_resched();
+		mdelay(len);
 	}
 	console_locked = 0;
 

@@ -2806,6 +2821,18 @@ int unregister_console(struct console *console)
 }
 EXPORT_SYMBOL(unregister_console);
 
+static void do_print(struct work_struct *work)
+{
+	char buf[75];
+	int i;
+
+	sprintf(buf, "%p: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\n", work);
+	for (i = 0; i < 15; i++)
+		printk(buf);
+}
+
+static struct delayed_work print_work[100];
+
 /*
  * Some boot consoles access data that is in the init section and which will
  * be discarded after the initcalls have been run. To make sure that no code

@@ -2824,6 +2851,12 @@ EXPORT_SYMBOL(unregister_console);
 static int __init printk_late_init(void)
 {
 	struct console *con;
+	int i;
+
+	for (i = 0; i < 100; i++) {
+		INIT_DELAYED_WORK(&print_work[i], do_print);
+		schedule_delayed_work(&print_work[i], HZ * 180);
+	}
 
 	for_each_console(con) {
 		if (!keep_bootcon && con->flags & CON_BOOT) {

2.6.2

A few questions.

(1) How do you handle PM/suspend? I think kernel threads including workqueue will be frozen during suspend operation. Maybe we can use an atomic_t counter (like oom_victims) which forces synchronous printing if counter value > 0.

(2) Can we have a method for waiting for pending data to be flushed with timeout? If I want to emit as much messages as SysRq-t from schedulable context, I want to wait for flush before proceeding. This is different from using atomic_t counter suggested in (1), for asynchronous printk() helps reducing RCU duration; queuing to string buffer from RCU context and emitting from !RCU context will be preferable.

(3) Is reliability of SysRq-t changed by this patch? I mean, does this patch make SysRq-t prone to drop traces if the logbuf was not large enough?

(4) This will be outside of this proposal's scope, but it would be nice if we can selectively allow each console driver to control loglevel to emit. For example, send all kernel messages to serial console (console=ttyS0,115200n8) but send only critical messages to login console (console=tty0). I'm interested in logging via serial console and netconsole but not via login console. Since traces sent to login console is swept away soon, waiting for login console is wasteful.

(5) This will be outside of this proposal's scope, but it would be nice if printk() can combine multiple logs and pass to console drivers. For example, logging via netconsole will become significantly faster if printk() can combine multiple logs up to ethernet packet's size. A single stack trace can likely be sent using one ethernet packet.

Well, it depends on whether you make the workqueue freezable or not... I don't think printk workqueue should be actually freezable. But it's a good think to have in mind.

Separate problem => separate patch please. This was hard to push through already as is.

Qualitatively no - even currently Sysrq-t can see console_lock locked (because there's some other printk happening as well) and thus will just dump all the information into kernel buffer. Quantitatively - likely yes - now the printing will be always async, previous it was only when racing with other printk. But you should have large enough printk buffer to accommodate full sysrq-t output if you care about it being complete.

Yes, that's a completely separate issue. But it would be nice, yes.

This would be rather non-trivial to achieve I suspect since the console code is pretty much line-oriented...

Honza

Jan Kara <[email protected]>
SUSE Labs, CR

Hello,

hm, workqueues should be freezible only when we pass WQ_FREEZABLE. I allocate printk_wq passing WQ_MEM_RECLAIM only.

I'll post the patch shortly; for a wider testing.

well... you can do something like

	console_lock
	printk()
	...
	printk()
	console_unlock

but it can spend much more time in console_unlock(), printing the messages. in case if you have (or had) additional sources of printk (coming from other CPUs).

hm, not really. printk() and actual printing of the message can easily be executed on different CPUs.

CPU0 CPU1

                                    console_lock
                                    console_unlock
                                      for (;;) {

SysRq
for (....) spin_lock logbuf_lock
read the message from logbuf
printk()
{ spin_unlock logbuf_lock
spin_lock logbuf_lock call_console_drivers

     add message to logbuf            }

spin_unlock logbuf_lock

   try lock console_lock
   return
  }

so if CPU1 is slow in evicting the messages from logbuf and logbuf is not large enough then we can lose some messages from CPU0.

yes, may be later.

hm. that's easier to handle in console driver's code, I think. but, while I understand what you mean here, I'd generally expect that every message ending with a new line is getting printed asap, w/o any buffering. well, just saying.

	-ss