From a961ec4e2860af4933e8c1763fe4f038c2d6ac80 Mon Sep 17 00:00:00 2001 From: "Isaac J. Manjarres" Date: Mon, 30 Sep 2024 11:48:24 -0700 Subject: 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(-) (limited to 'kernel/printk') 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 @@ err_free_descs: 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; -- cgit v1.2.3 From ed76c07c6885b249ce8486dac22fb97151a83185 Mon Sep 17 00:00:00 2001 From: Marcos Paulo de Souza Date: Tue, 5 Nov 2024 16:45:08 -0300 Subject: 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 --- kernel/printk/internal.h | 3 +++ kernel/printk/printk.c | 21 ++++++++++++++++----- kernel/printk/printk_safe.c | 18 ++++++++++++++++++ 3 files changed, 37 insertions(+), 5 deletions(-) (limited to 'kernel/printk') 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. */ -- cgit v1.2.3