sysrq: rcu-ify __handle_sysrq

Echoing values into /proc/sysrq-trigger seems to be a popular way to get information out of the kernel. However, dumping information about thousands of processes, or hundreds of CPUs to serial console can result in IRQs being blocked for minutes, resulting in various kinds of cascade failures.

The most common failure is due to interrupts being blocked for a very long time. This can lead to things like failed IO requests, and other things the system cannot easily recover from.

This problem is easily fixable by making __handle_sysrq use RCU instead of spin_lock_irqsave.

This leaves the warning that RCU grace periods have not elapsed for a long time, but the system will come back from that automatically.

It also leaves sysrq-from-irq-context when the sysrq keys are pressed, but that is probably desired since people want that to work in situations where the system is already hosed.

The callers of register_sysrq_key and unregister_sysrq_key appear to be capable of sleeping.

drivers/tty/sysrq.c +3 -5

@@ -510,9 +510,8 @@ void __handle_sysrq(int key, bool check_mask)
 	struct sysrq_key_op *op_p;
 	int orig_log_level;
 	int i;
-	unsigned long flags;
 
-	spin_lock_irqsave(&sysrq_key_table_lock, flags);
+	rcu_read_lock();
 	/*
 	 * Raise the apparent loglevel to maximum so that the sysrq header
 	 * is shown to provide the user with positive feedback.  We do not

@@ -554,7 +553,7 @@ void __handle_sysrq(int key, bool check_mask)
 		printk("\n");
 		console_loglevel = orig_log_level;
 	}
-	spin_unlock_irqrestore(&sysrq_key_table_lock, flags);
+	rcu_read_unlock();
 }
 
 void handle_sysrq(int key)

@@ -1043,16 +1042,23 @@ static int __sysrq_swap_key_ops(int key, struct sysrq_key_op *insert_op_p,
                                 struct sysrq_key_op *remove_op_p)
 {
 	int retval;
-	unsigned long flags;
 
-	spin_lock_irqsave(&sysrq_key_table_lock, flags);
+	spin_lock(&sysrq_key_table_lock);
 	if (__sysrq_get_key_op(key) == remove_op_p) {

drivers/tty/sysrq.c +5 -0

+	 * Wait for it to go away before returning, so the code for an old
+	 * op is not freed (eg. on module unload) while it is in use.
+	 */
+	synchronize_rcu();
+
 	return retval;
 }

Quoted 6 lines · On Wed, 23 Apr 2014 12:53:52 -0400 Rik van Riel <[email protected]> wrote:

Echoing values into /proc/sysrq-trigger seems to be a popular way to get information out of the kernel. However, dumping information about thousands of processes, or hundreds of CPUs to serial console can result in IRQs being blocked for minutes, resulting in various kinds of cascade failures.

Quoted 3 lines

The most common failure is due to interrupts being blocked for a very long time. This can lead to things like failed IO requests, and other things the system cannot easily recover from.

I bet nobody wants that console output anyway. You do the sysrq then run dmesg or look in /var/log/messages to see what happened. People who are experiencing problems such as this should run `dmesg -n 1' before writing to sysrq-trigger.

Quoted 6 lines

It also leaves sysrq-from-irq-context when the sysrq keys are pressed, but that is probably desired since people want that to work in situations where the system is already hosed.

The callers of register_sysrq_key and unregister_sysrq_key appear to be capable of sleeping.

unregister_sysrq_key() is basically never used - a couple of scruffy drivers during rmmod. We hardly need any locking in there at all. I guess using simple RCU is better than just removing it though.

Quoted 28 lines

drivers/tty/sysrq.c +2 -4

@@ -510,9 +510,8 @@ void __handle_sysrq(int key, bool check_mask)
 	struct sysrq_key_op *op_p;
 	int orig_log_level;
 	int i;
-	unsigned long flags;
 
-	spin_lock_irqsave(&sysrq_key_table_lock, flags);
+	rcu_read_lock();
 	/*
 	 * Raise the apparent loglevel to maximum so that the sysrq header
 	 * is shown to provide the user with positive feedback.  We do not

@@ -554,7 +553,7 @@ void __handle_sysrq(int key, bool check_mask)
 		printk("\n");
 		console_loglevel = orig_log_level;
 	}
-	spin_unlock_irqrestore(&sysrq_key_table_lock, flags);
+	rcu_read_unlock();
 }
 
 void handle_sysrq(int key)

@@ -1043,16 +1042,23 @@ static int __sysrq_swap_key_ops(int key, struct sysrq_key_op *insert_op_p,
                                 struct sysrq_key_op *remove_op_p)
 {
 	int retval;
-	unsigned long flags;
 

drivers/tty/sysrq.c static int __sysrq_swap_key_ops(int key, struct sysrq_key_op *insert_op_p, · line 1056

Quoted 13 lines

drivers/tty/sysrq.c +5 -2

-	spin_lock_irqsave(&sysrq_key_table_lock, flags);
+	spin_lock(&sysrq_key_table_lock);
 	if (__sysrq_get_key_op(key) == remove_op_p) {
 		__sysrq_put_key_op(key, insert_op_p);
 		retval = 0;
 	} else {
 		retval = -1;
 	}
-	spin_unlock_irqrestore(&sysrq_key_table_lock, flags);
+	spin_unlock(&sysrq_key_table_lock);
+
+	/*
+	 * A concurrent __handle_sysrq eitehr got the old op or the new op.

yuo cnat spel

Quoted 7 lines

drivers/tty/sysrq.c +5 -0

+	 * Wait for it to go away before returning, so the code for an old
+	 * op is not freed (eg. on module unload) while it is in use.
+	 */
+	synchronize_rcu();
+
 	return retval;
 }

Quoted 6 lines

Echoing values into /proc/sysrq-trigger seems to be a popular way to get information out of the kernel. However, dumping information about thousands of processes, or hundreds of CPUs to serial console can result in IRQs being blocked for minutes, resulting in various kinds of cascade failures.

Quoted 3 lines

The most common failure is due to interrupts being blocked for a very long time. This can lead to things like failed IO requests, and other things the system cannot easily recover from.

I bet nobody wants that console output anyway. You do the sysrq then run dmesg or look in /var/log/messages to see what happened. People who are experiencing problems such as this should run `dmesg -n 1' before writing to sysrq-trigger.

Quoted 10 lines · Andrew Morton

Quoted 9 lines

Echoing values into /proc/sysrq-trigger seems to be a popular way to get information out of the kernel. However, dumping information about thousands of processes, or hundreds of CPUs to serial console can result in IRQs being blocked for minutes, resulting in various kinds of cascade failures.

The most common failure is due to interrupts being blocked for a very long time. This can lead to things like failed IO requests, and other things the system cannot easily recover from.

Quoted 4 lines

I bet nobody wants that console output anyway. You do the sysrq then run dmesg or look in /var/log/messages to see what happened. People who are experiencing problems such as this should run `dmesg -n 1' before writing to sysrq-trigger.

I don't agree. I have used sysrq-t multiple times in situations where userspace was already dead, but sysrq was still able to provide valuable information about the state of the kernel.

Quoted 15 lines

Quoted 14 lines

Quoted 9 lines

Echoing values into /proc/sysrq-trigger seems to be a popular way to get information out of the kernel. However, dumping information about thousands of processes, or hundreds of CPUs to serial console can result in IRQs being blocked for minutes, resulting in various kinds of cascade failures.

The most common failure is due to interrupts being blocked for a very long time. This can lead to things like failed IO requests, and other things the system cannot easily recover from.

I bet nobody wants that console output anyway. You do the sysrq then run dmesg or look in /var/log/messages to see what happened. People who are experiencing problems such as this should run `dmesg -n 1' before writing to sysrq-trigger.

Quoted 4 lines

I don't agree. I have used sysrq-t multiple times in situations where userspace was already dead, but sysrq was still able to provide valuable information about the state of the kernel.

I'm talking about /proc/sysrq-trigger, not the magic key combo.

Quoted 20 lines · Andrew Morton

Quoted 19 lines

Quoted 6 lines

Quoted 6 lines

Echoing values into /proc/sysrq-trigger seems to be a popular way to get information out of the kernel. However, dumping information about thousands of processes, or hundreds of CPUs to serial console can result in IRQs being blocked for minutes, resulting in various kinds of cascade failures.

Quoted 8 lines

Quoted 3 lines

The most common failure is due to interrupts being blocked for a very long time. This can lead to things like failed IO requests, and other things the system cannot easily recover from.

I bet nobody wants that console output anyway. You do the sysrq then run dmesg or look in /var/log/messages to see what happened. People who are experiencing problems such as this should run `dmesg -n 1' before writing to sysrq-trigger.

I don't agree. I have used sysrq-t multiple times in situations where userspace was already dead, but sysrq was still able to provide valuable information about the state of the kernel.

Quoted 1 line

I'm talking about /proc/sysrq-trigger, not the magic key combo.

At the end of the day, that reaches the same __handle_sysrq() codepath, no?

Echoing values into /proc/sysrq-trigger seems to be a popular way to get information out of the kernel. However, dumping information about thousands of processes, or hundreds of CPUs to serial console can result in IRQs being blocked for minutes, resulting in various kinds of cascade failures.

The most common failure is due to interrupts being blocked for a very long time. This can lead to things like failed IO requests, and other things the system cannot easily recover from.

This problem is easily fixable by making __handle_sysrq use RCU instead of spin_lock_irqsave.

This leaves the warning that RCU grace periods have not elapsed for a long time, but the system will come back from that automatically.

Quoted 10 lines · Rik van Riel

Echoing values into /proc/sysrq-trigger seems to be a popular way to get information out of the kernel. However, dumping information about thousands of processes, or hundreds of CPUs to serial console can result in IRQs being blocked for minutes, resulting in various kinds of cascade failures.

The most common failure is due to interrupts being blocked for a very long time. This can lead to things like failed IO requests, and other things the system cannot easily recover from.

Quoted 5 lines

This problem is easily fixable by making __handle_sysrq use RCU instead of spin_lock_irqsave.

This leaves the warning that RCU grace periods have not elapsed for a long time, but the system will come back from that automatically.

This, however, will make RCU stall detector to send NMI to all online CPUs so that they can dump their stacks.

IOW, this might actually make the whole sysrq dump last for much longer, and have the log polluted with all-CPU dumps for no good reason.

I wonder whether explicitly setting rcu_cpu_stall_suppress during sysrq handling might be a viable workaround for this.

Quoted 10 lines

Quoted 10 lines

Echoing values into /proc/sysrq-trigger seems to be a popular way to get information out of the kernel. However, dumping information about thousands of processes, or hundreds of CPUs to serial console can result in IRQs being blocked for minutes, resulting in various kinds of cascade failures.

The most common failure is due to interrupts being blocked for a very long time. This can lead to things like failed IO requests, and other things the system cannot easily recover from.

Quoted 8 lines

Quoted 5 lines

This problem is easily fixable by making __handle_sysrq use RCU instead of spin_lock_irqsave.

This leaves the warning that RCU grace periods have not elapsed for a long time, but the system will come back from that automatically.

This, however, will make RCU stall detector to send NMI to all online CPUs so that they can dump their stacks.

It already does that, since several of the longer-running sysrq handlers already grab rcu_read_lock(), for example show_state().

Quoted 5 lines

IOW, this might actually make the whole sysrq dump last for much longer, and have the log polluted with all-CPU dumps for no good reason.

I wonder whether explicitly setting rcu_cpu_stall_suppress during sysrq handling might be a viable workaround for this.

I suppose that would do the trick.

Quoted 10 lines · Rik van Riel

Quoted 10 lines

Quoted 10 lines

Echoing values into /proc/sysrq-trigger seems to be a popular way to get information out of the kernel. However, dumping information about thousands of processes, or hundreds of CPUs to serial console can result in IRQs being blocked for minutes, resulting in various kinds of cascade failures.

The most common failure is due to interrupts being blocked for a very long time. This can lead to things like failed IO requests, and other things the system cannot easily recover from.

Quoted 8 lines

Quoted 8 lines

Quoted 5 lines

This problem is easily fixable by making __handle_sysrq use RCU instead of spin_lock_irqsave.

This leaves the warning that RCU grace periods have not elapsed for a long time, but the system will come back from that automatically.

This, however, will make RCU stall detector to send NMI to all online CPUs so that they can dump their stacks.

Quoted 7 lines

It already does that, since several of the longer-running sysrq handlers already grab rcu_read_lock(), for example show_state().

Quoted 3 lines

IOW, this might actually make the whole sysrq dump last for much longer, and have the log polluted with all-CPU dumps for no good reason.

Quoted 4 lines

Quoted 2 lines

I wonder whether explicitly setting rcu_cpu_stall_suppress during sysrq handling might be a viable workaround for this.

I suppose that would do the trick.

I can imagine Paul opposing this though ... this variable is supposed to be changed only by cmdline/modparam, not really flipped during runtime as a bandaid ... let's add Paul to CC.

As suggested by Paul McKenney...

This seems small and simple enough that it should not introduce any extra maintenance work in the future.

---8<---

Some sysrq handlers can run for a long time, because they dump a lot of data onto a serial console. Having RCU stall warnings pop up in the middle of them only makes the problem worse.

This patch temporarily disables RCU stall warnings while a sysrq request is handled.

Signed-off-by Rik van Riel <[email protected]>

Suggested-by Paul McKenney <[email protected]>

---
 drivers/tty/sysrq.c      |  2 ++
 include/linux/rcupdate.h |  2 ++
 kernel/rcu/update.c      | 11 +++++++++++
 3 files changed, 15 insertions(+)

drivers/tty/sysrq.c +2 -0

index 3c61e9b..dd53af9 100644
@@ -511,6 +511,7 @@ void __handle_sysrq(int key, bool check_mask)
 	int orig_log_level;
 	int i;
 
+	rcu_sysrq_start();
 	rcu_read_lock();
 	/*
 	 * Raise the apparent loglevel to maximum so that the sysrq header

@@ -554,6 +555,7 @@ void __handle_sysrq(int key, bool check_mask)
 		console_loglevel = orig_log_level;
 	}
 	rcu_read_unlock();
+	rcu_sysrq_end();
 }
 
 void handle_sysrq(int key)

include/linux/rcupdate.h +2 -0

index 00a7fd6..b9a95f8 100644
@@ -227,6 +227,8 @@ void rcu_idle_enter(void);
 void rcu_idle_exit(void);
 void rcu_irq_enter(void);
 void rcu_irq_exit(void);
+void rcu_sysrq_start(void);
+void rcu_sysrq_end(void);
 
 #ifdef CONFIG_RCU_USER_QS
 void rcu_user_enter(void);

kernel/rcu/update.c +11 -0

index 4c0a9b0..2ac3289 100644
@@ -320,6 +320,17 @@ int rcu_jiffies_till_stall_check(void)
 	return till_stall_check * HZ + RCU_STALL_DELAY_DELTA;
 }
 
+void rcu_sysrq_start(void)
+{
+	rcu_cpu_stall_suppress = 2;
+}
+
+void rcu_sysrq_end(void)
+{
+	if (rcu_cpu_stall_suppress == 2)
+		rcu_cpu_stall_suppress = 0;
+}
+
 static int rcu_panic(struct notifier_block *this, unsigned long ev, void *ptr)
 {
 	rcu_cpu_stall_suppress = 1;

This, however, will make RCU stall detector to send NMI to all online CPUs so that they can dump their stacks.

IOW, this might actually make the whole sysrq dump last for much longer, and have the log polluted with all-CPU dumps for no good reason.

From 8286b521865503f92837a036fecdb51f41c0141c Mon Sep 17 00:00:00 2001

I use the patch below for some time now. While it doesn't avoid the log pollution in the first place, it lessens the impact somewhat.

Quoted 3 lines · Jörn Engel

I use the patch below for some time now. While it doesn't avoid the log pollution in the first place, it lessens the impact somewhat.

Added a config option and ported it to current -linus. Andrew, would you take this patch?

---

Sometimes the printk log is heavily interleaving between different cpus. This is particularly bad when you have two backtraces at the same time, but can be annoying in other cases as well. With an explicit cpu number, a simple grep can disentangle the mess for you.

Signed-off-by Joern Engel <[email protected]>

---
 kernel/printk/printk.c | 19 ++++++++++++++++---
 lib/Kconfig.debug      |  9 +++++++++
 2 files changed, 25 insertions(+), 3 deletions(-)

kernel/printk/printk.c +3 -1

index a45b50962295..b9e464924825 100644
@@ -200,6 +200,7 @@ struct printk_log {
 	u16 len;		/* length of entire record */
 	u16 text_len;		/* length of text buffer */
 	u16 dict_len;		/* length of dictionary buffer */
+	u16 cpu;		/* cpu the message was generated on */
 	u8 facility;		/* syslog facility */
 	u8 flags:5;		/* internal record flags */
 	u8 level:3;		/* syslog level */

@@ -346,6 +347,7 @@ static void log_store(int facility, int level,
 	msg->facility = facility;
 	msg->level = level & 7;
 	msg->flags = flags & 0x1f;
+	msg->cpu = smp_processor_id();
 	if (ts_nsec > 0)
 		msg->ts_nsec = ts_nsec;
 	else

@@ -859,7 +861,7 @@ static bool printk_time;
 #endif
 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
 
-static size_t print_time(u64 ts, char *buf)
+static size_t print_time(u64 ts, u16 cpu, char *buf)
 {
 	unsigned long rem_nsec;
 

kernel/printk/printk.c static size_t print_time(u64 ts, char *buf) · line 875

Quoted 7 lines

kernel/printk/printk.c +3 -0

@@ -868,11 +870,20 @@ static size_t print_time(u64 ts, char *buf)
 
 	rem_nsec = do_div(ts, 1000000000);
 
+#ifdef CONFIG_PRINTK_CPU
+	if (!buf)
+		return snprintf(NULL, 0, "[%5lu.000000,%02x] ",

%02x for a cpu? What happens on machines with 8k cpus?

And is this really an issue? Debugging by using printk is fun, but not really something that people need to add a cpu number to. Why not just use a tracepoint in your code to get the needed information instead?

kernel/printk/printk.c static size_t print_time(u64 ts, char *buf) · line 875

Quoted 3 lines

kernel/printk/printk.c +3 -0

+#ifdef CONFIG_PRINTK_CPU
+	if (!buf)
+		return snprintf(NULL, 0, "[%5lu.000000,%02x] ",

%02x for a cpu? What happens on machines with 8k cpus?

And is this really an issue? Debugging by using printk is fun, but not really something that people need to add a cpu number to. Why not just use a tracepoint in your code to get the needed information instead?

Quoted 5 lines · Greg Kroah-Hartman

kernel/printk/printk.c static size_t print_time(u64 ts, char *buf) · line 875

Quoted 3 lines

kernel/printk/printk.c +3 -0

+#ifdef CONFIG_PRINTK_CPU
+	if (!buf)
+		return snprintf(NULL, 0, "[%5lu.000000,%02x] ",

%02x for a cpu? What happens on machines with 8k cpus?

Ummm ... what issue do you see here, Greg? It'll print 0x1f40, no?

Quoted 3 lines

And is this really an issue? Debugging by using printk is fun, but not really something that people need to add a cpu number to. Why not just use a tracepoint in your code to get the needed information instead?

Well, if you have dmesg dump from panic that happens every other year, and you have to do post-mortem analysis on it, I am pretty sure you would love to be able to figure out how the stack traces would look like without inter-CPU interleaving. And I am pretty sure you wouldn't want to insert/enable a tracepoint and wait another two years for the bug to trigger again.

Quoted 5 lines

kernel/printk/printk.c static size_t print_time(u64 ts, char *buf) · line 875

Quoted 3 lines

kernel/printk/printk.c +3 -0

+#ifdef CONFIG_PRINTK_CPU
+	if (!buf)
+		return snprintf(NULL, 0, "[%5lu.000000,%02x] ",

%02x for a cpu? What happens on machines with 8k cpus?

Ummm ... what issue do you see here, Greg? It'll print 0x1f40, no?

Quoted 3 lines

And is this really an issue? Debugging by using printk is fun, but not really something that people need to add a cpu number to. Why not just use a tracepoint in your code to get the needed information instead?

Well, if you have dmesg dump from panic that happens every other year, and you have to do post-mortem analysis on it, I am pretty sure you would love to be able to figure out how the stack traces would look like without inter-CPU interleaving. And I am pretty sure you wouldn't want to insert/enable a tracepoint and wait another two years for the bug to trigger again.

Quoted 6 lines

Well, if you have dmesg dump from panic that happens every other year, and you have to do post-mortem analysis on it, I am pretty sure you would love to be able to figure out how the stack traces would look like without inter-CPU interleaving. And I am pretty sure you wouldn't want to insert/enable a tracepoint and wait another two years for the bug to trigger again.

Sounds like the appropriate fix would be to serialize stack dumping to the kernel log.

Quoted 7 lines · David Rientjes

Quoted 6 lines

Well, if you have dmesg dump from panic that happens every other year, and you have to do post-mortem analysis on it, I am pretty sure you would love to be able to figure out how the stack traces would look like without inter-CPU interleaving. And I am pretty sure you wouldn't want to insert/enable a tracepoint and wait another two years for the bug to trigger again.

Quoted 2 lines

Sounds like the appropriate fix would be to serialize stack dumping to the kernel log.

That's rather difficult, as it can be done both from NMI and non-NMI contexts, and those are very hard to synchronize.

Quoted 3 lines · Jörn Engel

I use the patch below for some time now. While it doesn't avoid the log pollution in the first place, it lessens the impact somewhat.

Added a config option and ported it to current -linus. Andrew, would you take this patch?

---

Sometimes the printk log is heavily interleaving between different cpus. This is particularly bad when you have two backtraces at the same time, but can be annoying in other cases as well. With an explicit cpu number, a simple grep can disentangle the mess for you.

Signed-off-by Joern Engel <[email protected]>

---
 kernel/printk/printk.c | 19 ++++++++++++++++---
 lib/Kconfig.debug      |  9 +++++++++
 2 files changed, 25 insertions(+), 3 deletions(-)

kernel/printk/printk.c +16 -3

index a45b50962295..b9e464924825 100644
@@ -200,6 +200,7 @@ struct printk_log {
 	u16 len;		/* length of entire record */
 	u16 text_len;		/* length of text buffer */
 	u16 dict_len;		/* length of dictionary buffer */
+	u16 cpu;		/* cpu the message was generated on */
 	u8 facility;		/* syslog facility */
 	u8 flags:5;		/* internal record flags */
 	u8 level:3;		/* syslog level */

@@ -346,6 +347,7 @@ static void log_store(int facility, int level,
 	msg->facility = facility;
 	msg->level = level & 7;
 	msg->flags = flags & 0x1f;
+	msg->cpu = smp_processor_id();
 	if (ts_nsec > 0)
 		msg->ts_nsec = ts_nsec;
 	else

@@ -859,7 +861,7 @@ static bool printk_time;
 #endif
 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
 
-static size_t print_time(u64 ts, char *buf)
+static size_t print_time(u64 ts, u16 cpu, char *buf)
 {
 	unsigned long rem_nsec;
 

@@ -868,11 +870,20 @@ static size_t print_time(u64 ts, char *buf)
 
 	rem_nsec = do_div(ts, 1000000000);
 
+#ifdef CONFIG_PRINTK_CPU
+	if (!buf)
+		return snprintf(NULL, 0, "[%5lu.000000,%02x] ",
+				(unsigned long)ts, cpu);
+
+	return sprintf(buf, "[%5lu.%06lu,%02x] ",
+			(unsigned long)ts, rem_nsec / 1000, cpu);
+#else
 	if (!buf)
 		return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
 
 	return sprintf(buf, "[%5lu.%06lu] ",
 		       (unsigned long)ts, rem_nsec / 1000);
+#endif
 }
 
 static size_t print_prefix(const struct printk_log *msg, bool syslog, char *buf)

@@ -894,7 +905,7 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog, char *buf)
 		}
 	}
 
-	len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
+	len += print_time(msg->ts_nsec, msg->cpu, buf ? buf + len : NULL);
 	return len;
 }
 

@@ -1391,6 +1402,7 @@ static struct cont {
 	size_t cons;			/* bytes written to console */
 	struct task_struct *owner;	/* task of first print*/
 	u64 ts_nsec;			/* time of first print */
+	u16 cpu;			/* cpu the message was generated on */
 	u8 level;			/* log level of first message */
 	u8 facility;			/* log level of first message */
 	enum log_flags flags;		/* prefix, newline flags */

@@ -1440,6 +1452,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 		cont.facility = facility;
 		cont.level = level;
 		cont.owner = current;
+		cont.cpu = smp_processor_id();
 		cont.ts_nsec = local_clock();
 		cont.flags = 0;
 		cont.cons = 0;

@@ -1461,7 +1474,7 @@ static size_t cont_print_text(char *text, size_t size)
 	size_t len;
 
 	if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
-		textlen += print_time(cont.ts_nsec, text);
+		textlen += print_time(cont.ts_nsec, cont.cpu, text);
 		size -= textlen;
 	}
 

lib/Kconfig.debug +9 -0

index 819ac51202c0..bdec67eca521 100644
@@ -15,6 +15,15 @@ config PRINTK_TIME
 	  The behavior is also controlled by the kernel command line
 	  parameter printk.time=1. See Documentation/kernel-parameters.txt
 
+config PRINTK_CPU
+	bool "Show CPU number along with timing information"
+	depends on PRINTK_TIME
+	help
+	  Selecting this option adds the CPU number to be added to
+	  timestamps of printk() messages.  This can be useful when
+	  messages from several CPUs are interleaved, in particular
+	  for stack traces.
+
 config DEFAULT_MESSAGE_LOGLEVEL
 	int "Default message log level (1-7)"
 	range 1 7

Signature · 1 line

2.0.0.rc0.1.g7b2ba98

Quoted 7 lines · J__rn Engel

Quoted 3 lines · J__rn Engel

I use the patch below for some time now. While it doesn't avoid the log pollution in the first place, it lessens the impact somewhat.

Added a config option and ported it to current -linus. Andrew, would you take this patch?

Andrew? Did you dislike this patch for some reason or just miss it in the thread?

Quoted 9 lines · On Mon, 28 Apr 2014 19:40:39 -0400 J__rn Engel <[email protected]> wrote:

Quoted 7 lines · J__rn Engel

Quoted 3 lines · J__rn Engel

I use the patch below for some time now. While it doesn't avoid the log pollution in the first place, it lessens the impact somewhat.

Added a config option and ported it to current -linus. Andrew, would you take this patch?

Quoted 2 lines

Andrew? Did you dislike this patch for some reason or just miss it in the thread?

Neither ;) I try to respond in some way to all patches unless I think it's clear to the originator why I took no action. And I think I'm pretty good at not losing stuff.

otoh, it has only been four days, three of which I spent offline...

Quoted 13 lines · Andrew Morton

Quoted 11 lines · On Mon, 28 Apr 2014 19:40:39 -0400 J__rn Engel <[email protected]> wrote:

Quoted 7 lines · J__rn Engel

Quoted 3 lines · J__rn Engel

I use the patch below for some time now. While it doesn't avoid the log pollution in the first place, it lessens the impact somewhat.

Added a config option and ported it to current -linus. Andrew, would you take this patch?

Andrew? Did you dislike this patch for some reason or just miss it in the thread?

Quoted 5 lines

Neither ;) I try to respond in some way to all patches unless I think it's clear to the originator why I took no action. And I think I'm pretty good at not losing stuff.

otoh, it has only been four days, three of which I spent offline...

Ping. It is closer to 40 days now. Can I fault this patch back into your memory?

Sorry, it seems I'm better at losing stuff than I thought I was.

I've restored the patch to the input queue.

Quoted 13 lines · Andrew Morton

Quoted 11 lines · On Mon, 28 Apr 2014 19:40:39 -0400 J__rn Engel <[email protected]> wrote:

Quoted 7 lines · J__rn Engel

Quoted 3 lines · J__rn Engel

I use the patch below for some time now. While it doesn't avoid the log pollution in the first place, it lessens the impact somewhat.

Added a config option and ported it to current -linus. Andrew, would you take this patch?

Andrew? Did you dislike this patch for some reason or just miss it in the thread?

Quoted 5 lines

Neither ;) I try to respond in some way to all patches unless I think it's clear to the originator why I took no action. And I think I'm pretty good at not losing stuff.

otoh, it has only been four days, three of which I spent offline...

Ping.

Quoted 18 lines · J__rn Engel

Quoted 17 lines · Andrew Morton

Quoted 11 lines · On Mon, 28 Apr 2014 19:40:39 -0400 J__rn Engel <[email protected]> wrote:

Quoted 7 lines · J__rn Engel

Quoted 3 lines · J__rn Engel

I use the patch below for some time now. While it doesn't avoid the log pollution in the first place, it lessens the impact somewhat.

Added a config option and ported it to current -linus. Andrew, would you take this patch?

Andrew? Did you dislike this patch for some reason or just miss it in the thread?

Neither ;) I try to respond in some way to all patches unless I think it's clear to the originator why I took no action. And I think I'm pretty good at not losing stuff.

Quoted 3 lines

Quoted 1 line

otoh, it has only been four days, three of which I spent offline...

Ping.

Ping.

Sometimes the printk log is heavily interleaving between different cpus. This is particularly bad when you have two backtraces at the same time, but can be annoying in other cases as well. With an explicit cpu number, a simple grep can disentangle the mess for you.

Signed-off-by Joern Engel <[email protected]>

---
 kernel/printk/printk.c | 19 ++++++++++++++++---
 lib/Kconfig.debug      |  9 +++++++++
 2 files changed, 25 insertions(+), 3 deletions(-)

kernel/printk/printk.c +1 -0

index a45b50962295..b9e464924825 100644
@@ -200,6 +200,7 @@ struct printk_log {
 	u16 len;		/* length of entire record */
 	u16 text_len;		/* length of text buffer */
 	u16 dict_len;		/* length of dictionary buffer */
+	u16 cpu;		/* cpu the message was generated on */
 	u8 facility;		/* syslog facility */
 	u8 flags:5;		/* internal record flags */
 	u8 level:3;		/* syslog level */