Add support to dump printk buffer to console via sysrq

It is useful to be able to dump the printk buffer directly to consoles in some situations so as to not flood the buffer. To do this, we reuse the CONSOLE_REPLAY_ALL mode code in console_flush_on_panic() by moving the code to a helper function console_rewind_all(). This is done because console_flush_on_panic() sets console_may_schedule to 0 but this should not be done in our case. Then console_rewind_all() is called from the new function dump_printk_buffer() with console lock held to set the console sequence number to oldest record in the buffer for all consoles. Releasing the console lock will flush the contents of printk buffer to the consoles.

Suggested-by John Ogness <[email protected]>

Signed-off-by Sreenath Vijayan <[email protected]>

Signed-off-by Shimoyashiki Taichi <[email protected]>

It is useful to be able to dump the printk buffer directly to consoles in some situations so as to not flood the buffer.

To do this, we reuse the CONSOLE_REPLAY_ALL mode code in console_flush_on_panic() by moving the code to a helper function console_rewind_all(). This is done because console_flush_on_panic() sets console_may_schedule to 0 but this should not be done in our case.

Then console_rewind_all() is called from the new function dump_printk_buffer() with console lock held to set the console sequence number to oldest record in the buffer for all consoles. Releasing the console lock will flush the contents of printk buffer to the consoles.

kernel/printk/printk.c +10 -0

+static void console_rewind_all(void)
+{
+	struct console *c;
+	short flags;
+	int cookie;
+	u64 seq;
+
+	seq = prb_first_valid_seq(prb);
+
+	cookie = console_srcu_read_lock();

kernel/printk/printk.c +8 -24

+			c->seq = seq;
+		}
+	}
+	console_srcu_read_unlock(cookie);
+}
+
 /**
  * console_flush_on_panic - flush console content on panic
  * @mode: flush all messages in buffer or just the pending ones

@@ -3162,30 +3188,8 @@ void console_flush_on_panic(enum con_flush_mode mode)
 	 */
 	console_may_schedule = 0;
 
-	if (mode == CONSOLE_REPLAY_ALL) {
-		struct console *c;
-		short flags;
-		int cookie;
-		u64 seq;
-
-		seq = prb_first_valid_seq(prb);
-
-		cookie = console_srcu_read_lock();
-		for_each_console_srcu(c) {
-			flags = console_srcu_read_flags(c);
-
-			if (flags & CON_NBCON) {
-				nbcon_seq_force(c, seq);
-			} else {
-				/*
-				 * This is an unsynchronized assignment. On
-				 * panic legacy consoles are only best effort.
-				 */
-				c->seq = seq;
-			}
-		}
-		console_srcu_read_unlock(cookie);
-	}
+	if (mode == CONSOLE_REPLAY_ALL)
+		console_rewind_all();
 
 	console_flush_all(false, &next_seq, &handover);
 }

Quoted 2 lines · Sreenath Vijayan

It is useful to be able to dump the printk buffer directly to consoles in some situations so as to not flood the buffer.

This is not longer true. I think that it was valid for the previous versions which used separate buffers with the kmsg_dump API.

Quoted 5 lines

To do this, we reuse the CONSOLE_REPLAY_ALL mode code in console_flush_on_panic() by moving the code to a helper function console_rewind_all(). This is done because console_flush_on_panic() sets console_may_schedule to 0 but this should not be done in our case.

Also the "c->seq = seq;" is not safe in the panic version. But it will be safe when called under the console_lock.

Quoted 5 lines

Then console_rewind_all() is called from the new function dump_printk_buffer() with console lock held to set the console sequence number to oldest record in the buffer for all consoles. Releasing the console lock will flush the contents of printk buffer to the consoles.

My proposed commit message is:

<proposal>
Add a generic function for replaying the kernel log on consoles. It would allow seeing the the log on an unresponsive terminal via sysrq interface.

Reuse the existing code from console_flush_on_panic() for reseting the sequence numbers. It will be safe when called under console_lock(). Also the console_unlock() will automatically flush the messages on the consoles.

kernel/printk/printk.c void console_unblank(void) · line 3136

Quoted 6 lines

kernel/printk/printk.c +0 -0

@@ -3134,6 +3134,32 @@ void console_unblank(void)
 		pr_flush(1000, true);
 }
 

I would call this function __console_rewind_all(void) because it is not safe on its own. Also It would deserve a comment, something like:

/*
* Rewind all consoles to the oldest available record. *
* IMPORTANT: The function is safe only when called under
* console_lock(). It is not enforced because
* it is used as a best effort in panic().
*/
static void __console_rewind_all(void)

This would deserve a comment because it is not safe by default.

Quoted 10 lines

kernel/printk/printk.c +10 -0

+static void console_rewind_all(void)
+{
+	struct console *c;
+	short flags;
+	int cookie;
+	u64 seq;
+
+	seq = prb_first_valid_seq(prb);
+
+	cookie = console_srcu_read_lock();

kernel/printk/printk.c void console_unblank(void) · line 3156

Quoted 10 lines

kernel/printk/printk.c +10 -0

+	for_each_console_srcu(c) {
+		flags = console_srcu_read_flags(c);
+
+		if (flags & CON_NBCON) {
+			nbcon_seq_force(c, seq);
+		} else {
+			/*
+			 * This is an unsynchronized assignment. On
+			 * panic legacy consoles are only best effort.
+			 */

We should change this to something like:

			/*
			 * This assigment is safe only when called under
			 * console_lock(). */
			 */

Quoted 43 lines

kernel/printk/printk.c +8 -24

+			c->seq = seq;
+		}
+	}
+	console_srcu_read_unlock(cookie);
+}
+
 /**
  * console_flush_on_panic - flush console content on panic
  * @mode: flush all messages in buffer or just the pending ones

@@ -3162,30 +3188,8 @@ void console_flush_on_panic(enum con_flush_mode mode)
 	 */
 	console_may_schedule = 0;
 
-	if (mode == CONSOLE_REPLAY_ALL) {
-		struct console *c;
-		short flags;
-		int cookie;
-		u64 seq;
-
-		seq = prb_first_valid_seq(prb);
-
-		cookie = console_srcu_read_lock();
-		for_each_console_srcu(c) {
-			flags = console_srcu_read_flags(c);
-
-			if (flags & CON_NBCON) {
-				nbcon_seq_force(c, seq);
-			} else {
-				/*
-				 * This is an unsynchronized assignment. On
-				 * panic legacy consoles are only best effort.
-				 */
-				c->seq = seq;
-			}
-		}
-		console_srcu_read_unlock(cookie);
-	}
+	if (mode == CONSOLE_REPLAY_ALL)
+		console_rewind_all();
 
 	console_flush_all(false, &next_seq, &handover);
 }

kernel/printk/printk.c void kmsg_dump_rewind(struct kmsg_dump_iter *iter) · line 4269

Quoted 7 lines

kernel/printk/printk.c +4 -0

@@ -4259,6 +4263,15 @@ void kmsg_dump_rewind(struct kmsg_dump_iter *iter)
 }
 EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
 
+/**
+ * Dump the printk ring buffer directly to consoles
+ */
+void dump_printk_buffer(void)

I would call this function console_replay_all(). IMHO, it better describes what it does.

kernel/printk/printk.c void kmsg_dump_rewind(struct kmsg_dump_iter *iter) · line 4272

Quoted 3 lines

kernel/printk/printk.c +3 -0

+{
+	console_lock();
+	console_rewind_all();

I would add a comment:

	/* Consoles are flushed as part of console_unlock(). */

kernel/printk/printk.c void kmsg_dump_rewind(struct kmsg_dump_iter *iter) · line 4275

Quoted 3 lines

kernel/printk/printk.c +2 -0

+	console_unlock();
+}
 #endif

Best Regards,
Petr

When terminal is unresponsive, one cannot use dmesg to view printk ring buffer messages. Also, syslog services may be disabled, to check the messages after a reboot, especially on embedded systems. In this scenario, dump the printk ring buffer messages via sysrq by pressing sysrq+D.

Signed-off-by Sreenath Vijayan <[email protected]>

Signed-off-by Shimoyashiki Taichi <[email protected]>

When terminal is unresponsive, one cannot use dmesg to view printk ring buffer messages. Also, syslog services may be disabled, to check the messages after a reboot, especially on embedded systems. In this scenario, dump the printk ring buffer messages via sysrq by pressing sysrq+D.

Quoted 5 lines · Sreenath Vijayan

When terminal is unresponsive, one cannot use dmesg to view printk ring buffer messages. Also, syslog services may be disabled, to check the messages after a reboot, especially on embedded systems. In this scenario, dump the printk ring buffer messages via sysrq by pressing sysrq+D.

I would use sysrq-R and say that it replays the kernel log on consoles.

The word "dump" is ambiguous. People might thing that it calls dmesg dumpers.

Also the messages would be shown on the terminal only when console_loglevel is set to show all messages. This is done in __handle_sysrq(). But it is not done in the workqueue context.

Finally, the commit message should explain why workqueues are used and what are the limitations. Something like:

<add>
The log is replayed using workqueues. The reason is that it has to be done a safe way (in compare with panic context).

This also means that the sysrq won't have the desired effect when the system is in so bad state that workqueues do not make any progress.
</add>

Another reason might be that we do not want to do it in an interrupt context. But this reason is questionable. Many other sysrq commands do a complicate work and print many messages as well.

Another reason is that the function need to use console_lock() which can't be called in IRQ context. Maybe, we should use console_trylock() instead.

The function would replay the messages only when console_trylock() succeeds. Users could repeat the sysrq when it fails.

Idea:

Using console_trylock() actually might be more reliable than workqueues. console_trylock() might fail repeatably when:

+ the console_lock() owner is stuck. But workqueues would fail in this case as well.

+ there is a flood of messages. In this case, replaying the log would not help much.

Another advantage is that the consoles would be flushed in sysrq context with the manipulated console_loglevel.

I just remembered all the rt-changes coming down the pipe for consoles/printk, is this going to mess with that?

So when this option fails when people need it the most, perhaps it's not worth adding? When else would people want to use it?

Quoted 5 lines · Sreenath Vijayan

When terminal is unresponsive, one cannot use dmesg to view printk ring buffer messages. Also, syslog services may be disabled, to check the messages after a reboot, especially on embedded systems. In this scenario, dump the printk ring buffer messages via sysrq by pressing sysrq+D.

I would use sysrq-R and say that it replays the kernel log on consoles.

The word "dump" is ambiguous. People might thing that it calls dmesg dumpers.

Also the messages would be shown on the terminal only when console_loglevel is set to show all messages. This is done in __handle_sysrq(). But it is not done in the workqueue context.

Finally, the commit message should explain why workqueues are used and what are the limitations. Something like:

<add>
The log is replayed using workqueues. The reason is that it has to be done a safe way (in compare with panic context).

This also means that the sysrq won't have the desired effect when the system is in so bad state that workqueues do not make any progress.
</add>

Another reason might be that we do not want to do it in an interrupt context. But this reason is questionable. Many other sysrq commands do a complicate work and print many messages as well.

Another reason is that the function need to use console_lock() which can't be called in IRQ context. Maybe, we should use console_trylock() instead.

The function would replay the messages only when console_trylock() succeeds. Users could repeat the sysrq when it fails.

Idea:

Using console_trylock() actually might be more reliable than workqueues. console_trylock() might fail repeatably when:

+ the console_lock() owner is stuck. But workqueues would fail in this case as well.

+ there is a flood of messages. In this case, replaying the log would not help much.

Another advantage is that the consoles would be flushed in sysrq context with the manipulated console_loglevel.

Best Regards,
Petr

Quoted 8 lines · Petr Mladek

Idea:

Using console_trylock() actually might be more reliable than workqueues. console_trylock() might fail repeatably when:

+ the console_lock() owner is stuck. But workqueues would fail in this case as well.

Quoted 8 lines

+ there is a flood of messages. In this case, replaying the log would not help much.

Another advantage is that the consoles would be flushed in sysrq context with the manipulated console_loglevel.

Best Regards,
Petr

Yes, this seems to work well from interrupt context when the console lock owner is not stuck. We can also manipulate the console_loglevel. Something like this:

//in printk.c
void console_replay_all(void)

{
       if (console_trylock()) {
               __console_rewind_all();
               console_unlock();
       }
}

//in sysrq.c
static void sysrq_handle_dmesg_dump(u8 key)

{
       int orig_log_level = console_loglevel;
       console_loglevel = CONSOLE_LOGLEVEL_DEFAULT;
       console_replay_all();
       console_loglevel = orig_log_level;
}

The downside I see is that the user may have to hit the key multiple times or give up trying if the console lock owner is busy at the time of key press. This information should probably be updated in the documentation.

Please let me know your opinion.

Regards,
Sreenath

//in printk.c
void console_replay_all(void)

{
       if (console_trylock()) {
               __console_rewind_all();
               console_unlock();
       }
}

//in sysrq.c
static void sysrq_handle_dmesg_dump(u8 key)

{
       int orig_log_level = console_loglevel;
       console_loglevel = CONSOLE_LOGLEVEL_DEFAULT;
       console_replay_all();
       console_loglevel = orig_log_level;
}

Quoted 5 lines · Sreenath Vijayan

When terminal is unresponsive, one cannot use dmesg to view printk ring buffer messages. Also, syslog services may be disabled, to check the messages after a reboot, especially on embedded systems. In this scenario, dump the printk ring buffer messages via sysrq by pressing sysrq+D.

I would use sysrq-R and say that it replays the kernel log on consoles.

The word "dump" is ambiguous. People might thing that it calls dmesg dumpers.

Also the messages would be shown on the terminal only when console_loglevel is set to show all messages. This is done in __handle_sysrq(). But it is not done in the workqueue context.

Finally, the commit message should explain why workqueues are used and what are the limitations. Something like:

<add>
The log is replayed using workqueues. The reason is that it has to be done a safe way (in compare with panic context).

This also means that the sysrq won't have the desired effect when the system is in so bad state that workqueues do not make any progress.
</add>

Another reason might be that we do not want to do it in an interrupt context. But this reason is questionable. Many other sysrq commands do a complicate work and print many messages as well.

Another reason is that the function need to use console_lock() which can't be called in IRQ context. Maybe, we should use console_trylock() instead.

The function would replay the messages only when console_trylock() succeeds. Users could repeat the sysrq when it fails.

Idea:

Using console_trylock() actually might be more reliable than workqueues. console_trylock() might fail repeatably when:

+ the console_lock() owner is stuck. But workqueues would fail in this case as well.

+ there is a flood of messages. In this case, replaying the log would not help much.

Another advantage is that the consoles would be flushed in sysrq context with the manipulated console_loglevel.

Best Regards,
Petr

Hi,

This patch series enables one to dump the messages in printk ring buffer unless all CPUs are locked up. This is useful to view the kernel messages when terminal is unresponsive to enter commands like dmesg and syslog services are also disabled, especially on embedded targets.

Hi,

first, I am sorry for joining the game so late. I was sick and have had a lot of pending tasks after Christmas's holidays and the sickness.

Quoted 2 lines · Sreenath Vijayan

Hi,

Quoted 5 lines

This patch series enables one to dump the messages in printk ring buffer unless all CPUs are locked up. This is useful to view the kernel messages when terminal is unresponsive to enter commands like dmesg and syslog services are also disabled, especially on embedded targets.

What is the exact scenario for this feature, please?

IMHO, rewinding the entire log on an unresponsive terminal has a questionable value. Most messages would scroll down quickly and only the last messages would stay visible.

Also this code would rewind all consoles, including (slow) serial ones. I wonder if rewind on these consoles would be useful as well.

That said, I am not completely against this feature. I just want to be sure that it does what you expect.

Best Regards,
Petr