Re: [PATCH] printk/console: Do not suppress information about dropped messages

[John Ogness <john.ogness@linutronix.de>]

On 2019-02-27, Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
>>>  		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.
>
> I think this is exactly the problem (and thus the patch) we discussed
> some 3 years ago.

I guess you are referring to this [0] thread.

> I had a number of rather strangely looking serial logs, which clearly
> had lost messages but no "%llu printk messages dropped" markers. So I
> added `static bool lost_messages' to console_unlock(), set it when
> printing loop would discover lost messages, then print "%llu printk
> messages dropped" attached to whatever msg was next in the logbuf,
> regardless of msg->level.  IOW, if lost_messages was set then
> suppress_message_printing(msg->level) was not even invoked. Yes, that
> would sometimes print several "debugging noise" messages, but the main
> part was that I would have "%llu printk messages dropped" markers in
> the logs; which was much more important to me.

I would agree with the proposed solution from 2016. My experience is
that the dropped messages are very important. Yes, printing them could
lead to the loss of even more messages. But still, it is important
information that needs to get out.

John Ogness

[0] https://lkml.kernel.org/r/20161224140902.1962-3-sergey.senozhatsky@gmail.com