Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1288545 > unrolled thread

Re: [PATCH 1/7] printk: Hand over printing to console if printing too long

Back to article view | Back to linux.kernel

Contents

  Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2015-12-10 16:00 +0100
    Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2015-12-10 16:30 +0100
    Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2015-12-11 05:30 +0100
      Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2015-12-11 07:30 +0100

#1288545 — Re: [PATCH 1/7] printk: Hand over printing to console if printing too long

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()
---
 kernel/printk/printk.c | 11 ++++++-----
 1 file changed, 6 insertions(+), 5 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index d986599..2a86ff1 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -85,7 +85,7 @@ EXPORT_SYMBOL_GPL(console_drivers);
  * we can spin on it when some other thread wants to take over printing to
  * console.
  */
-static DEFINE_SPINLOCK(print_lock);
+static DEFINE_RAW_SPINLOCK(print_lock);
 
 /*
  * Number of printing threads spinning on print_lock. Can go away once
@@ -1516,6 +1516,7 @@ static void zap_locks(void)
 	/* If a crash is occurring, make sure we can't deadlock */
 	raw_spin_lock_init(&logbuf_lock);
 	/* And make sure that we print immediately */
+	raw_spin_lock_init(&print_lock);
 	sema_init(&console_sem, 1);
 }
 
@@ -2311,7 +2312,7 @@ void console_unlock(void)
 	console_cont_flush(text, sizeof(text));
 again:
 	retry = false;
-	spin_lock_irqsave(&print_lock, flags);
+	raw_spin_lock_irqsave(&print_lock, flags);
 	for (;;) {
 		struct printk_log *msg;
 		size_t ext_len = 0;
@@ -2410,7 +2411,7 @@ skip:
 	 * succeeds in getting console_sem (unless someone else takes it and
 	 * then he'll be responsible for printing).
          */
-	spin_unlock_irqrestore(&print_lock, flags);
+	raw_spin_unlock_irqrestore(&print_lock, flags);
 
 	/*
 	 * In case we cannot trylock the console_sem again, there's a new owner
@@ -2773,9 +2774,9 @@ static int printing_task(void *arg)
 		 * want to sleep once we got scheduled to make sure we take
 		 * over printing without depending on the scheduler.
 		 */
-		spin_lock_irqsave(&print_lock, flags);
+		raw_spin_lock_irqsave(&print_lock, flags);
 		atomic_dec(&printing_tasks_spinning);
-		spin_unlock_irqrestore(&print_lock, flags);
+		raw_spin_unlock_irqrestore(&print_lock, flags);
 		if (console_trylock())
 			console_unlock();
 		preempt_enable();
-- 
2.6.3

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [next] | [standalone]

#1288591

On (12/10/15 23:52), Sergey Senozhatsky wrote:
> 
> 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()

while we are on this, what do you guys think?


CPU1                                        CPU2
console_unlock()
  call_console_drivers()
    con->write()
       ... spin_lock ... uart, etc          panic

zap_lock() will raw_spin_lock_init(&logbuf_lock) and
sema_init(&console_sem, 1), but we still have `spin_lock'
held by con->write().

so the `panic' flush or print out will see con->write() being already
blocked.


===8<====

We do zap_lock() in printk to make a panic print out possible, but we
can end up having a locked serial console - e.g. panic has occurred
whilst CPUx was in con->write(), which takes some internal locks, thus
call_console_drivers() will perform con->write() on an already locked
console.

Try to reset() every console in zap_lock() via console specific
->reset() call.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 include/linux/console.h | 1 +
 kernel/printk/printk.c  | 6 ++++++
 2 files changed, 7 insertions(+)

diff --git a/include/linux/console.h b/include/linux/console.h
index bd19434..1cb8f72 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -125,6 +125,7 @@ struct console {
 	void	(*unblank)(void);
 	int	(*setup)(struct console *, char *);
 	int	(*match)(struct console *, char *name, int idx, char *options);
+	void	(*reset)(struct console *);
 	short	flags;
 	short	index;
 	int	cflag;
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index f4a9565..ad172c4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1580,6 +1580,7 @@ static void call_console_drivers(int level,
  */
 static void zap_locks(void)
 {
+	struct console *c;
 	static unsigned long oops_timestamp;
 
 	if (time_after_eq(jiffies, oops_timestamp) &&
@@ -1589,6 +1590,11 @@ static void zap_locks(void)
 	oops_timestamp = jiffies;
 
 	debug_locks_off();
+
+	for_each_console(c)
+		if ((c->flags & CON_ENABLED) && c->reset)
+			c->reset(c);
+
 	/* If a crash is occurring, make sure we can't deadlock */
 	raw_spin_lock_init(&logbuf_lock);
 	/* And make sure that we print immediately */
-- 
2.6.3

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1289137

On (12/10/15 23:52), Sergey Senozhatsky wrote:
> > 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>


> static bool cpu_stop_printing(int printed_chars)
> {
>         /* Oops? Print everything now to maximize chances user will see it */
>         if (oops_in_progress)
>                 return false;
>         if (!printk_offload_chars || printed_chars < printk_offload_chars)
>                 return false;
>         /*
>          * Make sure we load fresh value of printing_tasks_spinning. Matches
>          * the barrier in printing_task()
>          */
>         smp_rmb();
>         if (atomic_read(&printing_tasks_spinning))
>                 return true;
>         wake_up(&print_queue);
>
-	return false;
+	return true;
> }


we just woke up a task we will offload printing to. no need to do another round
of call_console_drivers() from current, possibly overrunning printk_offload_chars
by strlen of next msg, which can be close to max text length in the worst case,
while woken up print task will burn cpu cycles spinning on the print_lock.

	-ss
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1289255

On (12/11/15 13:27), Sergey Senozhatsky wrote:
[..]
> > static bool cpu_stop_printing(int printed_chars)
> > {
> >         /* Oops? Print everything now to maximize chances user will see it */
> >         if (oops_in_progress)
> >                 return false;
> >         if (!printk_offload_chars || printed_chars < printk_offload_chars)
> >                 return false;
> >         /*
> >          * Make sure we load fresh value of printing_tasks_spinning. Matches
> >          * the barrier in printing_task()
> >          */
> >         smp_rmb();
> >         if (atomic_read(&printing_tasks_spinning))
> >                 return true;
> >         wake_up(&print_queue);
> >
> -	return false;
> +	return true;
> > }

*just as an idea*, I was thinking about having two different offload
limits -- for user space processes doing console_unlock() for whatever
reason (printk in syscall or because of console_lock, etc.) and for
KTHREADS. the kernel threads can have normal offload_limit, while user
space processes can return back from syscal sooner (doing only half of
printk worload, for example). but this is probably too `custom', though
sort of make some sense.

(compile tested only)

---
 kernel/printk/printk.c | 19 +++++++++++++++++--
 1 file changed, 17 insertions(+), 2 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 79915da..cff1dd1 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -330,6 +330,7 @@ static struct kernel_param_ops offload_chars_ops = {
  * 0.1s maximum latency due to printing.
  */
 static unsigned int __read_mostly printk_offload_chars = 1000;
+static unsigned int __read_mostly printk_offload_limits[2] = {500, 1000};
 
 module_param_cb(offload_chars, &offload_chars_ops, &printk_offload_chars,
 		   S_IRUGO | S_IWUSR);
@@ -343,10 +344,14 @@ MODULE_PARM_DESC(offload_chars, "offload printing to console to a different"
  */
 static bool cpu_stop_printing(int printed_chars)
 {
+	bool type = current->flags & PF_KTHREAD;
+
 	/* Oops? Print everything now to maximize chances user will see it */
 	if (oops_in_progress)
 		return false;
-	if (!printk_offload_chars || printed_chars < printk_offload_chars)
+	if (!printk_offload_chars)
+		return false;
+	if (printed_chars < printk_offload_limits[type])
 		return false;
 	/*
 	 * Make sure we load fresh value of printing_tasks_spinning. Matches
@@ -2995,6 +3000,12 @@ out_err:
 	return ret;
 }
 
+static void offload_limits_set(void)
+{
+	printk_offload_limits[0] = printk_offload_chars >> 1;
+	printk_offload_limits[1] = printk_offload_chars;
+}
+
 static int offload_chars_set(const char *val, const struct kernel_param *kp)
 {
 	int ret;
@@ -3006,6 +3017,8 @@ static int offload_chars_set(const char *val, const struct kernel_param *kp)
 		mutex_unlock(&printing_kthread_mutex);
 		return ret;
 	}
+
+	offload_limits_set();
 	ret = printk_start_offload_kthreads();
 	mutex_unlock(&printing_kthread_mutex);
 	return ret;
@@ -3014,11 +3027,13 @@ static int offload_chars_set(const char *val, const struct kernel_param *kp)
 static void printk_offload_init(void)
 {
 	mutex_lock(&printing_kthread_mutex);
+	offload_limits_set();
 	if (num_possible_cpus() <= 1) {
 		/* Offloading doesn't make sense. Disable print offloading. */
 		printk_offload_chars = 0;
-	} else
+	} else {
 		printk_start_offload_kthreads();
+	}
 	mutex_unlock(&printing_kthread_mutex);
 }
 
-- 
2.6.4

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web