Re: [PATCH] printk: Ratelimit messages printed by console drivers

[Steven Rostedt <rostedt@goodmis.org>]

On Fri, 20 Apr 2018 16:01:57 +0200
Petr Mladek <pmladek@suse.com> wrote:

> On Fri 2018-04-20 08:04:28, Steven Rostedt wrote:
> > On Fri, 20 Apr 2018 11:12:24 +0200
> > Petr Mladek <pmladek@suse.com> wrote:
> >   
> > > Yes, my number was arbitrary. The important thing is that it was long
> > > enough. Or do you know about an console that will not be able to write
> > > 100 lines within one hour?  
> > 
> > The problem is the way rate limit works. If you print 100 lines (or
> > 1000) in 5 seconds, then you just stopped printing from that context
> > for 59 minutes and 55 seconds. That's a long time to block printing.  
> 
> Are we talking about the same context?
> 
> I am talking about console drivers called from console_unlock(). It is
> very special context because it is more or less recursive:
> 
>      + could cause infinite loop
>      + the errors are usually the same again and again

The check is only when console_owner == current, which can easily
happen with an interrupt let alone an NMI.

The common case is not recursive.

> 
> As a result, if you get too many messages from this context:
> 
>      + you are lost (recursion)
>      + more messages != new information
> 
> And you need to fix the problem anyway. Otherwise, the system
> logging is a mess.
> 
> 
> > What happens if you had a couple of NMIs go off that takes up that
> > time, and then you hit a bug 10 minutes later from that context. You
> > just lost it.  
> 
> I do not understand how this is related to the NMI context.
> The messages in NMI context are not throttled!
> 
> OK, the original patch throttled also NMI messages when NMI
> interrupted console drivers. But it is easy to fix.

My mistake in just mentioning NMIs, because the check is on
console_owner which can be set with interrupts enabled. That means an
interrupt that does a print could hide printks from other interrupts or
NMIs when console_owner is set.

> 
> 
> > This is a magnitude larger than any other user of rate limit in the
> > kernel. The most common time is 5 seconds. The longest I can find is 1
> > minute. You are saying you want to block printing from this context for
> > 60 minutes!  
> 
> I see 1 day long limits in dio_warn_stale_pagecache() and
> xfs_scrub_experimental_warning().
> 
> Note that most ratelimiting is related to a single message. Also it
> is in situation where the system should recover within seconds.
> 
> 
> > That is HUGE! I don't understand your rational for such a huge number.
> > What data do you have to back that up with?  
> 
> We want to allow seeing the entire lockdep splat (Sergey wants more
> than 100 lines). Also it is not that unusual that slow console is busy
> several minutes when too many things are happening.
> 
> I proposed that long delay because I want to be on the safe side.
> Also I do not see a huge benefit in repeating the same messages
> too often.
> 
> Alternative solution would be to allow first, lets say 250, lines
> and then nothing. I mean to change the approach from rate-limiting
> to print-once.


Actually, I think we are fine with the one hour and 1000 prints if we
add to the condition. It can't just check console_owner. We need a way
to know that this is indeed a recursion. Perhaps we should set the
context we are in when setting console owner. Something like I have in
the ring buffer code.

enum {
	CONTEXT_NONE,
	CONTEXT_NMI,
	CONTEXT_IRQ,
	CONTEXT_SOFTIRQ,
	CONTEXT_NORMAL
};

int git_context(void)
{
	unsigned long pc = preempt_count();

	if (!(pc & (NMI_MASK | HARDIRQ_MASK | SOFTIRQ_OFFSET)))
		return CONTEXT_NORMAL;
	else
		return pc & NMI_MASK ? CONTEXT_NMI :
			pc & HARDIRQ_MASK ? CONTEXT_IRQ : CONTEXT_SOFTIRQ;
}

static void console_lock_spinning_enable(void)
{
	raw_spin_lock(&console_owner_lock);
	console_owner = current;
	console_context = get_context();
	raw_spin_unlock(&console_owner_lock);
[..]


static int console_lock_spinning_disable_and_check(void)
{
	raw_spin_lock(&console_owner_lock);
	waiter = READ_ONCE(console_waiter);
	console_owner = NULL;
	console_context = CONTEXT_NONE;
	raw_spin_unlock(&console_owner_lock);
[..]


Then have your check be:

+	/* Prevent infinite loop caused by messages from console drivers. */
+	if (console_owner == current && console_context == get_context() &&
+	    !__ratelimit(&ratelimit_console))
+		return 0;

Then you know that this is definitely due to recursion.

-- Steve