On Sat 2016-12-24 23:09:02, Sergey Senozhatsky wrote: > The "printk messages dropped" report is 'attached' to a kernel > message located at console_idx offset. This does not work well > if we skip that message due to loglevel filtering, because in > this case we also skip/lose dropped message report.
Good catch! > Disable suppress_message_printing() loglevel filtering if we > must report "printk messages dropped" condition. > > Signed-off-by: Sergey Senozhatsky <[email protected]> > --- > kernel/printk/printk.c | 5 ++++- > 1 file changed, 4 insertions(+), 1 deletion(-) > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 11a9842a2f47..6a7ebcb0bb6e 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -2218,6 +2218,7 @@ void console_unlock(void) > struct printk_log *msg; > size_t ext_len = 0; > size_t len; > + bool report_dropped_msg = false; > > raw_spin_lock_irqsave(&logbuf_lock, flags); > if (seen_seq != log_next_seq) { > @@ -2232,6 +2233,7 @@ void console_unlock(void) > /* messages are gone, move to first one */ > console_seq = log_first_seq; > console_idx = log_first_idx; > + report_dropped_msg = true; > } else { > len = 0; > } > @@ -2240,7 +2242,8 @@ void console_unlock(void) > break; > > msg = log_from_idx(console_idx); > - if (suppress_message_printing(msg->level)) { > + if (!report_dropped_msg && > + suppress_message_printing(msg->level)) { > /* > * Skip record we have buffered and already printed > * directly to the console when we received it, and This causes the opposite problem. We might print a message that was supposed to be suppressed. I think that it is not a good idea in this situation. I played with it and cooked a patch, see below. Please, do not feel offended. I do not want to take you credits for finding the problem. But the printk code is very twisted and console_unlock() is one of the worst pieces. Solution based on my concerns could make it even worse. I do not want to push you into clean ups and tried it myself. The result is not as good as I hoped. But it it is not worse, IMHO. Which is good given the circumstances. Feel free to provide even better one and use pieces from my patch. I also think about spling it into two patches and make msg_print() helper in a separate patch. >From 976073de3e0f3daa4f1d700ef605165d97533c9b Mon Sep 17 00:00:00 2001 From: Petr Mladek <[email protected]> Date: Tue, 3 Jan 2017 14:32:04 +0100 Subject: [PATCH] printk: Always report lost messages on serial console The "printk messages dropped" report is 'attached' to a kernel message located at console_idx offset. This does not work well if we skip that message due to loglevel filtering, because in this case we also skip/lose dropped message report. A simple solution would be to ignore the level and always print the warning with the next message. But the situation suggests that we are under a high load and could not afford printing less important messages. Also we could not print only the warning because we might lose even more messages in the meantime. The best solution seems to be to print the warning with the next visible message. This patch tries to keep readability of the code. It puts msg_print*() calls into a helper function. Also it hides there the visibility check. As a result we could have only one copy of console_idx = log_next(console_idx); console_seq++; Reported-by: Sergey Senozhatsky <[email protected]> Signed-off-by: Petr Mladek <[email protected]> --- kernel/printk/printk.c | 61 ++++++++++++++++++++++++++++---------------------- 1 file changed, 34 insertions(+), 27 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 0dbde4e7bb15..7cc2e7effdc3 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1234,6 +1234,28 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog, char *bu return len; } +static bool console_check_and_print_msg(u32 console_idx, + char *text, size_t size, size_t *len, + char *ext_text, size_t ext_size, size_t *ext_len) +{ + struct printk_log *msg = log_from_idx(console_idx); + + if (suppress_message_printing(msg->level)) + return false; + + *len += msg_print_text(msg, false, text, size); + if (nr_ext_console_drivers) { + *ext_len = msg_print_ext_header(ext_text, ext_size, + msg, console_seq); + *ext_len += msg_print_ext_body(ext_text + *ext_len, + ext_size - *ext_len, + log_dict(msg), msg->dict_len, + log_text(msg), msg->text_len); + } + + return true; +} + static int syslog_print(char __user *buf, int size) { char *text; @@ -2215,9 +2237,9 @@ void console_unlock(void) } for (;;) { - struct printk_log *msg; + bool printed_msg = false; size_t ext_len = 0; - size_t len; + size_t len = 0; raw_spin_lock_irqsave(&logbuf_lock, flags); if (seen_seq != log_next_seq) { @@ -2232,37 +2254,22 @@ void console_unlock(void) /* messages are gone, move to first one */ console_seq = log_first_seq; console_idx = log_first_idx; - } else { - len = 0; } -skip: - if (console_seq == log_next_seq) - break; - msg = log_from_idx(console_idx); - if (suppress_message_printing(msg->level)) { - /* - * Skip record we have buffered and already printed - * directly to the console when we received it, and - * record that has level above the console loglevel. - */ + /* Get the next message with a visible level */ + while (console_seq < log_next_seq && !printed_msg) { + printed_msg = console_check_and_print_msg(console_seq, + text + len, sizeof(text) - len, &len, + ext_text, sizeof(ext_text), &ext_len); + console_idx = log_next(console_idx); console_seq++; - goto skip; } - len += msg_print_text(msg, false, text + len, sizeof(text) - len); - if (nr_ext_console_drivers) { - ext_len = msg_print_ext_header(ext_text, - sizeof(ext_text), - msg, console_seq); - ext_len += msg_print_ext_body(ext_text + ext_len, - sizeof(ext_text) - ext_len, - log_dict(msg), msg->dict_len, - log_text(msg), msg->text_len); - } - console_idx = log_next(console_idx); - console_seq++; + /* No warning and no visible message => done */ + if (!len && !printed_msg) + break; + raw_spin_unlock(&logbuf_lock); stop_critical_timings(); /* don't trace print latency */ -- 1.8.5.6
