From 17b655759e83fd5e28931a0ece96fa9c2ab718e7 Mon Sep 17 00:00:00 2001 From: Raul E Rangel Date: Wed, 11 Sep 2024 12:35:14 -0600 Subject: [PATCH 1/5] init: Don't proxy `console=` to earlycon Today we are proxying the `console=` command line args to the `param_setup_earlycon()` handler. This is done because the following are equivalent: console=uart[8250],mmio,[,options] earlycon=uart[8250],mmio,[,options] Both invocations enable an early `bootconsole`. `console=uartXXXX` is just an alias for `earlycon=uartXXXX`. In addition, when `earlycon=` (empty value) or just `earlycon` (no value) is specified on the command line, we enable the earlycon `bootconsole` specified by the SPCR table or the DT. The problem arises when `console=` (empty value) is specified on the command line. It's intention is to disable the `console`, but what happens instead is that the SPRC/DT console gets enabled. This happens because we are proxying the `console=` (empty value) parameter to the `earlycon` handler. The `earlycon` handler then sees that the parameter value is empty, so it enables the SPCR/DT `bootconsole`. This change makes it so that the `console` or `console=` parameters no longer enable the SPCR/DT `bootconsole`. I also cleans up the hack in `main.c` that would forward the `console` parameter to the `earlycon` handler. Signed-off-by: Raul E Rangel Reviewed-by: Petr Mladek Tested-by: Petr Mladek Link: https://lore.kernel.org/r/20240911123507.v2.1.Id08823b2f848237ae90ce5c5fa7e027e97c33ad3@changeid Signed-off-by: Petr Mladek --- drivers/tty/serial/earlycon.c | 23 +++++++++++++++++++++++ init/main.c | 5 +---- 2 files changed, 24 insertions(+), 4 deletions(-) diff --git a/drivers/tty/serial/earlycon.c b/drivers/tty/serial/earlycon.c index a5fbb6ed38ae..ab9af37f6cda 100644 --- a/drivers/tty/serial/earlycon.c +++ b/drivers/tty/serial/earlycon.c @@ -248,6 +248,29 @@ static int __init param_setup_earlycon(char *buf) } early_param("earlycon", param_setup_earlycon); +/* + * The `console` parameter is overloaded. It's handled here as an early param + * and in `printk.c` as a late param. It's possible to specify an early + * `bootconsole` using `earlycon=uartXXXX` (handled above), or via + * the `console=uartXXX` alias. See the comment in `8250_early.c`. + */ +static int __init param_setup_earlycon_console_alias(char *buf) +{ + /* + * A plain `console` parameter must not enable the SPCR `bootconsole` + * like a plain `earlycon` does. + * + * A `console=` parameter that specifies an empty value is used to + * disable the `console`, not the `earlycon` `bootconsole`. The + * disabling of the `console` is handled by `printk.c`. + */ + if (!buf || !buf[0]) + return 0; + + return param_setup_earlycon(buf); +} +early_param("console", param_setup_earlycon_console_alias); + #ifdef CONFIG_OF_EARLY_FLATTREE int __init of_setup_earlycon(const struct earlycon_id *match, diff --git a/init/main.c b/init/main.c index c4778edae797..00fac1170294 100644 --- a/init/main.c +++ b/init/main.c @@ -754,10 +754,7 @@ static int __init do_early_param(char *param, char *val, const struct obs_kernel_param *p; for (p = __setup_start; p < __setup_end; p++) { - if ((p->early && parameq(param, p->str)) || - (strcmp(param, "console") == 0 && - strcmp(p->str, "earlycon") == 0) - ) { + if (p->early && parameq(param, p->str)) { if (p->setup_func(val) != 0) pr_warn("Malformed early option '%s'\n", param); } From a961ec4e2860af4933e8c1763fe4f038c2d6ac80 Mon Sep 17 00:00:00 2001 From: "Isaac J. Manjarres" Date: Mon, 30 Sep 2024 11:48:24 -0700 Subject: [PATCH 2/5] printk: Improve memory usage logging during boot When the initial printk ring buffer size is updated, setup_log_buf() allocates a new ring buffer, as well as a set of meta-data structures for the new ring buffer. The function also emits the new size of the ring buffer, but not the size of the meta-data structures. This makes it difficult to assess how changing the log buffer size impacts memory usage during boot. For instance, increasing the ring buffer size from 512 KB to 1 MB through the command line yields an increase of 2304 KB in reserved memory at boot, while the only obvious change is the 512 KB difference in the ring buffer sizes: log_buf_len=512K: printk: log_buf_len: 524288 bytes Memory: ... (... 733252K reserved ...) log_buf_len=1M: printk: log_buf_len: 1048576 bytes Memory: ... (... 735556K reserved ...) This is because of how the size of the meta-data structures scale with the size of the ring buffer. Even when there aren't changes to the printk ring buffer size (i.e. the initial size == 1 << CONFIG_LOG_BUF_SHIFT), it is impossible to tell how much memory is consumed by the printk ring buffer during boot. Therefore, unconditionally log the sizes of the printk ring buffer and its meta-data structures, so that it's easier to understand how changing the log buffer size (either through the command line or by changing CONFIG_LOG_BUF_SHIFT) affects boot time memory usage. With the new logs, it is much easier to see exactly why the memory increased by 2304 KB: log_buf_len=512K: printk: log buffer data + meta data: 524288 + 1835008 = 2359296 bytes Memory: ... (... 733252K reserved ...) log_buf_len=1M: printk: log buffer data + meta data: 1048576 + 3670016 = 4718592 bytes Memory: ... (... 735556K reserved ...) Signed-off-by: Isaac J. Manjarres Reviewed-by: Petr Mladek Tested-by: Petr Mladek Link: https://lore.kernel.org/r/20240930184826.3595221-1-isaacmanjarres@google.com [pmladek@suse.com: Updated the examples in the commit message, simplified comment for default buffer.] Signed-off-by: Petr Mladek --- kernel/printk/printk.c | 26 ++++++++++++++++++++++---- 1 file changed, 22 insertions(+), 4 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 71e4fe6f9b85..968830cfc606 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1156,6 +1156,17 @@ static unsigned int __init add_to_rb(struct printk_ringbuffer *rb, static char setup_text_buf[PRINTKRB_RECORD_MAX] __initdata; +static void print_log_buf_usage_stats(void) +{ + unsigned int descs_count = log_buf_len >> PRB_AVGBITS; + size_t meta_data_size; + + meta_data_size = descs_count * (sizeof(struct prb_desc) + sizeof(struct printk_info)); + + pr_info("log buffer data + meta data: %u + %zu = %zu bytes\n", + log_buf_len, meta_data_size, log_buf_len + meta_data_size); +} + void __init setup_log_buf(int early) { struct printk_info *new_infos; @@ -1185,20 +1196,25 @@ void __init setup_log_buf(int early) if (!early && !new_log_buf_len) log_buf_add_cpu(); - if (!new_log_buf_len) + if (!new_log_buf_len) { + /* Show the memory stats only once. */ + if (!early) + goto out; + return; + } new_descs_count = new_log_buf_len >> PRB_AVGBITS; if (new_descs_count == 0) { pr_err("new_log_buf_len: %lu too small\n", new_log_buf_len); - return; + goto out; } new_log_buf = memblock_alloc(new_log_buf_len, LOG_ALIGN); if (unlikely(!new_log_buf)) { pr_err("log_buf_len: %lu text bytes not available\n", new_log_buf_len); - return; + goto out; } new_descs_size = new_descs_count * sizeof(struct prb_desc); @@ -1261,7 +1277,7 @@ void __init setup_log_buf(int early) prb_next_seq(&printk_rb_static) - seq); } - pr_info("log_buf_len: %u bytes\n", log_buf_len); + print_log_buf_usage_stats(); pr_info("early log buf free: %u(%u%%)\n", free, (free * 100) / __LOG_BUF_LEN); return; @@ -1270,6 +1286,8 @@ void __init setup_log_buf(int early) memblock_free(new_descs, new_descs_size); err_free_log_buf: memblock_free(new_log_buf, new_log_buf_len); +out: + print_log_buf_usage_stats(); } static bool __read_mostly ignore_loglevel; From ed76c07c6885b249ce8486dac22fb97151a83185 Mon Sep 17 00:00:00 2001 From: Marcos Paulo de Souza Date: Tue, 5 Nov 2024 16:45:08 -0300 Subject: [PATCH 3/5] printk: Introduce FORCE_CON flag Introduce FORCE_CON flag to printk. The new flag will make it possible to create a context where printk messages will never be suppressed. This mechanism will be used in the next patch to create a force_con context on sysrq handling, removing an existing workaround on the loglevel global variable. The workaround existed to make sure that sysrq header messages were sent to all consoles, but this doesn't work with deferred messages because the loglevel might be restored to its original value before a console flushes the messages. Signed-off-by: Marcos Paulo de Souza Reviewed-by: John Ogness Reviewed-by: Petr Mladek Acked-by: Greg Kroah-Hartman Link: https://lore.kernel.org/r/20241105-printk-loud-con-v2-1-bd3ecdf7b0e4@suse.com Signed-off-by: Petr Mladek --- include/linux/printk.h | 3 +++ kernel/printk/internal.h | 3 +++ kernel/printk/printk.c | 21 ++++++++++++++++----- kernel/printk/printk_safe.c | 18 ++++++++++++++++++ 4 files changed, 40 insertions(+), 5 deletions(-) diff --git a/include/linux/printk.h b/include/linux/printk.h index eca9bb2ee637..232e5fd06701 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -166,6 +166,9 @@ __printf(1, 2) __cold int _printk_deferred(const char *fmt, ...); extern void __printk_deferred_enter(void); extern void __printk_deferred_exit(void); +extern void printk_force_console_enter(void); +extern void printk_force_console_exit(void); + /* * The printk_deferred_enter/exit macros are available only as a hack for * some code paths that need to defer all printk console printing. Interrupts diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h index 3fcb48502adb..c6bb47666aef 100644 --- a/kernel/printk/internal.h +++ b/kernel/printk/internal.h @@ -53,6 +53,8 @@ int devkmsg_sysctl_set_loglvl(const struct ctl_table *table, int write, /* Flags for a single printk record. */ enum printk_info_flags { + /* always show on console, ignore console_loglevel */ + LOG_FORCE_CON = 1, LOG_NEWLINE = 2, /* text ended with a newline */ LOG_CONT = 8, /* text is a fragment of a continuation line */ }; @@ -90,6 +92,7 @@ bool printk_percpu_data_ready(void); void defer_console_output(void); bool is_printk_legacy_deferred(void); +bool is_printk_force_console(void); u16 printk_parse_prefix(const char *text, int *level, enum printk_info_flags *flags); diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 71e4fe6f9b85..7cb44f9f3825 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1319,11 +1319,11 @@ static void boot_delay_msec(int level) { unsigned long long k; unsigned long timeout; + bool suppress = !is_printk_force_console() && + suppress_message_printing(level); - if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING) - || suppress_message_printing(level)) { + if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING) || suppress) return; - } k = (unsigned long long)loops_per_msec * boot_delay; @@ -2273,6 +2273,9 @@ int vprintk_store(int facility, int level, if (dev_info) flags |= LOG_NEWLINE; + if (is_printk_force_console()) + flags |= LOG_FORCE_CON; + if (flags & LOG_CONT) { prb_rec_init_wr(&r, reserve_size); if (prb_reserve_in_last(&e, prb, &r, caller_id, PRINTKRB_RECORD_MAX)) { @@ -2280,6 +2283,9 @@ int vprintk_store(int facility, int level, facility, &flags, fmt, args); r.info->text_len += text_len; + if (flags & LOG_FORCE_CON) + r.info->flags |= LOG_FORCE_CON; + if (flags & LOG_NEWLINE) { r.info->flags |= LOG_NEWLINE; prb_final_commit(&e); @@ -2947,6 +2953,7 @@ bool printk_get_next_message(struct printk_message *pmsg, u64 seq, struct printk_info info; struct printk_record r; size_t len = 0; + bool force_con; /* * Formatting extended messages requires a separate buffer, so use the @@ -2965,9 +2972,13 @@ bool printk_get_next_message(struct printk_message *pmsg, u64 seq, pmsg->seq = r.info->seq; pmsg->dropped = r.info->seq - seq; + force_con = r.info->flags & LOG_FORCE_CON; - /* Skip record that has level above the console loglevel. */ - if (may_suppress && suppress_message_printing(r.info->level)) + /* + * Skip records that are not forced to be printed on consoles and that + * has level above the console loglevel. + */ + if (!force_con && may_suppress && suppress_message_printing(r.info->level)) goto out; if (is_extended) { diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c index 2b35a9d3919d..6f94418d53ff 100644 --- a/kernel/printk/printk_safe.c +++ b/kernel/printk/printk_safe.c @@ -12,6 +12,24 @@ #include "internal.h" +/* Context where printk messages are never suppressed */ +static atomic_t force_con; + +void printk_force_console_enter(void) +{ + atomic_inc(&force_con); +} + +void printk_force_console_exit(void) +{ + atomic_dec(&force_con); +} + +bool is_printk_force_console(void) +{ + return atomic_read(&force_con); +} + static DEFINE_PER_CPU(int, printk_context); /* Can be preempted by NMI. */ From e3eea25e0b28ea06eb841ef1814ce7b7254f2fce Mon Sep 17 00:00:00 2001 From: Marcos Paulo de Souza Date: Tue, 5 Nov 2024 16:45:09 -0300 Subject: [PATCH 4/5] tty: sysrq: Use printk_force_console context on __handle_sysrq By using the printk_force_console the loglevel workaround can be removed. The workaround existed to always send the sysrq header message to all consoles not matter what was the current loglevel, but it won't work for deferred messages, since the loglevel can be restore before the message is printed, suppressing the message that wasn't supposed to be suppressed by the workaround. Signed-off-by: Marcos Paulo de Souza Reviewed-by: John Ogness Reviewed-by: Petr Mladek Acked-by: Greg Kroah-Hartman Link: https://lore.kernel.org/r/20241105-printk-loud-con-v2-2-bd3ecdf7b0e4@suse.com Signed-off-by: Petr Mladek --- drivers/tty/sysrq.c | 18 ++++++++---------- 1 file changed, 8 insertions(+), 10 deletions(-) diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c index 14f8f00fdcf9..4a8405478ad8 100644 --- a/drivers/tty/sysrq.c +++ b/drivers/tty/sysrq.c @@ -582,7 +582,6 @@ static void __sysrq_put_key_op(u8 key, const struct sysrq_key_op *op_p) void __handle_sysrq(u8 key, bool check_mask) { const struct sysrq_key_op *op_p; - int orig_log_level; int orig_suppress_printk; int i; @@ -592,13 +591,12 @@ void __handle_sysrq(u8 key, bool check_mask) rcu_sysrq_start(); 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 - * simply emit this at KERN_EMERG as that would change message - * routing in the consumers of /proc/kmsg. + * Enter in the force_console context so that sysrq header is shown to + * provide the user with positive feedback. We do not simply emit this + * at KERN_EMERG as that would change message routing in the consumers + * of /proc/kmsg. */ - orig_log_level = console_loglevel; - console_loglevel = CONSOLE_LOGLEVEL_DEFAULT; + printk_force_console_enter(); op_p = __sysrq_get_key_op(key); if (op_p) { @@ -608,11 +606,11 @@ void __handle_sysrq(u8 key, bool check_mask) */ if (!check_mask || sysrq_on_mask(op_p->enable_mask)) { pr_info("%s\n", op_p->action_msg); - console_loglevel = orig_log_level; + printk_force_console_exit(); op_p->handler(key); } else { pr_info("This sysrq operation is disabled.\n"); - console_loglevel = orig_log_level; + printk_force_console_exit(); } } else { pr_info("HELP : "); @@ -630,7 +628,7 @@ void __handle_sysrq(u8 key, bool check_mask) } } pr_cont("\n"); - console_loglevel = orig_log_level; + printk_force_console_exit(); } rcu_read_unlock(); rcu_sysrq_end(); From da115c4ee29f589bb72ec2e86eb5e196b6bbcb41 Mon Sep 17 00:00:00 2001 From: Arnd Bergmann Date: Tue, 12 Nov 2024 15:29:15 +0100 Subject: [PATCH 5/5] printk: add dummy printk_force_console_enter/exit helpers The newly added interface is broken when PRINTK is disabled: drivers/tty/sysrq.c: In function '__handle_sysrq': drivers/tty/sysrq.c:601:9: error: implicit declaration of function 'printk_force_console_enter' [-Wimplicit-function-declaration] 601 | printk_force_console_enter(); | ^~~~~~~~~~~~~~~~~~~~~~~~~~ drivers/tty/sysrq.c:611:25: error: implicit declaration of function 'printk_force_console_exit' [-Wimplicit-function-declaration] 611 | printk_force_console_exit(); | ^~~~~~~~~~~~~~~~~~~~~~~~~ Add empty stub functions for both. Fixes: ed76c07c6885 ("printk: Introduce FORCE_CON flag") Signed-off-by: Arnd Bergmann Reviewed-by: Andy Shevchenko Reviewed-by: Marcos Paulo de Souza Tested-by: Marcos Paulo de Souza Link: https://lore.kernel.org/r/20241112142939.724093-1-arnd@kernel.org Signed-off-by: Petr Mladek --- include/linux/printk.h | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/include/linux/printk.h b/include/linux/printk.h index 232e5fd06701..4217a9f412b2 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -232,6 +232,14 @@ static inline void printk_deferred_exit(void) { } +static inline void printk_force_console_enter(void) +{ +} + +static inline void printk_force_console_exit(void) +{ +} + static inline int printk_ratelimit(void) { return 0;