Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async

[Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>]

Hello Jan,

On (03/07/16 13:16), Jan Kara wrote:
[..]
> > So if this will be a problem in practice, using a kthread will probably be
> > the easiest solution.
> 
> Hum, and thinking more about it: Considering that WQ_MEM_RECLAIM workqueues
> create kthread anyway as a rescuer thread, it may be the simplest to just
> go back to using a single kthread for printing. What do you think?

I have this patch on top of the series now. In short, it closes one more
possibility of lockups -- console_lock()/console_unlock() calls. the patch
splits console_unlock() in two parts:
-- the fast one just wake up printing kthread
-- the slow one does call_console_drivers() loop

I think it sort of makes sense to tweak the patch below a bit and fold it
into 0001, and move _some_ of the vprintk_emit() checks to console_unlock().

very schematically, after folding, vprintk_emit() will be

	if (in_sched) {
		if (!printk_sync && printk_thread)
			wake_up()
		else
			irq_work_queue()
	}
	
	if (!in_sched)
		if (console_trylock())
			console_unlock()

and console_unlock() will be

	if (!in_panic && !printk_sync && printk_thread) {
		up_console_sem()
		wake_up()
	} else {
		console_unlock_for_printk()
	}

console_unlock_for_printk() does the call_console_drivers() loop.

console_flush_on_panic() and printing_func() call console_unlock_for_printk()
directly.


What do you think? Or would you prefer to first introduce async
printk() rework, and move to console_unlock() in vprintk_emit()
one release cycle later?
IOW, in 3 steps:
-- first make printk() async
-- then console_unlock() async, and use console_unlock_for_printk() in
   vprintk_emit()
-- then switch to console_unlock() in vprintk_emit().


below is the patch which introduces console_unlock_for_printk().
not the squashed console_unlock_for_printk() and 0001.

	-ss

======

>From bc3932c68c5afb9bf43af98335c705c75067a93a Mon Sep 17 00:00:00 2001
From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Subject: [PATCH 3/4] printk: introduce console_unlock_for_printk()

Even though we already have asynchronous printk()->vprintk_emit(),
there are still good chances to get lockups, because we don't have
asynchronous console_unlock(). So any process doing console_lock()
and console_unlock() will end up looping in console_unlock(), pushing
the messages to console drivers (possibly with IRQs or preemption
disabled), regardless the fact that we have a dedicated kthread for
that particular job.

Apart from that, console_lock()/console_unlock() can be executed by
user processes as a part of system calls:

a)  SyS_open()
     ...
      chrdev_open()
       tty_open()
        console_device()
         console_lock()
         console_unlock()
          for (;;) {
           call_console_drivers()
          }

b) SyS_read()
    ...
     sysfs_read_file()
      dev_attr_show()
       show_cons_active()
        console_lock()
        console_unlock()
         for (;;) {
          call_console_drivers()
         }

c) doing `cat /proc/consoles`
  SyS_read()
   vfs_read()
    proc_reg_read()
     seq_read()
      c_stop()
       console_unlock()
        for (;;) {
         call_console_drivers()
        }

etc.

This can add unnecessary latencies to the user space processes.

This patch splits console_unlock() in two parts:
-- the fast path up() console semaphore and wake up printing kthread
   (if there is one, of course), otherwise
-- the slow path: does what console_unlock() did previously, emit
   the messages and then up() console semaphore

The actual printing loop is, thus, moved to a new function,
console_unlock_for_printk(). There are 3 places that
unconditionally call it:
 a) direct printing from vprintk_emit()
 b) console_flush_on_panic()
 c) printing kthread callback

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 51 +++++++++++++++++++++++++++++++++++++++++++-------
 1 file changed, 44 insertions(+), 7 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index de45d86..ddaf62e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -303,6 +303,8 @@ static struct task_struct *printk_thread;
 /* Wait for printing wakeups from async vprintk_emit() */
 static DECLARE_WAIT_QUEUE_HEAD(printing_wait);
 
+static void console_unlock_for_printk(void);
+
 static int printing_func(void *data)
 {
 	while (1) {
@@ -314,7 +316,7 @@ static int printing_func(void *data)
 		remove_wait_queue(&printing_wait, &wait);
 
 		console_lock();
-		console_unlock();
+		console_unlock_for_printk();
 	}
 
 	return 0;
@@ -1900,7 +1902,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 * /dev/kmsg and syslog() users.
 		 */
 		if (console_trylock())
-			console_unlock();
+			console_unlock_for_printk();
 		lockdep_on();
 	}
 
@@ -2339,20 +2341,20 @@ out:
 #define PRINT_MSGS_BEFORE_OOPS 100
 
 /**
- * console_unlock - unlock the console system
+ * console_unlock_for_printk - unlock the console system
  *
  * Releases the console_lock which the caller holds on the console system
  * and the console driver list.
  *
  * While the console_lock was held, console output may have been buffered
- * by printk().  If this is the case, console_unlock(); emits
+ * by printk().  If this is the case, console_unlock_for_printk() emits
  * the output prior to releasing the lock.
  *
  * If there is output waiting, we wake /dev/kmsg and syslog() users.
  *
- * console_unlock(); may be called from any context.
+ * console_unlock_for_printk() may be called from any context.
  */
-void console_unlock(void)
+static void console_unlock_for_printk(void)
 {
 	static char ext_text[CONSOLE_EXT_LOG_MAX];
 	static char text[LOG_LINE_MAX + PREFIX_MAX];
@@ -2511,6 +2513,41 @@ skip:
 	if (wake_klogd)
 		wake_up_klogd();
 }
+
+
+/**
+ * console_unlock - unlock the console system
+ *
+ * Releases the console_lock which the caller holds on the console system.
+ *
+ * The fast path is to wake up the printing kthread (if the system can
+ * perform asynchronous printing) and return; the slow path is to emit
+ * the messages directly invoking console_unlock_for_printk().
+ *
+ * console_unlock() may be called from any context.
+ */
+void console_unlock(void)
+{
+	bool in_panic = console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH;
+
+	if (in_panic) {
+		/*
+		 * If the system is in panic console_flush_on_panic() issued
+		 * from panic_cpu will flush the messages.
+		 */
+		console_locked = 0;
+		up_console_sem();
+		return;
+	}
+
+	if (!printk_sync && printk_thread) {
+		console_locked = 0;
+		up_console_sem();
+		wake_up(&printing_wait);
+	} else {
+		console_unlock_for_printk();
+	}
+}
 EXPORT_SYMBOL(console_unlock);
 
 /**
@@ -2567,7 +2604,7 @@ void console_flush_on_panic(void)
 	 */
 	console_trylock();
 	console_may_schedule = 0;
-	console_unlock();
+	console_unlock_for_printk();
 }
 
 /*
-- 
2.8.0.rc0.1.gd285ab0