Re: [PATCH printk v1 08/10] printk: introduce kernel sync mode

Petr Mladek
2021-08-05T17:11:38Z

On Tue 2021-08-03 15:18:59, John Ogness wrote:
> Introduce "sync mode", which means that all printk calls will
> synchronously write to the console. Once activated, this mode is
> never deactivated. It is used when the kernel is about to end
> (such as panic, oops, shutdown, reboot).
>
> Sync mode can only be activated if atomic consoles are available.
>
> In sync mode:
>
> - only atomic consoles (write_atomic() callback) will print
> - printing occurs within vprintk_store() instead of console_unlock()
>
> CONSOLE_LOG_MAX is moved to printk.h to support the per-console
> buffer used in sync mode.
>
> diff --git a/include/linux/console.h b/include/linux/console.h
> index 2f11b604e487..eda9b96e3fb6 100644
> --- a/include/linux/console.h
> +++ b/include/linux/console.h
> @@ -151,6 +151,9 @@ struct console {
> short flags;
> short index;
> int cflag;
> +#if defined(CONFIG_PRINTK) && defined(CONFIG_HAVE_ATOMIC_CONSOLE)
> + char sync_buf[CONSOLE_LOG_MAX];

Could it be allocated in register_console()?

It is needed only when sync_write() callback is defined...

> +#endif
> void *data;
> struct console *next;
> };
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> +static bool print_sync(struct console *con, u64 *seq)
> +{
> + struct printk_info info;
> + struct printk_record r;
> + size_t text_len;
> +
> + prb_rec_init_rd(&r, &info, &con->sync_buf[0], sizeof(con->sync_buf));
> +
> + if (!prb_read_valid(prb, *seq, &r))
> + return false;
> +

It should check suppress_message_printing().

> + text_len = record_print_text(&r, console_msg_format & MSG_FORMAT_SYSLOG, printk_time);
> +
> + con->write_atomic(con, &con->sync_buf[0], text_len);
> +
> + *seq = r.info->seq;
> +
> + touch_softlockup_watchdog_sync();
> + clocksource_touch_watchdog();
> + rcu_cpu_stall_reset();
> + touch_nmi_watchdog();
> +
> + if (text_len)
> + printk_delay(r.info->level);
> +
> + return true;
> +}
> +
> +static void print_sync_to(struct console *con, u64 seq)
> +{
> + u64 printk_seq;
> +
> + while (!__printk_cpu_trylock())
> + __printk_wait_on_cpu_lock();
> +
> + for (;;) {
> + printk_seq = read_console_seq();
> + if (printk_seq > seq)
> + break;
> + if (!print_sync(con, &printk_seq))
> + break;
> +#ifdef CONFIG_PRINTK_NMI
> + if (in_nmi()) {
> + latched_seq_write(&console_sync_nmi_seq, printk_seq + 1);
> + continue;
> + }
> +#endif
> + latched_seq_write(&console_sync_seq, printk_seq + 1);
> + }
> +
> + __printk_cpu_unlock();
> +}
> +
> +static void call_sync_console_drivers(u64 seq)
> +{
> + struct console *con;
> +
> + for_each_console(con) {
> + if (!(con->flags & CON_ENABLED))
> + continue;
> + if (!con->write_atomic)
> + continue;
> + print_sync_to(con, seq);
> + }
> +}
> +#else
> +
> +#define read_console_seq() latched_seq_read_nolock(&console_seq)
> +#define in_sync_mode() false
> +#define enable_sync_mode()
> +#define call_sync_console_drivers(seq) ((void)seq)
> +
> +#endif /* CONFIG_HAVE_ATOMIC_CONSOLE */
> +
> /*
> * Special console_lock variants that help to reduce the risk of soft-lockups.
> * They allow to pass console_lock to another printk() call using a busy wait.
> @@ -2084,6 +2231,8 @@ static void call_console_drivers(const char *ext_text, size_t ext_len,
> if (!cpu_online(smp_processor_id()) &&
> !(con->flags & CON_ANYTIME))
> continue;
> + if (in_sync_mode())
> + continue;

IMHO, this causes that console_unlock() will iterate over all pending
messsages without calling console. But it will still increment
console_seq.

As a result, the messages will be skipped also by print_sync_to() because
read_console_seq() will return the incremented value.

I think that we need to break the iteration in console_unlock().

Or do I miss something?

> if (con->flags & CON_EXTENDED)
> con->write(con, ext_text, ext_len);
> else {
> @@ -2251,6 +2400,7 @@ int vprintk_store(int facility, int level,
> const u32 caller_id = printk_caller_id();
> struct prb_reserved_entry e;
> enum printk_info_flags flags = 0;
> + bool final_commit = false;
> struct printk_record r;
> unsigned long irqflags;
> u16 trunc_msg_len = 0;
> @@ -2261,6 +2411,7 @@ int vprintk_store(int facility, int level,
> u16 text_len;
> int ret = 0;
> u64 ts_nsec;
> + u64 seq;
>
> /*
> * Since the duration of printk() can vary depending on the message
> @@ -2299,6 +2450,7 @@ int vprintk_store(int facility, int level,
> if (flags & LOG_CONT) {
> prb_rec_init_wr(&r, reserve_size);
> if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) {
> + seq = r.info->seq;
> text_len = printk_sprint(&r.text_buf[r.info->text_len], reserve_size,
> facility, &flags, fmt, args);
> r.info->text_len += text_len;
> @@ -2306,6 +2458,7 @@ int vprintk_store(int facility, int level,
> if (flags & LOG_NEWLINE) {
> r.info->flags |= LOG_NEWLINE;
> prb_final_commit(&e);
> + final_commit = true;
> } else {
> prb_commit(&e);
> }
> @@ -2330,6 +2483,8 @@ int vprintk_store(int facility, int level,
> goto out;
> }
>
> + seq = r.info->seq;
> +
> /* fill message */
> text_len = printk_sprint(&r.text_buf[0], reserve_size, facility, &flags, fmt, args);
> if (trunc_msg_len)
> @@ -2344,13 +2499,19 @@ int vprintk_store(int facility, int level,
> memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info));
>
> /* A message without a trailing newline can be continued. */
> - if (!(flags & LOG_NEWLINE))
> + if (!(flags & LOG_NEWLINE)) {
> prb_commit(&e);
> - else
> + } else {
> prb_final_commit(&e);
> + final_commit = true;
> + }
>
> ret = text_len + trunc_msg_len;
> out:
> + /* only the kernel may perform synchronous printing */
> + if (in_sync_mode() && facility == 0 && final_commit)
> + call_sync_console_drivers(seq);

Is there any reason why this is called from vprintk_emit()?

I guess that you wanted to call it before releasing IRQ.
But is it really necessary? call_sync_console_drivers(seq)
reads the message again via the seq number anyway.

I have to say that the new code makes the printk() code/api much more
twisted. It is a combination of the naming scheme and design.

The original code path is:

+ printk()
+ vprintk_emit()
+ vprintk_store()
+ console_trylock()
+ console_unlock()
+ prb_read_valid()
+ record_print_text()
+ call_console_drivers()
+ con->write()

The new code path is:

+ printk()
+ vprintk_emit()
+ vprintk_store()
+ call_sync_console_drivers()
+ printk_sync_to()
+ print_sync()
+ prb_read_valid()
+ record_print_text()
+ con->write_atomic()

One thing is the ordering of the api names:

+ printk -> vprintk -> console -> record_print -> call_console -> con -> write
vs.
+ printk -> vprintk -> call_console -> print -> record_print -> con -> write

The original patch called console() API from printk() API. The most
ugly things were:

+ console_unlock() flushed the messages to the console.
A cleaner API would be:

console_lock();
console_flush();
console_unlock();

+ record_print() called from console_unlock(). The "print" name
name makes it hard to distinguish from the "printk" API.
But it does a completely different job:

+ "printk" API stores the message and call console
+ "record_print" API converts the message into the console format

The new code adds even more twists:

+ Adds yet another "print" API. It has another meaning than
"printk" or "record_print" API:

+ "printk" API stores the message and call console
+ "print" API prints the message to the console
+ "record_print" API converts the message into the console format

+ call_sync_console_drivers() does similar job as console_unlock()
(iterates over all pending messages, read, format, call console).
While the original call_console_drivers() only called the
console. The logic is somehow inside out.

This is why I opened the discussion about the behavior with console
kthreads.

I think that we might need another synchronous mode also for the early
boot, suspend, kexec, panic, for non-atomic consoles. We might need
another cycle/solution when there are per-console kthreads.

I would prefer to somehow refactor the existing console_unlock()
so that the iteration over pending messages and call_console_drivers()
might be usable also in the other sync modes, console kthreads, ...

Best Regards,
Petr

PS: I have vacation the following two weeks. I am still going to work
tomorrow (Friday) but I am not sure how much time I will have to
discuss this. I am afraid that I won't be able to help much before
I am back from the vacation.