From 5c6fb48313777b15ea366464ccc3dbda1ff9003c Mon Sep 17 00:00:00 2001 From: John Ogness Date: Mon, 30 Nov 2020 01:42:06 +0106 Subject: [PATCH 104/323] printk: introduce kernel sync mode Origin: https://www.kernel.org/pub/linux/kernel/projects/rt/5.10/older/patches-5.10.215-rt107.tar.xz When the kernel performs an OOPS, enter into "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. Signed-off-by: John Ogness Signed-off-by: Sebastian Andrzej Siewior Signed-off-by: Luis Claudio R. Goncalves --- include/linux/console.h | 4 ++ include/linux/printk.h | 6 ++ kernel/printk/printk.c | 133 ++++++++++++++++++++++++++++++++++++++-- 3 files changed, 137 insertions(+), 6 deletions(-) diff --git a/include/linux/console.h b/include/linux/console.h index 613df76903f54..fcc98354f7332 100644 --- a/include/linux/console.h +++ b/include/linux/console.h @@ -16,6 +16,7 @@ #include #include +#include struct vc_data; struct console_font_op; @@ -151,6 +152,9 @@ struct console { short flags; short index; int cflag; +#ifdef CONFIG_PRINTK + char sync_buf[CONSOLE_LOG_MAX]; +#endif uint ispeed; uint ospeed; void *data; diff --git a/include/linux/printk.h b/include/linux/printk.h index c6bb48f0134c0..3738374e2b3bc 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -46,6 +46,12 @@ static inline const char *printk_skip_headers(const char *buffer) #define CONSOLE_EXT_LOG_MAX 8192 +/* + * The maximum size of a record formatted for console printing + * (i.e. with the prefix prepended to every line). + */ +#define CONSOLE_LOG_MAX 4096 + /* printk's without a loglevel use this.. */ #define MESSAGE_LOGLEVEL_DEFAULT CONFIG_MESSAGE_LOGLEVEL_DEFAULT diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 818c17b26bdee..1ce593876dca9 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -44,6 +44,7 @@ #include #include #include +#include #include #include #include @@ -361,6 +362,9 @@ enum log_flags { static DEFINE_SPINLOCK(syslog_lock); #ifdef CONFIG_PRINTK +/* Set to enable sync mode. Once set, it is never cleared. */ +static bool sync_mode; + DECLARE_WAIT_QUEUE_HEAD(log_wait); /* All 3 protected by @syslog_lock. */ /* the next printk record to read by syslog(READ) or /proc/kmsg */ @@ -400,9 +404,6 @@ static struct latched_seq clear_seq = { /* the maximum size allowed to be reserved for a record */ #define LOG_LINE_MAX (1024 - PREFIX_MAX) -/* the maximum size of a formatted record (i.e. with prefix added per line) */ -#define CONSOLE_LOG_MAX 4096 - #define LOG_LEVEL(v) ((v) & 0x07) #define LOG_FACILITY(v) ((v) >> 3 & 0xff) @@ -1745,6 +1746,91 @@ static inline void printk_delay(int level) } } +static bool kernel_sync_mode(void) +{ + return (oops_in_progress || sync_mode); +} + +static bool console_can_sync(struct console *con) +{ + if (!(con->flags & CON_ENABLED)) + return false; + if (con->write_atomic && kernel_sync_mode()) + return true; + return false; +} + +static bool call_sync_console_driver(struct console *con, const char *text, size_t text_len) +{ + if (!(con->flags & CON_ENABLED)) + return false; + if (con->write_atomic && kernel_sync_mode()) + con->write_atomic(con, text, text_len); + else + return false; + + return true; +} + +static bool have_atomic_console(void) +{ + struct console *con; + + for_each_console(con) { + if (!(con->flags & CON_ENABLED)) + continue; + if (con->write_atomic) + return true; + } + return false; +} + +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; + + text_len = record_print_text(&r, console_msg_format & MSG_FORMAT_SYSLOG, printk_time); + + if (!call_sync_console_driver(con, &con->sync_buf[0], text_len)) + return false; + + *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_until(struct console *con, u64 seq) +{ + unsigned int flags; + u64 printk_seq; + + console_atomic_lock(&flags); + for (;;) { + printk_seq = atomic64_read(&console_seq); + if (printk_seq >= seq) + break; + if (!print_sync(con, &printk_seq)) + break; + atomic64_set(&console_seq, printk_seq + 1); + } + console_atomic_unlock(flags); +} + /* * 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. @@ -1925,6 +2011,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 (kernel_sync_mode()) + continue; if (con->flags & CON_EXTENDED) con->write(con, ext_text, ext_len); else { @@ -2079,6 +2167,7 @@ int vprintk_store(int facility, int level, const u32 caller_id = printk_caller_id(); struct prb_reserved_entry e; enum log_flags lflags = 0; + bool final_commit = false; struct printk_record r; unsigned long irqflags; u16 trunc_msg_len = 0; @@ -2088,6 +2177,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 @@ -2126,6 +2216,7 @@ int vprintk_store(int facility, int level, if (lflags & 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, &lflags, fmt, args); r.info->text_len += text_len; @@ -2133,6 +2224,7 @@ int vprintk_store(int facility, int level, if (lflags & LOG_NEWLINE) { r.info->flags |= LOG_NEWLINE; prb_final_commit(&e); + final_commit = true; } else { prb_commit(&e); } @@ -2157,6 +2249,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, &lflags, fmt, args); if (trunc_msg_len) @@ -2171,13 +2265,25 @@ 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 (!(lflags & LOG_NEWLINE)) + if (!(lflags & 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 (facility == 0 && final_commit) { + struct console *con; + + for_each_console(con) { + if (console_can_sync(con)) + print_sync_until(con, seq + 1); + } + } + printk_exit_irqrestore(irqflags); return ret; } @@ -2273,12 +2379,13 @@ EXPORT_SYMBOL(printk); #else /* CONFIG_PRINTK */ -#define CONSOLE_LOG_MAX 0 #define printk_time false #define prb_read_valid(rb, seq, r) false #define prb_first_valid_seq(rb) 0 +#define kernel_sync_mode() false + static u64 syslog_seq; static atomic64_t console_seq = ATOMIC64_INIT(0); static u64 exclusive_console_stop_seq; @@ -2571,6 +2678,8 @@ static int have_callable_console(void) */ static inline int can_use_console(void) { + if (kernel_sync_mode()) + return false; return cpu_online(raw_smp_processor_id()) || have_callable_console(); } @@ -3408,6 +3517,18 @@ void kmsg_dump(enum kmsg_dump_reason reason) struct kmsg_dumper_iter iter; struct kmsg_dumper *dumper; + if (!oops_in_progress) { + /* + * If atomic consoles are available, activate kernel sync mode + * to make sure any final messages are visible. The trailing + * printk message is important to flush any pending messages. + */ + if (have_atomic_console()) { + sync_mode = true; + pr_info("enabled sync mode\n"); + } + } + rcu_read_lock(); list_for_each_entry_rcu(dumper, &dump_list, list) { enum kmsg_dump_reason max_reason = dumper->max_reason; -- 2.44.0