printk: rebalance printk

From: Pan Xinhui <[email protected]>

printk can be called in any context, It's very useful to output debug info.

But it might cause very bad issues on some special cases. For example, some driver hit errors, and it dumps many messages like reg values, etc.

Sometimes, printk is called when irqs disabled. This is OKay if there is a few messages. But What would happen if many messages outputted by other drivers at same time.

Here is the scenario.
CPUA CPUB

					local_irq_save(flags);
					printk()
while(..) {					--> console_unlock
	printk(...);			
	//hundreds or thousands loops
}				//all messages flushed out to consoles
					local_irq_restore(flags);

printk runs on CPUA just store the messages in the buf and return. printk runs on CPUB(who owns the console_sem lock) would take the duty to flush all messages to consoles. It would take a long time to flush messages out, IOW, irq would be disabled for a long time. Such case is too bad. We hit many interrupt related panics, for example, cpu did not respond to IPI.

Here is the solution, if we detect such case above, try to rebalance it. Let CPUA take the duty to flush messages to consoles.

The idea is simple, but the implementation is a little difficult. Introduce many help functions to fix it.

Signed-off-by Pan Xinhui <[email protected]>

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

kernel/printk/printk.c +100 -1

index cf8c242..3dc2f60 100644
@@ -1652,6 +1652,65 @@ static size_t cont_print_text(char *text, size_t size)
 	return textlen;
 }
 
+static struct {
+	unsigned int request:1;/* set it with logbuf_lock and console_sem held
+				* clear it with logbuf_lock held.
+				*/
+	unsigned int reply:1; /* set/clear it with logbuf_lock held*/
+	struct semaphore help_sem;
+} help_t = {
+	.request = 0,
+	.reply = 0,
+	.help_sem = __SEMAPHORE_INITIALIZER(help_t.help_sem, 0),
+};
+
+/* protected by logbuf_lock*/
+static int check_help(void)
+{
+	return !!help_t.request;
+}
+
+/* protected by logbuf_lock and console_sem*/
+static void request_help(void)
+{
+	help_t.request = 1;
+}
+
+/* protected by logbuf_lock*/
+static void cancel_help(void)
+{
+	help_t.request = 0;
+}
+
+/* protected by logbuf_lock*/
+static void reply_help(void)
+{
+	help_t.request = 0;
+	help_t.reply = 1;
+}
+
+/* protected by logbuf_lock*/
+static int ack_help(void)
+{
+	return !!help_t.reply;
+}
+
+/* protected by logbuf_lock*/
+static void close_help(void)
+{
+	help_t.reply = 0;
+}
+
+static void thanks_help(void)
+{
+	up(&help_t.help_sem);
+}
+
+static int done_help(void)
+{
+	return !down_trylock(&help_t.help_sem);
+}
+
 asmlinkage int vprintk_emit(int facility, int level,
 			    const char *dict, size_t dictlen,
 			    const char *fmt, va_list args)

@@ -1667,6 +1726,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 	bool in_sched = false;
 	/* cpu currently holding logbuf_lock in this function */
 	static unsigned int logbuf_cpu = UINT_MAX;
+	bool help = 0;
+	bool can_help = !(irqs_disabled() || in_sched || in_interrupt());
 
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;

@@ -1701,6 +1762,10 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	lockdep_off();
 	raw_spin_lock(&logbuf_lock);
+	if (can_help && check_help()) {
+		reply_help();
+		help = true;
+	}
 	logbuf_cpu = this_cpu;
 
 	if (unlikely(recursion_bug)) {

@@ -1811,6 +1876,9 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		preempt_disable();
 
+		if (help)
+			while (!done_help())
+				cpu_relax();
 		/*
 		 * Try to acquire and then immediately release the console
 		 * semaphore.  The release will print out buffers and wake up

@@ -2230,6 +2298,8 @@ void console_unlock(void)
 	unsigned long flags;
 	bool wake_klogd = false;
 	bool retry;
+	bool help = !!(irqs_disabled() || in_interrupt());
+	bool skip_ack = true;
 
 	if (console_suspended) {
 		up_console_sem();

@@ -2248,6 +2318,21 @@ again:
 		int level;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
+		if (help) {
+			if (!skip_ack) {
+				if (ack_help()) {
+					/*
+					* If request got replyed by another
+					* printk-on-going, close the request.
+					*/
+					close_help();
+					break;
+				}
+				cancel_help();
+			}
+			request_help();
+			skip_ack = 0;
+		}
 		if (seen_seq != log_next_seq) {
 			wake_klogd = true;
 			seen_seq = log_next_seq;

@@ -2265,8 +2350,13 @@ again:
 			len = 0;
 		}
 skip:
-		if (console_seq == log_next_seq)
+		if (console_seq == log_next_seq) {
+			if (help) {
+				cancel_help();
+				help = 0;
+			}
 			break;
+		}
 
 		msg = log_from_idx(console_idx);
 		if (msg->flags & LOG_NOCONS) {

@@ -2318,6 +2408,14 @@ skip:
 
 	up_console_sem();
 
+	if (help) {
+		/*
+		* Need call up_console_sem first.
+		*/
+		thanks_help();
+		goto wake_up;
+	}
+
 	/*
 	 * Someone could have filled up the buffer again, so re-check if there's
 	 * something to flush. In case we cannot trylock the console_sem again,

@@ -2331,6 +2429,7 @@ skip:
 	if (retry && console_trylock())
 		goto again;
 
+wake_up:
 	if (wake_klogd)
 		wake_up_klogd();
 }

From: Pan Xinhui <[email protected]>

printk can be called in any context, It's very useful to output debug info.

But it might cause very bad issues on some special cases. For example, some driver hit errors, and it dumps many messages like reg values, etc.

Sometimes, printk is called when irqs disabled. This is OKay if there is a few messages. But What would happen if many messages outputted by other drivers at same time.

Here is the scenario.
CPUA CPUB

					local_irq_save(flags);
					printk()
while(..) {					--> console_unlock
	printk(...);			
	//hundreds or thousands loops
}				//all messages flushed out to consoles
					local_irq_restore(flags);

printk runs on CPUA just store the messages in the buf and return. printk runs on CPUB(who owns the console_sem lock) would take the duty to flush all messages to consoles. It would take a long time to flush messages out, IOW, irq would be disabled for a long time. Such case is too bad. We hit many interrupt related panics, for example, cpu did not respond to IPI.

Here is the solution, if we detect such case above, try to rebalance it. Let CPUA take the duty to flush messages to consoles.

The idea is simple, but the implementation is a little difficult. Introduce many help functions to fix it.

Signed-off-by Pan Xinhui <[email protected]>

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

kernel/printk/printk.c +100 -1

index cf8c242..3dc2f60 100644
@@ -1652,6 +1652,65 @@ static size_t cont_print_text(char *text, size_t size)
 	return textlen;
 }
 
+static struct {
+	unsigned int request:1;/* set it with logbuf_lock and console_sem held
+				* clear it with logbuf_lock held.
+				*/
+	unsigned int reply:1; /* set/clear it with logbuf_lock held*/
+	struct semaphore help_sem;
+} help_t = {
+	.request = 0,
+	.reply = 0,
+	.help_sem = __SEMAPHORE_INITIALIZER(help_t.help_sem, 0),
+};
+
+/* protected by logbuf_lock*/
+static int check_help(void)
+{
+	return !!help_t.request;
+}
+
+/* protected by logbuf_lock and console_sem*/
+static void request_help(void)
+{
+	help_t.request = 1;
+}
+
+/* protected by logbuf_lock*/
+static void cancel_help(void)
+{
+	help_t.request = 0;
+}
+
+/* protected by logbuf_lock*/
+static void reply_help(void)
+{
+	help_t.request = 0;
+	help_t.reply = 1;
+}
+
+/* protected by logbuf_lock*/
+static int ack_help(void)
+{
+	return !!help_t.reply;
+}
+
+/* protected by logbuf_lock*/
+static void close_help(void)
+{
+	help_t.reply = 0;
+}
+
+static void thanks_help(void)
+{
+	up(&help_t.help_sem);
+}
+
+static int done_help(void)
+{
+	return !down_trylock(&help_t.help_sem);
+}
+
 asmlinkage int vprintk_emit(int facility, int level,
 			    const char *dict, size_t dictlen,
 			    const char *fmt, va_list args)

@@ -1667,6 +1726,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 	bool in_sched = false;
 	/* cpu currently holding logbuf_lock in this function */
 	static unsigned int logbuf_cpu = UINT_MAX;
+	bool help = 0;
+	bool can_help = !(irqs_disabled() || in_sched || in_interrupt());
 
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;

@@ -1701,6 +1762,10 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	lockdep_off();
 	raw_spin_lock(&logbuf_lock);
+	if (can_help && check_help()) {
+		reply_help();
+		help = true;
+	}
 	logbuf_cpu = this_cpu;
 
 	if (unlikely(recursion_bug)) {

@@ -1811,6 +1876,9 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		preempt_disable();
 
+		if (help)
+			while (!done_help())
+				cpu_relax();
 		/*
 		 * Try to acquire and then immediately release the console
 		 * semaphore.  The release will print out buffers and wake up

@@ -2230,6 +2298,8 @@ void console_unlock(void)
 	unsigned long flags;
 	bool wake_klogd = false;
 	bool retry;
+	bool help = !!(irqs_disabled() || in_interrupt());
+	bool skip_ack = true;
 
 	if (console_suspended) {
 		up_console_sem();

@@ -2248,6 +2318,21 @@ again:
 		int level;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
+		if (help) {
+			if (!skip_ack) {
+				if (ack_help()) {
+					/*
+					* If request got replyed by another
+					* printk-on-going, close the request.
+					*/
+					close_help();
+					break;
+				}
+				cancel_help();
+			}
+			request_help();
+			skip_ack = 0;
+		}
 		if (seen_seq != log_next_seq) {
 			wake_klogd = true;
 			seen_seq = log_next_seq;

@@ -2265,8 +2350,13 @@ again:
 			len = 0;
 		}
 skip:
-		if (console_seq == log_next_seq)
+		if (console_seq == log_next_seq) {
+			if (help) {
+				cancel_help();
+				help = 0;
+			}
 			break;
+		}
 
 		msg = log_from_idx(console_idx);
 		if (msg->flags & LOG_NOCONS) {

@@ -2318,6 +2408,14 @@ skip:
 
 	up_console_sem();
 
+	if (help) {
+		/*
+		* Need call up_console_sem first.
+		*/
+		thanks_help();
+		goto wake_up;
+	}
+
 	/*
 	 * Someone could have filled up the buffer again, so re-check if there's
 	 * something to flush. In case we cannot trylock the console_sem again,

@@ -2331,6 +2429,7 @@ skip:
 	if (retry && console_trylock())
 		goto again;
 
+wake_up:
 	if (wake_klogd)
 		wake_up_klogd();
 }

Quoted 32 lines · Pan Xinhui

From: Pan Xinhui <[email protected]>

printk can be called in any context, It's very useful to output debug info.

But it might cause very bad issues on some special cases. For example, some driver hit errors, and it dumps many messages like reg values, etc.

Sometimes, printk is called when irqs disabled. This is OKay if there is a few messages. But What would happen if many messages outputted by other drivers at same time.

Here is the scenario.
CPUA CPUB

					local_irq_save(flags);
					printk()
while(..) {					--> console_unlock
	printk(...);			
	//hundreds or thousands loops
}				//all messages flushed out to consoles
					local_irq_restore(flags);

printk runs on CPUA just store the messages in the buf and return. printk runs on CPUB(who owns the console_sem lock) would take the duty to flush all messages to consoles. It would take a long time to flush messages out, IOW, irq would be disabled for a long time. Such case is too bad. We hit many interrupt related panics, for example, cpu did not respond to IPI.

Here is the solution, if we detect such case above, try to rebalance it. Let CPUA take the duty to flush messages to consoles.

Quoted 2 lines

The idea is simple, but the implementation is a little difficult. Introduce many help functions to fix it.

Please describe the rebalance state machine/message passing in detail.

Regards,
Peter Hurley

From: Pan Xinhui <[email protected]>

printk can be called in any context, It's very useful to output debug info.

But it might cause very bad issues on some special cases. For example, some driver hit errors, and it dumps many messages like reg values, etc.

Sometimes, printk is called when irqs disabled. This is OKay if there is a few messages. But What would happen if many messages outputted by other drivers at same time.

Here is the scenario.
CPUA CPUB

					local_irq_save(flags);
					printk()
while(..) {					--> console_unlock
	printk(...);			
	//hundreds or thousands loops
}				//all messages flushed out to consoles
					local_irq_restore(flags);

Quoted 14 lines · Pan Xinhui

From: Pan Xinhui <[email protected]>

printk can be called in any context, It's very useful to output debug info.

But it might cause very bad issues on some special cases. For example, some driver hit errors, and it dumps many messages like reg values, etc.

Sometimes, printk is called when irqs disabled. This is OKay if there is a few messages. But What would happen if many messages outputted by other drivers at same time.

Here is the scenario.
CPUA CPUB

Quoted 8 lines

					local_irq_save(flags);
					printk()
while(..) {					--> console_unlock
	printk(...);			
	//hundreds or thousands loops
}				//all messages flushed out to consoles
					local_irq_restore(flags);

Where are you seeing this type of scenario "in the wild"? Or is this just a "debug/bringup hardware" issue? We shouldn't be ever stuck in a printk that prints hundreds or thousands of loops, if so, we need to fix the kernel code that does that, as we do have control over this.

thanks,

greg k-h

Hi, Greg
thanks for your reply!

Quoted 24 lines · Greg Kroah-Hartman

Quoted 14 lines · Pan Xinhui

From: Pan Xinhui <[email protected]>

printk can be called in any context, It's very useful to output debug info.

But it might cause very bad issues on some special cases. For example, some driver hit errors, and it dumps many messages like reg values, etc.

Sometimes, printk is called when irqs disabled. This is OKay if there is a few messages. But What would happen if many messages outputted by other drivers at same time.

Here is the scenario.
CPUA CPUB

Quoted 8 lines

					local_irq_save(flags);
					printk()
while(..) {					--> console_unlock
	printk(...);			
	//hundreds or thousands loops
}				//all messages flushed out to consoles
					local_irq_restore(flags);

Quoted 5 lines

Where are you seeing this type of scenario "in the wild"? Or is this just a "debug/bringup hardware" issue? We shouldn't be ever stuck in a printk that prints hundreds or thousands of loops, if so, we need to fix the kernel code that does that, as we do have control over this.

Sorry for misleading. these loops are just an example. In real world, there are many pr_info/pr_err when some drivers hit device errors to dump debug information.

There is camera and sound test(multimedia test) in our side, we enable dynamic_debug to collect logs to fix some weird issues. sound driver will dump many reg/memory values, and camera will output a few logs with irqs disabled. So we hit this printk issues very frequently, and it blocks our tests indeed.

As printk is announced that it could be used in most context, So I prefer to enhance the stability of printk to handle such case.

Quoted 33 lines · Pan Xinhui

Hi, Greg
thanks for your reply!

Quoted 29 lines · Greg Kroah-Hartman

Quoted 14 lines · Pan Xinhui

From: Pan Xinhui <[email protected]>

printk can be called in any context, It's very useful to output debug info.

But it might cause very bad issues on some special cases. For example, some driver hit errors, and it dumps many messages like reg values, etc.

Sometimes, printk is called when irqs disabled. This is OKay if there is a few messages. But What would happen if many messages outputted by other drivers at same time.

Here is the scenario.
CPUA CPUB

Quoted 8 lines

					local_irq_save(flags);
					printk()
while(..) {					--> console_unlock
	printk(...);			
	//hundreds or thousands loops
}				//all messages flushed out to consoles
					local_irq_restore(flags);

Where are you seeing this type of scenario "in the wild"? Or is this just a "debug/bringup hardware" issue? We shouldn't be ever stuck in a printk that prints hundreds or thousands of loops, if so, we need to fix the kernel code that does that, as we do have control over this.

Quoted 3 lines

Sorry for misleading. these loops are just an example. In real world, there are many pr_info/pr_err when some drivers hit device errors to dump debug information.

That's not good, they should use dev_dbg() for that instead.

Quoted 5 lines

There is camera and sound test(multimedia test) in our side, we enable dynamic_debug to collect logs to fix some weird issues. sound driver will dump many reg/memory values, and camera will output a few logs with irqs disabled. So we hit this printk issues very frequently, and it blocks our tests indeed.

Maybe those memory value dumps should be done through debugfs instead of printk?

Quoted 2 lines

As printk is announced that it could be used in most context, So I prefer to enhance the stability of printk to handle such case.

Stability is nice, but using printk for things it was never ment to be used for, isn't good. Especially if you are forced to add additional complexity to the printk logic just for these corner cases that no one uses :)

thanks,

greg k-h

Quoted 14 lines · Pan Xinhui

From: Pan Xinhui <[email protected]>

printk can be called in any context, It's very useful to output debug info.

But it might cause very bad issues on some special cases. For example, some driver hit errors, and it dumps many messages like reg values, etc.

Sometimes, printk is called when irqs disabled. This is OKay if there is a few messages. But What would happen if many messages outputted by other drivers at same time.

Here is the scenario.
CPUA CPUB

Quoted 8 lines

					local_irq_save(flags);
					printk()
while(..) {					--> console_unlock
	printk(...);			
	//hundreds or thousands loops
}				//all messages flushed out to consoles
					local_irq_restore(flags);

Where are you seeing this type of scenario "in the wild"? Or is this just a "debug/bringup hardware" issue?

We shouldn't be ever stuck in a
printk that prints hundreds or thousands of loops, if so, we need to fix the kernel code that does that, as we do have control over this.

Quoted 24 lines · Greg Kroah-Hartman

Quoted 22 lines · Pan Xinhui

From: Pan Xinhui <[email protected]>

printk can be called in any context, It's very useful to output debug info.

But it might cause very bad issues on some special cases. For example, some driver hit errors, and it dumps many messages like reg values, etc.

Sometimes, printk is called when irqs disabled. This is OKay if there is a few messages. But What would happen if many messages outputted by other drivers at same time.

Here is the scenario.
CPUA CPUB

					local_irq_save(flags);
					printk()
while(..) {					--> console_unlock
	printk(...);			
	//hundreds or thousands loops
}				//all messages flushed out to consoles
					local_irq_restore(flags);

Quoted 2 lines

Where are you seeing this type of scenario "in the wild"? Or is this just a "debug/bringup hardware" issue?

There have been problem reports of big machines getting soft-lockup/RCU stall warnings with serial console attached. I think SLES is carrying patches from Jan Kara to try to workaround this issue.

Quoted 3 lines

We shouldn't be ever stuck in a
printk that prints hundreds or thousands of loops, if so, we need to fix the kernel code that does that, as we do have control over this.

The loop referred to here is the loop in console_unlock(). Essentially what happens is one cpu can get trapped in the console_unlock() output loop; printk()'s from other cpus are only appending to the logbuf since they can't acquire the console_lock (which is owned by the one cpu trapped in the output loop).

Regards,
Peter Hurley