On 2019-02-26, Petr Mladek <pmla...@suse.com> wrote:
> The warning about dropped messages gets lost when the current
> message is above console_loglevel and suppressed.
Here you are reporting a bug. (More on this below.)
> The suppressed messages allow even slow consoles to caught up
> with a flood of messages. The consoles must not get slowed
> down by many warnings. Instead, the warning is delayed until
> the next printable message.
Here you are introducing a new behavior. (Also discussed below.)
Although the two are similar, they are really 2 different things.
> The handling of newly registered consoles is handled with a compromise:
>
> + It does not make sense to reply the log when it is already behind.
> This prevents a bogus number at the beginning of the replayed log.
>
> + The counter is restarted when switching to all consoles. This
> prevents a bogus number on already registered consoles.
>
> + The last number in the replayed log might be lower than reality.
> But it does not look worth existing.
>
> Signed-off-by: Petr Mladek <pmla...@suse.com>
> ---
> kernel/printk/printk.c | 54
> ++++++++++++++++++++++++++++++++------------------
> 1 file changed, 35 insertions(+), 19 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index b4d26388bc62..c3f287422ef4 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -420,6 +420,7 @@ static u32 log_next_idx;
> /* the next printk record to write to the console */
> static u64 console_seq;
> static u32 console_idx;
> +static u64 console_dropped_cnt;
> static u64 exclusive_console_stop_seq;
>
> /* the next printk record to read after the last 'clear' command */
> @@ -2060,6 +2061,7 @@ static u64 syslog_seq;
> static u32 syslog_idx;
> static u64 console_seq;
> static u32 console_idx;
> +static u64 console_dropped_cnt;
> static u64 exclusive_console_stop_seq;
> static u64 log_first_seq;
> static u32 log_first_idx;
> @@ -2398,20 +2400,24 @@ void console_unlock(void)
> for (;;) {
> struct printk_log *msg;
> size_t ext_len = 0;
> - size_t len;
> + size_t len = 0;
>
> printk_safe_enter_irqsave(flags);
> raw_spin_lock(&logbuf_lock);
> +
> + /* Reset dropped msg count when switching to all consoles. */
> + if (unlikely(exclusive_console &&
> + exclusive_console_stop_seq < log_first_seq)) {
> + console_dropped_cnt = 0;
> + console_seq = exclusive_console_stop_seq;
> + }
> +
Wouldn't the fix to the bug be to move the "skip" target here?
skip:
> if (console_seq < log_first_seq) {
> - len = sprintf(text,
> - "** %llu printk messages dropped **\n",
> - log_first_seq - console_seq);
> + console_dropped_cnt += log_first_seq - console_seq;
>
> /* 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)
> @@ -2435,6 +2441,13 @@ void console_unlock(void)
> exclusive_console = NULL;
> }
>
> + if (unlikely(console_dropped_cnt)) {
> + len = sprintf(text,
> + "** %llu printk messages dropped **\n",
> + console_dropped_cnt);
> + console_dropped_cnt = 0;
> + }
> +
My only objection to this is that the "messages dropped" only comes if a
non-supressed message comes. So information about dropped information
may never get printed unless some task prints something non-supressed.
Imagine a situation where I am expecting a message to come, but don't
see it because it was dropped. But if no more non-supressed messages
come, I see neither the expected message nor the dropped message.
John Ogness
