[PATCH 1/3] printk: Make printk() completely async

[PATCH 1/3] printk: Make printk() completely async

[Jan Kara]

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              | 146 +++++++++++++++++++++---------------
 2 files changed, 97 insertions(+), 59 deletions(-)

diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
index 9a53c929f017..4d33376a9904 100644
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -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.
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index c963ba534a78..73ec760a4bc8 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -284,6 +284,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)
 {
@@ -1669,15 +1736,15 @@ 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 ||
+			  console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH;
 	/* 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();
 
@@ -1804,10 +1871,25 @@ 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 synchronous printing was explicitely requested by
+	 * kernel parameter, or when console_verbose() was called to print
+	 * everything during panic / oops.
+	 */
+	if (keventd_up() && !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
@@ -2731,60 +2813,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

[PATCH 2/3] printk: Skip messages on oops

[Jan Kara]

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 73ec760a4bc8..03f5278b47b4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -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

[PATCH 3/3] printk: debug: Slow down printing to 9600 bauds

[Jan Kara]

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 03f5278b47b4..8ac60219059a 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -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

Re: [PATCH 2/3] printk: Skip messages on oops

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 1395 bytes --]

Hi Jan,

[auto build test ERROR on v4.5-rc6]
[cannot apply to next-20160302]
[if your patch is applied to the wrong git tree, please drop us a note to help improving the system]

url:    https://github.com/0day-ci/linux/commits/Jan-Kara/printk-Make-printk-completely-async/20160303-000904
config: i386-tinyconfig (attached as .config)
reproduce:
        # save the attached .config to linux build tree
        make ARCH=i386 

All errors (new ones prefixed by >>):

   kernel/printk/printk.c: In function 'console_unlock':
>> kernel/printk/printk.c:2370:7: error: 'oops_start_seq' undeclared (first use in this function)
      if (oops_start_seq &&
          ^
   kernel/printk/printk.c:2370:7: note: each undeclared identifier is reported only once for each function it appears in

vim +/oops_start_seq +2370 kernel/printk/printk.c

  2364	
  2365			/*
  2366			 * If oops happened and there are more than
  2367			 * PRINT_MSGS_BEFORE_OOPS messages pending before oops message,
  2368			 * skip them to make oops appear faster.
  2369			 */
> 2370			if (oops_start_seq &&
  2371			    console_seq + PRINT_MSGS_BEFORE_OOPS < oops_start_seq) {
  2372				len = sprintf(text,
  2373					"** %u printk messages dropped due to oops ** ",

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/octet-stream, Size: 6204 bytes --]

Re: [PATCH 1/3] printk: Make printk() completely async

[Tetsuo Handa]

On 2016/03/03 0:59, Jan Kara wrote:
> 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.

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.

Re: [PATCH 1/3] printk: Make printk() completely async

[Jan Kara]

On Thu 03-03-16 20:26:55, Tetsuo Handa wrote:
> On 2016/03/03 0:59, Jan Kara wrote:
> > 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.
> 
> 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.

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.

> (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.

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

> (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?

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.

> (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.

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

> (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.

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

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: [PATCH 1/3] printk: Make printk() completely async

[Sergey Senozhatsky]

Hello,

On (03/03/16 20:26), Tetsuo Handa wrote:
> On 2016/03/03 0:59, Jan Kara wrote:
> > 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.
> 
> 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.

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.

> (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.

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).

> (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?

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.


> (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.

yes, may be later.

> (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.


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